Project

General

Profile

Bug #37270

radosgw response 500 error while putting object

Added by 伟杰 谭 over 5 years ago. Updated over 5 years ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
rgw
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

My env is :
[tanweijie@gz-ceph-52-203 ~]$ cat /etc/redhat-release
CentOS Linux release 7.2.1511 (Core)
[tanweijie@gz-ceph-52-203 ~]$ sudo ceph -v
ceph version 12.2.7 (3ec878d1e53e1aeb47a9f619c49d9e7c0aa384d5) luminous (stable)
[tanweijie@gz-ceph-52-203 ~]$

2018-11-15 16:32:25.897665 7f187d57d700 1 ====== starting new request req=0x7f187d577110 =====
2018-11-15 16:32:25.897677 7f187d57d700 2 req 67835212:0.000011::PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665::initializing for trans_id = tx0000000000000040b154c-005bed2f19-4a9157-tupu-201-zone1
2018-11-15 16:32:25.897683 7f187d57d700 10 rgw api priority: s3=5 s3website=4
2018-11-15 16:32:25.897684 7f187d57d700 10 host=172.26.2.58
2018-11-15 16:32:25.897685 7f187d57d700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2018-11-15 16:32:25.897687 7f187d57d700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665
2018-11-15 16:32:25.897694 7f187d57d700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2018-11-15 16:32:25.897697 7f187d57d700 10 meta>> HTTP_X_AMZ_DATE
2018-11-15 16:32:25.897699 7f187d57d700 10 x>> x-amz-content-sha256:dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
2018-11-15 16:32:25.897701 7f187d57d700 10 x>> x-amz-date:20181115T083208Z
2018-11-15 16:32:25.897709 7f187d57d700 20 get_handler handler=22RGWHandler_REST_Obj_S3
2018-11-15 16:32:25.897711 7f187d57d700 10 handler=22RGWHandler_REST_Obj_S3
2018-11-15 16:32:25.897713 7f187d57d700 2 req 67835212:0.000047:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665::getting op 1
2018-11-15 16:32:25.897720 7f187d57d700 10 op=21RGWPutObj_ObjStore_S3
2018-11-15 16:32:25.897721 7f187d57d700 2 req 67835212:0.000055:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying requester
2018-11-15 16:32:25.897723 7f187d57d700 20 rgw::auth::StrategyRegistry::s3_main_strategy_t: trying rgw::auth::s3::AWSAuthStrategy
2018-11-15 16:32:25.897724 7f187d57d700 20 rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::S3AnonymousEngine
2018-11-15 16:32:25.897726 7f187d57d700 20 rgw::auth::s3::S3AnonymousEngine denied with reason=-1
2018-11-15 16:32:25.897727 7f187d57d700 20 rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::LocalEngine
2018-11-15 16:32:25.897732 7f187d57d700 10 v4 signature format = 7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897735 7f187d57d700 10 v4 credential format = HEREISMYACCESSKEY/20181115/us-east-1/s3/aws4_request
2018-11-15 16:32:25.897736 7f187d57d700 10 access key id = HEREISMYACCESSKEY
2018-11-15 16:32:25.897737 7f187d57d700 10 credential scope = 20181115/us-east-1/s3/aws4_request
2018-11-15 16:32:25.897749 7f187d57d700 10 canonical headers format = host:172.26.2.58:7480
x-amz-content-sha256:dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
x-amz-date:20181115T083208Z

2018-11-15 16:32:25.897751 7f187d57d700 10 payload request hash = dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
2018-11-15 16:32:25.897761 7f187d57d700 10 canonical request = PUT
/2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665

host:172.26.2.58:7480
x-amz-content-sha256:dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
x-amz-date:20181115T083208Z

host;x-amz-content-sha256;x-amz-date
dc3e238b80e8d3e945a2e56069aa5d8075102b31c518a9b70b33c8710585e4e8
2018-11-15 16:32:25.897762 7f187d57d700 10 canonical request hash = bc606bfc44d01f8db7d94686ff02abf3a642af84a885c5ae7936bc319ecd006a
2018-11-15 16:32:25.897772 7f187d57d700 10 string to sign = AWS4-HMAC-SHA256
20181115T083208Z
20181115/us-east-1/s3/aws4_request
bc606bfc44d01f8db7d94686ff02abf3a642af84a885c5ae7936bc319ecd006a
2018-11-15 16:32:25.897783 7f187d57d700 10 delaying v4 auth
2018-11-15 16:32:25.897849 7f187d57d700 10 date_k = ad45895410fc6277d9a3a70b2ed71d32e9834037482c2b6868f1fbf56f05b025
2018-11-15 16:32:25.897854 7f187d57d700 10 region_k = 60ed98f8c01c34bc2d806e1eb7f48c57961117dd9a7aa3f4a64d1e32b426a0a1
2018-11-15 16:32:25.897859 7f187d57d700 10 service_k = 7c782408bcdcc759be1f83d973ce833243076e707ec1422584b7f81b8c012f17
2018-11-15 16:32:25.897864 7f187d57d700 10 signing_k = b26c41194026c05feaf64bb514440e07d4ac2598fec27c13a9e41aca1babf4a1
2018-11-15 16:32:25.897886 7f187d57d700 10 generated signature = 7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897887 7f187d57d700 15 string_to_sign=AWS4-HMAC-SHA256
20181115T083208Z
20181115/us-east-1/s3/aws4_request
bc606bfc44d01f8db7d94686ff02abf3a642af84a885c5ae7936bc319ecd006a
2018-11-15 16:32:25.897897 7f187d57d700 15 server signature=7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897898 7f187d57d700 15 client signature=7ecb9afd29d38dd7413e004d44bbd5a00e399a8034f8bbb06c60dcc4cb564396
2018-11-15 16:32:25.897899 7f187d57d700 15 compare=0
2018-11-15 16:32:25.897903 7f187d57d700 20 rgw::auth::s3::LocalEngine granted access
2018-11-15 16:32:25.897904 7f187d57d700 20 rgw::auth::s3::AWSAuthStrategy granted access
2018-11-15 16:32:25.897907 7f187d57d700 2 req 67835212:0.000242:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:normalizing buckets and tenants
2018-11-15 16:32:25.897910 7f187d57d700 10 s->object=599a5b2f483442afa8fa65d8/15422706636870.6152642808670665 s->bucket=2018-11-15-16
2018-11-15 16:32:25.897912 7f187d57d700 2 req 67835212:0.000246:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:init permissions
2018-11-15 16:32:25.897925 7f187d57d700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>tupubi</ID><DisplayName>tupu-s3-system</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>tupubi</ID><DisplayName>tupu-s3-system</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2018-11-15 16:32:25.897939 7f187d57d700 2 req 67835212:0.000274:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:recalculating target
2018-11-15 16:32:25.897941 7f187d57d700 2 req 67835212:0.000276:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:reading permissions
2018-11-15 16:32:25.897943 7f187d57d700 2 req 67835212:0.000278:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:init op
2018-11-15 16:32:25.897945 7f187d57d700 2 req 67835212:0.000279:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying op mask
2018-11-15 16:32:25.897946 7f187d57d700 20 required_mask= 2 user.op_mask=7
2018-11-15 16:32:25.897947 7f187d57d700 2 req 67835212:0.000282:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying op permissions
2018-11-15 16:32:25.897949 7f187d57d700 20 -- Getting permissions begin with perm_mask=50
2018-11-15 16:32:25.897951 7f187d57d700 5 Searching permissions for identity=rgw::auth::SysReqApplier > rgw::auth::LocalApplier(acct_user=tupubi, acct_name=tupu-s3-system, subuser=, perm_mask=15, is_admin=0) mask=50
2018-11-15 16:32:25.897954 7f187d57d700 5 Searching permissions for uid=tupubi
2018-11-15 16:32:25.897955 7f187d57d700 5 Found permission: 15
2018-11-15 16:32:25.897958 7f187d57d700 5 Searching permissions for group=1 mask=50
2018-11-15 16:32:25.897959 7f187d57d700 5 Permissions for group not found
2018-11-15 16:32:25.897960 7f187d57d700 5 Searching permissions for group=2 mask=50
2018-11-15 16:32:25.897961 7f187d57d700 5 Permissions for group not found
2018-11-15 16:32:25.897962 7f187d57d700 5 -
Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=tupubi, acct_name=tupu-s3-system, subuser=, perm_mask=15, is_admin=0), owner=tupubi, perm=2
2018-11-15 16:32:25.897964 7f187d57d700 10 identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=tupubi, acct_name=tupu-s3-system, subuser=, perm_mask=15, is_admin=0) requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
2018-11-15 16:32:25.897966 7f187d57d700 2 req 67835212:0.000300:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:verifying op params
2018-11-15 16:32:25.897968 7f187d57d700 2 req 67835212:0.000302:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:pre-executing
2018-11-15 16:32:25.897969 7f187d57d700 2 req 67835212:0.000303:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422706636870.6152642808670665:put_obj:executing
2018-11-15 16:32:25.981901 7f184450b700 2 req 67833405:165.197798:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779:put_obj:completing
2018-11-15 16:32:25.981915 7f184450b700 0 WARNING: set_req_state_err err_no=5 resorting to 500
2018-11-15 16:32:25.982003 7f184450b700 2 req 67833405:165.197902:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779:put_obj:op status=-5
2018-11-15 16:32:25.982011 7f184450b700 2 req 67833405:165.197910:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779:put_obj:http status=500
2018-11-15 16:32:25.982025 7f184450b700 1 ====== req done req=0x7f1844505110 op status=-5 http_status=500 ======
2018-11-15 16:32:25.982049 7f184450b700 20 process_request() returned -5
2018-11-15 16:32:25.983337 7f184450b700 1 civetweb: 0x7f18fc366000: 172.25.52.186 - - [15/Nov/2018:16:29:40 +0800] "PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779 HTTP/1.1" 500 0 - aws-sdk-nodejs/2.262.1 linux/v8.9.3 promise
2018-11-15 16:32:25.983467 7f184450b700 20 CONTENT_LENGTH=373584
2018-11-15 16:32:25.983474 7f184450b700 20 CONTENT_TYPE=application/octet-stream
2018-11-15 16:32:25.983476 7f184450b700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=HEREISMYACCESSKEY/20181115/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=a7ad9fcf05040259956f952696f8f56ea2acdd32fffce0c9325f0b9ba405f7f6
2018-11-15 16:32:25.983480 7f184450b700 20 HTTP_CONNECTION=close
2018-11-15 16:32:25.983482 7f184450b700 20 HTTP_HOST=172.26.2.58:7480
2018-11-15 16:32:25.983485 7f184450b700 20 HTTP_USER_AGENT=aws-sdk-nodejs/2.262.1 linux/v8.9.3 promise
2018-11-15 16:32:25.983488 7f184450b700 20 HTTP_VERSION=1.1
2018-11-15 16:32:25.983490 7f184450b700 20 HTTP_X_AMZ_CONTENT_SHA256=2909e9c16ef46bc688b9a248a4885bc304b0168e56f4932d0b0b94d865c8b104
2018-11-15 16:32:25.983494 7f184450b700 20 HTTP_X_AMZ_DATE=20181115T083214Z
2018-11-15 16:32:25.983498 7f184450b700 20 REMOTE_ADDR=172.25.52.187
2018-11-15 16:32:25.983500 7f184450b700 20 REQUEST_METHOD=PUT
2018-11-15 16:32:25.983502 7f184450b700 20 REQUEST_URI=/2018-11-15-16/5b572e82878b01abf107dd7f/15422706736040.4062170427445626.jpg
2018-11-15 16:32:25.983505 7f184450b700 20 SCRIPT_URI=/2018-11-15-16/5b572e82878b01abf107dd7f/15422706736040.4062170427445626.jpg
2018-11-15 16:32:25.983506 7f184450b700 20 SERVER_PORT=7480

History

#1 Updated by Casey Bodley over 5 years ago

2018-11-15 16:32:25.981901 7f184450b700 2 req 67833405:165.197798:s3:PUT /2018-11-15-16/599a5b2f483442afa8fa65d8/15422704985510.6297163260040779:put_obj:completing
2018-11-15 16:32:25.981915 7f184450b700 0 WARNING: set_req_state_err err_no=5 resorting to 500

The '165.197798' in this log output shows that it took over two minutes to complete. It's likely the client timed out and closed the connection. This doesn't look like a bug.

#2 Updated by Casey Bodley over 5 years ago

  • Status changed from New to Closed

Also available in: Atom PDF