Ceph » RADOS

   -37> 2017-10-05 22:50:26.680889 7f38ec092700 10 journal op_submit_finish 6792
   -36> 2017-10-05 22:50:26.680900 7f38ec092700 10 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] eval_repop repgather(0x55a5038c
a580 441'2098 rep_tid=1518 committed?=0 applied?=0 r=0) (no op)
   -35> 2017-10-05 22:50:26.680928 7f3908062700 20 filestore dbobjectmap: seq is 139
   -34> 2017-10-05 22:50:26.680933 7f38ec092700 10 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] agent_choose_mode flush_mode: i
   -33> 2017-10-05 22:50:26.680947 7f38ec092700 20 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] agent_choose_mode dirty 0.387096 full 0.790322
   -32> 2017-10-05 22:50:26.680973 7f38ec092700 10 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] kick_object_context_blocked 3:c68c7f92:::smithi20116203-320:head requeuing 6 requests
   -31> 2017-10-05 22:50:26.680988 7f38ec092700 20 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] requeue_ops 0x55a501ab9a40
   -30> 2017-10-05 22:50:26.681001 7f38ec092700 20 osd.4 op_wq(3) _enqueue_front 3.3 PGQueueable(0x55a501ab9a40 prio 63 cost 0 e441)
   -24> 2017-10-05 22:50:26.681013 7f38ec092700 20 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] requeue_ops 0x55a501aba840
   -21> 2017-10-05 22:50:26.681036 7f38ec092700 20 osd.4 op_wq(3) _enqueue_front 3.3 PGQueueable(0x55a501aba840 prio 63 cost 66 e441) shuffled w/ PGQueueable(0x55a501ab9a40 prio 63 cost 0 e441)
   -20> 2017-10-05 22:50:26.681045 7f38ec092700 20 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] requeue_ops 0x55a501aba680
   -19> 2017-10-05 22:50:26.681058 7f38ec092700 20 osd.4 op_wq(3) _enqueue_front 3.3 PGQueueable(0x55a501aba680 prio 63 cost 582380 e441) shuffled w/ PGQueueable(0x55a501aba840 prio 63 cost 66 e441)
   -18> 2017-10-05 22:50:26.681061 7f38ec092700 20 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] requeue_ops 0x55a50227b640
   -17> 2017-10-05 22:50:26.681070 7f38ec092700 20 osd.4 op_wq(3) _enqueue_front 3.3 PGQueueable(0x55a50227b640 prio 63 cost 0 e441) shuffled w/ PGQueueable(0x55a501aba680 prio 63 cost 582380 e441)
   -16> 2017-10-05 22:50:26.681073 7f38ec092700 20 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] requeue_ops 0x55a50227a300
   -15> 2017-10-05 22:50:26.681084 7f38ec092700 20 osd.4 op_wq(3) _enqueue_front 3.3 PGQueueable(0x55a50227a300 prio 63 cost 66 e441) shuffled w/ PGQueueable(0x55a50227b640 prio 63 cost 0 e441)
   -14> 2017-10-05 22:50:26.681087 7f38ec092700 20 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] requeue_ops 0x55a50227a680
   -13> 2017-10-05 22:50:26.681096 7f38ec092700 20 osd.4 op_wq(3) _enqueue_front 3.3 PGQueueable(0x55a50227a680 prio 63 cost 582380 e441) shuffled w/ PGQueueable(0x55a50227a300 prio 63 cost 66 e441)
    -2> 2017-10-05 22:50:26.681252 7f38ec092700 10 osd.4 pg_epoch: 441 pg[3.3( v 441'2098 (367'1702,441'2098] local-lis/les=19/20 n=49 ec=19/19 lis/c 19/19 les/c/f 20/20/0 19/19/19) [4,0,6] r=0 lpr=19 luod=441'2097 lua=441'2095 crt=441'2098 lcod 441'2095 mlcod 441'2095 active+clean] finish_flush 3:f4299464:::smithi20116203-226:17c tid 1278 (0) Success
     0> 2017-10-05 22:50:26.683726 7f38ec092700 -1 /build/ceph-12.2.1-93-g1304d34/src/osd/PrimaryLogPG.cc: In function 'void PrimaryLogPG::kick_object_context_blocked(ObjectContextRef)' thread 7f38ec092700 time 2017-10-05 22:50:26.681275
/build/ceph-12.2.1-93-g1304d34/src/osd/PrimaryLogPG.cc: 10195: FAILED assert(i->second == obc)

 ceph version 12.2.1-93-g1304d34 (1304d343bfb323c0f86e6a1ca0a76a0d1ea95618) luminous (stable)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x102) [0x55a4f4e43f82]
 2: (PrimaryLogPG::kick_object_context_blocked(std::shared_ptr<ObjectContext>)+0x394) [0x55a4f49a0624]
 3: (PrimaryLogPG::try_flush_mark_clean(std::shared_ptr<PrimaryLogPG::FlushOp>)+0x84) [0x55a4f49e0494]
 4: (PrimaryLogPG::finish_flush(hobject_t, unsigned long, int)+0x29a) [0x55a4f49e562a]
 5: (C_Flush::finish(int)+0xb8) [0x55a4f4a5aac8]
 6: (Context::complete(int)+0x9) [0x55a4f488e2b9]
 7: (Finisher::finisher_thread_entry()+0x460) [0x55a4f4e424a0]
 8: (()+0x770a) [0x7f3914b8c70a]
 9: (clone()+0x6d) [0x7f3913c0382d]

/a/sage-2017-10-05_22:34:19-rados-wip-sage-testing-2017-10-05-1601-distro-basic-smithi/1707439