Ceph » rgw

hi casey,

to clarify, is this a bug in the lc code, or the api it's calling?

Matt

i was able to reproduce this locally by a) running radosgw under valgrind to slow things down, and b) using the pytest-repeat plugin to run test_bucket_concurrent_set_canned_acl hundreds of times in a row

s3tests diff:

diff --git a/requirements.txt b/requirements.txt
index 7742d8f..39736c2 100644
--- a/requirements.txt
+++ b/requirements.txt
@@ -12,4 +12,5 @@ pytz >=2011k
 httplib2
 lxml
 pytest
+pytest-repeat
 tox

in this case, the failures started after 335 runs:

$ S3TEST_CONF=s3tests.conf.SAMPLE tox -- -v s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl --count 1000
...
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[332-1000] PASSED                                                            [ 33%] 
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[333-1000] PASSED                                                            [ 33%] 
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[334-1000] PASSED                                                            [ 33%] 
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[335-1000] PASSED                                                            [ 33%]
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[336-1000] PASSED                                                            [ 33%] 
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[336-1000] ERROR                                                             [ 33%] 
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[337-1000] PASSED                                                            [ 33%]
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[337-1000] ERROR                                                             [ 33%]
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[338-1000] PASSED                                                            [ 33%]
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[338-1000] ERROR                                                             [ 33%]
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[339-1000] PASSED                                                            [ 33%]
s3tests_boto3/functional/test_s3.py::test_bucket_concurrent_set_canned_acl[339-1000] ERROR                                                             [ 33%]

the teuthology run doesn't enable debug-ms=1, so i'm sharing sections of my logs:

2023-08-11T12:29:15.210-0400 7b4d26c0 20 req 10056301545426509648 0.082002886s s3:delete_bucket abort_multiparts INFO: aborting and cleaning up multipart upload(s); bucket=":yournamehere-vkrdgfri5xv6mcl3-335[fbfb299a-87f1-4a5b-bc21-232931f78614.4156.335])"; uploads.size()=0; is_truncated=0
2023-08-11T12:29:15.211-0400 7b4d26c0 10 lifecycle: RGWRados::convert_old_bucket_info(): bucket=:yournamehere-vkrdgfri5xv6mcl3-335[fbfb299a-87f1-4a5b-bc21-232931f78614.4156.335])
2023-08-11T12:29:15.211-0400 7b4d26c0 10 lifecycle: cache get: name=default.rgw.meta+root+yournamehere-vkrdgfri5xv6mcl3-335 : hit (requested=0x17, cached=0x17)
2023-08-11T12:29:15.211-0400 7b4d26c0 20 lifecycle: WARNING: blocking librados call
2023-08-11T12:29:15.212-0400 7b4d26c0  1 -- 192.168.245.130:0/706717837 --> [v2:192.168.245.130:6800/3526074991,v1:192.168.245.130:6801/3526074991] -- osd_op(unknown.0.0:70954 4.0 4:eeb87d7b:root::.bucket.meta.yournamehere-vkrdgfri5xv6mcl3-335%3afbfb299a-87f1-4a5b-bc21-232931f78614.4156.335:head [delete,create,call version.check_conds in=122b,call version.set in=58b,writefull 0~387 in=387b,setxattr user.rgw.acl (209) in=221b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e16) v8 -- 0xbd3e230 con 0x15644f30
2023-08-11T12:29:15.214-0400 13b766c0  1 -- 192.168.245.130:0/706717837 <== osd.0 v2:192.168.245.130:6800/3526074991 78664 ==== osd_op_reply(70954 .bucket.meta.yournamehere-vkrdgfri5xv6mcl3-335:fbfb299a-87f1-4a5b-bc21-232931f78614.4156.335 [delete,create,call,call,writefull 0~387,setxattr (209)] v16'67567 uv67560 ondisk = -125 ((125) Operation canceled)) v8 ==== 446+0+0 (crc 0 0 0) 0x3ef3e610 con 0x15644f30
2023-08-11T12:29:15.215-0400 7b4d26c0 10 lifecycle: removing default.rgw.meta+root+.bucket.meta.yournamehere-vkrdgfri5xv6mcl3-335:fbfb299a-87f1-4a5b-bc21-232931f78614.4156.335 from cache
2023-08-11T12:29:15.215-0400 7b4d26c0  0 lifecycle: RGWLC::RGWDeleteLC() failed to set attrs on bucket=yournamehere-vkrdgfri5xv6mcl3-335 returned err=-125

this error is coming from the call to RGWLC::remove_bucket_config() in RadosBucket::remove_bucket(): https://github.com/ceph/ceph/blob/875dae76/src/rgw/driver/rados/rgw_sal_rados.cc#L453-L455
because that unnecessarily uses the default argument bool merge_attrs = true, that overwrites the bucket metadata to remove RGW_ATTR_LC, which uses cls_version to bump the version number

2023-08-11T12:29:15.276-0400 764c86c0  1 -- 192.168.245.130:0/706717837 --> [v2:192.168.245.130:6800/3526074991,v1:192.168.245.130:6801/3526074991] -- osd_op(unknown.0.0:70992 4.0 4:eeb87d7b:root::.bucket.meta.yournamehere-vkrdgfri5xv6mcl3-335%3afbfb299a-87f1-4a5b-bc21-232931f78614.4156.335:head [call version.check_conds in=122b,call version.set in=58b,delete] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e16) v8 -- 0x57ae1430 con 0x15644f30
2023-08-11T12:29:15.278-0400 3ebcb6c0  1 -- 192.168.245.130:0/2158442906 --> [v2:192.168.245.130:6800/3526074991,v1:192.168.245.130:6801/3526074991] -- osd_op(unknown.0.0:1546 2.0 2:6fe6cc47:notif::queues_list_object:head [omap-get-keys in=12b] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e16) v8 -- 0x57b14000 con 0x308b6740
2023-08-11T12:29:15.279-0400 13b766c0  1 -- 192.168.245.130:0/706717837 <== osd.0 v2:192.168.245.130:6800/3526074991 78706 ==== osd_op_reply(70992 .bucket.meta.yournamehere-vkrdgfri5xv6mcl3-335:fbfb299a-87f1-4a5b-bc21-232931f78614.4156.335 [call,call,delete] v16'67570 uv67560 ondisk = -125 ((125) Operation canceled)) v8 ==== 320+0+0 (crc 0 0 0) 0x3ece7c80 con 0x15644f30
2023-08-11T12:29:15.280-0400 6bcb36c0 -1 req 10056301545426509648 0.152005360s s3:delete_bucket ERROR: could not remove bucket yournamehere-vkrdgfri5xv6mcl3-335

this ECANCELED error is likely due to the write from remove_bucket_config(). i just don't understand why this doesn't fail on every DeleteBucket request

p.s. the buckets in this test case don't even have a lifecycle policy, so we're running this stuff unnecessarily

Casey Bodley wrote:

this error is coming from the call to RGWLC::remove_bucket_config() in RadosBucket::remove_bucket(): https://github.com/ceph/ceph/blob/875dae76/src/rgw/driver/rados/rgw_sal_rados.cc#L453-L455
because that unnecessarily uses the default argument bool merge_attrs = true, that overwrites the bucket metadata to remove RGW_ATTR_LC, which uses cls_version to bump the version number

this write could cause the later delete to fail with ECANCELED because the version number changed, but in the log it's this write in remove_bucket_config() that fails with ECANCELED - which implies that remove_bucket_config() is racing with some other update. i can't tell from the log what it is yet

i added some extra logging to the RGWObjVersionTracker to follow the cls_version updates. i see one of the put_acls requests bumping the version from 6->7, but the later delete_bucket request is checking for version 6. the delete_bucket starts after put_acls completes, so the requests themselves don't race

it seems to be a race in RGWSI_SysObj_Cache itself. while the put_acls requests are racing, i see the cache notifications arriving out of order:

2023-08-11T16:34:50.594-0400 1c7876c0 20 rgw watcher librados: RGWSI_SysObj_Cache received notify for objv _XqpmbIiCICgx1_zAdi60Nd9:7 of default.rgw.meta+root+.bucket.meta.yournamehere-3a276u7iwxaslg1c-242:40bd6ef6-ca4f-4f22-95d9-978bb0945b94.4156.242
...
2023-08-11T16:34:50.599-0400 1c7876c0 20 rgw watcher librados: RGWSI_SysObj_Cache received notify for objv _XqpmbIiCICgx1_zAdi60Nd9:6 of default.rgw.meta+root+.bucket.meta.yournamehere-3a276u7iwxaslg1c-242:40bd6ef6-ca4f-4f22-95d9-978bb0945b94.4156.242