Bug #17111
ERROR: got unexpected error when trying to read object: -2
0%
Description
- 1. Problem
With bucket versioning enabled, I generate a new object(name: 'copyerror', version_id: 'nema23nRODS6KZT7SPYDE5VG1Vmo4PZ') from a existed
object(name: 'zzzzzzzzzzzzz', version_id: 'YntHGGurLOkBVzNpgVp9.8os6kXuq4o') through COPY mothed.
Then the get object 'copyerror' operation failed.
App error:
[joseph@joseph w]$ python cc-final.py list testbucket5 ------------ ... version name: zzzzzzzzzzzzz version version id: YntHGGurLOkBVzNpgVp9.8os6kXuq4o delete marker: False version name: zzzzzzzzzzzzz version version id: eJnplcAtbdndb8iQ8oKgGw5GEb7ZiA8 delete marker: False version name: zzzzzzzzzzzzz version version id: MsPZhO80ngDFxSxw2F2Ohvje8ecxxkq delete marker: False version name: zzzzzzzzzzzzz version version id: m8myoYrTxQfiTNzqt7Bm9vigG3-VMT6 delete marker: False version name: zzzzzzzzzzzzz version version id: UhGcPnFfJVQsyA7DkLaawGFh2.j1tCB delete marker: False get to local Traceback (most recent call last): File "cc-final.py", line 54, in <module> print nk.get_contents_to_filename('./get-data-8m') File "/usr/lib/python2.7/site-packages/boto/s3/key.py", line 1754, in get_contents_to_filename response_headers=response_headers) File "/usr/lib/python2.7/site-packages/boto/s3/key.py", line 1692, in get_contents_to_file response_headers=response_headers) File "/usr/lib/python2.7/site-packages/boto/s3/key.py", line 1524, in get_file query_args=None) File "/usr/lib/python2.7/site-packages/boto/s3/key.py", line 1556, in _get_file_internal override_num_retries=override_num_retries) File "/usr/lib/python2.7/site-packages/boto/s3/key.py", line 343, in open override_num_retries=override_num_retries) File "/usr/lib/python2.7/site-packages/boto/s3/key.py", line 303, in open_read self.resp.reason, body) boto.exception.S3ResponseError: S3ResponseError: 404 Not Found <?xml version="1.0" encoding="UTF-8"?><Error><Code>NoSuchKey</Code><BucketName>testbucket5</BucketName><RequestId>tx000000000000000000034-0057b56da4-854e-myzone</RequestId><HostId>854e-myzone-xtao</HostId></Error>
In rgw's log I found error messages:
2016-08-18 08:11:16.500896 7fbed5aeb700 20 get_obj_state: rctx=0x7fbed5ae4e50 obj=testbucket5:_:nema23nRODS6KZT7SPYDE5VG1Vmo4PZ_copyerror state=0xc59d218 s->prefetch_da ta=0 2016-08-18 08:11:16.500906 7fbed5aeb700 20 Read xattr: user.rgw.acl 2016-08-18 08:11:16.500932 7fbed5aeb700 20 Read xattr: user.rgw.content_type 2016-08-18 08:11:16.500934 7fbed5aeb700 20 Read xattr: user.rgw.etag 2016-08-18 08:11:16.500935 7fbed5aeb700 20 Read xattr: user.rgw.idtag 2016-08-18 08:11:16.500935 7fbed5aeb700 20 Read xattr: user.rgw.manifest 2016-08-18 08:11:16.500936 7fbed5aeb700 20 Read xattr: user.rgw.pg_ver 2016-08-18 08:11:16.500937 7fbed5aeb700 20 Read xattr: user.rgw.source_zone 2016-08-18 08:11:16.500957 7fbed5aeb700 20 get_obj_state: rctx=0x7fbed5ae4e50 obj=testbucket5:_:nema23nRODS6KZT7SPYDE5VG1Vmo4PZ_copyerror state=0xc59d218 s->prefetch_data=0 2016-08-18 08:11:16.500980 7fbed5aeb700 20 rados->get_obj_iterate_cb oid=4dc9006b-4225-4ec7-baf7-4186e5d6feec.34126.1__:nema23nRODS6KZT7SPYDE5VG1Vmo4PZ_copyerror obj-ofs=0 read_ofs=0 len=524288 2016-08-18 08:11:16.501030 7fbed5aeb700 20 rados->aio_operate r=0 bl.length=0 2016-08-18 08:11:16.501042 7fbed5aeb700 20 rados->get_obj_iterate_cb oid=*4dc9006b-4225-4ec7-baf7-4186e5d6feec.34126.1__shadow:nema23nRODS6KZT7SPYDE5VG1Vmo4PZ_.BXIeBMPaMWwXju_NBbURaY79qOTehwQ_*1 obj-ofs=524288 read_ofs=0 len=4194304 2016-08-18 08:11:16.501063 7fbed5aeb700 20 rados->aio_operate r=0 bl.length=0 2016-08-18 08:11:16.501066 7fbed5aeb700 20 RGWObjManifest::operator++(): rule->part_size=0 rules.size()=1 2016-08-18 08:11:16.501067 7fbed5aeb700 20 RGWObjManifest::operator++(): result: ofs=4718592 stripe_ofs=4718592 part_ofs=0 rule->part_size=0 2016-08-18 08:11:16.501073 7fbed5aeb700 20 rados->get_obj_iterate_cb oid=*4dc9006b-4225-4ec7-baf7-4186e5d6feec.34126.1__shadow:nema23nRODS6KZT7SPYDE5VG1Vmo4PZ_.BXIeBMPaMWwXju_NBbURaY79qOTehwQ_2* obj-ofs=4718592 read_ofs=0 len=3670023 2016-08-18 08:11:16.501129 7fbed5aeb700 20 rados->aio_operate r=0 bl.length=0 2016-08-18 08:11:16.501134 7fbed5aeb700 20 RGWObjManifest::operator++(): rule->part_size=0 rules.size()=1 2016-08-18 08:11:16.501136 7fbed5aeb700 20 RGWObjManifest::operator++(): result: ofs=8388615 stripe_ofs=8388615 part_ofs=0 rule->part_size=0 2016-08-18 08:11:16.503223 7fbf15f6f700 20 get_obj_aio_completion_cb: io completion ofs=0 len=524288 2016-08-18 08:11:16.503294 7fbf15f6f700 20 get_obj_aio_completion_cb: io completion ofs=524288 len=4194304 2016-08-18 08:11:16.503306 7fbf15f6f700 0* ERROR: got unexpected error when trying to read object: -2 * 2016-08-18 08:11:16.503694 7fbf15f6f700 20 get_obj_aio_completion_cb: io completion ofs=4718592 len=3670023 2016-08-18 08:11:16.503711 7fbf15f6f700 0 *ERROR: got unexpected error when trying to read object: -2* 2016-08-18 08:11:16.503846 7fbed5aeb700 10 get_obj_iterate() r=-2, canceling all io 2016-08-18 08:11:16.503306 7fbf15f6f700 0 *ERROR: got unexpected error when trying to read object: -2* 2016-08-18 08:11:16.503694 7fbf15f6f700 20 get_obj_aio_completion_cb: io completion ofs=4718592 len=3670023 2016-08-18 08:11:16.503711 7fbf15f6f700 0 *ERROR: got unexpected error when trying to read object: -2* 2016-08-18 08:11:16.503846 7fbed5aeb700 10 get_obj_iterate() r=-2, canceling all io
- 2. Reason
When copy a object, we only add refcount on the source object's shadow objects.
But only source object's prefix is record into dest object's manifest.
When get the dest object, rgw construct a error shadow object name string.
"4dc9006b-4225-4ec7-baf7-4186e5d6feec.34126.1__shadow:nema23nRODS6KZT7SPYDE5VG1Vmo4PZ_.BXIeBMPaMWwXju_NBbURaY79qOTehwQ_1"
SHOULD BE
"4dc9006b-4225-4ec7-baf7-4186e5d6feec.34126.1__shadow:YntHGGurLOkBVzNpgVp9.8os6kXuq4o_.BXIeBMPaMWwXju_NBbURaY79qOTehwQ_1"
- 3. Fix proposal
[[https://github.com/ceph/ceph/pull/10820]]
- 4. How to trigger this bug
Please prepare copy source object's instances and replace 'YntHGGurLOkBVzNpgVp9.8os6kXuq4o' with the right one before execute the following program.
#!/usr/bin/env python # -*- coding: utf-8 -* # cc.py import time import boto import boto.s3.connection from keys import * s3_conn = boto.connect_s3( aws_access_key_id=CONS_AK, aws_secret_access_key=CONS_SK, host='192.168.12.79', port=7480, is_secure=False, calling_format=boto.s3.connection.OrdinaryCallingFormat(), ) # amazon is eventual consistent, retry a bit if failed def check_configure_versioning_retry(bucket, status, expected_string): bucket.configure_versioning(status) read_status = None for i in xrange(5): try: read_status = bucket.get_versioning_status()['Versioning'] except KeyError: read_status = None if (expected_string == read_status): break time.sleep(1) if read_status is None: return False else: return True # create bucket bucket_name = 'testbucket5' mb = s3_conn.get_bucket(bucket_name) print "list %s ------------ " % bucket_name versions = mb.list_versions() for ver in versions: print "\tversion name: ", ver.name print "\t\tversion version id: ", ver.version_id if 'delete_marker' in ver.__dict__: print "\t\tdelete marker: ", ver.delete_marker s_obj_name = 'zzzzzzzzzzzzz' nk_name = 'copyerror' nk = mb.copy_key(nk_name, bucket_name, s_obj_name, src_version_id='YntHGGurLOkBVzNpgVp9.8os6kXuq4o') print "get to local" print nk.get_contents_to_filename('./get-data-8m')
Related issues
History
#1 Updated by Nathan Cutler over 7 years ago
- Target version deleted (
v10.2.3)
#2 Updated by Nathan Cutler over 7 years ago
- Backport set to jewel
#3 Updated by Yehuda Sadeh over 7 years ago
- Priority changed from Normal to Urgent
#4 Updated by Matt Benjamin over 7 years ago
- Assignee changed from Yehuda Sadeh to Orit Wasserman
#5 Updated by Orit Wasserman over 7 years ago
- Status changed from New to In Progress
#7 Updated by Yehuda Sadeh over 7 years ago
- Status changed from In Progress to Pending Backport
Note that we need to be careful here when backporting, there's an encoding change.
#8 Updated by Nathan Cutler over 7 years ago
- Copied to Backport #17510: jewel: ERROR: got unexpected error when trying to read object: -2 added
#9 Updated by Loïc Dachary over 7 years ago
- Status changed from Pending Backport to Resolved