Project

General

Profile

Bug #5665 » ceph-mds.b-s-a.log

Sage Weil, 07/18/2013 09:10 AM

 
2013-07-17 21:50:23.851999 7f39aa631780 0 ceph version 0.61.4-77-g39bffac (39bffac6b6c898882d03de392f7f2218933d942b), process ceph-mds, pid 1089
2013-07-17 21:50:23.852468 7f39aa631780 1 accepter.accepter.bind my_inst.addr is 0.0.0.0:6800/1089 need_addr=1
2013-07-17 21:50:23.852917 7f39aa631780 0 lockdep is enabled
2013-07-17 21:50:23.853033 7f39aa631780 1 -- 0.0.0.0:6800/1089 messenger.start
2013-07-17 21:50:23.853356 7f39aa631780 10 mds.-1.0 168 MDSCacheObject
2013-07-17 21:50:23.853369 7f39aa631780 10 mds.-1.0 2144 CInode
2013-07-17 21:50:23.853418 7f39aa631780 10 mds.-1.0 16 elist<>::item *7=112
2013-07-17 21:50:23.853420 7f39aa631780 10 mds.-1.0 384 inode_t
2013-07-17 21:50:23.853421 7f39aa631780 10 mds.-1.0 56 nest_info_t
2013-07-17 21:50:23.853423 7f39aa631780 10 mds.-1.0 32 frag_info_t
2013-07-17 21:50:23.853424 7f39aa631780 10 mds.-1.0 40 SimpleLock *5=200
2013-07-17 21:50:23.853425 7f39aa631780 10 mds.-1.0 48 ScatterLock *3=144
2013-07-17 21:50:23.853427 7f39aa631780 10 mds.-1.0 472 CDentry
2013-07-17 21:50:23.853428 7f39aa631780 10 mds.-1.0 16 elist<>::item
2013-07-17 21:50:23.853429 7f39aa631780 10 mds.-1.0 40 SimpleLock
2013-07-17 21:50:23.853431 7f39aa631780 10 mds.-1.0 1016 CDir
2013-07-17 21:50:23.853436 7f39aa631780 10 mds.-1.0 16 elist<>::item *2=32
2013-07-17 21:50:23.853438 7f39aa631780 10 mds.-1.0 192 fnode_t
2013-07-17 21:50:23.853439 7f39aa631780 10 mds.-1.0 56 nest_info_t *2
2013-07-17 21:50:23.853440 7f39aa631780 10 mds.-1.0 32 frag_info_t *2
2013-07-17 21:50:23.853441 7f39aa631780 10 mds.-1.0 168 Capability
2013-07-17 21:50:23.853445 7f39aa631780 10 mds.-1.0 32 xlist<>::item *2=64
2013-07-17 21:50:23.853479 7f39aa631780 1 accepter.accepter.start
2013-07-17 21:50:23.867837 7f39aa631780 1 -- 0.0.0.0:6800/1089 --> 10.214.132.29:6789/0 -- auth(proto 0 30 bytes epoch 0) v1 -- ?+0 0x1ae36c0 con 0x1aff580
2013-07-17 21:50:23.871248 7f39aa62d700 0 -- 0.0.0.0:6800/1089 >> 10.214.132.29:6789/0 pipe(0x1b04280 sd=16 :0 s=1 pgs=0 cs=0 l=1).fault
2013-07-17 21:50:24.072199 7f39aa62d700 1 -- 10.214.131.17:6800/1089 learned my addr 10.214.131.17:6800/1089
2013-07-17 21:50:24.072290 7f39aa62d700 10 mds.-1.0 MDS::ms_get_authorizer type=mon
2013-07-17 21:50:24.073657 7f39a5eb1700 5 mds.-1.0 ms_handle_connect on 10.214.132.29:6789/0
2013-07-17 21:50:26.854228 7f39a4eaf700 1 -- 10.214.131.17:6800/1089 mark_down 0x1aff580 -- 0x1b04280
2013-07-17 21:50:26.854539 7f39a4eaf700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- auth(proto 0 30 bytes epoch 0) v1 -- ?+0 0x1ae36c0 con 0x1aff840
2013-07-17 21:50:26.855003 7f39a3dac700 10 mds.-1.0 MDS::ms_get_authorizer type=mon
2013-07-17 21:50:26.855385 7f39a5eb1700 5 mds.-1.0 ms_handle_connect on 10.214.132.29:6790/0
2013-07-17 21:50:26.962139 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 1 ==== mon_map v1 ==== 473+0+0 (1166952924 0 0) 0x1aeca00 con 0x1aff840
2013-07-17 21:50:26.963551 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 2 ==== auth_reply(proto 2 0 Success) v1 ==== 33+0+0 (591571988 0 0) 0x1aec800 con 0x1aff840
2013-07-17 21:50:26.963815 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- auth(proto 2 32 bytes epoch 0) v1 -- ?+0 0x1ae3b40 con 0x1aff840
2013-07-17 21:50:27.078658 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 3 ==== auth_reply(proto 2 0 Success) v1 ==== 206+0+0 (279964006 0 0) 0x1aecc00 con 0x1aff840
2013-07-17 21:50:27.078819 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- auth(proto 2 165 bytes epoch 0) v1 -- ?+0 0x1ae3b40 con 0x1aff840
2013-07-17 21:50:27.081958 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 4 ==== auth_reply(proto 2 0 Success) v1 ==== 580+0+0 (3148459168 0 0) 0x1aeca00 con 0x1aff840
2013-07-17 21:50:27.082044 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x1b05700 con 0x1aff840
2013-07-17 21:50:27.085148 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- auth(proto 2 2 bytes epoch 0) v1 -- ?+0 0x1ae36c0 con 0x1aff840
2013-07-17 21:50:27.086996 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 5 ==== mon_map v1 ==== 473+0+0 (1166952924 0 0) 0x1aece00 con 0x1aff840
2013-07-17 21:50:27.087067 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 6 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (673156111 0 0) 0x1b05a80 con 0x1aff840
2013-07-17 21:50:27.087093 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 7 ==== auth_reply(proto 2 0 Success) v1 ==== 194+0+0 (3522179935 0 0) 0x1aeca00 con 0x1aff840
2013-07-17 21:50:27.087384 7f39aa631780 10 mds.-1.0 beacon_send up:boot seq 1 (currently up:boot)
2013-07-17 21:50:27.088370 7f39aa631780 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:boot seq 1 v0) v2 -- ?+0 0x1b19000 con 0x1aff840
2013-07-17 21:50:27.092418 7f39aa631780 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mon_subscribe({monmap=2+,osdmap=0}) v2 -- ?+0 0x1b05540 con 0x1aff840
2013-07-17 21:50:27.092458 7f39aa631780 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mon_subscribe({mdsmap=0+,monmap=2+,osdmap=0}) v2 -- ?+0 0x1b05e00 con 0x1aff840
2013-07-17 21:50:27.092490 7f39aa631780 10 mds.-1.0 create_logger
2013-07-17 21:50:27.093740 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 8 ==== osd_map(3..3 src has 1..3) v3 ==== 3962+0+0 (1009265937 0 0) 0x1ae3d80 con 0x1aff840
2013-07-17 21:50:27.095103 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 9 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (673156111 0 0) 0x1b05540 con 0x1aff840
2013-07-17 21:50:27.095154 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 10 ==== mdsmap(e 2) v1 ==== 356+0+0 (3333750197 0 0) 0x1aecc00 con 0x1aff840
2013-07-17 21:50:27.095190 7f39a5eb1700 5 mds.-1.0 handle_mds_map epoch 2 from mon.2
2013-07-17 21:50:27.095209 7f39a5eb1700 10 mds.-1.0 my compat 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}
2013-07-17 21:50:27.095220 7f39a5eb1700 10 mds.-1.0 mdsmap compat 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}
2013-07-17 21:50:27.095227 7f39a5eb1700 10 mds.-1.-1 map says i am 10.214.131.17:6800/1089 mds.-1.-1 state down:dne
2013-07-17 21:50:27.095232 7f39a5eb1700 10 mds.-1.-1 not in map yet
2013-07-17 21:50:27.095250 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 11 ==== osd_map(3..3 src has 1..3) v3 ==== 3962+0+0 (1009265937 0 0) 0x1b1f240 con 0x1aff840
2013-07-17 21:50:27.095275 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 12 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (673156111 0 0) 0x1b05700 con 0x1aff840
2013-07-17 21:50:27.226038 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 13 ==== mdsmap(e 3) v1 ==== 559+0+0 (1454482218 0 0) 0x1aec800 con 0x1aff840
2013-07-17 21:50:27.226067 7f39a5eb1700 5 mds.-1.-1 handle_mds_map epoch 3 from mon.2
2013-07-17 21:50:27.226115 7f39a5eb1700 10 mds.-1.-1 my compat 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}
2013-07-17 21:50:27.226122 7f39a5eb1700 10 mds.-1.-1 mdsmap compat 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}
2013-07-17 21:50:27.226126 7f39a5eb1700 10 mds.-1.-1 map says i am 10.214.131.17:6800/1089 mds.-1.-1 state down:dne
2013-07-17 21:50:27.226132 7f39a5eb1700 10 mds.-1.-1 not in map yet
2013-07-17 21:50:27.334987 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 14 ==== mdsmap(e 4) v1 ==== 767+0+0 (1950902404 0 0) 0x1aecc00 con 0x1aff840
2013-07-17 21:50:27.335016 7f39a5eb1700 5 mds.-1.-1 handle_mds_map epoch 4 from mon.2
2013-07-17 21:50:27.335081 7f39a5eb1700 10 mds.-1.-1 my compat 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}
2013-07-17 21:50:27.335089 7f39a5eb1700 10 mds.-1.-1 mdsmap compat 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}
2013-07-17 21:50:27.335094 7f39a5eb1700 10 mds.-1.0 map says i am 10.214.131.17:6800/1089 mds.-1.0 state up:standby
2013-07-17 21:50:27.335104 7f39a5eb1700 1 mds.-1.0 handle_mds_map standby
2013-07-17 21:50:27.443372 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 15 ==== mdsmap(e 5) v1 ==== 791+0+0 (3038094493 0 0) 0x1aeca00 con 0x1aff840
2013-07-17 21:50:27.443400 7f39a5eb1700 5 mds.-1.0 handle_mds_map epoch 5 from mon.2
2013-07-17 21:50:27.443444 7f39a5eb1700 10 mds.-1.0 my compat 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}
2013-07-17 21:50:27.443453 7f39a5eb1700 10 mds.-1.0 mdsmap compat 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}
2013-07-17 21:50:27.443458 7f39a5eb1700 10 mds.-1.0 map says i am 10.214.131.17:6800/1089 mds.-1.0 state up:standby
2013-07-17 21:50:27.443464 7f39a5eb1700 1 mds.-1.0 handle_mds_map standby
2013-07-17 21:50:27.652173 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 16 ==== mdsmap(e 6) v1 ==== 791+0+0 (2287223844 0 0) 0x1aece00 con 0x1aff840
2013-07-17 21:50:27.652202 7f39a5eb1700 5 mds.-1.0 handle_mds_map epoch 6 from mon.2
2013-07-17 21:50:27.652225 7f39a5eb1700 10 mds.-1.0 my compat 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}
2013-07-17 21:50:27.652232 7f39a5eb1700 10 mds.-1.0 mdsmap compat 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}
2013-07-17 21:50:27.652237 7f39a5eb1700 10 mds.-1.0 map says i am 10.214.131.17:6800/1089 mds.-1.0 state up:standby
2013-07-17 21:50:27.652242 7f39a5eb1700 1 mds.-1.0 handle_mds_map standby
2013-07-17 21:50:31.092549 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 2 (currently up:standby)
2013-07-17 21:50:31.092617 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 2 v6) v2 -- ?+0 0x1b19840 con 0x1aff840
2013-07-17 21:50:31.094924 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 17 ==== mdsbeacon(4103/b-s-a up:standby seq 2 v6) v2 ==== 107+0+0 (3507888832 0 0) 0x1b19000 con 0x1aff840
2013-07-17 21:50:31.094955 7f39a5eb1700 10 mds.-1.0 handle_mds_beacon up:standby seq 2 rtt 0.002390
2013-07-17 21:50:32.093783 7f39a3cab700 20 mds.-1.bal get_load no root, no load
2013-07-17 21:50:32.095256 7f39a3cab700 15 mds.-1.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.91>
2013-07-17 21:50:35.092811 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 3 (currently up:standby)
2013-07-17 21:50:35.092844 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 3 v6) v2 -- ?+0 0x1b19b00 con 0x1aff840
2013-07-17 21:50:35.095002 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 18 ==== mdsbeacon(4103/b-s-a up:standby seq 3 v6) v2 ==== 107+0+0 (433055884 0 0) 0x1b1a080 con 0x1aff840
2013-07-17 21:50:35.095033 7f39a5eb1700 10 mds.-1.0 handle_mds_beacon up:standby seq 3 rtt 0.002207
2013-07-17 21:50:37.093933 7f39a3cab700 20 mds.-1.bal get_load no root, no load
2013-07-17 21:50:37.093979 7f39a3cab700 15 mds.-1.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.84>
2013-07-17 21:50:39.093035 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 4 (currently up:standby)
2013-07-17 21:50:39.093078 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 4 v6) v2 -- ?+0 0x1b19840 con 0x1aff840
2013-07-17 21:50:39.095288 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 19 ==== mdsbeacon(4103/b-s-a up:standby seq 4 v6) v2 ==== 107+0+0 (1746563722 0 0) 0x1b19dc0 con 0x1aff840
2013-07-17 21:50:39.095322 7f39a5eb1700 10 mds.-1.0 handle_mds_beacon up:standby seq 4 rtt 0.002266
2013-07-17 21:50:42.094100 7f39a3cab700 20 mds.-1.bal get_load no root, no load
2013-07-17 21:50:42.094152 7f39a3cab700 15 mds.-1.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.77>
2013-07-17 21:50:43.093265 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 5 (currently up:standby)
2013-07-17 21:50:43.093299 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 5 v6) v2 -- ?+0 0x1b1a340 con 0x1aff840
2013-07-17 21:50:43.159154 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 20 ==== mdsbeacon(4103/b-s-a up:standby seq 5 v6) v2 ==== 107+0+0 (2697181382 0 0) 0x1b1a340 con 0x1aff840
2013-07-17 21:50:43.159186 7f39a5eb1700 10 mds.-1.0 handle_mds_beacon up:standby seq 5 rtt 0.065904
2013-07-17 21:50:47.093495 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 6 (currently up:standby)
2013-07-17 21:50:47.093529 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 6 v6) v2 -- ?+0 0x1b1a080 con 0x1aff840
2013-07-17 21:50:47.094204 7f39a3cab700 20 mds.-1.bal get_load no root, no load
2013-07-17 21:50:47.094249 7f39a3cab700 15 mds.-1.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.71>
2013-07-17 21:50:47.095941 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 21 ==== mdsbeacon(4103/b-s-a up:standby seq 6 v6) v2 ==== 107+0+0 (4232417507 0 0) 0x1b19840 con 0x1aff840
2013-07-17 21:50:47.095972 7f39a5eb1700 10 mds.-1.0 handle_mds_beacon up:standby seq 6 rtt 0.002462
2013-07-17 21:50:51.093723 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 7 (currently up:standby)
2013-07-17 21:50:51.093754 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 7 v6) v2 -- ?+0 0x1b19000 con 0x1aff840
2013-07-17 21:50:51.096023 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 22 ==== mdsbeacon(4103/b-s-a up:standby seq 7 v6) v2 ==== 107+0+0 (882662063 0 0) 0x1b19b00 con 0x1aff840
2013-07-17 21:50:51.096054 7f39a5eb1700 10 mds.-1.0 handle_mds_beacon up:standby seq 7 rtt 0.002316
2013-07-17 21:50:52.094355 7f39a3cab700 20 mds.-1.bal get_load no root, no load
2013-07-17 21:50:52.094402 7f39a3cab700 15 mds.-1.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.65>
2013-07-17 21:50:55.093942 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 8 (currently up:standby)
2013-07-17 21:50:55.093974 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 8 v6) v2 -- ?+0 0x1b1a600 con 0x1aff840
2013-07-17 21:50:55.096227 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 23 ==== mdsbeacon(4103/b-s-a up:standby seq 8 v6) v2 ==== 107+0+0 (535733487 0 0) 0x1b1ab80 con 0x1aff840
2013-07-17 21:50:55.096261 7f39a5eb1700 10 mds.-1.0 handle_mds_beacon up:standby seq 8 rtt 0.002304
2013-07-17 21:50:57.094510 7f39a3cab700 20 mds.-1.bal get_load no root, no load
2013-07-17 21:50:57.094557 7f39a3cab700 15 mds.-1.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.6>
2013-07-17 21:50:59.094160 7f39a3cab700 10 mds.-1.0 beacon_send up:standby seq 9 (currently up:standby)
2013-07-17 21:50:59.094192 7f39a3cab700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:standby seq 9 v6) v2 -- ?+0 0x1b19840 con 0x1aff840
2013-07-17 21:50:59.266608 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 24 ==== mdsmap(e 7) v1 ==== 588+0+0 (1128987303 0 0) 0x1aec600 con 0x1aff840
2013-07-17 21:50:59.266638 7f39a5eb1700 5 mds.-1.0 handle_mds_map epoch 7 from mon.2
2013-07-17 21:50:59.266661 7f39a5eb1700 10 mds.-1.0 my compat 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}
2013-07-17 21:50:59.266669 7f39a5eb1700 10 mds.-1.0 mdsmap compat 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}
2013-07-17 21:50:59.266684 7f39a5eb1700 10 mds.0.2 map says i am 10.214.131.17:6800/1089 mds.0.2 state up:replay
2013-07-17 21:50:59.266693 7f39a5eb1700 10 mds.0.2 peer mds gid 4099 removed from map
2013-07-17 21:50:59.266698 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down 10.214.131.4:6803/27816 -- pipe dne
2013-07-17 21:50:59.266727 7f39a5eb1700 1 mds.0.2 handle_mds_map i am now mds.0.2
2013-07-17 21:50:59.266730 7f39a5eb1700 1 mds.0.2 handle_mds_map state change up:standby --> up:replay
2013-07-17 21:50:59.266733 7f39a5eb1700 1 mds.0.2 replay_start
2013-07-17 21:50:59.266744 7f39a5eb1700 7 mds.0.cache set_recovery_set
2013-07-17 21:50:59.266749 7f39a5eb1700 1 mds.0.2 recovery set is
2013-07-17 21:50:59.266752 7f39a5eb1700 1 mds.0.2 need osdmap epoch 6, have 3
2013-07-17 21:50:59.266759 7f39a5eb1700 1 mds.0.2 waiting for osdmap 6 (which blacklists prior instance)
2013-07-17 21:50:59.266780 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mon_subscribe({mdsmap=8+,monmap=2+,osdmap=4}) v2 -- ?+0 0x1b05700 con 0x1aff840
2013-07-17 21:50:59.266801 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down 10.214.131.4:6803/27816 -- pipe dne
2013-07-17 21:50:59.266816 7f39a5eb1700 5 mds.0.2 handle_mds_failure for myself; not doing anything
2013-07-17 21:50:59.308301 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 25 ==== mdsbeacon(4103/b-s-a up:standby seq 9 v7) v2 ==== 107+0+0 (1444638711 0 0) 0x1b1a8c0 con 0x1aff840
2013-07-17 21:50:59.308333 7f39a5eb1700 10 mds.0.2 handle_mds_beacon up:standby seq 9 rtt 0.214156
2013-07-17 21:50:59.308563 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 26 ==== osd_map(4..6 src has 1..6) v3 ==== 2990+0+0 (385343007 0 0) 0x1b1fb40 con 0x1aff840
2013-07-17 21:50:59.308766 7f39a5eb1700 2 mds.0.2 boot_start 1: opening inotable
2013-07-17 21:50:59.308829 7f39a5eb1700 10 mds.0.inotable: load
2013-07-17 21:50:59.320231 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.2:1 mds0_inotable [read 0~0] 1.b852b893 e6) v4 -- ?+0 0x1b1f000 con 0x1aff9a0
2013-07-17 21:50:59.320262 7f39a5eb1700 2 mds.0.2 boot_start 1: opening sessionmap
2013-07-17 21:50:59.320307 7f39a5eb1700 10 mds.0.sessionmap load
2013-07-17 21:50:59.320423 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:2 mds0_sessionmap [read 0~0] 1.3270c60b e6) v4 -- ?+0 0x1b1f240 con 0x1affc60
2013-07-17 21:50:59.320461 7f39a5eb1700 2 mds.0.2 boot_start 1: opening anchor table
2013-07-17 21:50:59.320469 7f39a5eb1700 10 mds.0.anchortable: load
2013-07-17 21:50:59.320493 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.2:3 mds_anchortable [read 0~0] 1.a977f6a7 e6) v4 -- ?+0 0x1ae3d80 con 0x1aff9a0
2013-07-17 21:50:59.320509 7f39a5eb1700 2 mds.0.2 boot_start 1: opening snap table
2013-07-17 21:50:59.320518 7f39a5eb1700 10 mds.0.snaptable: load
2013-07-17 21:50:59.320616 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6800/8225 -- osd_op(mds.0.2:4 mds_snaptable [read 0~0] 1.d90270ad e6) v4 -- ?+0 0x1b1fd80 con 0x1affb00
2013-07-17 21:50:59.320651 7f39a5eb1700 2 mds.0.2 boot_start 1: opening mds log
2013-07-17 21:50:59.320657 7f39a5eb1700 5 mds.0.log open discovering log bounds
2013-07-17 21:50:59.320698 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:5 200.00000000 [read 0~0] 1.844f3494 e6) v4 -- ?+0 0x1b396c0 con 0x1affc60
2013-07-17 21:50:59.320729 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 27 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (673156111 0 0) 0x1b05540 con 0x1aff840
2013-07-17 21:50:59.321139 7f39aa62d700 10 mds.0.2 MDS::ms_get_authorizer type=osd
2013-07-17 21:50:59.321148 7f39a34aa700 10 mds.0.2 MDS::ms_get_authorizer type=osd
2013-07-17 21:50:59.321593 7f39a33a9700 10 mds.0.2 MDS::ms_get_authorizer type=osd
2013-07-17 21:50:59.321668 7f39a5eb1700 5 mds.0.2 ms_handle_connect on 10.214.131.4:6804/27817
2013-07-17 21:50:59.321843 7f39a5eb1700 5 mds.0.2 ms_handle_connect on 10.214.132.29:6806/8238
2013-07-17 21:50:59.322545 7f39a5eb1700 5 mds.0.2 ms_handle_connect on 10.214.132.29:6800/8225
2013-07-17 21:50:59.323172 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.2 10.214.132.29:6806/8238 1 ==== osd_op_reply(1 mds0_inotable [read 0~34] ondisk = 0) v4 ==== 112+0+34 (18516043 0 1054821296) 0x1aec800 con 0x1aff9a0
2013-07-17 21:50:59.325026 7f39a5eb1700 10 mds.0.inotable: load_2 got 34 bytes
2013-07-17 21:50:59.325069 7f39a5eb1700 10 mds.0.inotable: load_2 loaded v0
2013-07-17 21:50:59.325191 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.2 10.214.132.29:6806/8238 2 ==== osd_op_reply(3 mds_anchortable [read 0~34] ondisk = 0) v4 ==== 114+0+34 (881869765 0 2191498079) 0x1aeca00 con 0x1aff9a0
2013-07-17 21:50:59.325220 7f39a5eb1700 10 mds.0.anchortable: load_2 got 34 bytes
2013-07-17 21:50:59.325223 7f39a5eb1700 10 mds.0.anchortable: load_2 loaded v0
2013-07-17 21:50:59.325245 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.1 10.214.132.29:6800/8225 1 ==== osd_op_reply(4 mds_snaptable [read 0~46] ondisk = 0) v4 ==== 112+0+46 (2542550824 0 2603725198) 0x1aece00 con 0x1affb00
2013-07-17 21:50:59.325264 7f39a5eb1700 10 mds.0.snaptable: load_2 got 46 bytes
2013-07-17 21:50:59.325266 7f39a5eb1700 10 mds.0.snaptable: load_2 loaded v0
2013-07-17 21:50:59.325328 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 1 ==== osd_op_reply(5 200.00000000 [read 0~84] ondisk = 0) v4 ==== 111+0+84 (268097357 0 2960925567) 0x1aec600 con 0x1affc60
2013-07-17 21:50:59.325431 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:6 200.00000001 [stat] 1.6e5f474 rwordered e6) v4 -- ?+0 0x1b1fb40 con 0x1affc60
2013-07-17 21:50:59.325482 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 2 ==== osd_op_reply(2 mds0_sessionmap [read 0~22] ondisk = 0) v4 ==== 114+0+22 (107916576 0 3628653333) 0x1b41200 con 0x1affc60
2013-07-17 21:50:59.325509 7f39a5eb1700 10 mds.0.sessionmap dump
2013-07-17 21:50:59.325519 7f39a5eb1700 10 mds.0.sessionmap _load_finish v 0, 0 sessions, 22 bytes
2013-07-17 21:50:59.325522 7f39a5eb1700 10 mds.0.sessionmap dump
2013-07-17 21:50:59.326443 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 3 ==== osd_op_reply(6 200.00000001 [stat] ondisk = 0) v4 ==== 111+0+16 (3176102897 0 2739558597) 0x1b41000 con 0x1affc60
2013-07-17 21:50:59.326524 7f39a5eb1700 2 mds.0.2 boot_start 2: loading/discovering base inodes
2013-07-17 21:50:59.326529 7f39a5eb1700 0 mds.0.cache creating system inode with ino:100
2013-07-17 21:50:59.326578 7f39a5eb1700 10 mds.0.cache.ino(100) fetch
2013-07-17 21:50:59.326612 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6806/8238 -- osd_op(mds.0.2:7 100.00000000 [getxattr inode] 1.c5265ab3 e6) v4 -- ?+0 0x1b39240 con 0x1aff9a0
2013-07-17 21:50:59.326710 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:8 100.00000000.inode [read 0~0] 1.85dde07f e6) v4 -- ?+0 0x1b39000 con 0x1affc60
2013-07-17 21:50:59.326781 7f39a5eb1700 0 mds.0.cache creating system inode with ino:1
2013-07-17 21:50:59.326787 7f39a5eb1700 10 mds.0.cache.ino(1) fetch
2013-07-17 21:50:59.326808 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:9 1.00000000 [getxattr inode] 1.6b2cdaff e6) v4 -- ?+0 0x1b396c0 con 0x1affc60
2013-07-17 21:50:59.326897 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:10 1.00000000.inode [read 0~0] 1.232c0e14 e6) v4 -- ?+0 0x1b1f240 con 0x1affc60
2013-07-17 21:50:59.327860 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 4 ==== osd_op_reply(8 100.00000000.inode [read 0~432] ondisk = 0) v4 ==== 117+0+432 (3911251570 0 3552250706) 0x1aece00 con 0x1affc60
2013-07-17 21:50:59.327917 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.2 10.214.132.29:6806/8238 3 ==== osd_op_reply(7 100.00000000 [getxattr] ondisk = -61 (No data available)) v4 ==== 111+0+0 (3030160755 0 0) 0x1aecc00 con 0x1aff9a0
2013-07-17 21:50:59.329779 7f39a5eb1700 10 mds.0.cache.ino(100) _fetched got 0 and 432
2013-07-17 21:50:59.329789 7f39a5eb1700 10 mds.0.cache.ino(100) magic is 'ceph fs volume v011' (expecting 'ceph fs volume v011')
2013-07-17 21:50:59.329807 7f39a5eb1700 20 mds.0.cache.ino(100) decode_snap_blob snaprealm(100 seq 1 lc 0 cr 0 cps 1 snaps={} 0x1b39480)
2013-07-17 21:50:59.329817 7f39a5eb1700 10 mds.0.cache.ino(100) _fetched [inode 100 [...2,head] ~mds0/ auth v1 snaprealm=0x1b39480 f(v0 11=1+10) n(v0 11=1+10) (iversion lock) 0x1b48000]
2013-07-17 21:50:59.329876 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 5 ==== osd_op_reply(10 1.00000000.inode [read 0~432] ondisk = 0) v4 ==== 115+0+432 (1366033585 0 3278768658) 0x1aeca00 con 0x1affc60
2013-07-17 21:50:59.329910 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 6 ==== osd_op_reply(9 1.00000000 [getxattr] ondisk = -61 (No data available)) v4 ==== 109+0+0 (4140852365 0 0) 0x1aec800 con 0x1affc60
2013-07-17 21:50:59.329935 7f39a5eb1700 10 mds.0.cache.ino(1) _fetched got 0 and 432
2013-07-17 21:50:59.329939 7f39a5eb1700 10 mds.0.cache.ino(1) magic is 'ceph fs volume v011' (expecting 'ceph fs volume v011')
2013-07-17 21:50:59.329945 7f39a5eb1700 20 mds.0.cache.ino(1) decode_snap_blob snaprealm(1 seq 1 lc 0 cr 0 cps 1 snaps={} 0x1b39900)
2013-07-17 21:50:59.329948 7f39a5eb1700 10 mds.0.cache.ino(1) _fetched [inode 1 [...2,head] / auth v1 snaprealm=0x1b39900 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) 0x1b48860]
2013-07-17 21:50:59.329956 7f39a5eb1700 2 mds.0.2 boot_start 3: replaying mds log
2013-07-17 21:50:59.329959 7f39a5eb1700 10 mds.0.log replay start, from 4194304 to 4194464
2013-07-17 21:50:59.330078 7f39a2fa5700 10 mds.0.log _replay_thread start
2013-07-17 21:50:59.330157 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:11 200.00000001 [read 0~160] 1.6e5f474 e6) v4 -- ?+0 0x1b1fb40 con 0x1affc60
2013-07-17 21:50:59.331167 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 7 ==== osd_op_reply(11 200.00000001 [read 0~160] ondisk = 0) v4 ==== 111+0+160 (2547231849 0 560837148) 0x1aec600 con 0x1affc60
2013-07-17 21:50:59.332219 7f39a2fa5700 10 mds.0.log _replay 4194304~156 / 4194464 2013-07-17 21:50:27.463391: ESubtreeMap 0 subtrees , 0 ambiguous [metablob]
2013-07-17 21:50:59.332291 7f39a2fa5700 10 mds.0.journal ESubtreeMap.replay -- reconstructing (auth) subtree spanning tree
2013-07-17 21:50:59.332297 7f39a2fa5700 10 mds.0.journal EMetaBlob.replay 0 dirlumps by unknown.0
2013-07-17 21:50:59.332308 7f39a2fa5700 10 mds.0.cache show_subtrees - no subtrees
2013-07-17 21:50:59.332315 7f39a2fa5700 10 mds.0.log _replay - complete, 1 events
2013-07-17 21:50:59.332318 7f39a2fa5700 10 mds.0.log _replay_thread kicking waiters
2013-07-17 21:50:59.332322 7f39a2fa5700 1 mds.0.2 replay_done
2013-07-17 21:50:59.332324 7f39a2fa5700 1 mds.0.2 making mds journal writeable
2013-07-17 21:50:59.332355 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:12 200.00000001 [zero 160~4194144] 1.6e5f474 e6) v4 -- ?+0 0x1b39000 con 0x1affc60
2013-07-17 21:50:59.332398 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:13 200.00000002 [delete] 1.eb272dbb e6) v4 -- ?+0 0x1b39d80 con 0x1affc60
2013-07-17 21:50:59.332428 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:14 200.00000003 [delete] 1.95e3ab e6) v4 -- ?+0 0x1b39b40 con 0x1affc60
2013-07-17 21:50:59.332483 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:15 200.00000004 [delete] 1.1ba6bc1f e6) v4 -- ?+0 0x1b5f6c0 con 0x1affc60
2013-07-17 21:50:59.332664 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6803/8226 -- osd_op(mds.0.2:16 200.00000005 [delete] 1.96d5827a e6) v4 -- ?+0 0x1b5f480 con 0x1affdc0
2013-07-17 21:50:59.332711 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6800/8225 -- osd_op(mds.0.2:17 200.00000006 [delete] 1.ade7efde e6) v4 -- ?+0 0x1b5f240 con 0x1affb00
2013-07-17 21:50:59.332728 7f39a2fa5700 2 mds.0.2 i am alone, moving to state reconnect
2013-07-17 21:50:59.332733 7f39a2fa5700 3 mds.0.2 request_state up:reconnect
2013-07-17 21:50:59.332735 7f39a2fa5700 10 mds.0.2 beacon_send up:reconnect seq 10 (currently up:replay)
2013-07-17 21:50:59.332756 7f39a2fa5700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:reconnect seq 10 v7) v2 -- ?+0 0x1b1a080 con 0x1aff840
2013-07-17 21:50:59.332787 7f39a2fa5700 10 mds.0.log _replay_thread finish
2013-07-17 21:50:59.333291 7f39a27a4700 10 mds.0.2 MDS::ms_get_authorizer type=osd
2013-07-17 21:50:59.333709 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 8 ==== osd_op_reply(13 200.00000002 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (2669173395 0 0) 0x1b5e800 con 0x1affc60
2013-07-17 21:50:59.333813 7f39a5eb1700 5 mds.0.2 ms_handle_connect on 10.214.132.29:6803/8226
2013-07-17 21:50:59.334027 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.1 10.214.132.29:6800/8225 2 ==== osd_op_reply(17 200.00000006 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (3551616066 0 0) 0x1b5ec00 con 0x1affb00
2013-07-17 21:50:59.334112 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 9 ==== osd_op_reply(14 200.00000003 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (3277404193 0 0) 0x1b5e600 con 0x1affc60
2013-07-17 21:50:59.334184 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 10 ==== osd_op_reply(15 200.00000004 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (259985480 0 0) 0x1b5e400 con 0x1affc60
2013-07-17 21:50:59.336107 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.0 10.214.132.29:6803/8226 1 ==== osd_op_reply(16 200.00000005 [delete] ondisk = -2 (No such file or directory)) v4 ==== 111+0+0 (2819496719 0 0) 0x1aece00 con 0x1affdc0
2013-07-17 21:50:59.387536 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 11 ==== osd_op_reply(12 200.00000001 [truncate 160] ondisk = 0) v4 ==== 111+0+0 (3524527094 0 0) 0x1b5e200 con 0x1affc60
2013-07-17 21:50:59.550705 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 28 ==== mdsmap(e 8) v1 ==== 588+0+0 (4260846762 0 0) 0x1b5ec00 con 0x1aff840
2013-07-17 21:50:59.550728 7f39a5eb1700 5 mds.0.2 handle_mds_map epoch 8 from mon.2
2013-07-17 21:50:59.550746 7f39a5eb1700 10 mds.0.2 my compat 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}
2013-07-17 21:50:59.550751 7f39a5eb1700 10 mds.0.2 mdsmap compat 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}
2013-07-17 21:50:59.550755 7f39a5eb1700 10 mds.0.2 map says i am 10.214.131.17:6800/1089 mds.0.2 state up:reconnect
2013-07-17 21:50:59.550760 7f39a5eb1700 1 mds.0.2 handle_mds_map i am now mds.0.2
2013-07-17 21:50:59.550763 7f39a5eb1700 1 mds.0.2 handle_mds_map state change up:replay --> up:reconnect
2013-07-17 21:50:59.550765 7f39a5eb1700 1 mds.0.2 reconnect_start
2013-07-17 21:50:59.550767 7f39a5eb1700 1 mds.0.2 reopen_log
2013-07-17 21:50:59.550772 7f39a5eb1700 10 mds.0.cache rollback_uncommitted_fragments: 0 pending
2013-07-17 21:50:59.550779 7f39a5eb1700 7 mds.0.server reconnect_clients -- no sessions, doing nothing.
2013-07-17 21:50:59.550780 7f39a5eb1700 7 mds.0.server reconnect_gather_finish. failed on 0 clients
2013-07-17 21:50:59.550782 7f39a5eb1700 1 mds.0.2 reconnect_done
2013-07-17 21:50:59.550783 7f39a5eb1700 3 mds.0.2 request_state up:rejoin
2013-07-17 21:50:59.550785 7f39a5eb1700 10 mds.0.2 beacon_send up:rejoin seq 11 (currently up:reconnect)
2013-07-17 21:50:59.550796 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:rejoin seq 11 v8) v2 -- ?+0 0x1b1a8c0 con 0x1aff840
2013-07-17 21:50:59.550824 7f39a5eb1700 10 mds.0.bal check_targets have need want
2013-07-17 21:50:59.550834 7f39a5eb1700 5 mds.0.bal rebalance done
2013-07-17 21:50:59.550839 7f39a5eb1700 10 mds.0.cache show_subtrees - no subtrees
2013-07-17 21:50:59.551100 7f39a25a2700 1 -- 10.214.131.17:6800/1089 >> :/0 pipe(0x1b59000 sd=21 :6800 s=0 pgs=0 cs=0 l=0).accept sd=21 10.214.131.17:56281/0
2013-07-17 21:50:59.554396 7f39a25a2700 10 mds.0.2 new session 0x1b1fd80 for client.4136 10.214.131.17:0/1109 con 0x1b5d000
2013-07-17 21:50:59.554502 7f39a5eb1700 10 mds.0.2 ms_handle_accept 10.214.131.17:0/1109 con 0x1b5d000 session 0x1b1fd80
2013-07-17 21:50:59.554923 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== client.4136 10.214.131.17:0/1109 1 ==== client_reconnect(0 caps) v3 ==== 0+0+4 (0 0 0) 0x1b5ee00 con 0x1b5d000
2013-07-17 21:50:59.554992 7f39a5eb1700 7 mds.0.server handle_client_reconnect client.4136
2013-07-17 21:50:59.555001 7f39a5eb1700 20 mds.0.server get_session have 0x1b1fd80 client.4136 10.214.131.17:0/1109 state closed
2013-07-17 21:50:59.555013 7f39a5eb1700 10 mds.0.server reconnect_start 0.000000 delay 2013-07-17 21:50:59.555012
2013-07-17 21:50:59.555020 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.17:0/1109 -- client_session(open) v1 -- ?+0 0x1b41380 con 0x1b5d000
2013-07-17 21:50:59.555040 7f39a5eb1700 10 mds.0.server session is closed, will make best effort to reconnect client.4136 10.214.131.17:0/1109
2013-07-17 21:50:59.555064 7f39a5eb1700 5 mds.0.log submit_entry 4194464~194 : ESession client.4136 10.214.131.17:0/1109 open cmapv 1
2013-07-17 21:50:59.555127 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:18 200.00000001 [write 160~198] 1.6e5f474 e6) v4 -- ?+0 0x1b1f000 con 0x1affc60
2013-07-17 21:50:59.555248 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.4:6804/27817 -- osd_op(mds.0.2:19 200.00000000 [writefull 0~84] 1.844f3494 e6) v4 -- ?+0 0x1ae3d80 con 0x1affc60
2013-07-17 21:50:59.557217 7f39a5eb1700 0 log [DBG] : reconnect by new client.4136 10.214.131.17:0/1109 after 2013-07-17 21:50:59.555012
2013-07-17 21:50:59.557260 7f39a5eb1700 7 mds.0.server reconnect_gather_finish. failed on 0 clients
2013-07-17 21:50:59.557263 7f39a5eb1700 1 mds.0.2 reconnect_done
2013-07-17 21:50:59.557264 7f39a5eb1700 3 mds.0.2 request_state up:rejoin
2013-07-17 21:50:59.557266 7f39a5eb1700 10 mds.0.2 beacon_send up:rejoin seq 12 (currently up:reconnect)
2013-07-17 21:50:59.557279 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a up:rejoin seq 12 v8) v2 -- ?+0 0x1b1ab80 con 0x1aff840
2013-07-17 21:50:59.557488 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== client.4136 10.214.131.17:0/1109 2 ==== client_session(request_renewcaps seq 3) v1 ==== 28+0+0 (1219686481 0 0) 0x1b41380 con 0x1b5d000
2013-07-17 21:50:59.557526 7f39a5eb1700 3 mds.0.server not active yet, waiting
2013-07-17 21:50:59.587346 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 12 ==== osd_op_reply(18 200.00000001 [write 160~198] ondisk = 0) v4 ==== 111+0+0 (2552078477 0 0) 0x1b5e000 con 0x1affc60
2013-07-17 21:50:59.587422 7f39a5eb1700 10 mds.0.server _session_logged client.4136 10.214.131.17:0/1109 state_seq 1 open 1
2013-07-17 21:50:59.587436 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.131.17:0/1109 -- client_session(open) v1 -- ?+0 0x1b41000 con 0x1b5d000
2013-07-17 21:50:59.588055 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== client.4136 10.214.131.17:0/1109 3 ==== client_session(request_renewcaps seq 4) v1 ==== 28+0+0 (1634281192 0 0) 0x1b41000 con 0x1b5d000
2013-07-17 21:50:59.588095 7f39a5eb1700 3 mds.0.server not active yet, waiting
2013-07-17 21:50:59.612617 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== osd.3 10.214.131.4:6804/27817 13 ==== osd_op_reply(19 200.00000000 [writefull 0~84] ondisk = 0) v4 ==== 111+0+0 (1227216870 0 0) 0x1b6aa00 con 0x1affc60
2013-07-17 21:50:59.701028 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 29 ==== mdsmap(e 9) v1 ==== 588+0+0 (2252234621 0 0) 0x1b5e800 con 0x1aff840
2013-07-17 21:50:59.701055 7f39a5eb1700 5 mds.0.2 handle_mds_map epoch 9 from mon.2
2013-07-17 21:50:59.701073 7f39a5eb1700 10 mds.0.2 my compat 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}
2013-07-17 21:50:59.701078 7f39a5eb1700 10 mds.0.2 mdsmap compat 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}
2013-07-17 21:50:59.701083 7f39a5eb1700 10 mds.0.2 map says i am 10.214.131.17:6800/1089 mds.0.2 state up:rejoin
2013-07-17 21:50:59.701091 7f39a5eb1700 1 mds.0.2 handle_mds_map i am now mds.0.2
2013-07-17 21:50:59.701094 7f39a5eb1700 1 mds.0.2 handle_mds_map state change up:reconnect --> up:rejoin
2013-07-17 21:50:59.701097 7f39a5eb1700 1 mds.0.2 rejoin_joint_start
2013-07-17 21:50:59.701108 7f39a5eb1700 10 mds.0.cache rejoin_send_rejoins with recovery_set
2013-07-17 21:50:59.701119 7f39a5eb1700 10 mds.0.cache nothing to rejoin
2013-07-17 21:50:59.701128 7f39a5eb1700 10 mds.0.cache rejoin_gather_finish
2013-07-17 21:50:59.701130 7f39a5eb1700 10 mds.0.cache open_undef_inodes_dirfrags 0 inodes 0 dirfrags
2013-07-17 21:50:59.701135 7f39a5eb1700 10 mds.0.cache process_imported_caps
2013-07-17 21:50:59.701137 7f39a5eb1700 10 mds.0.cache choose_lock_states_and_reconnect_caps
2013-07-17 21:50:59.701142 7f39a5eb1700 15 mds.0.cache chose lock states on [inode 1 [...2,head] / auth v1 snaprealm=0x1b39900 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) 0x1b48860]
2013-07-17 21:50:59.701155 7f39a5eb1700 10 mds.0.cache.snaprealm(1 seq 1 0x1b39900) have_past_parents_open [1,head]
2013-07-17 21:50:59.701158 7f39a5eb1700 10 mds.0.cache have past snap parents for realm snaprealm(1 seq 1 lc 0 cr 0 cps 1 snaps={} 0x1b39900) on [inode 1 [...2,head] / auth v1 snaprealm=0x1b39900 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) 0x1b48860]
2013-07-17 21:50:59.701169 7f39a5eb1700 15 mds.0.cache chose lock states on [inode 100 [...2,head] ~mds0/ auth v1 snaprealm=0x1b39480 f(v0 11=1+10) n(v0 11=1+10) (iversion lock) 0x1b48000]
2013-07-17 21:50:59.701176 7f39a5eb1700 10 mds.0.cache.snaprealm(100 seq 1 0x1b39480) have_past_parents_open [1,head]
2013-07-17 21:50:59.701178 7f39a5eb1700 10 mds.0.cache have past snap parents for realm snaprealm(100 seq 1 lc 0 cr 0 cps 1 snaps={} 0x1b39480) on [inode 100 [...2,head] ~mds0/ auth v1 snaprealm=0x1b39480 f(v0 11=1+10) n(v0 11=1+10) (iversion lock) 0x1b48000]
2013-07-17 21:50:59.701190 7f39a5eb1700 10 mds.0.cache send_snaps
2013-07-17 21:50:59.701194 7f39a5eb1700 10 mds.0.cache identify_files_to_recover
2013-07-17 21:50:59.701201 7f39a5eb1700 7 mds.0.cache rejoin_send_acks
2013-07-17 21:50:59.701208 7f39a5eb1700 10 mds.0.cache open_snap_parents
2013-07-17 21:50:59.701209 7f39a5eb1700 10 mds.0.cache send_snaps
2013-07-17 21:50:59.701210 7f39a5eb1700 10 mds.0.cache open_snap_parents - all open
2013-07-17 21:50:59.701212 7f39a5eb1700 10 mds.0.cache do_delayed_cap_imports
2013-07-17 21:50:59.701218 7f39a5eb1700 20 mds.0.locker check_inode_max_size no-op on [inode 1 [...2,head] / auth v1 snaprealm=0x1b39900 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) 0x1b48860]
2013-07-17 21:50:59.701228 7f39a5eb1700 20 mds.0.locker check_inode_max_size no-op on [inode 100 [...2,head] ~mds0/ auth v1 snaprealm=0x1b39480 f(v0 11=1+10) n(v0 11=1+10) (iversion lock) 0x1b48000]
2013-07-17 21:50:59.701234 7f39a5eb1700 1 mds.0.2 rejoin_done
2013-07-17 21:50:59.701236 7f39a5eb1700 10 mds.0.cache show_subtrees - no subtrees
2013-07-17 21:50:59.701239 7f39a5eb1700 7 mds.0.cache show_cache
2013-07-17 21:50:59.701241 7f39a5eb1700 7 mds.0.cache unlinked [inode 1 [...2,head] / auth v1 snaprealm=0x1b39900 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) 0x1b48860]
2013-07-17 21:50:59.701248 7f39a5eb1700 7 mds.0.cache unlinked [inode 100 [...2,head] ~mds0/ auth v1 snaprealm=0x1b39480 f(v0 11=1+10) n(v0 11=1+10) (iversion lock) 0x1b48000]
2013-07-17 21:50:59.701254 7f39a5eb1700 1 mds.0.2 empty cache, no subtrees, leaving cluster
2013-07-17 21:50:59.701256 7f39a5eb1700 3 mds.0.2 request_state down:stopped
2013-07-17 21:50:59.701257 7f39a5eb1700 10 mds.0.2 beacon_send down:stopped seq 13 (currently up:rejoin)
2013-07-17 21:50:59.701274 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 --> 10.214.132.29:6790/0 -- mdsbeacon(4103/b-s-a down:stopped seq 13 v9) v2 -- ?+0 0x1b19b00 con 0x1aff840
2013-07-17 21:50:59.701296 7f39a5eb1700 10 mds.0.bal check_targets have need want
2013-07-17 21:50:59.701299 7f39a5eb1700 5 mds.0.bal rebalance done
2013-07-17 21:50:59.701301 7f39a5eb1700 10 mds.0.cache show_subtrees - no subtrees
2013-07-17 21:50:59.701318 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 30 ==== mdsbeacon(4103/b-s-a up:rejoin seq 12 v9) v2 ==== 107+0+0 (64745062 0 0) 0x1b19840 con 0x1aff840
2013-07-17 21:50:59.701330 7f39a5eb1700 10 mds.0.2 handle_mds_beacon up:rejoin seq 12 rtt 0.144061
2013-07-17 21:50:59.851244 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 <== mon.2 10.214.132.29:6790/0 31 ==== mdsmap(e 10) v1 ==== 368+0+0 (11291301 0 0) 0x1aec600 con 0x1aff840
2013-07-17 21:50:59.851274 7f39a5eb1700 5 mds.0.2 handle_mds_map epoch 10 from mon.2
2013-07-17 21:50:59.851292 7f39a5eb1700 10 mds.0.2 my compat 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}
2013-07-17 21:50:59.851301 7f39a5eb1700 10 mds.0.2 mdsmap compat 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}
2013-07-17 21:50:59.851311 7f39a5eb1700 10 mds.-1.-1 map says i am 10.214.131.17:6800/1089 mds.-1.-1 state down:dne
2013-07-17 21:50:59.851321 7f39a5eb1700 10 mds.-1.-1 peer mds gid 4103 removed from map
2013-07-17 21:50:59.851324 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down 10.214.131.17:6800/1089 -- pipe dne
2013-07-17 21:50:59.851328 7f39a5eb1700 1 mds.-1.-1 handle_mds_map i (10.214.131.17:6800/1089) dne in the mdsmap, respawning myself
2013-07-17 21:50:59.851335 7f39a5eb1700 1 mds.-1.-1 respawn
2013-07-17 21:50:59.851336 7f39a5eb1700 1 mds.-1.-1 e: 'ceph-mds'
2013-07-17 21:50:59.851337 7f39a5eb1700 1 mds.-1.-1 0: 'ceph-mds'
2013-07-17 21:50:59.851339 7f39a5eb1700 1 mds.-1.-1 1: '-f'
2013-07-17 21:50:59.851340 7f39a5eb1700 1 mds.-1.-1 2: '-i'
2013-07-17 21:50:59.851341 7f39a5eb1700 1 mds.-1.-1 3: 'b-s-a'
2013-07-17 21:50:59.851351 7f39a5eb1700 1 mds.-1.-1 cwd /home/ubuntu
2013-07-17 21:50:59.851379 7f39a5eb1700 0 mds.-1.-1 respawn execv ceph-mds failed with (2) No such file or directory
2013-07-17 21:50:59.851387 7f39a5eb1700 1 mds.-1.-1 suicide. wanted down:dne, now down:dne
2013-07-17 21:50:59.851398 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down 0x1affdc0 -- 0x1b2dc80
2013-07-17 21:50:59.851433 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down 0x1affb00 -- 0x1b2d780
2013-07-17 21:50:59.851460 7f39a25a2700 0 -- 10.214.131.17:6800/1089 >> 10.214.131.17:0/1109 pipe(0x1b59000 sd=21 :6800 s=2 pgs=12 cs=1 l=0).fault with nothing to send, going to standby
2013-07-17 21:50:59.851501 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down 0x1aff9a0 -- 0x1b2d280
2013-07-17 21:50:59.851615 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down 0x1affc60 -- 0x1b04c80
2013-07-17 21:50:59.851716 7f39a5eb1700 1 -- 10.214.131.17:6800/1089 mark_down_all
2013-07-17 21:50:59.854419 7f39aa631780 1 -- 10.214.131.17:6800/1089 shutdown complete.
2013-07-17 21:50:59.854535 7f39aa631780 0 stopped.
(1-1/2)