Bug #12321
closedMDS crash when try to connect clients
0%
Description
I have 3 mon 9 osd .
when I recovery after the disaster happened. I found that mds can't run.
log :
2015-07-14 16:14:31.515863 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:31.517419 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:31.517460 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:31.517482 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:31.517497 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 21 0x4a97b00 mdsbeacon(94247/codetest up:reconnect seq 6 v513) v3
2015-07-14 16:14:31.517534 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:31.517549 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 21
2015-07-14 16:14:31.517564 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:31.517582 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 21 ==== mdsbeacon(94247/codetest up:reconnect seq 6 v513) v3 ==== 120+0+0 (401768720 0 0) 0x4a97b00 con 0x4a3e160
2015-07-14 16:14:31.517620 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:14:35.515829 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 7 v513) v3 -- ?+0 0x4a96f00 con 0x4a3e160
2015-07-14 16:14:35.515894 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:35.515997 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:35.517577 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:35.517623 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:35.517645 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:35.517659 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 22 0x4a97800 mdsbeacon(94247/codetest up:reconnect seq 7 v513) v3
2015-07-14 16:14:35.517698 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:35.517729 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 22
2015-07-14 16:14:35.517750 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:35.517736 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 22 ==== mdsbeacon(94247/codetest up:reconnect seq 7 v513) v3 ==== 120+0+0 (3910525111 0 0) 0x4a97800 con 0x4a3e160
2015-07-14 16:14:35.517776 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:14:38.031639 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:38.031696 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_keepalive2 14 2015-07-14 16:14:38.031695
2015-07-14 16:14:38.031751 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:39.515916 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 8 v513) v3 -- ?+0 0x4a96000 con 0x4a3e160
2015-07-14 16:14:39.515994 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:39.516095 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:39.517857 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:39.517904 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:39.517952 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:39.517968 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 23 0x4b3c900 mdsbeacon(94247/codetest up:reconnect seq 8 v513) v3
2015-07-14 16:14:39.518009 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:39.518040 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 23
2015-07-14 16:14:39.518061 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:39.518058 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 23 ==== mdsbeacon(94247/codetest up:reconnect seq 8 v513) v3 ==== 120+0+0 (4106708175 0 0) 0x4b3c900 con 0x4a3e160
2015-07-14 16:14:39.518094 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:14:43.516003 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 9 v513) v3 -- ?+0 0x4b3d500 con 0x4a3e160
2015-07-14 16:14:43.516078 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:43.516176 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:43.517877 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:43.517921 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:43.517942 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:43.517956 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 24 0x4b3c600 mdsbeacon(94247/codetest up:reconnect seq 9 v513) v3
2015-07-14 16:14:43.517996 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:43.518027 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 24
2015-07-14 16:14:43.518047 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:43.518043 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 24 ==== mdsbeacon(94247/codetest up:reconnect seq 9 v513) v3 ==== 120+0+0 (169870696 0 0) 0x4b3c600 con 0x4a3e160
2015-07-14 16:14:43.518096 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:14:47.516088 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 10 v513) v3 -- ?+0 0x4b3d200 con 0x4a3e160
2015-07-14 16:14:47.516161 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:47.516270 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:47.517983 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:47.518029 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:47.518054 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:47.518068 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 25 0x4b3c300 mdsbeacon(94247/codetest up:reconnect seq 10 v513) v3
2015-07-14 16:14:47.518133 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:47.518163 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 25
2015-07-14 16:14:47.518153 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 25 ==== mdsbeacon(94247/codetest up:reconnect seq 10 v513) v3 ==== 120+0+0 (216387952 0 0) 0x4b3c300 con 0x4a3e160
2015-07-14 16:14:47.518185 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:14:47.518186 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:48.031821 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:48.031859 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_keepalive2 14 2015-07-14 16:14:48.031858
2015-07-14 16:14:48.031909 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:51.516208 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 11 v513) v3 -- ?+0 0x4b3cf00 con 0x4a3e160
2015-07-14 16:14:51.516285 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:51.516385 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:51.518222 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:51.518263 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:51.518287 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:51.518302 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 26 0x4b3c000 mdsbeacon(94247/codetest up:reconnect seq 11 v513) v3
2015-07-14 16:14:51.518346 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:51.518377 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 26
2015-07-14 16:14:51.518398 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:51.518400 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 26 ==== mdsbeacon(94247/codetest up:reconnect seq 11 v513) v3 ==== 120+0+0 (4060262615 0 0) 0x4b3c000 con 0x4a3e160
2015-07-14 16:14:51.518451 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:14:55.516268 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 12 v513) v3 -- ?+0 0x4b3cc00 con 0x4a3e160
2015-07-14 16:14:55.516344 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:55.516426 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:55.518102 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:55.518170 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:55.518194 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:55.518209 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 27 0x4b3d800 mdsbeacon(94247/codetest up:reconnect seq 12 v513) v3
2015-07-14 16:14:55.518249 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:55.518280 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 27
2015-07-14 16:14:55.518300 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:55.518294 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 27 ==== mdsbeacon(94247/codetest up:reconnect seq 12 v513) v3 ==== 120+0+0 (24017216 0 0) 0x4b3d800 con 0x4a3e160
2015-07-14 16:14:55.518343 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:14:58.031980 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:58.032017 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_keepalive2 14 2015-07-14 16:14:58.032016
2015-07-14 16:14:58.032089 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:59.516361 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 13 v513) v3 -- ?+0 0x4b3db00 con 0x4a3e160
2015-07-14 16:14:59.516433 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:59.516528 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:59.518354 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:14:59.518395 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:14:59.518417 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:14:59.518432 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 28 0x4b3d500 mdsbeacon(94247/codetest up:reconnect seq 13 v513) v3
2015-07-14 16:14:59.518470 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:59.518500 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 28
2015-07-14 16:14:59.518521 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:14:59.518522 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 28 ==== mdsbeacon(94247/codetest up:reconnect seq 13 v513) v3 ==== 120+0+0 (4287174887 0 0) 0x4b3d500 con 0x4a3e160
2015-07-14 16:14:59.518570 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:15:03.516471 7f3ea8de7700 1 -- 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:reconnect seq 14 v513) v3 -- ?+0 0x4b46f00 con 0x4a3e160
2015-07-14 16:15:03.516539 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:15:03.516642 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:15:03.518299 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 120 from dispatch throttler 0/104857600
2015-07-14 16:15:03.518348 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
2015-07-14 16:15:03.518372 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
2015-07-14 16:15:03.518389 7f3ea96e9700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 29 0x4a96000 mdsbeacon(94247/codetest up:reconnect seq 14 v513) v3
2015-07-14 16:15:03.518428 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:15:03.518459 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 29
2015-07-14 16:15:03.518481 7f3eb13d8700 10 -- 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
2015-07-14 16:15:03.518485 7f3eac6ef700 1 -- 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 29 ==== mdsbeacon(94247/codetest up:reconnect seq 14 v513) v3 ==== 120+0+0 (4182559999 0 0) 0x4a96000 con 0x4a3e160
2015-07-14 16:15:03.518537 7f3eac6ef700 10 -- 172.16.0.50:6800/25422 dispatch_throttle_release 120 to dispatch throttler 120/104857600
2015-07-14 16:15:05.036630 7f3ea95e8700 1 mds.0.server reconnect gave up on client.4254 172.16.0.60:0/17315
2015-07-14 16:15:05.043112 7f3ea95e8700 -1 ./include/interval_set.h: In function 'void interval_set<T>::insert(T, T) [with T = inodeno_t]' thread 7f3ea95e8700 time 2015-07-14 16:15:05.036693
./include/interval_set.h: 340: FAILED assert(0)
ceph version 9.0.0 (bd7989103911796eb5698cf208b0ccdc3370d707)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x72) [0xa623c2]
2: /usr/bin/ceph-mds() [0x69e82a]
3: (interval_set<inodeno_t>::insert(interval_set<inodeno_t> const&)+0x1eb) [0x744e7b]
4: (InoTable::project_release_ids(interval_set<inodeno_t>&)+0x73) [0x8c3893]
5: (Server::journal_close_session(Session*, int, Context*)+0x168) [0x70d0d8]
6: (Server::kill_session(Session*, Context*)+0x13b) [0x70d69b]
7: (Server::reconnect_tick()+0x128) [0x70d9d8]
8: (MDS::tick()+0x3fc) [0x6b1e0c]
9: (MDSInternalContextBase::complete(int)+0x15b) [0x8e6f2b]
10: (SafeTimer::timer_thread()+0x1af) [0xa5496f]
11: (SafeTimerThread::entry()+0xd) [0xa55f2d]
12: (()+0x6b50) [0x7f3eb0d70b50]
13: (clone()+0x6d) [0x7f3eaf8127bd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.--- begin dump of recent events ---
753> 2015-07-14 16:14:15.016688 7f3eb13e0780 5 asok(0x4a2e000) register_command perfcounters_dump hook 0x4a18050 :/0 rank.bind :/0
-752> 2015-07-14 16:14:15.016728 7f3eb13e0780 5 asok(0x4a2e000) register_command 1 hook 0x4a18050
-751> 2015-07-14 16:14:15.016739 7f3eb13e0780 5 asok(0x4a2e000) register_command perf dump hook 0x4a18050
-750> 2015-07-14 16:14:15.016756 7f3eb13e0780 5 asok(0x4a2e000) register_command perfcounters_schema hook 0x4a18050
-749> 2015-07-14 16:14:15.016761 7f3eb13e0780 5 asok(0x4a2e000) register_command 2 hook 0x4a18050
-748> 2015-07-14 16:14:15.016764 7f3eb13e0780 5 asok(0x4a2e000) register_command perf schema hook 0x4a18050
-747> 2015-07-14 16:14:15.016769 7f3eb13e0780 5 asok(0x4a2e000) register_command perf reset hook 0x4a18050
-746> 2015-07-14 16:14:15.016778 7f3eb13e0780 5 asok(0x4a2e000) register_command config show hook 0x4a18050
-745> 2015-07-14 16:14:15.016782 7f3eb13e0780 5 asok(0x4a2e000) register_command config set hook 0x4a18050
-744> 2015-07-14 16:14:15.016786 7f3eb13e0780 5 asok(0x4a2e000) register_command config get hook 0x4a18050
-743> 2015-07-14 16:14:15.016795 7f3eb13e0780 5 asok(0x4a2e000) register_command config diff hook 0x4a18050
-742> 2015-07-14 16:14:15.016799 7f3eb13e0780 5 asok(0x4a2e000) register_command log flush hook 0x4a18050
-741> 2015-07-14 16:14:15.016808 7f3eb13e0780 5 asok(0x4a2e000) register_command log dump hook 0x4a18050
-740> 2015-07-14 16:14:15.016812 7f3eb13e0780 5 asok(0x4a2e000) register_command log reopen hook 0x4a18050
-739> 2015-07-14 16:14:15.019122 7f3eb13e0780 0 ceph version 9.0.0 (bd7989103911796eb5698cf208b0ccdc3370d707), process ceph-mds, pid 25422
-738> 2015-07-14 16:14:15.019452 7f3eb13e0780 10 -
737> 2015-07-14 16:14:15.019464 7f3eb13e0780 10 accepter.accepter.bind 0.0.0.0:6800/25422 messenger.start
-736> 2015-07-14 16:14:15.019481 7f3eb13e0780 10 accepter.accepter.bind bound on random port 0.0.0.0:6800/0
-735> 2015-07-14 16:14:15.019491 7f3eb13e0780 10 accepter.accepter.bind bound to 0.0.0.0:6800/0
-734> 2015-07-14 16:14:15.019503 7f3eb13e0780 1 accepter.accepter.bind my_inst.addr is 0.0.0.0:6800/25422 need_addr=1
-733> 2015-07-14 16:14:15.020286 7f3eb13e0780 1 finished global_init_daemonize
-732> 2015-07-14 16:14:15.020767 7f3eb13e0780 5 asok(0x4a2e000) init /var/run/ceph/ceph-mds.codetest.asok
-731> 2015-07-14 16:14:15.020811 7f3eb13e0780 5 asok(0x4a2e000) bind_and_listen /var/run/ceph/ceph-mds.codetest.asok
-730> 2015-07-14 16:14:15.021100 7f3eb13e0780 5 asok(0x4a2e000) register_command 0 hook 0x4a16038
-729> 2015-07-14 16:14:15.021124 7f3eb13e0780 5 asok(0x4a2e000) register_command version hook 0x4a16038
-728> 2015-07-14 16:14:15.021131 7f3eb13e0780 5 asok(0x4a2e000) register_command git_version hook 0x4a16038
-727> 2015-07-14 16:14:15.021142 7f3eb13e0780 5 asok(0x4a2e000) register_command help hook 0x4a18030
-726> 2015-07-14 16:14:15.021156 7f3eb13e0780 5 asok(0x4a2e000) register_command get_command_descriptions hook 0x4a180a0
-725> 2015-07-14 16:14:15.021255 7f3eb13e0780 10 monclient(hunting): build_initial_monmap
-724> 2015-07-14 16:14:15.021231 7f3eae51a700 5 asok(0x4a2e000) entry start
-723> 2015-07-14 16:14:15.030308 7f3eb13e0780 1 -
722> 2015-07-14 16:14:15.030409 7f3eb13e0780 5 adding auth protocol: none 0.0.0.0:6800/25422 reaper_entry start
-721> 2015-07-14 16:14:15.030424 7f3eb13e0780 5 adding auth protocol: none
-720> 2015-07-14 16:14:15.030455 7f3ead6f1700 10 -
719> 2015-07-14 16:14:15.030496 7f3ead6f1700 10 - 0.0.0.0:6800/25422 reaper
718> 2015-07-14 16:14:15.030502 7f3ead6f1700 10 - 0.0.0.0:6800/25422 reaper done
717> 2015-07-14 16:14:15.030731 7f3eb13e0780 5 asok(0x4a2e000) register_command objecter_requests hook 0x4a180f0 0.0.0.0:6800/25422 ready 0.0.0.0:6800/25422
-716> 2015-07-14 16:14:15.030799 7f3eb13e0780 10 -
715> 2015-07-14 16:14:15.030906 7f3eb13e0780 1 accepter.accepter.start 0.0.0.0:6800/25422 connect_rank to 172.16.5.170:6789/0, creating pipe and registering
-714> 2015-07-14 16:14:15.030954 7f3eb13e0780 10 monclient(hunting): init
-713> 2015-07-14 16:14:15.030978 7f3eb13e0780 5 adding auth protocol: none
-712> 2015-07-14 16:14:15.030991 7f3eb13e0780 10 monclient(hunting): auth_supported 1 method none
-711> 2015-07-14 16:14:15.031016 7f3eab6ed700 10 accepter.accepter starting
-710> 2015-07-14 16:14:15.031190 7f3eb13e0780 10 log_channel(cluster) update_config to_monitors: true to_syslog: false syslog_facility: daemon prio: info)
-709> 2015-07-14 16:14:15.031213 7f3eb13e0780 -1 mds.-1.0 log_to_monitors {default=true}
-708> 2015-07-14 16:14:15.031243 7f3eb13e0780 10 monclient(hunting): _reopen_session rank -1 name
-707> 2015-07-14 16:14:15.031252 7f3eb13e0780 10 -
706> 2015-07-14 16:14:15.031344 7f3eb13e0780 10 - 0.0.0.0:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=-1 :0 s=1 pgs=0 cs=0 l=1 c=0x4a3e160).register_pipe
705> 2015-07-14 16:14:15.031395 7f3eb13e0780 10 - 0.0.0.0:6800/25422 get_connection mon.2 172.16.5.170:6789/0 new 0x4a7e000
704> 2015-07-14 16:14:15.031396 7f3eb13d8700 10 - 0.0.0.0:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=-1 :0 s=1 pgs=0 cs=0 l=1 c=0x4a3e160).writer: state = connecting policy.server=0
703> 2015-07-14 16:14:15.031433 7f3eb13d8700 10 - 0.0.0.0:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=-1 :0 s=1 pgs=0 cs=0 l=1 c=0x4a3e160).connect 0
702> 2015-07-14 16:14:15.031451 7f3eb13d8700 10 - 0.0.0.0:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :0 s=1 pgs=0 cs=0 l=1 c=0x4a3e160).connecting to 172.16.5.170:6789/0
701> 2015-07-14 16:14:15.031455 7f3eb13e0780 10 monclient(hunting): picked mon.noname-c con 0x4a3e160 addr 172.16.5.170:6789/0 0.0.0.0:6800/25422 --> 172.16.5.170:6789/0 -- auth(proto 0 33 bytes epoch 0) v1 -- ?+0 0x4a2c240 con 0x4a3e160
-700> 2015-07-14 16:14:15.031510 7f3eb13e0780 10 monclient(hunting): _send_mon_message to mon.noname-c at 172.16.5.170:6789/0
-699> 2015-07-14 16:14:15.031564 7f3eb13e0780 1 -
698> 2015-07-14 16:14:15.031600 7f3eb13e0780 10 monclient(hunting): renew_subs 172.16.0.50:6800/25422 learned my addr 172.16.0.50:6800/25422
-697> 2015-07-14 16:14:15.032184 7f3eb13d8700 1 -
696> 2015-07-14 16:14:15.032240 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=1 pgs=0 cs=0 l=1 c=0x4a3e160).connect sent my addr 172.16.0.50:6800/25422
695> 2015-07-14 16:14:15.032263 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=1 pgs=0 cs=0 l=1 c=0x4a3e160).connect sending gseq=1 cseq=0 proto=15
694> 2015-07-14 16:14:15.032520 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).connect success 1, lossy = 1, features 1125899906842623
693> 2015-07-14 16:14:15.032626 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
692> 2015-07-14 16:14:15.032657 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_keepalive2 14 2015-07-14 16:14:15.032653
691> 2015-07-14 16:14:15.032769 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
690> 2015-07-14 16:14:15.033222 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 495 from dispatch throttler 0/104857600
689> 2015-07-14 16:14:15.033271 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
688> 2015-07-14 16:14:15.033313 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
687> 2015-07-14 16:14:15.033334 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 1 0x4a2c6c0 mon_map magic: 0 v1
686> 2015-07-14 16:14:15.033363 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 24 from dispatch throttler 495/104857600
685> 2015-07-14 16:14:15.033380 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
684> 2015-07-14 16:14:15.033399 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
683> 2015-07-14 16:14:15.033367 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
682> 2015-07-14 16:14:15.033418 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 1
681> 2015-07-14 16:14:15.033428 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 2 0x4a2cb40 auth_reply(proto 1 0 (0) Success) v1
680> 2015-07-14 16:14:15.033423 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 1 ==== mon_map magic: 0 v1 ==== 495+0+0 (2629194327 0 0) 0x4a2c6c0 con 0x4a3e160
679> 2015-07-14 16:14:15.033483 7f3eac6ef700 10 monclient(hunting): handle_monmap mon_map magic: 0 v1 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
-678> 2015-07-14 16:14:15.033473 7f3eb13d8700 10 -
677> 2015-07-14 16:14:15.033491 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 2
676> 2015-07-14 16:14:15.033503 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
-675> 2015-07-14 16:14:15.033510 7f3eac6ef700 10 monclient(hunting): got monmap 2, mon.noname-c is now rank -1
-674> 2015-07-14 16:14:15.033515 7f3eac6ef700 10 monclient(hunting): dump:
epoch 2
fsid a09e3308-e4ed-4c15-973e-d21142b6be04
last_changed 2015-05-28 18:29:46.831963
created 0.000000
0: 172.16.0.50:6789/0 mon.codetest
1: 172.16.0.60:6789/0 mon.cctext
2: 172.16.5.170:6789/0 mon.cloudCode04
673> 2015-07-14 16:14:15.033603 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 495 to dispatch throttler 519/104857600
672> 2015-07-14 16:14:15.033627 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 2 ==== auth_reply(proto 1 0 (0) Success) v1 ==== 24+0+0 (763678429 0 0) 0x4a2cb40 con 0x4a3e160
671> 2015-07-14 16:14:15.033667 7f3eac6ef700 10 monclient(hunting): my global_id is 94247
-670> 2015-07-14 16:14:15.033673 7f3eac6ef700 1 monclient(hunting): found mon.cloudCode04
-669> 2015-07-14 16:14:15.033676 7f3eac6ef700 10 monclient: _send_mon_message to mon.cloudCode04 at 172.16.5.170:6789/0
-668> 2015-07-14 16:14:15.033683 7f3eac6ef700 1 - 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x4a38400 con 0x4a3e160
667> 2015-07-14 16:14:15.033737 7f3eac6ef700 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2015-07-14 16:13:45.033734)
-666> 2015-07-14 16:14:15.033740 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
665> 2015-07-14 16:14:15.033761 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 24 to dispatch throttler 24/104857600
664> 2015-07-14 16:14:15.033771 7f3eb13e0780 5 monclient: authenticate success, global_id 94247
-663> 2015-07-14 16:14:15.033803 7f3eb13e0780 10 monclient: renew_subs
-662> 2015-07-14 16:14:15.033802 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
661> 2015-07-14 16:14:15.033811 7f3eb13e0780 10 monclient: _send_mon_message to mon.cloudCode04 at 172.16.5.170:6789/0
-660> 2015-07-14 16:14:15.033824 7f3eb13e0780 1 - 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mon_subscribe({monmap=3+,osdmap=0}) v2 -- ?+0 0x4a38200 con 0x4a3e160
659> 2015-07-14 16:14:15.033848 7f3eb13e0780 10 monclient: renew_subs
-658> 2015-07-14 16:14:15.033856 7f3eb13e0780 10 monclient: _send_mon_message to mon.cloudCode04 at 172.16.5.170:6789/0
-657> 2015-07-14 16:14:15.033848 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
656> 2015-07-14 16:14:15.033871 7f3eb13e0780 1 - 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mon_subscribe({mdsmap=0+,monmap=3+,osdmap=0}) v2 -- ?+0 0x4a38c00 con 0x4a3e160
655> 2015-07-14 16:14:15.033912 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
654> 2015-07-14 16:14:15.033958 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
653> 2015-07-14 16:14:15.034411 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 495 from dispatch throttler 0/104857600
652> 2015-07-14 16:14:15.034439 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
651> 2015-07-14 16:14:15.034454 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
650> 2015-07-14 16:14:15.034480 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 3 0x4a2c900 mon_map magic: 0 v1
649> 2015-07-14 16:14:15.034535 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 20 from dispatch throttler 495/104857600
648> 2015-07-14 16:14:15.034559 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
647> 2015-07-14 16:14:15.034541 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
646> 2015-07-14 16:14:15.034571 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 3
645> 2015-07-14 16:14:15.034595 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
644> 2015-07-14 16:14:15.034594 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
643> 2015-07-14 16:14:15.034584 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 3 ==== mon_map magic: 0 v1 ==== 495+0+0 (2629194327 0 0) 0x4a2c900 con 0x4a3e160
642> 2015-07-14 16:14:15.034618 7f3eac6ef700 10 monclient: handle_monmap mon_map magic: 0 v1
-641> 2015-07-14 16:14:15.034616 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 4 0x4a8e000 mon_subscribe_ack(300s) v1
-640> 2015-07-14 16:14:15.034641 7f3eac6ef700 10 monclient: got monmap 2, mon.cloudCode04 is now rank 2
-639> 2015-07-14 16:14:15.034646 7f3eac6ef700 10 monclient: dump:
epoch 2
fsid a09e3308-e4ed-4c15-973e-d21142b6be04
last_changed 2015-05-28 18:29:46.831963
created 0.000000
0: 172.16.0.50:6789/0 mon.codetest
1: 172.16.0.60:6789/0 mon.cctext
2: 172.16.5.170:6789/0 mon.cloudCode04638> 2015-07-14 16:14:15.034684 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
637> 2015-07-14 16:14:15.034692 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 495 to dispatch throttler 515/104857600
636> 2015-07-14 16:14:15.034688 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 8077 from dispatch throttler 515/104857600
635> 2015-07-14 16:14:15.034699 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 4
634> 2015-07-14 16:14:15.034709 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 4 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (892755957 0 0) 0x4a8e000 con 0x4a3e160
633> 2015-07-14 16:14:15.034712 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
632> 2015-07-14 16:14:15.034734 7f3eac6ef700 10 monclient: handle_subscribe_ack sent 2015-07-14 16:14:15.031616 renew after 2015-07-14 16:16:45.031616
-631> 2015-07-14 16:14:15.034751 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 20 to dispatch throttler 8097/104857600
630> 2015-07-14 16:14:15.034795 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
629> 2015-07-14 16:14:15.034855 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
628> 2015-07-14 16:14:15.034876 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 5 0x4a2cd80 osd_map(2382..2382 src has 1757..2382) v3
627> 2015-07-14 16:14:15.034901 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 20 from dispatch throttler 8077/104857600
626> 2015-07-14 16:14:15.034906 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
625> 2015-07-14 16:14:15.034918 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
624> 2015-07-14 16:14:15.034920 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 5
623> 2015-07-14 16:14:15.034912 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 5 ==== osd_map(2382..2382 src has 1757..2382) v3 ==== 8077+0+0 (2554887417 0 0) 0x4a2cd80 con 0x4a3e160
622> 2015-07-14 16:14:15.034932 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
621> 2015-07-14 16:14:15.034933 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
620> 2015-07-14 16:14:15.034962 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 6 0x4a8e3c0 mon_subscribe_ack(300s) v1
619> 2015-07-14 16:14:15.034984 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 680 from dispatch throttler 8097/104857600
618> 2015-07-14 16:14:15.034989 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
617> 2015-07-14 16:14:15.034999 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
616> 2015-07-14 16:14:15.035003 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 6
615> 2015-07-14 16:14:15.035013 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
614> 2015-07-14 16:14:15.035014 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
613> 2015-07-14 16:14:15.035039 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 7 0x4a2cb40 mdsmap(e 510) v1
612> 2015-07-14 16:14:15.035062 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
611> 2015-07-14 16:14:15.035058 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 8077 from dispatch throttler 8777/104857600
610> 2015-07-14 16:14:15.035074 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 7
609> 2015-07-14 16:14:15.035087 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
608> 2015-07-14 16:14:15.035106 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
607> 2015-07-14 16:14:15.035139 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
606> 2015-07-14 16:14:15.035155 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 8 0x4a2c6c0 osd_map(2382..2382 src has 1757..2382) v3
605> 2015-07-14 16:14:15.035175 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 20 from dispatch throttler 16854/104857600
604> 2015-07-14 16:14:15.035179 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
603> 2015-07-14 16:14:15.035188 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
602> 2015-07-14 16:14:15.035193 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 8
601> 2015-07-14 16:14:15.035200 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
600> 2015-07-14 16:14:15.035205 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
599> 2015-07-14 16:14:15.035232 7f3eac6ef700 10 monclient: renew_subs
-598> 2015-07-14 16:14:15.035228 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 9 0x4a8e1e0 mon_subscribe_ack(300s) v1
597> 2015-07-14 16:14:15.035245 7f3eac6ef700 10 monclient: _send_mon_message to mon.cloudCode04 at 172.16.5.170:6789/0
-596> 2015-07-14 16:14:15.035254 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
595> 2015-07-14 16:14:15.035255 7f3eac6ef700 1 - 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mon_subscribe({mdsmap=0+,monmap=3+,osdmap=2383}) v2 -- ?+0 0x4a38200 con 0x4a3e160
594> 2015-07-14 16:14:15.035268 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 9
593> 2015-07-14 16:14:15.035295 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 8077 to dispatch throttler 16874/104857600
592> 2015-07-14 16:14:15.035309 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 6 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (892755957 0 0) 0x4a8e3c0 con 0x4a3e160
591> 2015-07-14 16:14:15.035313 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
590> 2015-07-14 16:14:15.035325 7f3eac6ef700 10 monclient: handle_subscribe_ack sent 2015-07-14 16:14:15.035242 renew after 2015-07-14 16:16:45.035242
-589> 2015-07-14 16:14:15.035349 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 20 to dispatch throttler 8797/104857600
588> 2015-07-14 16:14:15.035365 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 7 ==== mdsmap(e 510) v1 ==== 680+0+0 (2892432026 0 0) 0x4a2cb40 con 0x4a3e160
587> 2015-07-14 16:14:15.035479 7f3eb13e0780 10 monclient: _send_mon_message to mon.cloudCode04 at 172.16.5.170:6789/0
-586> 2015-07-14 16:14:15.035498 7f3eb13e0780 1 - 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mdsbeacon(94247/codetest up:boot seq 1 v0) v3 -- ?+0 0x4a96000 con 0x4a3e160
585> 2015-07-14 16:14:15.035608 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
584> 2015-07-14 16:14:15.035666 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
583> 2015-07-14 16:14:15.035745 7f3eb13e0780 5 asok(0x4a2e000) register_command status hook 0x4a181a0
-582> 2015-07-14 16:14:15.035767 7f3eb13e0780 5 asok(0x4a2e000) register_command dump_ops_in_flight hook 0x4a181a0
-581> 2015-07-14 16:14:15.035777 7f3eb13e0780 5 asok(0x4a2e000) register_command ops hook 0x4a181a0
-580> 2015-07-14 16:14:15.035785 7f3eb13e0780 5 asok(0x4a2e000) register_command dump_historic_ops hook 0x4a181a0
-579> 2015-07-14 16:14:15.035795 7f3eb13e0780 5 asok(0x4a2e000) register_command scrub_path hook 0x4a181a0
-578> 2015-07-14 16:14:15.035805 7f3eb13e0780 5 asok(0x4a2e000) register_command flush_path hook 0x4a181a0
-577> 2015-07-14 16:14:15.035814 7f3eb13e0780 5 asok(0x4a2e000) register_command export dir hook 0x4a181a0
-576> 2015-07-14 16:14:15.035824 7f3eb13e0780 5 asok(0x4a2e000) register_command dump cache hook 0x4a181a0
-575> 2015-07-14 16:14:15.035832 7f3eb13e0780 5 asok(0x4a2e000) register_command session evict hook 0x4a181a0
-574> 2015-07-14 16:14:15.035841 7f3eb13e0780 5 asok(0x4a2e000) register_command osdmap barrier hook 0x4a181a0
-573> 2015-07-14 16:14:15.035847 7f3eb13e0780 5 asok(0x4a2e000) register_command session ls hook 0x4a181a0
-572> 2015-07-14 16:14:15.035868 7f3eb13e0780 5 asok(0x4a2e000) register_command flush journal hook 0x4a181a0
-571> 2015-07-14 16:14:15.035878 7f3eb13e0780 5 asok(0x4a2e000) register_command force_readonly hook 0x4a181a0
-570> 2015-07-14 16:14:15.035895 7f3eb13e0780 5 asok(0x4a2e000) register_command get subtrees hook 0x4a181a0
-569> 2015-07-14 16:14:15.035948 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 680 from dispatch throttler 8777/104857600
568> 2015-07-14 16:14:15.035980 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
567> 2015-07-14 16:14:15.035974 7f3eac6ef700 5 mds.-1.0 handle_mds_map epoch 510 from mon.2
-566> 2015-07-14 16:14:15.036007 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
565> 2015-07-14 16:14:15.036010 7f3eb13e0780 10 - 172.16.0.50:6800/25422 wait: waiting for dispatch queue
564> 2015-07-14 16:14:15.036021 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 10 0x4a2d680 mdsmap(e 510) v1
563> 2015-07-14 16:14:15.036038 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 20 from dispatch throttler 9457/104857600
562> 2015-07-14 16:14:15.036070 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
561> 2015-07-14 16:14:15.036062 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
560> 2015-07-14 16:14:15.036085 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
559> 2015-07-14 16:14:15.036093 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 10
558> 2015-07-14 16:14:15.036096 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 11 0x4a8e5a0 mon_subscribe_ack(300s) v1
557> 2015-07-14 16:14:15.036103 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 680 to dispatch throttler 9477/104857600
556> 2015-07-14 16:14:15.036113 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
555> 2015-07-14 16:14:15.036131 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 11
554> 2015-07-14 16:14:15.036143 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
553> 2015-07-14 16:14:15.036130 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 8 ==== osd_map(2382..2382 src has 1757..2382) v3 ==== 8077+0+0 (2554887417 0 0) 0x4a2c6c0 con 0x4a3e160
552> 2015-07-14 16:14:15.036194 7f3eac6ef700 10 monclient: renew_subs
-551> 2015-07-14 16:14:15.036202 7f3eac6ef700 10 monclient: _send_mon_message to mon.cloudCode04 at 172.16.5.170:6789/0
-550> 2015-07-14 16:14:15.036209 7f3eac6ef700 1 - 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mon_subscribe({mdsmap=511+,monmap=3+,osdmap=2383}) v2 -- ?+0 0x4a38600 con 0x4a3e160
549> 2015-07-14 16:14:15.036232 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 8077 to dispatch throttler 8797/104857600
548> 2015-07-14 16:14:15.036237 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
547> 2015-07-14 16:14:15.036242 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 9 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (892755957 0 0) 0x4a8e1e0 con 0x4a3e160
546> 2015-07-14 16:14:15.036290 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
545> 2015-07-14 16:14:15.036258 7f3eac6ef700 10 monclient: handle_subscribe_ack sent 2015-07-14 16:14:15.036199 renew after 2015-07-14 16:16:45.036199
-544> 2015-07-14 16:14:15.036317 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 20 to dispatch throttler 720/104857600
543> 2015-07-14 16:14:15.036330 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 10 ==== mdsmap(e 510) v1 ==== 680+0+0 (2892432026 0 0) 0x4a2d680 con 0x4a3e160
542> 2015-07-14 16:14:15.036347 7f3eac6ef700 5 mds.-1.-1 handle_mds_map epoch 510 from mon.2
-541> 2015-07-14 16:14:15.036352 7f3eac6ef700 5 mds.-1.-1 old map epoch 510 <= 510, discarding
-540> 2015-07-14 16:14:15.036357 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 680 to dispatch throttler 700/104857600
539> 2015-07-14 16:14:15.036370 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 11 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (892755957 0 0) 0x4a8e5a0 con 0x4a3e160
538> 2015-07-14 16:14:15.036395 7f3eac6ef700 10 monclient: handle_subscribe_ack sent 0.000000, ignoring
-537> 2015-07-14 16:14:15.036400 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 20 to dispatch throttler 20/104857600
536> 2015-07-14 16:14:15.036849 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 20 from dispatch throttler 0/104857600
535> 2015-07-14 16:14:15.036881 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
534> 2015-07-14 16:14:15.036898 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
533> 2015-07-14 16:14:15.036911 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 12 0x4a8e3c0 mon_subscribe_ack(300s) v1
532> 2015-07-14 16:14:15.036948 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 12 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (892755957 0 0) 0x4a8e3c0 con 0x4a3e160
531> 2015-07-14 16:14:15.036948 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
530> 2015-07-14 16:14:15.036976 7f3eac6ef700 10 monclient: handle_subscribe_ack sent 0.000000, ignoring
-529> 2015-07-14 16:14:15.036981 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 20 to dispatch throttler 20/104857600
528> 2015-07-14 16:14:15.036979 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 12
527> 2015-07-14 16:14:15.037001 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
526> 2015-07-14 16:14:15.170211 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 358 from dispatch throttler 0/104857600
525> 2015-07-14 16:14:15.170253 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
524> 2015-07-14 16:14:15.170274 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
523> 2015-07-14 16:14:15.170312 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 13 0x4a2d440 osd_map(2383..2383 src has 1757..2383) v3
522> 2015-07-14 16:14:15.170354 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
521> 2015-07-14 16:14:15.170384 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 13
520> 2015-07-14 16:14:15.170402 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
519> 2015-07-14 16:14:15.170400 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 13 ==== osd_map(2383..2383 src has 1757..2383) v3 ==== 358+0+0 (3081206777 0 0) 0x4a2d440 con 0x4a3e160
518> 2015-07-14 16:14:15.170486 7f3eac6ef700 10 monclient: renew_subs
-517> 2015-07-14 16:14:15.170502 7f3eac6ef700 10 monclient: _send_mon_message to mon.cloudCode04 at 172.16.5.170:6789/0
-516> 2015-07-14 16:14:15.170521 7f3eac6ef700 1 - 172.16.0.50:6800/25422 --> 172.16.5.170:6789/0 -- mon_subscribe({mdsmap=511+,monmap=3+,osdmap=2384}) v2 -- ?+0 0x4a38600 con 0x4a3e160
515> 2015-07-14 16:14:15.170557 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 358 to dispatch throttler 358/104857600
514> 2015-07-14 16:14:15.170593 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
513> 2015-07-14 16:14:15.170671 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
512> 2015-07-14 16:14:15.236983 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 20 from dispatch throttler 0/104857600
511> 2015-07-14 16:14:15.237025 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
510> 2015-07-14 16:14:15.237042 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
509> 2015-07-14 16:14:15.237057 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 14 0x4a8e000 mon_subscribe_ack(300s) v1
508> 2015-07-14 16:14:15.237100 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
507> 2015-07-14 16:14:15.237130 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 14
506> 2015-07-14 16:14:15.237151 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
505> 2015-07-14 16:14:15.237145 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 14 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (892755957 0 0) 0x4a8e000 con 0x4a3e160
504> 2015-07-14 16:14:15.237182 7f3eac6ef700 10 monclient: handle_subscribe_ack sent 2015-07-14 16:14:15.170498 renew after 2015-07-14 16:16:45.170498
-503> 2015-07-14 16:14:15.237217 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 20 to dispatch throttler 20/104857600
502> 2015-07-14 16:14:15.396583 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wants 672 from dispatch throttler 0/104857600
501> 2015-07-14 16:14:15.396650 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).aborted = 0
500> 2015-07-14 16:14:15.396671 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).No session security set
499> 2015-07-14 16:14:15.396686 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader got message 15 0x4a2d200 mdsmap(e 511) v1
498> 2015-07-14 16:14:15.396731 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
497> 2015-07-14 16:14:15.396762 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).write_ack 15
496> 2015-07-14 16:14:15.396765 7f3eac6ef700 1 - 172.16.0.50:6800/25422 <== mon.2 172.16.5.170:6789/0 15 ==== mdsmap(e 511) v1 ==== 672+0+0 (2417860917 0 0) 0x4a2d200 con 0x4a3e160
495> 2015-07-14 16:14:15.396780 7f3eb13d8700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).writer: state = open policy.server=0
494> 2015-07-14 16:14:15.396798 7f3eac6ef700 5 mds.-1.-1 handle_mds_map epoch 511 from mon.2
-493> 2015-07-14 16:14:15.396841 7f3eac6ef700 1 - 172.16.0.50:6800/25422 mark_down 172.16.0.50:6800/25308 -- pipe dne
492> 2015-07-14 16:14:15.396876 7f3eac6ef700 1 mds.-1.0 handle_mds_map standby
-491> 2015-07-14 16:14:15.396918 7f3eac6ef700 10 - 172.16.0.50:6800/25422 dispatch_throttle_release 672 to dispatch throttler 672/104857600
490> 2015-07-14 16:14:15.496974 7f3ea96e9700 10 - 172.16.0.50:6800/25422 >> 172.16.5.170:6789/0 pipe(0x4a7e000 sd=8 :36805 s=2 pgs=6011 cs=1 l=1 c=0x4a3e160).reader wantFiles
Updated by Greg Farnum almost 9 years ago
- Project changed from Ceph to CephFS
What's the disaster that happened? Did you lose some of your RADOS objects?
Updated by John Spray almost 9 years ago
This indicates an inconsistency between the inodes apparently allocated to the session, and those marked as free in the inotable.
Please tell us as much as you can about how the system got into this state, especially what the "disaster" was. If you have a journal, export it to a file with "cephfs-journal-tool export myjournal.bin", and upload it somewhere if you can.
This situation could happen if for example the MDS journal had been reset. If that's what you did, then you can try to make the sessionmap consistent with that by clearing it, with "cephfs-table-tool reset session". Note that this is a destructive operation, and not guaranteed to make things better (it could make things worse)
If you get your MDS to come back online, exercise caution; you might end up in a situation where the MDS incorrectly thinks some inodes numbers are free that actually have data in them. The tool for correcting that isn't there yet (#12131)
Updated by zcc icy almost 9 years ago
Greg Farnum wrote:
What's the disaster that happened? Did you lose some of your RADOS objects?
I deploy 3 mon & 5 osd & 2 mds in 5 machine. Then I shutdown the three machines what have 1 mon , 3 osd, 1 mds .
Then I reboot the machines, the mds cluster doesn't work, When I restart mds process,The process crash when try to reconnect other session.
Then I try to reset the session . I try to use "cephfs-table-tool all reset session" . The mds status change to active . But still crash.
0> 2015-07-15 12:19:14.119167 7f513c6e0700 1 mds/CDir.cc: In function 'void CDir::_committed(int, version_t)' thread 7f513c6e0700 time 2015-07-15 12:19:14.115860
mds/CDir.cc: 2160: FAILED assert(in>is_dirty() || in->last < ((__u64)(-2)))ceph status
cluster a09e3308-e4ed-4c15-973e-d21142b6be04
health HEALTH_WARN
1 requests are blocked > 32 sec
mds codetest is laggy
monmap e2: 3 mons at {cctext=172.16.0.60:6789/0,cloudCode04=172.16.5.170:6789/0,codetest=172.16.0.50:6789/0}
election epoch 70, quorum 0,1,2 codetest,cctext,cloudCode04
mdsmap e553: 1/1/2 up {0=codetest=up:active(laggy or crashed)}
osdmap e2399: 9 osds: 9 up, 9 in
pgmap v139131: 144 pgs, 3 pools, 156 GB data, 159 kobjects
708 GB used, 9055 GB / 10285 GB avail
144 active+clean
Updated by zcc icy almost 9 years ago
John Spray wrote:
This indicates an inconsistency between the inodes apparently allocated to the session, and those marked as free in the inotable.
Please tell us as much as you can about how the system got into this state, especially what the "disaster" was. If you have a journal, export it to a file with "cephfs-journal-tool export myjournal.bin", and upload it somewhere if you can.
This situation could happen if for example the MDS journal had been reset. If that's what you did, then you can try to make the sessionmap consistent with that by clearing it, with "cephfs-table-tool reset session". Note that this is a destructive operation, and not guaranteed to make things better (it could make things worse)
If you get your MDS to come back online, exercise caution; you might end up in a situation where the MDS incorrectly thinks some inodes numbers are free that actually have data in them. The tool for correcting that isn't there yet (#12131)
I deploy 3 mon & 5 osd & 2 mds in 5 machine. Then I shutdown the three machines what have 1 mon , 3 osd, 1 mds .
Then I reboot the machines, the mds cluster doesn't work, When I restart mds process,The process crash when try to reconnect other session.
Then I try to reset the session . I try to use "cephfs-table-tool all reset session" . The mds status change to active . But still crash.
0> 2015-07-15 12:19:14.119167 7f513c6e0700 1 mds/CDir.cc: In function 'void CDir::_committed(int, version_t)' thread 7f513c6e0700 time 2015-07-15 12:19:14.115860
mds/CDir.cc: 2160: FAILED assert(in>is_dirty() || in->last < ((__u64)(-2)))
ceph status
cluster a09e3308-e4ed-4c15-973e-d21142b6be04
health HEALTH_WARN
1 requests are blocked > 32 sec
mds codetest is laggy
monmap e2: 3 mons at {cctext=172.16.0.60:6789/0,cloudCode04=172.16.5.170:6789/0,codetest=172.16.0.50:6789/0}
election epoch 70, quorum 0,1,2 codetest,cctext,cloudCode04
mdsmap e553: 1/1/2 up {0=codetest=up:active(laggy or crashed)}
osdmap e2399: 9 osds: 9 up, 9 in
pgmap v139131: 144 pgs, 3 pools, 156 GB data, 159 kobjects
708 GB used, 9055 GB / 10285 GB avail
144 active+clean
Updated by zcc icy almost 9 years ago
zcc icy wrote:
John Spray wrote:
This indicates an inconsistency between the inodes apparently allocated to the session, and those marked as free in the inotable.
Please tell us as much as you can about how the system got into this state, especially what the "disaster" was. If you have a journal, export it to a file with "cephfs-journal-tool export myjournal.bin", and upload it somewhere if you can.
This situation could happen if for example the MDS journal had been reset. If that's what you did, then you can try to make the sessionmap consistent with that by clearing it, with "cephfs-table-tool reset session". Note that this is a destructive operation, and not guaranteed to make things better (it could make things worse)
If you get your MDS to come back online, exercise caution; you might end up in a situation where the MDS incorrectly thinks some inodes numbers are free that actually have data in them. The tool for correcting that isn't there yet (#12131)
I deploy 3 mon & 5 osd & 2 mds in 5 machine. Then I shutdown the three machines what have 1 mon , 3 osd, 1 mds .
Then I reboot the machines, the mds cluster doesn't work, When I restart mds process,The process crash when try to reconnect other session.
Then I try to reset the session . I try to use "cephfs-table-tool all reset session" . The mds status change to active . But still crash.
after i reset session , inode may be missing
16 2015-07-15 12:10:23.440983 7fc201fa5700 1 mds.0.server reconnect_clients -- 1 sessions
17 2015-07-15 12:10:23.442869 7fc1fb28c700 1 mds.0.84 ms_verify_authorizer: cannot decode auth caps bl of length 0
18 2015-07-15 12:10:23.845644 7fc201fa5700 0 log_channel(cluster) log [DBG] : reconnect by client.114285 172.16.0.50:0/19082 after 0.404554
19 2015-07-15 12:10:23.973255 7fc201fa5700 1 mds.0.84 reconnect_done
20 2015-07-15 12:10:24.496473 7fc201fa5700 1 mds.0.84 handle_mds_map i am now mds.0.84
21 2015-07-15 12:10:24.496481 7fc201fa5700 1 mds.0.84 handle_mds_map state change up:reconnect --> up:rejoin
22 2015-07-15 12:10:24.496486 7fc201fa5700 1 mds.0.84 rejoin_start
23 2015-07-15 12:10:29.278089 7fc201fa5700 1 mds.0.84 rejoin_joint_start
24 2015-07-15 12:10:33.049698 7fc1fde9c700 1 mds.0.84 rejoin_done
25 2015-07-15 12:10:33.281334 7fc201fa5700 1 mds.0.84 handle_mds_map i am now mds.0.84
26 2015-07-15 12:10:33.281343 7fc201fa5700 1 mds.0.84 handle_mds_map state change up:rejoin --> up:active
27 2015-07-15 12:10:33.281347 7fc201fa5700 1 mds.0.84 recovery_done -- successful recovery!
28 2015-07-15 12:10:33.309625 7fc201fa5700 1 mds.0.84 active_start
29 2015-07-15 12:10:35.087789 7fc201fa5700 0 log_channel(cluster) log [WRN] : failed to reconnect caps for missing inodes:
30 2015-07-15 12:10:35.087803 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 10000000002
31 2015-07-15 12:10:35.087808 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 100000002d8
32 2015-07-15 12:10:35.087814 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 100000002d9
33 2015-07-15 12:10:35.087820 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 100000002da
34 2015-07-15 12:10:35.087824 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 100000002db
35 2015-07-15 12:10:35.087828 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 100000002dc
36 2015-07-15 12:10:35.087833 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 100000002dd
37 2015-07-15 12:10:35.087837 7fc201fa5700 0 log_channel(cluster) log [WRN] : ino 100000002de0> 2015-07-15 12:19:14.119167 7f513c6e0700 1 mds/CDir.cc: In function 'void CDir::_committed(int, version_t)' thread 7f513c6e0700 time 2015-07-15 12:19:14.115860
mds/CDir.cc: 2160: FAILED assert(in>is_dirty() || in->last < ((__u64)(-2)))
ceph statuscluster a09e3308-e4ed-4c15-973e-d21142b6be04
health HEALTH_WARN
1 requests are blocked > 32 sec
mds codetest is laggy
monmap e2: 3 mons at {cctext=172.16.0.60:6789/0,cloudCode04=172.16.5.170:6789/0,codetest=172.16.0.50:6789/0}
election epoch 70, quorum 0,1,2 codetest,cctext,cloudCode04
mdsmap e553: 1/1/2 up {0=codetest=up:active(laggy or crashed)}
osdmap e2399: 9 osds: 9 up, 9 in
pgmap v139131: 144 pgs, 3 pools, 156 GB data, 159 kobjects
708 GB used, 9055 GB / 10285 GB avail
144 active+clean
Updated by John Spray almost 9 years ago
After you've destroyed the MDS's record of client sessions, it's important to make sure that those clients don't exist in the real world as well. Kill all the mounts (you may need to reboot machines if they are using the kernel client).
I notice in the original log that the journal is very short, so presumably this isn't a real system that you need to recover data from.
I also notice that you've got max_mds set to 2 -- were there ever two active MDSs?
Updated by John Spray over 8 years ago
Hi, do you have any updates for us on this? If the system is unavailable for any more debug then we'll close this.
Updated by zcc icy over 8 years ago
John Spray wrote:
Hi, do you have any updates for us on this? If the system is unavailable for any more debug then we'll close this.
I try to remove fs and renew it. I found it can work. maybe dirty data make it crashed. thank you for your help.
Updated by John Spray over 8 years ago
- Status changed from New to Can't reproduce