ceph-mon.a.log - Ceph - Ceph

Bug #10220 » ceph-mon.a.log

Joao Eduardo Luis, 12/12/2014 11:19 AM

       --- 8< ---
 -12-02 09:12:24.495259 7f2204c3a700  1 mon.a@0(leader).paxos(paxos writing c 9288..9991) accept timeout, calling fresh election
 -12-02 09:12:25.222090 7f2204c3a700 10 mon.a@0(leader) e1 bootstrap
 -12-02 09:12:25.492610 7f2204c3a700 10 mon.a@0(leader) e1 wait_for_paxos_write flushing pending write
       // waiting to flush all the work in the store
       if (paxos is writing or is writing_previous):
         mon_lock.Unlock()
         store->flush()
           io_work.wait_for_empty()
         mon_lock.Lock()
       // io_work handles next callback on the queue, C_DoTransaction
       C_DoTransaction::finish():
         store->apply_transaction()
         oncommit->complete(ret)
         // oncommit happens to be Paxos::C_Committed
       Paxos::C_Committed::finish():
         paxos->commit_finish()
       // enters commit_finish()
 -12-02 09:12:25.492839 7f220623e700 20 mon.a@0(leader).paxos(paxos writing c 9288..9991) commit_finish 9992
       // commit_finish: sends commits to other mons
 -12-02 09:12:25.493007 7f220623e700 10 mon.a@0(leader).paxos(paxos writing c 9288..9992)  sending commit to mon.1
 -12-02 09:12:25.493025 7f220623e700  1 -- 10.214.138.162:6789/0 --> mon.1 10.214.138.162:6790/0 -- paxos(commit lc 9992 fc 0 pn 800 opn 0) v3 -- ?+0 0x5742580
 -12-02 09:12:25.493046 7f220623e700 10 mon.a@0(leader).paxos(paxos writing c 9288..9992)  sending commit to mon.2
 -12-02 09:12:25.493053 7f220623e700  1 -- 10.214.138.162:6789/0 --> mon.2 10.214.138.162:6791/0 -- paxos(commit lc 9992 fc 0 pn 800 opn 0) v3 -- ?+0 0x563f300
       // commit_finish: do_refresh()
 -12-02 09:12:25.493073 7f220623e700 10 mon.a@0(leader) e1 refresh_from_paxos
 -12-02 09:12:25.493130 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) refresh
 -12-02 09:12:25.493133 7f220623e700 10 mon.a@0(leader).pg v4688 update_from_paxos read_incremental
 -12-02 09:12:25.493208 7f220623e700 20 mon.a@0(leader).pg v4688  refreshing pg 58.4 got 0 len 460
 -12-02 09:12:25.493237 7f220623e700 20 mon.a@0(leader).pg v4688  refreshing pg 59.3 got 0 len 460
 -12-02 09:12:25.493260 7f220623e700 20 mon.a@0(leader).pg v4688  refreshing pg 59.9 got 0 len 460
 -12-02 09:12:25.493267 7f220623e700 20 mon.a@0(leader).pg v4688  refreshing osd.3
 -12-02 09:12:25.493292 7f220623e700 10 mon.a@0(leader).pg v4689 read_pgmap_meta
 -12-02 09:12:25.493353 7f220623e700 10 mon.a@0(leader).pg v4689 map_pg_creates to 0 pgs -- no change
 -12-02 09:12:25.493355 7f220623e700 10 mon.a@0(leader).pg v4689 send_pg_creates to 0 pgs
 -12-02 09:12:25.493357 7f220623e700 10 mon.a@0(leader).pg v4689 update_logger
 -12-02 09:12:25.493460 7f220623e700 10 mon.a@0(leader).paxosservice(mdsmap 1..5) refresh
 -12-02 09:12:25.493495 7f220623e700 10 mon.a@0(leader).paxosservice(osdmap 1001..1701) refresh
 -12-02 09:12:25.493529 7f220623e700 10 mon.a@0(leader).paxosservice(logm 2764..3520) refresh
 -12-02 09:12:25.493532 7f220623e700 10 mon.a@0(leader).log v3520 update_from_paxos
 -12-02 09:12:25.493534 7f220623e700 10 mon.a@0(leader).log v3520 update_from_paxos version 3520 summary v 3520
 -12-02 09:12:25.493559 7f220623e700 10 mon.a@0(leader).paxosservice(monmap 1..1) refresh
 -12-02 09:12:25.493587 7f220623e700 10 mon.a@0(leader).paxosservice(auth 1..9) refresh
 -12-02 09:12:25.493589 7f220623e700 10 mon.a@0(leader).auth v9 update_from_paxos
 -12-02 09:12:25.493592 7f220623e700 10 mon.a@0(leader).pg v4689 map_pg_creates to 0 pgs -- no change
 -12-02 09:12:25.493593 7f220623e700 10 mon.a@0(leader).pg v4689 send_pg_creates to 0 pgs
       // commit_finish: commit_proposal
 -12-02 09:12:25.493596 7f220623e700 10 mon.a@0(leader).paxos(paxos refresh c 9288..9992) commit_proposal
 -12-02 09:12:25.493599 7f220623e700 10 mon.a@0(leader).paxos(paxos refresh c 9288..9992) commit_proposal proposal 0x53bc6e0 took 14.245555 to finish
       // commit_finish: wake up everyone waiting for paxos commit (waiting_for_commit)
 -12-02 09:12:25.493604 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) _active - not active
 -12-02 09:12:25.493610 7f220623e700  7 mon.a@0(leader).paxos(paxos refresh c 9288..9992) extend_lease now+15 (2014-12-02 09:12:40.493609)
 -12-02 09:12:25.493652 7f220623e700  1 -- 10.214.138.162:6789/0 --> mon.1 10.214.138.162:6790/0 -- paxos(lease lc 9992 fc 9288 pn 0 opn 0) v3 -- ?+0 0x5952d00
 -12-02 09:12:25.493662 7f220623e700  1 -- 10.214.138.162:6789/0 --> mon.2 10.214.138.162:6791/0 -- paxos(lease lc 9992 fc 9288 pn 0 opn 0) v3 -- ?+0 0x5279680
       // commit_finish: finish_round()
 -12-02 09:12:25.493670 7f220623e700 10 mon.a@0(leader).paxos(paxos active c 9288..9992) finish_round state 1 proposals left 1
       // commit_finish: finish_round(): set state = ACTIVE
       // commit_finish: finish_round(): propose queued value
 -12-02 09:12:25.493675 7f220623e700 10 mon.a@0(leader).paxos(paxos active c 9288..9992) propose_queued 9993 17263 bytes
       // commit_finish: finish_round(): propose_queued(): paxos::begin()
 -12-02 09:12:25.493678 7f220623e700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992) begin for 9993 17263 bytes
 -12-02 09:12:25.544843 7f2204239700  1 -- 10.214.138.162:6789/0 <== mds.0 10.214.138.162:6812/14611 366 ==== mdsbeacon(4103/a up:active seq 1717 v5) v2 ==== 279+0+0 (266296686 0 0) 0x5ac8b00 con 0x400dac0
 -12-02 09:12:25.583678 7f220623e700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992)  sending begin to mon.1
 -12-02 09:12:25.583699 7f220623e700  1 -- 10.214.138.162:6789/0 --> mon.1 10.214.138.162:6790/0 -- paxos(begin lc 9992 fc 0 pn 800 opn 0) v3 -- ?+0 0x5a4fd00
 -12-02 09:12:25.583775 7f220623e700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992)  sending begin to mon.2
 -12-02 09:12:25.583787 7f220623e700  1 -- 10.214.138.162:6789/0 --> mon.2 10.214.138.162:6791/0 -- paxos(begin lc 9992 fc 0 pn 800 opn 0) v3 -- ?+0 0x57c6680
       // commit_finish: wake up 'waiting_for_active', 'waiting_for_readable' and
       // 'waiting_for_writeable' contexts
       //
       // commit_finish() will only exit once all contexts have been awaken and
       // churned through.
       //
       // io_work will only attend the next queued value after commit_finish() exits
       //
       // io_work will only have another queued value if paxos finishes the current proposal (9993)
       // however, the monitor is currently waiting on io_work to be empty
       // (Finisher::wait_for_empty()).  This function waits for a signal on
       // 'finisher_empty_cond'.  this condition will be signaled once
       // Finisher::finisher_thread_entry() deals with whatever contexts it had when
       // the latest loop cycle started (finisher queue is swapped at start of cycle
       // and any newer values will only be dealt with in the next cycle).
       //
       // Given the finisher has dealt with this paxos proposal, it will not deal with
       // newer proposals before signaling the monitor.  This means that the monitor,
       // waiting on Finisher::wait_for_empty(), will be awaken before we get to start
       // writing the new proposal's value to disk
       //
 -12-02 09:12:25.583808 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) _active
 -12-02 09:12:25.583810 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) remove_legacy_versions
 -12-02 09:12:25.583840 7f220623e700  7 mon.a@0(leader).paxosservice(pgmap 4043..4689) _active creating new pending
 -12-02 09:12:25.583847 7f220623e700 10 mon.a@0(leader).pg v4689 create_pending v 4690
 -12-02 09:12:25.583850 7f220623e700  7 mon.a@0(leader).pg v4689 _updated_stats for osd.3 10.214.138.173:6804/3549
 -12-02 09:12:25.583855 7f220623e700 15 mon.a@0(leader) e1 send_reply routing reply to 10.214.138.173:6804/3549 via 10.214.138.162:6790/0 for request pg_stats(3 pgs tid 674 v 0) v1
 -12-02 09:12:25.583861 7f220623e700  1 -- 10.214.138.162:6789/0 --> 10.214.138.162:6790/0 -- route(pg_stats_ack(3 pgs tid 674) v1 tid 1650) v2 -- ?+0 0x5ab5f00 con 0x4009080
 -12-02 09:12:25.583872 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(3 pgs tid 671 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:25.583878 7f220623e700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.583878 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.583885 7f220623e700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(3 pgs tid 671 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:25.583889 7f220623e700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.583891 7f220623e700 20  allow so far , doing grant allow *
 -12-02 09:12:25.583892 7f220623e700 20  allow all
 -12-02 09:12:25.583893 7f220623e700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.583894 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.583898 7f220623e700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(3 pgs tid 671 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:25.583902 7f220623e700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(3 pgs tid 671 v 0) v1 from osd.4
 -12-02 09:12:25.583911 7f220623e700 10 mon.a@0(leader).pg v4689  got osd.4 osd_stat(11085 MB used, 189 GB avail, 199 GB total, peers [0,1,2,3,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,1,0,18]) (was osd_stat(11077 MB used, 189 GB avail, 199 GB total, peers [0,1,2,3,5]/[] op hist [0,0,0,0,0,0,0,0,0,6,1,1,2]))
 -12-02 09:12:25.583923 7f220623e700 15 mon.a@0(leader).pg v4689  got 58.0 reported at 1701:420 state active+clean -> active+clean
 -12-02 09:12:25.583932 7f220623e700 15 mon.a@0(leader).pg v4689  got 58.9 reported at 1701:382 state active+clean -> active+clean
 -12-02 09:12:25.583937 7f220623e700 15 mon.a@0(leader).pg v4689  got 59.1 reported at 1701:621 state active+clean -> active+clean
 -12-02 09:12:25.583943 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  setting proposal_timer 0x3f5ee50 with delay of 0.908914
 -12-02 09:12:25.583954 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 607 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:25.583959 7f220623e700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.583960 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.583964 7f220623e700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 607 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:25.583968 7f220623e700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.583970 7f220623e700 20  allow so far , doing grant allow *
 -12-02 09:12:25.583971 7f220623e700 20  allow all
 -12-02 09:12:25.583972 7f220623e700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.583972 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.583976 7f220623e700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 607 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:25.583980 7f220623e700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 607 v 0) v1 from osd.0
 -12-02 09:12:25.583984 7f220623e700 10 mon.a@0(leader).pg v4689  got osd.0 osd_stat(10754 MB used, 189 GB avail, 199 GB total, peers [1,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,13,0,0,10]) (was osd_stat(10746 MB used, 189 GB avail, 199 GB total, peers [1,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,17,0,8]))
 -12-02 09:12:25.583993 7f220623e700 15 mon.a@0(leader).pg v4689  got 58.5 reported at 1701:447 state active+clean -> active+clean
 -12-02 09:12:25.583999 7f220623e700 15 mon.a@0(leader).pg v4689  got 59.8 reported at 1701:587 state active+clean -> active+clean
 -12-02 09:12:25.584004 7f220623e700 15 mon.a@0(leader).pg v4689  got 59.a reported at 1701:596 state active+clean -> active+clean
 -12-02 09:12:25.584009 7f220623e700 15 mon.a@0(leader).pg v4689  got 59.e reported at 1701:686 state active+clean -> active+clean
 -12-02 09:12:25.584015 7f220623e700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.584018 7f220623e700 10 mon.a@0(leader).pg v4689 check_osd_map already seen 1701 >= 1701
 -12-02 09:12:25.584019 7f220623e700 10 mon.a@0(leader).pg v4689 update_logger
 -12-02 09:12:25.584036 7f220623e700  0 log_channel(cluster) log [INF] : pgmap v4689: 120 pgs: 120 active+clean; 29360 MB data, 59237 MB used, 1141 GB / 1199 GB avail; 1416 kB/s rd, 19908 kB/s wr, 15 op/s
 -12-02 09:12:25.584050 7f220623e700  1 -- 10.214.138.162:6789/0 --> 10.214.138.162:6789/0 -- log(1 entries) v1 -- ?+0 0x3fede80 con 0x4008dc0
 -12-02 09:12:25.586355 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.586364 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mds.0 10.214.138.162:6812/14611 is openallow * for mds.0 10.214.138.162:6812/14611
 -12-02 09:12:25.586374 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.586376 7f2204239700 10 mon.a@0(leader).paxosservice(mdsmap 1..5) dispatch mdsbeacon(4103/a up:active seq 1717 v5) v2 from mds.0 10.214.138.162:6812/14611
 -12-02 09:12:25.586383 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.586384 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.586390 7f2204239700 10 mon.a@0(leader).mds e5 preprocess_query mdsbeacon(4103/a up:active seq 1717 v5) v2 from mds.0 10.214.138.162:6812/14611
 -12-02 09:12:25.586396 7f2204239700 20 is_capable service=mds command= exec on cap allow *
 -12-02 09:12:25.586397 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.586398 7f2204239700 20  allow all
 -12-02 09:12:25.586400 7f2204239700 12 mon.a@0(leader).mds e5 preprocess_beacon mdsbeacon(4103/a up:active seq 1717 v5) v2 from mds.0 10.214.138.162:6812/14611 compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding}
 -12-02 09:12:25.586410 7f2204239700 15 mon.a@0(leader).mds e5 _note_beacon mdsbeacon(4103/a up:active seq 1717 v5) v2 noting time
 -12-02 09:12:25.586415 7f2204239700  1 -- 10.214.138.162:6789/0 --> 10.214.138.162:6812/14611 -- mdsbeacon(4103/a up:active seq 1717 v5) v3 -- ?+0 0x5ac8840 con 0x400dac0
 -12-02 09:12:25.586441 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.0 10.214.138.162:6789/0 0 ==== log(1 entries) v1 ==== 0+0+0 (0 0 0) 0x3fede80 con 0x4008dc0
 -12-02 09:12:25.586456 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.586461 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.0 10.214.138.162:6789/0 is openallow * for mon.0 10.214.138.162:6789/0
 -12-02 09:12:25.586468 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.586469 7f2204239700 10 mon.a@0(leader).paxosservice(logm 2764..3520) dispatch log(1 entries) v1 from mon.0 10.214.138.162:6789/0
 -12-02 09:12:25.586474 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.586475 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.586480 7f2204239700 10 mon.a@0(leader).log v3520 preprocess_query log(1 entries) v1 from mon.0 10.214.138.162:6789/0
 -12-02 09:12:25.586484 7f2204239700 10 mon.a@0(leader).log v3520 preprocess_log log(1 entries) v1 from mon.0
 -12-02 09:12:25.586487 7f2204239700 20 is_capable service=log command= write on cap allow *
 -12-02 09:12:25.586488 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.586489 7f2204239700 20  allow all
 -12-02 09:12:25.586509 7f2204239700 10 mon.a@0(leader).log v3520 prepare_update log(1 entries) v1 from mon.0 10.214.138.162:6789/0
 -12-02 09:12:25.586512 7f2204239700 10 mon.a@0(leader).log v3520 prepare_log log(1 entries) v1 from mon.0
 -12-02 09:12:25.586515 7f2204239700 10 mon.a@0(leader).log v3520  logging 2014-12-02 09:12:25.584038 mon.0 10.214.138.162:6789/0 808 : cluster [INF] pgmap v4689: 120 pgs: 120 active+clean; 29360 MB data, 59237 MB used, 1141 GB / 1199 GB avail; 1416 kB/s rd, 19908 kB/s wr, 15 op/s
 -12-02 09:12:25.586530 7f2204239700 10 mon.a@0(leader).paxosservice(logm 2764..3520)  setting proposal_timer 0x3f5ee30 with delay of 0.906327
 -12-02 09:12:25.589103 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4623 ==== paxos(lease_ack lc 9992 fc 9288 pn 0 opn 0) v3 ==== 80+0+0 (3411068198 0 0) 0x5952d00 con 0x4009080
 -12-02 09:12:25.589120 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589122 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589127 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589130 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.589131 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589132 7f2204239700 20  allow all
 -12-02 09:12:25.589134 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.589135 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589136 7f2204239700 20  allow all
 -12-02 09:12:25.589137 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992) handle_lease_ack from mon.1 -- stray (probably since revoked)
 -12-02 09:12:25.589144 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.2 10.214.138.162:6791/0 2955 ==== paxos(lease_ack lc 9992 fc 9288 pn 0 opn 0) v3 ==== 80+0+0 (2216071500 0 0) 0x57c6680 con 0x4009fa0
 -12-02 09:12:25.589150 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589152 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.2 10.214.138.162:6791/0 is openallow * for mon.2 10.214.138.162:6791/0
 -12-02 09:12:25.589156 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589158 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.589159 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589160 7f2204239700 20  allow all
 -12-02 09:12:25.589161 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.589162 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589163 7f2204239700 20  allow all
 -12-02 09:12:25.589164 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992) handle_lease_ack from mon.2 -- stray (probably since revoked)
 -12-02 09:12:25.589168 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4624 ==== forward(pg_stats(3 pgs tid 596 v 0) v1 caps allow * tid 1653 con_features 70368744177663) to leader v2 ==== 1827+0+0 (3489783430 0 0) 0x5742580 con 0x4009080
 -12-02 09:12:25.589176 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589177 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589213 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589215 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.589216 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589217 7f2204239700 20  allow all
 -12-02 09:12:25.589219 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.2 10.214.138.162:6810/7444 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589224 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.589225 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589226 7f2204239700 20  allow all
 -12-02 09:12:25.589229 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:25.589230 7f2204239700 10 mon.a@0(leader) e1  mesg 0x4086300 from 10.214.138.162:6790/0
 -12-02 09:12:25.589259 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589261 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.2 :/0 is openallow * for osd.2 :/0
 -12-02 09:12:25.589265 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589267 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(3 pgs tid 596 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:25.589272 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589273 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589279 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(3 pgs tid 596 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:25.589284 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.589311 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589313 7f2204239700 20  allow all
 -12-02 09:12:25.589315 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589315 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589321 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(3 pgs tid 596 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:25.589326 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(3 pgs tid 596 v 0) v1 from osd.2
 -12-02 09:12:25.589357 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.2 osd_stat(7382 MB used, 192 GB avail, 199 GB total, peers [0,1,3,4,5]/[] op hist []) (was osd_stat(7344 MB used, 192 GB avail, 199 GB total, peers [0,1,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,5]))
 -12-02 09:12:25.589418 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.7 reported at 1701:548 state active+clean -> active+clean
 -12-02 09:12:25.589439 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.c reported at 1701:494 state active+clean -> active+clean
 -12-02 09:12:25.589444 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.d reported at 1701:696 state active+clean -> active+clean
 -12-02 09:12:25.589454 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.589459 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4625 ==== forward(pg_stats(4 pgs tid 668 v 0) v1 caps allow * tid 1654 con_features 52776558133247) to leader v2 ==== 2212+0+0 (2632109938 0 0) 0x595c600 con 0x4009080
 -12-02 09:12:25.589469 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589470 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589475 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589477 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.589478 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589479 7f2204239700 20  allow all
 -12-02 09:12:25.589480 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.5 10.214.138.173:6821/3797 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589484 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.589485 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589487 7f2204239700 20  allow all
 -12-02 09:12:25.589489 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:25.589490 7f2204239700 10 mon.a@0(leader) e1  mesg 0x4082100 from 10.214.138.162:6790/0
 -12-02 09:12:25.589493 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589495 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.5 :/0 is openallow * for osd.5 :/0
 -12-02 09:12:25.589497 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589499 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 668 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:25.589503 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589504 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589509 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 668 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:25.589513 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.589514 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589515 7f2204239700 20  allow all
 -12-02 09:12:25.589516 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589517 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589521 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 668 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:25.589524 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 668 v 0) v1 from osd.5
 -12-02 09:12:25.589529 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.5 osd_stat(11367 MB used, 188 GB avail, 199 GB total, peers [0,1,2,3,4]/[] op hist [0,0,0,0,0,0,0,0,0,0,1,1,2,2]) (was osd_stat(11257 MB used, 188 GB avail, 199 GB total, peers [0,1,2,3,4]/[] op hist [0,0,0,0,0,0,0,0,0,0,0,5,3,5]))
 -12-02 09:12:25.589539 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.2 reported at 1701:479 state active+clean -> active+clean
 -12-02 09:12:25.589545 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.2 reported at 1701:746 state active+clean -> active+clean
 -12-02 09:12:25.589550 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.6 reported at 1701:792 state active+clean -> active+clean
 -12-02 09:12:25.589554 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.7 reported at 1701:721 state active+clean -> active+clean
 -12-02 09:12:25.589559 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.589563 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4626 ==== forward(pg_stats(6 pgs tid 616 v 0) v1 caps allow * tid 1655 con_features 70368744177663) to leader v2 ==== 3302+0+0 (1365139505 0 0) 0x554f800 con 0x4009080
 -12-02 09:12:25.589570 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589572 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589576 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589578 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.589579 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589580 7f2204239700 20  allow all
 -12-02 09:12:25.589581 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.1 10.214.138.162:6805/7218 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589585 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.589586 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589587 7f2204239700 20  allow all
 -12-02 09:12:25.589589 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:25.589591 7f2204239700 10 mon.a@0(leader) e1  mesg 0x4083180 from 10.214.138.162:6790/0
 -12-02 09:12:25.589593 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589595 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.1 :/0 is openallow * for osd.1 :/0
 -12-02 09:12:25.589597 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589599 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(6 pgs tid 616 v 0) v1 from osd.1 10.214.138.162:6805/7218
 -12-02 09:12:25.589603 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589603 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589633 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(6 pgs tid 616 v 0) v1 from osd.1 10.214.138.162:6805/7218
 -12-02 09:12:25.589640 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.589641 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589643 7f2204239700 20  allow all
 -12-02 09:12:25.589644 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589644 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589653 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(6 pgs tid 616 v 0) v1 from osd.1 10.214.138.162:6805/7218
 -12-02 09:12:25.589676 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(6 pgs tid 616 v 0) v1 from osd.1
 -12-02 09:12:25.589683 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.1 osd_stat(9298 MB used, 190 GB avail, 199 GB total, peers [0,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,11,0,2]) (was osd_stat(9278 MB used, 190 GB avail, 199 GB total, peers [0,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,8,2,2,2]))
 -12-02 09:12:25.589692 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.8 reported at 1701:558 state active+clean -> active+clean
 -12-02 09:12:25.589721 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.b reported at 1701:483 state active+clean -> active+clean
 -12-02 09:12:25.589750 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.f reported at 1701:462 state active+clean -> active+clean
 -12-02 09:12:25.589758 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.4 reported at 1701:753 state active+clean -> active+clean
 -12-02 09:12:25.589763 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.5 reported at 1701:729 state active+clean -> active+clean
 -12-02 09:12:25.589768 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.c reported at 1701:759 state active+clean -> active+clean
 -12-02 09:12:25.589774 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.589783 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4627 ==== forward(pg_stats(3 pgs tid 675 v 0) v1 caps allow * tid 1656 con_features 52776558133247) to leader v2 ==== 1756+0+0 (1813894243 0 0) 0x554a580 con 0x4009080
 -12-02 09:12:25.589793 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589794 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589799 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589801 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.589802 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589803 7f2204239700 20  allow all
 -12-02 09:12:25.589804 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.3 10.214.138.173:6804/3549 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589808 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.589809 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589810 7f2204239700 20  allow all
 -12-02 09:12:25.589812 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:25.589814 7f2204239700 10 mon.a@0(leader) e1  mesg 0x4081b80 from 10.214.138.162:6790/0
 -12-02 09:12:25.589816 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589818 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.3 :/0 is openallow * for osd.3 :/0
 -12-02 09:12:25.589820 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589822 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(3 pgs tid 675 v 0) v1 from osd.3 10.214.138.173:6804/3549
 -12-02 09:12:25.589826 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589826 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589831 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(3 pgs tid 675 v 0) v1 from osd.3 10.214.138.173:6804/3549
 -12-02 09:12:25.589836 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.589837 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589838 7f2204239700 20  allow all
 -12-02 09:12:25.589839 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589840 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.589843 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(3 pgs tid 675 v 0) v1 from osd.3 10.214.138.173:6804/3549
 -12-02 09:12:25.589847 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(3 pgs tid 675 v 0) v1 from osd.3
 -12-02 09:12:25.589852 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.3 osd_stat(9571 MB used, 190 GB avail, 199 GB total, peers [0,1,2,4,5]/[] op hist [0,0,0,0,0,0,0,0,6,2]) (was osd_stat(9531 MB used, 190 GB avail, 199 GB total, peers [0,1,2,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,0,0,1]))
 -12-02 09:12:25.589877 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.4 reported at 1701:363 state active+clean -> active+clean
 -12-02 09:12:25.589884 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.3 reported at 1701:644 state active+clean -> active+clean
 -12-02 09:12:25.589889 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.9 reported at 1701:655 state active+clean -> active+clean
 -12-02 09:12:25.589894 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.589898 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4628 ==== forward(pg_stats(5 pgs tid 672 v 0) v1 caps allow * tid 1657 con_features 52776558133247) to leader v2 ==== 2652+0+0 (1032121972 0 0) 0x58f5780 con 0x4009080
 -12-02 09:12:25.589907 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589908 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589938 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589941 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.589942 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589943 7f2204239700 20  allow all
 -12-02 09:12:25.589944 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.4 10.214.138.173:6816/3639 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.589948 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.589949 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.589955 7f2204239700 20  allow all
 -12-02 09:12:25.589978 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:25.589980 7f2204239700 10 mon.a@0(leader) e1  mesg 0x4083700 from 10.214.138.162:6790/0
 -12-02 09:12:25.589984 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.589985 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.4 :/0 is openallow * for osd.4 :/0
 -12-02 09:12:25.589988 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.589990 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(5 pgs tid 672 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:25.589995 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.589996 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.590004 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(5 pgs tid 672 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:25.590009 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.590011 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590033 7f2204239700 20  allow all
 -12-02 09:12:25.590035 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.590035 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.590040 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(5 pgs tid 672 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:25.590045 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(5 pgs tid 672 v 0) v1 from osd.4
 -12-02 09:12:25.590049 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.4 osd_stat(11142 MB used, 189 GB avail, 199 GB total, peers [0,1,2,3,5]/[] op hist [0,0,0,0,0,0,0,0,1,0,0,1,4,1]) (was osd_stat(11077 MB used, 189 GB avail, 199 GB total, peers [0,1,2,3,5]/[] op hist [0,0,0,0,0,0,0,0,0,6,1,1,2]))
 -12-02 09:12:25.590084 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.0 reported at 1701:422 state active+clean -> active+clean
 -12-02 09:12:25.590091 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.9 reported at 1701:383 state active+clean -> active+clean
 -12-02 09:12:25.590096 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.0 reported at 1701:707 state active+clean -> active+clean
 -12-02 09:12:25.590104 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.1 reported at 1701:632 state active+clean -> active+clean
 -12-02 09:12:25.590129 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.f reported at 1701:611 state active+clean -> active+clean
 -12-02 09:12:25.590137 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.590142 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4629 ==== forward(pg_stats(4 pgs tid 608 v 0) v1 caps allow * tid 1658 con_features 70368744177663) to leader v2 ==== 2360+0+0 (2882545136 0 0) 0x554b700 con 0x4009080
 -12-02 09:12:25.590155 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.590178 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.590185 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.590187 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.590189 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590190 7f2204239700 20  allow all
 -12-02 09:12:25.590191 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.0 10.214.138.162:6800/7075 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.590195 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.590196 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590197 7f2204239700 20  allow all
 -12-02 09:12:25.590199 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:25.590205 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5acc200 from 10.214.138.162:6790/0
 -12-02 09:12:25.590208 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.590209 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.0 :/0 is openallow * for osd.0 :/0
 -12-02 09:12:25.590212 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.590214 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 608 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:25.590218 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.590219 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.590224 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 608 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:25.590228 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.590229 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590230 7f2204239700 20  allow all
 -12-02 09:12:25.590231 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.590232 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.590236 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 608 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:25.590239 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 608 v 0) v1 from osd.0
 -12-02 09:12:25.590244 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.0 osd_stat(10792 MB used, 189 GB avail, 199 GB total, peers [1,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,0,2,2,1]) (was osd_stat(10746 MB used, 189 GB avail, 199 GB total, peers [1,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,17,0,8]))
 -12-02 09:12:25.590252 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.5 reported at 1701:447 state active+clean -> active+clean
 -12-02 09:12:25.590258 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.8 reported at 1701:589 state active+clean -> active+clean
 -12-02 09:12:25.590287 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.a reported at 1701:596 state active+clean -> active+clean
 -12-02 09:12:25.590292 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.e reported at 1701:686 state active+clean -> active+clean
 -12-02 09:12:25.590297 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.590306 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4630 ==== forward(pg_stats(4 pgs tid 597 v 0) v1 caps allow * tid 1659 con_features 70368744177663) to leader v2 ==== 2304+0+0 (3502534217 0 0) 0x55abc00 con 0x4009080
 -12-02 09:12:25.590337 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.590339 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.590345 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.590347 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.590348 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590349 7f2204239700 20  allow all
 -12-02 09:12:25.590372 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.2 10.214.138.162:6810/7444 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.590380 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.590381 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590382 7f2204239700 20  allow all
 -12-02 09:12:25.590385 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:25.590386 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5acc4c0 from 10.214.138.162:6790/0
 -12-02 09:12:25.590389 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.590391 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.2 :/0 is openallow * for osd.2 :/0
 -12-02 09:12:25.590394 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.590395 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 597 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:25.590400 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.590400 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.590430 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 597 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:25.590436 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:25.590438 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590439 7f2204239700 20  allow all
 -12-02 09:12:25.590440 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:25.590441 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:25.590445 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 597 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:25.590449 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 597 v 0) v1 from osd.2
 -12-02 09:12:25.590476 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.2 osd_stat(7382 MB used, 192 GB avail, 199 GB total, peers [0,1,3,4,5]/[] op hist []) (was osd_stat(7344 MB used, 192 GB avail, 199 GB total, peers [0,1,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,5]))
 -12-02 09:12:25.590484 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.1 reported at 1701:523 state active+clean -> active+clean
 -12-02 09:12:25.590491 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.7 reported at 1701:548 state active+clean -> active+clean
 -12-02 09:12:25.590495 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.c reported at 1701:495 state active+clean -> active+clean
 -12-02 09:12:25.590500 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.d reported at 1701:699 state active+clean -> active+clean
 -12-02 09:12:25.590528 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:25.590535 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4631 ==== forward(pg_stats(4 pgs tid 669 v 0) v1 caps allow * tid 1660 con_features 52776558133247) to leader v2 ==== 2208+0+0 (3874213199 0 0) 0x55acd80 con 0x4009080
 -12-02 09:12:25.590545 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:25.590546 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.590574 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:25.590577 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:25.590579 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590580 7f2204239700 20  allow all
 -12-02 09:12:25.590580 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.5 10.214.138.173:6821/3797 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:25.590586 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:25.590587 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:25.590588 7f2204239700 20  allow all
 -12-02 09:12:26.236296 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:26.236325 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5acc780 from 10.214.138.162:6790/0
 -12-02 09:12:26.236340 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.236342 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.5 :/0 is openallow * for osd.5 :/0
 -12-02 09:12:26.236349 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.236353 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 669 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:26.236364 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.236365 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.236377 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 669 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:26.236386 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:26.236388 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.236389 7f2204239700 20  allow all
 -12-02 09:12:26.236392 7f2204239700  5 mon.a@0(leader).paxos(paxos updating c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.236393 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.236398 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 669 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:26.236404 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 669 v 0) v1 from osd.5
 -12-02 09:12:26.236415 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.5 osd_stat(11390 MB used, 188 GB avail, 199 GB total, peers [0,1,2,3,4]/[] op hist [0,0,0,0,0,0,0,0,0,0,3,0,1]) (was osd_stat(11257 MB used, 188 GB avail, 199 GB total, peers [0,1,2,3,4]/[] op hist [0,0,0,0,0,0,0,0,0,0,0,5,3,5]))
 -12-02 09:12:26.236435 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.2 reported at 1701:480 state active+clean -> active+clean
 -12-02 09:12:26.236448 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.2 reported at 1701:751 state active+clean -> active+clean
 -12-02 09:12:26.236455 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.6 reported at 1701:793 state active+clean -> active+clean
 -12-02 09:12:26.236461 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.7 reported at 1701:723 state active+clean -> active+clean
 -12-02 09:12:26.236468 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:26.236486 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.2 10.214.138.162:6791/0 2956 ==== paxos(accept lc 9992 fc 0 pn 800 opn 0) v3 ==== 80+0+0 (4274025788 0 0) 0x5279680 con 0x4009fa0
 -12-02 09:12:26.236499 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.236501 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.2 10.214.138.162:6791/0 is openallow * for mon.2 10.214.138.162:6791/0
 -12-02 09:12:26.236508 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.236510 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.236511 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.236513 7f2204239700 20  allow all
 -12-02 09:12:26.236514 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.236515 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.236517 7f2204239700 20  allow all
 -12-02 09:12:26.236519 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992) handle_accept paxos(accept lc 9992 fc 0 pn 800 opn 0) v3
 -12-02 09:12:26.236523 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992)  now 0,2 have accepted
 -12-02 09:12:26.236532 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4639 ==== paxos(accept lc 9992 fc 0 pn 800 opn 0) v3 ==== 80+0+0 (61318401 0 0) 0x551d500 con 0x4009080
 -12-02 09:12:26.236540 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.236542 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.236548 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.236550 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.236551 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.236552 7f2204239700 20  allow all
 -12-02 09:12:26.236555 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.236556 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.236557 7f2204239700 20  allow all
 -12-02 09:12:26.236558 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992) handle_accept paxos(accept lc 9992 fc 0 pn 800 opn 0) v3
 -12-02 09:12:26.236563 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992)  now 0,1,2 have accepted
 -12-02 09:12:26.236566 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992)  got majority, committing, done with update
       // paxos transitions to 'writing' in paxos::commit_start
       //
       // paxos::commit_start() queues a new transaction on the store; io_work will
       // pick on it, but only after monitor::wait_for_paxos_write() has been awaken
       //
 -12-02 09:12:26.236568 7f2204239700 10 mon.a@0(leader).paxos(paxos updating c 9288..9992) commit_start 9993
 -12-02 09:12:26.237015 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4632 ==== forward(pg_stats(6 pgs tid 617 v 0) v1 caps allow * tid 1661 con_features 70368744177663) to leader v2 ==== 3314+0+0 (1544681194 0 0) 0x5affa80 con 0x4009080
 -12-02 09:12:26.237031 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237033 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237039 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237042 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.237044 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237045 7f2204239700 20  allow all
 -12-02 09:12:26.237047 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.1 10.214.138.162:6805/7218 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237053 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.237055 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237056 7f2204239700 20  allow all
 -12-02 09:12:26.237059 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:26.237061 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5acca40 from 10.214.138.162:6790/0
 -12-02 09:12:26.237065 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237067 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.1 :/0 is openallow * for osd.1 :/0
 -12-02 09:12:26.237071 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237072 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(6 pgs tid 617 v 0) v1 from osd.1 10.214.138.162:6805/7218
 -12-02 09:12:26.237078 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237079 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237086 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(6 pgs tid 617 v 0) v1 from osd.1 10.214.138.162:6805/7218
 -12-02 09:12:26.237091 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:26.237093 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237094 7f2204239700 20  allow all
 -12-02 09:12:26.237096 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237096 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237102 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(6 pgs tid 617 v 0) v1 from osd.1 10.214.138.162:6805/7218
 -12-02 09:12:26.237106 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(6 pgs tid 617 v 0) v1 from osd.1
 -12-02 09:12:26.237112 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.1 osd_stat(9358 MB used, 190 GB avail, 199 GB total, peers [0,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,0,1,1,7]) (was osd_stat(9278 MB used, 190 GB avail, 199 GB total, peers [0,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,8,2,2,2]))
 -12-02 09:12:26.237131 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.8 reported at 1701:558 state active+clean -> active+clean
 -12-02 09:12:26.237139 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.b reported at 1701:483 state active+clean -> active+clean
 -12-02 09:12:26.237146 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.f reported at 1701:462 state active+clean -> active+clean
 -12-02 09:12:26.237153 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.4 reported at 1701:755 state active+clean -> active+clean
 -12-02 09:12:26.237159 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.5 reported at 1701:731 state active+clean -> active+clean
 -12-02 09:12:26.237165 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.c reported at 1701:765 state active+clean -> active+clean
 -12-02 09:12:26.237171 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:26.237177 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4633 ==== forward(pg_stats(4 pgs tid 676 v 0) v1 caps allow * tid 1662 con_features 52776558133247) to leader v2 ==== 2156+0+0 (1216041161 0 0) 0x5a18c80 con 0x4009080
 -12-02 09:12:26.237188 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237190 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237196 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237198 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.237200 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237201 7f2204239700 20  allow all
 -12-02 09:12:26.237202 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.3 10.214.138.173:6804/3549 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237208 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.237210 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237211 7f2204239700 20  allow all
 -12-02 09:12:26.237213 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:26.237216 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5accd00 from 10.214.138.162:6790/0
 -12-02 09:12:26.237219 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237221 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.3 :/0 is openallow * for osd.3 :/0
 -12-02 09:12:26.237224 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237226 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 676 v 0) v1 from osd.3 10.214.138.173:6804/3549
 -12-02 09:12:26.237232 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237233 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237239 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 676 v 0) v1 from osd.3 10.214.138.173:6804/3549
 -12-02 09:12:26.237244 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:26.237246 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237247 7f2204239700 20  allow all
 -12-02 09:12:26.237248 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237249 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237254 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 676 v 0) v1 from osd.3 10.214.138.173:6804/3549
 -12-02 09:12:26.237259 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 676 v 0) v1 from osd.3
 -12-02 09:12:26.237264 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.3 osd_stat(9599 MB used, 190 GB avail, 199 GB total, peers [0,1,2,4,5]/[] op hist []) (was osd_stat(9531 MB used, 190 GB avail, 199 GB total, peers [0,1,2,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,0,0,1]))
 -12-02 09:12:26.237273 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.4 reported at 1701:366 state active+clean -> active+clean
 -12-02 09:12:26.237280 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.6 reported at 1701:618 state active+clean -> active+clean
 -12-02 09:12:26.237289 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.3 reported at 1701:645 state active+clean -> active+clean
 -12-02 09:12:26.237295 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.9 reported at 1701:655 state active+clean -> active+clean
 -12-02 09:12:26.237301 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:26.237307 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4634 ==== forward(pg_stats(6 pgs tid 673 v 0) v1 caps allow * tid 1663 con_features 52776558133247) to leader v2 ==== 3084+0+0 (2168776932 0 0) 0x5af8000 con 0x4009080
 -12-02 09:12:26.237316 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237319 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237324 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237327 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.237328 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237330 7f2204239700 20  allow all
 -12-02 09:12:26.237331 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.4 10.214.138.173:6816/3639 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237336 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.237338 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237339 7f2204239700 20  allow all
 -12-02 09:12:26.237342 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:26.237344 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5accfc0 from 10.214.138.162:6790/0
 -12-02 09:12:26.237347 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237349 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.4 :/0 is openallow * for osd.4 :/0
 -12-02 09:12:26.237353 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237354 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(6 pgs tid 673 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:26.237360 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237361 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237366 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(6 pgs tid 673 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:26.237372 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:26.237374 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237375 7f2204239700 20  allow all
 -12-02 09:12:26.237377 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237377 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237382 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(6 pgs tid 673 v 0) v1 from osd.4 10.214.138.173:6816/3639
 -12-02 09:12:26.237387 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(6 pgs tid 673 v 0) v1 from osd.4
 -12-02 09:12:26.237391 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.4 osd_stat(11186 MB used, 188 GB avail, 199 GB total, peers [0,1,2,3,5]/[] op hist [0,0,0,0,0,0,0,0,1,0,2,6]) (was osd_stat(11077 MB used, 189 GB avail, 199 GB total, peers [0,1,2,3,5]/[] op hist [0,0,0,0,0,0,0,0,0,6,1,1,2]))
 -12-02 09:12:26.237403 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.0 reported at 1701:422 state active+clean -> active+clean
 -12-02 09:12:26.237409 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.9 reported at 1701:383 state active+clean -> active+clean
 -12-02 09:12:26.237415 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.0 reported at 1701:714 state active+clean -> active+clean
 -12-02 09:12:26.237441 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.1 reported at 1701:632 state active+clean -> active+clean
 -12-02 09:12:26.237447 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.b reported at 1701:630 state active+clean -> active+clean
 -12-02 09:12:26.237454 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.f reported at 1701:615 state active+clean -> active+clean
 -12-02 09:12:26.237461 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:26.237466 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4635 ==== forward(pg_stats(4 pgs tid 609 v 0) v1 caps allow * tid 1664 con_features 70368744177663) to leader v2 ==== 2356+0+0 (3201636574 0 0) 0x5ab5f00 con 0x4009080
 -12-02 09:12:26.237477 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237479 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237485 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237487 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.237488 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237490 7f2204239700 20  allow all
 -12-02 09:12:26.237491 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.0 10.214.138.162:6800/7075 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237496 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.237498 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237499 7f2204239700 20  allow all
 -12-02 09:12:26.237501 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:26.237503 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5acd280 from 10.214.138.162:6790/0
 -12-02 09:12:26.237507 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237509 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.0 :/0 is openallow * for osd.0 :/0
 -12-02 09:12:26.237513 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237515 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 609 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:26.237520 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237521 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237526 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 609 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:26.237532 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:26.237533 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237534 7f2204239700 20  allow all
 -12-02 09:12:26.237536 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237537 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237542 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 609 v 0) v1 from osd.0 10.214.138.162:6800/7075
 -12-02 09:12:26.237546 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 609 v 0) v1 from osd.0
 -12-02 09:12:26.237551 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.0 osd_stat(10872 MB used, 189 GB avail, 199 GB total, peers [1,2,3,4,5]/[] op hist [0,0,0,0,0,1,0,1,0,0,3,2,1]) (was osd_stat(10746 MB used, 189 GB avail, 199 GB total, peers [1,2,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,17,0,8]))
 -12-02 09:12:26.237562 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.5 reported at 1701:448 state active+clean -> active+clean
 -12-02 09:12:26.237569 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.8 reported at 1701:590 state active+clean -> active+clean
 -12-02 09:12:26.237575 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.a reported at 1701:604 state active+clean -> active+clean
 -12-02 09:12:26.237580 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.e reported at 1701:687 state active+clean -> active+clean
 -12-02 09:12:26.237586 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:26.237591 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4636 ==== forward(pg_stats(4 pgs tid 598 v 0) v1 caps allow * tid 1665 con_features 70368744177663) to leader v2 ==== 2336+0+0 (3385266818 0 0) 0x5951400 con 0x4009080
 -12-02 09:12:26.237601 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237603 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237609 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237611 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.237613 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237614 7f2204239700 20  allow all
 -12-02 09:12:26.237615 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.2 10.214.138.162:6810/7444 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237620 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.237622 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237623 7f2204239700 20  allow all
 -12-02 09:12:26.237626 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:26.237628 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5acd540 from 10.214.138.162:6790/0
 -12-02 09:12:26.237631 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237633 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.2 :/0 is openallow * for osd.2 :/0
 -12-02 09:12:26.237636 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237638 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(4 pgs tid 598 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:26.237643 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237644 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237650 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(4 pgs tid 598 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:26.237655 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:26.237656 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.237658 7f2204239700 20  allow all
 -12-02 09:12:26.237659 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.237660 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.237665 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(4 pgs tid 598 v 0) v1 from osd.2 10.214.138.162:6810/7444
 -12-02 09:12:26.237669 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(4 pgs tid 598 v 0) v1 from osd.2
 -12-02 09:12:26.237674 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.2 osd_stat(7418 MB used, 192 GB avail, 199 GB total, peers [0,1,3,4,5]/[] op hist [0,0,0,0,0,0,14,3]) (was osd_stat(7344 MB used, 192 GB avail, 199 GB total, peers [0,1,3,4,5]/[] op hist [0,0,0,0,0,0,0,0,0,0,5]))
 -12-02 09:12:26.237685 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.1 reported at 1701:523 state active+clean -> active+clean
 -12-02 09:12:26.237691 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.7 reported at 1701:551 state active+clean -> active+clean
 -12-02 09:12:26.237697 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.c reported at 1701:495 state active+clean -> active+clean
 -12-02 09:12:26.237703 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.d reported at 1701:706 state active+clean -> active+clean
 -12-02 09:12:26.237709 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:26.237714 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4637 ==== forward(pg_stats(5 pgs tid 670 v 0) v1 caps allow * tid 1666 con_features 52776558133247) to leader v2 ==== 2648+0+0 (2763775360 0 0) 0x5638f00 con 0x4009080
 -12-02 09:12:26.237723 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.237725 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.237731 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.237733 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:26.240185 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.240190 7f2204239700 20  allow all
 -12-02 09:12:26.240192 7f2204239700 10 mon.a@0(leader) e1 received forwarded message from osd.5 10.214.138.173:6821/3797 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:26.240205 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:26.240207 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.240208 7f2204239700 20  allow all
 -12-02 09:12:26.240212 7f2204239700 10 mon.a@0(leader) e1  caps are allow *
 -12-02 09:12:26.240214 7f2204239700 10 mon.a@0(leader) e1  mesg 0x5acd800 from 10.214.138.162:6790/0
 -12-02 09:12:26.240218 7f2204239700 20 mon.a@0(leader) e1 have connection
 -12-02 09:12:26.240220 7f2204239700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.5 :/0 is openallow * for osd.5 :/0
 -12-02 09:12:26.240224 7f2204239700 20 mon.a@0(leader) e1  caps allow *
 -12-02 09:12:26.240227 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689) dispatch pg_stats(5 pgs tid 670 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:26.240234 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.240235 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.240242 7f2204239700 10 mon.a@0(leader).pg v4689 preprocess_query pg_stats(5 pgs tid 670 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:26.240248 7f2204239700 20 is_capable service=pg command= read on cap allow *
 -12-02 09:12:26.240250 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:26.240251 7f2204239700 20  allow all
 -12-02 09:12:26.240253 7f2204239700  5 mon.a@0(leader).paxos(paxos writing c 9288..9992) is_readable = 1 - now=2014-12-02 09:12:26.240253 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:26.240258 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_update pg_stats(5 pgs tid 670 v 0) v1 from osd.5 10.214.138.173:6821/3797
 -12-02 09:12:26.240264 7f2204239700 10 mon.a@0(leader).pg v4689 prepare_pg_stats pg_stats(5 pgs tid 670 v 0) v1 from osd.5
 -12-02 09:12:26.240270 7f2204239700 10 mon.a@0(leader).pg v4689  got osd.5 osd_stat(11436 MB used, 188 GB avail, 199 GB total, peers [0,1,2,3,4]/[] op hist [0,0,0,0,0,0,0,0,1,1,4,2,1]) (was osd_stat(11257 MB used, 188 GB avail, 199 GB total, peers [0,1,2,3,4]/[] op hist [0,0,0,0,0,0,0,0,0,0,0,5,3,5]))
 -12-02 09:12:26.240283 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.2 reported at 1701:480 state active+clean -> active+clean
 -12-02 09:12:26.240292 7f2204239700 15 mon.a@0(leader).pg v4689  got 58.a reported at 1701:398 state active+clean -> active+clean
 -12-02 09:12:26.240300 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.2 reported at 1701:756 state active+clean -> active+clean
 -12-02 09:12:26.240306 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.6 reported at 1701:794 state active+clean -> active+clean
 -12-02 09:12:26.240312 7f2204239700 15 mon.a@0(leader).pg v4689  got 59.7 reported at 1701:725 state active+clean -> active+clean
       // back on monitor::wait_for_paxos_write()
       //
       // finish_commit() has finished its work, paxos is still writing proposal 9993
       // to be written to disk.  io_work will deal with the new paxos write on its
       // next cycle, which will be happening now that paxos::commit_finish() has
       // finished, but the monitor would have been already woken up, it was simply
       // waiting on paxos::finish_commit() to relinquish the mon_lock.
       //
 -12-02 09:12:26.240404 7f2204239700 10 mon.a@0(leader).paxosservice(pgmap 4043..4689)  proposal_timer already set
 -12-02 09:12:26.240416 7f2204c3a700 10 mon.a@0(leader) e1 wait_for_paxos_write flushed pending write
 -12-02 09:12:26.240425 7f2204c3a700 10 mon.a@0(leader) e1 sync_reset_requester
 -12-02 09:12:26.240427 7f2204c3a700 10 mon.a@0(leader) e1 unregister_cluster_logger
 -12-02 09:12:26.240488 7f2204239700  1 -- 10.214.138.162:6789/0 <== mon.1 10.214.138.162:6790/0 4638 ==== forward(pg_stats(6 pgs tid 618 v 0) v1 caps allow * tid 1667 con_features 70368744177663) to leader v2 ==== 3314+0+0 (3309266684 0 0) 0x551e680 con 0x4009080
 -12-02 09:12:26.635768 7f2204c3a700 10 mon.a@0(leader) e1 cancel_probe_timeout (none scheduled)
       // enter monitor::_reset(): state is not probing
       //
 -12-02 09:12:27.841083 7f2204c3a700 10 mon.a@0(probing) e1 _reset
 -12-02 09:12:27.841104 7f2204c3a700 10 mon.a@0(probing) e1 cancel_probe_timeout (none scheduled)
 -12-02 09:12:27.841106 7f2204c3a700 10 mon.a@0(probing) e1 timecheck_finish
 -12-02 09:12:27.850073 7f2204c3a700 10 mon.a@0(probing) e1 scrub_reset
       // monitor::_reset(): call paxos::restart()
       //
 -12-02 09:12:27.850083 7f2204c3a700 10 mon.a@0(probing).paxos(paxos writing c 9288..9992) restart -- canceling timeouts
       // paxos::restart(): flush any pending writes, same as before, waiting for
       // the store to flush, for io_work to be empty.
       //
 -12-02 09:12:27.850094 7f2204c3a700 10 mon.a@0(probing).paxos(paxos writing c 9288..9992) restart flushing
 -12-02 09:12:27.850109 7f2204239700 20 mon.a@0(probing) e1 have connection
 -12-02 09:12:27.850111 7f2204239700 20 mon.a@0(probing) e1 ms_dispatch existing session MonSession: mon.1 10.214.138.162:6790/0 is openallow * for mon.1 10.214.138.162:6790/0
 -12-02 09:12:27.850127 7f2204239700 20 mon.a@0(probing) e1  caps allow *
 -12-02 09:12:27.850130 7f2204239700 20 is_capable service=mon command= read on cap allow *
 -12-02 09:12:27.850132 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:27.850134 7f2204239700 20  allow all
 -12-02 09:12:27.850135 7f2204239700 10 mon.a@0(probing) e1 received forwarded message from osd.1 10.214.138.162:6805/7218 via mon.1 10.214.138.162:6790/0
 -12-02 09:12:27.850141 7f2204239700 20 is_capable service=mon command= exec on cap allow *
 -12-02 09:12:27.850143 7f2204239700 20  allow so far , doing grant allow *
 -12-02 09:12:27.850143 7f2204239700 20  allow all
 -12-02 09:12:27.850150 7f2204239700 10 mon.a@0(probing) e1  caps are allow *
 -12-02 09:12:27.850153 7f2204239700 10 mon.a@0(probing) e1  mesg 0x5acdac0 from 10.214.138.162:6790/0
 -12-02 09:12:27.850158 7f2204239700 20 mon.a@0(probing) e1 have connection
 -12-02 09:12:27.850160 7f2204239700 20 mon.a@0(probing) e1 ms_dispatch existing session MonSession: osd.1 :/0 is openallow * for osd.1 :/0
 -12-02 09:12:27.850163 7f2204239700 20 mon.a@0(probing) e1  caps allow *
 -12-02 09:12:27.850166 7f2204239700 10 mon.a@0(probing).paxosservice(pgmap 4043..4689) dispatch pg_stats(6 pgs tid 618 v 0) v1 from osd.1 10.214.138.162:6805/7218
 -12-02 09:12:27.850173 7f2204239700  5 mon.a@0(probing).paxos(paxos writing c 9288..9992) is_readable = 0 - now=2014-12-02 09:12:27.850174 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
 -12-02 09:12:27.850180 7f2204239700 10 mon.a@0(probing).paxosservice(pgmap 4043..4689)  waiting for paxos -> readable (v0)
 -12-02 09:12:27.850182 7f2204239700  5 mon.a@0(probing).paxos(paxos writing c 9288..9992) is_readable = 0 - now=2014-12-02 09:12:27.850183 lease_expire=2014-12-02 09:12:40.493609 has v0 lc 9992
       // Finisher handles next write in the queue.  It's a paxos proposal.
       // calls paxos::commit_finish()
       //
 -12-02 09:12:27.850200 7f220623e700 20 mon.a@0(probing).paxos(paxos writing c 9288..9992) commit_finish 9993
 -12-02 09:12:27.850298 7f220623e700 10 mon.a@0(probing) e1 refresh_from_paxos
 -12-02 09:12:27.850398 7f220623e700 10 mon.a@0(probing).paxosservice(pgmap 4043..4689) refresh
 -12-02 09:12:27.850441 7f220623e700 10 mon.a@0(probing).paxosservice(mdsmap 1..5) refresh
 -12-02 09:12:27.850476 7f220623e700 10 mon.a@0(probing).paxosservice(osdmap 1001..1701) refresh
 -12-02 09:12:27.850518 7f220623e700 10 mon.a@0(probing).paxosservice(logm 3020..3520) refresh
 -12-02 09:12:27.850523 7f220623e700 10 mon.a@0(probing).log v3520 update_from_paxos
 -12-02 09:12:27.850528 7f220623e700 10 mon.a@0(probing).log v3520 update_from_paxos version 3520 summary v 3520
 -12-02 09:12:27.850571 7f220623e700 10 mon.a@0(probing).paxosservice(monmap 1..1) refresh
 -12-02 09:12:27.850604 7f220623e700 10 mon.a@0(probing).paxosservice(auth 1..9) refresh
 -12-02 09:12:27.850607 7f220623e700 10 mon.a@0(probing).auth v9 update_from_paxos
 -12-02 09:12:27.850611 7f220623e700 10 mon.a@0(probing).pg v4689 map_pg_creates to 0 pgs -- no change
 -12-02 09:12:27.850613 7f220623e700 10 mon.a@0(probing).pg v4689 send_pg_creates to 0 pgs
       // Unfortunately, by now we have gone through monitor::_reset(),
       // state has changed and we're no longer the leader, and we will now assert.
       // Good-bye cruel world.  I'm leaving you today.
       //
 -12-02 09:12:27.850616 7f220623e700 10 mon.a@0(probing).paxos(paxos refresh c 9288..9993) commit_proposal
 -12-02 09:12:29.545042 7f2204239700  1 -- 10.214.138.162:6789/0 <== mds.0 10.214.138.162:6812/14611 367 ==== mdsbeacon(4103/a up:active seq 1718 v5) v2 ==== 279+0+0 (539925903 0 0) 0x5ac8dc0 con 0x400dac0
 -12-02 09:12:32.326224 7f220623e700 -1 mon/Paxos.cc: In function 'void Paxos::commit_proposal()' thread 7f220623e700 time 2014-12-02 09:12:27.850624
       mon/Paxos.cc: 1033: FAILED assert(mon->is_leader())
        ceph version 0.87-40-g65f6814 (65f6814847fe8644f5d77a9021fbf13043b76dbe)
 : (Paxos::commit_proposal()+0x348) [0x5ac4b8]
 : (Paxos::commit_finish()+0x62a) [0x5b4a2a]
 : (C_Committed::finish(int)+0x33) [0x5bc933]
 : (Context::complete(int)+0x9) [0x58df99]
 : (MonitorDBStore::C_DoTransaction::finish(int)+0x64) [0x5ba6d4]
 : (Context::complete(int)+0x9) [0x58df99]
 : (Finisher::finisher_thread_entry()+0x188) [0x816288]
 : (()+0x7851) [0x7f220b319851]
 : (clone()+0x6d) [0x7f220a2ab90d]
        NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

(1-1/1)

Project

General

Profile

Ceph

Bug #10220 » ceph-mon.a.log