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

Also available in: Atom PDF