/a/teuthology-2014-11-23_18:13:01-upgrade:firefly-x-giant-distro-basic-multi/615700
2014-11-23 19:18:14.224698 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) write 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18 2097152~858903
2014-11-23 19:18:14.225564 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) write 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18 2097152~858903 = 858903
[size should be 2097152+858903=2956055, which appears to be right]
2014-11-23 19:18:14.225580 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) _omap_setkeys 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18
2014-11-23 19:18:14.225625 7f4d4817a700 10 filestore oid: 2e57ac39/plana3419355-7/2a0//18 not skipping op, *spos 15102.0.1
2014-11-23 19:18:14.225691 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) setattrs 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18
2014-11-23 19:18:14.225695 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) setattrs 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18 = 0
2014-11-23 19:18:14.225702 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) collection_add 18.19_head/2e57ac39/plana3419355-7/2a0//18 from 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18
2014-11-23 19:18:14.325294 7f4d4817a700 10 filestore oid: 2e57ac39/plana3419355-7/2a0//18 setting spos to 15102.0.3
2014-11-23 19:18:14.325299 7f4d4817a700 20 filestore set_map_header: setting 661 oid 2e57ac39/plana3419355-7/2a0//18 parent seq 0
2014-11-23 19:18:14.392082 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_add 18.19_head/2e57ac39/plana3419355-7/2a0//18 from 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18 = 0
2014-11-23 19:18:14.392095 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) remove 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18
2014-11-23 19:18:14.392169 7f4d4817a700 10 filestore oid: 2e57ac39/plana3419355-7/2a0//18 setting spos to 15102.0.4
2014-11-23 19:18:14.392173 7f4d4817a700 20 filestore set_map_header: setting 661 oid 2e57ac39/plana3419355-7/2a0//18 parent seq 0
2014-11-23 19:18:14.450728 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) remove 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18 = 0
...
2014-11-23 19:18:14.642835 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/265//18 0~556055 to 0
2014-11-23 19:18:14.676100 7f4d4817a700 10 filestore oid: 2e57ac39/plana3419355-7/265//18 setting spos to 15111.0.5
2014-11-23 19:18:14.676107 7f4d4817a700 20 filestore set_map_header: setting 664 oid 2e57ac39/plana3419355-7/265//18 parent seq 0
2014-11-23 19:18:14.709426 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/265//18 0~556055 to 0 = 31767
2014-11-23 19:18:14.709458 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/265//18 1040596~476694 to 1040596
2014-11-23 19:18:14.826178 7f4d4817a700 10 filestore oid: 2e57ac39/plana3419355-7/265//18 setting spos to 15111.0.6
2014-11-23 19:18:14.826184 7f4d4817a700 20 filestore set_map_header: setting 664 oid 2e57ac39/plana3419355-7/265//18 parent seq 0
2014-11-23 19:18:14.884547 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/265//18 1040596~476694 to 1040596 = 83478
2014-11-23 19:18:14.884563 7f4d4817a700 15 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/265//18 2272624~54548 to 2272624
2014-11-23 19:18:14.943120 7f4d4817a700 10 filestore oid: 2e57ac39/plana3419355-7/265//18 setting spos to 15111.0.7
2014-11-23 19:18:14.943127 7f4d4817a700 20 filestore set_map_header: setting 664 oid 2e57ac39/plana3419355-7/265//18 parent seq 0
2014-11-23 19:18:15.018070 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/265//18 2272624~54548 to 2272624 = 53904
from that, the line
2014-11-23 19:18:14.225564 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) write 18.19_TEMP/2e57ac39/plana3419355-7/2a0//18 2097152~858903 = 858903
indicates that size should be 2097152+858903=2956055, which appears to be right.
Later,
2014-11-23 19:18:15.018070 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/265//18 2272624~54548 to 2272624 = 53904
indicates a short read stopping at offset 2272624+53904=2326528 which is significantly less than the actual size. That appears to be the bug, no idea how it could have happened yet.
Later, we get another clone range with a short read:
2014-11-23 19:18:17.237803 7f4d4817a700 10 filestore(/var/lib/ceph/osd/ceph-2) clone_range 18.19_head/2e57ac39/plana3419355-7/2a0//18 -> 18.19_head/2e57ac39/plana3419355-7/297//18 2128446~596417 to 2128446 = 71106
2128446+71106=2199552 which is even smaller.
This occurred on a test with plana34,plana47,plana50. plana34 had osd 2 where the problem occurred. plana 34 is ubuntu 12.04.4 with kernel 3.18.0-rc6-ceph-00024-geb0e5fd.
plana 47 is 12.04.5 with kernel 3.18.0-rc6-ceph-00024-geb0e5fd
plana 50 is 12.04.4 with kernel 3.17.0-rc6-ceph-00002-ge8acad6