Ceph » rgw

ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2014-07-19_13:59:16-rgw-wip-8701-testing-basic-plana/370152

ubuntu@teuthology:/a/sage-2014-07-25_15:29:13-rgw-wip-msgr-testing-basic-plana/377978

I don't see anything wrong in the logs other than this:

2014-06-26 10:29:04.641601 7ffe417fa700  0 RGWObjManifest::operator++(): result: ofs=1574768 stripe_ofs=1574768 part_ofs=0 rule->part_size=0
2014-06-26 10:29:04.646731 7ffe55fc3700  0 ERROR: s->cio->send_status() returned err=-1
2014-06-26 10:29:04.646751 7ffe55fc3700  0 ERROR: s->cio->print() returned err=-1
2014-06-26 10:29:04.646754 7ffe55fc3700  0 ERROR: s->cio->print() returned err=-1
2014-06-26 10:29:04.646756 7ffe55fc3700  0 ERROR: s->cio->print() returned err=-1
2014-06-26 10:29:04.646757 7ffe55fc3700  0 ERROR: s->cio->complete_header() returned err=-1
2014-06-26 10:29:04.646880 7ffe55fc3700  1 ====== req done req=0x7ffe74057260 http_status=403 ======

but it's hard to tell whether it's the cause or the consequence. It usually means that the client hung up, but that might be due to the client having encountered an error previously.

ubuntu@teuthology:/a/sage-2014-08-04_11:34:19-rgw-next-testing-basic-vps/397522

Something I noticed now:

10.214.132.29 l - [26/Jun/2014:10:29:03 -0700] "GET /rwtest/qlzaf HTTP/1.1" 200 1949710 "{Referer}i" "Boto/2.29.1 Python/2.7.3 Linux/3.16.0-rc2-ceph-00016-g2172e93" 
10.214.132.29 l - [26/Jun/2014:10:29:03 -0700] "GET /rwtest/qlzaf HTTP/1.1" 200 1949710 "{Referer}i" "Boto/2.29.1 Python/2.7.3 Linux/3.16.0-rc2-ceph-00016-g2172e93" 
10.214.132.29 l - [26/Jun/2014:10:29:04 -0700] "GET /rwtest/qlzaf HTTP/1.1" 200 1949710 "{Referer}i" "Boto/2.29.1 Python/2.7.3 Linux/3.16.0-rc2-ceph-00016-g2172e93" 
10.214.132.29 l - [26/Jun/2014:10:29:03 -0700] "PUT /rwtest/qlzaf HTTP/1.1" 200 - "{Referer}i" "Boto/2.29.1 Python/2.7.3 Linux/3.16.0-rc2-ceph-00016-g2172e93" 
10.214.132.29 l - [26/Jun/2014:10:29:04 -0700] "GET /rwtest/qlzaf HTTP/1.1" 103 24576 "{Referer}i" "Boto/2.29.1 Python/2.7.3 Linux/3.16.0-rc2-ceph-00016-g2172e93" 

Client sends get, get, put, get, get. However, put ends up completing longer, and the get after the put completion fails with 103, which means that the client hung up. This might imply that the problem is that the client's md5 check is racy. There's a window in which we can't be sure whether we'd get the md5 value of the current, or of the previous object.

Well, it seems that the md5 digest is embedded in the object's data, so even if writes are racing (as they are), it shouldn't matter.

After some more research: The 103 is part of the normal shutdown sequence. Still might be a client teardown handling issue, but the logs don't help. The run would continue as normal, even if there's some issue in the middle and we'd only find out about it at the end of the run. Pushed a change that adds some logging during the run in case of md5 error, we'll need to wait for next occurance.

There's a chance this one is the same as #9307