we create a gen object normally, on a backfill target,
2018-11-08 13:03:13.969 7f6a4ffeb700 10 osd.7 249 dequeue_op 0xdb93ee0 prio 127 cost 0 latency 0.000744 MOSDECSubOpWrite(2.2s0 249/227 ECSubWrite(tid=7030, reqid=client.4451.0:35568, at_version=249'1377, trim_to=0'0, roll_forward_to=249'1376)) v2 pg pg[2.2s0( v 249'1376 (151'1003,249'1376] lb 2:67b0db2b:::smithi069
18487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head
(bitwise) local-lis/les=216/217 n=787 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 crt=249'1376 active+remapped mbc={}]
2018-11-08 13:03:13.969 7f6a4ffeb700 10 osd.7 pg_epoch: 249 pg[2.2s0( v 249'1376 (151'1003,249'1376] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=787 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 crt=249'1376 active+remapped mbc={}]
_handle_message: MOSDECSubOpWrite(2.2s0 249/227 ECSubWrite(tid=7030, reqid=client.4451.0:35568, at_version=249'1377, trim_to=0'0, roll_forward_to=249'1376)) v2
2018-11-08 13:03:13.969 7f6a4ffeb700 10 osd.7 pg_epoch: 249 pg[2.2s0( v 249'1376 (151'1003,249'1376] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=1260 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 crt=249'1376 active+remapped mbc={}
] append_log log((151'1003,249'1376], crt=249'1376) [249'1377 (143'858) modify 2:4f0416db:::smithi06918487-4332:head by client.4451.0:35568 2018-11-08 13:03:13.933531 0]
2018-11-08 13:03:13.969 7f6a4ffeb700 10 osd.7 pg_epoch: 249 pg[2.2s0( v 249'1377 (151'1003,249'1377] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=1260 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 lua=249'1376 crt=249'1376 lcod 249'
1376 active+remapped mbc={}] add_log_entry 249'1377 (143'858) modify 2:4f0416db:::smithi06918487-4332:head by client.4451.0:35568 2018-11-08 13:03:13.933531 0
2018-11-08 13:03:13.969 7f6a4ffeb700 10 osd.7 pg_epoch: 249 pg[2.2s0( v 249'1377 (151'1003,249'1377] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=1260 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 lua=249'1376 crt=249'1376 lcod 249'
1376 active+remapped mbc={}] append_log approx pg log length = 374
2018-11-08 13:03:13.969 7f6a4ffeb700 10 osd.7 pg_epoch: 249 pg[2.2s0( v 249'1377 (151'1003,249'1377] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=1260 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 lua=249'1376 crt=249'1376 lcod 249'
1376 active+remapped mbc={}] append_log transaction_applied = 1
2018-11-08 13:03:13.969 7f6a4ffeb700 5 filestore(/var/lib/ceph/osd/ceph-7) queue_transactions(2283): osr 0x11958880 osr(2.2s0_head)
2018-11-08 13:03:13.969 7f6a4ffeb700 10 osd.7 pg_epoch: 249 pg[2.2s0( v 249'1377 (151'1003,249'1377] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=1260 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 lua=249'1376 crt=249'1376 lcod 249'
1376 active+remapped mbc={}] op_applied version 249'1377
2018-11-08 13:03:13.977 7f6a64dd8700 5 filestore(/var/lib/ceph/osd/ceph-7) _journaled_ahead(2420): 0xfbdd980 seq 9115 osr(2.2s0_head) [Transaction(0x1457c9c0),Transaction(0x1457cb48)]
2018-11-08 13:03:13.977 7f6a64dd8700 5 filestore(/var/lib/ceph/osd/ceph-7) queue_op(2161): 0xfbdd980 seq 9115 osr(2.2s0_head) 1399599 bytes (queue has 1 ops and 1399599 bytes)
2018-11-08 13:03:13.977 7f6a655d9700 5 filestore(/var/lib/ceph/osd/ceph-7) _do_op(2204): 0xfbdd980 seq 9115 osr(2.2s0_head) start
2018-11-08 13:03:13.977 7f6a655d9700 15 filestore(/var/lib/ceph/osd/ceph-7) _collection_move_rename(5532): 2.2s0_head/0#2:4f0416db:::smithi06918487-4332:head#561 from 2.2s0_head/0#2:4f0416db:::smithi06918487-4332:head#
2018-11-08 13:03:13.977 7f6a69de2700 1 -- 172.21.15.135:6813/13193 --> 172.21.15.135:6805/13189 -- MOSDECSubOpWriteReply(2.2s0 249/227 ECSubWriteReply(tid=7030, last_complete=249'1377, committed=1, applied=1)) v2 -- ?+0 0xecf0480 con 0xc2a32c0
2018-11-08 13:03:13.977 7f6a655d9700 20 filestore(/var/lib/ceph/osd/ceph-7) lfn_unlink(485): clearing omap on 0#2:4f0416db:::smithi06918487-4332:head# in cid 2.2s0_head
2018-11-08 13:03:13.977 7f6a655d9700 10 filestore(/var/lib/ceph/osd/ceph-7) _collection_move_rename(5619): 2.2s0_head/0#2:4f0416db:::smithi06918487-4332:head#561 from 2.2s0_head/0#2:4f0416db:::smithi06918487-4332:head# = 0
that's 249'1377
then we get the next op, 1378, with a roll_forward_to=249'1376,
2018-11-08 13:03:14.221 7f6a4ffeb700 20 osd.7 op_wq(2) _process OpQueueItem(2.2s0 PGOpItem(op=MOSDECSubOpWrite(2.2s0 249/227 ECSubWrite(tid=7031, reqid=client.4451.0:35604, at_version=249'1378, trim_to=0'0, roll_forward_to=249'1376, backfill_or_async_recovery)) v2) prio 127 cost 0 e249) pg 0x10406000
but we actually roll all the way forward,
2018-11-08 13:03:14.221 7f6a4ffeb700 10 osd.7 pg_epoch: 249 pg[2.2s0( v 249'1378 (151'1003,249'1378] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=787 ec=20/20 lis/c 216/161 les/c/f 217/162/0 227/227/175) [7,0,2,4]/[5,0,2,3]p5(0) r=-1 lpr=227 pi=[161,227)/1 luod=0'0 lua=249'1377 crt=249'1378 lcod 249'1
377 active+remapped mbc={}] add_log_entry 249'1378 (149'924) delete 2:73568eae:::smithi06918487-1913 ooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo
ooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head by client.4451.0:35604 2018-11-08 13:03:14.217298 0
(note the crt=249'1378 above)
.. which deletes the gen object,
2018-11-08 13:03:14.221 7f6a6b5e5700 10 filestore(/var/lib/ceph/osd/ceph-7) _remove(3605): 2.2s0_head/0#2:4f0416db:::smithi06918487-4332:head#561 = 0
then the pg repeers, and we activate, and try to rewind,
2018-11-08 13:03:15.413 7f6a4ffeb700 10 osd.7 pg_epoch: 251 pg[2.2s0( v 249'1378 (151'1003,249'1378] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=787 ec=20/20 lis/c 227/161 les/c/f 228/162/0 250/250/175) [7,0,2,3]/[5,0,2,3]p5(0) r=-1 lpr=250 pi=[161,250)/1 crt=249'1378 remapped NOTIFY mbc={}] state<Started/Stray>: got info from osd.5(0) 2.2s0( v 249'1376 (144'882,249'1376] local-lis/les=250/251 n=1260 ec=20/20 lis/c 227/161 les/c/f 228/162/0 250/250/175)
2018-11-08 13:03:15.413 7f6a4ffeb700 10 rewind_divergent_log truncate divergent future 249'1376
2018-11-08 13:03:15.413 7f6a4ffeb700 10 rewind_divergent_log future divergent 249'1377 (143'858) modify 2:4f0416db:::smithi06918487-4332:head by client.4451.0:35568 2018-11-08 13:03:13.933531 0
2018-11-08 13:03:15.413 7f6a4ffeb700 10 rewind_divergent_log future divergent 249'1378 (149'924) delete 2:73568eae:::smithi06918487-1913 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head by client.4451.0:35604 2018-11-08 13:03:14.217298 0
2018-11-08 13:03:15.413 7f6a4ffeb700 20 _merge_object_divergent_entries: merging hoid 2:4f0416db:::smithi06918487-4332:head entries: 249'1377 (143'858) modify 2:4f0416db:::smithi06918487-4332:head by client.4451.0:35568 2018-11-08 13:03:13.933531 0
2018-11-08 13:03:15.413 7f6a4ffeb700 20 _merge_object_divergent_entries: keeping 249'1377 (143'858) modify 2:4f0416db:::smithi06918487-4332:head by client.4451.0:35568 2018-11-08 13:03:13.933531 0
2018-11-08 13:03:15.413 7f6a4ffeb700 10 _merge_object_divergent_entries: hoid 2:4f0416db:::smithi06918487-4332:head prior_version: 143'858 first_divergent_update: 249'1377 last_divergent_update: 249'1377
2018-11-08 13:03:15.413 7f6a4ffeb700 10 _merge_object_divergent_entries: hoid 2:4f0416db:::smithi06918487-4332:head has no more recent entries in log
2018-11-08 13:03:15.413 7f6a4ffeb700 10 _merge_object_divergent_entries: hoid 2:4f0416db:::smithi06918487-4332:head must be rolled back or recovered, attempting to rollback
2018-11-08 13:03:15.413 7f6a4ffeb700 10 _merge_object_divergent_entries: hoid 2:4f0416db:::smithi06918487-4332:head rolling back 249'1377 (143'858) modify 2:4f0416db:::smithi06918487-4332:head by client.4451.0:35568 2018-11-08 13:03:13.933531 0
2018-11-08 13:03:15.413 7f6a4ffeb700 10 _merge_object_divergent_entries: hoid 2:4f0416db:::smithi06918487-4332:head rolled back
2018-11-08 13:03:15.413 7f6a4ffeb700 20 _merge_object_divergent_entries: merging hoid 2:73568eae:::smithi06918487-1913 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head entries: 249'1378 (149'924) delete 2:73568eae:::smithi06918487-1913 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head by client.4451.0:35604 2018-11-08 13:03:14.217298 0
2018-11-08 13:03:15.413 7f6a4ffeb700 10 _merge_object_divergent_entries: hoid 2:73568eae:::smithi06918487-1913 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head after last_backfill
2018-11-08 13:03:15.413 7f6a4ffeb700 5 osd.7 pg_epoch: 251 pg[2.2s0( v 249'1376 (151'1003,249'1376] lb 2:67b0db2b:::smithi06918487-813 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head (bitwise) local-lis/les=216/217 n=1260 ec=20/20 lis/c 227/161 les/c/f 228/162/0 250/250/175) [7,0,2,3]/[5,0,2,3]p5(0) r=-1 lpr=250 pi=[161,250)/1 crt=249'1376 lcod 249'1378 remapped NOTIFY mbc={}] exit Started/Stray 1.005017 6 0.000329
...and we fail to apply that transaction because the gen object was deleted earlier.