Re: RADOSGW err=Input/output error

Drew Weaver <drew.weaver@xxxxxxxxxx> · Thu, 12 Jul 2018 13:47:16 +0000

I never actually was able to fix this, I just moved on to something else.

I guess I will try 13 and see if maybe the bug has been fixed when it’s released.

-Drew

From: ceph-users [mailto:ceph-users-bounces@xxxxxxxxxxxxxx]
On Behalf Of Will Zhao

Sent: Thursday, July 12, 2018 4:32 AM

To: response@xxxxxxxxxxxx

Cc: Ceph Users <ceph-users@xxxxxxxxxxxxxx>

Subject: Re: [ceph-users] RADOSGW err=Input/output error

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: [ceph-users] 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