Project

General

Profile

Actions
Copy link

Bug #22368

closed

Problem with RGW multipart uploads with resharded buckets

Added by Karol Babioch over 6 years ago. Updated about 6 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Casey Bodley
Target version:
-
% Done:

0%

Source:
Tags:
multipart radosgw rgw regression upload
Backport:
Regression:
Yes
Severity:
2 - major
Reviewed:
Affected Versions:
Ceph - v10.2.10
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Since 10.2.10 multipart uploads are broken. It used to work fine until 10.2.9. Therefore this is a regression.

Using s3cmd works fine when the bucket is not resharded, but once resharded, it does not work any longer.

This can be reproduced like this:

Creating a new bucket:

root@mp-cephtest:~# s3cmd mb s3://test3                                                                                          
    Bucket 's3://test3/' created

Using s3cmd to upload 20M file:

root@mp-cephtest:~# s3cmd put test20 s3://test3                                                                                  
    upload: 'test20' -> 's3://test3/test20'  [part 1 of 2, 15MB] [1 of 1]
     15728640 of 15728640   100% in    7s  1984.66 kB/s  done
    upload: 'test20' -> 's3://test3/test20'  [part 2 of 2, 5MB] [1 of 1]
     5242880 of 5242880   100% in    2s     2.04 MB/s  done

Resharding:

root@mp-cephtest:~# radosgw-admin bucket reshard --bucket=test3 --num-shards=35
  • NOTICE: operation will not remove old bucket index objects ***
  • these will need to be removed manually ***
    old bucket instance id: 14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54859.1
    new bucket instance id: 14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54861.1
    total entries: 1
    root@mp-cephtest:~# radosgw-admin bi purge --bucket=test3 --bucket-id=14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54859.1

s3cmd fails now for the same file:

root@mp-cephtest:~# s3cmd put test20 s3://test3                                                                                  
    upload: 'test20' -> 's3://test3/test20'  [part 1 of 2, 15MB] [1 of 1]                                                            
     15728640 of 15728640   100% in    8s  1869.04 kB/s  done                                                                        
    upload: 'test20' -> 's3://test3/test20'  [part 2 of 2, 5MB] [1 of 1]                                                             
     5242880 of 5242880   100% in    1s     2.99 MB/s  done                                                                          
    WARNING: Retrying failed request: /test20?uploadId=2~fMxzsetNHuz_Otf0CTHbUPwlJJLVUoE (500 (InternalError): This multipart complet|
    ion is already in progress)                                                                                                      
    WARNING: Waiting 3 sec...                                                                                                        
    WARNING: Retrying failed request: /test20?uploadId=2~fMxzsetNHuz_Otf0CTHbUPwlJJLVUoE (500 (InternalError): This multipart complet
    ion is already in progress)                                                                                                      
    WARNING: Waiting 6 sec...                                                                                                        
    WARNING: Retrying failed request: /test20?uploadId=2~fMxzsetNHuz_Otf0CTHbUPwlJJLVUoE (500 (InternalError): This multipart complet
    ion is already in progress)                                                                                                      
    WARNING: Waiting 9 sec...                                                                                                        
    WARNING: Retrying failed request: /test20?uploadId=2~fMxzsetNHuz_Otf0CTHbUPwlJJLVUoE (500 (InternalError): This multipart complet
    ion is already in progress)                                                                                                      
    WARNING: Waiting 12 sec...                                                                                                       
    WARNING: Retrying failed request: /test20?uploadId=2~fMxzsetNHuz_Otf0CTHbUPwlJJLVUoE (500 (InternalError): This multipart complet
    ion is already in progress)                                                                                                      
    WARNING: Waiting 15 sec...
    ERROR: S3 error: 500 (InternalError): This multipart completion is already in progress

As suggested we've increased the RGW log verbosity to 20, see: https://github.com/ceph/ceph/pull/16732#issuecomment-350778908

2017-12-11 20:43:09.546835 7f32dbff7700 20 RGWEnv::set(): HTTP_HOST: localhost
    2017-12-11 20:43:09.546854 7f32dbff7700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: identity
    2017-12-11 20:43:09.546855 7f32dbff7700 20 RGWEnv::set(): CONTENT_LENGTH: 0
    2017-12-11 20:43:09.546856 7f32dbff7700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS 8YG56CKA4E4G31WX606U:D0lNZLLhuxM12dH1UjkDGGzK7vs=
    2017-12-11 20:43:09.546859 7f32dbff7700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: Mon, 11 Dec 2017 19:43:09 +0000
    2017-12-11 20:43:09.546860 7f32dbff7700 20 RGWEnv::set(): HTTP_X_AMZ_META_S3CMD_ATTRS: atime:1513020894/ctime:1513020872/gid:0/gname:root/md5:8f4e33f3dc3e414ff94e5fb6905cba8c/mode:33188/mtime:1513020872/uid:0/uname:root
    2017-12-11 20:43:09.546891 7f32dbff7700 20 RGWEnv::set(): HTTP_X_AMZ_STORAGE_CLASS: STANDARD
    2017-12-11 20:43:09.546892 7f32dbff7700 20 RGWEnv::set(): CONTENT_TYPE: application/octet-stream
    2017-12-11 20:43:09.546892 7f32dbff7700 20 RGWEnv::set(): REQUEST_METHOD: POST
    2017-12-11 20:43:09.546892 7f32dbff7700 20 RGWEnv::set(): REQUEST_URI: /test2/test20
    2017-12-11 20:43:09.546892 7f32dbff7700 20 RGWEnv::set(): QUERY_STRING: uploads
    2017-12-11 20:43:09.546892 7f32dbff7700 20 RGWEnv::set(): REMOTE_USER: 
    2017-12-11 20:43:09.546892 7f32dbff7700 20 RGWEnv::set(): SCRIPT_URI: /test2/test20
    2017-12-11 20:43:09.546892 7f32dbff7700 20 RGWEnv::set(): SERVER_PORT: 80
    2017-12-11 20:43:09.546892 7f32dbff7700 20 CONTENT_LENGTH=0
    2017-12-11 20:43:09.546892 7f32dbff7700 20 CONTENT_TYPE=application/octet-stream
    2017-12-11 20:43:09.546892 7f32dbff7700 20 HTTP_ACCEPT_ENCODING=identity
    2017-12-11 20:43:09.546892 7f32dbff7700 20 HTTP_AUTHORIZATION=AWS 8YG56CKA4E4G31WX606U:D0lNZLLhuxM12dH1UjkDGGzK7vs=
    2017-12-11 20:43:09.546892 7f32dbff7700 20 HTTP_HOST=localhost
    2017-12-11 20:43:09.546892 7f32dbff7700 20 HTTP_X_AMZ_DATE=Mon, 11 Dec 2017 19:43:09 +0000
    2017-12-11 20:43:09.546892 7f32dbff7700 20 HTTP_X_AMZ_META_S3CMD_ATTRS=atime:1513020894/ctime:1513020872/gid:0/gname:root/md5:8f4e33f3dc3e414ff94e5fb6905cba8c/mode:33188/mtime:1513020872/uid:0/uname:root
    2017-12-11 20:43:09.546892 7f32dbff7700 20 HTTP_X_AMZ_STORAGE_CLASS=STANDARD
    2017-12-11 20:43:09.546892 7f32dbff7700 20 QUERY_STRING=uploads
    2017-12-11 20:43:09.546892 7f32dbff7700 20 REMOTE_USER=
    2017-12-11 20:43:09.546892 7f32dbff7700 20 REQUEST_METHOD=POST
    2017-12-11 20:43:09.546892 7f32dbff7700 20 REQUEST_URI=/test2/test20
    2017-12-11 20:43:09.546892 7f32dbff7700 20 SCRIPT_URI=/test2/test20
    2017-12-11 20:43:09.546892 7f32dbff7700 20 SERVER_PORT=80
    2017-12-11 20:43:09.546892 7f32dbff7700  1 ====== starting new request req=0x7f32dbff18a0 =====
    2017-12-11 20:43:09.546921 7f32dbff7700  2 req 1:0.000028::POST /test2/test20::initializing for trans_id = tx000000000000000000001-005a2edfcd-d64b-default
    2017-12-11 20:43:09.546921 7f32dbff7700 10 rgw api priority: s3=5 s3website=4
    2017-12-11 20:43:09.546921 7f32dbff7700 10 host=localhost
    2017-12-11 20:43:09.546921 7f32dbff7700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
    2017-12-11 20:43:09.546921 7f32dbff7700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/test2/test20
    2017-12-11 20:43:09.546943 7f32dbff7700 10 meta>> HTTP_X_AMZ_DATE
    2017-12-11 20:43:09.546943 7f32dbff7700 10 meta>> HTTP_X_AMZ_META_S3CMD_ATTRS
    2017-12-11 20:43:09.546943 7f32dbff7700 10 meta>> HTTP_X_AMZ_STORAGE_CLASS
    2017-12-11 20:43:09.546943 7f32dbff7700 10 x>> x-amz-date:Mon, 11 Dec 2017 19:43:09 +0000
    2017-12-11 20:43:09.546943 7f32dbff7700 10 x>> x-amz-meta-s3cmd-attrs:atime:1513020894/ctime:1513020872/gid:0/gname:root/md5:8f4e33f3dc3e414ff94e5fb6905cba8c/mode:33188/mtime:1513020872/uid:0/uname:root
    2017-12-11 20:43:09.546943 7f32dbff7700 10 x>> x-amz-storage-class:STANDARD
    2017-12-11 20:43:09.546950 7f32dbff7700 20 get_handler handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:09.546954 7f32dbff7700 10 handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:09.546955 7f32dbff7700  2 req 1:0.000062:s3:POST /test2/test20::getting op 4
    2017-12-11 20:43:09.546958 7f32dbff7700 10 op=28RGWInitMultipart_ObjStore_S3
    2017-12-11 20:43:09.546959 7f32dbff7700  2 req 1:0.000066:s3:POST /test2/test20:init_multipart:authorizing
    2017-12-11 20:43:09.546980 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbff03a0 obj=default.rgw.users.keys:8YG56CKA4E4G31WX606U state=0x7f33240134b8 s->prefetch_data=0
    2017-12-11 20:43:09.546985 7f32dbff7700 10 cache get: name=default.rgw.users.keys+8YG56CKA4E4G31WX606U : miss
    2017-12-11 20:43:09.548109 7f32dbff7700 10 cache put: name=default.rgw.users.keys+8YG56CKA4E4G31WX606U info.flags=6
    2017-12-11 20:43:09.548122 7f32dbff7700 10 adding default.rgw.users.keys+8YG56CKA4E4G31WX606U to cache LRU end
    2017-12-11 20:43:09.548129 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:09.548135 7f32dbff7700 10 cache get: name=default.rgw.users.keys+8YG56CKA4E4G31WX606U : type miss (requested=1, cached=6)
    2017-12-11 20:43:09.548139 7f32dbff7700 20 rados->read ofs=0 len=524288
    2017-12-11 20:43:09.548559 7f32dbff7700 20 rados->read r=0 bl.length=8
    2017-12-11 20:43:09.548570 7f32dbff7700 10 cache put: name=default.rgw.users.keys+8YG56CKA4E4G31WX606U info.flags=1
    2017-12-11 20:43:09.548573 7f32dbff7700 10 moving default.rgw.users.keys+8YG56CKA4E4G31WX606U to cache LRU end
    2017-12-11 20:43:09.548595 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbff0070 obj=default.rgw.users.uid:test state=0x7f3324089038 s->prefetch_data=0
    2017-12-11 20:43:09.548602 7f32dbff7700 10 cache get: name=default.rgw.users.uid+test : miss
    2017-12-11 20:43:09.549242 7f32dbff7700 10 cache put: name=default.rgw.users.uid+test info.flags=22
    2017-12-11 20:43:09.549242 7f32dbff7700 10 adding default.rgw.users.uid+test to cache LRU end
    2017-12-11 20:43:09.549242 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:09.549271 7f32dbff7700 10 cache get: name=default.rgw.users.uid+test : type miss (requested=17, cached=22)
    2017-12-11 20:43:09.549271 7f32dbff7700 20 rados->read ofs=0 len=524288
    2017-12-11 20:43:09.549758 7f32dbff7700 20 rados->read r=0 bl.length=314
    2017-12-11 20:43:09.549759 7f32dbff7700 10 cache put: name=default.rgw.users.uid+test info.flags=17
    2017-12-11 20:43:09.549759 7f32dbff7700 10 moving default.rgw.users.uid+test to cache LRU end
    2017-12-11 20:43:09.549771 7f32dbff7700 10 chain_cache_entry: cache_locator=default.rgw.users.uid+test
    2017-12-11 20:43:09.549814 7f32dbff7700 10 get_canon_resource(): dest=/test2/test20?uploads
    2017-12-11 20:43:09.549814 7f32dbff7700 10 auth_hdr:
    POST
application/octet-stream
x-amz-date:Mon, 11 Dec 2017 19:43:09 0000
    x-amz-meta-s3cmd-attrs:atime:1513020894/ctime:1513020872/gid:0/gname:root/md5:8f4e33f3dc3e414ff94e5fb6905cba8c/mode:33188/mtime:1513020872/uid:0/uname:root
    x-amz-storage-class:STANDARD
    /test2/test20?uploads
    2017-12-11 20:43:09.549840 7f32dbff7700 15 calculated digest=D0lNZLLhuxM12dH1UjkDGGzK7vs=
    2017-12-11 20:43:09.549840 7f32dbff7700 15 auth_sign=D0lNZLLhuxM12dH1UjkDGGzK7vs=
    2017-12-11 20:43:09.549840 7f32dbff7700 15 compare=0
    2017-12-11 20:43:09.549857 7f32dbff7700  2 req 1:0.002964:s3:POST /test2/test20:init_multipart:normalizing buckets and tenants
    2017-12-11 20:43:09.549857 7f32dbff7700 10 s->object=test20 s->bucket=test2
    2017-12-11 20:43:09.549857 7f32dbff7700  2 req 1:0.002964:s3:POST /test2/test20:init_multipart:init permissions
    2017-12-11 20:43:09.549857 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbff0ff0 obj=default.rgw.data.root:test2 state=0x7f332408bd98 s->prefetch_data=0
    2017-12-11 20:43:09.549873 7f32dbff7700 10 cache get: name=default.rgw.data.root+test2 : miss
    2017-12-11 20:43:09.550350 7f32dbff7700 10 cache put: name=default.rgw.data.root+test2 info.flags=22
    2017-12-11 20:43:09.550350 7f32dbff7700 10 adding default.rgw.data.root+test2 to cache LRU end
    2017-12-11 20:43:09.550350 7f32dbff7700 10 updating xattr: name=user.rgw.acl bl.length()=183
    2017-12-11 20:43:09.550350 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:09.550370 7f32dbff7700 20 Read xattr: user.rgw.acl
    2017-12-11 20:43:09.550370 7f32dbff7700 20 Read xattr: user.rgw.idtag
    2017-12-11 20:43:09.550370 7f32dbff7700 20 Read xattr: user.rgw.manifest
    2017-12-11 20:43:09.550370 7f32dbff7700 10 cache get: name=default.rgw.data.root+test2 : type miss (requested=17, cached=22)
    2017-12-11 20:43:09.550370 7f32dbff7700 20 rados->read ofs=0 len=524288
    2017-12-11 20:43:09.550813 7f32dbff7700 20 rados->read r=0 bl.length=251
    2017-12-11 20:43:09.550814 7f32dbff7700 10 cache put: name=default.rgw.data.root+test2 info.flags=17
    2017-12-11 20:43:09.550826 7f32dbff7700 10 moving default.rgw.data.root+test2 to cache LRU end
    2017-12-11 20:43:09.550826 7f32dbff7700 20 rgw_get_bucket_info: bucket instance: test2(@{i=default.rgw.buckets.index,e=default.rgw.buckets.non-ec}default.rgw.buckets.data[14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54097.1])
    2017-12-11 20:43:09.550826 7f32dbff7700 20 reading from default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1
    2017-12-11 20:43:09.550845 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbff0ff0 obj=default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 state=0x7f332408e9c8 s->prefetch_data=0
    2017-12-11 20:43:09.550845 7f32dbff7700 10 cache get: name=default.rgw.data.root.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : miss
    2017-12-11 20:43:09.551268 7f32dbff7700 10 cache put: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 info.flags=22
    2017-12-11 20:43:09.551268 7f32dbff7700 10 adding default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 to cache LRU end
    2017-12-11 20:43:09.551268 7f32dbff7700 10 updating xattr: name=user.rgw.acl bl.length()=121
    2017-12-11 20:43:09.551287 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:09.551288 7f32dbff7700 20 Read xattr: user.rgw.acl
    2017-12-11 20:43:09.551288 7f32dbff7700 20 Read xattr: user.rgw.idtag
    2017-12-11 20:43:09.551288 7f32dbff7700 20 Read xattr: user.rgw.manifest
    2017-12-11 20:43:09.551288 7f32dbff7700 10 cache get: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : type miss (requested=17, cached=22)
    2017-12-11 20:43:09.551288 7f32dbff7700 20 rados->read ofs=0 len=524288
    2017-12-11 20:43:09.551693 7f32dbff7700 20 rados->read r=0 bl.length=337
    2017-12-11 20:43:09.551694 7f32dbff7700 10 cache put: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 info.flags=17
    2017-12-11 20:43:09.551694 7f32dbff7700 10 moving default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 to cache LRU end
    2017-12-11 20:43:09.551706 7f32dbff7700 10 chain_cache_entry: cache_locator=default.rgw.data.root+test2
    2017-12-11 20:43:09.551706 7f32dbff7700 10 chain_cache_entry: cache_locator=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1
    2017-12-11 20:43:09.551725 7f32dbff7700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>test</ID><DisplayName>test</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>test</ID><DisplayName>test</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
    2017-12-11 20:43:09.551725 7f32dbff7700  2 req 1:0.004833:s3:POST /test2/test20:init_multipart:recalculating target
    2017-12-11 20:43:09.551726 7f32dbff7700  2 req 1:0.004833:s3:POST /test2/test20:init_multipart:reading permissions
    2017-12-11 20:43:09.551728 7f32dbff7700  2 req 1:0.004836:s3:POST /test2/test20:init_multipart:init op
    2017-12-11 20:43:09.551730 7f32dbff7700  2 req 1:0.004838:s3:POST /test2/test20:init_multipart:verifying op mask
    2017-12-11 20:43:09.551731 7f32dbff7700 20 required_mask= 2 user.op_mask=7
    2017-12-11 20:43:09.551732 7f32dbff7700  2 req 1:0.004840:s3:POST /test2/test20:init_multipart:verifying op permissions
    2017-12-11 20:43:09.551735 7f32dbff7700  5 Searching permissions for uid=test mask=50
    2017-12-11 20:43:09.551736 7f32dbff7700  5 Found permission: 15
    2017-12-11 20:43:09.551737 7f32dbff7700  5 Searching permissions for group=1 mask=50
    2017-12-11 20:43:09.551737 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:09.551739 7f32dbff7700  5 Searching permissions for group=2 mask=50
    2017-12-11 20:43:09.551740 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:09.551740 7f32dbff7700  5 Getting permissions id=test owner=test perm=2
    2017-12-11 20:43:09.551741 7f32dbff7700 10  uid=test requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
    2017-12-11 20:43:09.551742 7f32dbff7700  2 req 1:0.004849:s3:POST /test2/test20:init_multipart:verifying op params
    2017-12-11 20:43:09.551743 7f32dbff7700  2 req 1:0.004851:s3:POST /test2/test20:init_multipart:pre-executing
    2017-12-11 20:43:09.551745 7f32dbff7700  2 req 1:0.004852:s3:POST /test2/test20:init_multipart:executing
    2017-12-11 20:43:09.551765 7f32dbff7700 10 x>> x-amz-date:Mon, 11 Dec 2017 19:43:09 0000
    2017-12-11 20:43:09.551784 7f32dbff7700 10 x>> x-amz-meta-s3cmd-attrs:atime:1513020894/ctime:1513020872/gid:0/gname:root/md5:8f4e33f3dc3e414ff94e5fb6905cba8c/mode:33188/mtime:1513020872/uid:0/uname:root
    2017-12-11 20:43:09.551789 7f32dbff7700 10 x>> x-amz-storage-class:STANDARD
    2017-12-11 20:43:09.551818 7f32dbff7700 20 get_obj_state: rctx=0x7f32dbff0ff0 obj=test2:_multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.meta state=0x7f3324098cf8 s->prefetch_data=0
    2017-12-11 20:43:09.552157 7f32dbff7700 20 get_obj_state: rctx=0x7f32dbff0ff0 obj=test2:_multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.meta state=0x7f3324098cf8 s->prefetch_data=0
    2017-12-11 20:43:09.552165 7f32dbff7700 20 prepare_atomic_modification: state is not atomic. state=0x7f3324098cf8
    2017-12-11 20:43:09.552232 7f32dbff7700 20 reading from default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1
    2017-12-11 20:43:09.552244 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbfefe60 obj=default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 state=0x7f33240a69f8 s->prefetch_data=0
    2017-12-11 20:43:09.552252 7f32dbff7700 10 cache get: name=default.rgw.data.root.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : type miss (requested=22, cached=19)
    2017-12-11 20:43:09.552632 7f32dbff7700 10 cache put: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 info.flags=22
    2017-12-11 20:43:09.552632 7f32dbff7700 10 moving default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 to cache LRU end
    2017-12-11 20:43:09.552632 7f32dbff7700 10 updating xattr: name=user.rgw.acl bl.length()=121
    2017-12-11 20:43:09.552650 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:09.552650 7f32dbff7700 10 cache get: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : hit (requested=17, cached=23)
    2017-12-11 20:43:09.552650 7f32dbff7700 20  bucket index object: .dir.14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1.29
    2017-12-11 20:43:09.909086 7f32dbff7700  2 req 1:0.362192:s3:POST /test2/test20:init_multipart:completing
    2017-12-11 20:43:09.909152 7f32dbff7700  2 req 1:0.362259:s3:POST /test2/test20:init_multipart:op status=0
    2017-12-11 20:43:09.909168 7f32dbff7700  2 req 1:0.362275:s3:POST /test2/test20:init_multipart:http status=200
    2017-12-11 20:43:09.909172 7f32dbff7700  1 ====== req done req=0x7f32dbff18a0 op status=0 http_status=200 ======
    2017-12-11 20:43:09.909214 7f32dbff7700  1 civetweb: 0x7f332401db40: 127.0.0.1 - - [11/Dec/2017:20:43:09 +0100] "POST /test2/test20 HTTP/1.1" 200 0 - 
    2017-12-11 20:43:09.977755 7f32dbff7700 20 RGWEnv::set(): HTTP_HOST: localhost
    2017-12-11 20:43:09.977771 7f32dbff7700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: identity
    2017-12-11 20:43:09.977774 7f32dbff7700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS 8YG56CKA4E4G31WX606U:ymIdkqNzgQRgl8cryzgMxrFjalI=
    2017-12-11 20:43:09.977776 7f32dbff7700 20 RGWEnv::set(): CONTENT_LENGTH: 15728640
    2017-12-11 20:43:09.977777 7f32dbff7700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: Mon, 11 Dec 2017 19:43:09 +0000
    2017-12-11 20:43:09.977779 7f32dbff7700 20 RGWEnv::set(): REQUEST_METHOD: PUT
    2017-12-11 20:43:09.977780 7f32dbff7700 20 RGWEnv::set(): REQUEST_URI: /test2/test20
    2017-12-11 20:43:09.977781 7f32dbff7700 20 RGWEnv::set(): QUERY_STRING: partNumber=1&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:09.977783 7f32dbff7700 20 RGWEnv::set(): REMOTE_USER: 
    2017-12-11 20:43:09.977783 7f32dbff7700 20 RGWEnv::set(): SCRIPT_URI: /test2/test20
    2017-12-11 20:43:09.977786 7f32dbff7700 20 RGWEnv::set(): SERVER_PORT: 80
    2017-12-11 20:43:09.977787 7f32dbff7700 20 CONTENT_LENGTH=15728640
    2017-12-11 20:43:09.977789 7f32dbff7700 20 HTTP_ACCEPT_ENCODING=identity
    2017-12-11 20:43:09.977790 7f32dbff7700 20 HTTP_AUTHORIZATION=AWS 8YG56CKA4E4G31WX606U:ymIdkqNzgQRgl8cryzgMxrFjalI=
    2017-12-11 20:43:09.977791 7f32dbff7700 20 HTTP_HOST=localhost
    2017-12-11 20:43:09.977792 7f32dbff7700 20 HTTP_X_AMZ_DATE=Mon, 11 Dec 2017 19:43:09 +0000
    2017-12-11 20:43:09.977793 7f32dbff7700 20 QUERY_STRING=partNumber=1&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:09.977794 7f32dbff7700 20 REMOTE_USER=
    2017-12-11 20:43:09.977795 7f32dbff7700 20 REQUEST_METHOD=PUT
    2017-12-11 20:43:09.977796 7f32dbff7700 20 REQUEST_URI=/test2/test20
    2017-12-11 20:43:09.977797 7f32dbff7700 20 SCRIPT_URI=/test2/test20
    2017-12-11 20:43:09.977798 7f32dbff7700 20 SERVER_PORT=80
    2017-12-11 20:43:09.977800 7f32dbff7700  1 ====== starting new request req=0x7f32dbff18a0 =====
    2017-12-11 20:43:09.977823 7f32dbff7700  2 req 2:0.000023::PUT /test2/test20::initializing for trans_id = tx000000000000000000002-005a2edfcd-d64b-default
    2017-12-11 20:43:09.977835 7f32dbff7700 10 rgw api priority: s3=5 s3website=4
    2017-12-11 20:43:09.977838 7f32dbff7700 10 host=localhost
    2017-12-11 20:43:09.977842 7f32dbff7700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
    2017-12-11 20:43:09.977843 7f32dbff7700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s>info.domain= s->info.request_uri=/test2/test20
    2017-12-11 20:43:09.977852 7f32dbff7700 10 meta>> HTTP_X_AMZ_DATE
    2017-12-11 20:43:09.977856 7f32dbff7700 10 x>> x-amz-date:Mon, 11 Dec 2017 19:43:09 +0000
    2017-12-11 20:43:09.977872 7f32dbff7700 20 get_handler handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:09.977875 7f32dbff7700 10 handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:09.977877 7f32dbff7700  2 req 2:0.000077:s3:PUT /test2/test20::getting op 1
    2017-12-11 20:43:09.977880 7f32dbff7700 10 op=21RGWPutObj_ObjStore_S3
    2017-12-11 20:43:09.977881 7f32dbff7700  2 req 2:0.000082:s3:PUT /test2/test20:put_obj:authorizing
    2017-12-11 20:43:09.977909 7f32dbff7700 10 get_canon_resource(): dest=/test2/test20?partNumber=1&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:09.977911 7f32dbff7700 10 auth_hdr:
    PUT
x-amz-date:Mon, 11 Dec 2017 19:43:09 +0000
    /test2/test20?partNumber=1&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:09.977957 7f32dbff7700 15 calculated digest=ymIdkqNzgQRgl8cryzgMxrFjalI=
    2017-12-11 20:43:09.977963 7f32dbff7700 15 auth_sign=ymIdkqNzgQRgl8cryzgMxrFjalI=
    2017-12-11 20:43:09.977964 7f32dbff7700 15 compare=0
    2017-12-11 20:43:09.977966 7f32dbff7700  2 req 2:0.000167:s3:PUT /test2/test20:put_obj:normalizing buckets and tenants
    2017-12-11 20:43:09.977969 7f32dbff7700 10 s->object=test20 s->bucket=test2
    2017-12-11 20:43:09.977971 7f32dbff7700  2 req 2:0.000172:s3:PUT /test2/test20:put_obj:init permissions
    2017-12-11 20:43:09.977987 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbff0ff0 obj=default.rgw.data.root:test2 state=0x7f3324096d88 s->prefetch_data=0
    2017-12-11 20:43:09.977993 7f32dbff7700 10 cache get: name=default.rgw.data.root+test2 : type miss (requested=22, cached=19)
    2017-12-11 20:43:09.978689 7f32dbff7700 10 cache put: name=default.rgw.data.root+test2 info.flags=22
    2017-12-11 20:43:09.978694 7f32dbff7700 10 moving default.rgw.data.root+test2 to cache LRU end
    2017-12-11 20:43:09.978698 7f32dbff7700 10 updating xattr: name=user.rgw.acl bl.length()=183
    2017-12-11 20:43:09.978701 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:09.978703 7f32dbff7700 20 Read xattr: user.rgw.acl
    2017-12-11 20:43:09.978704 7f32dbff7700 20 Read xattr: user.rgw.idtag
    2017-12-11 20:43:09.978704 7f32dbff7700 20 Read xattr: user.rgw.manifest
    2017-12-11 20:43:09.978707 7f32dbff7700 10 cache get: name=default.rgw.data.root+test2 : hit (requested=17, cached=23)
    2017-12-11 20:43:09.978716 7f32dbff7700 20 rgw_get_bucket_info: bucket instance: test2({i=default.rgw.buckets.index,e=default.rgw.buckets.non-ec}default.rgw.buckets.data[14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54097.1])
    2017-12-11 20:43:09.978721 7f32dbff7700 20 reading from default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1
    2017-12-11 20:43:09.978725 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbff0ff0 obj=default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 state=0x7f332409dc38 s->prefetch_data=0
    2017-12-11 20:43:09.978728 7f32dbff7700 10 cache get: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : hit (requested=22, cached=23)
    2017-12-11 20:43:09.978731 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:09.978732 7f32dbff7700 20 Read xattr: user.rgw.acl
    2017-12-11 20:43:09.978733 7f32dbff7700 20 Read xattr: user.rgw.idtag
    2017-12-11 20:43:09.978733 7f32dbff7700 20 Read xattr: user.rgw.manifest
    2017-12-11 20:43:09.978734 7f32dbff7700 10 cache get: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : hit (requested=17, cached=23)
    2017-12-11 20:43:09.978742 7f32dbff7700 10 chain_cache_entry: cache_locator=default.rgw.data.root+test2
    2017-12-11 20:43:09.978743 7f32dbff7700 10 chain_cache_entry: cache_locator=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1
    2017-12-11 20:43:09.978758 7f32dbff7700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>test</ID><DisplayName>test</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>test</ID><DisplayName>test</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
    2017-12-11 20:43:09.978766 7f32dbff7700  2 req 2:0.000967:s3:PUT /test2/test20:put_obj:recalculating target
    2017-12-11 20:43:09.978769 7f32dbff7700  2 req 2:0.000969:s3:PUT /test2/test20:put_obj:reading permissions
    2017-12-11 20:43:09.978771 7f32dbff7700  2 req 2:0.000972:s3:PUT /test2/test20:put_obj:init op
    2017-12-11 20:43:09.978773 7f32dbff7700  2 req 2:0.000973:s3:PUT /test2/test20:put_obj:verifying op mask
    2017-12-11 20:43:09.978774 7f32dbff7700 20 required_mask= 2 user.op_mask=7
    2017-12-11 20:43:09.978775 7f32dbff7700  2 req 2:0.000975:s3:PUT /test2/test20:put_obj:verifying op permissions
    2017-12-11 20:43:09.978777 7f32dbff7700  5 Searching permissions for uid=test mask=50
    2017-12-11 20:43:09.978778 7f32dbff7700  5 Found permission: 15
    2017-12-11 20:43:09.978779 7f32dbff7700  5 Searching permissions for group=1 mask=50
    2017-12-11 20:43:09.978780 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:09.978781 7f32dbff7700  5 Searching permissions for group=2 mask=50
    2017-12-11 20:43:09.978781 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:09.978782 7f32dbff7700  5 Getting permissions id=test owner=test perm=2
    2017-12-11 20:43:09.978783 7f32dbff7700 10  uid=test requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
    2017-12-11 20:43:09.978784 7f32dbff7700  2 req 2:0.000984:s3:PUT /test2/test20:put_obj:verifying op params
    2017-12-11 20:43:09.978785 7f32dbff7700  2 req 2:0.000986:s3:PUT /test2/test20:put_obj:pre-executing
    2017-12-11 20:43:09.978787 7f32dbff7700  2 req 2:0.000987:s3:PUT /test2/test20:put_obj:executing
    2017-12-11 20:43:11.812538 7f332e7fc700  2 RGWDataChangesLog::ChangesRenewThread: start
    2017-12-11 20:43:12.306424 7f32dbff7700 10 x>> x-amz-date:Mon, 11 Dec 2017 19:43:09 +0000
    2017-12-11 20:43:13.228311 7f32dbff7700 20 get_obj_state: rctx=0x7f32dbff0ff0 obj=test2:_multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.1 state=0x7f3324096088 s->prefetch_data=0
    2017-12-11 20:43:13.229054 7f32dbff7700 20 get_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:13.229065 7f32dbff7700 20 get_obj_state: rctx=0x7f32dbff0ff0 obj=test2:_multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.1 state=0x7f3324096088 s->prefetch_data=0
    2017-12-11 20:43:13.229068 7f32dbff7700 20 prepare_atomic_modification: state is not atomic. state=0x7f3324096088
    2017-12-11 20:43:13.229093 7f32dbff7700 20 reading from default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1
    2017-12-11 20:43:13.229099 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbfef5d0 obj=default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 state=0x7f3324094898 s->prefetch_data=0
    2017-12-11 20:43:13.229105 7f32dbff7700 10 cache get: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : hit (requested=22, cached=23)
    2017-12-11 20:43:13.229111 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:13.229113 7f32dbff7700 10 cache get: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : hit (requested=17, cached=23)
    2017-12-11 20:43:13.229128 7f32dbff7700 20  bucket index object: .dir.14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1.29
    2017-12-11 20:43:13.481192 7f32dbff7700 15 omap_set bucket=test2({i=default.rgw.buckets.index,e=default.rgw.buckets.non-ec}default.rgw.buckets.data[14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54097.1]) oid=14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54097.1__multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.meta key=part.00000001
    2017-12-11 20:43:13.686284 7f32dbff7700  2 req 2:3.708485:s3:PUT /test2/test20:put_obj:completing
    2017-12-11 20:43:13.686347 7f32dbff7700  2 req 2:3.708548:s3:PUT /test2/test20:put_obj:op status=0
    2017-12-11 20:43:13.686347 7f32dbff7700  2 req 2:3.708548:s3:PUT /test2/test20:put_obj:http status=200
    2017-12-11 20:43:13.686348 7f32dbff7700  1 ====== req done req=0x7f32dbff18a0 op status=0 http_status=200 ======
    2017-12-11 20:43:13.686401 7f32dbff7700  1 civetweb: 0x7f332401db40: 127.0.0.1 - - [11/Dec/2017:20:43:09 +0100] "PUT /test2/test20 HTTP/1.1" 200 0 - 
    2017-12-11 20:43:13.728566 7f32dbff7700 20 RGWEnv::set(): HTTP_HOST: localhost
    2017-12-11 20:43:13.728588 7f32dbff7700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: identity
    2017-12-11 20:43:13.728596 7f32dbff7700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS 8YG56CKA4E4G31WX606U:PqFA9BqbFeMJeZMtTm3tK7YWkuU=
    2017-12-11 20:43:13.728601 7f32dbff7700 20 RGWEnv::set(): CONTENT_LENGTH: 5242880
    2017-12-11 20:43:13.728603 7f32dbff7700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: Mon, 11 Dec 2017 19:43:13 +0000
    2017-12-11 20:43:13.728605 7f32dbff7700 20 RGWEnv::set(): REQUEST_METHOD: PUT
    2017-12-11 20:43:13.728607 7f32dbff7700 20 RGWEnv::set(): REQUEST_URI: /test2/test20
    2017-12-11 20:43:13.728609 7f32dbff7700 20 RGWEnv::set(): QUERY_STRING: partNumber=2&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:13.728611 7f32dbff7700 20 RGWEnv::set(): REMOTE_USER: 
    2017-12-11 20:43:13.728613 7f32dbff7700 20 RGWEnv::set(): SCRIPT_URI: /test2/test20
    2017-12-11 20:43:13.728617 7f32dbff7700 20 RGWEnv::set(): SERVER_PORT: 80
    2017-12-11 20:43:13.728618 7f32dbff7700 20 CONTENT_LENGTH=5242880
    2017-12-11 20:43:13.728620 7f32dbff7700 20 HTTP_ACCEPT_ENCODING=identity
    2017-12-11 20:43:13.728621 7f32dbff7700 20 HTTP_AUTHORIZATION=AWS 8YG56CKA4E4G31WX606U:PqFA9BqbFeMJeZMtTm3tK7YWkuU=
    2017-12-11 20:43:13.728622 7f32dbff7700 20 HTTP_HOST=localhost
    2017-12-11 20:43:13.728623 7f32dbff7700 20 HTTP_X_AMZ_DATE=Mon, 11 Dec 2017 19:43:13 +0000
    2017-12-11 20:43:13.728624 7f32dbff7700 20 QUERY_STRING=partNumber=2&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:13.728625 7f32dbff7700 20 REMOTE_USER=
    2017-12-11 20:43:13.728626 7f32dbff7700 20 REQUEST_METHOD=PUT
    2017-12-11 20:43:13.728626 7f32dbff7700 20 REQUEST_URI=/test2/test20
    2017-12-11 20:43:13.728628 7f32dbff7700 20 SCRIPT_URI=/test2/test20
    2017-12-11 20:43:13.728629 7f32dbff7700 20 SERVER_PORT=80
    2017-12-11 20:43:13.728631 7f32dbff7700  1 ====== starting new request req=0x7f32dbff18a0 =====
    2017-12-11 20:43:13.728653 7f32dbff7700  2 req 3:0.000022::PUT /test2/test20::initializing for trans_id = tx000000000000000000003-005a2edfd1-d64b-default
    2017-12-11 20:43:13.728665 7f32dbff7700 10 rgw api priority: s3=5 s3website=4
    2017-12-11 20:43:13.728667 7f32dbff7700 10 host=localhost
    2017-12-11 20:43:13.728670 7f32dbff7700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
    2017-12-11 20:43:13.728673 7f32dbff7700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s>info.domain= s->info.request_uri=/test2/test20
    2017-12-11 20:43:13.728683 7f32dbff7700 10 meta>> HTTP_X_AMZ_DATE
    2017-12-11 20:43:13.728690 7f32dbff7700 10 x>> x-amz-date:Mon, 11 Dec 2017 19:43:13 +0000
    2017-12-11 20:43:13.728712 7f32dbff7700 20 get_handler handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:13.728718 7f32dbff7700 10 handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:13.728721 7f32dbff7700  2 req 3:0.000090:s3:PUT /test2/test20::getting op 1
    2017-12-11 20:43:13.728726 7f32dbff7700 10 op=21RGWPutObj_ObjStore_S3
    2017-12-11 20:43:13.728728 7f32dbff7700  2 req 3:0.000097:s3:PUT /test2/test20:put_obj:authorizing
    2017-12-11 20:43:13.728764 7f32dbff7700 10 get_canon_resource(): dest=/test2/test20?partNumber=2&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:13.728767 7f32dbff7700 10 auth_hdr:
    PUT
x-amz-date:Mon, 11 Dec 2017 19:43:13 0000
    /test2/test20?partNumber=2&uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:13.728825 7f32dbff7700 15 calculated digest=PqFA9BqbFeMJeZMtTm3tK7YWkuU=
    2017-12-11 20:43:13.728827 7f32dbff7700 15 auth_sign=PqFA9BqbFeMJeZMtTm3tK7YWkuU=
    2017-12-11 20:43:13.728829 7f32dbff7700 15 compare=0
    2017-12-11 20:43:13.728832 7f32dbff7700  2 req 3:0.000201:s3:PUT /test2/test20:put_obj:normalizing buckets and tenants
    2017-12-11 20:43:13.728836 7f32dbff7700 10 s->object=test20 s->bucket=test2
    2017-12-11 20:43:13.728840 7f32dbff7700  2 req 3:0.000209:s3:PUT /test2/test20:put_obj:init permissions
    2017-12-11 20:43:13.728873 7f32dbff7700 15 decode_policy Read AccessControlPolicy&lt;AccessControlPolicy xmlns=&quot;http://s3.amazonaws.com/doc/2006-03-01/&amp;quot;&amp;gt;&amp;lt;Owner&amp;gt;&amp;lt;ID&amp;gt;test&amp;lt;/ID&amp;gt;&amp;lt;DisplayName&amp;gt;test&amp;lt;/DisplayName&amp;gt;&amp;lt;/Owner&amp;gt;&amp;lt;AccessControlList&amp;gt;&amp;lt;Grant&amp;gt;&amp;lt;Grantee xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&amp;quot; xsi:type=&quot;CanonicalUser&quot;&gt;&lt;ID&gt;test&lt;/ID&gt;&lt;DisplayName&gt;test&lt;/DisplayName&gt;&lt;/Grantee&gt;&lt;Permission&gt;FULL_CONTROL&lt;/Permission&gt;&lt;/Grant&gt;&lt;/AccessControlList&gt;&lt;/AccessControlPolicy&gt;
    2017-12-11 20:43:13.728895 7f32dbff7700  2 req 3:0.000264:s3:PUT /test2/test20:put_obj:recalculating target
    2017-12-11 20:43:13.728899 7f32dbff7700  2 req 3:0.000268:s3:PUT /test2/test20:put_obj:reading permissions
    2017-12-11 20:43:13.728903 7f32dbff7700  2 req 3:0.000272:s3:PUT /test2/test20:put_obj:init op
    2017-12-11 20:43:13.728906 7f32dbff7700  2 req 3:0.000275:s3:PUT /test2/test20:put_obj:verifying op mask
    2017-12-11 20:43:13.728908 7f32dbff7700 20 required_mask= 2 user.op_mask=7
    2017-12-11 20:43:13.728910 7f32dbff7700  2 req 3:0.000279:s3:PUT /test2/test20:put_obj:verifying op permissions
    2017-12-11 20:43:13.728913 7f32dbff7700  5 Searching permissions for uid=test mask=50
    2017-12-11 20:43:13.728915 7f32dbff7700  5 Found permission: 15
    2017-12-11 20:43:13.728917 7f32dbff7700  5 Searching permissions for group=1 mask=50
    2017-12-11 20:43:13.728918 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:13.728920 7f32dbff7700  5 Searching permissions for group=2 mask=50
    2017-12-11 20:43:13.728921 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:13.728922 7f32dbff7700  5 Getting permissions id=test owner=test perm=2
    2017-12-11 20:43:13.728923 7f32dbff7700 10  uid=test requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
    2017-12-11 20:43:13.728925 7f32dbff7700  2 req 3:0.000294:s3:PUT /test2/test20:put_obj:verifying op params
    2017-12-11 20:43:13.728927 7f32dbff7700  2 req 3:0.000297:s3:PUT /test2/test20:put_obj:pre-executing
    2017-12-11 20:43:13.728930 7f32dbff7700  2 req 3:0.000299:s3:PUT /test2/test20:put_obj:executing
    2017-12-11 20:43:14.663390 7f32dbff7700 10 x>> x-amz-date:Mon, 11 Dec 2017 19:43:13 +0000
    2017-12-11 20:43:18.123879 7f32dbff7700 20 get_obj_state: rctx=0x7f32dbff0ff0 obj=test2:_multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.2 state=0x7f33240a20f8 s->prefetch_data=0
    2017-12-11 20:43:18.124414 7f32dbff7700 20 get_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:18.124424 7f32dbff7700 20 get_obj_state: rctx=0x7f32dbff0ff0 obj=test2:_multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.2 state=0x7f33240a20f8 s->prefetch_data=0
    2017-12-11 20:43:18.124426 7f32dbff7700 20 prepare_atomic_modification: state is not atomic. state=0x7f33240a20f8
    2017-12-11 20:43:18.124451 7f32dbff7700 20 reading from default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1
    2017-12-11 20:43:18.124457 7f32dbff7700 20 get_system_obj_state: rctx=0x7f32dbfef5d0 obj=default.rgw.data.root:.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 state=0x7f33240a0c28 s->prefetch_data=0
    2017-12-11 20:43:18.124462 7f32dbff7700 10 cache get: name=default.rgw.data.root.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : hit (requested=22, cached=23)
    2017-12-11 20:43:18.124468 7f32dbff7700 20 get_system_obj_state: s->obj_tag was set empty
    2017-12-11 20:43:18.124471 7f32dbff7700 10 cache get: name=default.rgw.data.root+.bucket.meta.test2:14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1 : hit (requested=17, cached=23)
    2017-12-11 20:43:18.124485 7f32dbff7700 20  bucket index object: .dir.14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1.29
    2017-12-11 20:43:19.120807 7f32dbff7700 15 omap_set bucket=test2(@{i=default.rgw.buckets.index,e=default.rgw.buckets.non-ec}default.rgw.buckets.data[14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54097.1]) oid=14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54097.1__multipart_test20.2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS.meta key=part.00000002
    2017-12-11 20:43:19.588347 7f32dbff7700  2 req 3:5.859715:s3:PUT /test2/test20:put_obj:completing
    2017-12-11 20:43:19.588433 7f32dbff7700  2 req 3:5.859801:s3:PUT /test2/test20:put_obj:op status=0
    2017-12-11 20:43:19.588438 7f32dbff7700  2 req 3:5.859807:s3:PUT /test2/test20:put_obj:http status=200
    2017-12-11 20:43:19.588450 7f32dbff7700  1 ====== req done req=0x7f32dbff18a0 op status=0 http_status=200 ======
    2017-12-11 20:43:19.588498 7f32dbff7700  1 civetweb: 0x7f332401db40: 127.0.0.1 - - [11/Dec/2017:20:43:13 +0100] "PUT /test2/test20 HTTP/1.1" 200 0 - 
    2017-12-11 20:43:19.590463 7f32dbff7700 20 RGWEnv::set(): HTTP_HOST: localhost
    2017-12-11 20:43:19.590476 7f32dbff7700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: identity
    2017-12-11 20:43:19.590478 7f32dbff7700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS 8YG56CKA4E4G31WX606U:ZY1p8gEsoMjJUio6gJSjkzOGKUI=
    2017-12-11 20:43:19.590480 7f32dbff7700 20 RGWEnv::set(): CONTENT_LENGTH: 219
    2017-12-11 20:43:19.590482 7f32dbff7700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: Mon, 11 Dec 2017 19:43:19 +0000
    2017-12-11 20:43:19.590484 7f32dbff7700 20 RGWEnv::set(): REQUEST_METHOD: POST
    2017-12-11 20:43:19.590492 7f32dbff7700 20 RGWEnv::set(): REQUEST_URI: /test2/test20
    2017-12-11 20:43:19.590493 7f32dbff7700 20 RGWEnv::set(): QUERY_STRING: uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:19.590495 7f32dbff7700 20 RGWEnv::set(): REMOTE_USER: 
    2017-12-11 20:43:19.590496 7f32dbff7700 20 RGWEnv::set(): SCRIPT_URI: /test2/test20
    2017-12-11 20:43:19.590496 7f32dbff7700 20 RGWEnv::set(): SERVER_PORT: 80
    2017-12-11 20:43:19.590497 7f32dbff7700 20 CONTENT_LENGTH=219
    2017-12-11 20:43:19.590498 7f32dbff7700 20 HTTP_ACCEPT_ENCODING=identity
    2017-12-11 20:43:19.590499 7f32dbff7700 20 HTTP_AUTHORIZATION=AWS 8YG56CKA4E4G31WX606U:ZY1p8gEsoMjJUio6gJSjkzOGKUI=
    2017-12-11 20:43:19.590500 7f32dbff7700 20 HTTP_HOST=localhost
    2017-12-11 20:43:19.590501 7f32dbff7700 20 HTTP_X_AMZ_DATE=Mon, 11 Dec 2017 19:43:19 +0000
    2017-12-11 20:43:19.590502 7f32dbff7700 20 QUERY_STRING=uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:19.590503 7f32dbff7700 20 REMOTE_USER=
    2017-12-11 20:43:19.590504 7f32dbff7700 20 REQUEST_METHOD=POST
    2017-12-11 20:43:19.590505 7f32dbff7700 20 REQUEST_URI=/test2/test20
    2017-12-11 20:43:19.590506 7f32dbff7700 20 SCRIPT_URI=/test2/test20
    2017-12-11 20:43:19.590507 7f32dbff7700 20 SERVER_PORT=80
    2017-12-11 20:43:19.590509 7f32dbff7700  1 ====== starting new request req=0x7f32dbff18a0 =====
    2017-12-11 20:43:19.590525 7f32dbff7700  2 req 4:0.000016::POST /test2/test20::initializing for trans_id = tx000000000000000000004-005a2edfd7-d64b-default
    2017-12-11 20:43:19.590535 7f32dbff7700 10 rgw api priority: s3=5 s3website=4
    2017-12-11 20:43:19.590538 7f32dbff7700 10 host=localhost
    2017-12-11 20:43:19.590541 7f32dbff7700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
    2017-12-11 20:43:19.590544 7f32dbff7700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s>info.domain= s->info.request_uri=/test2/test20
    2017-12-11 20:43:19.590554 7f32dbff7700 10 meta>> HTTP_X_AMZ_DATE
    2017-12-11 20:43:19.590562 7f32dbff7700 10 x>> x-amz-date:Mon, 11 Dec 2017 19:43:19 +0000
    2017-12-11 20:43:19.590580 7f32dbff7700 20 get_handler handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:19.590586 7f32dbff7700 10 handler=22RGWHandler_REST_Obj_S3
    2017-12-11 20:43:19.590589 7f32dbff7700  2 req 4:0.000080:s3:POST /test2/test20::getting op 4
    2017-12-11 20:43:19.590593 7f32dbff7700 10 op=32RGWCompleteMultipart_ObjStore_S3
    2017-12-11 20:43:19.590596 7f32dbff7700  2 req 4:0.000086:s3:POST /test2/test20:complete_multipart:authorizing
    2017-12-11 20:43:19.590632 7f32dbff7700 10 get_canon_resource(): dest=/test2/test20?uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:19.590636 7f32dbff7700 10 auth_hdr:
    POST
x-amz-date:Mon, 11 Dec 2017 19:43:19 +0000
    /test2/test20?uploadId=2~ZeDpjz2X_RjnxlZGm3Tsg_v3HUBwLdS
    2017-12-11 20:43:19.590681 7f32dbff7700 15 calculated digest=ZY1p8gEsoMjJUio6gJSjkzOGKUI=
    2017-12-11 20:43:19.590684 7f32dbff7700 15 auth_sign=ZY1p8gEsoMjJUio6gJSjkzOGKUI=
    2017-12-11 20:43:19.590685 7f32dbff7700 15 compare=0
    2017-12-11 20:43:19.590689 7f32dbff7700  2 req 4:0.000180:s3:POST /test2/test20:complete_multipart:normalizing buckets and tenants
    2017-12-11 20:43:19.590693 7f32dbff7700 10 s->object=test20 s->bucket=test2
    2017-12-11 20:43:19.590697 7f32dbff7700  2 req 4:0.000187:s3:POST /test2/test20:complete_multipart:init permissions
    2017-12-11 20:43:19.590724 7f32dbff7700 15 decode_policy Read AccessControlPolicy&lt;AccessControlPolicy xmlns=&quot;http://s3.amazonaws.com/doc/2006-03-01/&amp;quot;&amp;gt;&amp;lt;Owner&amp;gt;&amp;lt;ID&amp;gt;test&amp;lt;/ID&amp;gt;&amp;lt;DisplayName&amp;gt;test&amp;lt;/DisplayName&amp;gt;&amp;lt;/Owner&amp;gt;&amp;lt;AccessControlList&amp;gt;&amp;lt;Grant&amp;gt;&amp;lt;Grantee xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&amp;quot; xsi:type=&quot;CanonicalUser&quot;&gt;&lt;ID&gt;test&lt;/ID&gt;&lt;DisplayName&gt;test&lt;/DisplayName&gt;&lt;/Grantee&gt;&lt;Permission&gt;FULL_CONTROL&lt;/Permission&gt;&lt;/Grant&gt;&lt;/AccessControlList&gt;&lt;/AccessControlPolicy&gt;
    2017-12-11 20:43:19.590738 7f32dbff7700  2 req 4:0.000228:s3:POST /test2/test20:complete_multipart:recalculating target
    2017-12-11 20:43:19.590742 7f32dbff7700  2 req 4:0.000233:s3:POST /test2/test20:complete_multipart:reading permissions
    2017-12-11 20:43:19.590745 7f32dbff7700  2 req 4:0.000236:s3:POST /test2/test20:complete_multipart:init op
    2017-12-11 20:43:19.590749 7f32dbff7700  2 req 4:0.000240:s3:POST /test2/test20:complete_multipart:verifying op mask
    2017-12-11 20:43:19.590751 7f32dbff7700 20 required_mask= 2 user.op_mask=7
    2017-12-11 20:43:19.590753 7f32dbff7700  2 req 4:0.000244:s3:POST /test2/test20:complete_multipart:verifying op permissions
    2017-12-11 20:43:19.590757 7f32dbff7700  5 Searching permissions for uid=test mask=50
    2017-12-11 20:43:19.590759 7f32dbff7700  5 Found permission: 15
    2017-12-11 20:43:19.590761 7f32dbff7700  5 Searching permissions for group=1 mask=50
    2017-12-11 20:43:19.590762 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:19.590764 7f32dbff7700  5 Searching permissions for group=2 mask=50
    2017-12-11 20:43:19.590766 7f32dbff7700  5 Permissions for group not found
    2017-12-11 20:43:19.590766 7f32dbff7700  5 Getting permissions id=test owner=test perm=2
    2017-12-11 20:43:19.590768 7f32dbff7700 10  uid=test requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
    2017-12-11 20:43:19.590770 7f32dbff7700  2 req 4:0.000261:s3:POST /test2/test20:complete_multipart:verifying op params
    2017-12-11 20:43:19.590772 7f32dbff7700  2 req 4:0.000263:s3:POST /test2/test20:complete_multipart:pre-executing
    2017-12-11 20:43:19.590775 7f32dbff7700  2 req 4:0.000265:s3:POST /test2/test20:complete_multipart:executing
    2017-12-11 20:43:19.591963 7f32dbff7700  0 RGWCompleteMultipart::execute() failed to acquire lock 
    2017-12-11 20:43:19.591989 7f32dbff7700  2 req 4:0.001479:s3:POST /test2/test20:complete_multipart:completing
    2017-12-11 20:43:19.592063 7f32dbff7700  2 req 4:0.001553:s3:POST /test2/test20:complete_multipart:op status=-2200
    2017-12-11 20:43:19.592068 7f32dbff7700  2 req 4:0.001559:s3:POST /test2/test20:complete_multipart:http status=500
    2017-12-11 20:43:19.592072 7f32dbff7700  1 ====== req done req=0x7f32dbff18a0 op status=-2200 http_status=500 ======
    2017-12-11 20:43:19.592084 7f32dbff7700 20 process_request() returned -2200
    2017-12-11 20:43:19.592102 7f32dbff7700  1 civetweb: 0x7f332401db40: 127.0.0.1 - - [11/Dec/2017:20:43:19 +0100] "POST /test2/test20 HTTP/1.1" 500 0 - -

10.2.9 worked fine, so it might have to do something with this commit: https://github.com/ceph/ceph/commit/37dec0227a9522e730baabb9c7428f007ba9c202#diff-91c04dc5e6532eab0d6f52eec3d03b1e

Files

debugms1 (106 KB) debugms1 Log output debug ms = 1 Karol Babioch, 12/11/2017 09:41 PM

Related issues 2 (0 open — 2 closed)

Related to rgw - Backport #20900: jewel: Object data loss in RGW when multipart upload completion times outResolvedMatt BenjaminActions
Is duplicate of rgw - Backport #21873: jewel: failed CompleteMultipartUpload request does not release lockResolvedMatt BenjaminActions
Actions
Copy link
 #1

Updated by Casey Bodley over 6 years ago

it's hard to tell where that RGWCompleteMultipart::execute() error is coming from here - can you please capture another log with debug_ms=1? that should tell us the osd return code, and which raw rados object names are being used

Actions
Copy link
 #2

Updated by Karol Babioch over 6 years ago

Here is the log with debug ms = 1. Thank you for looking into it!

Actions
Copy link
 #3

Updated by Casey Bodley over 6 years ago

  • Assignee set to Casey Bodley
  • Priority changed from Normal to Urgent

log shows the use of two different object names between the InitMultipart and CompleteMultipart operations:

14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54097.1__multipart_foo.2~QxYlcF6enTAQQfW00H_wDgfIYgvT5xG.meta
14935c5a-4f59-43ef-bd3c-2a8af0231d5b.54857.1__multipart_foo.2~QxYlcF6enTAQQfW00H_wDgfIYgvT5xG.meta

the part before '__multipart_foo' is the bucket_id, which changes on reshard. it looks like InitMultipart is using the old bucket_id, while Complete uses the new one

Actions
Copy link
 #4

Updated by Karol Babioch over 6 years ago

Yup, that is what we also suspected. Not sure why it is broken in luminous, though. Let us know if there is something else you need from us to narrow this down, and/or if you want us to test something. Thanks again for looking into this.

Actions
Copy link
 #5

Updated by Nicolas Rachinsky over 6 years ago

Casey Bodley wrote:

log shows the use of two different object names between the InitMultipart and CompleteMultipart operations:

[...]

the part before '__multipart_foo' is the bucket_id, which changes on reshard. it looks like InitMultipart is using the old bucket_id, while Complete uses the new one

Thank you very much for looking into this.

The old bucket_id is identical to the marker. The objects are named with the marker if I understand the layout correctly. So shouldn't both use the marker (the first bucket_id)?

Actions
Copy link
 #6

Updated by Casey Bodley over 6 years ago

  • Related to Backport #20900: jewel: Object data loss in RGW when multipart upload completion times out added
Actions
Copy link
 #7

Updated by Casey Bodley over 6 years ago

  • Status changed from New to 7
Actions
Copy link
 #8

Updated by Casey Bodley about 6 years ago

  • Is duplicate of Backport #21873: jewel: failed CompleteMultipartUpload request does not release lock added
Actions
Copy link
 #9

Updated by Casey Bodley about 6 years ago

  • Status changed from 7 to Resolved

the backport is being tracked separately in #21873, closing this one

Actions
Copy link
 #10

Updated by Karol Babioch about 6 years ago

@Casey Bodley: Are you sure marking this as duplicate of #21873 was correct? At least to me it looks like another problem. I just want to make sure that the fix you came up with isn't lost and will finally be merged into the "master" branch.

Actions
Copy link
 #11

Updated by Casey Bodley about 6 years ago

Hi Karol,

While the issues are separate, the backport for #21873 does include the single commit from this one. And this specific issue was never present on luminous or master, as it was introduced by a previous jewel backport. The commit message contains "(this fixes a previous backport, so has no associated commit from master)" to document this.

Actions
Copy link

Also available in: Atom PDF