Hi :
I use libs3 to run test . The network is IB.
The error in libcurl is the following:
== Info: Operation too slow. Less than 1 bytes/sec transferred the last 15 seconds
== Info: Closing connection 766
and a full request error in rgw is as the following:
2018-07-12 15:42:30.501074 7fe8bc83f700 1 civetweb: 0x7fe940ebf000: 10.5.131.193 - - [12/Jul/2018:15:42:15 +0800] "PUT /yesonggao.hdd77/2217856 HTTP/1.1" 1 0 - Mozilla/4.0 (Compatible; s3; libs3 2.0; Linux x86_64)
2018-07-12 15:43:05.332318 7fe8bc83f700 20 HTTP_HOST=localhost
2018-07-12 15:43:05.332326 7fe8bc83f700 20 HTTP_VERSION=1.1
2018-07-12 15:43:05.332327 7fe8bc83f700 20 REMOTE_ADDR=10.5.131.193
2018-07-12 15:43:05.332328 7fe8bc83f700 20 REQUEST_METHOD=HEAD
2018-07-12 15:43:05.332330 7fe8bc83f700 20 REQUEST_URI=/
2018-07-12 15:43:05.332331 7fe8bc83f700 20 SCRIPT_URI=/
2018-07-12 15:43:05.332331 7fe8bc83f700 20 SERVER_PORT=80
2018-07-12 15:43:05.332333 7fe8bc83f700 1 ====== starting new request req=0x7fe8bc839110 =====
2018-07-12 15:43:05.332344 7fe8bc83f700 2 req 18326229:0.000010::HEAD /::initializing for trans_id = tx00000000000000117a2d5-005b470689-d41b-default
2018-07-12 15:43:05.332351 7fe8bc83f700 10 rgw api priority: s3=5 s3website=4
2018-07-12 15:43:05.332352 7fe8bc83f700 10 host=localhost
2018-07-12 15:43:05.332354 7fe8bc83f700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2018-07-12 15:43:05.332355 7fe8bc83f700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/
2018-07-12 15:43:05.332367 7fe8bc83f700 20 get_handler handler=26RGWHandler_REST_Service_S3
2018-07-12 15:43:05.332370 7fe8bc83f700 10 handler=26RGWHandler_REST_Service_S3
2018-07-12 15:43:05.332371 7fe8bc83f700 2 req 18326229:0.000038:s3:HEAD /::getting op 3
2018-07-12 15:43:05.332373 7fe8bc83f700 10 op=26RGWListBuckets_ObjStore_S3
2018-07-12 15:43:05.332374 7fe8bc83f700 2 req 18326229:0.000041:s3:HEAD /:list_buckets:verifying requester
2018-07-12 15:43:05.332376 7fe8bc83f700 20 rgw::auth::StrategyRegistry::s3_main_strategy_t: trying rgw::auth::s3::AWSAuthStrategy
2018-07-12 15:43:05.332378 7fe8bc83f700 20 rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::S3AnonymousEngine
2018-07-12 15:43:05.332381 7fe8bc83f700 20 rgw::auth::s3::S3AnonymousEngine granted access
2018-07-12 15:43:05.332383 7fe8bc83f700 20 rgw::auth::s3::AWSAuthStrategy granted access
2018-07-12 15:43:05.332384 7fe8bc83f700 2 req 18326229:0.000051:s3:HEAD /:list_buckets:normalizing buckets and tenants
2018-07-12 15:43:05.332386 7fe8bc83f700 10 s->object=<NULL> s->bucket=
2018-07-12 15:43:05.332387 7fe8bc83f700 2 req 18326229:0.000054:s3:HEAD /:list_buckets:init permissions
2018-07-12 15:43:05.332400 7fe8bc83f700 2 req 18326229:0.000066:s3:HEAD /:list_buckets:recalculating target
2018-07-12 15:43:05.332402 7fe8bc83f700 2 req 18326229:0.000068:s3:HEAD /:list_buckets:reading permissions
2018-07-12 15:43:05.332403 7fe8bc83f700 2 req 18326229:0.000070:s3:HEAD /:list_buckets:init op
[root@SH-IDC1-10-5-30-221 ceph]# grep 7fe8bc83f700 ceph-client.rgw.SH-IDC1-10-5-30-221.log | grep http_status=500 -B 50 -A 50
2018-07-12 15:42:15.499588 7fe8bc83f700 10 get_canon_resource(): dest=/yesonggao.hdd77/2217856
2018-07-12 15:42:15.499589 7fe8bc83f700 10 string_to_sign:
2018-07-12 15:42:15.499611 7fe8bc83f700 15 string_to_sign=PUT
2018-07-12 15:42:15.499620 7fe8bc83f700 15 server signature=14+b6nTNy3cPjVxFlqhRY+hahsA=
2018-07-12 15:42:15.499620 7fe8bc83f700 15 client signature=14+b6nTNy3cPjVxFlqhRY+hahsA=
2018-07-12 15:42:15.499621 7fe8bc83f700 15 compare=0
2018-07-12 15:42:15.499623 7fe8bc83f700 20 rgw::auth::s3::LocalEngine granted access
2018-07-12 15:42:15.499624 7fe8bc83f700 20 rgw::auth::s3::AWSAuthStrategy granted access
2018-07-12 15:42:15.499626 7fe8bc83f700 2 req 18325783:0.000112:s3:PUT /yesonggao.hdd77/2217856:put_obj:normalizing buckets and tenants
2018-07-12 15:42:15.499628 7fe8bc83f700 10 s->object=2217856 s->bucket=yesonggao.hdd77
2018-07-12 15:42:15.499630 7fe8bc83f700 2 req 18325783:0.000116:s3:PUT /yesonggao.hdd77/2217856:put_obj:init permissions
2018-07-12 15:42:15.499642 7fe8bc83f700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>yesonggao</ID><DisplayName>yesonggao</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>yesonggao</ID><DisplayName>yesonggao</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2018-07-12 15:42:15.499658 7fe8bc83f700 2 req 18325783:0.000144:s3:PUT /yesonggao.hdd77/2217856:put_obj:recalculating target
2018-07-12 15:42:15.499662 7fe8bc83f700 2 req 18325783:0.000148:s3:PUT /yesonggao.hdd77/2217856:put_obj:reading permissions
2018-07-12 15:42:15.499664 7fe8bc83f700 2 req 18325783:0.000150:s3:PUT /yesonggao.hdd77/2217856:put_obj:init op
2018-07-12 15:42:15.499666 7fe8bc83f700 2 req 18325783:0.000152:s3:PUT /yesonggao.hdd77/2217856:put_obj:verifying op mask
2018-07-12 15:42:15.499667 7fe8bc83f700 20 required_mask= 2 user.op_mask=7
2018-07-12 15:42:15.499668 7fe8bc83f700 2 req 18325783:0.000154:s3:PUT /yesonggao.hdd77/2217856:put_obj:verifying op permissions
2018-07-12 15:42:15.499670 7fe8bc83f700 20 -- Getting permissions begin with perm_mask=50
2018-07-12 15:42:15.499671 7fe8bc83f700 5 Searching permissions for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=yesonggao, acct_name=yesonggao, subuser=, perm_mask=15, is_admin=0) mask=50
2018-07-12 15:42:15.499673 7fe8bc83f700 5 Searching permissions for uid=yesonggao
2018-07-12 15:42:15.499674 7fe8bc83f700 5 Found permission: 15
2018-07-12 15:42:15.499675 7fe8bc83f700 5 Searching permissions for group=1 mask=50
2018-07-12 15:42:15.499676 7fe8bc83f700 5 Permissions for group not found
2018-07-12 15:42:15.499677 7fe8bc83f700 5 Searching permissions for group=2 mask=50
2018-07-12 15:42:15.499677 7fe8bc83f700 5 Permissions for group not found
2018-07-12 15:42:15.499678 7fe8bc83f700 5 -- Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=yesonggao, acct_name=yesonggao, subuser=, perm_mask=15, is_admin=0), owner=yesonggao, perm=2
2018-07-12 15:42:15.499680 7fe8bc83f700 10 identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=yesonggao, acct_name=yesonggao, subuser=, perm_mask=15, is_admin=0) requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2
2018-07-12 15:42:15.499682 7fe8bc83f700 2 req 18325783:0.000168:s3:PUT /yesonggao.hdd77/2217856:put_obj:verifying op params
2018-07-12 15:42:15.499684 7fe8bc83f700 2 req 18325783:0.000169:s3:PUT /yesonggao.hdd77/2217856:put_obj:pre-executing
2018-07-12 15:42:15.499695 7fe8bc83f700 30 AccountingFilter::send_100_continue: e=0, sent=25, total=0
2018-07-12 15:42:15.499697 7fe8bc83f700 2 req 18325783:0.000183:s3:PUT /yesonggao.hdd77/2217856:put_obj:executing
2018-07-12 15:42:15.499708 7fe8bc83f700 20 bucket quota: max_objects=-1 max_size=-1
2018-07-12 15:42:15.499710 7fe8bc83f700 20 bucket quota OK: stats.num_objects=8691569 stats.size=38504303859334
2018-07-12 15:42:15.499712 7fe8bc83f700 20 user quota: max_objects=-1 max_size=-1
2018-07-12 15:42:15.499713 7fe8bc83f700 20 user quota OK: stats.num_objects=11692824 stats.size=64478020156197
2018-07-12 15:42:15.499747 7fe8bc83f700 30 AccountingFilter::set_account: e=1
2018-07-12 15:42:30.500915 7fe8bc83f700 -1 ERROR: get_data, read_len = -5
2018-07-12 15:42:30.500938 7fe8bc83f700 2 req 18325783:15.001424:s3:PUT /yesonggao.hdd77/2217856:put_obj:completing
2018-07-12 15:42:30.500951 7fe8bc83f700 0 WARNING: set_req_state_err err_no=5 resorting to 500
2018-07-12 15:42:30.500956 7fe8bc83f700 30 AccountingFilter::send_status: e=1, sent=36, total=0
2018-07-12 15:42:30.500959 7fe8bc83f700 30 AccountingFilter::send_header: e=1, sent=0, total=36
2018-07-12 15:42:30.500975 7fe8bc83f700 30 AccountingFilter::send_content_length: e=1, sent=21, total=36
2018-07-12 15:42:30.500980 7fe8bc83f700 30 AccountingFilter::send_header: e=1, sent=0, total=57
2018-07-12 15:42:30.500982 7fe8bc83f700 30 AccountingFilter::send_header: e=1, sent=0, total=57
2018-07-12 15:42:30.501002 7fe8bc83f700 0 ERROR: RESTFUL_IO(s)->complete_header() returned err=Input/output error
2018-07-12 15:42:30.501006 7fe8bc83f700 30 AccountingFilter::set_account: e=1
2018-07-12 15:42:30.501020 7fe8bc83f700 30 AccountingFilter::complete_request: e=1, sent=0, total=57
2018-07-12 15:42:30.501025 7fe8bc83f700 2 req 18325783:15.001511:s3:PUT /yesonggao.hdd77/2217856:put_obj:op status=-5
2018-07-12 15:42:30.501027 7fe8bc83f700 2 req 18325783:15.001513:s3:PUT /yesonggao.hdd77/2217856:put_obj:http status=500
2018-07-12 15:42:30.501035 7fe8bc83f700 1 ====== req done req=0x7fe8bc839110 op status=-5 http_status=500 ======
2018-07-12 15:42:30.501050 7fe8bc83f700 20 process_request() returned -5
Can you see anything wrong? And Do you have any idea about how I should debug next ?
On Wed, Jul 4, 2018 at 5:23 PM <response@xxxxxxxxxxxx> wrote:
Hi Drew,
Try to increase debugging with
debug ms = 1
debug rgw = 20
Regards
Kev
----- Original Message -----
From: "Drew Weaver" <drew.weaver@xxxxxxxxxx>
To: "ceph-users" <ceph-users@xxxxxxxxxxxxxx>
Sent: Tuesday, July 3, 2018 1:39:55 PM
Subject: RADOSGW err=Input/output error
An application is having general failures writing to a test cluster we have setup.
2018-07-02 23:13:26.128282 7fe00b560700 0 WARNING: set_req_state_err err_no=5 resorting to 500
2018-07-02 23:13:26.128460 7fe00b560700 1 ====== req done req=0x7fe00b55a110 op status=-5 http_status=500 ======
2018-07-02 23:13:27.530236 7fe00b560700 1 civetweb: 0x55639acc0000: x - - [02/Jul/2018:23:12:55 -0400] "PUT /my-new-bucket/BEOST_00000292/2752 HTTP/1.1" 500 0 - APN/1.0 Veritas/1.0 BackupExec/20.0
2018-07-02 23:13:27.532849 7fdfe2d0f700 1 ====== starting new request req=0x7fdfe2d09110 =====
2018-07-02 23:13:27.538476 7fdfe2d0f700 0 WARNING: set_req_state_err err_no=5 resorting to 500
2018-07-02 23:13:27.538554 7fdfe2d0f700 0 ERROR: RESTFUL_IO(s)->complete_header() returned err=Input/output error
2018-07-02 23:13:27.538623 7fdfe2d0f700 1 ====== req done req=0x7fdfe2d09110 op status=-5 http_status=500 ======
2018-07-02 23:13:27.538683 7fdfe2d0f700 1 civetweb: 0x55639ae7d000: x - - [02/Jul/2018:23:13:27 -0400] "PUT /my-new-bucket/BEOST_00000292/2753 HTTP/1.1" 500 0 - APN/1.0 Veritas/1.0 BackupExec/20.0
2018-07-02 23:13:28.252088 7fe002d4f700 1 ====== starting new request req=0x7fe002d49110 =====
I’ve done a bit of Googling and trying to match the time up with logs on other hosts but there really doesn’t seem to be very much else happening at the time when this error occurs. This is version 12.2.5.
Anyone have any hints at what I could look at to try and find the cause of this?
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
