Hi List; I'm having an issue where the mds failed over between two nodes, and now is stuck in "clientreplay" state. It's been like this for several hours. Here are some details about the environment:
mds/mon server sap: sap ceph # emerge --info Portage 2.1.10.65 (default/linux/amd64/10.0, gcc-4.5.3, glibc-2.14.1-r3, 3.5.3-gentoo x86_64) ================================================================= System uname: Linux-3.5.3-gentoo-x86_64-Intel-R-_Xeon-R-_CPU_E5-2620_0_@_2.00GHz-with-gentoo-2.1 Timestamp of tree: Sun, 23 Sep 2012 18:00:01 +0000 app-shells/bash: 4.2_p20 dev-lang/python: 2.7.3-r2, 3.1.3-r1, 3.2.3 dev-util/pkgconfig: 0.26 sys-apps/baselayout: 2.1-r1 sys-apps/openrc: 0.9.8.4 sys-apps/sandbox: 2.5 sys-devel/autoconf: 2.65-r1 sys-devel/automake: 1.11.1 sys-devel/binutils: 2.21.1-r1 sys-devel/gcc: 4.4.5, 4.5.3-r2 sys-devel/gcc-config: 1.6 sys-devel/libtool: 2.4-r1 sys-devel/make: 3.82-r1 sys-kernel/linux-headers: 3.4 (virtual/os-headers) sys-libs/glibc: 2.14.1-r3 mds/mon server fern: fern ceph # emerge --info Portage 2.1.10.65 (default/linux/amd64/10.0, gcc-4.5.3, glibc-2.14.1-r3, 3.5.3-gentoo x86_64) ================================================================= System uname: Linux-3.5.3-gentoo-x86_64-Intel-R-_Xeon-R-_CPU_E5-2620_0_@_2.00GHz-with-gentoo-2.1 Timestamp of tree: Mon, 24 Sep 2012 18:00:01 +0000 app-shells/bash: 4.2_p20 dev-lang/python: 2.7.3-r2, 3.1.3-r1, 3.2.3 dev-util/pkgconfig: 0.26 sys-apps/baselayout: 2.1-r1 sys-apps/openrc: 0.9.8.4 sys-apps/sandbox: 2.5 sys-devel/autoconf: 2.65-r1 sys-devel/automake: 1.11.1 sys-devel/binutils: 2.21.1-r1 sys-devel/gcc: 4.4.5, 4.5.3-r2 sys-devel/gcc-config: 1.6 sys-devel/libtool: 2.4-r1 sys-devel/make: 3.82-r1 sys-kernel/linux-headers: 3.4 (virtual/os-headers) sys-libs/glibc: 2.14.1-r3 mds/mon/osd server ocr46-ire ocr46-ire ceph # emerge --info Portage 2.1.10.65 (default/linux/amd64/10.0, gcc-4.4.5, glibc-2.14.1-r3, 3.5.3-gentoo x86_64) ================================================================= System uname: Linux-3.5.3-gentoo-x86_64-Intel-R-_Xeon-R-_CPU_E5-2620_0_@_2.00GHz-with-gentoo-2.1 Timestamp of tree: Mon, 24 Sep 2012 18:00:01 +0000 app-shells/bash: 4.2_p20 dev-lang/python: 2.7.3-r2, 3.1.3-r1, 3.2.3 dev-util/pkgconfig: 0.26 sys-apps/baselayout: 2.1-r1 sys-apps/openrc: 0.9.8.4 sys-apps/sandbox: 2.5 sys-devel/autoconf: 2.65-r1 sys-devel/automake: 1.11.1 sys-devel/binutils: 2.21.1-r1 sys-devel/gcc: 4.4.5, 4.5.3-r2 sys-devel/gcc-config: 1.6 sys-devel/libtool: 2.4-r1 sys-devel/make: 3.82-r1 sys-kernel/linux-headers: 3.4 (virtual/os-headers) sys-libs/glibc: 2.14.1-r3 osd servers ocr31-ire - ocr46-ire Portage 2.1.10.65 (default/linux/amd64/10.0, gcc-4.4.5, glibc-2.14.1-r3, 3.5.3-gentoo x86_64) ================================================================= System uname: Linux-3.5.3-gentoo-x86_64-Intel-R-_Xeon-R-_CPU_E5-2620_0_@_2.00GHz-with-gentoo-2.1 Timestamp of tree: Mon, 24 Sep 2012 18:00:01 +0000 app-shells/bash: 4.2_p20 dev-lang/python: 2.7.3-r2, 3.2.3 dev-util/pkgconfig: 0.26 sys-apps/baselayout: 2.1-r1 sys-apps/openrc: 0.9.8.4 sys-apps/sandbox: 2.5 sys-devel/autoconf: 2.65-r1 sys-devel/automake: 1.11.1 sys-devel/binutils: 2.21.1-r1 sys-devel/gcc: 4.5.3-r2 sys-devel/gcc-config: 1.6 sys-devel/libtool: 2.4-r1 sys-devel/make: 3.82-r1 sys-kernel/linux-headers: 3.4 (virtual/os-headers) sys-libs/glibc: 2.14.1-r3 All ceph servers are running ceph-0.51. Here is the output of ceph -s: ocr31-ire ~ # ceph -s health HEALTH_OK monmap e1: 3 mons at {fern=10.87.1.88:6789/0,ocr46=10.87.1.104:6789/0,sap=10.87.1.87:6789/0}, election epoch 92, quorum 0,1,2 fern,ocr46,sap osdmap e60: 192 osds: 192 up, 192 in pgmap v47728: 73728 pgs: 73728 active+clean; 290 GB data, 2794 GB used, 283 TB / 286 TB avail mdsmap e19: 1/1/1 up {0=fern=up:clientreplay}, 2 up:standby Here are the logs from sap, which was the mds master before it was told to respawn: 2012-09-25 04:45:32.588374 7f2a34a40700 0 mds.0.3 ms_handle_reset on 10.87.1.100:6832/32257 2012-09-25 04:45:32.589064 7f2a34a40700 0 mds.0.3 ms_handle_connect on 10.87.1.100:6832/32257 2012-09-25 04:45:57.787416 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 04:55:21.718357 7f2a34a40700 0 mds.0.3 ms_handle_reset on 10.87.1.89:6815/8101 2012-09-25 04:55:21.719044 7f2a34a40700 0 mds.0.3 ms_handle_connect on 10.87.1.89:6815/8101 2012-09-25 04:55:26.758359 7f2a34a40700 0 mds.0.3 ms_handle_reset on 10.87.1.96:6800/6628 2012-09-25 04:55:26.759415 7f2a34a40700 0 mds.0.3 ms_handle_connect on 10.87.1.96:6800/6628 2012-09-25 05:13:16.367476 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:18:45.177585 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:19:44.911831 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:30:38.178449 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:37:26.597832 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:37:34.088781 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:38:37.548132 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:39:21.528884 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:39:57.791457 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:40:13.579926 7f2a34a40700 0 mds.0.3 handle_mds_beacon no longer laggy 2012-09-25 05:41:07.598457 7f2a2f709700 0 -- 10.87.1.87:6801/27351 >> 10.87.1.89:0/30567 pipe(0x1db2fc0 sd=100 pgs=2 cs=1 l=0).fault with nothing to send, going to standby 2012-09-25 05:41:07.603802 7f2a30517700 0 -- 10.87.1.87:6801/27351 >> 10.87.1.94:0/9358 pipe(0x1db2b40 sd=99 pgs=2 cs=1 l=0).fault with nothing to send, going to standby 2012-09-25 05:41:07.969148 7f2a34a40700 1 mds.-1.-1 handle_mds_map i (10.87.1.87:6801/27351) dne in the mdsmap, respawning myself 2012-09-25 05:41:07.969154 7f2a34a40700 1 mds.-1.-1 respawn 2012-09-25 05:41:07.969155 7f2a34a40700 1 mds.-1.-1 e: '/usr/bin/ceph-mds' 2012-09-25 05:41:07.969157 7f2a34a40700 1 mds.-1.-1 0: '/usr/bin/ceph-mds' 2012-09-25 05:41:07.969159 7f2a34a40700 1 mds.-1.-1 1: '-i' 2012-09-25 05:41:07.969160 7f2a34a40700 1 mds.-1.-1 2: 'sap' 2012-09-25 05:41:07.969161 7f2a34a40700 1 mds.-1.-1 3: '--pid-file' 2012-09-25 05:41:07.969162 7f2a34a40700 1 mds.-1.-1 4: '/var/run/ceph/mds.sap.pid' 2012-09-25 05:41:07.969163 7f2a34a40700 1 mds.-1.-1 5: '-c' 2012-09-25 05:41:07.969164 7f2a34a40700 1 mds.-1.-1 6: '/etc/ceph/ceph.conf' 2012-09-25 05:41:07.969165 7f2a34a40700 1 mds.-1.-1 cwd / 2012-09-25 05:41:08.003262 7fae819af780 0 ceph version 0.51 (commit:c03ca95d235c9a072dcd8a77ad5274a52e93ae30), process ceph-mds, pid 1173 2012-09-25 05:41:08.005237 7fae7c9bd700 0 mds.-1.0 ms_handle_connect on 10.87.1.88:6789/0 2012-09-25 05:41:08.802610 7fae7c9bd700 1 mds.-1.0 handle_mds_map standby 2012-09-25 05:41:09.602141 7fae7c9bd700 1 mds.-1.0 handle_mds_map standby 2012-09-25 05:41:23.772891 7fae7c9bd700 1 mds.-1.0 handle_mds_map standby 2012-09-25 05:41:25.273745 7fae7c9bd700 1 mds.-1.0 handle_mds_map standby 2012-09-25 05:41:27.994344 7fae7c9bd700 1 mds.-1.0 handle_mds_map standby 2012-09-25 05:41:28.588681 7fae7c9bd700 1 mds.-1.0 handle_mds_map standby 2012-09-25 05:41:42.282588 7fae7c9bd700 1 mds.-1.0 handle_mds_map standby Why did sap get marked as down in the mdsmap? Here is the mds logs from fern, the node that took over: 2012-09-25 05:41:09.482638 7f6a921c5700 1 mds.0.4 replay_done 2012-09-25 05:41:09.482652 7f6a921c5700 1 mds.0.4 making mds journal writeable 2012-09-25 05:41:09.483589 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.94:6800/19702 2012-09-25 05:41:09.483602 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.101:6818/7441 2012-09-25 05:41:09.483606 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.90:6812/13521 2012-09-25 05:41:09.483623 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.104:6825/30845 2012-09-25 05:41:09.602861 7f6a95ae2700 1 mds.0.4 handle_mds_map i am now mds.0.4 2012-09-25 05:41:09.602865 7f6a95ae2700 1 mds.0.4 handle_mds_map state change up:replay --> up:reconnect 2012-09-25 05:41:09.602867 7f6a95ae2700 1 mds.0.4 reconnect_start 2012-09-25 05:41:09.602869 7f6a95ae2700 1 mds.0.4 reopen_log 2012-09-25 05:41:09.602879 7f6a95ae2700 1 mds.0.server reconnect_clients -- 2 sessions 2012-09-25 05:41:10.793524 7f6a95ae2700 0 log [DBG] : reconnect by client.4755 10.87.1.89:0/30567 after 1.190611 2012-09-25 05:41:10.793568 7f6a95ae2700 0 mds.0.server non-auth 10000000004 #10000000004, will pass off to authority 2012-09-25 05:41:10.793594 7f6a95ae2700 0 mds.0.server non-auth 10000000005 #10000000005, will pass off to authority 2012-09-25 05:41:10.793609 7f6a95ae2700 0 mds.0.server non-auth 10000000006 #10000000006, will pass off to authority 2012-09-25 05:41:10.793625 7f6a95ae2700 0 mds.0.server non-auth 100000000d7 #100000000d7, will pass off to authority 2012-09-25 05:41:10.793636 7f6a95ae2700 0 mds.0.server non-auth 100000000d8 #100000000d8, will pass off to authority 2012-09-25 05:41:10.793653 7f6a95ae2700 0 mds.0.server non-auth 100000000d9 #100000000d9, will pass off to authority 2012-09-25 05:41:10.793664 7f6a95ae2700 0 mds.0.server non-auth 100000000da #100000000da, will pass off to authority 2012-09-25 05:41:10.793675 7f6a95ae2700 0 mds.0.server non-auth 100000000db #100000000db, will pass off to authority ... Goes on for a few hundred thousand lines. It seems like there's a race here somewhere as it made about 860,000 lines of this "server non-auth" ... 2012-09-25 05:41:19.474557 7f6a95ae2700 0 mds.0.server non-auth 100002b8a83 #100002b8a83, will pass off to authority 2012-09-25 05:41:19.474568 7f6a95ae2700 0 mds.0.server non-auth 100002b8a84 #100002b8a84, will pass off to authority 2012-09-25 05:41:19.474579 7f6a95ae2700 0 mds.0.server non-auth 100002b8a87 #100002b8a87, will pass off to authority 2012-09-25 05:41:19.474588 7f6a95ae2700 0 mds.0.server non-auth 100002b8a89 #100002b8a89, will pass off to authority 2012-09-25 05:41:19.474605 7f6a95ae2700 0 mds.0.server non-auth 100002b8a8a #100002b8a8a, will pass off to authority 2012-09-25 05:41:19.474626 7f6a95ae2700 0 mds.0.server non-auth 100002b8a8b #100002b8a8b, will pass off to authority 2012-09-25 05:41:19.474637 7f6a95ae2700 0 mds.0.server non-auth 100002b8a8c #100002b8a8c, will pass off to authority 2012-09-25 05:41:19.474652 7f6a95ae2700 0 mds.0.server non-auth 100002b8a8d #100002b8a8d, will pass off to authority 2012-09-25 05:41:19.474667 7f6a95ae2700 0 mds.0.server non-auth 100002b8a8f #100002b8a8f, will pass off to authority 2012-09-25 05:41:19.474689 7f6a95ae2700 0 mds.0.server non-auth 100002b8a96 #100002b8a96, will pass off to authority 2012-09-25 05:41:19.484342 7f6a95ae2700 0 mds.0.server missing 100002ba853 #10000000002/ArchiveOutbound/111/1111968/20110701/385439240.tif (mine), will load later 2012-09-25 05:41:19.484361 7f6a95ae2700 0 mds.0.server missing 100002ba854 #10000000002/ArchiveOutbound/111/1111968/20110701/385439251.tif (mine), will load later 2012-09-25 05:41:19.484367 7f6a95ae2700 0 mds.0.server missing 100002ba855 #10000000002/ArchiveOutbound/111/1111968/20110701/385439350.tif (mine), will load later 2012-09-25 05:41:19.484378 7f6a95ae2700 0 mds.0.server missing 100002ba856 #10000000002/ArchiveOutbound/111/1111968/20110701/385439352.tif (mine), will load later 2012-09-25 05:41:19.484382 7f6a95ae2700 0 mds.0.server missing 100002ba857 #10000000002/ArchiveOutbound/111/1111968/20110701/385439354.tif (mine), will load later 2012-09-25 05:41:19.484387 7f6a95ae2700 0 mds.0.server missing 100002ba858 #10000000002/ArchiveOutbound/111/1111968/20110701/385439430.tif (mine), will load later 2012-09-25 05:41:19.484393 7f6a95ae2700 0 mds.0.server missing 100002ba859 #10000000002/ArchiveOutbound/111/1111968/20110701/.385439444.tif.RxChkh (mine), will load later 2012-09-25 05:41:19.484401 7f6a95ae2700 1 mds.0.4 reconnect_done 2012-09-25 05:41:23.835106 7f6a95ae2700 0 mds.0.4 handle_mds_beacon no longer laggy 2012-09-25 05:41:27.994961 7f6a95ae2700 1 mds.0.4 handle_mds_map i am now mds.0.4 2012-09-25 05:41:27.994965 7f6a95ae2700 1 mds.0.4 handle_mds_map state change up:reconnect --> up:rejoin 2012-09-25 05:41:27.994968 7f6a95ae2700 1 mds.0.4 rejoin_joint_start 2012-09-25 05:41:28.424292 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.98:6827/21424 2012-09-25 05:41:28.441796 7f6a95ae2700 1 mds.0.4 rejoin_done 2012-09-25 05:41:28.589425 7f6a95ae2700 1 mds.0.4 handle_mds_map i am now mds.0.4 2012-09-25 05:41:28.589428 7f6a95ae2700 1 mds.0.4 handle_mds_map state change up:rejoin --> up:clientreplay 2012-09-25 05:41:28.589430 7f6a95ae2700 1 mds.0.4 recovery_done -- successful recovery! 2012-09-25 05:41:28.598110 7f6a95ae2700 1 mds.0.4 clientreplay_start 2012-09-25 05:41:28.613610 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.103:6833/9804 2012-09-25 05:41:28.615111 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.95:6818/8725 2012-09-25 05:41:28.616342 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.98:6812/20834 2012-09-25 05:41:28.618528 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.102:6809/21045 2012-09-25 05:41:28.619851 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.98:6821/21183 2012-09-25 05:41:28.622614 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.89:6809/7883 2012-09-25 05:56:07.824706 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.103:6818/9242 2012-09-25 05:56:07.824827 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.100:6816/31393 2012-09-25 05:56:07.825437 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.103:6818/9242 2012-09-25 05:56:07.834669 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.96:6809/6968 2012-09-25 05:56:07.835271 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.96:6809/6968 2012-09-25 05:56:08.094667 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.101:6824/7669 2012-09-25 05:56:08.095320 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.101:6824/7669 2012-09-25 05:56:08.104670 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.94:6803/19811 2012-09-25 05:56:08.105254 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.94:6803/19811 2012-09-25 05:56:08.464684 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.99:6815/4360 2012-09-25 05:56:08.465283 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.99:6815/4360 2012-09-25 05:56:08.554740 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.101:6830/7898 2012-09-25 05:56:08.554815 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.96:6827/7710 2012-09-25 05:56:08.555387 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.96:6827/7710 2012-09-25 05:56:08.555395 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.101:6830/7898 2012-09-25 05:56:08.564681 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.104:6816/30466 2012-09-25 05:56:08.564759 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.93:6833/28547 2012-09-25 05:56:08.565390 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.104:6816/30466 2012-09-25 05:56:08.565415 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.93:6833/28547 2012-09-25 05:56:08.574702 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.98:6830/21540 2012-09-25 05:56:08.574746 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.104:6804/29957 2012-09-25 05:56:08.575357 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.104:6804/29957 2012-09-25 05:56:08.575366 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.98:6830/21540 2012-09-25 05:56:08.584683 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.101:6806/6990 2012-09-25 05:56:08.585261 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.101:6806/6990 2012-09-25 05:56:08.594677 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.100:6828/31704 2012-09-25 05:56:08.654687 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.102:6833/21939 2012-09-25 05:56:08.655264 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.102:6833/21939 2012-09-25 05:56:08.694689 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.90:6833/14293 2012-09-25 05:56:08.695442 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.90:6833/14293 ... 2012-09-25 09:41:30.183380 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.95:6818/8725 2012-09-25 09:41:30.202467 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.89:6809/7883 2012-09-25 09:41:30.203014 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.89:6809/7883 2012-09-25 09:41:30.224668 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.98:6812/20834 2012-09-25 09:41:30.254959 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.98:6812/20834 2012-09-25 09:41:30.274665 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.98:6821/21183 2012-09-25 09:41:30.286990 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.93:6827/28326 2012-09-25 09:41:30.287631 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.93:6827/28326 2012-09-25 09:41:30.294907 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.98:6821/21183 2012-09-25 09:41:30.353745 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.99:6833/5044 2012-09-25 09:41:30.354364 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.99:6833/5044 2012-09-25 09:41:32.934674 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.104:6819/30603 2012-09-25 09:41:32.935642 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.104:6819/30603 2012-09-25 09:41:33.254681 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.100:6854/32722 2012-09-25 09:41:33.279245 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.100:6854/32722 2012-09-25 09:41:40.012905 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.103:6833/9804 2012-09-25 09:41:40.013620 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.103:6833/9804 2012-09-25 09:41:51.574710 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.93:6800/27331 2012-09-25 09:41:51.581248 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.93:6800/27331 2012-09-25 09:42:01.164453 7f6a95ae2700 0 mds.0.4 ms_handle_reset on 10.87.1.94:6815/20249 2012-09-25 09:42:01.165036 7f6a95ae2700 0 mds.0.4 ms_handle_connect on 10.87.1.94:6815/20249 I enabled a higher level of debugging from ferns mds server: ceph mds tell 'fern' injectargs "--debug_mds 20" Here is what the mds logs show on fern: 2012-09-25 09:54:50.017750 7f6a95ae2700 -1 mds.0.4 applying configuration change: internal_safe_to_start_threads = 'true' 2012-09-25 09:54:52.770191 7f6a941de700 10 mds.0.4 beacon_send up:clientreplay seq 16692 (currently up:clientreplay) 2012-09-25 09:54:52.770761 7f6a95ae2700 10 mds.0.4 handle_mds_beacon up:clientreplay seq 16692 rtt 0.000562 2012-09-25 09:54:54.723205 7f6a941de700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0> 2012-09-25 09:54:54.723241 7f6a941de700 10 mds.0.locker scatter_tick 2012-09-25 09:54:54.723244 7f6a941de700 10 mds.0.server find_idle_sessions. laggy until 2012-09-25 05:41:23.835106 2012-09-25 09:54:54.723256 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 2012-09-25 09:54:54.723262 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 and sufficiently new (2012-09-25 09:54:45.380736) 2012-09-25 09:54:56.770279 7f6a941de700 10 mds.0.4 beacon_send up:clientreplay seq 16693 (currently up:clientreplay) 2012-09-25 09:54:56.770782 7f6a95ae2700 10 mds.0.4 handle_mds_beacon up:clientreplay seq 16693 rtt 0.000489 2012-09-25 09:54:59.723269 7f6a941de700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0> 2012-09-25 09:54:59.723304 7f6a941de700 10 mds.0.locker scatter_tick 2012-09-25 09:54:59.723306 7f6a941de700 10 mds.0.server find_idle_sessions. laggy until 2012-09-25 05:41:23.835106 2012-09-25 09:54:59.723312 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 2012-09-25 09:54:59.723318 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 and sufficiently new (2012-09-25 09:54:45.380736) 2012-09-25 09:55:00.770376 7f6a941de700 10 mds.0.4 beacon_send up:clientreplay seq 16694 (currently up:clientreplay) 2012-09-25 09:55:00.770875 7f6a95ae2700 10 mds.0.4 handle_mds_beacon up:clientreplay seq 16694 rtt 0.000491 2012-09-25 09:55:04.723314 7f6a941de700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0> 2012-09-25 09:55:04.723340 7f6a941de700 10 mds.0.locker scatter_tick 2012-09-25 09:55:04.723344 7f6a941de700 10 mds.0.server find_idle_sessions. laggy until 2012-09-25 05:41:23.835106 2012-09-25 09:55:04.723349 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 2012-09-25 09:55:04.723355 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 and sufficiently new (2012-09-25 09:54:45.380736) 2012-09-25 09:55:04.770462 7f6a941de700 10 mds.0.4 beacon_send up:clientreplay seq 16695 (currently up:clientreplay) 2012-09-25 09:55:04.771033 7f6a95ae2700 10 mds.0.4 handle_mds_beacon up:clientreplay seq 16695 rtt 0.000566 2012-09-25 09:55:05.381914 7f6a95ae2700 20 mds.0.server get_session have 0x3419d40 client.4755 10.87.1.89:0/30567 state open 2012-09-25 09:55:05.381922 7f6a95ae2700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 3303) v1 from client.4755 2012-09-25 09:55:06.426145 7f6a95ae2700 20 mds.0.server get_session have 0x302b680 client.4746 10.87.1.94:0/9358 state open 2012-09-25 09:55:06.426153 7f6a95ae2700 3 mds.0.server handle_client_session client_session(request_renewcaps seq 3304) v1 from client.4746 2012-09-25 09:55:08.770543 7f6a941de700 10 mds.0.4 beacon_send up:clientreplay seq 16696 (currently up:clientreplay) 2012-09-25 09:55:08.771030 7f6a95ae2700 10 mds.0.4 handle_mds_beacon up:clientreplay seq 16696 rtt 0.000479 2012-09-25 09:55:09.723353 7f6a941de700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0> 2012-09-25 09:55:09.723372 7f6a941de700 10 mds.0.locker scatter_tick 2012-09-25 09:55:09.723374 7f6a941de700 10 mds.0.server find_idle_sessions. laggy until 2012-09-25 05:41:23.835106 2012-09-25 09:55:09.723379 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 2012-09-25 09:55:09.723383 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 and sufficiently new (2012-09-25 09:55:05.381926) 2012-09-25 09:55:12.770623 7f6a941de700 10 mds.0.4 beacon_send up:clientreplay seq 16697 (currently up:clientreplay) 2012-09-25 09:55:12.771158 7f6a95ae2700 10 mds.0.4 handle_mds_beacon up:clientreplay seq 16697 rtt 0.000529 2012-09-25 09:55:14.723412 7f6a941de700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0> 2012-09-25 09:55:14.723431 7f6a941de700 10 mds.0.locker scatter_tick 2012-09-25 09:55:14.723433 7f6a941de700 10 mds.0.server find_idle_sessions. laggy until 2012-09-25 05:41:23.835106 2012-09-25 09:55:14.723438 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 2012-09-25 09:55:14.723442 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 and sufficiently new (2012-09-25 09:55:05.381926) 2012-09-25 09:55:16.770700 7f6a941de700 10 mds.0.4 beacon_send up:clientreplay seq 16698 (currently up:clientreplay) 2012-09-25 09:55:16.771198 7f6a95ae2700 10 mds.0.4 handle_mds_beacon up:clientreplay seq 16698 rtt 0.000491 2012-09-25 09:55:19.723466 7f6a941de700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0> 2012-09-25 09:55:19.723485 7f6a941de700 10 mds.0.locker scatter_tick 2012-09-25 09:55:19.723487 7f6a941de700 10 mds.0.server find_idle_sessions. laggy until 2012-09-25 05:41:23.835106 2012-09-25 09:55:19.723491 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 2012-09-25 09:55:19.723496 7f6a941de700 20 mds.0.server laggiest active session is client.4755 10.87.1.89:0/30567 and sufficiently new (2012-09-25 09:55:05.381926) The mds is still in clientreplay. I have not attempted to restart the mds process yet as I wanted to leave it in this state so we can hopefully provide whatever information is needed to get this resolved. Please let me know if there is any extra information I can provide that would be helpful. Regards, Tren -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html