a replica was servicing a read and tried to do a cache promotion:
-37> 2017-08-04 17:36:21.700080 7fc30e880700 20 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] do_op: op osd_op(client.4224.0:2408 12.2 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:19 [read 0~4194304] snapc 0=[] ondisk+read+localize_reads+known_if_redirected e95) v8
-36> 2017-08-04 17:36:21.700088 7fc30e880700 20 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] op_has_sufficient_caps session=0x7fc33be21200 pool=12 (test-librbd-smithi037-320057-10 ) owner=0 need_read_cap=1 need_write_cap=0 classes=[] -> yes
-35> 2017-08-04 17:36:21.700098 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] do_op osd_op(client.4224.0:2408 12.2 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:19 [read 0~4194304] snapc 0=[] ondisk+read+localize_reads+known_if_redirected e95) v8 may_read -> read-ordered flags ondisk+read+localize_reads+known_if_redirected
-34> 2017-08-04 17:36:21.700107 7fc30e880700 15 filestore(/var/lib/ceph/osd/ceph-0) getattr(4392): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head# 'snapset'
-33> 2017-08-04 17:36:21.700127 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) error opening file /var/lib/ceph/osd/ceph-0/current/12.2_head/rbd\udata.10803bc4e8cd.0000000000000000__head_3A1F1D4A__c with flags=2: (2) No such file or directory
-32> 2017-08-04 17:36:21.700132 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) getattr(4426): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head# 'snapset' = -2
-31> 2017-08-04 17:36:21.700135 7fc30e880700 15 filestore(/var/lib/ceph/osd/ceph-0) getattr(4392): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:snapdir# 'snapset'
-30> 2017-08-04 17:36:21.700146 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) error opening file /var/lib/ceph/osd/ceph-0/current/12.2_head/rbd\udata.10803bc4e8cd.0000000000000000__snapdir_3A1F1D4A__c with flags=2: (2) No such file or directory
-29> 2017-08-04 17:36:21.700149 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) getattr(4426): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:snapdir# 'snapset' = -2
-28> 2017-08-04 17:36:21.700152 7fc30e880700 20 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] find_object_context 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:19 no snapset
-27> 2017-08-04 17:36:21.700159 7fc30e880700 25 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] maybe_handle_cache_detail (no obc) missing_oid 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head must_promote 0 in_hit_set 0
-26> 2017-08-04 17:36:21.700166 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] get_object_context: obc NOT found in cache: 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head
-25> 2017-08-04 17:36:21.700171 7fc30e880700 15 filestore(/var/lib/ceph/osd/ceph-0) getattr(4392): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head# '_'
-24> 2017-08-04 17:36:21.700181 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) error opening file /var/lib/ceph/osd/ceph-0/current/12.2_head/rbd\udata.10803bc4e8cd.0000000000000000__head_3A1F1D4A__c with flags=2: (2) No such file or directory
-23> 2017-08-04 17:36:21.700185 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) getattr(4426): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head# '_' = -2
-22> 2017-08-04 17:36:21.700187 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] get_object_context: no obc for soid 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head but can_create
-21> 2017-08-04 17:36:21.700193 7fc30e880700 15 filestore(/var/lib/ceph/osd/ceph-0) getattr(4392): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:snapdir# 'snapset'
-20> 2017-08-04 17:36:21.700201 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) error opening file /var/lib/ceph/osd/ceph-0/current/12.2_head/rbd\udata.10803bc4e8cd.0000000000000000__snapdir_3A1F1D4A__c with flags=2: (2) No such file or directory
-19> 2017-08-04 17:36:21.700204 7fc30e880700 10 filestore(/var/lib/ceph/osd/ceph-0) getattr(4426): 12.2_head/#12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:snapdir# 'snapset' = -2
-18> 2017-08-04 17:36:21.700211 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] create_object_context 0x7fc33c439440 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head
-17> 2017-08-04 17:36:21.700216 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] populate_obc_watchers 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head
-16> 2017-08-04 17:36:21.700220 7fc30e880700 20 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] PrimaryLogPG::check_blacklisted_obc_watchers for obc 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head
-15> 2017-08-04 17:36:21.700224 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] get_object_context: 0x7fc33c439440 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head rwstate(none n=0 w=0) oi: 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head(0'0 unknown.0.0:0 s 0 uv 0 alloc_hint [0 0 0]) ssc: 0x7fc33c1326c0 snapset: 0=[]:[]
-14> 2017-08-04 17:36:21.700232 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] start_copy 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head from 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head @3 v0 flags 30 mirror_snapset
-13> 2017-08-04 17:36:21.700239 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] _copy_some 0x7fc33c439440 0x7fc33c82a398
-12> 2017-08-04 17:36:21.700270 7fc30e880700 1 -- 172.21.15.37:0/316573 --> 172.21.15.35:6809/14816 -- osd_op(unknown.0.11:5 3.2 3:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:snapdir [list-snaps] snapc 0=[] ondisk+read+rwordered+ignore_cache+ignore_overlay+map_snap_clone+known_if_redirected e95) v8 -- 0x7fc33b39db00 con 0
-11> 2017-08-04 17:36:21.700290 7fc30e880700 1 -- 172.21.15.37:0/316573 --> 172.21.15.35:6809/14816 -- osd_op(unknown.0.11:6 3.2 3:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head [copy-get max 8388608] snapc 0=[] ondisk+read+rwordered+ignore_cache+ignore_overlay+map_snap_clone+known_if_redirected e95) v8 -- 0x7fc33be48900 con 0
-10> 2017-08-04 17:36:21.700298 7fc30e880700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] wait_for_blocked_object 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head 0x7fc33bdf0b80
-9> 2017-08-04 17:36:21.700313 7fc30e880700 10 osd.0 95 dequeue_op 0x7fc33bdf0b80 finish
-8> 2017-08-04 17:36:21.700316 7fc30e880700 20 osd.0 op_wq(2) _process empty q, waiting
-7> 2017-08-04 17:36:21.701275 7fc32b1b5700 1 -- 172.21.15.37:0/316573 <== osd.5 172.21.15.35:6809/14816 1 ==== osd_op_reply(5 rbd_data.10803bc4e8cd.0000000000000000 [list-snaps] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 182+0+0 (4112046353 0 0) 0x7fc33be48900 con 0x7fc33b44a800
-6> 2017-08-04 17:36:21.701472 7fc32b1b5700 1 -- 172.21.15.37:0/316573 <== osd.5 172.21.15.35:6809/14816 2 ==== osd_op_reply(6 rbd_data.10803bc4e8cd.0000000000000000 [copy-get max 8388608] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 182+0+103 (1547587044 0 1324605519) 0x7fc33be48900 con 0x7fc33b44a800
-5> 2017-08-04 17:36:21.701495 7fc309876700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] process_copy_chunk 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head tid 6 (2) No such file or directory
-4> 2017-08-04 17:36:21.701507 7fc309876700 20 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] process_copy_chunk complete r = (2) No such file or directory
-3> 2017-08-04 17:36:21.701512 7fc309876700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] finish_promote 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head r=-2 uv0
-2> 2017-08-04 17:36:21.701518 7fc309876700 10 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] finish_promote whiteout 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head
-1> 2017-08-04 17:36:21.701522 7fc309876700 20 osd.0 pg_epoch: 95 pg[12.2( v 95'3 (0'0,95'3] local-lis/les=88/89 n=2 ec=88/88 lis/c 88/88 les/c/f 89/89/0 88/88/88) [3,0] r=1 lpr=89 luod=0'0 crt=95'3 lcod 95'2 active] simple_opc_create 12:52b8f85c:::rbd_data.10803bc4e8cd.0000000000000000:head
0> 2017-08-04 17:36:21.703638 7fc309876700 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.2-163-g554a790/rpm/el7/BUILD/ceph-12.1.2-163-g554a790/src/osd/PG.h: In function 'eversion_t PG::get_next_version() const' thread 7fc309876700 time 2017-08-04 17:36:21.701531
/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.2-163-g554a790/rpm/el7/BUILD/ceph-12.1.2-163-g554a790/src/osd/PG.h: 2370: FAILED assert(at_version > info.last_update)
(note the r=1).