Project

General

Profile

Bug #48571

Multi part upload abort on first put with unknown error -2009

Added by Simon Pierre Desrosiers 3 months ago. Updated about 2 months ago.

Status:
Need More Info
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

Source:
Community (user)
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
ceph-deploy
Pull request ID:
Crash signature:

Description

Hello,

We are trying to configure IBM Cloud Tape Connector to do backup on our Cephs<s S3. Initial Connection happens just fine, the client does a few Heads which returns 200 code. Then a few POST which also return 200 and on the furst PUT, rados return a 404.

10.146.1.13 - - [11/Dec/2020:14:31:23 -0500] "HEAD /S3-VMTLTEST HTTP/1.1" 200 0 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:23 -0500] "HEAD /S3-VMTLTEST HTTP/1.1" 200 0 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:23 -0500] "HEAD /S3-VMTLTEST HTTP/1.1" 200 0 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:23 -0500] "HEAD /S3-VMTLTEST HTTP/1.1" 200 0 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:23 -0500] "HEAD /S3-VMTLTEST HTTP/1.1" 200 0 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2540804?uploads= HTTP/1.1" 200 286 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?uploads= HTTP/1.1" 200 286 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R4503547?uploads= HTTP/1.1" 200 286 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2052731?uploads= HTTP/1.1" 200 286 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42388.CUZCLOUD.R0370939?uploads= HTTP/1.1" 200 286 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?partNumber=1&uploadId=2ZtjbLjH2reZgFREDhgGHxxfeVoK7XdB HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R4503547?partNumber=1&uploadId=2M-kiZpueu6Z6-mAIOJ8WgDQqeHskmmW HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2540804?partNumber=1&uploadId=2ijVk2_JiVItBIa_2cWCVWFGxgLVASek HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2052731?partNumber=1&uploadId=2PPWdD8Xq2FgUQ398bNWIRn5761Sr5t9 HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:26 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42388.CUZCLOUD.R0370939?partNumber=1&uploadId=2j6vxSZ502ox7Htvq5olrkr17BeH83Xp HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R4503547?partNumber=1&uploadId=2M-kiZpueu6Z6-mAIOJ8WgDQqeHskmmW HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?partNumber=1&uploadId=2ZtjbLjH2reZgFREDhgGHxxfeVoK7XdB HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42388.CUZCLOUD.R0370939?partNumber=1&uploadId=2j6vxSZ502ox7Htvq5olrkr17BeH83Xp HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2052731?partNumber=1&uploadId=2PPWdD8Xq2FgUQ398bNWIRn5761Sr5t9 HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2540804?partNumber=1&uploadId=2ijVk2_JiVItBIa_2cWCVWFGxgLVASek HTTP/1.1" 404 248 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R4503547?uploadId=2M-kiZpueu6Z6-mAIOJ8WgDQqeHskmmW HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?uploadId=2ZtjbLjH2reZgFREDhgGHxxfeVoK7XdB HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2540804?uploadId=2ijVk2_JiVItBIa_2cWCVWFGxgLVASek HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42388.CUZCLOUD.R0370939?uploadId=2j6vxSZ502ox7Htvq5olrkr17BeH83Xp HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2052731?uploadId=2PPWdD8Xq2FgUQ398bNWIRn5761Sr5t9 HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R4503547?uploadId=2M-kiZpueu6Z6-mAIOJ8WgDQqeHskmmW HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42388.CUZCLOUD.R0370939?uploadId=2j6vxSZ502ox7Htvq5olrkr17BeH83Xp HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?uploadId=2ZtjbLjH2reZgFREDhgGHxxfeVoK7XdB HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2540804?uploadId=2ijVk2_JiVItBIa_2cWCVWFGxgLVASek HTTP/1.1" 404 223 "-" "-"
10.146.1.13 - - [11/Dec/2020:14:31:27 -0500] "DELETE /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42252.CUZCLOUD.R2052731?uploadId=2PPWdD8Xq2FgUQ398bNWIRn5761Sr5t9 HTTP/1.1" 404 223 "-" "-"

This is snippet is comming from the nginx logs, the reverse proxy in front of the rados gateways.

Here are the logs of the radosGW ( at the maximum 20 level ) :

@
2020-12-11 14:29:13.163 7efe555ae700 20 CONTENT_LENGTH=1730
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=REN49YSX1MZTETD9QZW3/20201211/us-east-1/s3/aws4_request,SignedHeaders=content-length;expect;host;x-amz-content-sha256;x-amz-date,Signature=316351c2e811eb28fdd31295da21c1d10b585d6baa7318f8fbc4a504b24f1ca8
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_CONNECTION=close
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_EXPECT=100-continue
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_HOST=s3.interne.montreal.ca
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_VERSION=1.1
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_X_AMZ_CONTENT_SHA256=410c6cf2894fd7335fe98fd3f6d3a0cc509af163701fb57ed56a716f9b872836
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_X_AMZ_DATE=20201211T192901Z
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_X_FORWARDED_FOR=10.146.1.13
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_X_FORWARDED_PROTO=http
2020-12-11 14:29:13.163 7efe555ae700 20 HTTP_X_REAL_IP=10.146.1.13
2020-12-11 14:29:13.163 7efe555ae700 20 QUERY_STRING=partNumber=1&uploadId=2fsSb8O663B3YT5atpkxyJEuj6i14kOk
2020-12-11 14:29:13.163 7efe555ae700 20 REMOTE_ADDR=10.224.12.17
2020-12-11 14:29:13.163 7efe555ae700 20 REQUEST_METHOD=PUT
2020-12-11 14:29:13.163 7efe555ae700 20 REQUEST_URI=/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
2020-12-11 14:29:13.163 7efe555ae700 20 SCRIPT_URI=/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
2020-12-11 14:29:13.163 7efe555ae700 20 SERVER_PORT=7480
2020-12-11 14:29:13.163 7efe555ae700 1 ====== starting new request req=0x5567abbd2700 =====
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s initializing for trans_id = tx000000000000000179c5b-005fd3c889-d0c1d-default
2020-12-11 14:29:13.163 7efe555ae700 10 rgw api priority: s3=8 s3website=7
2020-12-11 14:29:13.163 7efe555ae700 10 host=s3.interne.montreal.ca
2020-12-11 14:29:13.163 7efe555ae700 20 subdomain= domain=s3.interne.montreal.ca in_hosted_domain=1 in_hosted_domain_s3website=0
2020-12-11 14:29:13.163 7efe555ae700 20 final domain/bucket subdomain= domain=s3.interne.montreal.ca in_hosted_domain=1 in_hosted_domain_s3website=0 s->info.domain=s3.interne.montreal.ca s->info.request_uri=/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
2020-12-11 14:29:13.163 7efe555ae700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2020-12-11 14:29:13.163 7efe555ae700 10 meta>> HTTP_X_AMZ_DATE
2020-12-11 14:29:13.163 7efe555ae700 10 x>> x-amz-content-sha256:410c6cf2894fd7335fe98fd3f6d3a0cc509af163701fb57ed56a716f9b872836
2020-12-11 14:29:13.163 7efe555ae700 10 x>> x-amz-date:20201211T192901Z
2020-12-11 14:29:13.163 7efe555ae700 20 get_handler handler=22RGWHandler_REST_Obj_S3
2020-12-11 14:29:13.163 7efe555ae700 10 handler=22RGWHandler_REST_Obj_S3
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s getting op 1
2020-12-11 14:29:13.163 7efe555ae700 10 req 1547355 0.000s s3:put_obj scheduling with dmclock client=2 cost=1
2020-12-11 14:29:13.163 7efe555ae700 10 op=21RGWPutObj_ObjStore_S3
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj verifying requester
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj rgw::auth::StrategyRegistry::s3_main_strategy_t: trying rgw::auth::s3::AWSAuthStrategy
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::S3AnonymousEngine
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj rgw::auth::s3::S3AnonymousEngine denied with reason=-1
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::LocalEngine
2020-12-11 14:29:13.163 7efe555ae700 10 v4 signature format = 316351c2e811eb28fdd31295da21c1d10b585d6baa7318f8fbc4a504b24f1ca8
2020-12-11 14:29:13.163 7efe555ae700 10 v4 credential format = REN49YSX1MZTETD9QZW3/20201211/us-east-1/s3/aws4_request
2020-12-11 14:29:13.163 7efe555ae700 10 access key id = REN49YSX1MZTETD9QZW3
2020-12-11 14:29:13.163 7efe555ae700 10 credential scope = 20201211/us-east-1/s3/aws4_request
2020-12-11 14:29:13.163 7efe555ae700 10 canonical headers format = content-length:1730
expect:100-continue
host:s3.interne.montreal.ca
x-amz-content-sha256:410c6cf2894fd7335fe98fd3f6d3a0cc509af163701fb57ed56a716f9b872836
x-amz-date:20201211T192901Z

2020-12-11 14:29:13.163 7efe555ae700 10 payload request hash = 410c6cf2894fd7335fe98fd3f6d3a0cc509af163701fb57ed56a716f9b872836
2020-12-11 14:29:13.163 7efe555ae700 10 canonical request = PUT
/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
partNumber=1&uploadId=2fsSb8O663B3YT5atpkxyJEuj6i14kOk
content-length:1730
expect:100-continue
host:s3.interne.montreal.ca
x-amz-content-sha256:410c6cf2894fd7335fe98fd3f6d3a0cc509af163701fb57ed56a716f9b872836
x-amz-date:20201211T192901Z

content-length;expect;host;x-amz-content-sha256;x-amz-date
410c6cf2894fd7335fe98fd3f6d3a0cc509af163701fb57ed56a716f9b872836
2020-12-11 14:29:13.163 7efe555ae700 10 canonical request hash = 311a07eee03fd02f30928754a41526b9be644afc290185586ffb93a75ff9d16b
2020-12-11 14:29:13.163 7efe555ae700 10 string to sign = AWS4-HMAC-SHA256
20201211T192901Z
20201211/us-east-1/s3/aws4_request
311a07eee03fd02f30928754a41526b9be644afc290185586ffb93a75ff9d16b
2020-12-11 14:29:13.163 7efe555ae700 10 delaying v4 auth
2020-12-11 14:29:13.163 7efe555ae700 10 date_k = 4653868db95153f7ef693460c42c9475db4eeb59a2a0588cfda445a9a8703c5a
2020-12-11 14:29:13.163 7efe555ae700 10 region_k = 4384b17bf60edc1b7ce45cc7b5312ac1fc2c166979099261e64f83d2d5a2fbd2
2020-12-11 14:29:13.163 7efe555ae700 10 service_k = 4375a67425f692c63bce20f83681a42ad60970eec027227cf96c46b243217966
2020-12-11 14:29:13.163 7efe555ae700 10 signing_k = a55b01d80378e2771f49a06cb496b9af73601b582619f7ee85b66cf4a433e323
2020-12-11 14:29:13.163 7efe555ae700 10 generated signature = 316351c2e811eb28fdd31295da21c1d10b585d6baa7318f8fbc4a504b24f1ca8
2020-12-11 14:29:13.163 7efe555ae700 15 req 1547355 0.000s s3:put_obj string_to_sign=AWS4-HMAC-SHA256
20201211T192901Z
20201211/us-east-1/s3/aws4_request
311a07eee03fd02f30928754a41526b9be644afc290185586ffb93a75ff9d16b
2020-12-11 14:29:13.163 7efe555ae700 15 req 1547355 0.000s s3:put_obj server signature=316351c2e811eb28fdd31295da21c1d10b585d6baa7318f8fbc4a504b24f1ca8
2020-12-11 14:29:13.163 7efe555ae700 15 req 1547355 0.000s s3:put_obj client signature=316351c2e811eb28fdd31295da21c1d10b585d6baa7318f8fbc4a504b24f1ca8
2020-12-11 14:29:13.163 7efe555ae700 15 req 1547355 0.000s s3:put_obj compare=0
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj rgw::auth::s3::LocalEngine granted access
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj rgw::auth::s3::AWSAuthStrategy granted access
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj normalizing buckets and tenants
2020-12-11 14:29:13.163 7efe555ae700 10 s->object=CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779 s->bucket=S3-VMTLTEST
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj init permissions
2020-12-11 14:29:13.163 7efe555ae700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>OC</ID><DisplayName>Ordinateur Central</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>OC</ID><DisplayName>Ordinateur Central</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2020-12-11 14:29:13.163 7efe555ae700 20 get_system_obj_state: rctx=0x5567abbd1130 obj=default.rgw.meta:users.uid:OC state=0x5567ab4fcac0 s->prefetch_data=0
2020-12-11 14:29:13.163 7efe555ae700 10 cache get: name=default.rgw.meta+users.uid+OC : hit (requested=0x6, cached=0x17)
2020-12-11 14:29:13.163 7efe555ae700 20 get_system_obj_state: s->obj_tag was set empty
2020-12-11 14:29:13.163 7efe555ae700 20 Read xattr: user.rgw.idtag
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj recalculating target
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj reading permissions
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj init op
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj verifying op mask
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj required_mask= 2 user.op_mask=7
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj verifying op permissions
2020-12-11 14:29:13.163 7efe555ae700 20 req 1547355 0.000s s3:put_obj -- Getting permissions begin with perm_mask=50
2020-12-11 14:29:13.163 7efe555ae700 5 req 1547355 0.000s s3:put_obj Searching permissions for identity=rgw::auth::SysReqApplier > rgw::auth::LocalApplier(acct_user=OC, acct_name=Ordinateur Central, subuser=, perm_mask=15, is_admin=0) mask=50
2020-12-11 14:29:13.163 7efe555ae700 5 Searching permissions for uid=OC
2020-12-11 14:29:13.163 7efe555ae700 5 Found permission: 15
2020-12-11 14:29:13.163 7efe555ae700 5 Searching permissions for group=1 mask=50
2020-12-11 14:29:13.163 7efe555ae700 5 Permissions for group not found
2020-12-11 14:29:13.163 7efe555ae700 5 Searching permissions for group=2 mask=50
2020-12-11 14:29:13.163 7efe555ae700 5 Permissions for group not found
2020-12-11 14:29:13.163 7efe555ae700 5 req 1547355 0.000s s3:put_obj -
Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=OC, acct_name=Ordinateur Central, subuser=, perm_mask=15, is_admin=0), owner=OC, perm=2
2020-12-11 14:29:13.163 7efe555ae700 10 req 1547355 0.000s s3:put_obj identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=OC, acct_name=Ordinateur Central, subuser=, perm_mask=15, is_admin=0) requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj verifying op params
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj pre-executing
2020-12-11 14:29:13.163 7efe555ae700 2 req 1547355 0.000s s3:put_obj executing
2020-12-11 14:29:13.163 7efe555ae700 20 get_obj_state: rctx=0x5567abbd1e00 obj=S3-VMTLTEST:_multipart_CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779.2fsSb8O663B3YT5atpkxyJEuj6i14kOk.meta state=0x5567af8095a0 s->prefetch_data=1
2020-12-11 14:29:13.164 7efe555ae700 0 req 1547355 0.001s s3:put_obj ERROR: get_multipart_info returned -2009: (2009) Unknown error 2009
2020-12-11 14:29:13.164 7efe555ae700 2 req 1547355 0.001s s3:put_obj completing
2020-12-11 14:29:13.164 7efe555ae700 2 req 1547355 0.001s s3:put_obj op status=-2009
2020-12-11 14:29:13.164 7efe555ae700 2 req 1547355 0.001s s3:put_obj http status=404
2020-12-11 14:29:13.164 7efe555ae700 1 ====== req done req=0x5567abbd2700 op status=-2009 http_status=404 latency=0.0010001s ======
2020-12-11 14:29:13.164 7efe555ae700 1 beast: 0x5567abbd2700: 10.224.12.17 - - [2020-12-11 14:29:13.0.164836s] "PUT /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?partNumber=1&uploadId=2fsSb8O663B3YT5atpkxyJEuj6i14kOk HTTP/1.1" 404 223 - - -
@

We can see

anomalie2 2.zip (805 KB) Simon Pierre Desrosiers, 12/17/2020 04:50 PM

History

#1 Updated by Simon Pierre Desrosiers 3 months ago

I am sorry, the end of my message was lost during edition.

We can see in the rgw output that an unknown error is happening around the end with the get_multipart_info function which returns error -2009. That error is transformed in a http 404 return code.

#2 Updated by Casey Bodley 3 months ago

rgw_common.h:#define ERR_NO_SUCH_UPLOAD 2009
rgw_common.cc: { ERR_NO_SUCH_UPLOAD, {404, "NoSuchUpload" }},

#3 Updated by Matt Benjamin 3 months ago

Can you provide an rgw log segment which shows the required init-multipart-upload step which needs to run before any part is uploaded/PUT?

#4 Updated by Casey Bodley 3 months ago

what is the s3 client? does it support multipart uploads?

#5 Updated by Casey Bodley 3 months ago

  • Status changed from New to Need More Info

#6 Updated by Simon Pierre Desrosiers 3 months ago

I am not sure what exactly you are looking for, but here are the logs for the two rgw server, both in debug log level 20. I have cut the logs based on the nginx log at the top of the ticket.

Hope this help, if I need to clean it up, I can try, but removing all the other request would quite hard.

#7 Updated by Simon Pierre Desrosiers 3 months ago

Casey Bodley wrote:

what is the s3 client? does it support multipart uploads?

The S3 client, as stated at the beginning of the ticket, is IBM Cloud Tape Connector (https://www.ibm.com/support/pages/ibm-cloud-tape-connector-zos) which is a Back Up solution for ZOS that can send vtapes to a S3 storage. The client is the one doing a multi-part upload, so I would guess it feals confident it can do so, but maybe its just hubris. We actually tested uploading using IBM's cloud S3 and it worked fine.

#8 Updated by Simon Pierre Desrosiers 3 months ago

Matt Benjamin wrote:

Can you provide an rgw log segment which shows the required init-multipart-upload step which needs to run before any part is uploaded/PUT?

On second thought, I can extract just the logs for the last PUT message which is in the original post (VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779). This is the logs asscociated with the POST of the PUT message above.

@
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=REN49YSX1MZTETD9QZW3/20201211/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=0ddf9cc3f24043b653f0ffaf096da341f37fb1dbcad6ed62fa6dfb22e19446c3
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_CONNECTION=close
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_HOST=s3.interne.montreal.ca
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_VERSION=1.1
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_X_AMZ_CONTENT_SHA256=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_X_AMZ_DATE=20201211T192859Z
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_X_FORWARDED_FOR=10.146.1.13
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_X_FORWARDED_PROTO=http
2020-12-11 14:29:11.761 7f82e2d26700 20 HTTP_X_REAL_IP=10.146.1.13
2020-12-11 14:29:11.761 7f82e2d26700 20 QUERY_STRING=uploads=
2020-12-11 14:29:11.761 7f82e2d26700 20 REMOTE_ADDR=10.224.12.17
2020-12-11 14:29:11.761 7f82e2d26700 20 REQUEST_METHOD=POST
2020-12-11 14:29:11.761 7f82e2d26700 20 REQUEST_URI=/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
2020-12-11 14:29:11.761 7f82e2d26700 20 SCRIPT_URI=/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
2020-12-11 14:29:11.761 7f82e2d26700 20 SERVER_PORT=7480
2020-12-11 14:29:11.761 7f82e2d26700 1 ====== starting new request req=0x55bc38832700 =====
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s initializing for trans_id = tx00000000000000060d353-005fd3c887-d2f7c-default
2020-12-11 14:29:11.761 7f82e2d26700 10 rgw api priority: s3=8 s3website=7
2020-12-11 14:29:11.761 7f82e2d26700 10 host=s3.interne.montreal.ca
2020-12-11 14:29:11.761 7f82e2d26700 20 subdomain= domain=s3.interne.montreal.ca in_hosted_domain=1 in_hosted_domain_s3website=0
2020-12-11 14:29:11.761 7f82e2d26700 20 final domain/bucket subdomain= domain=s3.interne.montreal.ca in_hosted_domain=1 in_hosted_domain_s3website=0 s->info.domain=s3.interne.montreal.ca s->info.request_uri=/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
2020-12-11 14:29:11.761 7f82e2d26700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2020-12-11 14:29:11.761 7f82e2d26700 10 meta>> HTTP_X_AMZ_DATE
2020-12-11 14:29:11.761 7f82e2d26700 10 x>> x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2020-12-11 14:29:11.761 7f82e2d26700 10 x>> x-amz-date:20201211T192859Z
2020-12-11 14:29:11.761 7f82e2d26700 20 get_handler handler=22RGWHandler_REST_Obj_S3
2020-12-11 14:29:11.761 7f82e2d26700 10 handler=22RGWHandler_REST_Obj_S3
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s getting op 4
2020-12-11 14:29:11.761 7f82e2d26700 10 req 6345555 0.000s s3:init_multipart scheduling with dmclock client=3 cost=1
2020-12-11 14:29:11.761 7f82e2d26700 10 op=28RGWInitMultipart_ObjStore_S3
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart verifying requester
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart rgw::auth::StrategyRegistry::s3_main_strategy_t: trying rgw::auth::s3::AWSAuthStrategy
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::S3AnonymousEngine
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart rgw::auth::s3::S3AnonymousEngine denied with reason=-1
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::LocalEngine
2020-12-11 14:29:11.761 7f82e2d26700 10 v4 signature format = 0ddf9cc3f24043b653f0ffaf096da341f37fb1dbcad6ed62fa6dfb22e19446c3
2020-12-11 14:29:11.761 7f82e2d26700 10 v4 credential format = REN49YSX1MZTETD9QZW3/20201211/us-east-1/s3/aws4_request
2020-12-11 14:29:11.761 7f82e2d26700 10 access key id = REN49YSX1MZTETD9QZW3
2020-12-11 14:29:11.761 7f82e2d26700 10 credential scope = 20201211/us-east-1/s3/aws4_request
2020-12-11 14:29:11.761 7f82e2d26700 10 canonical headers format = host:s3.interne.montreal.ca
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201211T192859Z

2020-12-11 14:29:11.761 7f82e2d26700 10 payload request hash = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2020-12-11 14:29:11.761 7f82e2d26700 10 canonical request = POST
/S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779
uploads=
host:s3.interne.montreal.ca
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201211T192859Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2020-12-11 14:29:11.761 7f82e2d26700 10 canonical request hash = 2f877012c7faae0d1b53dbea804e2013731603d4448a8c2faf8d16847d33030e
2020-12-11 14:29:11.761 7f82e2d26700 10 string to sign = AWS4-HMAC-SHA256
20201211T192859Z
20201211/us-east-1/s3/aws4_request
2f877012c7faae0d1b53dbea804e2013731603d4448a8c2faf8d16847d33030e
2020-12-11 14:29:11.761 7f82e2d26700 10 date_k = 4653868db95153f7ef693460c42c9475db4eeb59a2a0588cfda445a9a8703c5a
2020-12-11 14:29:11.761 7f82e2d26700 10 region_k = 4384b17bf60edc1b7ce45cc7b5312ac1fc2c166979099261e64f83d2d5a2fbd2
2020-12-11 14:29:11.761 7f82e2d26700 10 service_k = 4375a67425f692c63bce20f83681a42ad60970eec027227cf96c46b243217966
2020-12-11 14:29:11.761 7f82e2d26700 10 signing_k = a55b01d80378e2771f49a06cb496b9af73601b582619f7ee85b66cf4a433e323
2020-12-11 14:29:11.761 7f82e2d26700 10 generated signature = 0ddf9cc3f24043b653f0ffaf096da341f37fb1dbcad6ed62fa6dfb22e19446c3
2020-12-11 14:29:11.761 7f82e2d26700 15 req 6345555 0.000s s3:init_multipart string_to_sign=AWS4-HMAC-SHA256
20201211T192859Z
20201211/us-east-1/s3/aws4_request
2f877012c7faae0d1b53dbea804e2013731603d4448a8c2faf8d16847d33030e
2020-12-11 14:29:11.761 7f82e2d26700 15 req 6345555 0.000s s3:init_multipart server signature=0ddf9cc3f24043b653f0ffaf096da341f37fb1dbcad6ed62fa6dfb22e19446c3
2020-12-11 14:29:11.761 7f82e2d26700 15 req 6345555 0.000s s3:init_multipart client signature=0ddf9cc3f24043b653f0ffaf096da341f37fb1dbcad6ed62fa6dfb22e19446c3
2020-12-11 14:29:11.761 7f82e2d26700 15 req 6345555 0.000s s3:init_multipart compare=0
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart rgw::auth::s3::LocalEngine granted access
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart rgw::auth::s3::AWSAuthStrategy granted access
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart normalizing buckets and tenants
2020-12-11 14:29:11.761 7f82e2d26700 10 s->object=CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779 s->bucket=S3-VMTLTEST
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart init permissions
2020-12-11 14:29:11.761 7f82e2d26700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>OC</ID><DisplayName>Ordinateur Central</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>OC</ID><DisplayName>Ordinateur Central</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2020-12-11 14:29:11.761 7f82e2d26700 20 get_system_obj_state: rctx=0x55bc38831130 obj=default.rgw.meta:users.uid:OC state=0x55bc387b4340 s->prefetch_data=0
2020-12-11 14:29:11.761 7f82e2d26700 10 cache get: name=default.rgw.meta+users.uid+OC : hit (requested=0x6, cached=0x17)
2020-12-11 14:29:11.761 7f82e2d26700 20 get_system_obj_state: s->obj_tag was set empty
2020-12-11 14:29:11.761 7f82e2d26700 20 Read xattr: user.rgw.idtag
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart recalculating target
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart reading permissions
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart init op
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart verifying op mask
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart required_mask= 2 user.op_mask=7
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart verifying op permissions
2020-12-11 14:29:11.761 7f82e2d26700 20 req 6345555 0.000s s3:init_multipart -- Getting permissions begin with perm_mask=50
2020-12-11 14:29:11.761 7f82e2d26700 5 req 6345555 0.000s s3:init_multipart Searching permissions for identity=rgw::auth::SysReqApplier > rgw::auth::LocalApplier(acct_user=OC, acct_name=Ordinateur Central, subuser=, perm_mask=15, is_admin=0) mask=50
2020-12-11 14:29:11.761 7f82e2d26700 5 Searching permissions for uid=OC
2020-12-11 14:29:11.761 7f82e2d26700 5 Found permission: 15
2020-12-11 14:29:11.761 7f82e2d26700 5 Searching permissions for group=1 mask=50
2020-12-11 14:29:11.761 7f82e2d26700 5 Permissions for group not found
2020-12-11 14:29:11.761 7f82e2d26700 5 Searching permissions for group=2 mask=50
2020-12-11 14:29:11.761 7f82e2d26700 5 Permissions for group not found
2020-12-11 14:29:11.761 7f82e2d26700 5 req 6345555 0.000s s3:init_multipart -
Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=OC, acct_name=Ordinateur Central, subuser=, perm_mask=15, is_admin=0), owner=OC, perm=2
2020-12-11 14:29:11.761 7f82e2d26700 10 req 6345555 0.000s s3:init_multipart identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=OC, acct_name=Ordinateur Central, subuser=, perm_mask=15, is_admin=0) requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart verifying op params
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart pre-executing
2020-12-11 14:29:11.761 7f82e2d26700 2 req 6345555 0.000s s3:init_multipart executing
2020-12-11 14:29:11.761 7f82e2d26700 10 x>> x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2020-12-11 14:29:11.761 7f82e2d26700 10 x>> x-amz-date:20201211T192859Z
2020-12-11 14:29:11.761 7f82e2d26700 20 get_obj_state: rctx=0x55bc38831e00 obj=S3-VMTLTEST:_multipart_CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779.2~fsSb8O663B3YT5atpkxyJEuj6i14kOk.meta state=0x55bc3641eaa0 s->prefetch_data=0
2020-12-11 14:29:11.761 7f82e2d26700 20 get_obj_state: rctx=0x55bc38831e00 obj=S3-VMTLTEST:_multipart_CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779.2~fsSb8O663B3YT5atpkxyJEuj6i14kOk.meta state=0x55bc3641eaa0 s->prefetch_data=0
2020-12-11 14:29:11.761 7f82e2d26700 20 prepare_atomic_modification: state is not atomic. state=0x55bc3641eaa0
2020-12-11 14:29:11.761 7f82e2d26700 20 reading from default.rgw.meta:root:.bucket.meta.S3-VMTLTEST:999ce54c-b092-444f-b490-738246784dbd.864127.414
2020-12-11 14:29:11.761 7f82e2d26700 20 get_system_obj_state: rctx=0x55bc38830bf0 obj=default.rgw.meta:root:.bucket.meta.S3-VMTLTEST:999ce54c-b092-444f-b490-738246784dbd.864127.414 state=0x55bc3630a1c0 s->prefetch_data=0
2020-12-11 14:29:11.761 7f82e2d26700 10 cache get: name=default.rgw.meta+root+.bucket.meta.S3-VMTLTEST:999ce54c-b092-444f-b490-738246784dbd.864127.414 : hit (requested=0x16, cached=0x17)
2020-12-11 14:29:11.761 7f82e2d26700 20 get_system_obj_state: s->obj_tag was set empty
2020-12-11 14:29:11.761 7f82e2d26700 10 cache get: name=default.rgw.meta+root+.bucket.meta.S3-VMTLTEST:999ce54c-b092-444f-b490-738246784dbd.864127.414 : hit (requested=0x11, cached=0x17)
2020-12-11 14:29:11.761 7f82e2d26700 20 bucket index object: .dir.999ce54c-b092-444f-b490-738246784dbd.864127.414
2020-12-11 14:29:11.795 7f82e2d26700 20 get_system_obj_state: rctx=0x55bc388312b8 obj=default.rgw.log:pubsub.user.OC.bucket.S3-VMTLTEST/999ce54c-b092-444f-b490-738246784dbd.864127.414 state=0x55bc3630a1c0 s->prefetch_data=0
2020-12-11 14:29:11.795 7f82e2d26700 10 cache get: name=default.rgw.log++pubsub.user.OC.bucket.S3-VMTLTEST/999ce54c-b092-444f-b490-738246784dbd.864127.414 : hit (negative entry)
2020-12-11 14:29:11.795 7f82e2d26700 2 req 6345555 0.034s s3:init_multipart completing
2020-12-11 14:29:11.795 7f82e2d26700 2 req 6345555 0.034s s3:init_multipart op status=0
2020-12-11 14:29:11.795 7f82e2d26700 2 req 6345555 0.034s s3:init_multipart http status=200
2020-12-11 14:29:11.795 7f82e2d26700 1 ====== req done req=0x55bc38832700 op status=0 http_status=200 latency=0.0340034s ======
2020-12-11 14:29:11.795 7f82e2d26700 1 beast: 0x55bc38832700: 10.224.12.17 - - [2020-12-11 14:29:11.0.795453s] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?uploads= HTTP/1.1" 200 286 - -
2020-12-11 14:30:21.802 7f8359e14700 1 ====== starting new request req=0x55bc37bc0700 =====
2020-12-11 14:30:21.846 7f8359e14700 1 ====== req done req=0x55bc37bc0700 op status=0 http_status=200 latency=0.0440045s ======
2020-12-11 14:30:21.846 7f8359e14700 1 beast: 0x55bc37bc0700: 10.224.12.17 - - [2020-12-11 14:30:21.0.846539s] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?uploads= HTTP/1.1" 200 286 - - -

2020-12-11 14:31:26.291 7efd77bf3700 1 ====== starting new request req=0x5567ae57a700 =====
2020-12-11 14:31:26.350 7efd77bf3700 1 ====== req done req=0x5567ae57a700 op status=0 http_status=200 latency=0.0590058s ======
2020-12-11 14:31:26.350 7efd77bf3700 1 beast: 0x5567ae57a700: 10.224.12.17 - - [2020-12-11 14:31:26.0.350823s] "POST /S3-VMTLTEST/CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779?uploads= HTTP/1.1" 200 286 - - -
@

#9 Updated by Casey Bodley about 2 months ago

2020-12-11 14:29:11.761 7f82e2d26700 20 get_obj_state: rctx=0x55bc38831e00 obj=S3-VMTLTEST:_multipart_CUZSTAGE.CUZCLOUD.JOB42383.CUZCLOUD.R0662779.2~fsSb8O663B3YT5atpkxyJEuj6i14kOk.meta state=0x55bc3641eaa0 s->prefetch_data=0

from this object name during init_multipart, it looks like the chosen uploadId was "fsSb8O663B3YT5atpkxyJEuj6i14kOk"

the part upload request contains QUERY_STRING=partNumber=1&uploadId=2fsSb8O663B3YT5atpkxyJEuj6i14kOk, which has an extra '2' at the front of the uploadId. it looks like the client is somehow adding that?

#10 Updated by Simon Pierre Desrosiers about 2 months ago

Thank you very much

I passed your answer along to IBM, hopefully, it will be spot on, and IBM can fix the problem.

Also available in: Atom PDF