Bug #3553: MDS core dumped running 0.48.2argonaut - CephFS - Ceph

Actions

Copy link

Bug #3553

closed

MDS core dumped running 0.48.2argonaut

Added by Anonymous over 11 years ago. Updated over 7 years ago.

Status:

Won't Fix

Priority:

High

Assignee:

Category:

Target version:

% Done:

Source:

Q/A

Tags:

Backport:

Regression:

Severity:

Reviewed:

Affected Versions:

ceph-qa-suite:

Component(FS):

Labels (FS):

Pull request ID:

Crash signature (v1):

Crash signature (v2):

Description

/var/ceph/ceph-mds.a.log shows mds 'comitting suicide':
2012-11-29 00:09:08.569400 7f38fa8b2700 1 mds.0.6 handle_mds_map state change up:standby --> up:creating
2012-11-29 00:09:08.569796 7f38fa8b2700 0 mds.0.cache creating system inode with ino:1
2012-11-29 00:09:08.569867 7f38fa8b2700 0 mds.0.cache creating system inode with ino:2
2012-11-29 00:09:08.570037 7f38fa8b2700 0 mds.0.cache creating system inode with ino:100
2012-11-29 00:09:08.570043 7f38fa8b2700 0 mds.0.cache creating system inode with ino:600
2012-11-29 00:09:08.570093 7f38fa8b2700 0 mds.0.cache creating system inode with ino:601
2012-11-29 00:09:08.570133 7f38fa8b2700 0 mds.0.cache creating system inode with ino:602
2012-11-29 00:09:08.570176 7f38fa8b2700 0 mds.0.cache creating system inode with ino:603
2012-11-29 00:09:08.570213 7f38fa8b2700 0 mds.0.cache creating system inode with ino:604
2012-11-29 00:09:08.577602 7f38fa8b2700 0 mds.0.cache creating system inode with ino:605
2012-11-29 00:09:08.577813 7f38fa8b2700 0 mds.0.cache creating system inode with ino:606
2012-11-29 00:09:08.578163 7f38fa8b2700 0 mds.0.cache creating system inode with ino:607
2012-11-29 00:09:08.593088 7f38fa8b2700 0 mds.0.cache creating system inode with ino:608
2012-11-29 00:09:08.593608 7f38fa8b2700 0 mds.0.cache creating system inode with ino:609
2012-11-29 00:09:08.594045 7f38fa8b2700 0 mds.0.cache creating system inode with ino:200
2012-11-29 00:09:08.596847 7f38fa8b2700 1 mds.0.cache handle_mds_failure mds.0 : recovery peers are
2012-11-29 00:09:08.597289 7f38fa8b2700 0 mds.0.6 ms_handle_connect on 10.1.10.21:6800/6621
2012-11-29 00:09:08.597594 7f38fa8b2700 0 mds.0.6 ms_handle_connect on 10.1.10.22:6803/1418
2012-11-29 00:09:08.597896 7f38fa8b2700 0 mds.0.6 ms_handle_connect on 10.1.10.21:6804/3310
2012-11-29 00:09:08.598213 7f38fa8b2700 0 mds.0.6 ms_handle_connect on 10.1.10.26:6803/15483
2012-11-29 00:09:08.602016 7f38fa8b2700 0 mds.0.6 ms_handle_connect on 10.1.10.26:6800/15105
2012-11-29 00:09:08.604531 7f38fa8b2700 -1 mds.0.journaler(rw) _prezeroed got (6) No such device or address
2012-11-29 00:09:08.604635 7f38fa8b2700 -1 mds.0.journaler(rw) handle_write_error (6) No such device or address
2012-11-29 00:09:08.604692 7f38fa8b2700 -1 mds.0.log unhandled error (6) No such device or address, shutting down...
2012-11-29 00:09:08.604753 7f38fa8b2700 1 mds.0.6 suicide. wanted down:dne, now up:creating
2012-11-29 00:09:08.608606 7f39005fd780 0 stopped.

I had run:
strace service ceph start mds.a

2012-11-29 00:08:50.688792 7f38fa8b2700  0 mds.-1.0 ms_handle_connect on 10.1.10.22:6789/0
    2012-11-29 00:08:50.704239 7f38fa8b2700  1 mds.-1.0 handle_mds_map standby
    ...
    2012-11-29 00:09:08.604753 7f38fa8b2700  1 mds.0.6 suicide.  wanted down:dne, now up:creating
    2012-11-29 00:09:08.608606 7f39005fd780  0 stopped.

ceph mds dump
dumped mdsmap epoch 112
epoch 112
flags 0
created 2012-11-27 21:37:02.536700
modified 2012-11-29 00:10:13.581751
tableserver 0
root 0
session_timeout 60
session_autoclose 300
last_failure 0
last_failure_osd_epoch 122
compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object}
max_mds 1
in 0
up {0=5050}
failed
stopped
data_pools [0]
metadata_pool 1
5050: 10.1.10.21:6803/6909 'a' mds.0.6 up:creating seq 1 laggy since 2012-11-29 00:09:23.513234

ceph mds stat
e125: 1/1/1 up {0=a=up:creating(laggy or crashed)}

service ceph start mds.a
=== mds.a ===
Starting Ceph mds.a on ceph1...
starting mds.a at :/0
root@ceph1:/var/lib/ceph/mds/ceph-a# 2012-11-29 00:14:03.877182 7f5bb2889700 0 mds.-1.0 ms_handle_connect on 10.1.10.22:6789/0
2012-11-29 00:14:03.889854 7f5bb2889700 1 mds.-1.0 handle_mds_map standby
ceph mds stat
e127: 1/1/1 up {0=a=up:creating(laggy or crashed)}, 1 up:standby

ceph mds stat
e127: 1/1/1 up {0=a=up:creating(laggy or crashed)}, 1 up:standby

ceph mds stat
e127: 1/1/1 up {0=a=up:creating(laggy or crashed)}, 1 up:standby

ceph mds stat
2012-11-29 00:14:13.872619 7f5bb2889700 1 mds.0.7 handle_mds_map i am now mds.0.7
2012-11-29 00:14:13.872621 7f5bb2889700 1 mds.0.7 handle_mds_map state change up:standby --> up:creating
2012-11-29 00:14:13.872966 7f5bb2889700 0 mds.0.cache creating system inode with ino:1
2012-11-29 00:14:13.873032 7f5bb2889700 0 mds.0.cache creating system inode with ino:2
2012-11-29 00:14:13.873234 7f5bb2889700 0 mds.0.cache creating system inode with ino:100
2012-11-29 00:14:13.873240 7f5bb2889700 0 mds.0.cache creating system inode with ino:600
2012-11-29 00:14:13.873281 7f5bb2889700 0 mds.0.cache creating system inode with ino:601
2012-11-29 00:14:13.873318 7f5bb2889700 0 mds.0.cache creating system inode with ino:602
2012-11-29 00:14:13.873352 7f5bb2889700 0 mds.0.cache creating system inode with ino:603
2012-11-29 00:14:13.873393 7f5bb2889700 0 mds.0.cache creating system inode with ino:604
2012-11-29 00:14:13.873453 7f5bb2889700 0 mds.0.cache creating system inode with ino:605
2012-11-29 00:14:13.873494 7f5bb2889700 0 mds.0.cache creating system inode with ino:606
2012-11-29 00:14:13.873529 7f5bb2889700 0 mds.0.cache creating system inode with ino:607
2012-11-29 00:14:13.873580 7f5bb2889700 0 mds.0.cache creating system inode with ino:608
2012-11-29 00:14:13.873614 7f5bb2889700 0 mds.0.cache creating system inode with ino:609
2012-11-29 00:14:13.873649 7f5bb2889700 0 mds.0.cache creating system inode with ino:200
2012-11-29 00:14:13.873829 7f5bb2889700 1 mds.0.cache handle_mds_failure mds.0 : recovery peers are
2012-11-29 00:14:13.889027 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.21:6804/3310
2012-11-29 00:14:13.892693 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.22:6803/1418
2012-11-29 00:14:13.893313 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.22:6800/31304
2012-11-29 00:14:13.896744 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.26:6800/15105
2012-11-29 00:14:13.901255 7f5bb2889700 -1 mds/MDSTable.cc: In function 'virtual void C_MT_Save::finish(int)' thread 7f5bb2889700 time 2012-11-29 00:14:13.900486
mds/MDSTable.cc: 39: FAILED assert(r >= 0)

and below is the full crash....
attached is the "objdump -rdS /usr/bin/ceph-mds"

ceph mds stat2012-11-29 00:14:13.872619 7f5bb2889700 1 mds.0.7 handle_mds_map i am now mds.0.7
2012-11-29 00:14:13.872621 7f5bb2889700 1 mds.0.7 handle_mds_map state change up:standby --> up:creating
2012-11-29 00:14:13.872966 7f5bb2889700 0 mds.0.cache creating system inode with ino:1
2012-11-29 00:14:13.873032 7f5bb2889700 0 mds.0.cache creating system inode with ino:2
2012-11-29 00:14:13.873234 7f5bb2889700 0 mds.0.cache creating system inode with ino:100
2012-11-29 00:14:13.873240 7f5bb2889700 0 mds.0.cache creating system inode with ino:600
2012-11-29 00:14:13.873281 7f5bb2889700 0 mds.0.cache creating system inode with ino:601
2012-11-29 00:14:13.873318 7f5bb2889700 0 mds.0.cache creating system inode with ino:602
2012-11-29 00:14:13.873352 7f5bb2889700 0 mds.0.cache creating system inode with ino:603
2012-11-29 00:14:13.873393 7f5bb2889700 0 mds.0.cache creating system inode with ino:604
2012-11-29 00:14:13.873453 7f5bb2889700 0 mds.0.cache creating system inode with ino:605
2012-11-29 00:14:13.873494 7f5bb2889700 0 mds.0.cache creating system inode with ino:606
2012-11-29 00:14:13.873529 7f5bb2889700 0 mds.0.cache creating system inode with ino:607
2012-11-29 00:14:13.873580 7f5bb2889700 0 mds.0.cache creating system inode with ino:608
2012-11-29 00:14:13.873614 7f5bb2889700 0 mds.0.cache creating system inode with ino:609
2012-11-29 00:14:13.873649 7f5bb2889700 0 mds.0.cache creating system inode with ino:200
2012-11-29 00:14:13.873829 7f5bb2889700 1 mds.0.cache handle_mds_failure mds.0 : recovery peers are
2012-11-29 00:14:13.889027 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.21:6804/3310
2012-11-29 00:14:13.892693 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.22:6803/1418
2012-11-29 00:14:13.893313 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.22:6800/31304
2012-11-29 00:14:13.896744 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.26:6800/15105
2012-11-29 00:14:13.901255 7f5bb2889700 -1 mds/MDSTable.cc: In function 'virtual void C_MT_Save::finish(int)' thread 7f5bb2889700 time 2012-11-29 00:14:13.900486
mds/MDSTable.cc: 39: FAILED assert(r >= 0)
ceph version 0.48.2argonaut (commit:3e02b2fad88c2a95d9c0c86878f10d1beb780bfe)
1: /usr/bin/ceph-mds() [0x668bb2]
2: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xe03) [0x6b6083]
3: (MDS::handle_core_message(Message*)+0xae8) [0x4c1708]
4: (MDS::_dispatch(Message*)+0x2f) [0x4c18cf]
5: (MDS::ms_dispatch(Message*)+0x1eb) [0x4c34ab]
6: (SimpleMessenger::DispatchQueue::entry()+0x903) [0x7579a3]
7: (SimpleMessenger::dispatch_entry()+0x24) [0x758744]
8: (SimpleMessenger::DispatchThread::entry()+0xd) [0x717a5d]
9: (()+0x7e9a) [0x7f5bb7c68e9a]
10: (clone()+0x6d) [0x7f5bb6b0c4bd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
193> 2012-11-29 00:14:03.868751 7f5bb85d4780 5 asok(0x2e8b000) register_command perfcounters_dump hook 0x2e80010
-192> 2012-11-29 00:14:03.868783 7f5bb85d4780 5 asok(0x2e8b000) register_command 1 hook 0x2e80010
-191> 2012-11-29 00:14:03.868797 7f5bb85d4780 5 asok(0x2e8b000) register_command perf dump hook 0x2e80010
-190> 2012-11-29 00:14:03.868813 7f5bb85d4780 5 asok(0x2e8b000) register_command perfcounters_schema hook 0x2e80010
-189> 2012-11-29 00:14:03.868824 7f5bb85d4780 5 asok(0x2e8b000) register_command 2 hook 0x2e80010
-188> 2012-11-29 00:14:03.868834 7f5bb85d4780 5 asok(0x2e8b000) register_command perf schema hook 0x2e80010
-187> 2012-11-29 00:14:03.868844 7f5bb85d4780 5 asok(0x2e8b000) register_command config show hook 0x2e80010
-186> 2012-11-29 00:14:03.868853 7f5bb85d4780 5 asok(0x2e8b000) register_command config set hook 0x2e80010
-185> 2012-11-29 00:14:03.868861 7f5bb85d4780 5 asok(0x2e8b000) register_command log flush hook 0x2e80010
-184> 2012-11-29 00:14:03.868869 7f5bb85d4780 5 asok(0x2e8b000) register_command log dump hook 0x2e80010
-183> 2012-11-29 00:14:03.868876 7f5bb85d4780 5 asok(0x2e8b000) register_command log reopen hook 0x2e80010
-182> 2012-11-29 00:14:03.869659 7f5bb85d4780 0 ceph version 0.48.2argonaut (commit:3e02b2fad88c2a95d9c0c86878f10d1beb780bfe), process ceph-mds, pid 7389
-181> 2012-11-29 00:14:03.869895 7f5bb85d4780 1 - 0.0.0.0:6803/7389 accepter.bind my_inst.addr is 0.0.0.0:6803/7389 need_addr=1
180> 2012-11-29 00:14:03.872243 7f5bb85d4780 1 finished global_init_daemonize
-179> 2012-11-29 00:14:03.873959 7f5bb85d4780 5 asok(0x2e8b000) init /var/run/ceph/ceph-mds.a.asok
-178> 2012-11-29 00:14:03.873972 7f5bb85d4780 5 asok(0x2e8b000) bind_and_listen /var/run/ceph/ceph-mds.a.asok
-177> 2012-11-29 00:14:03.873993 7f5bb85d4780 5 asok(0x2e8b000) register_command 0 hook 0x2e7f0a8
-176> 2012-11-29 00:14:03.873998 7f5bb85d4780 5 asok(0x2e8b000) register_command version hook 0x2e7f0a8
-175> 2012-11-29 00:14:03.874001 7f5bb85d4780 5 asok(0x2e8b000) register_command git_version hook 0x2e7f0a8
-174> 2012-11-29 00:14:03.874003 7f5bb85d4780 5 asok(0x2e8b000) register_command help hook 0x2e800c0
-173> 2012-11-29 00:14:03.874074 7f5bb85d4780 1 - 0.0.0.0:6803/7389 messenger.start
~~193> 2012-11-29 00:14:03.874084 7f5bb85d4780 1 -~~ 0.0.0.0:6803/7389 accepter.start
192> 2012-11-29 00:14:03.874234 7f5bb85d4780 2 auth: CephX auth is not supported.
-191> 2012-11-29 00:14:03.874326 7f5bb85d4780 1 - 0.0.0.0:6803/7389 --> 10.1.10.22:6789/0 -- auth(proto 0 26 bytes epoch 0) v1 -- ?+0 0x2e90e00 con 0x2ebd280
190> 2012-11-29 00:14:03.876323 7f5bb488d700 5 asok(0x2e8b000) entry start
-189> 2012-11-29 00:14:03.876824 7f5bb1086700 1 - 10.1.10.21:6803/7389 learned my addr 10.1.10.21:6803/7389
188> 2012-11-29 00:14:03.877182 7f5bb2889700 0 mds.-1.0 ms_handle_connect on 10.1.10.22:6789/0
-187> 2012-11-29 00:14:03.879827 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 473 (0 -> 473)
-186> 2012-11-29 00:14:03.880136 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 1 ==== mon_map v1 ==== 473+0+0 (1810473923 0 0) 0x2ec0400 con 0x2ebd280
185> 2012-11-29 00:14:03.880167 7f5bb2889700 1 monclient(hunting): found mon.c
-184> 2012-11-29 00:14:03.880173 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 473 (0xaab328 -> 0)
-183> 2012-11-29 00:14:03.880210 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 24 (0 -> 24)
-182> 2012-11-29 00:14:03.880273 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 2 ==== auth_reply(proto 1 0 Success) v1 ==== 24+0+0 (1089245616 0 0) 0x2ec0200 con 0x2ebd280
~~181> 2012-11-29 00:14:03.880302 7f5bb2889700 1 -~~ 10.1.10.21:6803/7389 --> 10.1.10.22:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x2ea31c0 con 0x2ebd280
180> 2012-11-29 00:14:03.880356 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 24 (0xaab328 -> 0)
-179> 2012-11-29 00:14:03.880375 7f5bb85d4780 5 monclient: authenticate success, global_id 5053
-178> 2012-11-29 00:14:03.880425 7f5bb85d4780 1 - 10.1.10.21:6803/7389 --> 10.1.10.22:6789/0 -- mdsbeacon(5053/a up:boot seq 1 v0) v2 -- ?+0 0x2ebc500 con 0x2ebd280
177> 2012-11-29 00:14:03.880444 7f5bb85d4780 5 asok(0x2e8b000) register_command objecter_requests hook 0x2e80100
-176> 2012-11-29 00:14:03.880456 7f5bb85d4780 1 - 10.1.10.21:6803/7389 --> 10.1.10.22:6789/0 -- mon_subscribe({monmap=2+,osdmap=0}) v2 -- ?+0 0x2ea38c0 con 0x2ebd280
~~175> 2012-11-29 00:14:03.880465 7f5bb85d4780 1 -~~ 10.1.10.21:6803/7389 --> 10.1.10.22:6789/0 -- mon_subscribe({mdsmap=0+,monmap=2+,osdmap=0}) v2 -- ?+0 0x2ea3700 con 0x2ebd280
174> 2012-11-29 00:14:03.884484 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 473 (0 -> 473)
-173> 2012-11-29 00:14:03.884525 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 3 ==== mon_map v1 ==== 473+0+0 (1810473923 0 0) 0x2ec0c00 con 0x2ebd280
172> 2012-11-29 00:14:03.884543 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 473 (0xaab328 -> 0)
-171> 2012-11-29 00:14:03.884555 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 20 (0 -> 20)
-170> 2012-11-29 00:14:03.884580 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 4 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (3361640162 0 0) 0x2ea31c0 con 0x2ebd280
169> 2012-11-29 00:14:03.884589 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 20 (0xaab328 -> 0)
-168> 2012-11-29 00:14:03.884599 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 4423 (0 -> 4423)
-167> 2012-11-29 00:14:03.884641 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 5 ==== osd_map(123..123 src has 1..123) v3 ==== 4423+0+0 (2572857167 0 0) 0x2ec0c00 con 0x2ebd280
166> 2012-11-29 00:14:03.884722 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 4423 (0xaab328 -> 0)
-165> 2012-11-29 00:14:03.884736 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 20 (0 -> 20)
-164> 2012-11-29 00:14:03.884754 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 6 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (3361640162 0 0) 0x2ea3a80 con 0x2ebd280
163> 2012-11-29 00:14:03.884762 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 20 (0xaab328 -> 0)
-162> 2012-11-29 00:14:03.884771 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 535 (0 -> 535)
-161> 2012-11-29 00:14:03.884793 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 7 ==== mdsmap(e 126) v1 ==== 535+0+0 (4058266551 0 0) 0x2ec0e00 con 0x2ebd280
160> 2012-11-29 00:14:03.884803 7f5bb2889700 5 mds.-1.0 handle_mds_map epoch 126 from mon.1
-159> 2012-11-29 00:14:03.884818 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 535 (0xaab328 -> 0)
-158> 2012-11-29 00:14:03.884829 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 4423 (0 -> 4423)
-157> 2012-11-29 00:14:03.884852 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 8 ==== osd_map(123..123 src has 1..123) v3 ==== 4423+0+0 (2572857167 0 0) 0x2ec0200 con 0x2ebd280
156> 2012-11-29 00:14:03.884862 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 4423 (0xaab328 -> 0)
-155> 2012-11-29 00:14:03.884877 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 20 (0 -> 20)
-154> 2012-11-29 00:14:03.884946 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 9 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (3361640162 0 0) 0x2ea38c0 con 0x2ebd280
153> 2012-11-29 00:14:03.884955 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 20 (0xaab328 -> 0)
-152> 2012-11-29 00:14:03.889781 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 733 (0 -> 733)
-151> 2012-11-29 00:14:03.889828 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 10 ==== mdsmap(e 127) v1 ==== 733+0+0 (941466860 0 0) 0x2ecb800 con 0x2ebd280
150> 2012-11-29 00:14:03.889839 7f5bb2889700 5 mds.-1.-1 handle_mds_map epoch 127 from mon.1
-149> 2012-11-29 00:14:03.889854 7f5bb2889700 1 mds.-1.0 handle_mds_map standby
-148> 2012-11-29 00:14:03.889859 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 733 (0xaab328 -> 0)
-147> 2012-11-29 00:14:07.884413 7f5bb0f85700 1 - 10.1.10.21:6803/7389 --> 10.1.10.22:6789/0 -- mdsbeacon(5053/a up:standby seq 2 v127) v2 -- ?+0 0x2ebc780 con 0x2ebd280
146> 2012-11-29 00:14:07.888124 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 103 (0 -> 103)
-145> 2012-11-29 00:14:07.888193 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 11 ==== mdsbeacon(5053/a up:standby seq 2 v127) v2 ==== 103+0+0 (3207107670 0 0) 0x2ebc500 con 0x2ebd280
144> 2012-11-29 00:14:07.888229 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 103 (0xaab328 -> 0)
-143> 2012-11-29 00:14:11.888557 7f5bb0f85700 1 - 10.1.10.21:6803/7389 --> 10.1.10.22:6789/0 -- mdsbeacon(5053/a up:standby seq 3 v127) v2 -- ?+0 0x2ebca00 con 0x2ebd280
142> 2012-11-29 00:14:11.896688 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 103 (0 -> 103)
-141> 2012-11-29 00:14:11.896911 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 12 ==== mdsbeacon(5053/a up:standby seq 3 v127) v2 ==== 103+0+0 (3322014001 0 0) 0x2ebcc80 con 0x2ebd280
140> 2012-11-29 00:14:11.896949 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 103 (0xaab328 -> 0)
-139> 2012-11-29 00:14:13.872525 7f5bb85d2700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 535 (0 -> 535)
-138> 2012-11-29 00:14:13.872576 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== mon.1 10.1.10.22:6789/0 13 ==== mdsmap(e 128) v1 ==== 535+0+0 (1993446896 0 0) 0x2ecb600 con 0x2ebd280
137> 2012-11-29 00:14:13.872592 7f5bb2889700 5 mds.-1.0 handle_mds_map epoch 128 from mon.1
-136> 2012-11-29 00:14:13.872615 7f5bb2889700 1 - 10.1.10.21:6803/7389 mark_down 10.1.10.21:6803/6909 -- pipe dne
135> 2012-11-29 00:14:13.872619 7f5bb2889700 1 mds.0.7 handle_mds_map i am now mds.0.7
-134> 2012-11-29 00:14:13.872621 7f5bb2889700 1 mds.0.7 handle_mds_map state change up:standby -> up:creating
133> 2012-11-29 00:14:13.872623 7f5bb2889700 3 mds.0.7 boot_create
-132> 2012-11-29 00:14:13.872630 7f5bb2889700 5 mds.0.log create empty log
-131> 2012-11-29 00:14:13.872636 7f5bb2889700 1 mds.0.journaler(ro) set_writeable
-130> 2012-11-29 00:14:13.872637 7f5bb2889700 1 mds.0.journaler(rw) create blank journal
-129> 2012-11-29 00:14:13.872664 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 84
-128> 2012-11-29 00:14:13.872666 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-127> 2012-11-29 00:14:13.872740 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6803/15483 -- osd_op(mds.0.7:1 200.00000000 [writefull 0~84] 1.844f3494) v4 -- ?+0 0x2ec8000 con 0x2ebdb40
126> 2012-11-29 00:14:13.872776 7f5bb2889700 5 mds.0.log submit_entry 4194304~127 : ESubtreeMap 0 subtrees , 0 ambiguous [metablob]
-125> 2012-11-29 00:14:13.872802 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 0
-124> 2012-11-29 00:14:13.872803 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-123> 2012-11-29 00:14:13.872808 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6803/15483 -- osd_op(mds.0.7:2 200.00000001 [delete] 1.6e5f474) v4 -- ?+0 0x2ec8b40 con 0x2ebdb40
122> 2012-11-29 00:14:13.872815 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 0
-121> 2012-11-29 00:14:13.872816 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-120> 2012-11-29 00:14:13.872822 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6803/15483 -- osd_op(mds.0.7:3 200.00000002 [delete] 1.eb272dbb) v4 -- ?+0 0x2ed4480 con 0x2ebdb40
119> 2012-11-29 00:14:13.872829 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 0
-118> 2012-11-29 00:14:13.872833 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-117> 2012-11-29 00:14:13.872861 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6804/3310 -- osd_op(mds.0.7:4 200.00000003 [delete] 1.95e3ab) v4 -- ?+0 0x2ed4240 con 0x2ebdc80
116> 2012-11-29 00:14:13.872872 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 0
-115> 2012-11-29 00:14:13.872873 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-114> 2012-11-29 00:14:13.872899 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6800/15105 -- osd_op(mds.0.7:5 200.00000004 [delete] 1.1ba6bc1f) v4 -- ?+0 0x2ed4000 con 0x2ed6140
113> 2012-11-29 00:14:13.872915 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 0
-112> 2012-11-29 00:14:13.872916 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-111> 2012-11-29 00:14:13.872941 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6800/6621 -- osd_op(mds.0.7:6 200.00000005 [delete] 1.96d5827a) v4 -- ?+0 0x2ed4d80 con 0x2ed68c0
110> 2012-11-29 00:14:13.872951 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 0
-109> 2012-11-29 00:14:13.872952 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-108> 2012-11-29 00:14:13.872955 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6800/15105 -- osd_op(mds.0.7:7 200.00000006 [delete] 1.ade7efde) v4 -- ?+0 0x2ed4b40 con 0x2ed6140
107> 2012-11-29 00:14:13.872960 7f5bb2889700 3 mds.0.7 boot_create creating fresh hierarchy
-106> 2012-11-29 00:14:13.872966 7f5bb2889700 0 mds.0.cache creating system inode with ino:1
-105> 2012-11-29 00:14:13.873032 7f5bb2889700 0 mds.0.cache creating system inode with ino:2
-104> 2012-11-29 00:14:13.873142 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 256
-103> 2012-11-29 00:14:13.873145 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-102> 2012-11-29 00:14:13.873149 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6800/15105 -- osd_op(mds.0.7:8 2.00000000 [setxattr path (6),setxattr parent (38),tmapup 0~0] 1.96f33707) v4 -- ?+0 0x2ed46c0 con 0x2ed6140
101> 2012-11-29 00:14:13.873190 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 580
-100> 2012-11-29 00:14:13.873192 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-99> 2012-11-29 00:14:13.873200 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6804/3310 -- osd_op(mds.0.7:9 1.00000000 [setxattr path,setxattr parent (13),tmapput 0~557] 1.6b2cdaff) v4 -- ?+0 0x2f06900 con 0x2ebdc80
98> 2012-11-29 00:14:13.873219 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 428
-97> 2012-11-29 00:14:13.873220 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-96> 2012-11-29 00:14:13.873225 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6803/15483 -- osd_op(mds.0.7:10 1.00000000.inode [writefull 0~428] 1.232c0e14) v4 -- ?+0 0x2f066c0 con 0x2ebdb40
95> 2012-11-29 00:14:13.873231 7f5bb2889700 3 mds.0.7 boot_create creating mydir hierarchy
-94> 2012-11-29 00:14:13.873234 7f5bb2889700 0 mds.0.cache creating system inode with ino:100
-93> 2012-11-29 00:14:13.873240 7f5bb2889700 0 mds.0.cache creating system inode with ino:600
-92> 2012-11-29 00:14:13.873268 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-91> 2012-11-29 00:14:13.873270 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-90> 2012-11-29 00:14:13.873273 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6800/6621 -- osd_op(mds.0.7:11 600.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.c2e541b0) v4 -- ?+0 0x2f06000 con 0x2ed68c0
89> 2012-11-29 00:14:13.873281 7f5bb2889700 0 mds.0.cache creating system inode with ino:601
-88> 2012-11-29 00:14:13.873306 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-87> 2012-11-29 00:14:13.873308 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-86> 2012-11-29 00:14:13.873312 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6804/3310 -- osd_op(mds.0.7:12 601.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.81580290) v4 -- ?+0 0x2f06d80 con 0x2ebdc80
85> 2012-11-29 00:14:13.873318 7f5bb2889700 0 mds.0.cache creating system inode with ino:602
-84> 2012-11-29 00:14:13.873340 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-83> 2012-11-29 00:14:13.873342 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-82> 2012-11-29 00:14:13.873345 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6804/3310 -- osd_op(mds.0.7:13 602.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.2a8b6bd0) v4 -- ?+0 0x2f06b40 con 0x2ebdc80
81> 2012-11-29 00:14:13.873352 7f5bb2889700 0 mds.0.cache creating system inode with ino:603
-80> 2012-11-29 00:14:13.873378 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-79> 2012-11-29 00:14:13.873379 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-78> 2012-11-29 00:14:13.873386 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6800/6621 -- osd_op(mds.0.7:14 603.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.7a4d91b0) v4 -- ?+0 0x2f28d80 con 0x2ed68c0
77> 2012-11-29 00:14:13.873393 7f5bb2889700 0 mds.0.cache creating system inode with ino:604
-76> 2012-11-29 00:14:13.873413 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-75> 2012-11-29 00:14:13.873415 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-74> 2012-11-29 00:14:13.873443 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.22:6803/1418 -- osd_op(mds.0.7:15 604.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.43e85c95) v4 -- ?+0 0x2f28b40 con 0x2ed6500
73> 2012-11-29 00:14:13.873453 7f5bb2889700 0 mds.0.cache creating system inode with ino:605
-72> 2012-11-29 00:14:13.873482 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-71> 2012-11-29 00:14:13.873483 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-70> 2012-11-29 00:14:13.873487 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6800/6621 -- osd_op(mds.0.7:16 605.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.d0c18e1d) v4 -- ?+0 0x2f28900 con 0x2ed68c0
69> 2012-11-29 00:14:13.873494 7f5bb2889700 0 mds.0.cache creating system inode with ino:606
-68> 2012-11-29 00:14:13.873514 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-67> 2012-11-29 00:14:13.873515 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-66> 2012-11-29 00:14:13.873522 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6803/15483 -- osd_op(mds.0.7:17 606.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.f89eaaf4) v4 -- ?+0 0x2f286c0 con 0x2ebdb40
65> 2012-11-29 00:14:13.873529 7f5bb2889700 0 mds.0.cache creating system inode with ino:607
-64> 2012-11-29 00:14:13.873555 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-63> 2012-11-29 00:14:13.873557 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-62> 2012-11-29 00:14:13.873567 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6800/6621 -- osd_op(mds.0.7:18 607.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.bb590b7c) v4 -- ?+0 0x2f28480 con 0x2ed68c0
61> 2012-11-29 00:14:13.873580 7f5bb2889700 0 mds.0.cache creating system inode with ino:608
-60> 2012-11-29 00:14:13.873602 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-59> 2012-11-29 00:14:13.873604 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-58> 2012-11-29 00:14:13.873607 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6804/3310 -- osd_op(mds.0.7:19 608.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.c4405e8e) v4 -- ?+0 0x2f28240 con 0x2ebdc80
57> 2012-11-29 00:14:13.873614 7f5bb2889700 0 mds.0.cache creating system inode with ino:609
-56> 2012-11-29 00:14:13.873638 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 263
-55> 2012-11-29 00:14:13.873640 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-54> 2012-11-29 00:14:13.873643 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6800/15105 -- osd_op(mds.0.7:20 609.00000000 [setxattr path (12),setxattr parent (39),tmapup 0~0] 1.60b82d07) v4 -- ?+0 0x2f28000 con 0x2ed6140
53> 2012-11-29 00:14:13.873649 7f5bb2889700 0 mds.0.cache creating system inode with ino:200
-52> 2012-11-29 00:14:13.873686 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 4117
-51> 2012-11-29 00:14:13.873688 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-50> 2012-11-29 00:14:13.873691 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6800/15105 -- osd_op(mds.0.7:21 100.00000000 [setxattr path (5),setxattr parent (13),tmapput 0~4089] 1.c5265ab3) v4 -- ?+0 0x2f06240 con 0x2ed6140
49> 2012-11-29 00:14:13.873706 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 399
-48> 2012-11-29 00:14:13.873708 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-47> 2012-11-29 00:14:13.873713 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.21:6804/3310 -- osd_op(mds.0.7:22 100.00000000.inode [writefull 0~399] 1.85dde07f) v4 -- ?+0 0x2f5ed80 con 0x2ebdc80
46> 2012-11-29 00:14:13.873731 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 29
-45> 2012-11-29 00:14:13.873732 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-44> 2012-11-29 00:14:13.873735 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6800/15105 -- osd_op(mds.0.7:23 mds0_inotable [writefull 0~29] 1.b852b893) v4 -- ?+0 0x2f5eb40 con 0x2ed6140
43> 2012-11-29 00:14:13.873748 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 17
-42> 2012-11-29 00:14:13.873751 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-41> 2012-11-29 00:14:13.873754 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6803/15483 -- osd_op(mds.0.7:24 mds0_sessionmap [writefull 0~17] 1.3270c60b) v4 -- ?+0 0x2f5e900 con 0x2ebdb40
40> 2012-11-29 00:14:13.873767 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 29
-39> 2012-11-29 00:14:13.873768 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-38> 2012-11-29 00:14:13.873771 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.26:6800/15105 -- osd_op(mds.0.7:25 mds_anchortable [writefull 0~29] 1.a977f6a7) v4 -- ?+0 0x2f5e6c0 con 0x2ed6140
37> 2012-11-29 00:14:13.873784 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) take 41
-36> 2012-11-29 00:14:13.873786 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) take 1
-35> 2012-11-29 00:14:13.873817 7f5bb2889700 1 - 10.1.10.21:6803/7389 --> 10.1.10.22:6800/31304 -- osd_op(mds.0.7:26 mds_snaptable [writefull 0~41] 1.d90270ad) v4 -- ?+0 0x2f5e480 con 0x2ed6b40
34> 2012-11-29 00:14:13.873829 7f5bb2889700 1 mds.0.cache handle_mds_failure mds.0 : recovery peers are
-33> 2012-11-29 00:14:13.873835 7f5bb2889700 5 mds.0.migrator handle_mds_failure_or_stop mds.0
-32> 2012-11-29 00:14:13.873861 7f5bb2889700 5 mds.0.bal rebalance done
-31> 2012-11-29 00:14:13.873869 7f5bb2889700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) put 535 (0xaab328 -> 0)
-30> 2012-11-29 00:14:13.889027 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.21:6804/3310
-29> 2012-11-29 00:14:13.892693 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.22:6803/1418
-28> 2012-11-29 00:14:13.893313 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.22:6800/31304
-27> 2012-11-29 00:14:13.896744 7f5bb2889700 0 mds.0.7 ms_handle_connect on 10.1.10.26:6800/15105
-26> 2012-11-29 00:14:13.900367 7f5bb007d700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (0 -> 195)
-25> 2012-11-29 00:14:13.900408 7f5baff7c700 5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 112 (195 -> 307)
-24> 2012-11-29 00:14:13.900443 7f5bb2889700 1 - 10.1.10.21:6803/7389 <== osd.4 10.1.10.22:6800/31304 1 ==== osd_op_reply(26 mds_snaptable [writefull 0~41] ondisk = -6 (No such device or address)) v4 ==== 112+0+0 (4018908758 0 0) 0x2f6a200 con 0x2ed6b40
-23> 2012-11-29 00:14:13.900469 7f5bb2889700 5 throttle(objecter_bytes 0x2eb7238) put 41 (0xaab328 -> 8569)
-22> 2012-11-29 00:14:13.900472 7f5bb2889700 5 throttle(objecter_ops 0x2eb72b0) put 1 (0xaab328 -> 25)
-21> 2012-11-29 00:14:13.901255 7f5bb2889700 -1 mds/MDSTable.cc: In function 'virtual void C_MT_Save::finish(int)' thread 7f5bb2889700 time 2012-11-29 00:14:13.900486
mds/MDSTable.cc: 39: FAILED assert(r >= 0)

ceph version 0.48.2argonaut (commit:3e02b2fad88c2a95d9c0c86878f10d1beb780bfe)
 1: /usr/bin/ceph-mds() [0x668bb2]
 2: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xe03) [0x6b6083]
 3: (MDS::handle_core_message(Message*)+0xae8) [0x4c1708]
 4: (MDS::_dispatch(Message*)+0x2f) [0x4c18cf]
 5: (MDS::ms_dispatch(Message*)+0x1eb) [0x4c34ab]
 6: (SimpleMessenger::DispatchQueue::entry()+0x903) [0x7579a3]
 7: (SimpleMessenger::dispatch_entry()+0x24) [0x758744]
 8: (SimpleMessenger::DispatchThread::entry()+0xd) [0x717a5d]
 9: (()+0x7e9a) [0x7f5bb7c68e9a]
 10: (clone()+0x6d) [0x7f5bb6b0c4bd]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.

20> 2012-11-29 00:14:13.920617 7f5bafe7b700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 111 (307 -> 418)
   -19> 2012-11-29 00:14:13.920736 7f5bafe7b700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 111 (418 -> 529)
   -18> 2012-11-29 00:14:13.920756 7f5bafe7b700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 112 (529 -> 641)
   -17> 2012-11-29 00:14:13.921239 7f5bafe7b700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 114 (641 -> 755)
   -16> 2012-11-29 00:14:13.921259 7f5bafe7b700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 193 (755 -> 948)
   -15> 2012-11-29 00:14:13.921277 7f5bafe7b700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (948 -> 1143)
   -14> 2012-11-29 00:14:13.921294 7f5bafe7b700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (1143 -> 1338)
   -13> 2012-11-29 00:14:13.921322 7f5bb017e700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 111 (1338 -> 1449)
   -12> 2012-11-29 00:14:13.921364 7f5bb017e700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 193 (1449 -> 1642)
   -11> 2012-11-29 00:14:13.921385 7f5bb017e700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (1642 -> 1837)
   -10> 2012-11-29 00:14:13.921403 7f5bb017e700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (1837 -> 2032)
    -9> 2012-11-29 00:14:13.921425 7f5bb017e700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (2032 -> 2227)
    -8> 2012-11-29 00:14:13.924156 7f5bafc79700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 111 (2227 -> 2338)
    -7> 2012-11-29 00:14:13.924344 7f5bafc79700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 111 (2338 -> 2449)
    -6> 2012-11-29 00:14:13.924412 7f5bafc79700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 115 (2449 -> 2564)
    -5> 2012-11-29 00:14:13.924470 7f5bafc79700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (2564 -> 2759)
    -4> 2012-11-29 00:14:13.925622 7f5bafd7a700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (2759 -> 2954)
    -3> 2012-11-29 00:14:13.925676 7f5bafd7a700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (2954 -> 3149)
    -2> 2012-11-29 00:14:13.925722 7f5bafd7a700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 195 (3149 -> 3344)
    -1> 2012-11-29 00:14:13.925770 7f5bafd7a700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 111 (3344 -> 3455)
     0> 2012-11-29 00:14:13.925813 7f5bafd7a700  5 throttle(msgr_dispatch_throttler-mds 0x2e859e0) get 400 (3455 -> 3855)
-- end dump of recent events ---
2012-11-29 00:14:14.054031 7f5bb2889700 -1 ** Caught signal (Aborted) *
 in thread 7f5bb2889700

ceph version 0.48.2argonaut (commit:3e02b2fad88c2a95d9c0c86878f10d1beb780bfe)
 1: /usr/bin/ceph-mds() [0x7e315a]
 2: (()+0xfcb0) [0x7f5bb7c70cb0]
 3: (gsignal()+0x35) [0x7f5bb6a50445]
 4: (abort()+0x17b) [0x7f5bb6a53bab]
 5: (_gnu_cxx::_verbose_terminate_handler()+0x11d) [0x7f5bb739e69d]
 6: (()+0xb5846) [0x7f5bb739c846]
 7: (()+0xb5873) [0x7f5bb739c873]
 8: (()+0xb596e) [0x7f5bb739c96e]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x1de) [0x7771fe]
 10: /usr/bin/ceph-mds() [0x668bb2]
 11: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xe03) [0x6b6083]
 12: (MDS::handle_core_message(Message*)+0xae8) [0x4c1708]
 13: (MDS::_dispatch(Message*)+0x2f) [0x4c18cf]
 14: (MDS::ms_dispatch(Message*)+0x1eb) [0x4c34ab]
 15: (SimpleMessenger::DispatchQueue::entry()+0x903) [0x7579a3]
 16: (SimpleMessenger::dispatch_entry()+0x24) [0x758744]
 17: (SimpleMessenger::DispatchThread::entry()+0xd) [0x717a5d]
 18: (()+0x7e9a) [0x7f5bb7c68e9a]
 19: (clone()+0x6d) [0x7f5bb6b0c4bd]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.

--- begin dump of recent events ---
0> 2012-11-29 00:14:14.054031 7f5bb2889700 -1 ** Caught signal (Aborted) *
in thread 7f5bb2889700

ceph version 0.48.2argonaut (commit:3e02b2fad88c2a95d9c0c86878f10d1beb780bfe)
 1: /usr/bin/ceph-mds() [0x7e315a]
 2: (()+0xfcb0) [0x7f5bb7c70cb0]
 3: (gsignal()+0x35) [0x7f5bb6a50445]
 4: (abort()+0x17b) [0x7f5bb6a53bab]
 5: (_gnu_cxx::_verbose_terminate_handler()+0x11d) [0x7f5bb739e69d]
 6: (()+0xb5846) [0x7f5bb739c846]
 7: (()+0xb5873) [0x7f5bb739c873]
 8: (()+0xb596e) [0x7f5bb739c96e]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x1de) [0x7771fe]
 10: /usr/bin/ceph-mds() [0x668bb2]
 11: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xe03) [0x6b6083]
 12: (MDS::handle_core_message(Message*)+0xae8) [0x4c1708]
 13: (MDS::_dispatch(Message*)+0x2f) [0x4c18cf]
 14: (MDS::ms_dispatch(Message*)+0x1eb) [0x4c34ab]
 15: (SimpleMessenger::DispatchQueue::entry()+0x903) [0x7579a3]
 16: (SimpleMessenger::dispatch_entry()+0x24) [0x758744]
 17: (SimpleMessenger::DispatchThread::entry()+0xd) [0x717a5d]
 18: (()+0x7e9a) [0x7f5bb7c68e9a]
 19: (clone()+0x6d) [0x7f5bb6b0c4bd]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.

--- end dump of recent events ---

e128: 1/1/1 up {0=a=up:creating}
root@ceph1:/var/lib/ceph/mds/ceph-a#

Files

Download all files

mds.objdump (48.6 MB) mds.objdump	objdump -rdS /usr/bin/ceph-mds	Anonymous, 11/28/2012 04:35 PM
ceph-osd.tar.gz (30.7 MB) ceph-osd.tar.gz		Anonymous, 11/29/2012 11:15 AM

Actions

Copy link

Updated by Anonymous over 11 years ago

This cluster has 3 VM nodes

Actions

Copy link

Updated by Anonymous over 11 years ago

ubuntu@ceph1:/var/log/ceph$ uname -a
Linux ceph1 3.2.0-23-virtual #36-Ubuntu SMP Tue Apr 10 22:29:03 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

DISTRIB_DESCRIPTION="Ubuntu 12.04 LTS"

Actions

Copy link

Updated by Sage Weil over 11 years ago

Status changed from New to Need More Info
Priority changed from Normal to High

ENXIO from teh OSD means we sent the request to the wrong osd. what version is the osd running?

also, do you have the osd logs? there should be a message like 'misdirected op ...' in there somewhere...

Actions

Copy link

Updated by Anonymous over 11 years ago

ubuntu@ceph1:/var/log/ceph$ sudo service ceph status === mon.a ===
mon.a: running 0.48.2argonaut === mds.a ===
mds.a: not running. === osd.0 ===
osd.0: running 0.48.2argonaut === osd.1 ===
osd.1: running 0.48.2argonaut

attached tarfile of logs.

Actions

Copy link

Updated by Anonymous over 11 years ago

File ceph-osd.tar.gz ceph-osd.tar.gz added

too large of a file. Only did a tar for the osd logs.

Actions

Copy link

Updated by Anonymous over 11 years ago

I added requested info last week on 11/29. How do I change Status?

Actions

Copy link

Updated by Dan Mick over 11 years ago

Status changed from Need More Info to 12

update/status

Actions

Copy link

Updated by Anonymous over 11 years ago

How was this bug verified? Would you provide the test and its description in this bug, please.

Actions

Copy link

Updated by Dan Mick over 11 years ago

Verified just means we agree it's a bug. New->Verified->In Progress->Need Review->Testing->Resolved is the simple path through states

Actions

Copy link

#10

Updated by Ian Colle over 11 years ago

Project changed from Ceph to CephFS
Category changed from 1 to 47

Actions

Copy link

#11

Updated by Greg Farnum over 11 years ago

Project changed from CephFS to Ceph
Category changed from 47 to 1

Given what we know so far (the Op got sent to the wrong OSD) this is a bug in the Objecter, not the MDS. Or possibly the actual OSDs, but nothing to do with the MDS proper.

Actions

Copy link

#12

Updated by Sage Weil about 11 years ago

Status changed from 12 to Won't Fix

if/when see this on bobtail or later, we'll investigate.

Actions

Copy link

#13

Updated by John Spray over 7 years ago

Project changed from Ceph to CephFS
Category deleted (1)

Bulk updating project=ceph category=mds bugs so that I can remove the MDS category from the Ceph project to avoid confusion.

Actions

Copy link

Also available in: Atom PDF

Project

General

Profile

Ceph » CephFS

Custom queries

Bug #3553

MDS core dumped running 0.48.2argonaut

Updated by Anonymous over 11 years ago

Updated by Anonymous over 11 years ago

Updated by Sage Weil over 11 years ago

Updated by Anonymous over 11 years ago

Updated by Anonymous over 11 years ago

Updated by Anonymous over 11 years ago

Updated by Dan Mick over 11 years ago

Updated by Anonymous over 11 years ago

Updated by Dan Mick over 11 years ago

Updated by Ian Colle over 11 years ago

Updated by Greg Farnum over 11 years ago

Updated by Sage Weil about 11 years ago

Updated by John Spray over 7 years ago