Hi, I ran into an odd situation where after a snap rollback, a file appears to be incorrectly truncated. The file in question is part of a ceph-osd backing store. I've attached a grepped and annotated excerpt from the osd log detailing the operations on this file since creation. Ceph sha1: 8603cce1efbdbba9a3054d938394d673b59fd4d1 (wip-sam-btrfs in ceph git) Kernel sha1: f74d66a3ec1b62a663451083091ccb8341d721ec (ceph kernel git, testing branch, based on 3.14) I've got a bunch of additional logging, let me know if there is anything else I can grab. Also, let me know if there is additional information which would be good to have if it recurs. Thanks! -Sam
2014-04-28 05:29:29.756213 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) remove 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:29.756245 7f7fb0de0700 10 filestore(/var/lib/ceph/osd/ceph-1) remove 3.c_head/a5cd460c/plana6123747-15/11e//3 = -2 2014-04-28 05:29:29.756253 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) remove 3.c_TEMP/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:29.756274 7f7fb0de0700 10 filestore(/var/lib/ceph/osd/ceph-1) remove 3.c_TEMP/a5cd460c/plana6123747-15/11e//3 = -2 2014-04-28 05:29:29.756278 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) touch 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:29.756358 7f7fb0de0700 10 filestore(/var/lib/ceph/osd/ceph-1) touch 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 2014-04-28 05:29:29.756368 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) _omap_setheader 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:29.756416 7f7fb0de0700 20 filestore set_map_header: setting 1128 oid a5cd460c/plana6123747-15/11e//3 parent seq 0 2014-04-28 05:29:29.756426 7f7fb0de0700 10 filestore oid: a5cd460c/plana6123747-15/11e//3 not skipping op, *spos 9073.0.3 2014-04-28 05:29:29.756442 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) _omap_setkeys 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:29.756489 7f7fb0de0700 10 filestore oid: a5cd460c/plana6123747-15/11e//3 not skipping op, *spos 9073.0.4 2014-04-28 05:29:29.756523 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) setattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:29.756565 7f7fb0de0700 10 filestore oid: a5cd460c/plana6123747-15/11e//3 not skipping op, *spos 9073.0.5 2014-04-28 05:29:29.756576 7f7fb0de0700 10 filestore(/var/lib/ceph/osd/ceph-1) setattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 [The contents of the file are filled in here (twice, apparently) from the adjacent clones. The actual size should be 103955, and the 0~103955 extent happens to be shared with both adjacent clones. It seems to get clone_range'd in from both clones due to a bug in the OSD recovery logic, but that should be unrelated. The logic for the following use of BTRFS_IOC_CLONE_RANGE is in the ceph tree at src/os/BtrfsFileStoreBackend.cc:clone_range https://github.com/ceph/ceph/blob/wip-sam-btrfs/src/os/BtrfsFileStoreBackend.cc] 2014-04-28 05:29:29.756581 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) clone_range 3.c_head/a5cd460c/plana6123747-15/b9//3 -> 3.c_head/a5cd460c/plana6123747-15/11e//3 0~103955 to 0 2014-04-28 05:29:29.756593 7f7fb0de0700 20 filestore(/var/lib/ceph/osd/ceph-1) _do_clone_range copy 0~103955 to 0 [The clone range from the first clone, b9, seems to successfully clone 102400 bytes (rounded since the file size is not the same as the clone_range length), and the remaining 1555 is written in] 2014-04-28 05:29:29.756595 7f7fb0de0700 20 btrfsfilestorebackend(/var/lib/ceph/osd/ceph-1) clone_range: 0~103955 to 0 2014-04-28 05:29:29.756597 7f7fb0de0700 20 btrfsfilestorebackend(/var/lib/ceph/osd/ceph-1) clone_range: cloning 0~102400 to 0 = 0 2014-04-28 05:29:29.756620 7f7fb0de0700 20 filestore(/var/lib/ceph/osd/ceph-1) _do_copy_range 102400~1555 to 102400 2014-04-28 05:29:29.756635 7f7fb0de0700 20 filestore(/var/lib/ceph/osd/ceph-1) _do_copy_range 102400~1555 to 102400 = 1555 2014-04-28 05:29:29.756638 7f7fb0de0700 20 btrfsfilestorebackend(/var/lib/ceph/osd/ceph-1) clone_range: finished 0~103955 to 0 = 1555 2014-04-28 05:29:29.756640 7f7fb0de0700 10 filestore(/var/lib/ceph/osd/ceph-1) clone_range 3.c_head/a5cd460c/plana6123747-15/b9//3 -> 3.c_head/a5cd460c/plana6123747-15/11e//3 0~103955 to 0 = 1555 2014-04-28 05:29:29.756645 7f7fb0de0700 15 filestore(/var/lib/ceph/osd/ceph-1) clone_range 3.c_head/a5cd460c/plana6123747-15/126//3 -> 3.c_head/a5cd460c/plana6123747-15/11e//3 0~103955 to 0 2014-04-28 05:29:29.756658 7f7fb0de0700 20 filestore(/var/lib/ceph/osd/ceph-1) _do_clone_range copy 0~103955 to 0 2014-04-28 05:29:29.756659 7f7fb0de0700 20 btrfsfilestorebackend(/var/lib/ceph/osd/ceph-1) clone_range: 0~103955 to 0 [The second clone range from the second clone, 126, appears to successfully clone the full 103955 (not rounded since it matches the file size) bytes over the same extent as before] 2014-04-28 05:29:29.756662 7f7fb0de0700 20 btrfsfilestorebackend(/var/lib/ceph/osd/ceph-1) clone_range: cloning 0~103955 to 0 = 0 2014-04-28 05:29:29.756689 7f7fb0de0700 20 btrfsfilestorebackend(/var/lib/ceph/osd/ceph-1) clone_range: finished 0~103955 to 0 = 0 2014-04-28 05:29:29.756697 7f7fb0de0700 10 filestore(/var/lib/ceph/osd/ceph-1) clone_range 3.c_head/a5cd460c/plana6123747-15/126//3 -> 3.c_head/a5cd460c/plana6123747-15/11e//3 0~103955 to 0 = 0 2014-04-28 05:29:34.257491 7f7fa549b700 15 filestore(/var/lib/ceph/osd/ceph-1) getattr 3.c_head/a5cd460c/plana6123747-15/11e//3 '_' 2014-04-28 05:29:34.257524 7f7fa549b700 10 filestore(/var/lib/ceph/osd/ceph-1) getattr 3.c_head/a5cd460c/plana6123747-15/11e//3 '_' = 235 2014-04-28 05:29:34.257698 7f7fa549b700 15 filestore(/var/lib/ceph/osd/ceph-1) omap_get_header 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:34.257761 7f7fa549b700 15 filestore(/var/lib/ceph/osd/ceph-1) getattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:34.257838 7f7fa549b700 10 filestore(/var/lib/ceph/osd/ceph-1) getattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 2014-04-28 05:29:34.257846 7f7fa549b700 15 filestore(/var/lib/ceph/osd/ceph-1) get_omap_iterator 3.c_head/a5cd460c/plana6123747-15/11e//3 [Here, we read the file and find the size to be 103955] 2014-04-28 05:29:34.257892 7f7fa549b700 15 filestore(/var/lib/ceph/osd/ceph-1) read 3.c_head/a5cd460c/plana6123747-15/11e//3 0~103955 2014-04-28 05:29:34.262477 7f7fa549b700 10 filestore(/var/lib/ceph/osd/ceph-1) FileStore::read 3.c_head/a5cd460c/plana6123747-15/11e//3 0~103955/103955 2014-04-28 05:29:34.977290 7f7fa4c9a700 15 filestore(/var/lib/ceph/osd/ceph-1) getattr 3.c_head/a5cd460c/plana6123747-15/11e//3 '_' 2014-04-28 05:29:34.977349 7f7fa4c9a700 10 filestore(/var/lib/ceph/osd/ceph-1) getattr 3.c_head/a5cd460c/plana6123747-15/11e//3 '_' = 235 2014-04-28 05:29:34.980000 7f7fb05df700 15 filestore(/var/lib/ceph/osd/ceph-1) setattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:34.980152 7f7fb05df700 10 filestore oid: a5cd460c/plana6123747-15/11e//3 not skipping op, *spos 10182.0.7 2014-04-28 05:29:34.980179 7f7fb05df700 10 filestore(/var/lib/ceph/osd/ceph-1) setattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 2014-04-28 05:29:57.520546 7f7fa4c9a700 15 filestore(/var/lib/ceph/osd/ceph-1) getattr 3.c_head/a5cd460c/plana6123747-15/11e//3 '_' 2014-04-28 05:29:57.520650 7f7fa4c9a700 10 filestore(/var/lib/ceph/osd/ceph-1) getattr 3.c_head/a5cd460c/plana6123747-15/11e//3 '_' = 227 2014-04-28 05:29:57.526358 7f7fb05df700 15 filestore(/var/lib/ceph/osd/ceph-1) setattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:29:57.526443 7f7fb05df700 10 filestore oid: a5cd460c/plana6123747-15/11e//3 not skipping op, *spos 10819.0.7 2014-04-28 05:29:57.526468 7f7fb05df700 10 filestore(/var/lib/ceph/osd/ceph-1) setattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 [Here, the osd restarts and rolls back to a stable snapshot taken after the setattrs above] 2014-04-28 05:30:46.451702 7fe5559a4780 0 ceph version 0.80-rc1-33-g8603cce (8603cce1efbdbba9a3054d938394d673b59fd4d1), process ceph-osd, pid 30390 2014-04-28 05:30:50.328148 7fe540f57700 10 osd.1 445 _collect_metadata {arch=x86_64,back_addr=10.214.132.17:6811/30390,ceph_version=ceph version 0.80-rc1-33-g8603cce (8603cce1efbdbba9a3054d938394d673b59fd4d1),cpu=Intel(R) Xeon(R) CPU E5620 @ 2.40GHz,distro=Ubuntu,distro_codename=precise,distro_description=Ubuntu 12.04.3 LTS,distro_version=12.04,front_addr=10.214.132.17:6810/30390,hb_back_addr=10.214.132.17:6812/30390,hb_front_addr=10.214.132.17:6813/30390,hostname=plana61,kernel_description=#1 SMP Sun Apr 27 01:47:05 UTC 2014,kernel_version=3.14.0-ceph-00097-gf74d66a3,mem_swap_kb=8373244,mem_total_kb=8162164,os=Linux,osd_data=/var/lib/ceph/osd/ceph-1,osd_journal=/var/lib/ceph/osd/ceph-1/journal} [This stat shows the now truncated 102400 size] 2014-04-28 05:31:04.720224 7fe53ff55700 10 filestore(/var/lib/ceph/osd/ceph-1) stat 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 (size 102400) 2014-04-28 05:31:04.720254 7fe53ff55700 15 filestore(/var/lib/ceph/osd/ceph-1) omap_get_header 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:31:04.720377 7fe53ff55700 15 filestore(/var/lib/ceph/osd/ceph-1) getattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:31:04.720618 7fe53ff55700 10 filestore(/var/lib/ceph/osd/ceph-1) getattrs 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 2014-04-28 05:31:04.720646 7fe53ff55700 15 filestore(/var/lib/ceph/osd/ceph-1) get_omap_iterator 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:31:04.720781 7fe53ff55700 15 filestore(/var/lib/ceph/osd/ceph-1) read 3.c_head/a5cd460c/plana6123747-15/11e//3 0~103955 [read of 103955 returns 102400 bytes] 2014-04-28 05:31:04.746900 7fe53ff55700 10 filestore(/var/lib/ceph/osd/ceph-1) FileStore::read 3.c_head/a5cd460c/plana6123747-15/11e//3 0~102400/103955 2014-04-28 05:31:10.096470 7fe53ff55700 10 filestore(/var/lib/ceph/osd/ceph-1) stat 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0 (size 102400) 2014-04-28 05:31:10.096507 7fe53ff55700 15 filestore(/var/lib/ceph/osd/ceph-1) read 3.c_head/a5cd460c/plana6123747-15/11e//3 102400~1555 [read of 1555 at offset 102400 return 0 bytes] 2014-04-28 05:31:10.096532 7fe53ff55700 10 filestore(/var/lib/ceph/osd/ceph-1) FileStore::read 3.c_head/a5cd460c/plana6123747-15/11e//3 102400~0/1555 2014-04-28 05:44:07.640390 7fe53ef53700 20 filestore(/var/lib/ceph/osd/ceph-1) objects: [a5cd460c/plana6123747-15/11e//3,a5cd460c/plana6123747-15/15a//3,a5cd460c/plana6123747-15/17f//3,a5cd460c/plana6123747-15/1b3//3,a5cd460c/plana6123747-15/1b8//3,a5cd460c/plana6123747-15/1bc//3,a5cd460c/plana6123747-15/1cd//3,a5cd460c/plana6123747-15/1db//3,a5cd460c/plana6123747-15/1ec//3,a5cd460c/plana6123747-15/1fd//3,a5cd460c/plana6123747-15/207//3,a5cd460c/plana6123747-15/216//3,a5cd460c/plana6123747-15/235//3,a5cd460c/plana6123747-15/27b//3,a5cd460c/plana6123747-15/2ad//3,a5cd460c/plana6123747-15/2b2//3,a5cd460c/plana6123747-15/2bf//3,a5cd460c/plana6123747-15/2c1//3,a5cd460c/plana6123747-15/2ca//3,a5cd460c/plana6123747-15/323//3,a5cd460c/plana6123747-15/32a//3,a5cd460c/plana6123747-15/338//3,a5cd460c/plana6123747-15/33c//3,a5cd460c/plana6123747-15/head//3,f1e15a8c/plana6123747-36/15a//3,f1e15a8c/plana6123747-36/17d//3,f1e15a8c/plana6123747-36/1a9//3,f1e15a8c/plana6123747-36/1b5//3,f1e15a8c/plana6123747-36/1c5//3,f1e15a8c/plana6123747-36/1d1//3,f1e15a8c/plana6123747-36/1de//3,f1e15a8c/plana6123747-36/201//3,f1e15a8c/plana6123747-36/213//3,f1e15a8c/plana6123747-36/2a1//3,f1e15a8c/plana6123747-36/2ad//3,f1e15a8c/plana6123747-36/2e5//3,f1e15a8c/plana6123747-36/2f8//3,f1e15a8c/plana6123747-36/33c//3,f1e15a8c/plana6123747-36/347//3,f1e15a8c/plana6123747-36/351//3,f1e15a8c/plana6123747-36/head//3] 2014-04-28 05:44:07.646073 7fe54b099700 15 filestore(/var/lib/ceph/osd/ceph-1) remove 3.c_head/a5cd460c/plana6123747-15/11e//3 2014-04-28 05:44:07.646125 7fe54b099700 20 filestore(/var/lib/ceph/osd/ceph-1) lfn_unlink: clearing omap on a5cd460c/plana6123747-15/11e//3 in cid 3.c_head 2014-04-28 05:44:07.646165 7fe54b099700 10 filestore oid: a5cd460c/plana6123747-15/11e//3 not skipping op, *spos 19378.0.2 2014-04-28 05:44:07.646172 7fe54b099700 20 filestore remove_map_header: removing 1128 oid a5cd460c/plana6123747-15/11e//3 2014-04-28 05:44:07.646539 7fe54b099700 10 filestore(/var/lib/ceph/osd/ceph-1) remove 3.c_head/a5cd460c/plana6123747-15/11e//3 = 0
