osd/PGLog.cc: 716: FAILED assert(log.log.size() == log_keys_debug.size())

osd/PGLog.cc: 716: FAILED assert(log.log.size() == log_keys_debug.size())

[David Zafman]

Your debugging code dumped out information ( tracker #10718 )

ubuntu@teuthology:/a/dzafman-2015-05-12_08:43:26-rados-wip-10809-11135-10290---basic-multi/887648

Missing 562'201 in log_keys_debug?

2015-05-12 14:36:52.874844 7f40906cf700 10 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (562'201,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] handle_peering_event: epoch_sent: 718 epoch_requested: 718 
MLogRec from 0
2015-05-12 14:36:52.874868 7f40906cf700 10 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (562'201,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] state<Started/Primary/Peering/GetLog>: GetLog: received 
master log from osd0
2015-05-12 14:36:52.874883 7f40906cf700 10 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (562'201,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] state<Started/Primary/Peering/GetLog>: leaving GetLog
2015-05-12 14:36:52.874896 7f40906cf700 10 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (562'201,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] state<Started/Primary/Peering/GetLog>: processing master log
2015-05-12 14:36:52.874907 7f40906cf700 10 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (562'201,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] proc_master_log for osd.0: log((0'0,562'201], crt=562'201) 
missing(0)
2015-05-12 14:36:52.874921 7f40906cf700 10 merge_log log((0'0,562'201], 
crt=562'201) from osd.0 into log((562'201,562'201], crt=562'201)
2015-05-12 14:36:52.874925 7f40906cf700 10 merge_log extending tail to 0'0
2015-05-12 14:36:52.874928 7f40906cf700 15 15'134 (0'0) modify 
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2212 2015-05-12 
14:04:42.823178
2015-05-12 14:36:52.874938 7f40906cf700 15 15'135 (15'134) modify 
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2213 2015-05-12 
14:04:42.844801
2015-05-12 14:36:52.874944 7f40906cf700 15 15'136 (15'135) modify 
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2214 2015-05-12 
14:04:42.848297
2015-05-12 14:36:52.874949 7f40906cf700 15 15'137 (15'136) modify 
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2215 2015-05-12 
14:04:42.848357
2015-05-12 14:36:52.874955 7f40906cf700 15 279'175 (15'137) modify 
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5420 2015-05-12 
14:19:04.447741
2015-05-12 14:36:52.874960 7f40906cf700 15 279'176 (279'175) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5421 2015-05-12 
14:19:04.464582
2015-05-12 14:36:52.874965 7f40906cf700 15 279'177 (279'176) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5422 2015-05-12 
14:19:04.464660
2015-05-12 14:36:52.874971 7f40906cf700 15 337'178 (279'177) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5808 2015-05-12 
14:20:50.892462
2015-05-12 14:36:52.874977 7f40906cf700 15 337'179 (337'178) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5809 2015-05-12 
14:20:50.914984
2015-05-12 14:36:52.874982 7f40906cf700 15 337'180 (337'179) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5810 2015-05-12 
14:20:50.916936
2015-05-12 14:36:52.874987 7f40906cf700 15 337'181 (337'180) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5811 2015-05-12 
14:20:50.916966
2015-05-12 14:36:52.874994 7f40906cf700 15 562'197 (337'181) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7714 2015-05-12 
14:30:30.661467
2015-05-12 14:36:52.874999 7f40906cf700 15 562'198 (562'197) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7715 2015-05-12 
14:30:30.681130
2015-05-12 14:36:52.875004 7f40906cf700 15 562'199 (562'198) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7716 2015-05-12 
14:30:30.700124
2015-05-12 14:36:52.875009 7f40906cf700 15 562'200 (562'199) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7717 2015-05-12 
14:30:30.700243
2015-05-12 14:36:52.875015 7f40906cf700 15 562'201 (562'200) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7718 2015-05-12 
14:30:30.700555
2015-05-12 14:36:52.875020 7f40906cf700 10 merge_log result 
log((0'0,562'201], crt=562'201) missing(0) changed=1
2015-05-12 14:36:52.875025 7f40906cf700 10 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering]  peer osd.0 now 1.17( v 562'201 (0'0,562'201] local-les=714 
n=1 ec=6 les/c 714/714 718/718/718) missing(0)
2015-05-12 14:36:52.875046 7f40906cf700  5 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] exit Started/Primary/Peering/GetLog 0.006766 2 0.000301
2015-05-12 14:36:52.875061 7f40906cf700 15 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] publish_stats_to_osd 718:24
2015-05-12 14:36:52.875074 7f40906cf700  5 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] enter Started/Primary/Peering/GetMissing
2015-05-12 14:36:52.875085 7f40906cf700 10 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] state<Started/Primary/Peering/GetMissing>:  still need 
up_thru update before going active
2015-05-12 14:36:52.875098 7f40906cf700  5 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] exit Started/Primary/Peering/GetMissing 0.000024 0 0.000000
2015-05-12 14:36:52.875111 7f40906cf700 15 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] publish_stats_to_osd 718: no change since
2015-05-12 14:36:52.875123 7f40906cf700  5 osd.4 pg_epoch: 718 pg[1.17( 
v 562'201 (0'0,562'201] local-les=714 n=1 ec=6 les/c 714/714 
718/718/718) [4,5] r=0 lpr=718 pi=629-717/4 crt=562'201 lcod 0'0 mlcod 
0'0 peering] enter Started/Primary/Peering/WaitUpThru
2015-05-12 14:36:52.875159 7f40906cf700  5 write_log with: dirty_to: 
562'201, dirty_from: 4294967295'18446744073709551615, 
dirty_divergent_priors: false, divergent_priors: 0, writeout_from: 
4294967295'18446744073709551615, trimmed:
2015-05-12 14:36:52.875277 7f40906cf700 -1 log.log.size() != 
log_keys_debug.size()
2015-05-12 14:36:52.875281 7f40906cf700 -1 actual log:
2015-05-12 14:36:52.875282 7f40906cf700 -1     15'134 (0'0) modify 
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2212 2015-05-12 
14:04:42.823178
2015-05-12 14:36:52.875293 7f40906cf700 -1     15'135 (15'134) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2213 2015-05-12 
14:04:42.844801
2015-05-12 14:36:52.875302 7f40906cf700 -1     15'136 (15'135) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2214 2015-05-12 
14:04:42.848297
2015-05-12 14:36:52.875310 7f40906cf700 -1     15'137 (15'136) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:2215 2015-05-12 
14:04:42.848357
2015-05-12 14:36:52.875319 7f40906cf700 -1     279'175 (15'137) modify   
90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5420 2015-05-12 
14:19:04.447741
2015-05-12 14:36:52.875328 7f40906cf700 -1     279'176 (279'175) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5421 
2015-05-12 14:19:04.464582
2015-05-12 14:36:52.875338 7f40906cf700 -1     279'177 (279'176) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5422 
2015-05-12 14:19:04.464660
2015-05-12 14:36:52.875344 7f40906cf700 -1     337'178 (279'177) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5808 
2015-05-12 14:20:50.892462
2015-05-12 14:36:52.875348 7f40906cf700 -1     337'179 (337'178) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5809 
2015-05-12 14:20:50.914984
2015-05-12 14:36:52.875353 7f40906cf700 -1     337'180 (337'179) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5810 
2015-05-12 14:20:50.916936
2015-05-12 14:36:52.875358 7f40906cf700 -1     337'181 (337'180) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:5811 
2015-05-12 14:20:50.916966
2015-05-12 14:36:52.875363 7f40906cf700 -1     562'197 (337'181) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7714 
2015-05-12 14:30:30.661467
2015-05-12 14:36:52.875368 7f40906cf700 -1     562'198 (562'197) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7715 
2015-05-12 14:30:30.681130
2015-05-12 14:36:52.875373 7f40906cf700 -1     562'199 (562'198) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7716 
2015-05-12 14:30:30.700124
2015-05-12 14:36:52.875377 7f40906cf700 -1     562'200 (562'199) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7717 
2015-05-12 14:30:30.700243
2015-05-12 14:36:52.875382 7f40906cf700 -1     562'201 (562'200) 
modify   90e1ad17/burnupi6122880-441/head//1 by client.4125.0:7718 
2015-05-12 14:30:30.700555
2015-05-12 14:36:52.875387 7f40906cf700 -1 log_keys_debug:
2015-05-12 14:36:52.875388 7f40906cf700 -1 0000000015.00000000000000000134
2015-05-12 14:36:52.875389 7f40906cf700 -1 0000000015.00000000000000000135
2015-05-12 14:36:52.875390 7f40906cf700 -1 0000000015.00000000000000000136
2015-05-12 14:36:52.875391 7f40906cf700 -1 0000000015.00000000000000000137
2015-05-12 14:36:52.875392 7f40906cf700 -1 0000000279.00000000000000000175
2015-05-12 14:36:52.875393 7f40906cf700 -1 0000000279.00000000000000000176
2015-05-12 14:36:52.875393 7f40906cf700 -1 0000000279.00000000000000000177
2015-05-12 14:36:52.875394 7f40906cf700 -1 0000000337.00000000000000000178
2015-05-12 14:36:52.875395 7f40906cf700 -1 0000000337.00000000000000000179
2015-05-12 14:36:52.875396 7f40906cf700 -1 0000000337.00000000000000000180
2015-05-12 14:36:52.875397 7f40906cf700 -1 0000000337.00000000000000000181
2015-05-12 14:36:52.875398 7f40906cf700 -1 0000000562.00000000000000000197
2015-05-12 14:36:52.875398 7f40906cf700 -1 0000000562.00000000000000000198
2015-05-12 14:36:52.875399 7f40906cf700 -1 0000000562.00000000000000000199
2015-05-12 14:36:52.875400 7f40906cf700 -1 0000000562.00000000000000000200
2015-05-12 14:36:52.894933 7f40906cf700 -1 osd/PGLog.cc: In function 
'void PGLog::check()' thread 7f40906cf700 time 2015-05-12 14:36:52.875403
osd/PGLog.cc: 716: FAILED assert(log.log.size() == log_keys_debug.size())

  ceph version 9.0.0-682-g8f4927e (8f4927eab2f016edeb5719f67d109e9abb3180f7)
  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char 
const*)+0x7f) [0xaebcff]
  2: (PGLog::check()+0x794) [0x7324e4]
  3: (PGLog::write_log(ObjectStore::Transaction&, std::map<std::string, 
ceph::buffer::list, std::less<std::string>, 
std::allocator<std::pair<std::string const, ceph::buffer::list> > >*, 
coll_t const&, ghobject_t const&)+0x1c4) [0x73b604]
  4: (PG::write_if_dirty(ObjectStore::Transaction&)+0x87) [0x78e1c7]
  5: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > 
const&, ThreadPool::TPHandle&)+0x2c0) [0x673c80]
  6: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > 
const&, ThreadPool::TPHandle&)+0x12) [0x6c9652]
  7: (ThreadPool::worker(ThreadPool::WorkThread*)+0x48e) [0xadb1de]
  8: (ThreadPool::WorkThread::entry()+0x10) [0xaddfe0]
  9: (()+0x7e9a) [0x7f40a9c14e9a]
  10: (clone()+0x6d) [0x7f40a83bd3fd]