Bug #17040
closedFiles incorrectly uploaded with swift api
0%
Description
Hello,
I am trying to upload a file with size=55042267 to an S3 bucket backed by EC pool using SWIFT api. I have approx 5TB used and around 250TB available, ceph/rgw version = 0.94.7. This particular file size is not the issue, I've seen it happen to other files of similar size (30-500MB).
The file upload goes through without any issues but I cannot download the file I just uploaded.
I am getting the following error messages in the logs:
ERROR: got unexpected error when trying to read object: -2
I've done a bit of digging and it turns out that the last stripe of the file is more than the max stripe size of rgw. How can it possibly be like that?
Also it is a bit suspicious that the head size is a bit smaller than 512kB (I saw it exactly 512kB on a different installation). As this is a production installation, what I've done so far is wrote a script to recover damaged files. The script downloads the metadata, parses it, then downloads the last stripe, splits it into to parts: [max_strip_size] and [remainder] and re-uploads them using rados CLI tool. File download works after that and md5 sum match.
I tried to set up an extra rgw and downgraded it to 0.94.5 but it did not help. I also tried to stand up another Ceph 0.94.7 cluster in a separate environment with EC pool or replicated pool for .rgw.buckets, but could not reproduce the issue there.
Interestingly, it does not happen for all files:
$ ls -l 456 457 -rw-r--r-- 1 eugene eugene 55042267 Aug 10 16:00 456 -rw-r--r-- 1 eugene eugene 55054267 Aug 11 17:16 457 $ swift -A http://ceph-rgw-1/auth -U evgeny:swift -K *** upload evgeny-test 456 456 $ swift -A http://ceph-rgw-1/auth -U evgeny:swift -K *** upload evgeny-test 457 457 $ s3cmd get s3://evgeny-test/456 s3://evgeny-test/456 -> ./456 [1 of 1] 4702208 of 55042267 8% in 0s 18.46 MB/s # GETS STUCK FOREVER and I have to CTRL+C $ s3cmd get s3://evgeny-test/457 s3://evgeny-test/457 -> ./457 [1 of 1] 55054267 of 55054267 100% in 2s 21.87 MB/s done # ALL GOOD
Failed object radosgw-admin object stat output:
{ "name": "456", "size": 55042267, "policy": { ... irrelevant ... }, "etag": "ec3a295eeae0197f43a46885cd3fdcf4\u0000", "tag": "default.547935.122010\u0000", "manifest": { "objs": [], "obj_size": 55042267, "explicit_objs": "false", "head_obj": { "bucket": { "name": "evgeny-test", "pool": ".rgw.buckets", "data_extra_pool": ".rgw.buckets.extra", "index_pool": ".rgw.buckets.index", "marker": "default.474762.1", "bucket_id": "default.474762.1" }, "key": "", "ns": "", "object": "456", "instance": "" }, "head_size": 510880, "max_head_size": 510880, "prefix": ".3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_", "tail_bucket": { "name": "evgeny-test", "pool": ".rgw.buckets", "data_extra_pool": ".rgw.buckets.extra", "index_pool": ".rgw.buckets.index", "marker": "default.474762.1", "bucket_id": "default.474762.1" }, "rules": [ { "key": 0, "val": { "start_part_num": 0, "start_ofs": 510880, "part_size": 0, "stripe_max_size": 4194304, "override_prefix": "" } } ] }, "attrs": { "user.rgw.x-amz-meta-mtime": "1470808854.547306\u0000" } }
Rados CLI tool stats (look at stripe #13):
# head stat $ rados -p .rgw.buckets stat default.474762.1_456 .rgw.buckets/default.474762.1_456 mtime 2016-08-16 18:20:11.000000, size 510880 # stripes stat $ i=1; while rados -p .rgw.buckets stat default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_$i; do i=$[i+1]; done; .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_1 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_2 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_3 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_4 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_5 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_6 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_7 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_8 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_9 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_10 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_11 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_12 mtime 2016-08-16 18:20:11.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_13 mtime 2016-08-16 18:20:11.000000, size 4199739 error stat-ing .rgw.buckets/default.474762.1__shadow_.3fPWQ7jFRNpK8do-EvT8L4ZgDTkdIrx_14: (2) No such file or directory
Just out of interest, the 457 file that works fine has the following stats:
{ ... skipped irrelevant data... "etag": "b70585007ca1a95ddf89fe95550ccd85\u0000", "tag": "default.547935.122023\u0000", "manifest": { "objs": [], "obj_size": 55054267, "explicit_objs": "false", "head_obj": { "bucket": { "name": "evgeny-test", "pool": ".rgw.buckets", "data_extra_pool": ".rgw.buckets.extra", "index_pool": ".rgw.buckets.index", "marker": "default.474762.1", "bucket_id": "default.474762.1" }, "key": "", "ns": "", "object": "457", "instance": "" }, "head_size": 510880, "max_head_size": 510880, "prefix": ".ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_", "tail_bucket": { "name": "evgeny-test", "pool": ".rgw.buckets", "data_extra_pool": ".rgw.buckets.extra", "index_pool": ".rgw.buckets.index", "marker": "default.474762.1", "bucket_id": "default.474762.1" }, "rules": [ { "key": 0, "val": { "start_part_num": 0, "start_ofs": 510880, "part_size": 0, "stripe_max_size": 4194304, "override_prefix": "" } } ] }, "attrs": { "user.rgw.x-amz-meta-mtime": "1470899785.795187\u0000" } } # head $ rados -p .rgw.buckets stat default.474762.1_457 .rgw.buckets/default.474762.1_457 mtime 2016-08-16 18:20:36.000000, size 510880 # all good here. $ i=1; while rados -p .rgw.buckets stat default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_$i; do i=$[i+1]; done; .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_1 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_2 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_3 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_4 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_5 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_6 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_7 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_8 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_9 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_10 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_11 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_12 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_13 mtime 2016-08-16 18:20:36.000000, size 4194304 .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_14 mtime 2016-08-16 18:20:36.000000, size 17435 error stat-ing .rgw.buckets/default.474762.1__shadow_.ahiUY0BCABF0MB0vjcFbIi4YbZlSbqJ_15: (2) No such file or directory
Ceph configuration:
[global] fsid = *****48 mon_initial_members = ******52 mon_host = x.x.x.235 auth_cluster_required = cephx auth_service_required = cephx auth_client_required = cephx filestore_xattr_use_omap = true public_network = x.x.x.0/24 max_open_files = 131072 osd_pool_default_size = 3 osd_pool_default_min_size = 2 osd_pool_default_pg_num = 128 osd_pool_default_pgp_num = 128 rgw_gc_max_objs = 512 rgw_gc_obj_min_wait = 1200 rgw_gc_processor_max_time = 600 rgw_gc_processor_period = 600 rgw_override_bucket_index_max_shards = 8 osd_pool_erasure_code_stripe_width = 16384 mon_osd_min_down_reporters = 2 mon_osd_min_down_reports = 4 [osd] osd_journal_size = 10240 [client.radosgw.gw1] host = ******55 keyring = /etc/ceph/ceph.client.radosgw.keyring rgw_print_continue = false rgw_thread_pool_size = 300 rgw_frontends = "civetweb port=80" rgw_dns_name = "ceph-rgw-1" debug_rgw = 0/5 rgw_enable_ops_log = true rgw_enable_usage_log = true [client.radosgw.gw2] host = ******56 keyring = /etc/ceph/ceph.client.radosgw.keyring rgw_print_continue = false rgw_thread_pool_size = 300 rgw_frontends = "civetweb port=80" rgw_dns_name = "ceph-rgw-2" debug_rgw = 0/5 rgw_enable_ops_log = true rgw_enable_usage_log = true
Thanks for looking,
Evgeny.