Bug #3497
Updated by Joao Eduardo Luis over 11 years ago
<pre> -135> 2012-11-15 08:01:09.179382 a31a700 -1 *** Caught signal (Segmentation fault) ** in thread a31a700 ceph version 0.54-589-gd9bfbc1 (d9bfbc11160bd7b1d659b62238dbd0e4fd0204be) 1: ./ceph-mon() [0x53d10a] 2: (()+0xfcb0) [0x4e41cb0] 3: (SimpleMessenger::_send_message(Message*, Connection*, bool)+0x1d3) [0x5db373] 4: (Monitor::send_reply(PaxosServiceMessage*, Message*)+0x475) [0x477625] 5: (OSDMonitor::send_incremental(PaxosServiceMessage*, unsigned int)+0xc6) [0x4b1ad6] 6: (OSDMonitor::send_latest(PaxosServiceMessage*, unsigned int)+0x79) [0x4bc729] 7: (OSDMonitor::_booted(MOSDBoot*, bool)+0xd6) [0x4be076] 8: (Context::complete(int)+0xa) [0x48ee8a] 9: (finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int)+0x11d) [0x490cbd] 10: (Paxos::handle_accept(MMonPaxos*)+0x83a) [0x4a4c2a] 11: (Paxos::dispatch(PaxosServiceMessage*)+0x24b) [0x4a7d0b] 12: (Monitor::_ms_dispatch(Message*)+0xfb0) [0x48df90] 13: (Monitor::ms_dispatch(Message*)+0x32) [0x49dac2] 14: (DispatchQueue::entry()+0x349) [0x642019] 15: (DispatchQueue::DispatchThread::entry()+0xd) [0x5dc7ed] 16: (()+0x7e9a) [0x4e39e9a] 17: (clone()+0x6d) [0x64494bd] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. </pre> Unfortunately, most of the log (everything that didn't fit the terminal's buffer) is unavailable. Here's what was available: <pre> -555> 2012-11-15 08:01:07.943449 9b19700 10 mon.a@0(leader).osd e70 encode_pending e 71 -554> 2012-11-15 08:01:07.944266 9b19700 2 mon.a@0(leader).osd e70 osd.0 UP 127.0.0.1:6800/6325 -553> 2012-11-15 08:01:07.947744 9b19700 2 mon.a@0(leader).osd e70 osd.1 UP 127.0.0.1:6803/6576 -552> 2012-11-15 08:01:07.955651 9b19700 20 mon.a@0(leader) e1 get_global_paxos_version 324 -551> 2012-11-15 08:01:07.955768 9b19700 5 mon.a@0(leader).paxos(osdmap active c 1..70) propose_new_value 71 1040 bytes, gv 324 -550> 2012-11-15 08:01:07.955940 9b19700 10 mon.a@0(leader).paxos(osdmap active c 1..70) begin for 71 1040 bytes gv 324 -549> 2012-11-15 08:01:07.956203 9b19700 15 store(dev/mon.a) put_bl osdmap/71 = 1040 bytes -548> 2012-11-15 08:01:07.956488 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got MSG -547> 2012-11-15 08:01:07.956861 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got envelope type=66 src mon.2 front=88 data=0 off 0 -546> 2012-11-15 08:01:07.957240 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader wants 88 from dispatch throttler 0/104857600 -545> 2012-11-15 08:01:07.957678 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got front 88 -544> 2012-11-15 08:01:07.958048 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).aborted = 0 -543> 2012-11-15 08:01:07.958361 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got 88 + 0 + 0 byte message -542> 2012-11-15 08:01:07.958786 b222700 10 check_message_signature: seq # = 20 front_crc_ = 3785343319 middle_crc = 0 data_crc = 0 -541> 2012-11-15 08:01:07.959553 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got message 20 0xbcaf600 paxos(auth lease_ack lc 35 fc 13 pn 0 opn 0 gv {}) v2 -540> 2012-11-15 08:01:07.959998 b222700 20 -- 127.0.0.1:6789/0 queue 0xbcaf600 prio 196 -539> 2012-11-15 08:01:07.960293 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -538> 2012-11-15 08:01:07.960700 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -537> 2012-11-15 08:01:07.961052 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer encoding 2 0xbca1f00 auth_reply(proto 2 0 Success) v1 -536> 2012-11-15 08:01:07.961546 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sending 2 0xbca1f00 -535> 2012-11-15 08:01:07.961873 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).Put signature in client message (seq # 2): sig = 0 -534> 2012-11-15 08:01:07.962219 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).write_message 0xbca1f00 -533> 2012-11-15 08:01:07.962595 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -532> 2012-11-15 08:01:07.963182 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_ack 20 -531> 2012-11-15 08:01:07.963699 a31a700 1 -- 127.0.0.1:6789/0 <== mon.2 127.0.0.1:6791/0 20 ==== paxos(auth lease_ack lc 35 fc 13 pn 0 opn 0 gv {}) v2 ==== 88+0+0 (3785343319 0 0) 0xbcaf600 con 0x6826c60 -530> 2012-11-15 08:01:07.964261 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -529> 2012-11-15 08:01:07.964585 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sleeping -528> 2012-11-15 08:01:07.964949 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ACK -527> 2012-11-15 08:01:07.965317 b121700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ack seq 2 -526> 2012-11-15 08:01:07.965628 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -525> 2012-11-15 08:01:07.965973 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got MSG -524> 2012-11-15 08:01:07.966324 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got envelope type=17 src osd.1 front=158 data=0 off 0 -523> 2012-11-15 08:01:07.966720 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pg s=62 cs=1 l=1).reader wants 158 from policy throttler 1162/419430400 -522> 2012-11-15 08:01:07.967073 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pg s=62 cs=1 l=1).reader wants 158 from dispatch throttler 88/104857600 -521> 2012-11-15 08:01:07.967500 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -520> 2012-11-15 08:01:07.967838 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -519> 2012-11-15 08:01:07.968576 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got front 158 -518> 2012-11-15 08:01:07.968946 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).aborted = 0 -517> 2012-11-15 08:01:07.969253 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got 158 + 0 + 0 byte message -516> 2012-11-15 08:01:07.969693 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got message 2 0xbcbd630 auth(proto 2 128 bytes epoch 0) v1 -515> 2012-11-15 08:01:07.970072 b121700 20 -- 127.0.0.1:6789/0 queue 0xbcbd630 prio 127 -514> 2012-11-15 08:01:07.970270 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -513> 2012-11-15 08:01:07.970636 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -512> 2012-11-15 08:01:07.970998 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).write_ack 2 -511> 2012-11-15 08:01:07.971352 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -510> 2012-11-15 08:01:07.971665 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sleeping -509> 2012-11-15 08:01:08.181751 9b19700 15 store(dev/mon.a) set_int osdmap_gv/71 = 324 -508> 2012-11-15 08:01:08.328114 9b19700 10 mon.a@0(leader).paxos(osdmap updating c 1..70) sending begin to mon.2 -507> 2012-11-15 08:01:08.328358 9b19700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(osdmap begin lc 70 fc 0 pn 2100 opn 0 gv {71=324}) v2 -- ?+0 0xbcd0b50 -506> 2012-11-15 08:01:08.328775 9b19700 20 -- 127.0.0.1:6789/0 submit_message paxos(osdmap begin lc 70 fc 0 pn 2100 opn 0 gv {71=324}) v2 remote, 127.0.0.1:6791/0, have pipe. -505> 2012-11-15 08:01:08.329602 a31a700 20 mon.a@0(leader) e1 have connection -504> 2012-11-15 08:01:08.329722 a31a700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.2 127.0.0.1:6791/0 is openallow * for mon.2 127.0.0.1:6791/0 -503> 2012-11-15 08:01:08.330041 a31a700 20 mon.a@0(leader) e1 caps allow * -502> 2012-11-15 08:01:08.330164 a31a700 10 mon.a@0(leader).paxos(auth active c 15..35) handle_lease_ack from mon.2 -- got everyone -501> 2012-11-15 08:01:08.330349 a31a700 10 mon.a@0(leader).auth v35 update_from_paxos() -500> 2012-11-15 08:01:08.330489 a31a700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 88 to dispatch throttler 246/104857600 -499> 2012-11-15 08:01:08.330698 a31a700 20 -- 127.0.0.1:6789/0 done calling dispatch on 0xbcaf600 -498> 2012-11-15 08:01:08.330901 a31a700 1 -- 127.0.0.1:6789/0 <== osd.1 127.0.0.1:6803/6576 2 ==== auth(proto 2 128 bytes epoch 0) v1 ==== 158+0+0 (334118950 0 0) 0xbcbd630 con 0xba72d40 -497> 2012-11-15 08:01:08.331309 a31a700 20 mon.a@0(leader) e1 have connection -496> 2012-11-15 08:01:08.331413 a31a700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.1 127.0.0.1:6803/6576 is open for osd.1 127.0.0.1:6803/6576 -495> 2012-11-15 08:01:08.331722 a31a700 20 mon.a@0(leader) e1 caps -494> 2012-11-15 08:01:08.331825 a31a700 10 mon.a@0(leader).paxosservice(auth) dispatch auth(proto 2 128 bytes epoch 0) v1 from osd.1 127.0.0.1:6803/6576 -493> 2012-11-15 08:01:08.332076 a31a700 1 mon.a@0(leader).paxos(auth active c 15..35) is_readable now=2012-11-15 08:01:08.332119 lease_expire=2012-11-15 08:01:12.288658 has v0 lc 35 -492> 2012-11-15 08:01:08.332448 a31a700 10 mon.a@0(leader).auth v35 update_from_paxos() -491> 2012-11-15 08:01:08.332553 a31a700 10 mon.a@0(leader).auth v35 preprocess_query auth(proto 2 128 bytes epoch 0) v1 from osd.1 127.0.0.1:6803/6576 -490> 2012-11-15 08:01:08.332816 a31a700 10 mon.a@0(leader).auth v35 prep_auth() blob_size=128 -489> 2012-11-15 08:01:08.332982 a31a700 10 cephx server osd.1: handle_request get_auth_session_key for osd.1 -488> 2012-11-15 08:01:08.333660 a31a700 20 cephx server osd.1: checking key: req.key=c777cfde183185c8 expected_key=c777cfde183185c8 -487> 2012-11-15 08:01:08.334519 a31a700 10 cephx server osd.1: decoded old_ticket with global_id=5802 -486> 2012-11-15 08:01:08.334796 a31a700 10 cephx keyserverdata: get_service_secret service auth id 3 AQCQdaNQsGBqAhAAPKcHSBVozowpUuDCZZffNA== expires 2012-11-15 14:42:24.040361 -485> 2012-11-15 08:01:08.335357 a31a700 10 cephx: build_service_ticket_reply encoding 1 tickets with secret AQCidaNQyOLEEhAAHgHndtIdkI3t9OCy40HfTA== -484> 2012-11-15 08:01:08.336202 a31a700 10 cephx: build_service_ticket service auth secret_id 3 ticket_info.ticket.name=osd.1 -483> 2012-11-15 08:01:08.336921 a31a700 20 cephx: service_ticket_blob is 0000 : 01 03 00 00 00 00 00 00 00 60 00 00 00 eb 39 e2 : .........`....9. 0010 : 24 5c a0 78 f1 51 b3 13 e9 15 07 97 c2 1d 60 4c : $\.x.Q........`L 0020 : 65 64 eb c4 be 8c a6 05 a6 9a 4c fd 97 18 21 2c : ed........L...!, 0030 : e6 07 fa 10 d8 91 6f df 79 62 e5 98 52 d9 a9 6a : ......o.yb..R..j 0040 : 6b 1b e7 6d 6c 1e e4 9e 1a 69 2e b8 48 5f b0 c1 : k..ml....i..H_.. 0050 : 07 5c 85 56 a7 df 9d c6 0f 8c 83 8b 44 c1 b5 c6 : .\.V........D... 0060 : e2 c4 b2 e5 3f 3f ea 1f 6e 7b da 4d 24 : ....??..n{.M$ -482> 2012-11-15 08:01:08.339274 a31a700 10 cephx keyserverdata: get_caps: name=osd.1 -481> 2012-11-15 08:01:08.339350 a31a700 10 cephx keyserverdata: get_secret: num of caps=2 -480> 2012-11-15 08:01:08.339695 a31a700 1 -- 127.0.0.1:6789/0 --> 127.0.0.1:6803/6576 -- auth_reply(proto 2 0 Success) v1 -- ?+0 0xbcf58e0 con 0xba72d40 -479> 2012-11-15 08:01:08.340066 a31a700 20 -- 127.0.0.1:6789/0 submit_message auth_reply(proto 2 0 Success) v1 remote, 127.0.0.1:6803/6576, have pipe. -478> 2012-11-15 08:01:08.340468 a31a700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 158 to dispatch throttler 158/104857600 -477> 2012-11-15 08:01:08.340675 a31a700 20 -- 127.0.0.1:6789/0 done calling dispatch on 0xbcbd630 -476> 2012-11-15 08:01:08.341227 9b19700 10 mon.a@0(leader).paxosservice(logm) propose_pending -475> 2012-11-15 08:01:08.341332 9b19700 10 mon.a@0(leader).log v115 encode_pending v 116 -474> 2012-11-15 08:01:08.341848 9b19700 20 mon.a@0(leader) e1 get_global_paxos_version 325 -473> 2012-11-15 08:01:08.341957 9b19700 5 mon.a@0(leader).paxos(logm active c 1..115) propose_new_value 116 1579 bytes, gv 325 -472> 2012-11-15 08:01:08.342127 9b19700 10 mon.a@0(leader).paxos(logm active c 1..115) begin for 116 1579 bytes gv 325 -471> 2012-11-15 08:01:08.342384 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -470> 2012-11-15 08:01:08.342772 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer encoding 3 0xbcf58e0 auth_reply(proto 2 0 Success) v1 -469> 2012-11-15 08:01:08.343284 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sending 3 0xbcf58e0 -468> 2012-11-15 08:01:08.343610 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).Put signature in client message (seq # 3): sig = 0 -467> 2012-11-15 08:01:08.343955 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).write_message 0xbcf58e0 -466> 2012-11-15 08:01:08.344370 9b19700 15 store(dev/mon.a) put_bl logm/116 = 1579 bytes -465> 2012-11-15 08:01:08.344552 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -464> 2012-11-15 08:01:08.344960 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer encoding 1970736226 0xbcd0b50 paxos(osdmap begin lc 70 fc 0 pn 2100 opn 0 gv {71=324}) v2 -463> 2012-11-15 08:01:08.345554 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sending 1970736226 0xbcd0b50 -462> 2012-11-15 08:01:08.345960 ac1c700 10 sign_message: seq # 1970736226 CRCs are: header 3838740135 front 3108178450 middle 0 data 0 -461> 2012-11-15 08:01:08.346571 ac1c700 20 Putting signature in client message(seq # 1970736226): sig = 15571391595183978041 -460> 2012-11-15 08:01:08.346705 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).Put signature in client message (seq # 1970736226): sig = 15571391595183978041 -459> 2012-11-15 08:01:08.347064 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_message 0xbcd0b50 -458> 2012-11-15 08:01:08.347523 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -457> 2012-11-15 08:01:08.347857 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -456> 2012-11-15 08:01:08.348273 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -455> 2012-11-15 08:01:08.348598 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sleeping -454> 2012-11-15 08:01:08.349032 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ACK -453> 2012-11-15 08:01:08.349656 b121700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ack seq 3 -452> 2012-11-15 08:01:08.349984 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -451> 2012-11-15 08:01:08.350328 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got MSG -450> 2012-11-15 08:01:08.350675 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got envelope type=15 src osd.1 front=50 data=0 off 0 -449> 2012-11-15 08:01:08.351043 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 50 from policy throttler 1162/419430400 -448> 2012-11-15 08:01:08.351391 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 50 from dispatch throttler 0/104857600 -447> 2012-11-15 08:01:08.351811 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got front 50 -446> 2012-11-15 08:01:08.352166 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).aborted = 0 -445> 2012-11-15 08:01:08.352471 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got 50 + 0 + 0 byte message -444> 2012-11-15 08:01:08.353033 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got message 3 0xbcdf410 mon_subscribe({monmap=2+,osd_pg_creates=0}) v2 -443> 2012-11-15 08:01:08.353458 b121700 20 -- 127.0.0.1:6789/0 queue 0xbcdf410 prio 127 -442> 2012-11-15 08:01:08.353712 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -441> 2012-11-15 08:01:08.354117 a31a700 1 -- 127.0.0.1:6789/0 <== osd.1 127.0.0.1:6803/6576 3 ==== mon_subscribe({monmap=2+,osd_pg_creates=0}) v2 ==== 50+0+0 (3889722309 0 0) 0xbcdf410 con 0xba72d40 -440> 2012-11-15 08:01:08.354631 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -439> 2012-11-15 08:01:08.355031 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).write_ack 3 -438> 2012-11-15 08:01:08.355453 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got MSG -437> 2012-11-15 08:01:08.355857 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got envelope type=19 src osd.1 front=18 data=0 off 0 -436> 2012-11-15 08:01:08.356227 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 18 from policy throttler 1212/419430400 -435> 2012-11-15 08:01:08.356576 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 18 from dispatch throttler 50/104857600 -434> 2012-11-15 08:01:08.356996 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got front 18 -433> 2012-11-15 08:01:08.357352 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).aborted = 0 -432> 2012-11-15 08:01:08.357658 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got 18 + 0 + 0 byte message -431> 2012-11-15 08:01:08.358061 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got message 4 0xbcd8630 mon_get_version(what=osdmap handle=7) v1 -430> 2012-11-15 08:01:08.358419 b121700 20 -- 127.0.0.1:6789/0 queue 0xbcd8630 prio 127 -429> 2012-11-15 08:01:08.358616 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -428> 2012-11-15 08:01:08.358963 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got MSG -427> 2012-11-15 08:01:08.359311 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got envelope type=19 src osd.1 front=18 data=0 off 0 -426> 2012-11-15 08:01:08.359690 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 18 from policy throttler 1230/419430400 -425> 2012-11-15 08:01:08.360037 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 18 from dispatch throttler 68/104857600 -424> 2012-11-15 08:01:08.360455 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got front 18 -423> 2012-11-15 08:01:08.360812 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).aborted = 0 -422> 2012-11-15 08:01:08.361118 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got 18 + 0 + 0 byte message -421> 2012-11-15 08:01:08.361515 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got message 5 0xbd0aa30 mon_get_version(what=osdmap handle=8) v1 -420> 2012-11-15 08:01:08.361869 b121700 20 -- 127.0.0.1:6789/0 queue 0xbd0aa30 prio 127 -419> 2012-11-15 08:01:08.362047 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -418> 2012-11-15 08:01:08.362667 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -417> 2012-11-15 08:01:08.363081 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).write_ack 5 -416> 2012-11-15 08:01:08.363430 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -415> 2012-11-15 08:01:08.363743 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sleeping -414> 2012-11-15 08:01:08.398737 9b19700 15 store(dev/mon.a) set_int logm_gv/116 = 325 -413> 2012-11-15 08:01:08.446992 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ACK -412> 2012-11-15 08:01:08.447383 b222700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736226 -411> 2012-11-15 08:01:08.447707 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736226 >= 1970736226 on 0xbcd0b50 paxos(osdmap begin lc 70 fc 0 pn 2100 opn 0 gv {71=324}) v2 -410> 2012-11-15 08:01:08.448207 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -409> 2012-11-15 08:01:08.448555 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got MSG -408> 2012-11-15 08:01:08.448903 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got envelope type=66 src mon.2 front=88 data=0 off 0 -407> 2012-11-15 08:01:08.449449 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader wants 88 from dispatch throttler 86/104857600 -406> 2012-11-15 08:01:08.450008 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got front 88 -405> 2012-11-15 08:01:08.450372 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).aborted = 0 -404> 2012-11-15 08:01:08.450684 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got 88 + 0 + 0 byte message -403> 2012-11-15 08:01:08.451115 b222700 10 check_message_signature: seq # = 21 front_crc_ = 3601163831 middle_crc = 0 data_crc = 0 -402> 2012-11-15 08:01:08.451849 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got message 21 0xbd15170 paxos(pgmap accept lc 95 fc 0 pn 2100 opn 0 gv {}) v2 -401> 2012-11-15 08:01:08.452292 b222700 20 -- 127.0.0.1:6789/0 queue 0xbd15170 prio 196 -400> 2012-11-15 08:01:08.452502 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -399> 2012-11-15 08:01:08.452875 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -398> 2012-11-15 08:01:08.453241 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_ack 21 -397> 2012-11-15 08:01:08.453599 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -396> 2012-11-15 08:01:08.453915 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -395> 2012-11-15 08:01:08.485548 9b19700 10 mon.a@0(leader).paxos(logm updating c 1..115) sending begin to mon.2 -394> 2012-11-15 08:01:08.485791 9b19700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(logm begin lc 115 fc 0 pn 2100 opn 0 gv {116=325}) v2 -- ?+0 0xbd1f8d0 -393> 2012-11-15 08:01:08.486199 9b19700 20 -- 127.0.0.1:6789/0 submit_message paxos(logm begin lc 115 fc 0 pn 2100 opn 0 gv {116=325}) v2 remote, 127.0.0.1:6791/0, have pipe. -392> 2012-11-15 08:01:08.486741 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -391> 2012-11-15 08:01:08.487171 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer encoding 1970736227 0xbd1f8d0 paxos(logm begin lc 115 fc 0 pn 2100 opn 0 gv {116=325}) v2 -390> 2012-11-15 08:01:08.487778 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sending 1970736227 0xbd1f8d0 -389> 2012-11-15 08:01:08.488157 ac1c700 10 sign_message: seq # 1970736227 CRCs are: header 2446227596 front 1879241916 middle 0 data 0 -388> 2012-11-15 08:01:08.488760 ac1c700 20 Putting signature in client message(seq # 1970736227): sig = 1489877203497555154 -387> 2012-11-15 08:01:08.488871 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).Put signature in client message (seq # 1970736227): sig = 1489877203497555154 -386> 2012-11-15 08:01:08.489216 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_message 0xbd1f8d0 -385> 2012-11-15 08:01:08.489829 a31a700 20 mon.a@0(leader) e1 have connection -384> 2012-11-15 08:01:08.489955 a31a700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: osd.1 127.0.0.1:6803/6576 is openallow rwx for osd.1 127.0.0.1:6803/6576 -383> 2012-11-15 08:01:08.490282 a31a700 20 mon.a@0(leader) e1 caps allow rwx -382> 2012-11-15 08:01:08.490386 a31a700 10 mon.a@0(leader) e1 handle_subscribe mon_subscribe({monmap=2+,osd_pg_creates=0}) v2 -381> 2012-11-15 08:01:08.490647 a31a700 10 mon.a@0(leader) e1 check_sub monmap next 2 have 1 -380> 2012-11-15 08:01:08.490857 a31a700 1 -- 127.0.0.1:6789/0 --> osd.1 127.0.0.1:6803/6576 -- mon_subscribe_ack(300s) v1 -- ?+0 0xbd27e10 -379> 2012-11-15 08:01:08.491180 a31a700 20 -- 127.0.0.1:6789/0 submit_message mon_subscribe_ack(300s) v1 remote, 12 7.0.0.1:6803/6576, have pipe. -378> 2012-11-15 08:01:08.491599 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -377> 2012-11-15 08:01:08.492027 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -376> 2012-11-15 08:01:08.492410 a31a700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 50 to dispatch throttler 174/104857600 -375> 2012-11-15 08:01:08.492630 a31a700 20 -- 127.0.0.1:6789/0 done calling dispatch on 0xbcdf410 -374> 2012-11-15 08:01:08.492911 a31a700 1 -- 127.0.0.1:6789/0 <== mon.2 127.0.0.1:6791/0 21 ==== paxos(pgmap accept lc 95 fc 0 pn 2100 opn 0 gv {}) v2 ==== 88+0+0 (3601163831 0 0) 0xbd15170 con 0x6826c60 -373> 2012-11-15 08:01:08.493364 a31a700 20 mon.a@0(leader) e1 have connection -372> 2012-11-15 08:01:08.493478 a31a700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.2 127.0.0.1:6791/0 is openallow * for mon.2 127.0.0.1:6791/0 -371> 2012-11-15 08:01:08.493784 a31a700 20 mon.a@0(leader) e1 caps allow * -370> 2012-11-15 08:01:08.493888 a31a700 10 mon.a@0(leader).paxos(pgmap updating c 1..95) handle_accept paxos(pgmap accept lc 95 fc 0 pn 2100 opn 0 gv {}) v2 -369> 2012-11-15 08:01:08.494121 a31a700 10 mon.a@0(leader).paxos(pgmap updating c 1..95) now 0,2 have accepted -368> 2012-11-15 08:01:08.494270 a31a700 10 mon.a@0(leader).paxos(pgmap updating c 1..95) got majority, committing -367> 2012-11-15 08:01:08.494392 a31a700 10 mon.a@0(leader).paxos(pgmap updating c 1..95) commit 96 -366> 2012-11-15 08:01:08.494581 a31a700 15 store(dev/mon.a) set_int pgmap/last_committed = 96 -365> 2012-11-15 08:01:08.495135 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -364> 2012-11-15 08:01:08.495522 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer encoding 4 0xbd27e10 mon_subscribe_ack(300s) v1 -363> 2012-11-15 08:01:08.495930 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sending 4 0xbd27e10 -362> 2012-11-15 08:01:08.496260 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).Put signature in client message (seq # 4): sig = 0 -361> 2012-11-15 08:01:08.496588 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).write_message 0xbd27e10 -360> 2012-11-15 08:01:08.497006 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -359> 2012-11-15 08:01:08.497327 b020700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer sleeping -358> 2012-11-15 08:01:08.539116 a31a700 10 mon.a@0(leader).paxos(pgmap updating c 1..96) sending commit to mon.2 -357> 2012-11-15 08:01:08.539854 a31a700 15 store(dev/mon.a) get_int pgmap_gv/96 = 322 -356> 2012-11-15 08:01:08.539988 a31a700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(pgmap commit lc 96 fc 0 pn 2100 opn 0 gv {96=322}) v2 -- ?+0 0xbd32970 -355> 2012-11-15 08:01:08.540397 a31a700 20 -- 127.0.0.1:6789/0 submit_message paxos(pgmap commit lc 96 fc 0 pn 2100 opn 0 gv {96=322}) v2 remote, 127.0.0.1:6791/0, have pipe. -354> 2012-11-15 08:01:08.540797 a31a700 10 mon.a@0(leader).paxos(pgmap updating c 1..96) got quorum, done with update -353> 2012-11-15 08:01:08.540984 a31a700 7 mon.a@0(leader).paxos(pgmap active c 1..96) extend_lease now+5 (2012-11-15 08:01:13.540954) -352> 2012-11-15 08:01:08.541353 a31a700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(pgmap lease lc 96 fc 1 pn 0 opn 0 gv {}) v2 -- ?+0 0xbd33780 -351> 2012-11-15 08:01:08.541721 a31a700 20 -- 127.0.0.1:6789/0 submit_message paxos(pgmap lease lc 96 fc 1 pn 0 opn 0 gv {}) v2 remote, 127.0.0.1:6791/0, have pipe. -350> 2012-11-15 08:01:08.542646 a31a700 10 mon.a@0(leader).paxosservice(pgmap) _active -349> 2012-11-15 08:01:08.543959 a31a700 20 store(dev/mon.a) reading at off 0 of 8014 -348> 2012-11-15 08:01:08.544138 a31a700 15 store(dev/mon.a) get_bl pgmap/96 = 8014 bytes -347> 2012-11-15 08:01:08.545177 a31a700 7 mon.a@0(leader).pg v95 update_from_paxos applying incremental 96 -346> 2012-11-15 08:01:08.590164 a31a700 10 mon.a@0(leader).pg v96 v96: 24 pgs: 16 stale+active+clean, 8 stale+active+clean+replay; 8730 bytes data, 90650 MB used, 780 GB / 914 GB avail -345> 2012-11-15 08:01:08.608186 a31a700 10 mon.a@0(leader).paxos(pgmap active c 1..96) stash_latest v96 len 8114 -344> 2012-11-15 08:01:08.608438 a31a700 15 store(dev/mon.a) put_bl pgmap/latest = 8126 bytes -343> 2012-11-15 08:01:08.608659 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -342> 2012-11-15 08:01:08.609062 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer encoding 1970736228 0xbd32970 paxos(pgmap commit lc 96 fc 0 pn 2100 opn 0 gv {96=322}) v2 -341> 2012-11-15 08:01:08.609766 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sending 1970736228 0xbd32970 -340> 2012-11-15 08:01:08.610146 ac1c700 10 sign_message: seq # 1970736228 CRCs are: header 3101099573 front 214078119 middle 0 data 0 -339> 2012-11-15 08:01:08.610800 ac1c700 20 Putting signature in client message(seq # 1970736228): sig = 11233297914615331554 -338> 2012-11-15 08:01:08.610931 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).Put signature in client message (seq # 1970736228): sig = 11233297914615331554 -337> 2012-11-15 08:01:08.611296 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_message 0xbd32970 -336> 2012-11-15 08:01:08.611772 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -335> 2012-11-15 08:01:08.612295 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer encoding 1970736229 0xbd33780 paxos(pgmap lease lc 96 fc 1 pn 0 opn 0 gv {}) v2 -334> 2012-11-15 08:01:08.613146 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sending 1970736229 0xbd33780 -333> 2012-11-15 08:01:08.613782 ac1c700 10 sign_message: seq # 1970736229 CRCs are: header 628391017 front 4002913315 middle 0 data 0 -332> 2012-11-15 08:01:08.614455 ac1c700 20 Putting signature in client message(seq # 1970736229): sig = 417341696389127876 -331> 2012-11-15 08:01:08.614566 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).Put signature in client message (seq # 1970736229): sig = 417341696389127876 -330> 2012-11-15 08:01:08.614999 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_message 0xbd33780 -329> 2012-11-15 08:01:08.615425 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -328> 2012-11-15 08:01:08.615953 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -327> 2012-11-15 08:01:08.616988 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ACK -326> 2012-11-15 08:01:08.617363 b222700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736227 -325> 2012-11-15 08:01:08.617688 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736227 >= 1970736227 on 0xbd1f8d0 paxos(logm begin lc 115 fc 0 pn 2100 opn 0 gv {116=325}) v2 -324> 2012-11-15 08:01:08.618187 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -323> 2012-11-15 08:01:08.618538 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got MSG -322> 2012-11-15 08:01:08.618887 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got envelope type=66 src mon.2 front=88 data=0 off 0 -321> 2012-11-15 08:01:08.619263 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader wants 88 from dispatch throttler 124/104857600 -320> 2012-11-15 08:01:08.619692 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got front 88 -319> 2012-11-15 08:01:08.620058 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).aborted = 0 -318> 2012-11-15 08:01:08.620369 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got 88 + 0 + 0 byte message -317> 2012-11-15 08:01:08.620794 b222700 10 check_message_signature: seq # = 22 front_crc_ = 3209528496 middle_crc = 0 data_crc = 0 -316> 2012-11-15 08:01:08.621524 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got message 22 0xbd44b10 paxos(mdsmap accept lc 5 fc 0 pn 2100 opn 0 gv {}) v2 -315> 2012-11-15 08:01:08.621969 b222700 20 -- 127.0.0.1:6789/0 queue 0xbd44b10 prio 196 -314> 2012-11-15 08:01:08.622180 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -313> 2012-11-15 08:01:08.622546 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -312> 2012-11-15 08:01:08.622961 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_ack 22 -311> 2012-11-15 08:01:08.623345 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -310> 2012-11-15 08:01:08.623659 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -309> 2012-11-15 08:01:08.679370 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ACK -308> 2012-11-15 08:01:08.679762 b222700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736228 -307> 2012-11-15 08:01:08.680077 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736228 >= 1970736228 on 0xbd32970 paxos(pgmap commit lc 96 fc 0 pn 2100 opn 0 gv {96=322}) v2 -306> 2012-11-15 08:01:08.680594 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -305> 2012-11-15 08:01:08.680943 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ACK -304> 2012-11-15 08:01:08.681290 b222700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736229 -303> 2012-11-15 08:01:08.681601 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got ack seq 1970736229 >= 1970736229 on 0xbd33780 paxos(pgmap lease lc 96 fc 1 pn 0 opn 0 gv {}) v2 -302> 2012-11-15 08:01:08.682050 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -301> 2012-11-15 08:01:08.682396 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got MSG -300> 2012-11-15 08:01:08.682745 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got envelope type=66 src mon.2 front=88 data=0 off 0 -299> 2012-11-15 08:01:08.683160 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader wants 88 from dispatch throttler 212/104857600 -298> 2012-11-15 08:01:08.683597 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got front 88 -297> 2012-11-15 08:01:08.683982 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).aborted = 0 -296> 2012-11-15 08:01:08.684295 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got 88 + 0 + 0 byte message -295> 2012-11-15 08:01:08.684715 b222700 10 check_message_signature: seq # = 23 front_crc_ = 1618783307 middle_crc = 0 data_crc = 0 -294> 2012-11-15 08:01:08.685474 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader got message 23 0xbd68790 paxos(osdmap accept lc 70 fc 0 pn 2100 opn 0 gv {}) v2 -293> 2012-11-15 08:01:08.685927 b222700 20 -- 127.0.0.1:6789/0 queue 0xbd68790 prio 196 -292> 2012-11-15 08:01:08.686112 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader reading tag... -291> 2012-11-15 08:01:08.686486 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -290> 2012-11-15 08:01:08.686891 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).write_ack 23 -289> 2012-11-15 08:01:08.687289 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = open policy.server=0 -288> 2012-11-15 08:01:08.687605 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -287> 2012-11-15 08:01:08.698700 a31a700 10 mon.a@0(leader).pg v96 send_pg_creates to 0 pgs -286> 2012-11-15 08:01:08.698859 a31a700 10 mon.a@0(leader).pg v96 update_logger -285> 2012-11-15 08:01:08.699036 a31a700 7 mon.a@0(leader).paxosservice(pgmap) _active creating new pending -284> 2012-11-15 08:01:08.699319 a31a700 10 mon.a@0(leader).pg v96 create_pending v 97 -283> 2012-11-15 08:01:08.699436 a31a700 10 mon.a@0(leader).pg v96 check_osd_map already seen 70 >= 70 -282> 2012-11-15 08:01:08.699550 a31a700 10 mon.a@0(leader).pg v96 update_logger -281> 2012-11-15 08:01:08.700328 a31a700 0 log [INF] : pgmap v96: 24 pgs: 16 stale+active+clean, 8 stale+active+clean+replay; 8730 bytes data, 90650 MB used, 780 GB / 914 GB avail -280> 2012-11-15 08:01:08.700431 a31a700 10 send_log to self -279> 2012-11-15 08:01:08.700481 a31a700 10 log_queue is 8 last_log 15 sent 13 num 8 unsent 2 sending 2 -278> 2012-11-15 08:01:08.700613 a31a700 10 will send 2012-11-15 08:01:07.661098 mon.0 127.0.0.1:6789/0 13 : [INF] osdmap e70: 2 osds: 0 up, 2 in -277> 2012-11-15 08:01:08.700923 a31a700 10 will send 2012-11-15 08:01:07.669739 mon.0 127.0.0.1:6789/0 14 : [INF] monmap e1: 3 mons at {a=127.0.0.1:6789/0,b=127.0.0.1:6790/0,c=127.0.0.1:6791/0} -276> 2012-11-15 08:01:08.701242 a31a700 1 -- 127.0.0.1:6789/0 --> mon.0 127.0.0.1:6789/0 -- log(2 entries) v1 -- ?+0 0xbd76a20 -275> 2012-11-15 08:01:08.701561 a31a700 20 -- 127.0.0.1:6789/0 submit_message log(2 entries) v1 local -274> 2012-11-15 08:01:08.703379 a31a700 10 mon.a@0(leader).pg v96 check_osd_map already seen 70 >= 70 -273> 2012-11-15 08:01:08.703719 a31a700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 88 to dispatch throttler 300/104857600 -272> 2012-11-15 08:01:08.703939 a31a700 20 -- 127.0.0.1:6789/0 done calling dispatch on 0xbd15170 -271> 2012-11-15 08:01:08.704142 a31a700 1 -- 127.0.0.1:6789/0 <== mon.2 127.0.0.1:6791/0 22 ==== paxos(mdsmap accept lc 5 fc 0 pn 2100 opn 0 gv {}) v2 ==== 88+0+0 (3209528496 0 0) 0xbd44b10 con 0x6826c60 -270> 2012-11-15 08:01:08.704594 a31a700 20 mon.a@0(leader) e1 have connection -269> 2012-11-15 08:01:08.704701 a31a700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.2 127.0.0.1:6791/0 is openallow * for mon.2 127.0.0.1:6791/0 -268> 2012-11-15 08:01:08.705012 a31a700 20 mon.a@0(leader) e1 caps allow * -267> 2012-11-15 08:01:08.705116 a31a700 10 mon.a@0(leader).paxos(mdsmap updating c 1..5) handle_accept paxos(mdsmap accept lc 5 fc 0 pn 2100 opn 0 gv {}) v2 -266> 2012-11-15 08:01:08.705350 a31a700 10 mon.a@0(leader).paxos(mdsmap updating c 1..5) now 0,2 have accepted -265> 2012-11-15 08:01:08.705498 a31a700 10 mon.a@0(leader).paxos(mdsmap updating c 1..5) got majority, committing 2012-11-15 08:01:11.402368 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=18 :6789 pgs=8 cs=2 l=0).fault done waiting or woke up 2012-11-15 08:01:11.402734 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=18 :6789 pgs=8 cs=2 l=0).writer: state = connecting policy.server=0 2012-11-15 08:01:11.403067 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=18 :6789 pgs=8 cs=2 l=0).connect 2 2012-11-15 08:01:11.403419 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=18 :6789 pgs=8 cs=2 l=0).connecting to 127.0.0.1:6791/0 2012-11-15 08:01:11.403894 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=18 :6789 pgs=8 cs=2 l=0).connect error 127.0.0.1:6791/0, 111: Connection refused 2012-11-15 08:01:11.404316 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=18 :6789 pgs=8 cs=2 l=0).fault 111: Connection refused 2012-11-15 08:01:11.404660 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=18 :6789 pgs=8 cs=2 l=0).fault waiting 3.200000 -264> 2012-11-15 08:01:08.705627 a31a700 10 mon.a@0(leader).paxos(mdsmap updating c 1..5) commit 6 -270> 2012-11-15 08:01:08.705816 a31a700 15 store(dev/mon.a) set_int mdsmap/last_committed = 6 -269> 2012-11-15 08:01:08.708794 b222700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader couldn't read tag, Transport endpoint is not connected -268> 2012-11-15 08:01:08.709256 b222700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).fault 107: Transport endpoint is not connected -267> 2012-11-15 08:01:08.709654 b222700 0 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).fault with nothing to send, going to standby cs=1 l=0).fault with nothing to send, going to standby -266> 2012-11-15 08:01:08.709958 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader sleeping during reconnect|standby -265> 2012-11-15 08:01:08.710444 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = standby policy.server=0 -264> 2012-11-15 08:01:08.710786 ac1c700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer sleeping -263> 2012-11-15 08:01:08.712991 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ACK -262> 2012-11-15 08:01:08.713379 b121700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ack seq 4 -261> 2012-11-15 08:01:08.713690 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -260> 2012-11-15 08:01:08.740593 a31a700 10 mon.a@0(leader).paxos(mdsmap updating c 1..6) sending commit to mon.2 -259> 2012-11-15 08:01:08.741330 a31a700 15 store(dev/mon.a) get_int mdsmap_gv/6 = 323 -258> 2012-11-15 08:01:08.741458 a31a700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(mdsmap commit lc 6 fc 0 pn 2100 opn 0 gv {6=323}) v2 -- ?+0 0xbd7b5f0 -257> 2012-11-15 08:01:08.741860 a31a700 20 -- 127.0.0.1:6789/0 submit_message paxos(mdsmap commit lc 6 fc 0 pn 2100 opn 0 gv {6=323}) v2 remote, 127.0.0.1:6791/0, have pipe. -256> 2012-11-15 08:01:08.742270 a31a700 10 mon.a@0(leader).paxos(mdsmap updating c 1..6) got quorum, done with update -255> 2012-11-15 08:01:08.742463 a31a700 7 mon.a@0(leader).paxos(mdsmap active c 1..6) extend_lease now+5 (2012-11-15 08:01:13.742434) -254> 2012-11-15 08:01:08.742828 a31a700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(mdsmap lease lc 6 fc 1 pn 0 opn 0 gv {}) v2 -- ?+0 0xbd7c3a0 -253> 2012-11-15 08:01:08.743214 a31a700 20 -- 127.0.0.1:6789/0 submit_message paxos(mdsmap lease lc 6 fc 1 pn 0 opn 0 gv {}) v2 remote, 127.0.0.1:6791/0, have pipe. -252> 2012-11-15 08:01:08.743607 a31a700 10 mon.a@0(leader).paxosservice(mdsmap) _active -251> 2012-11-15 08:01:08.743701 a31a700 10 mon.a@0(leader).mds e5 update_from_paxos paxosv 6, my e 5 -250> 2012-11-15 08:01:08.743952 a31a700 20 store(dev/mon.a) reading at off 0 of 511 -249> 2012-11-15 08:01:08.744099 a31a700 15 store(dev/mon.a) get_bl mdsmap/6 = 511 bytes -248> 2012-11-15 08:01:08.744189 a31a700 10 mon.a@0(leader).mds e5 update_from_paxos got 6 -247> 2012-11-15 08:01:08.744829 a31a700 10 mon.a@0(leader).paxos(mdsmap active c 1..6) stash_latest v6 len 511 -246> 2012-11-15 08:01:08.745037 a31a700 15 store(dev/mon.a) put_bl mdsmap/latest = 523 bytes -245> 2012-11-15 08:01:08.745500 b222700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).reader sleeping during reconnect|standby -244> 2012-11-15 08:01:08.746171 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=1 l=0).writer: state = standby policy.server=0 -243> 2012-11-15 08:01:08.746545 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connect 2 -242> 2012-11-15 08:01:08.747578 b222700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).reader done -241> 2012-11-15 08:01:08.748311 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connecting to 127.0.0.1:6791/0 -240> 2012-11-15 08:01:08.749056 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connect error 127.0.0.1:6791/0, 111: Connection refused -239> 2012-11-15 08:01:08.749507 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).fault 111: Connection refused -238> 2012-11-15 08:01:08.749876 ac1c700 0 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).fault -237> 2012-11-15 08:01:08.750189 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).writer: state = connecting policy.server=0 -236> 2012-11-15 08:01:08.750500 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connect 2 -235> 2012-11-15 08:01:08.750843 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connecting to 127.0.0.1:6791/0 -234> 2012-11-15 08:01:08.751501 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connect error 127.0.0.1:6791/0, 111: Connection refused -233> 2012-11-15 08:01:08.751929 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).fault 111: Connection refused -232> 2012-11-15 08:01:08.752294 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).fault waiting 0.200000 -231> 2012-11-15 08:01:08.774383 a31a700 4 mon.a@0(leader).mds e6 new map -230> 2012-11-15 08:01:08.774526 a31a700 7 mon.a@0(leader).mds e6 print_map epoch 6 flags 0 created 2012-11-14 02:42:14.333454 modified 2012-11-15 08:01:07.533957 tableserver 0 root 0 session_timeout 60 session_autoclose 300 last_failure 0 last_failure_osd_epoch 0 compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object} max_mds 1 in 0 up {0=4105} failed stopped data_pools [0] metadata_pool 1 4105: 127.0.0.1:6806/13611 'a' mds.0.1 up:active seq 74 laggy since 2012-11-15 08:01:07.511428 -229> 2012-11-15 08:01:08.784579 a31a700 10 mon.a@0(leader).mds e6 update_logger -228> 2012-11-15 08:01:08.784711 a31a700 7 mon.a@0(leader).paxosservice(mdsmap) _active creating new pending -227> 2012-11-15 08:01:08.784936 a31a700 10 mon.a@0(leader).mds e6 create_pending e7 -226> 2012-11-15 08:01:08.785051 a31a700 10 mon.a@0(leader).mds e6 e6: 1/1/1 up {0=a=up:active(laggy or crashed)} -225> 2012-11-15 08:01:08.785484 a31a700 10 mon.a@0(leader).mds e6 adding 127.0.0.1:6806/13611 mds.0.1 up:active to last_beacon -224> 2012-11-15 08:01:08.785755 a31a700 10 mon.a@0(leader).mds e6 update_logger -223> 2012-11-15 08:01:08.786154 a31a700 0 log [INF] : mdsmap e6: 1/1/1 up {0=a=up:active(laggy or crashed)} -222> 2012-11-15 08:01:08.786238 a31a700 10 send_log to self -221> 2012-11-15 08:01:08.786285 a31a700 10 log_queue is 9 last_log 16 sent 14 num 9 unsent 2 sending 2 -220> 2012-11-15 08:01:08.786411 a31a700 10 will send 2012-11-15 08:01:07.669739 mon.0 127.0.0.1:6789/0 14 : [INF] monmap e1: 3 mons at {a=127.0.0.1:6789/0,b=127.0.0.1:6790/0,c=127.0.0.1:6791/0} -219> 2012-11-15 08:01:08.786716 a31a700 10 will send 2012-11-15 08:01:08.700418 mon.0 127.0.0.1:6789/0 15 : [INF] pgmap v96: 24 pgs: 16 stale+active+clean, 8 stale+active+clean+replay; 8730 bytes data, 90650 MB used, 780 GB / 914 GB avail -218> 2012-11-15 08:01:08.787045 a31a700 1 -- 127.0.0.1:6789/0 --> mon.0 127.0.0.1:6789/0 -- log(2 entries) v1 -- ?+0 0xbd86310 -217> 2012-11-15 08:01:08.787350 a31a700 20 -- 127.0.0.1:6789/0 submit_message log(2 entries) v1 local -216> 2012-11-15 08:01:08.787595 a31a700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 88 to dispatch throttler 212/104857600 -215> 2012-11-15 08:01:08.787802 a31a700 20 -- 127.0.0.1:6789/0 done calling dispatch on 0xbd44b10 -214> 2012-11-15 08:01:08.787993 a31a700 1 -- 127.0.0.1:6789/0 <== mon.0 127.0.0.1:6789/0 0 ==== log(2 entries) v1 ==== 0+0+0 (0 0 0) 0xbd76a20 con 0x67d61c0 -213> 2012-11-15 08:01:08.788370 a31a700 20 mon.a@0(leader) e1 have connection -212> 2012-11-15 08:01:08.788483 a31a700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.0 127.0.0.1:6789/0 is openallow * for mon.0 127.0.0.1:6789/0 -211> 2012-11-15 08:01:08.788792 a31a700 20 mon.a@0(leader) e1 caps allow * -210> 2012-11-15 08:01:08.788894 a31a700 10 mon.a@0(leader).paxosservice(logm) dispatch log(2 entries) v1 from mon.0 127.0.0.1:6789/0 -209> 2012-11-15 08:01:08.789124 a31a700 1 mon.a@0(leader).paxos(logm updating c 1..115) is_readable now=2012-11-15 08:01:08.789167 lease_expire=2012-11-15 08:01:12.156396 has v0 lc 115 -208> 2012-11-15 08:01:08.789501 a31a700 10 mon.a@0(leader).log v115 preprocess_query log(2 entries) v1 from mon.0 127.0.0.1:6789/0 -207> 2012-11-15 08:01:08.789750 a31a700 10 mon.a@0(leader).log v115 preprocess_log log(2 entries) v1 from mon.0 -206> 2012-11-15 08:01:08.791179 a31a700 10 mon.a@0(leader).paxosservice(logm) waiting for paxos -> writeable -205> 2012-11-15 08:01:08.794061 a31a700 20 -- 127.0.0.1:6789/0 done calling dispatch on 0xbd76a20 -204> 2012-11-15 08:01:08.794250 a31a700 1 -- 127.0.0.1:6789/0 <== mon.2 127.0.0.1:6791/0 23 ==== paxos(osdmap accept lc 70 fc 0 pn 2100 opn 0 gv {}) v2 ==== 88+0+0 (1618783307 0 0) 0xbd68790 con 0x6826c60 -203> 2012-11-15 08:01:08.794701 a31a700 20 mon.a@0(leader) e1 have connection -202> 2012-11-15 08:01:08.794814 a31a700 20 mon.a@0(leader) e1 ms_dispatch existing session MonSession: mon.2 127.0.0.1:6791/0 is openallow * for mon.2 127.0.0.1:6791/0 -201> 2012-11-15 08:01:08.795120 a31a700 20 mon.a@0(leader) e1 caps allow * -200> 2012-11-15 08:01:08.795223 a31a700 10 mon.a@0(leader).paxos(osdmap updating c 1..70) handle_accept paxos(osdmap accept lc 70 fc 0 pn 2100 opn 0 gv {}) v2 -199> 2012-11-15 08:01:08.795452 a31a700 10 mon.a@0(leader).paxos(osdmap updating c 1..70) now 0,2 have accepted -198> 2012-11-15 08:01:08.795597 a31a700 10 mon.a@0(leader).paxos(osdmap updating c 1..70) got majority, committing -197> 2012-11-15 08:01:08.795717 a31a700 10 mon.a@0(leader).paxos(osdmap updating c 1..70) commit 71 -196> 2012-11-15 08:01:08.796139 a31a700 15 store(dev/mon.a) set_int osdmap/last_committed = 71 -195> 2012-11-15 08:01:08.824805 a31a700 10 mon.a@0(leader).paxos(osdmap updating c 1..71) sending commit to mon.2 -194> 2012-11-15 08:01:08.825169 a31a700 15 store(dev/mon.a) get_int osdmap_gv/71 = 324 -193> 2012-11-15 08:01:08.825272 a31a700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(osdmap commit lc 71 fc 0 pn 2100 opn 0 gv {71=324}) v2 -- ?+0 0xbd8aba0 -192> 2012-11-15 08:01:08.825665 a31a700 20 -- 127.0.0.1:6789/0 submit_message paxos(osdmap commit lc 71 fc 0 pn 2100 opn 0 gv {71=324}) v2 remote, 127.0.0.1:6791/0, have pipe. -191> 2012-11-15 08:01:08.826053 a31a700 10 mon.a@0(leader).paxos(osdmap updating c 1..71) got quorum, done with update -190> 2012-11-15 08:01:08.826227 a31a700 7 mon.a@0(leader).paxos(osdmap active c 1..71) extend_lease now+5 (2012-11-15 08:01:13.826201) -189> 2012-11-15 08:01:08.826573 a31a700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(osdmap lease lc 71 fc 1 pn 0 opn 0 gv {}) v2 -- ?+0 0xbd8b830 -188> 2012-11-15 08:01:08.826942 a31a700 20 -- 127.0.0.1:6789/0 submit_message paxos(osdmap lease lc 71 fc 1 pn 0 opn 0 gv {}) v2 remote, 127.0.0.1:6791/0, have pipe. -187> 2012-11-15 08:01:08.827343 a31a700 10 mon.a@0(leader).paxosservice(osdmap) _active -186> 2012-11-15 08:01:08.827437 a31a700 15 mon.a@0(leader).osd e70 update_from_paxos paxos e 71, my e 70 -185> 2012-11-15 08:01:08.827634 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).fault done waiting or woke up -184> 2012-11-15 08:01:08.827995 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).writer: state = connecting policy.server=0 -183> 2012-11-15 08:01:08.828335 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connect 2 -182> 2012-11-15 08:01:08.828704 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connecting to 127.0.0.1:6791/0 -181> 2012-11-15 08:01:08.829165 a31a700 20 store(dev/mon.a) reading at off 0 of 1040 -180> 2012-11-15 08:01:08.829327 a31a700 15 store(dev/mon.a) get_bl osdmap/71 = 1040 bytes -179> 2012-11-15 08:01:08.829417 a31a700 7 mon.a@0(leader).osd e70 update_from_paxos applying incremental 71 -178> 2012-11-15 08:01:08.856522 a31a700 15 store(dev/mon.a) put_bl osdmap_full/71 = 1866 bytes -177> 2012-11-15 08:01:08.856733 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).connect error 127.0.0.1:6791/0, 111: Connection refused -176> 2012-11-15 08:01:08.857187 ac1c700 2 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).fault 111: Connection refused -175> 2012-11-15 08:01:08.857557 ac1c700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0xb9b8010 sd=20 :6789 pgs=8 cs=2 l=0).fault waiting 0.400000 -174> 2012-11-15 08:01:08.883585 a31a700 1 mon.a@0(leader).osd e71 e71: 2 osds: 2 up, 2 in -173> 2012-11-15 08:01:08.887015 a31a700 10 mon.a@0(leader).paxos(osdmap active c 1..71) stash_latest v71 len 1866 -172> 2012-11-15 08:01:08.887223 a31a700 15 store(dev/mon.a) put_bl osdmap/latest = 1878 bytes -171> 2012-11-15 08:01:08.909087 a31a700 1 mon.a@0(leader).paxos(osdmap active c 1..71) is_readable now=2012-11-15 08:01:08.909141 lease_expire=2012-11-15 08:01:13.826201 has v0 lc 71 -170> 2012-11-15 08:01:08.909507 a31a700 10 mon.a@0(leader).pg v96 check_osd_map applying osdmap e71 to pg_map -169> 2012-11-15 08:01:08.909728 a31a700 20 store(dev/mon.a) reading at off 0 of 1040 -168> 2012-11-15 08:01:08.909855 a31a700 15 store(dev/mon.a) get_bl osdmap/71 = 1040 bytes -167> 2012-11-15 08:01:08.910321 a31a700 10 mon.a@0(leader).pg v96 register_new_pgs checking pg pools for osdmap epoch 71, last_pg_scan 1 -166> 2012-11-15 08:01:08.910469 a31a700 10 mon.a@0(leader).pg v96 no change in pool 0 rep size 2 crush_ruleset 0 object_hash rjenkins pg_num 8 pgp_num 8 last_change 1 owner 0 crash_replay_interval 45 -165> 2012-11-15 08:01:08.910684 a31a700 10 mon.a@0(leader).pg v96 no change in pool 1 rep size 2 crush_ruleset 1 object_hash rjenkins pg_num 8 pgp_num 8 last_change 1 owner 0 -164> 2012-11-15 08:01:08.910888 a31a700 10 mon.a@0(leader).pg v96 no change in pool 2 rep size 2 crush_ruleset 2 object_hash rjenkins pg_num 8 pgp_num 8 last_change 1 owner 0 -163> 2012-11-15 08:01:08.911109 a31a700 10 mon.a@0(leader).pg v96 register_new_pgs registered 0 new pgs, removed 0 uncreated pgs -162> 2012-11-15 08:01:08.911248 a31a700 10 mon.a@0(leader).pg v96 check_down_pgs -161> 2012-11-15 08:01:08.911715 a31a700 10 mon.a@0(leader).paxosservice(pgmap) propose_pending -160> 2012-11-15 08:01:08.911817 a31a700 10 mon.a@0(leader).pg v96 encode_pending v 97 -159> 2012-11-15 08:01:08.912068 a31a700 20 mon.a@0(leader) e1 get_global_paxos_version 326 -158> 2012-11-15 08:01:08.912181 a31a700 5 mon.a@0(leader).paxos(pgmap active c 1..96) propose_new_value 97 46 bytes, gv 326 -157> 2012-11-15 08:01:08.912349 a31a700 10 mon.a@0(leader).paxos(pgmap active c 1..96) begin for 97 46 bytes gv 326 -156> 2012-11-15 08:01:08.912610 a31a700 15 store(dev/mon.a) put_bl pgmap/97 = 46 bytes -155> 2012-11-15 08:01:08.918568 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got KEEPALIVE -154> 2012-11-15 08:01:08.918935 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -153> 2012-11-15 08:01:08.942763 a31a700 15 store(dev/mon.a) set_int pgmap_gv/97 = 326 -152> 2012-11-15 08:01:09.071114 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ACK -151> 2012-11-15 08:01:09.165651 b121700 15 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got ack seq 5 -150> 2012-11-15 08:01:09.166026 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -149> 2012-11-15 08:01:09.166379 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got MSG -148> 2012-11-15 08:01:09.166743 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got envelope type=73 src osd.1 front=22 data=0 off 0 -147> 2012-11-15 08:01:09.167120 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 22 from policy throttler 1198/419430400 -146> 2012-11-15 08:01:09.167478 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader wants 22 from dispatch throttler 124/104857600 -145> 2012-11-15 08:01:09.167908 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got front 22 -144> 2012-11-15 08:01:09.168269 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).aborted = 0 -143> 2012-11-15 08:01:09.168578 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got 22 + 0 + 0 byte message -142> 2012-11-15 08:01:09.173299 b121700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader got message 6 0xbdacbe0 osd_alive(want up_thru 71 have 71) v1 -141> 2012-11-15 08:01:09.174639 b121700 20 -- 127.0.0.1:6789/0 queue 0xbdacbe0 prio 127 -140> 2012-11-15 08:01:09.174846 b121700 20 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).reader reading tag... -139> 2012-11-15 08:01:09.176493 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pg s=62 cs=1 l=1).writer: state = open policy.server=1 -138> 2012-11-15 08:01:09.176867 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).write_ack 6 -137> 2012-11-15 08:01:09.177230 b020700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6803/6576 pipe(0xba72ac0 sd=19 :6789 pgs=62 cs=1 l=1).writer: state = open policy.server=1 -136>