Bug #4644
Updated by Joao Eduardo Luis about 11 years ago
after upgrade from 0.58 to 0.60, one mds is crashed and still crashing directly after start <pre> --- begin dump of recent events --- -120> 2013-04-02 11:44:23.896083 7fe140415780 5 asok(0x2af0000) register_command perfcounters_dump hook 0x2aa8010 -119> 2013-04-02 11:44:23.896121 7fe140415780 5 asok(0x2af0000) register_command 1 hook 0x2aa8010 -118> 2013-04-02 11:44:23.896124 7fe140415780 5 asok(0x2af0000) register_command perf dump hook 0x2aa8010 -117> 2013-04-02 11:44:23.896130 7fe140415780 5 asok(0x2af0000) register_command perfcounters_schema hook 0x2aa8010 -116> 2013-04-02 11:44:23.896133 7fe140415780 5 asok(0x2af0000) register_command 2 hook 0x2aa8010 -115> 2013-04-02 11:44:23.896135 7fe140415780 5 asok(0x2af0000) register_command perf schema hook 0x2aa8010 -114> 2013-04-02 11:44:23.896137 7fe140415780 5 asok(0x2af0000) register_command config show hook 0x2aa8010 -113> 2013-04-02 11:44:23.896140 7fe140415780 5 asok(0x2af0000) register_command config set hook 0x2aa8010 -112> 2013-04-02 11:44:23.896144 7fe140415780 5 asok(0x2af0000) register_command log flush hook 0x2aa8010 -111> 2013-04-02 11:44:23.896147 7fe140415780 5 asok(0x2af0000) register_command log dump hook 0x2aa8010 -110> 2013-04-02 11:44:23.896181 7fe140415780 5 asok(0x2af0000) register_command log reopen hook 0x2aa8010 -109> 2013-04-02 11:44:23.904109 7fe140415780 0 ceph version 0.60 (f26f7a39021dbf440c28d6375222e21c94fe8e5c), process ceph-mds, pid 2228 -108> 2013-04-02 11:44:23.904528 7fe140415780 1 accepter.accepter.bind my_inst.addr is 0.0.0.0:6809/2228 need_addr=1 -107> 2013-04-02 11:44:23.910098 7fe140415780 1 finished global_init_daemonize -106> 2013-04-02 11:44:23.910307 7fe140415780 5 asok(0x2af0000) init /var/run/ceph/ceph-mds.a.asok -105> 2013-04-02 11:44:23.910331 7fe140415780 5 asok(0x2af0000) bind_and_listen /var/run/ceph/ceph-mds.a.asok -104> 2013-04-02 11:44:23.910405 7fe140415780 5 asok(0x2af0000) register_command 0 hook 0x2aa0038 -103> 2013-04-02 11:44:23.910415 7fe140415780 5 asok(0x2af0000) register_command version hook 0x2aa0038 -102> 2013-04-02 11:44:23.910420 7fe140415780 5 asok(0x2af0000) register_command git_version hook 0x2aa0038 -101> 2013-04-02 11:44:23.910425 7fe140415780 5 asok(0x2af0000) register_command help hook 0x2aa8050 -100> 2013-04-02 11:44:23.910478 7fe140415780 10 monclient(hunting): build_initial_monmap -99> 2013-04-02 11:44:23.910522 7fe13d70b700 5 asok(0x2af0000) entry start -98> 2013-04-02 11:44:23.939661 7fe140415780 1 -- 0.0.0.0:6809/2228 messenger.start -97> 2013-04-02 11:44:23.940508 7fe140415780 5 adding auth protocol: none -96> 2013-04-02 11:44:23.940528 7fe140415780 5 adding auth protocol: none -95> 2013-04-02 11:44:23.941582 7fe140415780 1 accepter.accepter.start -94> 2013-04-02 11:44:23.941610 7fe140415780 10 monclient(hunting): init -93> 2013-04-02 11:44:23.941616 7fe140415780 5 adding auth protocol: none -92> 2013-04-02 11:44:23.941617 7fe140415780 10 monclient(hunting): auth_supported 1 method none -91> 2013-04-02 11:44:23.941679 7fe140415780 10 monclient(hunting): _reopen_session -90> 2013-04-02 11:44:23.943741 7fe140415780 10 monclient(hunting): _pick_new_mon picked mon.c con 0x2b68580 addr 192.168.99.110:6789/0 -89> 2013-04-02 11:44:23.943799 7fe140415780 10 monclient(hunting): _send_mon_message to mon.c at 192.168.99.110:6789/0 -88> 2013-04-02 11:44:23.944853 7fe140411700 1 -- 192.168.16.129:6809/2228 learned my addr 192.168.16.129:6809/2228 -87> 2013-04-02 11:44:23.945572 7fe13bf08700 5 mds.-1.0 ms_handle_connect on 192.168.99.110:6789/0 -86> 2013-04-02 11:44:23.943809 7fe140415780 1 -- 0.0.0.0:6809/2228 --> 192.168.99.110:6789/0 -- auth(proto 0 26 bytes epoch 0) v1 -- ?+0 0x2b10400 con 0x2b68580 -85> 2013-04-02 11:44:23.965313 7fe140415780 10 monclient(hunting): renew_subs -84> 2013-04-02 11:44:26.941893 7fe13af06700 10 monclient(hunting): tick -83> 2013-04-02 11:44:26.941917 7fe13af06700 1 monclient(hunting): continuing hunt -82> 2013-04-02 11:44:26.941920 7fe13af06700 10 monclient(hunting): _reopen_session -81> 2013-04-02 11:44:26.941923 7fe13af06700 1 -- 192.168.16.129:6809/2228 mark_down 0x2b68580 -- 0x2b88280 -80> 2013-04-02 11:44:26.942055 7fe13af06700 10 monclient(hunting): _pick_new_mon picked mon.a con 0x2b68840 addr 192.168.16.129:6789/0 -79> 2013-04-02 11:44:26.941986 7fe139f04700 2 -- 192.168.16.129:6809/2228 >> 192.168.99.110:6789/0 pipe(0x2b88280 sd=16 :50721 s=4 pgs=44 cs=1 l=1).reader couldn't read tag, Success -78> 2013-04-02 11:44:26.942078 7fe13af06700 10 monclient(hunting): _send_mon_message to mon.a at 192.168.16.129:6789/0 -77> 2013-04-02 11:44:26.942082 7fe13af06700 1 -- 192.168.16.129:6809/2228 --> 192.168.16.129:6789/0 -- auth(proto 0 26 bytes epoch 0) v1 -- ?+0 0x2b10400 con 0x2b68840 -76> 2013-04-02 11:44:26.942079 7fe139f04700 2 -- 192.168.16.129:6809/2228 >> 192.168.99.110:6789/0 pipe(0x2b88280 sd=16 :50721 s=4 pgs=44 cs=1 l=1).fault 0: Success -75> 2013-04-02 11:44:26.942089 7fe13af06700 10 monclient(hunting): renew_subs -74> 2013-04-02 11:44:26.942784 7fe13bf08700 5 mds.-1.0 ms_handle_connect on 192.168.16.129:6789/0 -73> 2013-04-02 11:44:26.943603 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 1 ==== mon_map v1 ==== 473+0+0 (3243395836 0 0) 0x2bc83c0 con 0x2b68840 -72> 2013-04-02 11:44:26.943640 7fe13bf08700 10 monclient(hunting): handle_monmap mon_map v1 -71> 2013-04-02 11:44:26.943658 7fe13bf08700 10 monclient(hunting): got monmap 6, mon.a is now rank 2 -70> 2013-04-02 11:44:26.943660 7fe13bf08700 10 monclient(hunting): dump: epoch 6 fsid 4eacc6f6-6561-4359-a035-1eb9a91eb45d last_changed 2013-04-02 09:12:35.994897 created 2012-10-24 16:32:47.986799 0: 192.168.99.110:6789/0 mon.c 1: 192.168.23.110:6789/0 mon.b 2: 192.168.16.129:6789/0 mon.a -69> 2013-04-02 11:44:26.943715 7fe13bf08700 1 monclient(hunting): found mon.a -68> 2013-04-02 11:44:26.943725 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 2 ==== auth_reply(proto 1 0 Success) v1 ==== 24+0+0 (2265305362 0 0) 0x2b10600 con 0x2b68840 -67> 2013-04-02 11:44:26.943747 7fe13bf08700 10 monclient: my global_id is 10244 -66> 2013-04-02 11:44:26.943750 7fe13bf08700 10 monclient: _send_mon_message to mon.a at 192.168.16.129:6789/0 -65> 2013-04-02 11:44:26.943757 7fe13bf08700 1 -- 192.168.16.129:6809/2228 --> 192.168.16.129:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x2bb8380 con 0x2b68840 -64> 2013-04-02 11:44:26.950949 7fe13bf08700 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2013-04-02 11:43:56.950945) -63> 2013-04-02 11:44:26.951044 7fe140415780 5 monclient: authenticate success, global_id 10244 -62> 2013-04-02 11:44:26.951125 7fe140415780 5 asok(0x2af0000) register_command objecter_requests hook 0x2aa8100 -61> 2013-04-02 11:44:26.951207 7fe140415780 10 monclient: _send_mon_message to mon.a at 192.168.16.129:6789/0 -60> 2013-04-02 11:44:26.951220 7fe140415780 1 -- 192.168.16.129:6809/2228 --> 192.168.16.129:6789/0 -- mdsbeacon(10244/a up:boot seq 1 v0) v2 -- ?+0 0x2bd8000 con 0x2b68840 -59> 2013-04-02 11:44:26.951245 7fe140415780 10 monclient: renew_subs -58> 2013-04-02 11:44:26.951250 7fe140415780 10 monclient: _send_mon_message to mon.a at 192.168.16.129:6789/0 -57> 2013-04-02 11:44:26.951254 7fe140415780 1 -- 192.168.16.129:6809/2228 --> 192.168.16.129:6789/0 -- mon_subscribe({monmap=7+,osdmap=0}) v2 -- ?+0 0x2bb81c0 con 0x2b68840 -56> 2013-04-02 11:44:26.951267 7fe140415780 10 monclient: renew_subs -55> 2013-04-02 11:44:26.951277 7fe140415780 10 monclient: _send_mon_message to mon.a at 192.168.16.129:6789/0 -54> 2013-04-02 11:44:26.951291 7fe140415780 1 -- 192.168.16.129:6809/2228 --> 192.168.16.129:6789/0 -- mon_subscribe({mdsmap=0+,monmap=7+,osdmap=0}) v2 -- ?+0 0x2bb88c0 con 0x2b68840 -53> 2013-04-02 11:44:26.951561 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 3 ==== mon_map v1 ==== 473+0+0 (3243395836 0 0) 0x2bc85a0 con 0x2b68840 -52> 2013-04-02 11:44:26.951580 7fe13bf08700 10 monclient: handle_monmap mon_map v1 -51> 2013-04-02 11:44:26.951590 7fe13bf08700 10 monclient: got monmap 6, mon.a is now rank 2 -50> 2013-04-02 11:44:26.951592 7fe13bf08700 10 monclient: dump: epoch 6 fsid 4eacc6f6-6561-4359-a035-1eb9a91eb45d last_changed 2013-04-02 09:12:35.994897 created 2012-10-24 16:32:47.986799 0: 192.168.99.110:6789/0 mon.c 1: 192.168.23.110:6789/0 mon.b 2: 192.168.16.129:6789/0 mon.a -49> 2013-04-02 11:44:26.951623 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 4 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (3455830995 0 0) 0x2b904e0 con 0x2b68840 -48> 2013-04-02 11:44:26.951638 7fe13bf08700 10 monclient: handle_subscribe_ack sent 2013-04-02 11:44:23.965317 renew after 2013-04-02 11:46:53.965317 -47> 2013-04-02 11:44:26.963038 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 5 ==== osd_map(3678..3678 src has 3176..3678) v3 ==== 11918+0+0 (2321284020 0 0) 0x2b11200 con 0x2b68840 -46> 2013-04-02 11:44:26.968030 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 6 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (3455830995 0 0) 0x2b90820 con 0x2b68840 -45> 2013-04-02 11:44:26.968046 7fe13bf08700 10 monclient: handle_subscribe_ack sent 0.000000, ignoring -44> 2013-04-02 11:44:26.969045 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 7 ==== mdsmap(e 762) v1 ==== 583+0+0 (3620617815 0 0) 0x2b11000 con 0x2b68840 -43> 2013-04-02 11:44:26.969074 7fe13bf08700 5 mds.-1.0 handle_mds_map epoch 762 from mon.2 -42> 2013-04-02 11:44:26.969130 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 8 ==== osd_map(3678..3678 src has 3176..3678) v3 ==== 11918+0+0 (2321284020 0 0) 0x2b11800 con 0x2b68840 -41> 2013-04-02 11:44:26.969158 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 9 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (3455830995 0 0) 0x2b90680 con 0x2b68840 -40> 2013-04-02 11:44:26.969168 7fe13bf08700 10 monclient: handle_subscribe_ack sent 0.000000, ignoring -39> 2013-04-02 11:44:27.163253 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 10 ==== mdsmap(e 763) v1 ==== 786+0+0 (3610614263 0 0) 0x2b11600 con 0x2b68840 -38> 2013-04-02 11:44:27.163277 7fe13bf08700 5 mds.-1.-1 handle_mds_map epoch 763 from mon.2 -37> 2013-04-02 11:44:27.163301 7fe13bf08700 1 mds.-1.0 handle_mds_map standby -36> 2013-04-02 11:44:27.422404 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 11 ==== mdsmap(e 764) v1 ==== 583+0+0 (2230448747 0 0) 0x2b11400 con 0x2b68840 -35> 2013-04-02 11:44:27.422429 7fe13bf08700 5 mds.-1.0 handle_mds_map epoch 764 from mon.2 -34> 2013-04-02 11:44:27.422452 7fe13bf08700 1 -- 192.168.16.129:6809/2228 mark_down 192.168.23.110:6800/18751 -- pipe dne -33> 2013-04-02 11:44:27.422461 7fe13bf08700 1 mds.0.40 handle_mds_map i am now mds.0.40 -32> 2013-04-02 11:44:27.422463 7fe13bf08700 1 mds.0.40 handle_mds_map state change up:standby --> up:replay -31> 2013-04-02 11:44:27.422465 7fe13bf08700 1 mds.0.40 replay_start -30> 2013-04-02 11:44:27.422871 7fe13bf08700 1 mds.0.40 recovery set is -29> 2013-04-02 11:44:27.422885 7fe13bf08700 1 mds.0.40 need osdmap epoch 3679, have 3678 -28> 2013-04-02 11:44:27.422892 7fe13bf08700 1 mds.0.40 waiting for osdmap 3679 (which blacklists prior instance) -27> 2013-04-02 11:44:27.422901 7fe13bf08700 10 monclient: renew_subs -26> 2013-04-02 11:44:27.422907 7fe13bf08700 10 monclient: _send_mon_message to mon.a at 192.168.16.129:6789/0 -25> 2013-04-02 11:44:27.422914 7fe13bf08700 1 -- 192.168.16.129:6809/2228 --> 192.168.16.129:6789/0 -- mon_subscribe({mdsmap=765+,monmap=7+,osdmap=3679}) v2 -- ?+0 0x2bb8380 con 0x2b68840 -24> 2013-04-02 11:44:27.422936 7fe13bf08700 1 mds.0.cache handle_mds_failure mds.0 : recovery peers are -23> 2013-04-02 11:44:27.443165 7fe13bf08700 5 mds.0.migrator handle_mds_failure_or_stop mds.0 -22> 2013-04-02 11:44:27.464363 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 12 ==== osd_map(3679..3679 src has 3178..3679) v3 ==== 308+0+0 (1123034295 0 0) 0x2b11a00 con 0x2b68840 -21> 2013-04-02 11:44:27.464417 7fe13bf08700 2 mds.0.40 boot_start 1: opening inotable -20> 2013-04-02 11:44:27.464503 7fe13bf08700 1 -- 192.168.16.129:6809/2228 --> 192.168.23.153:6832/14317 -- osd_op(mds.0.40:1 mds0_inotable [read 0~0] 1.b852b893 e3679) v4 -- ?+0 0x2ae8240 con 0x2b68c60 -19> 2013-04-02 11:44:27.464531 7fe13bf08700 2 mds.0.40 boot_start 1: opening sessionmap -18> 2013-04-02 11:44:27.464584 7fe13bf08700 1 -- 192.168.16.129:6809/2228 --> 192.168.23.153:6841/14764 -- osd_op(mds.0.40:2 mds0_sessionmap [read 0~0] 1.3270c60b e3679) v4 -- ?+0 0x2ae86c0 con 0x2b694a0 -17> 2013-04-02 11:44:27.464594 7fe13bf08700 2 mds.0.40 boot_start 1: opening anchor table -16> 2013-04-02 11:44:27.464639 7fe13bf08700 1 -- 192.168.16.129:6809/2228 --> 192.168.23.110:6810/20043 -- osd_op(mds.0.40:3 mds_anchortable [read 0~0] 1.a977f6a7 e3679) v4 -- ?+0 0x2ae8480 con 0x2b69340 -15> 2013-04-02 11:44:27.464658 7fe13bf08700 2 mds.0.40 boot_start 1: opening snap table -14> 2013-04-02 11:44:27.464700 7fe13bf08700 1 -- 192.168.16.129:6809/2228 --> 192.168.23.153:6844/14861 -- osd_op(mds.0.40:4 mds_snaptable [read 0~0] 1.d90270ad e3679) v4 -- ?+0 0x2ae8d80 con 0x2b691e0 -13> 2013-04-02 11:44:27.464718 7fe13bf08700 2 mds.0.40 boot_start 1: opening mds log -12> 2013-04-02 11:44:27.464720 7fe13bf08700 5 mds.0.log open discovering log bounds -11> 2013-04-02 11:44:27.464726 7fe13bf08700 1 mds.0.journaler(ro) recover start -10> 2013-04-02 11:44:27.464727 7fe13bf08700 1 mds.0.journaler(ro) read_head -9> 2013-04-02 11:44:27.464776 7fe13bf08700 1 -- 192.168.16.129:6809/2228 --> 192.168.23.153:6847/14980 -- osd_op(mds.0.40:5 200.00000000 [read 0~0] 1.844f3494 e3679) v4 -- ?+0 0x2ae8b40 con 0x2b69080 -8> 2013-04-02 11:44:27.464796 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== mon.2 192.168.16.129:6789/0 13 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (3455830995 0 0) 0x2b909c0 con 0x2b68840 -7> 2013-04-02 11:44:27.464804 7fe13bf08700 10 monclient: handle_subscribe_ack sent 2013-04-02 11:44:27.422902 renew after 2013-04-02 11:46:57.422902 -6> 2013-04-02 11:44:27.465869 7fe13bf08700 5 mds.0.40 ms_handle_connect on 192.168.23.153:6832/14317 -5> 2013-04-02 11:44:27.465885 7fe13bf08700 5 mds.0.40 ms_handle_connect on 192.168.23.153:6847/14980 -4> 2013-04-02 11:44:27.465970 7fe13bf08700 5 mds.0.40 ms_handle_connect on 192.168.23.110:6810/20043 -3> 2013-04-02 11:44:27.465987 7fe13bf08700 5 mds.0.40 ms_handle_connect on 192.168.23.153:6841/14764 -2> 2013-04-02 11:44:27.466032 7fe13bf08700 5 mds.0.40 ms_handle_connect on 192.168.23.153:6844/14861 -1> 2013-04-02 11:44:27.474970 7fe13bf08700 1 -- 192.168.16.129:6809/2228 <== osd.7 192.168.23.153:6841/14764 1 ==== osd_op_reply(2 mds0_sessionmap [read 0~542] ondisk = 0) v4 ==== 114+0+542 (1234829482 0 3336007267) 0x2bc8780 con 0x2b694a0 0> 2013-04-02 11:44:27.479071 7fe13bf08700 -1 *** Caught signal (Aborted) ** in thread 7fe13bf08700 ceph version 0.60 (f26f7a39021dbf440c28d6375222e21c94fe8e5c) 1: /usr/local/bin/ceph-mds() [0x852349] 2: (()+0xf500) [0x7fe13fff5500] 3: (gsignal()+0x35) [0x7fe13e7418a5] 4: (abort()+0x175) [0x7fe13e743085] 5: (__gnu_cxx::__verbose_terminate_handler()+0x12d) [0x7fe13effaa5d] 6: (()+0xbcbe6) [0x7fe13eff8be6] 7: (()+0xbcc13) [0x7fe13eff8c13] 8: (()+0xbcd0e) [0x7fe13eff8d0e] 9: (ceph::buffer::list::iterator::copy(unsigned int, char*)+0x13e) [0x7b7fee] 10: (session_info_t::decode(ceph::buffer::list::iterator&)+0x415) [0x7dfa65] 11: (SessionMap::decode(ceph::buffer::list::iterator&)+0x82c) [0x6e478c] 12: (SessionMap::_load_finish(int, ceph::buffer::list&)+0x81) [0x6e59c1] 13: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xe1e) [0x71290e] 14: (MDS::handle_core_message(Message*)+0x957) [0x4d1c67] 15: (MDS::_dispatch(Message*)+0x2f) [0x4d1d1f] 16: (MDS::ms_dispatch(Message*)+0x19b) [0x4d38eb] 17: (DispatchQueue::entry()+0x309) [0x825da9] 18: (DispatchQueue::DispatchThread::entry()+0xd) [0x7a9e0d] 19: (()+0x7851) [0x7fe13ffed851] 20: (clone()+0x6d) [0x7fe13e7f711d] 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 journal 0/ 5 ms 1/ 5 mon 0/10 monc 0/ 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 hadoop 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/mds.a.log --- end dump of recent events --- </pre>