Actions
Bug #9630
closedosd: leaked pg refs on shutdown (dumpling)
% Done:
0%
Source:
Q/A
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
-3> 2014-09-30 05:11:35.482597 1dd14700 20 osd.2 45 kicking pg 2.15
-2> 2014-09-30 05:11:35.484593 1dd14700 30 osd.2 pg_epoch: 45 pg[2.15( empty local-les=45 n=0 ec=1 les/c 45/45 44/44/44) [2] r=0 lpr=44 mlcod 0'0 active+degraded] lock
-1> 2014-09-30 05:11:35.485793 1dd14700 -1 osd.2 45 pgid 2.15 has ref count of 2
0> 2014-09-30 05:11:35.971218 1dd14700 -1 osd/OSD.cc: In function 'int OSD::shutdown()' thread 1dd14700 time 2014-09-30 05:11:35.494271
osd/OSD.cc: 1612: FAILED assert(0)
ceph version 0.67.11-5-g3ebc350 (3ebc35026c697ed2b895fdc85f49056a007c7571)
1: (OSD::shutdown()+0x150d) [0x66454d]
2: (OSD::handle_signal(int)+0x118) [0x664b68]
3: (SignalHandler::entry()+0x18b) [0x7fd9bb]
4: (()+0x7e9a) [0x503be9a]
5: (clone()+0x6d) [0x6afd31d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
ubuntu@teuthology:/a/teuthology-2014-09-29_19:04:02-rgw-dumpling-testing-basic-vps/518660
Updated by Loïc Dachary over 9 years ago
The full valgrind report from remote/vpm180/log/valgrind/osd.2.log.gz
<error>
<unique>0x3d8</unique>
<tid>1</tid>
<kind>Leak_DefinitelyLost</kind>
<xwhat>
<text>144 (48 direct, 96 indirect) bytes in 2 blocks are definitely lost in loss record 982 of 1,523</text>
<leakedbytes>144</leakedbytes>
<leakedblocks>2</leakedblocks>
</xwhat>
<stack>
<frame>
<ip>0x4C2B1C7</ip>
<obj>/usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so</obj>
<fn>operator new(unsigned long)</fn>
</frame>
<frame>
<ip>0x6F0165</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>PG::finish_recovery(std::list<Context*, std::allocator<Context*> >&)</fn>
<dir>/usr/include/c++/4.6/ext</dir>
<file>new_allocator.h</file>
<line>92</line>
</frame>
<frame>
<ip>0x705BAB</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>PG::RecoveryState::Clean::Clean(boost::statechart::state<PG::RecoveryState::Clean, PG::RecoveryState::Active, boost::mpl::list<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, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::my_context)</fn>
<dir>/srv/autobuild-ceph/gitbuilder.git/build/out~/ceph-0.67.11-5-g3ebc350/src/osd</dir>
<file>PG.cc</file>
<line>5894</line>
</frame>
<frame>
<ip>0x74A9EB</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>boost::statechart::state<PG::RecoveryState::Clean, PG::RecoveryState::Active, boost::mpl::list<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, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::shallow_construct(boost::intrusive_ptr<PG::RecoveryState::Active> const&, boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>&)</fn>
<dir>/usr/include/boost/statechart</dir>
<file>state.hpp</file>
<line>89</line>
</frame>
<frame>
<ip>0x74ABF3</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>boost::statechart::detail::safe_reaction_result boost::statechart::simple_state<PG::RecoveryState::Recovered, PG::RecoveryState::Active, boost::mpl::list<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, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::transit_impl<PG::RecoveryState::Clean, PG::RecoveryState::RecoveryMachine, boost::statechart::detail::no_transition_function>(boost::statechart::detail::no_transition_function const&)</fn>
<dir>/usr/include/boost/statechart</dir>
<file>state.hpp</file>
<line>79</line>
</frame>
<frame>
<ip>0x74AD81</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>boost::statechart::simple_state<PG::RecoveryState::Recovered, PG::RecoveryState::Active, boost::mpl::list<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, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)</fn>
<dir>/usr/include/boost/statechart</dir>
<file>simple_state.hpp</file>
<line>314</line>
</frame>
<frame>
<ip>0x731FCA</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_queued_events()</fn>
<dir>/usr/include/boost/statechart</dir>
<file>state_machine.hpp</file>
<line>87</line>
</frame>
<frame>
<ip>0x73212D</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>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&)</fn>
<dir>/usr/include/boost/statechart</dir>
<file>state_machine.hpp</file>
<line>280</line>
</frame>
<frame>
<ip>0x6F2792</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>PG::handle_peering_event(std::tr1::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)</fn>
<dir>/srv/autobuild-ceph/gitbuilder.git/build/out~/ceph-0.67.11-5-g3ebc350/src/osd</dir>
<file>PG.h</file>
<line>1632</line>
</frame>
<frame>
<ip>0x686933</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)</fn>
<dir>/srv/autobuild-ceph/gitbuilder.git/build/out~/ceph-0.67.11-5-g3ebc350/src/osd</dir>
<file>OSD.cc</file>
<line>7231</line>
</frame>
<frame>
<ip>0x6C4B81</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)</fn>
<dir>/srv/autobuild-ceph/gitbuilder.git/build/out~/ceph-0.67.11-5-g3ebc350/src/osd</dir>
<file>OSD.h</file>
<line>1019</line>
</frame>
<frame>
<ip>0x8B6645</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>ThreadPool::worker(ThreadPool::WorkThread*)</fn>
<dir>/srv/autobuild-ceph/gitbuilder.git/build/out~/ceph-0.67.11-5-g3ebc350/src/common</dir>
<file>WorkQueue.cc</file>
<line>128</line>
</frame>
<frame>
<ip>0x8B865F</ip>
<obj>/usr/bin/ceph-osd</obj>
<fn>ThreadPool::WorkThread::entry()</fn>
<dir>/srv/autobuild-ceph/gitbuilder.git/build/out~/ceph-0.67.11-5-g3ebc350/src/common</dir>
<file>WorkQueue.h</file>
<line>318</line>
</frame>
<frame>
<ip>0x503BE99</ip>
<obj>/lib/x86_64-linux-gnu/libpthread-2.15.so</obj>
<fn>start_thread</fn>
<dir>/build/buildd/eglibc-2.15/nptl</dir>
<file>pthread_create.c</file>
<line>308</line>
</frame>
<frame>
<ip>0x6AFD31C</ip>
<obj>/lib/x86_64-linux-gnu/libc-2.15.so</obj>
<fn>clone</fn>
<dir>/build/buildd/eglibc-2.15/misc/../sysdeps/unix/sysv/linux/x86_64</dir>
<file>clone.S</file>
<line>112</line>
</frame>
</stack>
</error>
Updated by Loïc Dachary over 9 years ago
The osd.2 actually crashed with:
/3) [2] r=0 lpr=44 pi=4-43/1 luod=0'0 mlcod 0'0 active+degraded] lock
-40> 2014-09-30 05:11:35.373804 fddc700 10 osd.2 pg_epoch: 45 pg[1.13( v 9'2 (0'0,9'2] local-les=45 n=2 ec=1 les/c 9/9 44/44/3) [2] r=0 lpr=44 pi=4-43/1 luod=0'0 mlcod 0'0 active+degraded] _activate_committed 45, that was an old interval
-39> 2014-09-30 05:11:35.374288 fddc700 30 osd.2 pg_epoch: 45 pg[2.12( empty local-les=45 n=0 ec=1 les/c 9/9 44/44/3) [2] r=0 lpr=44 pi=4-43/1 mlcod 0'0 active+degraded] lock
-38> 2014-09-30 05:11:35.374633 fddc700 10 osd.2 pg_epoch: 45 pg[2.12( empty local-les=45 n=0 ec=1 les/c 9/9 44/44/3) [2] r=0 lpr=44 pi=4-43/1 mlcod 0'0 active+degraded] _activate_committed 45, that was an old interval
-37> 2014-09-30 05:11:35.428371 cdd6700 20 filestore(/var/lib/ceph/osd/ceph-2) done waiting for transid 351 to complete
-36> 2014-09-30 05:11:35.428597 cdd6700 10 filestore(/var/lib/ceph/osd/ceph-2) sync_entry commit took 1.088467, interval was 5.120726
-35> 2014-09-30 05:11:35.428773 cdd6700 10 journal commit_finish thru 1818
-34> 2014-09-30 05:11:35.428845 cdd6700 5 journal committed_thru 1818 (last_committed_seq 1807)
-33> 2014-09-30 05:11:35.428952 cdd6700 10 journal queue_completions_thru seq 1818 queueing seq 1815 0x2330ba50 lat 2.912300
-32> 2014-09-30 05:11:35.429133 cdd6700 10 journal queue_completions_thru seq 1818 queueing seq 1816 0x2260cc60 lat 2.871990
-31> 2014-09-30 05:11:35.429291 cdd6700 10 journal queue_completions_thru seq 1818 queueing seq 1817 0x218eff50 lat 2.811439
-30> 2014-09-30 05:11:35.429438 cdd6700 10 journal queue_completions_thru seq 1818 queueing seq 1818 0 lat 1.119748
-29> 2014-09-30 05:11:35.429561 cdd6700 10 journal header: block_size 4096 alignment 4096 max_size 104857600
-28> 2014-09-30 05:11:35.429647 cdd6700 10 journal header: start 10076160
-27> 2014-09-30 05:11:35.429707 cdd6700 10 journal write_pos 10076160
-26> 2014-09-30 05:11:35.429771 cdd6700 10 journal committed_thru done
-25> 2014-09-30 05:11:35.433310 cdd6700 10 filestore(/var/lib/ceph/osd/ceph-2) removing snap 'snap_1799'
-24> 2014-09-30 05:11:35.433986 cdd6700 15 filestore(/var/lib/ceph/osd/ceph-2) sync_entry committed to op_seq 1818
-23> 2014-09-30 05:11:35.448422 1dd14700 10 filestore(/var/lib/ceph/osd/ceph-2) sync done
-22> 2014-09-30 05:11:35.450198 1dd14700 5 filestore(/var/lib/ceph/osd/ceph-2) umount /var/lib/ceph/osd/ceph-2
-21> 2014-09-30 05:11:35.453966 d5d7700 20 journal do_write latency 0.094390
-20> 2014-09-30 05:11:35.454044 d5d7700 20 journal do_write queueing finishers through seq 1818
-19> 2014-09-30 05:11:35.454126 d5d7700 5 journal put_throttle finished 4 ops and 2812 bytes, now 0 ops and 0 bytes
-18> 2014-09-30 05:11:35.454224 d5d7700 20 journal write_thread_entry going to sleep
-17> 2014-09-30 05:11:35.455025 cdd6700 20 filestore(/var/lib/ceph/osd/ceph-2) sync_entry waiting for max_interval 5.000000
-16> 2014-09-30 05:11:35.455921 cdd6700 20 filestore(/var/lib/ceph/osd/ceph-2) sync_entry force_sync set
-15> 2014-09-30 05:11:35.456020 cdd6700 10 journal commit_start max_applied_seq 1818, open_ops 0
-14> 2014-09-30 05:11:35.456071 cdd6700 10 journal commit_start blocked, all open_ops have completed
-13> 2014-09-30 05:11:35.456105 cdd6700 10 journal commit_start nothing to do
-12> 2014-09-30 05:11:35.456141 cdd6700 10 journal commit_start
-11> 2014-09-30 05:11:35.456766 10dde700 1 FileStore::op_tp worker finish
-10> 2014-09-30 05:11:35.456940 105dd700 1 FileStore::op_tp worker finish
-9> 2014-09-30 05:11:35.457232 1dd14700 10 journal journal_stop
-8> 2014-09-30 05:11:35.458020 1dd14700 1 journal close /var/lib/ceph/osd/ceph-2/journal
-7> 2014-09-30 05:11:35.458172 d5d7700 20 journal write_thread_entry woke up
-6> 2014-09-30 05:11:35.458225 d5d7700 10 journal write_thread_entry finish
-5> 2014-09-30 05:11:35.458353 f5db700 10 journal write_finish_thread_entry exit
-4> 2014-09-30 05:11:35.478774 1dd14700 10 osd.2 45 Store synced
-3> 2014-09-30 05:11:35.482597 1dd14700 20 osd.2 45 kicking pg 2.15
-2> 2014-09-30 05:11:35.484593 1dd14700 30 osd.2 pg_epoch: 45 pg[2.15( empty local-les=45 n=0 ec=1 les/c 45/45 44/44/44) [2] r=0 lpr=44 mlcod 0'0 active+degraded] lock
-1> 2014-09-30 05:11:35.485793 1dd14700 -1 osd.2 45 pgid 2.15 has ref count of 2
0> 2014-09-30 05:11:35.971218 1dd14700 -1 osd/OSD.cc: In function 'int OSD::shutdown()' thread 1dd14700 time 2014-09-30 05:11:35.494271
osd/OSD.cc: 1612: FAILED assert(0)
ceph version 0.67.11-5-g3ebc350 (3ebc35026c697ed2b895fdc85f49056a007c7571)
1: (OSD::shutdown()+0x150d) [0x66454d]
2: (OSD::handle_signal(int)+0x118) [0x664b68]
3: (SignalHandler::entry()+0x18b) [0x7fd9bb]
4: (()+0x7e9a) [0x503be9a]
5: (clone()+0x6d) [0x6afd31d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
Updated by Loïc Dachary over 9 years ago
- Subject changed from osd: leaked C_PG_FinishRecovery on shutdown (dumpling) to osd: leaked pg refs on shutdown (dumpling)
It is the same assert as http://tracker.ceph.com/issues/7891 but the PGBackend did not exist at the time, therefore the source of the problem is different.
Updated by Loïc Dachary over 9 years ago
It could not be in_progress_splits : the logs do not contain the word split
Updated by Loïc Dachary over 9 years ago
Log lines related to pg 2.15
937:2014-09-30 04:36:32.020093 142ff700 20 osd.2 3 mkpg 2.15 e1
938:2014-09-30 04:36:32.020257 142ff700 15 osd.2 3 project_pg_history 2.15 from 1 to 3, start ec=1 les/c 0/1 0/0/0
939:2014-09-30 04:36:32.020463 142ff700 15 osd.2 3 project_pg_history 2.15 acting|up changed in 3 from [0]/[0] -> [2,1]/[2,1]
940:2014-09-30 04:36:32.020603 142ff700 15 osd.2 3 project_pg_history 2.15 up changed in 3 from [0] -> [2,1]
941:2014-09-30 04:36:32.020693 142ff700 15 osd.2 3 project_pg_history 2.15 primary changed in 3
943:2014-09-30 04:36:32.020859 142ff700 15 osd.2 3 calc_priors_during 2.15 [1,3)
944:2014-09-30 04:36:32.021022 142ff700 20 osd.2 3 2.15 in epoch 1 was []
945:2014-09-30 04:36:32.021188 142ff700 20 osd.2 3 2.15 in epoch 2 was [0]
946:2014-09-30 04:36:32.021286 142ff700 10 osd.2 3 calc_priors_during 2.15 [1,3) = 0
947:2014-09-30 04:36:32.021445 142ff700 10 osd.2 3 mkpg 2.15 e1 h ec=1 les/c 0/1 3/3/3 : querying priors 0
948:2014-09-30 04:36:32.021666 142ff700 10 osd.2 3 can_create_pg 2.15 - waiting for priors 0
951:2014-09-30 04:36:32.034386 142ff700 1 -- 10.214.139.166:6803/5633 --> 10.214.139.166:6804/5620 -- pg_query(2.15 epoch 3) v2 -- ?+0 0x7dbc490 con 0x7d72af0
1232:2014-09-30 04:36:32.484154 142ff700 20 osd.2 3 mkpg 2.15 e1
1233:2014-09-30 04:36:32.484338 142ff700 15 osd.2 3 project_pg_history 2.15 from 1 to 3, start ec=1 les/c 0/1 0/0/0
1234:2014-09-30 04:36:32.505786 142ff700 15 osd.2 3 project_pg_history 2.15 acting|up changed in 3 from [0]/[0] -> [2,1]/[2,1]
1235:2014-09-30 04:36:32.505964 142ff700 15 osd.2 3 project_pg_history 2.15 up changed in 3 from [0] -> [2,1]
1236:2014-09-30 04:36:32.506057 142ff700 15 osd.2 3 project_pg_history 2.15 primary changed in 3
1238:2014-09-30 04:36:32.506219 142ff700 15 osd.2 3 calc_priors_during 2.15 [1,3)
1239:2014-09-30 04:36:32.506390 142ff700 20 osd.2 3 2.15 in epoch 1 was []
1240:2014-09-30 04:36:32.506709 142ff700 20 osd.2 3 2.15 in epoch 2 was [0]
1241:2014-09-30 04:36:32.506840 142ff700 10 osd.2 3 calc_priors_during 2.15 [1,3) = 0
1242:2014-09-30 04:36:32.506993 142ff700 10 osd.2 3 mkpg 2.15 e1 h ec=1 les/c 0/1 3/3/3 : querying priors 0
1243:2014-09-30 04:36:32.507199 142ff700 10 osd.2 3 can_create_pg 2.15 - waiting for priors 0
1246:2014-09-30 04:36:32.513512 142ff700 1 -- 10.214.139.166:6803/5633 --> 10.214.139.166:6804/5620 -- pg_query(2.15 epoch 3) v2 -- ?+0 0x7df0d60 con 0x7d72af0
1336:2014-09-30 04:36:35.006918 15301700 10 osd.2 4 no longer primary for 2.15, stopping creation
2230:2014-09-30 04:36:38.464642 15301700 1 -- 10.214.139.166:6803/5633 <== osd.3 10.214.138.203:6806/5628 20 ==== pg_query(2.15 epoch 4) v2 ==== 137+0+0 (2175415201 0 0) 0x1f79aa90 con 0x7df59f0
2233:2014-09-30 04:36:38.470180 15301700 20 osd.2 5 _dispatch 0x1f79aa90 pg_query(2.15 epoch 4) v2
2236:2014-09-30 04:36:38.477849 15301700 15 osd.2 5 project_pg_history 2.15 from 4 to 5, start ec=1 les/c 0/1 4/4/4
2238:2014-09-30 04:36:38.481751 15301700 10 osd.2 5 pg 2.15 dne
2241:2014-09-30 04:36:38.482531 15301700 1 -- 10.214.139.166:6803/5633 --> 10.214.138.203:6806/5628 -- pg_notify(2.15 epoch 5) v4 -- ?+0 0x20466d60 con 0x7df59f0
4436:2014-09-30 04:36:51.218948 15301700 1 -- 10.214.139.166:6803/5633 <== osd.3 10.214.138.203:6806/5628 28 ==== pg_query(2.15 epoch 8) v2 ==== 137+0+0 (2227496888 0 0) 0x218ae500 con 0x7df59f0
4439:2014-09-30 04:36:51.219310 15301700 20 osd.2 9 _dispatch 0x218ae500 pg_query(2.15 epoch 8) v2
4442:2014-09-30 04:36:51.227524 15301700 15 osd.2 9 project_pg_history 2.15 from 4 to 9, start ec=1 les/c 0/1 4/4/4
4444:2014-09-30 04:36:51.228051 15301700 10 osd.2 9 pg 2.15 dne
4447:2014-09-30 04:36:51.228401 15301700 1 -- 10.214.139.166:6803/5633 --> 10.214.138.203:6806/5628 -- pg_notify(2.15 epoch 9) v4 -- ?+0 0x21cdda40 con 0x7df59f0
6453:2014-09-30 04:36:57.344243 15301700 1 -- 10.214.139.166:6803/5633 <== osd.3 10.214.138.203:6806/5628 35 ==== pg_log(2.15 epoch 9 query_epoch 9) v3 ==== 729+0+0 (143695434 0 0) 0x2217ad40 con 0x7df59f0
6456:2014-09-30 04:36:57.344696 15301700 20 osd.2 9 _dispatch 0x2217ad40 pg_log(2.15 epoch 9 query_epoch 9) v3
6457:2014-09-30 04:36:57.345764 15301700 7 osd.2 9 handle_pg_log pg_log(2.15 epoch 9 query_epoch 9) v3 from osd.3
6459:2014-09-30 04:36:57.346516 15301700 15 osd.2 9 project_pg_history 2.15 from 9 to 9, start ec=1 les/c 0/1 4/4/4
6461:2014-09-30 04:36:57.346958 15301700 20 osd.2 9 _create_lock_pg pgid 2.15
6462:2014-09-30 04:36:57.347032 15301700 10 osd.2 9 _open_lock_pg 2.15
6464:2014-09-30 04:36:57.348363 15301700 5 osd.2 pg_epoch: 9 pg[2.15(unlocked)] enter Initial
6465:2014-09-30 04:36:57.348625 15301700 20 osd.2 pg_epoch: 9 pg[2.15(unlocked)] enter NotTrimming
6466:2014-09-30 04:36:57.348829 15301700 10 osd.2 pg_epoch: 9 pg[2.15( DNE empty local-les=0 n=0 ec=0 les/c 0/0 0/0/0) [] r=0 lpr=0 mlcod 0'0 inactive] init role 1 up [3,2] acting [3,2] history ec=1 les/c 0/1 4/4/4 3 past_intervals
6468:2014-09-30 04:36:57.350582 15301700 7 osd.2 9 _create_lock_pg pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=0 pi=1-3/3 inactive]
6469:2014-09-30 04:36:57.350837 15301700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=0 pi=1-3/3 inactive] handle_create
6470:2014-09-30 04:36:57.351170 15301700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=0 pi=1-3/3 inactive] exit Initial 0.002811 0 0.000000
6471:2014-09-30 04:36:57.351632 15301700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=0 pi=1-3/3 inactive] enter Reset
6472:2014-09-30 04:36:57.351938 15301700 20 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=0 pi=1-3/3 inactive] set_last_peering_reset 9
6473:2014-09-30 04:36:57.352276 15301700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] update_heartbeat_peers unchanged
6474:2014-09-30 04:36:57.352591 15301700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] take_waiters
6475:2014-09-30 04:36:57.352907 15301700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] exit Reset 0.001278 1 0.001117
6476:2014-09-30 04:36:57.353273 15301700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] enter Started
6477:2014-09-30 04:36:57.353632 15301700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] enter Start
6478:2014-09-30 04:36:57.353938 15301700 1 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] state<Start>: transitioning to Stray
6496:2014-09-30 04:36:57.354308 15301700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] exit Start 0.000680 0 0.000000
6497:2014-09-30 04:36:57.361131 15301700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] enter Started/Stray
6499:2014-09-30 04:36:57.361569 15301700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_transactions new osr(2.15 0x22380fb0)/0x22380fb0
6616:2014-09-30 04:36:57.425203 15301700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_op 0x223a0d00 seq 55 osr(2.15 0x22380fb0) 1081 bytes (queue has 6 ops and 3676 bytes)
6618:2014-09-30 04:36:57.425405 15301700 10 osd.2 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] is new
6730:2014-09-30 04:36:57.478672 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] handle_peering_event: epoch_sent: 9 epoch_requested: 9 MLogRec from 3
6731:2014-09-30 04:36:57.479169 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] state<Started/Stray>: got info+log from osd.3 2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) log(0'0,0'0]
6734:2014-09-30 04:36:57.479932 19b0a700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] exit Started/Stray 0.118803 1 0.009203
6735:2014-09-30 04:36:57.480365 19b0a700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] enter Started/ReplicaActive
6736:2014-09-30 04:36:57.480790 19b0a700 5 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] enter Started/ReplicaActive/RepNotRecovering
6737:2014-09-30 04:36:57.481213 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=0 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 inactive] state<Started/ReplicaActive>: In ReplicaActive, about to call activate
6738:2014-09-30 04:36:57.481554 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] activate - no missing, moving last_complete 0'0 -> 0'0
6739:2014-09-30 04:36:57.481983 19b0a700 15 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] requeue_ops
6740:2014-09-30 04:36:57.482330 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started/ReplicaActive>: Activate Finished
6746:2014-09-30 04:36:57.486088 bdd4700 20 osd.2 9 2.15 heartbeat_peers
6768:2014-09-30 04:36:57.488028 10dde700 5 filestore(/var/lib/ceph/osd/ceph-2) _do_op 0x223a0d00 seq 55 osr(2.15 0x22380fb0)/0x22380fb0 start
6770:2014-09-30 04:36:57.488246 10dde700 15 filestore(/var/lib/ceph/osd/ceph-2) create_collection /var/lib/ceph/osd/ceph-2/current/2.15_head
6771:2014-09-30 04:36:57.488487 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) create_collection /var/lib/ceph/osd/ceph-2/current/2.15_head = 0
6772:2014-09-30 04:36:57.488991 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1
6773:2014-09-30 04:36:57.489139 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1 = 1
6777:2014-09-30 04:36:57.495707 10dde700 15 filestore(/var/lib/ceph/osd/ceph-2) touch meta/516be6bb/pglog_2.15/0//-1
6815:2014-09-30 04:36:57.525488 19b0a700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_transactions existing osr(2.15 0x22380fb0)/0x22380fb0
6820:2014-09-30 04:36:57.526180 19b0a700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_op 0x22496f60 seq 57 osr(2.15 0x22380fb0) 873 bytes (queue has 3 ops and 2714 bytes)
6860:2014-09-30 04:36:57.562375 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) touch meta/516be6bb/pglog_2.15/0//-1 = 0
6861:2014-09-30 04:36:57.562585 10dde700 15 filestore(/var/lib/ceph/osd/ceph-2) _omap_rmkeys meta/516be6bb/pglog_2.15/0//-1
6862:2014-09-30 04:36:57.566093 10dde700 15 filestore(/var/lib/ceph/osd/ceph-2) _omap_setkeys meta/516be6bb/pglog_2.15/0//-1
6864:2014-09-30 04:36:57.567391 10dde700 20 filestore set_map_header: setting 16 hoid 516be6bb/pglog_2.15/0//-1 parent seq 0
6865:2014-09-30 04:36:57.571947 10dde700 10 filestore hoid: 516be6bb/pglog_2.15/0//-1 not skipping op, *spos 55.0.5
6889:2014-09-30 04:36:57.588249 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) _finish_op 0x223a0d00 seq 55 osr(2.15 0x22380fb0)/0x22380fb0
6897:2014-09-30 04:36:57.594119 105dd700 5 filestore(/var/lib/ceph/osd/ceph-2) _do_op 0x22496f60 seq 57 osr(2.15 0x22380fb0)/0x22380fb0 start
6899:2014-09-30 04:36:57.594362 105dd700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1
6900:2014-09-30 04:36:57.594580 105dd700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1 = 1
6906:2014-09-30 04:36:57.597357 105dd700 10 filestore(/var/lib/ceph/osd/ceph-2) _finish_op 0x22496f60 seq 57 osr(2.15 0x22380fb0)/0x22380fb0
7500:2014-09-30 04:36:58.195914 fddc700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] flushed
7501:2014-09-30 04:36:58.196783 fddc700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] _activate_committed 9 telling primary
7503:2014-09-30 04:36:58.197614 fddc700 1 -- 10.214.139.166:6803/5633 --> osd.3 10.214.138.203:6806/5628 -- pg_info(1 pgs e9:2.15) v3 -- ?+0 0x22747e60
7514:2014-09-30 04:36:58.210829 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 9 epoch_requested: 9 FlushedEvt
7515:2014-09-30 04:36:58.211726 19b0a700 15 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] requeue_ops
7659:2014-09-30 04:36:58.449354 15301700 1 -- 10.214.139.166:6803/5633 <== osd.3 10.214.138.203:6806/5628 39 ==== pg_info(1 pgs e9:2.15) v3 ==== 588+0+0 (472837005 0 0) 0x227bfe10 con 0x7df59f0
7662:2014-09-30 04:36:58.449950 15301700 20 osd.2 9 _dispatch 0x227bfe10 pg_info(1 pgs e9:2.15) v3
7663:2014-09-30 04:36:58.455820 15301700 7 osd.2 9 handle_pg_info pg_info(1 pgs e9:2.15) v3 from osd.3
7707:2014-09-30 04:36:58.512715 bdd4700 20 osd.2 9 2.15 heartbeat_peers
7824:2014-09-30 04:36:58.660801 15301700 1 -- 10.214.139.166:6803/5633 <== osd.3 10.214.138.203:6806/5628 43 ==== pg_info(1 pgs e9:2.15) v3 ==== 588+0+0 (996512897 0 0) 0x2285b860 con 0x7df59f0
7827:2014-09-30 04:36:58.661433 15301700 20 osd.2 9 _dispatch 0x2285b860 pg_info(1 pgs e9:2.15) v3
7828:2014-09-30 04:36:58.663091 15301700 7 osd.2 9 handle_pg_info pg_info(1 pgs e9:2.15) v3 from osd.3
7855:2014-09-30 04:36:58.688479 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 0/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 9 epoch_requested: 9 MInfoRec from 3 info: 2.15( empty local-les=9 n=0 ec=1 les/c 9/1 4/4/4)
7857:2014-09-30 04:36:58.690916 19b0a700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_transactions existing osr(2.15 0x22380fb0)/0x22380fb0
7862:2014-09-30 04:36:58.696003 19b0a700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_op 0x2289af60 seq 74 osr(2.15 0x22380fb0) 869 bytes (queue has 2 ops and 1629 bytes)
7929:2014-09-30 04:36:58.776395 105dd700 5 filestore(/var/lib/ceph/osd/ceph-2) _do_op 0x2289af60 seq 74 osr(2.15 0x22380fb0)/0x22380fb0 start
7931:2014-09-30 04:36:58.776741 105dd700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1
7932:2014-09-30 04:36:58.777039 105dd700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1 = 1
7940:2014-09-30 04:36:58.787426 19b0a700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/1 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 9 epoch_requested: 9 MInfoRec from 3 info: 2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4)
7942:2014-09-30 04:36:58.789670 19b0a700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_transactions existing osr(2.15 0x22380fb0)/0x22380fb0
7963:2014-09-30 04:36:58.803130 19b0a700 5 filestore(/var/lib/ceph/osd/ceph-2) queue_op 0x228fbc20 seq 75 osr(2.15 0x22380fb0) 869 bytes (queue has 3 ops and 2502 bytes)
7972:2014-09-30 04:36:58.846122 105dd700 10 filestore(/var/lib/ceph/osd/ceph-2) _finish_op 0x2289af60 seq 74 osr(2.15 0x22380fb0)/0x22380fb0
7974:2014-09-30 04:36:58.846670 10dde700 5 filestore(/var/lib/ceph/osd/ceph-2) _do_op 0x228fbc20 seq 75 osr(2.15 0x22380fb0)/0x22380fb0 start
7976:2014-09-30 04:36:58.847016 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1
7977:2014-09-30 04:36:58.847264 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1 = 1
7983:2014-09-30 04:36:58.858226 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) _finish_op 0x228fbc20 seq 75 osr(2.15 0x22380fb0)/0x22380fb0
8107:2014-09-30 04:36:59.613760 bdd4700 20 osd.2 9 2.15 heartbeat_peers
11902:2014-09-30 04:39:18.431394 142ff700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
11908:2014-09-30 04:39:18.438208 1a30b700 10 osd.2 pg_epoch: 9 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
11909:2014-09-30 04:39:18.439012 1a30b700 10 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
11910:2014-09-30 04:39:18.439350 1a30b700 10 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
11911:2014-09-30 04:39:18.443767 1a30b700 10 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
11912:2014-09-30 04:39:18.444979 1a30b700 10 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
11913:2014-09-30 04:39:18.445595 1a30b700 20 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 10
11914:2014-09-30 04:39:18.445939 1a30b700 10 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 10 epoch_requested: 10 NullEvt
12172:2014-09-30 04:39:18.675626 142ff700 20 osd.2 10 2.15 heartbeat_peers
12550:2014-09-30 04:39:21.270869 142ff700 10 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
12555:2014-09-30 04:39:21.277551 1a30b700 10 osd.2 pg_epoch: 10 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
12556:2014-09-30 04:39:21.277980 1a30b700 10 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
12557:2014-09-30 04:39:21.278318 1a30b700 10 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
12558:2014-09-30 04:39:21.278648 1a30b700 10 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
12559:2014-09-30 04:39:21.278944 1a30b700 10 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
12560:2014-09-30 04:39:21.279232 1a30b700 20 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 11
12561:2014-09-30 04:39:21.286915 1a30b700 10 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 11 epoch_requested: 11 NullEvt
13010:2014-09-30 04:39:22.996041 15301700 10 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
13013:2014-09-30 04:39:22.998271 1a30b700 10 osd.2 pg_epoch: 11 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
13014:2014-09-30 04:39:22.998751 1a30b700 10 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
13015:2014-09-30 04:39:22.999197 1a30b700 10 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
13016:2014-09-30 04:39:23.003689 1a30b700 10 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
13017:2014-09-30 04:39:23.004054 1a30b700 10 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
13018:2014-09-30 04:39:23.004375 1a30b700 20 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 12
13019:2014-09-30 04:39:23.004712 1a30b700 10 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 12 epoch_requested: 12 NullEvt
13661:2014-09-30 04:39:31.679778 142ff700 10 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
13662:2014-09-30 04:39:31.703696 1a30b700 10 osd.2 pg_epoch: 12 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
13663:2014-09-30 04:39:31.704439 1a30b700 10 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
13664:2014-09-30 04:39:31.704931 1a30b700 10 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
13665:2014-09-30 04:39:31.705404 1a30b700 10 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
13666:2014-09-30 04:39:31.705845 1a30b700 10 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
13667:2014-09-30 04:39:31.706297 1a30b700 20 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 13
13668:2014-09-30 04:39:31.706756 1a30b700 10 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 13 epoch_requested: 13 NullEvt
14054:2014-09-30 04:39:32.509378 142ff700 20 osd.2 13 2.15 heartbeat_peers
14303:2014-09-30 04:39:33.012096 15301700 10 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
14314:2014-09-30 04:39:33.021676 1a30b700 10 osd.2 pg_epoch: 13 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
14315:2014-09-30 04:39:33.022219 1a30b700 10 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
14316:2014-09-30 04:39:33.022585 1a30b700 10 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
14317:2014-09-30 04:39:33.022954 1a30b700 10 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
14318:2014-09-30 04:39:33.023281 1a30b700 10 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
14319:2014-09-30 04:39:33.027854 1a30b700 20 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 14
14320:2014-09-30 04:39:33.028202 1a30b700 10 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 14 epoch_requested: 14 NullEvt
14700:2014-09-30 04:39:35.924552 142ff700 10 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
14703:2014-09-30 04:39:35.933700 19b0a700 10 osd.2 pg_epoch: 14 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
14704:2014-09-30 04:39:35.934203 19b0a700 10 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
14705:2014-09-30 04:39:35.934520 19b0a700 10 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
14706:2014-09-30 04:39:35.934847 19b0a700 10 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
14707:2014-09-30 04:39:35.935160 19b0a700 10 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
14708:2014-09-30 04:39:35.946478 19b0a700 20 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 15
14709:2014-09-30 04:39:35.947202 19b0a700 10 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 15 epoch_requested: 15 NullEvt
16150:2014-09-30 04:39:51.778440 142ff700 10 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
16151:2014-09-30 04:39:51.785573 1a30b700 10 osd.2 pg_epoch: 15 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
16152:2014-09-30 04:39:51.786353 1a30b700 10 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
16153:2014-09-30 04:39:51.786857 1a30b700 10 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
16154:2014-09-30 04:39:51.787255 1a30b700 10 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
16155:2014-09-30 04:39:51.795845 1a30b700 10 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
16156:2014-09-30 04:39:51.796368 1a30b700 20 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 16
16157:2014-09-30 04:39:51.796862 1a30b700 10 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 16 epoch_requested: 16 NullEvt
16579:2014-09-30 04:39:53.093758 142ff700 20 osd.2 16 2.15 heartbeat_peers
16730:2014-09-30 04:39:53.514955 15301700 10 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
16744:2014-09-30 04:39:53.539069 19b0a700 10 osd.2 pg_epoch: 16 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
16745:2014-09-30 04:39:53.545857 19b0a700 10 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
16746:2014-09-30 04:39:53.546347 19b0a700 10 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
16747:2014-09-30 04:39:53.546717 19b0a700 10 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
16748:2014-09-30 04:39:53.547042 19b0a700 10 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
16749:2014-09-30 04:39:53.547361 19b0a700 20 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 17
16750:2014-09-30 04:39:53.557598 19b0a700 10 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 17 epoch_requested: 17 NullEvt
17062:2014-09-30 04:39:54.090374 15301700 20 osd.2 17 2.15 heartbeat_peers
17341:2014-09-30 04:39:54.779801 142ff700 10 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
17352:2014-09-30 04:39:54.842081 19b0a700 10 osd.2 pg_epoch: 17 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
17353:2014-09-30 04:39:54.842884 19b0a700 10 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
17354:2014-09-30 04:39:54.854971 19b0a700 10 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
17355:2014-09-30 04:39:54.855728 19b0a700 10 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
17356:2014-09-30 04:39:54.856263 19b0a700 10 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
17357:2014-09-30 04:39:54.856805 19b0a700 20 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 18
17358:2014-09-30 04:39:54.857388 19b0a700 10 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 18 epoch_requested: 18 NullEvt
17571:2014-09-30 04:39:55.248920 142ff700 20 osd.2 18 2.15 heartbeat_peers
17898:2014-09-30 04:39:55.928776 142ff700 10 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
17959:2014-09-30 04:39:56.014568 19b0a700 10 osd.2 pg_epoch: 18 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
17960:2014-09-30 04:39:56.015008 19b0a700 10 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
17961:2014-09-30 04:39:56.015315 19b0a700 10 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
17962:2014-09-30 04:39:56.015696 19b0a700 10 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
17963:2014-09-30 04:39:56.015998 19b0a700 10 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
17965:2014-09-30 04:39:56.016292 19b0a700 20 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 19
17966:2014-09-30 04:39:56.020050 19b0a700 10 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 19 epoch_requested: 19 NullEvt
18658:2014-09-30 04:39:57.312548 142ff700 10 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
18688:2014-09-30 04:39:57.396914 19b0a700 10 osd.2 pg_epoch: 19 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
18689:2014-09-30 04:39:57.397408 19b0a700 10 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
18690:2014-09-30 04:39:57.397759 19b0a700 10 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
18691:2014-09-30 04:39:57.409494 19b0a700 10 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
18692:2014-09-30 04:39:57.409920 19b0a700 10 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
18693:2014-09-30 04:39:57.410293 19b0a700 20 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 20
18694:2014-09-30 04:39:57.410780 19b0a700 10 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 20 epoch_requested: 20 NullEvt
19462:2014-09-30 04:40:00.279905 15301700 10 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
19467:2014-09-30 04:40:00.292769 19b0a700 10 osd.2 pg_epoch: 20 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
19468:2014-09-30 04:40:00.293240 19b0a700 10 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
19469:2014-09-30 04:40:00.293568 19b0a700 10 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
19470:2014-09-30 04:40:00.293907 19b0a700 10 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
19471:2014-09-30 04:40:00.294242 19b0a700 10 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
19472:2014-09-30 04:40:00.294552 19b0a700 20 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 21
19473:2014-09-30 04:40:00.294889 19b0a700 10 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 21 epoch_requested: 21 NullEvt
19919:2014-09-30 04:40:01.155747 142ff700 10 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
19920:2014-09-30 04:40:01.156755 19b0a700 10 osd.2 pg_epoch: 21 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
19921:2014-09-30 04:40:01.157190 19b0a700 10 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
19922:2014-09-30 04:40:01.157519 19b0a700 10 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
19923:2014-09-30 04:40:01.157867 19b0a700 10 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
19924:2014-09-30 04:40:01.158248 19b0a700 10 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
19925:2014-09-30 04:40:01.158554 19b0a700 20 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 22
19926:2014-09-30 04:40:01.158876 19b0a700 10 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 22 epoch_requested: 22 NullEvt
20263:2014-09-30 04:40:01.614265 142ff700 20 osd.2 22 2.15 heartbeat_peers
20713:2014-09-30 04:40:03.315695 142ff700 10 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
20723:2014-09-30 04:40:03.332904 1a30b700 10 osd.2 pg_epoch: 22 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
20724:2014-09-30 04:40:03.333333 1a30b700 10 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
20725:2014-09-30 04:40:03.333667 1a30b700 10 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
20726:2014-09-30 04:40:03.334061 1a30b700 10 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
20727:2014-09-30 04:40:03.334387 1a30b700 10 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
20728:2014-09-30 04:40:03.334699 1a30b700 20 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 23
20729:2014-09-30 04:40:03.335022 1a30b700 10 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 23 epoch_requested: 23 NullEvt
21693:2014-09-30 04:40:05.541429 15301700 10 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
21696:2014-09-30 04:40:05.556448 19b0a700 10 osd.2 pg_epoch: 23 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
21697:2014-09-30 04:40:05.559295 19b0a700 10 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
21698:2014-09-30 04:40:05.567079 19b0a700 10 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
21699:2014-09-30 04:40:05.567511 19b0a700 10 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
21700:2014-09-30 04:40:05.567848 19b0a700 10 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
21701:2014-09-30 04:40:05.568177 19b0a700 20 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 24
21702:2014-09-30 04:40:05.568542 19b0a700 10 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 24 epoch_requested: 24 NullEvt
22125:2014-09-30 04:40:06.861322 15301700 10 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
22128:2014-09-30 04:40:06.868092 1a30b700 10 osd.2 pg_epoch: 24 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
22129:2014-09-30 04:40:06.868610 1a30b700 10 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
22130:2014-09-30 04:40:06.875570 1a30b700 10 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
22131:2014-09-30 04:40:06.875990 1a30b700 10 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
22132:2014-09-30 04:40:06.876326 1a30b700 10 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
22133:2014-09-30 04:40:06.876650 1a30b700 20 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 25
22134:2014-09-30 04:40:06.878270 1a30b700 10 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 25 epoch_requested: 25 NullEvt
22525:2014-09-30 04:40:07.839081 142ff700 10 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
22526:2014-09-30 04:40:07.844447 1a30b700 10 osd.2 pg_epoch: 25 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
22527:2014-09-30 04:40:07.844906 1a30b700 10 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
22528:2014-09-30 04:40:07.845224 1a30b700 10 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
22529:2014-09-30 04:40:07.845550 1a30b700 10 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
22530:2014-09-30 04:40:07.845850 1a30b700 10 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
22531:2014-09-30 04:40:07.846205 1a30b700 20 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 26
22532:2014-09-30 04:40:07.859736 1a30b700 10 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 26 epoch_requested: 26 NullEvt
23309:2014-09-30 04:40:10.655385 15301700 10 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
23312:2014-09-30 04:40:10.664106 1a30b700 10 osd.2 pg_epoch: 26 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
23313:2014-09-30 04:40:10.664647 1a30b700 10 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
23314:2014-09-30 04:40:10.665032 1a30b700 10 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
23315:2014-09-30 04:40:10.665400 1a30b700 10 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
23316:2014-09-30 04:40:10.665730 1a30b700 10 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
23317:2014-09-30 04:40:10.666119 1a30b700 20 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 27
23318:2014-09-30 04:40:10.666459 1a30b700 10 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 27 epoch_requested: 27 NullEvt
27336:2014-09-30 04:41:00.466897 142ff700 10 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
27339:2014-09-30 04:41:00.473053 1a30b700 10 osd.2 pg_epoch: 27 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
27340:2014-09-30 04:41:00.473485 1a30b700 10 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
27341:2014-09-30 04:41:00.473818 1a30b700 10 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
27342:2014-09-30 04:41:00.474153 1a30b700 10 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
27343:2014-09-30 04:41:00.474451 1a30b700 10 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
27344:2014-09-30 04:41:00.479258 1a30b700 20 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 28
27345:2014-09-30 04:41:00.479685 1a30b700 10 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 28 epoch_requested: 28 NullEvt
27806:2014-09-30 04:41:03.263541 15301700 10 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
27808:2014-09-30 04:41:03.264797 1a30b700 10 osd.2 pg_epoch: 28 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
27809:2014-09-30 04:41:03.265775 1a30b700 10 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
27810:2014-09-30 04:41:03.266150 1a30b700 10 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
27811:2014-09-30 04:41:03.266515 1a30b700 10 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
27812:2014-09-30 04:41:03.266938 1a30b700 10 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
27813:2014-09-30 04:41:03.267273 1a30b700 20 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 29
27814:2014-09-30 04:41:03.272427 1a30b700 10 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 29 epoch_requested: 29 NullEvt
28740:2014-09-30 04:41:06.669560 142ff700 10 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
28743:2014-09-30 04:41:06.681254 1a30b700 10 osd.2 pg_epoch: 29 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
28744:2014-09-30 04:41:06.681737 1a30b700 10 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
28745:2014-09-30 04:41:06.682126 1a30b700 10 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
28746:2014-09-30 04:41:06.682483 1a30b700 10 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
28747:2014-09-30 04:41:06.682801 1a30b700 10 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
28748:2014-09-30 04:41:06.683115 1a30b700 20 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 30
28749:2014-09-30 04:41:06.689922 1a30b700 10 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 30 epoch_requested: 30 NullEvt
29499:2014-09-30 04:41:10.057068 15301700 10 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
29502:2014-09-30 04:41:10.064773 1a30b700 10 osd.2 pg_epoch: 30 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
29503:2014-09-30 04:41:10.068211 1a30b700 10 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
29504:2014-09-30 04:41:10.068571 1a30b700 10 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
29505:2014-09-30 04:41:10.068945 1a30b700 10 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
29506:2014-09-30 04:41:10.069276 1a30b700 10 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
29507:2014-09-30 04:41:10.069604 1a30b700 20 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 31
29508:2014-09-30 04:41:10.069969 1a30b700 10 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 31 epoch_requested: 31 NullEvt
30275:2014-09-30 04:41:13.991659 15301700 10 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
30278:2014-09-30 04:41:13.996826 19b0a700 10 osd.2 pg_epoch: 31 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
30279:2014-09-30 04:41:13.997301 19b0a700 10 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
30280:2014-09-30 04:41:13.997656 19b0a700 10 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
30281:2014-09-30 04:41:13.998042 19b0a700 10 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
30282:2014-09-30 04:41:13.998375 19b0a700 10 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
30283:2014-09-30 04:41:13.998700 19b0a700 20 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 32
30284:2014-09-30 04:41:13.999042 19b0a700 10 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 32 epoch_requested: 32 NullEvt
32455:2014-09-30 04:41:23.189983 142ff700 10 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
32458:2014-09-30 04:41:23.197516 1a30b700 10 osd.2 pg_epoch: 32 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
32459:2014-09-30 04:41:23.198080 1a30b700 10 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
32460:2014-09-30 04:41:23.198437 1a30b700 10 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
32461:2014-09-30 04:41:23.198814 1a30b700 10 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
32462:2014-09-30 04:41:23.199155 1a30b700 10 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
32463:2014-09-30 04:41:23.207600 1a30b700 20 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 33
32464:2014-09-30 04:41:23.208030 1a30b700 10 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 33 epoch_requested: 33 NullEvt
32983:2014-09-30 04:41:26.441506 142ff700 10 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
32986:2014-09-30 04:41:26.448670 19b0a700 10 osd.2 pg_epoch: 33 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
32987:2014-09-30 04:41:26.449199 19b0a700 10 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
32988:2014-09-30 04:41:26.449543 19b0a700 10 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
32989:2014-09-30 04:41:26.449914 19b0a700 10 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
32990:2014-09-30 04:41:26.450243 19b0a700 10 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
32991:2014-09-30 04:41:26.450552 19b0a700 20 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 34
32992:2014-09-30 04:41:26.450874 19b0a700 10 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 34 epoch_requested: 34 NullEvt
33784:2014-09-30 04:41:28.538874 15301700 10 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
33785:2014-09-30 04:41:28.540065 19b0a700 10 osd.2 pg_epoch: 34 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
33786:2014-09-30 04:41:28.540522 19b0a700 10 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
33787:2014-09-30 04:41:28.540874 19b0a700 10 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
33788:2014-09-30 04:41:28.541250 19b0a700 10 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
33789:2014-09-30 04:41:28.541574 19b0a700 10 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
33790:2014-09-30 04:41:28.541907 19b0a700 20 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 35
33791:2014-09-30 04:41:28.542259 19b0a700 10 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 35 epoch_requested: 35 NullEvt
34434:2014-09-30 04:41:32.662437 142ff700 10 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
34437:2014-09-30 04:41:32.684046 19b0a700 10 osd.2 pg_epoch: 35 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
34438:2014-09-30 04:41:32.684611 19b0a700 10 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
34439:2014-09-30 04:41:32.684996 19b0a700 10 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
34440:2014-09-30 04:41:32.685369 19b0a700 10 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
34441:2014-09-30 04:41:32.685756 19b0a700 10 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
34442:2014-09-30 04:41:32.686085 19b0a700 20 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 36
34443:2014-09-30 04:41:32.690815 19b0a700 10 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 36 epoch_requested: 36 NullEvt
34949:2014-09-30 04:41:34.751855 142ff700 20 osd.2 36 2.15 heartbeat_peers
35114:2014-09-30 04:41:35.935265 142ff700 10 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
35118:2014-09-30 04:41:35.961353 1a30b700 10 osd.2 pg_epoch: 36 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
35119:2014-09-30 04:41:35.961951 1a30b700 10 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
35120:2014-09-30 04:41:35.962295 1a30b700 10 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
35121:2014-09-30 04:41:35.962665 1a30b700 10 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
35122:2014-09-30 04:41:35.962995 1a30b700 10 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
35123:2014-09-30 04:41:35.963302 1a30b700 20 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 37
35124:2014-09-30 04:41:35.975811 1a30b700 10 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 37 epoch_requested: 37 NullEvt
109679:2014-09-30 04:48:38.068192 cdd6700 10 filestore(/var/lib/ceph/osd/ceph-2) sync_entry commit took 2.154611, interval was 7.155313
195556:2014-09-30 05:00:18.022926 fddc700 15 osd.2 pg_epoch: 37 pg[6.0( v 37'75 (0'0,37'75] local-les=19 n=3 ec=17 les/c 19/20 17/17/17) [2,4] r=0 lpr=17 luod=37'74 lcod 37'74 mlcod 37'73 active+clean] log_op_stats osd_op(client.4142.0:8685 gc.0 [call rgw.gc_set_entry] 6.990e66d8 e37) v4 inb 429 outb 4 rlat 2.138669 lat 2.155852
239368:2014-09-30 05:06:47.209211 bdd4700 20 osd.2 37 scrub_should_schedule loadavg 2.15 < max 5 = yes
239527:2014-09-30 05:06:50.213763 bdd4700 20 osd.2 37 scrub_should_schedule loadavg 2.15 < max 5 = yes
265908:2014-09-30 05:10:55.042513 15301700 10 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
265926:2014-09-30 05:10:58.755809 19b0a700 10 osd.2 pg_epoch: 37 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
265927:2014-09-30 05:10:58.756553 19b0a700 10 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
265928:2014-09-30 05:10:58.757099 19b0a700 10 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
265929:2014-09-30 05:10:58.757659 19b0a700 10 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
265930:2014-09-30 05:10:58.758192 19b0a700 10 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
265931:2014-09-30 05:10:58.758701 19b0a700 20 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 38
265932:2014-09-30 05:10:59.575630 19b0a700 10 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 38 epoch_requested: 38 NullEvt
266398:2014-09-30 05:11:01.183707 15301700 20 osd.2 38 2.15 heartbeat_peers
267089:2014-09-30 05:11:02.387156 bdd4700 20 osd.2 38 2.15 heartbeat_peers
267329:2014-09-30 05:11:03.448294 bdd4700 20 osd.2 38 2.15 heartbeat_peers
267421:2014-09-30 05:11:05.144266 15301700 10 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
267425:2014-09-30 05:11:05.146514 1a30b700 10 osd.2 pg_epoch: 38 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
267426:2014-09-30 05:11:05.151507 1a30b700 10 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
267427:2014-09-30 05:11:05.151874 1a30b700 10 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
267428:2014-09-30 05:11:05.152239 1a30b700 10 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
267429:2014-09-30 05:11:05.152573 1a30b700 10 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
267430:2014-09-30 05:11:05.152896 1a30b700 20 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 39
267431:2014-09-30 05:11:05.153246 1a30b700 10 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 39 epoch_requested: 39 NullEvt
268044:2014-09-30 05:11:09.720886 15301700 10 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
268048:2014-09-30 05:11:09.728509 19b0a700 10 osd.2 pg_epoch: 39 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_advance_map [3,2]/[3,2]
268049:2014-09-30 05:11:09.733553 19b0a700 10 osd.2 pg_epoch: 40 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] state<Started>: Started advmap
268050:2014-09-30 05:11:09.733933 19b0a700 10 osd.2 pg_epoch: 40 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] check_recovery_sources no source osds () went down
268051:2014-09-30 05:11:09.734296 19b0a700 10 osd.2 pg_epoch: 40 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map
268052:2014-09-30 05:11:09.734621 19b0a700 10 osd.2 pg_epoch: 40 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] take_waiters
268053:2014-09-30 05:11:09.734937 19b0a700 20 osd.2 pg_epoch: 40 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_activate_map: Not dirtying info: last_persisted is 9 while current is 40
268054:2014-09-30 05:11:09.735265 19b0a700 10 osd.2 pg_epoch: 40 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] handle_peering_event: epoch_sent: 40 epoch_requested: 40 NullEvt
268385:2014-09-30 05:11:10.054589 142ff700 10 osd.2 pg_epoch: 40 pg[2.15( empty local-les=9 n=0 ec=1 les/c 9/9 4/4/4) [3,2] r=1 lpr=9 pi=1-3/3 active] null
268404:2014-09-30 05:11:10.069876 1a30b700 10 osd.2 pg_epoch: 40 pg[Updated by Loïc Dachary over 9 years ago
The last thing that happened to pg 2.15 was
2014-09-30 05:11:32.572926 10dde700 5 filestore(/var/lib/ceph/osd/ceph-2) _do_op 0x7b12f90 seq 1815 osr(2.15 0x22380fb0)/0x22380fb0 start 2014-09-30 05:11:32.573056 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) _do_transaction on 0x2330b8f0 2014-09-30 05:11:32.573232 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1 2014-09-30 05:11:32.573473 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) collection_setattr /var/lib/ceph/osd/ceph-2/current/2.15_head 'info' len 1 = 1 2014-09-30 05:11:32.573789 10dde700 15 filestore(/var/lib/ceph/osd/ceph-2) _omap_setkeys meta/16ef7597/infos/head//-1 2014-09-30 05:11:32.575563 10dde700 10 filestore hoid: 16ef7597/infos/head//-1 not skipping op, *spos 1815.0.1 2014-09-30 05:11:32.575681 10dde700 10 filestore > header.spos 0.0.0 2014-09-30 05:11:32.576832 10dde700 10 journal op_apply_finish 1815 open_ops 1 -> 0, max_applied_seq 1814 -> 1815 2014-09-30 05:11:32.576944 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) _do_op 0x7b12f90 seq 1815 r = 0, finisher 0x2330b9f0 0 2014-09-30 05:11:32.577087 10dde700 10 filestore(/var/lib/ceph/osd/ceph-2) _finish_op 0x7b12f90 seq 1815 osr(2.15 0x22380fb0)/0x22380fb0
before it was kicked
2014-09-30 05:11:34.027631 1dd14700 20 osd.2 45 kicking pg 2.15
All seems right and it is such a common operation before shutdown that if something was wrong it would happen more often.
Updated by Loïc Dachary over 9 years ago
2014-09-30 05:11:28.008991 142ff700 10 osd.2 44 handle_pg_stats_ack ... 2014-09-30 05:11:30.658917 bdd4700 10 osd.2 44 send_pg_stats - 32 pgs updated ... 2014-09-30 05:11:32.511052 1a30b700 15 osd.2 pg_epoch: 45 pg[2.15( empty local-les=45 n=0 ec=1 les/c 45/45 44/44/44) [2] r=0 lpr=44 mlcod 0'0 active+degraded] publish_stats_to_osd 45:9
PG::publish_stats_to_osd adds to pg_stat_queue but it is asserted to be empty just before the assert.
The send_pg_stats that would empty the list is not called after (it was called before). Same for handle_pg_stats_ack. OSD::flush_pg_stats and PG::clear_publish_stats are not called at all.
OSD::shutdown loops over PG and call PG::on_shutdown which removes itself from pg_stat_queue, removing the reference count. The pg_stat_queue is then checked to be empty.
Updated by Loïc Dachary over 9 years ago
OSD::shutdown clear() the finished list, calling the OpRequest destructor which put() the Message but does not delete it (because it does not own it).
<loicd> sjusthm: can a https://github.com/ceph/ceph/blob/dumpling/src/osd/OpRequest.h#L100 Message in dumpling reference (indirectly) a PG ? It does not look like it is should but I'm not 100% sure. <sjusthm> loicd: I don't think so <loicd> ok :-) And an OpRequest ? <sjusthm> don't see anything capable of transitively referencing a pg
Updated by Loïc Dachary over 9 years ago
- Category set to OSD
- Status changed from New to Need More Info
I'm out of ideas but happy to keep exploring if someone has a lead. If this happens again cross referencing the logs may help narrow down the guilty pointer holder ;-)
Updated by Greg Farnum about 9 years ago
- Status changed from Need More Info to 12
EDIT: Never mind, these are on master rather than dumpling. I missed that in the ticket description.
This has been happening a lot on FS tests recently. Here are some examples:
http://qa-proxy.ceph.com/teuthology/teuthology-2015-02-09_23:04:02-fs-master-testing-basic-multi/749232/
http://qa-proxy.ceph.com/teuthology/teuthology-2015-02-09_23:04:02-fs-master-testing-basic-multi/749230/
http://qa-proxy.ceph.com/teuthology/teuthology-2015-02-09_23:04:02-fs-master-testing-basic-multi/749228/
(The first and last of these also have examples of #10805, which might be helpful as it's valgrind memory leaks.)
Updated by Greg Farnum about 9 years ago
- Status changed from 12 to Need More Info
Updated by Sage Weil about 9 years ago
aha, Kefu just found this bug (on master). #10421
Updated by Sage Weil about 9 years ago
- Status changed from Need More Info to Duplicate
Updated by Greg Farnum about 9 years ago
- Status changed from Duplicate to 12
That may need to be backported, but it's not the final word. :(
See #10892
Actions