Bug #59487
openPUT actions (with ruby sdk) on Bucket failing on secure endpoint
0%
Description
Certain actions, when sent to a secure endpoint, fail to complete. From some testing, this happens when using the Ruby SDK (v3), but works when using the AWS CLI.
```
require 'aws-sdk-s3'
Aws.config.update(endpoint: 'https://ceph-rgw', verify_ssl_peer: false)
client = Aws::S3::Client.new(region: @region, credentials: Aws::Credentials.new(access_key, secret_key), force_path_style: true)
client.put_bucket_cors(bucket 'bucket-name', cors_configuration: { cors_rules: <HASH OF CORS RULES> })
```
Error in RGW log (S3 keys left in as they're not sensitive and might be part of the issue i.e. sigv4):
```
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 CONTENT_LENGTH=377
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_ACCEPT=*/*
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_ACCEPT_ENCODING=
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=HF5TFWVT14XY1RUGJTP7/20230419/uk/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date, Signature=3042730f11d620eb537d33533060b9ff19e56d130a6970b93bce14a8c0fe0ab8
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_CONTENT_MD5=DeQ5kKThbcv1sjIuswM/EA==
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_EXPECT=100-continue
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_HOST=ceph-rgw
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_USER_AGENT=aws-sdk-ruby3/3.171.0 ruby/3.1.1 x86_64-linux aws-sdk-s3/1.119.2
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_VERSION=1.1
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_X_AMZ_CONTENT_SHA256=1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 HTTP_X_AMZ_DATE=20230419T120442Z
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 QUERY_STRING=cors
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 REMOTE_ADDR=172.18.0.7
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 REQUEST_METHOD=PUT
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 REQUEST_URI=/naut-development-repository-1/?cors
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 SCRIPT_URI=/naut-development-repository-1/
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 SERVER_PORT=443
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 SERVER_PORT_SECURE=443
2023-04-19T12:04:42.094+0000 7fec55d0a700 1 ====== starting new request req=0x7feb67b2d650 =====
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s initializing for trans_id = tx00000531d0794e146cbeb-00643fd8da-114a-west
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s rgw api priority: s3=8 s3website=7
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s host=ceph-rgw
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/naut-development-repository-1/
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s meta>> HTTP_X_AMZ_CONTENT_SHA256
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s meta>> HTTP_X_AMZ_DATE
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s x>> x-amz-content-sha256:1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s x>> x-amz-date:20230419T120442Z
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s name: cors val:
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s get_handler handler=25RGWHandler_REST_Bucket_S3
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s handler=25RGWHandler_REST_Bucket_S3
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s getting op 1
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s cache get: name=west.rgw.log++script.prerequest. : hit (negative entry)
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s s3:put_cors scheduling with throttler client=3 cost=1
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s s3:put_cors op=22RGWPutCORS_ObjStore_S3
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors verifying requester
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::StrategyRegistry::s3_main_strategy_t: trying rgw::auth::s3::AWSAuthStrategy
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::S3AnonymousEngine
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::S3AnonymousEngine denied with reason=-1
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::STSAuthStrategy
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::STSAuthStrategy: trying rgw::auth::s3::STSEngine
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s v4 signature format = 3042730f11d620eb537d33533060b9ff19e56d130a6970b93bce14a8c0fe0ab8
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s v4 credential format = HF5TFWVT14XY1RUGJTP7/20230419/uk/s3/aws4_request
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s access key id = HF5TFWVT14XY1RUGJTP7
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s credential scope = 20230419/uk/s3/aws4_request
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s canonical headers format = content-md5:DeQ5kKThbcv1sjIuswM/EA==
host:ceph-rgw
x-amz-content-sha256:1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
x-amz-date:20230419T120442Z
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s payload request hash = 1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s canonical request = PUT
/naut-development-repository-1/
cors=
content-md5:DeQ5kKThbcv1sjIuswM/EA==
host:ceph-rgw
x-amz-content-sha256:1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
x-amz-date:20230419T120442Z
content-md5;host;x-amz-content-sha256;x-amz-date
1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s canonical request hash = 4f674913bcbedb42fd42767ebd69da02ddf8201cd6fccf6be2e0a20ef7301c7f
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s string to sign = AWS4-HMAC-SHA256
20230419T120442Z
20230419/uk/s3/aws4_request
4f674913bcbedb42fd42767ebd69da02ddf8201cd6fccf6be2e0a20ef7301c7f
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s delaying v4 auth
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::STSEngine denied with reason=-13
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::STSAuthStrategy denied with reason=-13
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::LocalEngine
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s v4 signature format = 3042730f11d620eb537d33533060b9ff19e56d130a6970b93bce14a8c0fe0ab8
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s v4 credential format = HF5TFWVT14XY1RUGJTP7/20230419/uk/s3/aws4_request
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s access key id = HF5TFWVT14XY1RUGJTP7
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s credential scope = 20230419/uk/s3/aws4_request
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s canonical headers format = content-md5:DeQ5kKThbcv1sjIuswM/EA==
host:ceph-rgw
x-amz-content-sha256:1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
x-amz-date:20230419T120442Z
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s payload request hash = 1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s canonical request = PUT
/naut-development-repository-1/
cors=
content-md5:DeQ5kKThbcv1sjIuswM/EA==
host:ceph-rgw
x-amz-content-sha256:1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
x-amz-date:20230419T120442Z
content-md5;host;x-amz-content-sha256;x-amz-date
1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s canonical request hash = 4f674913bcbedb42fd42767ebd69da02ddf8201cd6fccf6be2e0a20ef7301c7f
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s string to sign = AWS4-HMAC-SHA256
20230419T120442Z
20230419/uk/s3/aws4_request
4f674913bcbedb42fd42767ebd69da02ddf8201cd6fccf6be2e0a20ef7301c7f
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s delaying v4 auth
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s date_k = 2d4b0c15bf060992f58fe7c43433568ffe15d1c56c0b338c3e316fcca488875e
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s region_k = 06750d6c49dc098ff1b14b8466ed96de3b6b87061aed60dc20f36ad1d3b61104
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s service_k = b1cab66c70ee54b02b2410cc8f9288c164d21c43a553f164be0ca50be662272d
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s signing_k = 13744b7bff4d2c3b8771347e01648d6d78e6692627916dfcdea70e185a733ed6
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s generated signature = 3042730f11d620eb537d33533060b9ff19e56d130a6970b93bce14a8c0fe0ab8
2023-04-19T12:04:42.094+0000 7fec55d0a700 15 req 5988951415488695275 0.000000000s s3:put_cors string_to_sign=AWS4-HMAC-SHA256
20230419T120442Z
20230419/uk/s3/aws4_request
4f674913bcbedb42fd42767ebd69da02ddf8201cd6fccf6be2e0a20ef7301c7f
2023-04-19T12:04:42.094+0000 7fec55d0a700 15 req 5988951415488695275 0.000000000s s3:put_cors server signature=3042730f11d620eb537d33533060b9ff19e56d130a6970b93bce14a8c0fe0ab8
2023-04-19T12:04:42.094+0000 7fec55d0a700 15 req 5988951415488695275 0.000000000s s3:put_cors client signature=3042730f11d620eb537d33533060b9ff19e56d130a6970b93bce14a8c0fe0ab8
2023-04-19T12:04:42.094+0000 7fec55d0a700 15 req 5988951415488695275 0.000000000s s3:put_cors compare=0
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::LocalEngine granted access
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors rgw::auth::s3::AWSAuthStrategy granted access
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors normalizing buckets and tenants
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s s->object=<NULL> s->bucket=naut-development-repository-1
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors init permissions
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s s3:put_cors cache get: name=west.rgw.meta+root+naut-development-repository-1 : hit (requested=0x11, cached=0x11)
2023-04-19T12:04:42.094+0000 7fec55d0a700 15 req 5988951415488695275 0.000000000s s3:put_cors decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>naut</ID><DisplayName>naut</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>naut</ID><DisplayName>naut</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2023-04-19T12:04:42.094+0000 7fec55d0a700 10 req 5988951415488695275 0.000000000s s3:put_cors cache get: name=west.rgw.meta+users.uid+naut : hit (requested=0x13, cached=0x13)
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors recalculating target
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors reading permissions
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors init op
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors verifying op mask
2023-04-19T12:04:42.094+0000 7fec55d0a700 20 req 5988951415488695275 0.000000000s s3:put_cors required_mask= 2 user.op_mask=7
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors verifying op permissions
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors verifying op params
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors pre-executing
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors check rate limiting
2023-04-19T12:04:42.094+0000 7fec55d0a700 2 req 5988951415488695275 0.000000000s s3:put_cors executing
2023-04-19T12:04:44.798+0000 7fec721e0700 20 BucketsSyncThread: sync user=naut bucket=:naut-development-repository-1[10ec2622-e4e6-4789-917f-1b5755bdaacd.4283.1])
2023-04-19T12:04:46.962+0000 7fec701dc700 20 rgw notify: INFO: next queues processing will happen at: Wed Apr 19 12:05:17 2023
2023-04-19T12:05:01.666+0000 7fec819ff700 2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2023-04-19T12:05:17.246+0000 7fec701dc700 20 rgw notify: INFO: next queues processing will happen at: Wed Apr 19 12:05:47 2023
2023-04-19T12:05:23.666+0000 7fec819ff700 2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2023-04-19T12:05:45.666+0000 7fec819ff700 2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2023-04-19T12:05:47.098+0000 7fec52d04700 4 failed to read body: Operation canceled
2023-04-19T12:05:47.098+0000 7fec52d04700 2 req 5988951415488695275 65.004302979s s3:put_cors completing
2023-04-19T12:05:47.098+0000 7fec52d04700 0 WARNING: set_req_state_err err_no=125 resorting to 500
2023-04-19T12:05:47.098+0000 7fec52d04700 4 write_data failed: Broken pipe
2023-04-19T12:05:47.098+0000 7fec52d04700 0 req 5988951415488695275 65.004302979s ERROR: RESTFUL_IO(s)->complete_header() returned err=Broken pipe
2023-04-19T12:05:47.098+0000 7fec52d04700 4 write_data failed: Broken pipe
2023-04-19T12:05:47.098+0000 7fec52d04700 10 req 5988951415488695275 65.004302979s cache get: name=west.rgw.log++script.postrequest. : hit (negative entry)
2023-04-19T12:05:47.098+0000 7fec52d04700 2 req 5988951415488695275 65.004302979s s3:put_cors op status=-125
2023-04-19T12:05:47.098+0000 7fec52d04700 2 req 5988951415488695275 65.004302979s s3:put_cors http status=500
2023-04-19T12:05:47.098+0000 7fec52d04700 1 ====== req done req=0x7feb67b2d650 op status=-125 http_status=500 latency=65.004302979s ======
2023-04-19T12:05:47.098+0000 7fec52d04700 1 beast: 0x7feb67b2d650: 172.18.0.7 - naut [19/Apr/2023:12:04:42.094 +0000] "PUT /naut-development-repository-1/?cors HTTP/1.1" 500 0 - "aws-sdk-ruby3/3.171.0 ruby/3.1.1 x86_64-linux aws-sdk-s3/1.119.2" - latency=65.004302979s
```
Updated by Casey Bodley about 1 year ago
4 failed to read body: Operation canceled
rgw was waiting to read the request body, but timed out after 65 seconds. the request was sent with the Expect: 100-continue header, maybe this op is missing the 100 Continue response?
Updated by Aidan Damerell about 1 year ago
That would seem to be the case. Captured the requests from the SDK:
HTP endpoint:
```
PUT /naut-development-repository-1?cors HTTP/1.1
Accept-Encoding: gzip, deflate
User-Agent: aws-sdk-ruby3/3.132.0 ruby/2.5.7 x86_64-darwin18 aws-sdk-s3/1.114.0
Expect: 100-continue
Content-Md5: DeQ5kKThbcv1sjIuswM/EA==
Host: localhost:50400
X-Amz-Content-Sha256: 1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
Content-Length: 377
X-Amz-Date: 20230421T075240Z
Authorization: AWS4-HMAC-SHA256 Credential=HF5TFWVT14XY1RUGJTP7/20230421/uk/s3/aws4_request, SignedHeaders=content-md5;host;user-agent;x-amz-content-sha256;x-amz-date, Signature=04e2991dfb63f3c3ae7287983260a9aabc1ebcb81689397881cf98e16aad70e8
Accept: */*
Connection: close
HTTP Response:
```
HTTP/1.1 200 OK
x-amz-request-id: tx0000097dff63a81bf83bc-0064424457-1159-west
Content-Type: application/xml
Content-Length: 0
Date: Fri, 21 Apr 2023 08:07:51 GMT
Server: Ceph Object Gateway (reef)
Connection: close
```
HTTPS endpoint:
```
PUT /naut-development-repository-1?cors HTTP/1.1
Accept-Encoding: gzip, deflate
User-Agent: aws-sdk-ruby3/3.132.0 ruby/2.5.7 x86_64-darwin18 aws-sdk-s3/1.114.0
Expect: 100-continue
Content-Md5: DeQ5kKThbcv1sjIuswM/EA==
Host: localhost:8443
X-Amz-Content-Sha256: 1c211e7deef13e13a56b2269f80eb25f986f4296b282b61e70e8d677cd6fc0c3
Content-Length: 0
X-Amz-Date: 20230421T075532Z
Authorization: AWS4-HMAC-SHA256 Credential=HF5TFWVT14XY1RUGJTP7/20230421/uk/s3/aws4_request, SignedHeaders=content-md5;host;user-agent;x-amz-content-sha256;x-amz-date, Signature=ce1be812505a08a9e282350dc6233df8fbd53f35bc89cb933cd2f834d575ce36
Accept: */*
Connection: close
```
HTTPS Response: none
Updated by Casey Bodley about 1 year ago
- Subject changed from PUT actions on Bucket failing on secure endpoint to PUT actions (with ruby sdk) on Bucket failing on secure endpoint