Bug #8651
Updated by Sage Weil over 9 years ago
2 active mds, crashing while writing 4 rsync streams to it with cephko
{ "mdsmap": { "epoch": 1428,
"flags": 0,
"created": "2014-06-17 16:18:31.237442",
"modified": "2014-06-24 10:55:46.211994",
"tableserver": 0,
"root": 0,
"session_timeout": 60,
"session_autoclose": 300,
"max_file_size": 1099511627776,
"last_failure": 1419,
"last_failure_osd_epoch": 814,
"compat": { "compat": {},
"ro_compat": {},
"incompat": { "feature_1": "base v0.20",
"feature_2": "client writeable ranges",
"feature_3": "default file layouts on dirs",
"feature_4": "dir inode in separate object",
"feature_5": "mds uses versioned encoding",
"feature_6": "dirfrag is stored in omap",
"feature_8": "no anchor table"}},
"max_mds": 2,
"in": [
0,
1],
"up": { "mds_0": 23863,
"mds_1": 24119},
"failed": [],
"stopped": [],
"info": { "gid_23863": { "gid": 23863,
"name": "ceph002.cubone.os",
"rank": 0,
"incarnation": 147,
"state": "up:active",
"state_seq": 82,
"addr": "10.141.8.181:6833\/49442",
"standby_for_rank": -1,
"standby_for_name": "",
"export_targets": []},
"gid_24119": { "gid": 24119,
"name": "ceph001.cubone.os",
"rank": 1,
"incarnation": 34,
"state": "up:active",
"state_seq": 19,
"addr": "10.141.8.180:6831\/37285",
"standby_for_rank": -1,
"standby_for_name": "",
"export_targets": []}},
"data_pools": [
0],
"metadata_pool": 1},
"mdsmap_first_committed": 751,
"mdsmap_last_committed": 1428}
<pre>
-69> 2014-06-24 10:49:07.213947 7f76628c6700 10 monclient(hunting): renew_subs
-68> 2014-06-24 10:49:07.213952 7f76628c6700 1 -- 10.141.8.182:6832/43239 <== osd.10 10.141.8.181:6800/24877 10005 ==== osd_op_reply(7
0278 1000009f90c.00000000 [??? 1~0,omap-set-header 0~222,omap-set-vals 0~6417,omap-rm-keys 0~433] v811'232250 uv232250 ondisk = 0) v6 ====
313+0+0 (4229282455 0 0) 0x2624b0c80 con 0x375a3c0
-67> 2014-06-24 10:49:07.214029 7f76628c6700 5 mds.1.33 is_laggy 79.848239 > 15 since last acked beacon
-66> 2014-06-24 10:49:07.214035 7f76628c6700 5 mds.1.33 initiating monitor reconnect; maybe we're not the slow one
-65> 2014-06-24 10:49:07.214037 7f76628c6700 10 monclient(hunting): _reopen_session rank -1 name
-64> 2014-06-24 10:49:07.214038 7f76628c6700 1 -- 10.141.8.182:6832/43239 mark_down 0x1c277aaa0 -- 0x2624b0f00
-63> 2014-06-24 10:49:07.214055 7f765a67c700 2 -- 10.141.8.182:6832/43239 >> 10.141.8.181:6789/0 pipe(0x2624b0f00 sd=103 :0 s=4 pgs=0
cs=0 l=1 c=0x1c277aaa0).connect couldn't read banner, (0) Success
-62> 2014-06-24 10:49:07.214066 7f76628c6700 10 monclient(hunting): picked mon.ceph001 con 0xb74461a0 addr 10.141.8.180:6789/0
-61> 2014-06-24 10:49:07.214086 7f76628c6700 10 monclient(hunting): _send_mon_message to mon.ceph001 at 10.141.8.180:6789/0
-60> 2014-06-24 10:49:07.214091 7f76628c6700 1 -- 10.141.8.182:6832/43239 --> 10.141.8.180:6789/0 -- auth(proto 0 42 bytes epoch 1) v1
-- ?+0 0x21d300b40 con 0xb74461a0
-59> 2014-06-24 10:49:07.214101 7f76628c6700 10 monclient(hunting): renew_subs
-58> 2014-06-24 10:49:07.214081 7f765a67c700 3 -- 10.141.8.182:6832/43239 >> 10.141.8.181:6789/0 pipe(0x2624b0f00 sd=103 :0 s=4 pgs=0
cs=0 l=1 c=0x1c277aaa0).connect fault, but state = closed != connecting, stopping
-57> 2014-06-24 10:49:07.214111 7f76628c6700 1 -- 10.141.8.182:6832/43239 <== osd.21 10.141.8.182:6803/26308 10015 ==== osd_op_reply(6
5181 1000006b4f2.00000000 [??? 1~0,omap-set-header 0~222,omap-set-vals 0~399] v811'87242 uv87242 ondisk = 0) v6 ==== 271+0+0 (2860133359 0
0) 0x1b57fd000 con 0x3759fa0
-56> 2014-06-24 10:49:07.214136 7f76628c6700 5 mds.1.33 is_laggy 79.848346 > 15 since last acked beacon
-55> 2014-06-24 10:49:07.214141 7f76628c6700 5 mds.1.33 initiating monitor reconnect; maybe we're not the slow one
-54> 2014-06-24 10:49:07.214143 7f76628c6700 10 monclient(hunting): _reopen_session rank -1 name
-53> 2014-06-24 10:49:07.214152 7f76628c6700 1 -- 10.141.8.182:6832/43239 mark_down 0xb74461a0 -- 0x1b57fcd80
-52> 2014-06-24 10:49:07.214179 7f76628c6700 10 monclient(hunting): picked mon.ceph003 con 0xb7447380 addr 10.141.8.182:6789/0
-51> 2014-06-24 10:49:07.214167 7f765986e700 2 -- 10.141.8.182:6832/43239 >> 10.141.8.180:6789/0 pipe(0x1b57fcd80 sd=130 :0 s=4 pgs=0
cs=0 l=1 c=0xb74461a0).connect couldn't read banner, (0) Success
-50> 2014-06-24 10:49:07.214189 7f76628c6700 10 monclient(hunting): _send_mon_message to mon.ceph003 at 10.141.8.182:6789/0
-49> 2014-06-24 10:49:07.214194 7f76628c6700 1 -- 10.141.8.182:6832/43239 --> 10.141.8.182:6789/0 -- auth(proto 0 42 bytes epoch 1) v1
-- ?+0 0x21d303f00 con 0xb7447380
-48> 2014-06-24 10:49:07.214206 7f76628c6700 10 monclient(hunting): renew_subs
-47> 2014-06-24 10:49:07.214214 7f76628c6700 1 -- 10.141.8.182:6832/43239 <== osd.10 10.141.8.181:6800/24877 10006 ==== osd_op_reply(7
0249 200000ab00b.00000000 [??? 1~0,omap-set-header 0~222,omap-set-vals 0~196281,omap-rm-keys 0~13579] v811'250306 uv250306 ondisk = 0) v6
==== 313+0+0 (1741933792 0 0) 0x26258fd00 con 0x375a3c0
-46> 2014-06-24 10:49:07.214191 7f765986e700 3 -- 10.141.8.182:6832/43239 >> 10.141.8.180:6789/0 pipe(0x1b57fcd80 sd=130 :0 s=4 pgs=0
cs=0 l=1 c=0xb74461a0).connect fault, but state = closed != connecting, stopping
-45> 2014-06-24 10:49:07.216106 7f76628c6700 5 mds.1.33 is_laggy 79.850316 > 15 since last acked beacon
-44> 2014-06-24 10:49:07.216117 7f76628c6700 5 mds.1.33 initiating monitor reconnect; maybe we're not the slow one
-43> 2014-06-24 10:49:07.216118 7f76628c6700 10 monclient(hunting): _reopen_session rank -1 name
-42> 2014-06-24 10:49:07.216121 7f76628c6700 1 -- 10.141.8.182:6832/43239 mark_down 0xb7447380 -- 0x2624b0c80
-41> 2014-06-24 10:49:07.216169 7f7658f65700 2 -- 10.141.8.182:6832/43239 >> 10.141.8.182:6789/0 pipe(0x2624b0c80 sd=103 :50609 s=4 pg
s=20558 cs=1 l=1 c=0xb7447380).reader couldn't read tag, (0) Success
-40> 2014-06-24 10:49:07.216186 7f76628c6700 10 monclient(hunting): picked mon.ceph001 con 0x13dcd4ba0 addr 10.141.8.180:6789/0
-39> 2014-06-24 10:49:07.216209 7f76628c6700 10 monclient(hunting): _send_mon_message to mon.ceph001 at 10.141.8.180:6789/0
-38> 2014-06-24 10:49:07.216199 7f7658f65700 2 -- 10.141.8.182:6832/43239 >> 10.141.8.182:6789/0 pipe(0x2624b0c80 sd=103 :50609 s=4 pg
s=20558 cs=1 l=1 c=0xb7447380).fault (0) Success
-37> 2014-06-24 10:49:07.216216 7f76628c6700 1 -- 10.141.8.182:6832/43239 --> 10.141.8.180:6789/0 -- auth(proto 0 42 bytes epoch 1) v1
-- ?+0 0x21d304140 con 0x13dcd4ba0
-36> 2014-06-24 10:49:07.216224 7f76628c6700 10 monclient(hunting): renew_subs
-35> 2014-06-24 10:49:07.216232 7f76628c6700 5 mds.1.33 ms_handle_connect on 10.141.8.182:6789/0
-34> 2014-06-24 10:49:07.216241 7f76628c6700 1 -- 10.141.8.182:6832/43239 <== osd.21 10.141.8.182:6803/26308 10016 ==== osd_op_reply(65216 1000006b900.00000000 [??? 1~0,omap-set-header 0~222,omap-set-vals 0~400] v811'93660 uv93660 ondisk = 0) v6 ==== 271+0+0 (2766708515 0 0) 0x1b57fd280 con 0x3759fa0
-33> 2014-06-24 10:49:07.216280 7f76628c6700 5 mds.1.33 is_laggy 79.850489 > 15 since last acked beacon
-32> 2014-06-24 10:49:07.216287 7f76628c6700 5 mds.1.33 initiating monitor reconnect; maybe we're not the slow one
-31> 2014-06-24 10:49:07.216288 7f76628c6700 10 monclient(hunting): _reopen_session rank -1 name
-30> 2014-06-24 10:49:07.216292 7f76628c6700 1 -- 10.141.8.182:6832/43239 mark_down 0x13dcd4ba0 -- 0x1b57fd000
-29> 2014-06-24 10:49:07.216322 7f76628c6700 10 monclient(hunting): picked mon.ceph003 con 0x2c119a20 addr 10.141.8.182:6789/0
-28> 2014-06-24 10:49:07.216332 7f76628c6700 10 monclient(hunting): _send_mon_message to mon.ceph003 at 10.141.8.182:6789/0
-27> 2014-06-24 10:49:07.216310 7f765986e700 2 -- 10.141.8.182:6832/43239 >> 10.141.8.180:6789/0 pipe(0x1b57fd000 sd=130 :0 s=4 pgs=0
cs=0 l=1 c=0x13dcd4ba0).connect couldn't read banner, (0) Success
-26> 2014-06-24 10:49:07.216341 7f76628c6700 1 -- 10.141.8.182:6832/43239 --> 10.141.8.182:6789/0 -- auth(proto 0 42 bytes epoch 1) v1
-- ?+0 0x21d3072c0 con 0x2c119a20
-25> 2014-06-24 10:49:07.216354 7f76628c6700 10 monclient(hunting): renew_subs
-24> 2014-06-24 10:49:07.216350 7f765986e700 3 -- 10.141.8.182:6832/43239 >> 10.141.8.180:6789/0 pipe(0x1b57fd000 sd=130 :0 s=4 pgs=0
cs=0 l=1 c=0x13dcd4ba0).connect fault, but state = closed != connecting, stopping
-23> 2014-06-24 10:49:07.216361 7f76628c6700 1 -- 10.141.8.182:6832/43239 <== osd.10 10.141.8.181:6800/24877 10007 ==== osd_op_reply(7
0317 100000a0f12.00000000 [??? 1~0,omap-set-header 0~222,omap-set-vals 0~1594] v811'289159 uv289159 ondisk = 0) v6 ==== 271+0+0 (169687627
8 0 0) 0x26258fa80 con 0x375a3c0
-22> 2014-06-24 10:49:07.216408 7f76628c6700 5 mds.1.33 is_laggy 79.850617 > 15 since last acked beacon
-21> 2014-06-24 10:49:07.216411 7f76628c6700 5 mds.1.33 initiating monitor reconnect; maybe we're not the slow one
-20> 2014-06-24 10:49:07.216412 7f76628c6700 10 monclient(hunting): _reopen_session rank -1 name
-19> 2014-06-24 10:49:07.216414 7f76628c6700 1 -- 10.141.8.182:6832/43239 mark_down 0x2c119a20 -- 0x26258fd00
-18> 2014-06-24 10:49:07.216432 7f76628c6700 10 monclient(hunting): picked mon.ceph002 con 0x2c11d540 addr 10.141.8.181:6789/0
-17> 2014-06-24 10:49:07.216438 7f76628c6700 10 monclient(hunting): _send_mon_message to mon.ceph002 at 10.141.8.181:6789/0
-16> 2014-06-24 10:49:07.216440 7f76628c6700 1 -- 10.141.8.182:6832/43239 --> 10.141.8.181:6789/0 -- auth(proto 0 42 bytes epoch 1) v1
-- ?+0 0x21ca686c0 con 0x2c11d540
-15> 2014-06-24 10:49:07.216445 7f76628c6700 10 monclient(hunting): renew_subs
-14> 2014-06-24 10:49:07.216451 7f76628c6700 1 -- 10.141.8.182:6832/43239 <== osd.1 10.141.8.180:6803/28178 7803 ==== osd_op_reply(268
39 1000009992c.00000000 [??? 1~0,omap-set-header 0~222,omap-set-vals 0~4859,omap-rm-keys 0~371] v813'77416 uv77416 ondisk = 0) v6 ==== 313
+0+0 (2412616183 0 0) 0x25bb8f800 con 0x375b2e0
-13> 2014-06-24 10:49:07.216497 7f76628c6700 5 mds.1.33 is_laggy 79.850707 > 15 since last acked beacon
-12> 2014-06-24 10:49:07.216503 7f76628c6700 5 mds.1.33 initiating monitor reconnect; maybe we're not the slow one
-11> 2014-06-24 10:49:07.216504 7f76628c6700 10 monclient(hunting): _reopen_session rank -1 name
-10> 2014-06-24 10:49:07.216507 7f76628c6700 1 -- 10.141.8.182:6832/43239 mark_down 0x2c11d540 -- 0x1b57fd280
-9> 2014-06-24 10:49:07.216484 7f7658f65700 2 -- 10.141.8.182:6832/43239 >> 10.141.8.182:6789/0 pipe(0x26258fd00 sd=103 :0 s=4 pgs=0
cs=0 l=1 c=0x2c119a20).connect couldn't read banner, (0) Success
-8> 2014-06-24 10:49:07.216534 7f7658f65700 3 -- 10.141.8.182:6832/43239 >> 10.141.8.182:6789/0 pipe(0x26258fd00 sd=103 :0 s=4 pgs=0
cs=0 l=1 c=0x2c119a20).connect fault, but state = closed != connecting, stopping
-7> 2014-06-24 10:49:07.216530 7f765986e700 2 -- 10.141.8.182:6832/43239 >> 10.141.8.181:6789/0 pipe(0x1b57fd280 sd=130 :0 s=4 pgs=0
cs=0 l=1 c=0x2c11d540).connect couldn't read banner, (0) Success
-6> 2014-06-24 10:49:07.216551 7f76628c6700 10 monclient(hunting): picked mon.ceph001 con 0x2c11d960 addr 10.141.8.180:6789/0
-5> 2014-06-24 10:49:07.216569 7f76628c6700 10 monclient(hunting): _send_mon_message to mon.ceph001 at 10.141.8.180:6789/0
-4> 2014-06-24 10:49:07.216577 7f76628c6700 1 -- 10.141.8.182:6832/43239 --> 10.141.8.180:6789/0 -- auth(proto 0 42 bytes epoch 1) v1
-- ?+0 0x21ca6ca40 con 0x2c11d960
-3> 2014-06-24 10:49:07.216554 7f765986e700 3 -- 10.141.8.182:6832/43239 >> 10.141.8.181:6789/0 pipe(0x1b57fd280 sd=130 :0 s=4 pgs=0
cs=0 l=1 c=0x2c11d540).connect fault, but state = closed != connecting, stopping
-2> 2014-06-24 10:49:07.216587 7f76628c6700 10 monclient(hunting): renew_subs
-1> 2014-06-24 10:49:07.216594 7f76628c6700 1 -- 10.141.8.182:6832/43239 <== osd.0 10.141.8.180:6800/26720 7386 ==== osd_op_reply(697
77 200000a8488.00000000 [??? 1~0,omap-set-header 0~222,omap-set-vals 0~7618,omap-rm-keys 0~512] v0'0 uv0 ondisk = -108 ((108) Cannot send
after transport endpoint shutdown)) v6 ==== 313+0+0 (1160011566 0 0) 0x258993480 con 0x3759e40
0> 2014-06-24 10:49:07.235120 7f76628c6700 -1 mds/CDir.cc: In function 'virtual void C_Dir_Committed::finish(int)' thread 7f76628c670
0 time 2014-06-24 10:49:07.219091
mds/CDir.cc: 1767: FAILED assert(r == 0)
ceph version 0.81 (8de9501df275a5fe29f2c64cb44f195130e4a8fc)
1: /usr/bin/ceph-mds() [0x75d361]
2: (Context::complete(int)+0x9) [0x56a829]
3: (C_Gather::sub_finish(Context*, int)+0x227) [0x56c3a7]
4: (C_Gather::C_GatherSub::finish(int)+0x12) [0x56c4b2]
5: (Context::complete(int)+0x9) [0x56a829]
6: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xf56) [0x7cf306]
7: (MDS::handle_core_message(Message*)+0xb27) [0x58c447]
8: (MDS::_dispatch(Message*)+0x45) [0x58c655]
9: (MDS::ms_dispatch(Message*)+0xc3) [0x58e0a3]
10: (DispatchQueue::entry()+0x509) [0x9a9409]
11: (DispatchQueue::DispatchThread::entry()+0xd) [0x8c205d]
12: (()+0x7df3) [0x7f766750fdf3]
13: (clone()+0x6d) [0x7f76663e63dd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
--- logging levels ---
0/ 5 none
0/ 1 lockdep
0/ 1 context
1/ 1 crush
1/ 5 mds
1/ 5 mds_balancer
1/ 5 mds_locker
1/ 5 mds_log
1/ 5 mds_log_expire
1/ 5 mds_migrator
0/ 1 buffer
0/ 1 timer
0/ 1 filer
0/ 1 striper
0/ 1 objecter
0/ 5 rados
0/ 5 rbd
0/ 5 journaler
0/ 5 objectcacher
0/ 5 client
0/ 5 osd
0/ 5 optracker
0/ 5 objclass
1/ 3 filestore
1/ 3 keyvaluestore
1/ 3 journal
0/ 5 ms
1/ 5 mon
0/10 monc
1/ 5 paxos
0/ 5 tp
1/ 5 auth
1/ 5 crypto
1/ 1 finisher
1/ 5 heartbeatmap
1/ 5 perfcounter
1/ 5 rgw
1/ 5 javaclient
1/ 5 asok
1/ 1 throttle
-2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent 10000
max_new 1000
log_file /var/log/ceph/ceph-mds.ceph003.cubone.os.log
ceph version 0.81 (8de9501df275a5fe29f2c64cb44f195130e4a8fc)
1: /usr/bin/ceph-mds() [0x7f4b76]
2: (()+0xf130) [0x7f7667517130]
3: (gsignal()+0x39) [0x7f7666325989]
4: (abort()+0x148) [0x7f7666327098]
5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f7666c389d5]
6: (()+0x5e946) [0x7f7666c36946]
7: (()+0x5e973) [0x7f7666c36973]
8: (()+0x5eb9f) [0x7f7666c36b9f]
9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x1ef) [0x8daddf]
10: /usr/bin/ceph-mds() [0x75d361]
11: (Context::complete(int)+0x9) [0x56a829]
12: (C_Gather::sub_finish(Context*, int)+0x227) [0x56c3a7]
13: (C_Gather::C_GatherSub::finish(int)+0x12) [0x56c4b2]
14: (Context::complete(int)+0x9) [0x56a829]
15: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xf56) [0x7cf306]
16: (MDS::handle_core_message(Message*)+0xb27) [0x58c447]
17: (MDS::_dispatch(Message*)+0x45) [0x58c655]
18: (MDS::ms_dispatch(Message*)+0xc3) [0x58e0a3]
19: (DispatchQueue::entry()+0x509) [0x9a9409]
20: (DispatchQueue::DispatchThread::entry()+0xd) [0x8c205d]
21: (()+0x7df3) [0x7f766750fdf3]
22: (clone()+0x6d) [0x7f76663e63dd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
--- begin dump of recent events ---
0> 2014-06-24 10:49:07.490111 7f76628c6700 -1 *** Caught signal (Aborted) **
in thread 7f76628c6700
ceph version 0.81 (8de9501df275a5fe29f2c64cb44f195130e4a8fc)
1: /usr/bin/ceph-mds() [0x7f4b76]
2: (()+0xf130) [0x7f7667517130]
3: (gsignal()+0x39) [0x7f7666325989]
4: (abort()+0x148) [0x7f7666327098]
5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f7666c389d5]
6: (()+0x5e946) [0x7f7666c36946]
7: (()+0x5e973) [0x7f7666c36973]
8: (()+0x5eb9f) [0x7f7666c36b9f]
9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x1ef) [0x8daddf]
10: /usr/bin/ceph-mds() [0x75d361]
11: (Context::complete(int)+0x9) [0x56a829]
12: (C_Gather::sub_finish(Context*, int)+0x227) [0x56c3a7]
13: (C_Gather::C_GatherSub::finish(int)+0x12) [0x56c4b2]
14: (Context::complete(int)+0x9) [0x56a829]
15: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xf56) [0x7cf306]
16: (MDS::handle_core_message(Message*)+0xb27) [0x58c447]
17: (MDS::_dispatch(Message*)+0x45) [0x58c655]
18: (MDS::ms_dispatch(Message*)+0xc3) [0x58e0a3]
19: (DispatchQueue::entry()+0x509) [0x9a9409]
20: (DispatchQueue::DispatchThread::entry()+0xd) [0x8c205d]
21: (()+0x7df3) [0x7f766750fdf3]
22: (clone()+0x6d) [0x7f76663e63dd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
</pre>