Project

General

Profile

Bug #7915 ยป ceph-osd.11.log

Yann Dupont, 03/10/2015 08:42 AM

 
2015-03-10 09:11:00.290207 7f79762f6840 0 ceph version 0.93 (bebf8e9a830d998eeaab55f86bb256d4360dd3c4), process ceph-osd, pid 9460
2015-03-10 09:11:00.291346 7f79762f6840 1 -- 172.20.108.164:0/0 learned my addr 172.20.108.164:0/0
2015-03-10 09:11:00.291372 7f79762f6840 1 accepter.accepter.bind my_inst.addr is 172.20.108.164:6800/9460 need_addr=0
2015-03-10 09:11:00.291406 7f79762f6840 1 -- 172.20.114.164:0/0 learned my addr 172.20.114.164:0/0
2015-03-10 09:11:00.291414 7f79762f6840 1 accepter.accepter.bind my_inst.addr is 172.20.114.164:6800/9460 need_addr=0
2015-03-10 09:11:00.291439 7f79762f6840 1 -- 172.20.114.164:0/0 learned my addr 172.20.114.164:0/0
2015-03-10 09:11:00.291452 7f79762f6840 1 accepter.accepter.bind my_inst.addr is 172.20.114.164:6801/9460 need_addr=0
2015-03-10 09:11:00.291474 7f79762f6840 1 -- 172.20.108.164:0/0 learned my addr 172.20.108.164:0/0
2015-03-10 09:11:00.291482 7f79762f6840 1 accepter.accepter.bind my_inst.addr is 172.20.108.164:6801/9460 need_addr=0
2015-03-10 09:11:00.298154 7f79762f6840 10 filestore(/CEPH/E.11) dump_stop
2015-03-10 09:11:00.311513 7f79762f6840 10 ErasureCodePluginSelectJerasure: load: jerasure_sse4
2015-03-10 09:11:00.319978 7f79762f6840 10 load: jerasure load: lrc
2015-03-10 09:11:00.320410 7f79762f6840 5 filestore(/CEPH/E.11) test_mount basedir /CEPH/E.11 journal /var/lib/ceph/osd/ceph-11/journal-11
2015-03-10 09:11:00.320482 7f79762f6840 1 -- 172.20.108.164:6800/9460 messenger.start
2015-03-10 09:11:00.320558 7f79762f6840 1 -- :/0 messenger.start
2015-03-10 09:11:00.320693 7f79762f6840 1 -- 172.20.108.164:6801/9460 messenger.start
2015-03-10 09:11:00.320756 7f79762f6840 1 -- 172.20.114.164:6801/9460 messenger.start
2015-03-10 09:11:00.320806 7f79762f6840 1 -- 172.20.114.164:6800/9460 messenger.start
2015-03-10 09:11:00.320853 7f79762f6840 1 -- :/0 messenger.start
2015-03-10 09:11:00.320980 7f79762f6840 2 osd.11 0 mounting /CEPH/E.11 /var/lib/ceph/osd/ceph-11/journal-11
2015-03-10 09:11:00.321012 7f79762f6840 5 filestore(/CEPH/E.11) basedir /CEPH/E.11 journal /var/lib/ceph/osd/ceph-11/journal-11
2015-03-10 09:11:00.321054 7f79762f6840 10 filestore(/CEPH/E.11) mount fsid is 1e95df44-cb10-4c59-8886-7291f4670dad
2015-03-10 09:11:00.321193 7f79762f6840 0 filestore(/CEPH/E.11) backend xfs (magic 0x58465342)
2015-03-10 09:11:00.345011 7f79762f6840 0 genericfilestorebackend(/CEPH/E.11) detect_features: FIEMAP ioctl is supported and appears to work
2015-03-10 09:11:00.345030 7f79762f6840 0 genericfilestorebackend(/CEPH/E.11) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2015-03-10 09:11:00.346871 7f79762f6840 0 genericfilestorebackend(/CEPH/E.11) detect_features: syscall(SYS_syncfs, fd) fully supported
2015-03-10 09:11:00.347259 7f79762f6840 0 xfsfilestorebackend(/CEPH/E.11) detect_feature: extsize is supported and kernel 3.14.14-dsiun-130719 >= 3.5
2015-03-10 09:11:00.348123 7f79762f6840 5 filestore(/CEPH/E.11) mount op_seq is 15032786
2015-03-10 09:11:00.461982 7f79762f6840 20 filestore (init)dbobjectmap: seq is 917934
2015-03-10 09:11:00.462018 7f79762f6840 10 filestore(/CEPH/E.11) open_journal at /var/lib/ceph/osd/ceph-11/journal-11
2015-03-10 09:11:00.462074 7f79762f6840 0 filestore(/CEPH/E.11) mount: WRITEAHEAD journal mode explicitly enabled in conf
2015-03-10 09:11:00.462082 7f79762f6840 10 filestore(/CEPH/E.11) list_collections
2015-03-10 09:11:00.469754 7f79762f6840 -1 journal FileJournal::_open: disabling aio for non-block journal. Use journal_force_aio to force use of aio anyway
2015-03-10 09:11:00.469769 7f79762f6840 1 journal _open /var/lib/ceph/osd/ceph-11/journal-11 fd 19: 5242880000 bytes, block size 4096 bytes, directio = 1, aio = 0
2015-03-10 09:11:00.469721 7f796b4c5700 20 filestore(/CEPH/E.11) sync_entry waiting for max_interval 15.000000
2015-03-10 09:11:00.470810 7f79762f6840 10 filestore(/CEPH/E.11) _do_transaction on 0x4699340
2015-03-10 09:11:00.470844 7f79762f6840 15 filestore(/CEPH/E.11) _omap_setkeys 21.90s0_head/90//head//21/18446744073709551615/0
2015-03-10 09:11:00.471334 7f79762f6840 10 filestore oid: 90//head//21/18446744073709551615/0 not skipping op, *spos 15032787.0.0
2015-03-10 09:11:00.471349 7f79762f6840 10 filestore > header.spos 0.0.0
2015-03-10 09:11:00.471506 7f79762f6840 20 filestore(/CEPH/E.11) _omap_setkeys 21.90s0_head/90//head//21/18446744073709551615/0 = 0
2015-03-10 09:11:00.472830 7f79762f6840 10 filestore(/CEPH/E.11) _do_transaction on 0x4699340
2015-03-10 09:11:00.472888 7f79762f6840 20 filestore(/CEPH/E.11) _check_global_replay_guard no xattr
2015-03-10 09:11:00.472997 7f79762f6840 20 filestore(/CEPH/E.11) _check_replay_guard no xattr
2015-03-10 09:11:00.473023 7f79762f6840 15 filestore(/CEPH/E.11) write meta/a69f6357/inc_osdmap.8957/0//-1 0~182
2015-03-10 09:11:00.473101 7f79762f6840 10 filestore(/CEPH/E.11) write meta/a69f6357/inc_osdmap.8957/0//-1 0~182 = 182
2015-03-10 09:11:00.473136 7f79762f6840 20 filestore(/CEPH/E.11) _check_global_replay_guard no xattr
2015-03-10 09:11:00.473197 7f79762f6840 20 filestore(/CEPH/E.11) _check_replay_guard no xattr
2015-03-10 09:11:00.473209 7f79762f6840 15 filestore(/CEPH/E.11) write meta/a3ddde8/osdmap.8957/0//-1 0~25059
2015-03-10 09:11:00.473279 7f79762f6840 10 filestore(/CEPH/E.11) write meta/a3ddde8/osdmap.8957/0//-1 0~25059 = 25059
2015-03-10 09:11:00.473311 7f79762f6840 20 filestore(/CEPH/E.11) _check_global_replay_guard no xattr
2015-03-10 09:11:00.473352 7f79762f6840 20 filestore(/CEPH/E.11) _check_replay_guard no xattr
2015-03-10 09:11:00.473372 7f79762f6840 15 filestore(/CEPH/E.11) write meta/23c2fcde/osd_superblock/0//-1 0~440
2015-03-10 09:11:00.473417 7f79762f6840 10 filestore(/CEPH/E.11) write meta/23c2fcde/osd_superblock/0//-1 0~440 = 440
2015-03-10 09:11:00.473476 7f79762f6840 10 filestore(/CEPH/E.11) _do_transaction on 0x4699340
2015-03-10 09:11:00.473490 7f79762f6840 15 filestore(/CEPH/E.11) _omap_setkeys 17.4e_head/4e//head//17
2015-03-10 09:11:00.473623 7f79762f6840 10 filestore oid: 4e//head//17 not skipping op, *spos 15032789.0.0
2015-03-10 09:11:00.473635 7f79762f6840 10 filestore > header.spos 0.0.0
2015-03-10 09:11:00.473670 7f79762f6840 20 filestore(/CEPH/E.11) _omap_setkeys 17.4e_head/4e//head//17 = 0
2015-03-10 09:11:00.473725 7f79762f6840 10 filestore(/CEPH/E.11) _do_transaction on 0x4699340
2015-03-10 09:11:00.473738 7f79762f6840 15 filestore(/CEPH/E.11) _omap_setkeys 17.86_head/86//head//17
2015-03-10 09:11:00.473848 7f79762f6840 10 filestore oid: 86//head//17 not skipping op, *spos 15032790.0.0
2015-03-10 09:11:00.473861 7f79762f6840 10 filestore > header.spos 0.0.0
2015-03-10 09:11:00.473889 7f79762f6840 20 filestore(/CEPH/E.11) _omap_setkeys 17.86_head/86//head//17 = 0
2015-03-10 09:11:00.473939 7f79762f6840 10 filestore(/CEPH/E.11) _do_transaction on 0x4699340
2015-03-10 09:11:00.473951 7f79762f6840 15 filestore(/CEPH/E.11) _omap_setkeys 17.40_head/40//head//17
2015-03-10 09:11:00.474043 7f79762f6840 10 filestore oid: 40//head//17 not skipping op, *spos 15032791.0.0
2015-03-10 09:11:00.474054 7f79762f6840 10 filestore > header.spos 0.0.0
2015-03-10 09:11:00.474082 7f79762f6840 20 filestore(/CEPH/E.11) _omap_setkeys 17.40_head/40//head//17 = 0
2015-03-10 09:11:00.474129 7f79762f6840 10 filestore(/CEPH/E.11) _do_transaction on 0x4699340
2015-03-10 09:11:00.474140 7f79762f6840 15 filestore(/CEPH/E.11) _omap_setkeys 17.9e_head/9e//head//17
2015-03-10 09:11:00.474230 7f79762f6840 10 filestore oid: 9e//head//17 not skipping op, *spos 15032792.0.0
2015-03-10 09:11:00.474242 7f79762f6840 10 filestore > header.spos 0.0.0
2015-03-10 09:11:00.474289 7f79762f6840 20 filestore(/CEPH/E.11) _omap_setkeys 17.9e_head/9e//head//17 = 0
2015-03-10 09:11:00.474343 7f79762f6840 10 filestore(/CEPH/E.11) _do_transaction on 0x4699340
2015-03-10 09:11:00.474356 7f79762f6840 15 filestore(/CEPH/E.11) _omap_setkeys 17.83_head/83//head//17
2015-03-10 09:11:00.474450 7f79762f6840 10 filestore oid: 83//head//17 not skipping op, *spos 15032793.0.0
2015-03-10 09:11:00.474461 7f79762f6840 10 filestore > header.spos 0.0.0

[Lines deleted]


2015-03-10 09:11:18.064190 7f79565e6700 10 log is not dirty
2015-03-10 09:11:18.064206 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[21.85s4( v 8385'75772 (8380'72771,8385'75772] local-les=8756 n=12658 ec=5573 les/c 8756/8662 8886/9050/8991) [3,4,6,7,2,0,5,8]/[2147483647,2147483647,0,3,11,8,5,2] r=4 lpr=9050 pi=7008-9049/150 crt=8385'75763 lcod 0'0 remapped NOTIFY] handle_peering_event: epoch_sent: 9050 epoch_requested: 9050 MQuery from 0(2) query_epoch 9050 query: query(info 0'0)
2015-03-10 09:11:18.064232 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[21.85s4( v 8385'75772 (8380'72771,8385'75772] local-les=8756 n=12658 ec=5573 les/c 8756/8662 8886/9050/8991) [3,4,6,7,2,0,5,8]/[2147483647,2147483647,0,3,11,8,5,2] r=4 lpr=9050 pi=7008-9049/150 crt=8385'75763 lcod 0'0 remapped NOTIFY] sending info
2015-03-10 09:11:18.064486 7f79565e6700 10 log is not dirty
2015-03-10 09:11:18.064509 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 8883/8871 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] handle_peering_event: epoch_sent: 9050 epoch_requested: 9050 MNotifyRec from 0 notify: (query_epoch:9050, epoch_sent:9050, info:22.79( v 8641'408193 (8385'405169,8641'408193] local-les=9013 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)) features: 0x3ffffffffffff
2015-03-10 09:11:18.064543 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 8883/8871 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] got osd.0 22.79( v 8641'408193 (8385'405169,8641'408193] local-les=9013 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)
2015-03-10 09:11:18.064575 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] update_heartbeat_peers 0,2,11 unchanged
2015-03-10 09:11:18.064593 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: last_epoch_started moved forward, rebuilding prior
2015-03-10 09:11:18.064616 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(9045-9049 up [2,0](2) acting [2,0](2) maybe_went_rw)
2015-03-10 09:11:18.064637 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(9010-9044 up [0](0) acting [0](0) maybe_went_rw)
2015-03-10 09:11:18.064657 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(8998-9009 up [11,0](11) acting [11,0](11) maybe_went_rw)
2015-03-10 09:11:18.064675 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior final: probe 0,2,11 down blocked_by {}
2015-03-10 09:11:18.064849 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] up_thru 9053 >= same_since 9050, all is well
2015-03-10 09:11:18.064873 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: have osd.0 info 22.79( v 8641'408193 (8385'405169,8641'408193] local-les=9013 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)
2015-03-10 09:11:18.064894 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: have osd.2 info 22.79( v 8641'408193 (8385'405193,8641'408193] lb 69c407f9/rbd_data.1e9e2ae8944a.000000000014e636/head//22 local-les=8883 n=6149 ec=5576 les/c 8883/8871 9050/9050/9050)
2015-03-10 09:11:18.064934 7f79565e6700 15 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] publish_stats_to_osd 9054:725116
2015-03-10 09:11:18.064952 7f79565e6700 20 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: Adding osd: 0 features: 3ffffffffffff
2015-03-10 09:11:18.064968 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: last maybe_went_rw interval was interval(9045-9049 up [2,0](2) acting [2,0](2) maybe_went_rw)
2015-03-10 09:11:18.064987 7f79565e6700 20 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: Common features: 3ffffffffffff
2015-03-10 09:11:18.065007 7f79565e6700 5 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] exit Started/Primary/Peering/GetInfo 6.496472 20 0.002236
2015-03-10 09:11:18.065032 7f79565e6700 5 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] enter Started/Primary/Peering/GetLog
2015-03-10 09:11:18.065076 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] calc_acting osd.0 22.79( v 8641'408193 (8385'405169,8641'408193] local-les=9013 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)
2015-03-10 09:11:18.065098 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] calc_acting osd.2 22.79( v 8641'408193 (8385'405193,8641'408193] lb 69c407f9/rbd_data.1e9e2ae8944a.000000000014e636/head//22 local-les=8883 n=6149 ec=5576 les/c 8883/8871 9050/9050/9050)
2015-03-10 09:11:18.065117 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] calc_acting osd.11 22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)
2015-03-10 09:11:18.065137 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] calc_acting prefer osd.11 because it is current primary
2015-03-10 09:11:18.065172 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] calc_acting newest update on osd.11 with 22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)
up_primary: 11) selected as primary
calc_acting primary is osd.11 with 22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)
osd.0 (up) accepted 22.79( v 8641'408193 (8385'405169,8641'408193] local-les=9013 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050)

2015-03-10 09:11:18.065196 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] actingbackfill is 0,11
2015-03-10 09:11:18.065212 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] choose_acting want [11,0] (== acting) backfill_targets
2015-03-10 09:11:18.065235 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetLog>: leaving GetLog
2015-03-10 09:11:18.065267 7f79565e6700 5 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] exit Started/Primary/Peering/GetLog 0.000234 0 0.000000
2015-03-10 09:11:18.065289 7f79565e6700 15 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] publish_stats_to_osd 9054: no change since
2015-03-10 09:11:18.065308 7f79565e6700 5 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] enter Started/Primary/Peering/GetMissing
2015-03-10 09:11:18.065324 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetMissing>: osd.0 has no missing, identical log
2015-03-10 09:11:18.065353 7f79565e6700 5 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] exit Started/Primary/Peering/GetMissing 0.000045 0 0.000000
2015-03-10 09:11:18.065377 7f79565e6700 15 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] publish_stats_to_osd 9054: no change since
2015-03-10 09:11:18.065394 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering>: Leaving Peering
2015-03-10 09:11:18.065410 7f79565e6700 5 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 peering] exit Started/Primary/Peering 6.496909 0 0.000000
2015-03-10 09:11:18.065433 7f79565e6700 5 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 inactive] enter Started/Primary/Active
2015-03-10 09:11:18.065453 7f79565e6700 10 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=8570 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 inactive] state<Started/Primary/Active>: In Active, about to call activate
2015-03-10 09:11:18.065477 7f79565e6700 20 osd.11 pg_epoch: 9054 pg[22.79( v 8641'408193 (8385'405169,8641'408193] local-les=9054 n=8717 ec=5576 les/c 9013/9017 9050/9050/9050) [11,0] r=0 lpr=9050 pi=8569-9049/10 crt=8641'408191 lcod 0'0 mlcod 0'0 inactive] activate - purged_snaps [1~7,9~4,e~6] cached_removed_snaps [1~3]
2015-03-10 09:11:18.065738 7f7957de9700 5 osd.11 pg_epoch: 9054 pg[22.11( v 8641'424393 (8385'421393,8641'424393] lb 0//0//-1 local-les=9054 n=0 ec=5576 les/c 9038/9019 9050/9050/8874) [11,0]/[2] r=-1 lpr=9054 pi=9010-9049/3 crt=0'0 lcod 0'0 inactive] exit Started/Stray 0.052445 1 0.000180
2015-03-10 09:11:18.065772 7f7957de9700 5 osd.11 pg_epoch: 9054 pg[22.11( v 8641'424393 (8385'421393,8641'424393] lb 0//0//-1 local-les=9054 n=0 ec=5576 les/c 9038/9019 9050/9050/8874) [11,0]/[2] r=-1 lpr=9054 pi=9010-9049/3 crt=0'0 lcod 0'0 inactive] enter Started/ReplicaActive
2015-03-10 09:11:18.065794 7f7957de9700 5 osd.11 pg_epoch: 9054 pg[22.11( v 8641'424393 (8385'421393,8641'424393] lb 0//0//-1 local-les=9054 n=0 ec=5576 les/c 9038/9019 9050/9050/8874) [11,0]/[2] r=-1 lpr=9054 pi=9010-9049/3 crt=0'0 lcod 0'0 inactive] enter Started/ReplicaActive/RepNotRecovering
2015-03-10 09:11:18.065815 7f7957de9700 10 osd.11 pg_epoch: 9054 pg[22.11( v 8641'424393 (8385'421393,8641'424393] lb 0//0//-1 local-les=9054 n=0 ec=5576 les/c 9038/9019 9050/9050/8874) [11,0]/[2] r=-1 lpr=9054 pi=9010-9049/3 crt=0'0 lcod 0'0 inactive] state<Started/ReplicaActive>: In ReplicaActive, about to call activate
2015-03-10 09:11:18.065834 7f7957de9700 10 osd.11 pg_epoch: 9054 pg[22.11( v 8641'424393 (8385'421393,8641'424393] lb 0//0//-1 local-les=9054 n=0 ec=5576 les/c 9038/9019 9050/9050/8874) [11,0]/[2] r=-1 lpr=9054 pi=9010-9049/3 crt=0'0 lcod 0'0 inactive] activate - no missing, moving last_complete 8641'424393 -> 8641'424393
2015-03-10 09:11:18.065932 7f7957de9700 10 osd.11 pg_epoch: 9054 pg[22.11( v 8641'424393 (8385'421393,8641'424393] lb 0//0//-1 local-les=9054 n=0 ec=5576 les/c 9038/9019 9050/9050/8874) [11,0]/[2] r=-1 lpr=9054 pi=9010-9049/3 crt=0'0 lcod 0'0 inactive] state<Started/ReplicaActive>: Activate Finished
2015-03-10 09:11:18.067071 7f7957de9700 10 write_log with: dirty_to: 4294967295'18446744073709551615, dirty_from: 4294967295'18446744073709551615, dirty_divergent_priors: 1, writeout_from: 4294967295'18446744073709551615, trimmed:
2015-03-10 09:11:18.077513 7f79565e6700 -1 ./include/interval_set.h: In function 'void interval_set<T>::erase(T, T) [with T = snapid_t]' thread 7f79565e6700 time 2015-03-10 09:11:18.065498
./include/interval_set.h: 385: FAILED assert(_size >= 0)

ceph version 0.93 (bebf8e9a830d998eeaab55f86bb256d4360dd3c4)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x72) [0xcd7342]
2: (interval_set<snapid_t>::subtract(interval_set<snapid_t> const&)+0xa0) [0x93fba0]
3: (PG::activate(ObjectStore::Transaction&, unsigned int, std::list<Context*, std::allocator<Context*> >&, std::map<int, std::map<spg_t, pg_query_t, std::less<spg_t>, std::allocator<std::pair<spg_t const, pg_query_t> > >, std::less<int>, std::allocator<std::pair<int const, std::map<spg_t, pg_query_t, std::less<spg_t>, std::allocator<std::pair<spg_t const, pg_query_t> > > > > >&, std::map<int, std::vector<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > >, std::allocator<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > > > >, std::less<int>, std::allocator<std::pair<int const, std::vector<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > >, std::allocator<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > > > > > > >*, PG::RecoveryCtx*)+0xd63) [0x911543]
4: (PG::RecoveryState::Active::Active(boost::statechart::state<PG::RecoveryState::Active, PG::RecoveryState::Primary, PG::RecoveryState::Activating, (boost::statechart::history_mode)0>::my_context)+0x53a) [0x91415a]
5: (boost::statechart::state<PG::RecoveryState::Active, PG::RecoveryState::Primary, PG::RecoveryState::Activating, (boost::statechart::history_mode)0>::shallow_construct(boost::intrusive_ptr<PG::RecoveryState::Primary> const&, boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>&)+0x5c) [0x9503ac]
6: (boost::statechart::state<PG::RecoveryState::Active, PG::RecoveryState::Primary, PG::RecoveryState::Activating, (boost::statechart::history_mode)0>::deep_construct(boost::intrusive_ptr<PG::RecoveryState::Primary> const&, boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>&)+0x16) [0x951746]
7: (boost::statechart::detail::safe_reaction_result boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>::transit_impl<PG::RecoveryState::Active, PG::RecoveryState::RecoveryMachine, boost::statechart::detail::no_transition_function>(boost::statechart::detail::no_transition_function const&)+0x8d) [0x95181d]
8: (boost::statechart::transition<PG::Activate, PG::RecoveryState::Active, boost::statechart::detail::no_context<PG::Activate>, &boost::statechart::detail::no_context<PG::Activate>::no_function>::reactions<PG::RecoveryState::Peering>::react_without_action(PG::RecoveryState::Peering&)+0x12) [0x9518b2]
9: (boost::statechart::detail::reaction_result boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>::local_react_impl_non_empty::local_react_impl<boost::mpl::list2<boost::statechart::transition<PG::Activate, PG::RecoveryState::Active, boost::statechart::detail::no_context<PG::Activate>, &boost::statechart::detail::no_context<PG::Activate>::no_function>, boost::statechart::custom_reaction<PG::AdvMap> >, boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0> >(boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>&, boost::statechart::event_base const&, void const*)+0x7b) [0x95193b]
10: (boost::statechart::detail::reaction_result boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>::local_react_impl_non_empty::local_react_impl<boost::mpl::list<boost::statechart::custom_reaction<PG::QueryState>, boost::statechart::transition<PG::Activate, PG::RecoveryState::Active, boost::statechart::detail::no_context<PG::Activate>, &boost::statechart::detail::no_context<PG::Activate>::no_function>, boost::statechart::custom_reaction<PG::AdvMap>, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0> >(boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>&, boost::statechart::event_base const&, void const*)+0x57) [0x9519a7]
11: (boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x21) [0x951a21]
12: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_queued_events()+0x137) [0x931d57]
13: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::event_base const&)+0x26) [0x932356]
14: (PG::RecoveryState::handle_event(std::tr1::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x31) [0x9323e1]
15: (PG::handle_peering_event(std::tr1::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x338) [0x8e78f8]
16: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x34f) [0x7d273f]
17: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x14) [0x837c74]
18: (ThreadPool::worker(ThreadPool::WorkThread*)+0x629) [0xcc8c49]
19: (ThreadPool::WorkThread::entry()+0x10) [0xccac40]
20: (()+0x6b50) [0x7f7975200b50]
21: (clone()+0x6d) [0x7f7973c1c95d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

2015-03-10 09:11:18.079788 7f796a1b8700 5 filestore(/CEPH/E.11) _journaled_ahead 0x25441680 seq 15035284 osr(22.33 0x25106880) 0x26140fc0
2015-03-10 09:11:18.079808 7f796a1b8700 5 filestore(/CEPH/E.11) queue_op 0x25441680 seq 15035284 osr(22.33 0x25106880) 671435 bytes (queue has 5 ops and 1364961 bytes)
2015-03-10 09:11:18.079827 7f796a1b8700 10 filestore(/CEPH/E.11) queueing ondisk 0x26a0b4a0
2015-03-10 09:11:18.079836 7f796a1b8700 5 filestore(/CEPH/E.11) _journaled_ahead 0x51504b0 seq 15035285 osr(22.53 0x462fee0) 0x252f16c0
2015-03-10 09:11:18.079843 7f796a1b8700 5 filestore(/CEPH/E.11) queue_op 0x51504b0 seq 15035285 osr(22.53 0x462fee0) 673349 bytes (queue has 5 ops and 1364961 bytes)
2015-03-10 09:11:18.079855 7f796a1b8700 10 filestore(/CEPH/E.11) queueing ondisk 0x25370bc0
2015-03-10 09:11:18.079859 7f796a1b8700 5 filestore(/CEPH/E.11) _journaled_ahead 0x25423950 seq 15035286 osr(21.52s5 0x66ae540) 0x26c9a700
2015-03-10 09:11:18.079874 7f796a1b8700 5 filestore(/CEPH/E.11) queue_op 0x25423950 seq 15035286 osr(21.52s5 0x66ae540) 2891 bytes (queue has 5 ops and 1364961 bytes)
2015-03-10 09:11:18.079884 7f796a1b8700 10 filestore(/CEPH/E.11) queueing ondisk 0x2704a340
2015-03-10 09:11:18.079887 7f796a1b8700 5 filestore(/CEPH/E.11) _journaled_ahead 0x51503c0 seq 15035287 osr(21.58s2 0x66ae4d0) 0x25c63dc0
2015-03-10 09:11:18.079876 7f79691b6700 5 filestore(/CEPH/E.11) _do_op 0x25441680 seq 15035284 osr(22.33 0x25106880)/0x25106880 start
2015-03-10 09:11:18.079892 7f796a1b8700 5 filestore(/CEPH/E.11) queue_op 0x51503c0 seq 15035287 osr(21.58s2 0x66ae4d0) 14296 bytes (queue has 5 ops and 1364961 bytes)
2015-03-10 09:11:18.079894 7f79691b6700 10 filestore(/CEPH/E.11) _do_transaction on 0x26140fc0
2015-03-10 09:11:18.079926 7f79691b6700 15 filestore(/CEPH/E.11) _omap_setkeys 22.33_head/33//head//22
    (1-1/1)