MDS rejects clients causing hanging mountpoint on linux kernel client
Hi, We are running a ceph cluster on Ubuntu 18.04 machines with ceph 14.2.4. Our cephfs clients are using the kernel module and we have noticed that some of them are sometimes (at least once) hanging after an MDS restart. The only way to resolve this is to unmount and remount the mountpoint, or reboot the machine if unmounting is not possible. After some investigation, the problem seems to be that the MDS denies reconnect attempts from some clients during restart even though the reconnect interval is not yet reached. In particular, I see the following log entries. Note that there are supposedly 9 sessions. 9 clients reconnect (one client has two mountpoints) and then two more clients reconnect after the MDS already logged "reconnect_done". These two clients were hanging after the event. The kernel log of one of them is shown below too. Running `ceph tell mds.0 client ls` after the clients have been rebooted/remounted also shows 11 clients instead of 9. Do you have any ideas what is wrong here and how it could be fixed? I'm guessing that the issue is that the MDS apparently has an incorrect session count and stops the reconnect process to soon. Is this indeed a bug and if so, do you know what is broken? Regardless, I also think that the kernel should be able to deal with a denied reconnect and that it should try again later. Yet, even after 10 minutes, the kernel does not attempt to reconnect. Is this a known issue or maybe fixed in newer kernels? If not, is there a chance to get this fixed? Thanks, Florian MDS log:
2019-09-26 16:08:27.479 7f9fdde99700 1 mds.0.server reconnect_clients -- 9 sessions 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.24197043 v1:10.1.4.203:0/990008521 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.30487144 v1:10.1.4.146:0/483747473 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.21019865 v1:10.1.7.22:0/3752632657 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.21020717 v1:10.1.7.115:0/2841046616 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.24171153 v1:10.1.7.243:0/1127767158 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.23978093 v1:10.1.4.71:0/824226283 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.24209569 v1:10.1.4.157:0/1271865906 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.20190930 v1:10.1.4.240:0/3195698606 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.20190912 v1:10.1.4.146:0/852604154 after 0 2019-09-26 16:08:27.479 7f9fdde99700 1 mds.0.59 reconnect_done 2019-09-26 16:08:27.483 7f9fdde99700 1 mds.0.server no longer in reconnect state, ignoring reconnect, sending close 2019-09-26 16:08:27.483 7f9fdde99700 0 log_channel(cluster) log [INF] : denied reconnect attempt (mds is up:reconnect) from client.24167394 v1:10.1.67.49:0/1483641729 after 0.00400002 (allowed interval 45) 2019-09-26 16:08:27.483 7f9fe1087700 0 --1- [v2:10.1.4.203:6800/806949107,v1:10.1.4.203:6801/806949107] >> v1:10.1.67.49:0/1483641729 conn(0x55af50053f80 0x55af50140800 :6801 s=OPENED pgs=21 cs=1 l=0).fault server, going to standby 2019-09-26 16:08:27.483 7f9fdde99700 1 mds.0.server no longer in reconnect state, ignoring reconnect, sending close 2019-09-26 16:08:27.483 7f9fdde99700 0 log_channel(cluster) log [INF] : denied reconnect attempt (mds is up:reconnect) from client.30586072 v1:10.1.67.140:0/3664284158 after 0.00400002 (allowed interval 45) 2019-09-26 16:08:27.483 7f9fe1888700 0 --1- [v2:10.1.4.203:6800/806949107,v1:10.1.4.203:6801/806949107] >> v1:10.1.67.140:0/3664284158 conn(0x55af50055600 0x55af50143000 :6801 s=OPENED pgs=8 cs=1 l=0).fault server, going to standby
Hanging client (10.1.67.49) kernel log:
2019-09-26T16:08:27.481676+02:00 hostnamefoo kernel: [708596.227148] ceph: mds0 reconnect start 2019-09-26T16:08:27.488943+02:00 hostnamefoo kernel: [708596.233145] ceph: mds0 reconnect denied 2019-09-26T16:16:17.541041+02:00 hostnamefoo kernel: [709066.287601] libceph: mds0 10.1.4.203:6801 socket closed (con state NEGOTIATING) 2019-09-26T16:16:18.068934+02:00 hostnamefoo kernel: [709066.813064] ceph: mds0 rejected session 2019-09-26T16:16:18.068955+02:00 hostnamefoo kernel: [709066.814843] ceph: get_quota_realm: ino (10000000008.fffffffffffffffe) null i_snap_realm
On Fri, Sep 27, 2019 at 1:12 AM Florian Pritz <florian.pritz@rise-world.com> wrote:
Hi,
We are running a ceph cluster on Ubuntu 18.04 machines with ceph 14.2.4. Our cephfs clients are using the kernel module and we have noticed that some of them are sometimes (at least once) hanging after an MDS restart. The only way to resolve this is to unmount and remount the mountpoint, or reboot the machine if unmounting is not possible.
After some investigation, the problem seems to be that the MDS denies reconnect attempts from some clients during restart even though the reconnect interval is not yet reached. In particular, I see the following log entries. Note that there are supposedly 9 sessions. 9 clients reconnect (one client has two mountpoints) and then two more clients reconnect after the MDS already logged "reconnect_done". These two clients were hanging after the event. The kernel log of one of them is shown below too.
Running `ceph tell mds.0 client ls` after the clients have been rebooted/remounted also shows 11 clients instead of 9.
Do you have any ideas what is wrong here and how it could be fixed? I'm guessing that the issue is that the MDS apparently has an incorrect session count and stops the reconnect process to soon. Is this indeed a bug and if so, do you know what is broken?
Regardless, I also think that the kernel should be able to deal with a denied reconnect and that it should try again later. Yet, even after 10 minutes, the kernel does not attempt to reconnect. Is this a known issue or maybe fixed in newer kernels? If not, is there a chance to get this fixed?
Thanks, Florian
MDS log:
2019-09-26 16:08:27.479 7f9fdde99700 1 mds.0.server reconnect_clients -- 9 sessions 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.24197043 v1:10.1.4.203:0/990008521 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.30487144 v1:10.1.4.146:0/483747473 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.21019865 v1:10.1.7.22:0/3752632657 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.21020717 v1:10.1.7.115:0/2841046616 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.24171153 v1:10.1.7.243:0/1127767158 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.23978093 v1:10.1.4.71:0/824226283 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.24209569 v1:10.1.4.157:0/1271865906 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.20190930 v1:10.1.4.240:0/3195698606 after 0 2019-09-26 16:08:27.479 7f9fdde99700 0 log_channel(cluster) log [DBG] : reconnect by client.20190912 v1:10.1.4.146:0/852604154 after 0 2019-09-26 16:08:27.479 7f9fdde99700 1 mds.0.59 reconnect_done 2019-09-26 16:08:27.483 7f9fdde99700 1 mds.0.server no longer in reconnect state, ignoring reconnect, sending close 2019-09-26 16:08:27.483 7f9fdde99700 0 log_channel(cluster) log [INF] : denied reconnect attempt (mds is up:reconnect) from client.24167394 v1:10.1.67.49:0/1483641729 after 0.00400002 (allowed interval 45) 2019-09-26 16:08:27.483 7f9fe1087700 0 --1- [v2:10.1.4.203:6800/806949107,v1:10.1.4.203:6801/806949107] >> v1:10.1.67.49:0/1483641729 conn(0x55af50053f80 0x55af50140800 :6801 s=OPENED pgs=21 cs=1 l=0).fault server, going to standby 2019-09-26 16:08:27.483 7f9fdde99700 1 mds.0.server no longer in reconnect state, ignoring reconnect, sending close 2019-09-26 16:08:27.483 7f9fdde99700 0 log_channel(cluster) log [INF] : denied reconnect attempt (mds is up:reconnect) from client.30586072 v1:10.1.67.140:0/3664284158 after 0.00400002 (allowed interval 45) 2019-09-26 16:08:27.483 7f9fe1888700 0 --1- [v2:10.1.4.203:6800/806949107,v1:10.1.4.203:6801/806949107] >> v1:10.1.67.140:0/3664284158 conn(0x55af50055600 0x55af50143000 :6801 s=OPENED pgs=8 cs=1 l=0).fault server, going to standby
Hanging client (10.1.67.49) kernel log:
2019-09-26T16:08:27.481676+02:00 hostnamefoo kernel: [708596.227148] ceph: mds0 reconnect start 2019-09-26T16:08:27.488943+02:00 hostnamefoo kernel: [708596.233145] ceph: mds0 reconnect denied 2019-09-26T16:16:17.541041+02:00 hostnamefoo kernel: [709066.287601] libceph: mds0 10.1.4.203:6801 socket closed (con state NEGOTIATING) 2019-09-26T16:16:18.068934+02:00 hostnamefoo kernel: [709066.813064] ceph: mds0 rejected session 2019-09-26T16:16:18.068955+02:00 hostnamefoo kernel: [709066.814843] ceph: get_quota_realm: ino (10000000008.fffffffffffffffe) null i_snap_realm
strange! did this client have multiple IPs?
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
On Sun, Sep 29, 2019 at 10:49:58AM +0800, "Yan, Zheng" <ukernel@gmail.com> wrote:
Hanging client (10.1.67.49) kernel log:
2019-09-26T16:08:27.481676+02:00 hostnamefoo kernel: [708596.227148] ceph: mds0 reconnect start 2019-09-26T16:08:27.488943+02:00 hostnamefoo kernel: [708596.233145] ceph: mds0 reconnect denied 2019-09-26T16:16:17.541041+02:00 hostnamefoo kernel: [709066.287601] libceph: mds0 10.1.4.203:6801 socket closed (con state NEGOTIATING) 2019-09-26T16:16:18.068934+02:00 hostnamefoo kernel: [709066.813064] ceph: mds0 rejected session 2019-09-26T16:16:18.068955+02:00 hostnamefoo kernel: [709066.814843] ceph: get_quota_realm: ino (10000000008.fffffffffffffffe) null i_snap_realm
strange! did this client have multiple IPs?
No, this client only has a single IP configured. The other clients also only have a single IP each. Florian
On Sun, Sep 29, 2019 at 8:21 PM Florian Pritz <florian.pritz@rise-world.com> wrote:
On Sun, Sep 29, 2019 at 10:49:58AM +0800, "Yan, Zheng" <ukernel@gmail.com> wrote:
Hanging client (10.1.67.49) kernel log:
2019-09-26T16:08:27.481676+02:00 hostnamefoo kernel: [708596.227148] ceph: mds0 reconnect start 2019-09-26T16:08:27.488943+02:00 hostnamefoo kernel: [708596.233145] ceph: mds0 reconnect denied 2019-09-26T16:16:17.541041+02:00 hostnamefoo kernel: [709066.287601] libceph: mds0 10.1.4.203:6801 socket closed (con state NEGOTIATING) 2019-09-26T16:16:18.068934+02:00 hostnamefoo kernel: [709066.813064] ceph: mds0 rejected session 2019-09-26T16:16:18.068955+02:00 hostnamefoo kernel: [709066.814843] ceph: get_quota_realm: ino (10000000008.fffffffffffffffe) null i_snap_realm
strange! did this client have multiple IPs?
No, this client only has a single IP configured. The other clients also only have a single IP each.
Can you reproduce this. If you can, run 'ceph daemon mds.x session ls' before restart mds.
Florian
On Wed, Oct 02, 2019 at 10:24:41PM +0800, "Yan, Zheng" <ukernel@gmail.com> wrote:
Can you reproduce this. If you can, run 'ceph daemon mds.x session ls' before restart mds.
I just managed to run into this issue again. 'ceph daemon mds.x session ls' doesn't work because apparently our setup doesn't have the admin socket in the expected place. I've therefore used 'ceph tell mds.0 session ls' which I think should be the same expect for how the daemon is contacted. When the issue happens and 2 clients are hanging, 'ceph tell mds.0 session ls' shows only 9 clients instead of 11. The hanging clients are missing from the list. Once they are rebooted they show up in the output. On a potentially interesting note: The clients that were hanging this time are the same ones as last time. They aren't set up any differently from the others as far as I can tell though. Florian
Hi, Sorry to ping this old thread, but we have a few kernel client nodes stuck like this after an outage on their network. MDS's are running v14.2.11 and the client has kernel 3.10.0-1127.19.1.el7.x86_64. This is the first time at our lab that clients didn't reconnect after a network issue (but this might be the first large client network outage after we upgraded from luminous to nautilus). It looks identical to Florian's issue: Feb 08 10:07:23 hpc-qcd027.cern.ch kernel: libceph: mds0 10.32.5.17:6821 socket closed (con state NEGOTIATING) Feb 08 10:07:51 hpc-qcd027.cern.ch kernel: ceph: get_quota_realm: ino (10004fe5035.fffffffffffffffe) null i_snap_realm The full kernel log | grep ceph is at https://termbin.com/zdwc As of now, this client's mountpoint is "stuck" and it does not have a session open on mds.0, but has sessions on mds.1 and mds.2 (see below [1]). I evicted this client from all mds's but the client didn't manage to reconnect: Feb 08 10:20:01 hpc-qcd027.cern.ch kernel: libceph: mds1 188.185.88.47:6801 socket closed (con state OPEN) Feb 08 10:20:01 hpc-qcd027.cern.ch kernel: libceph: mds2 188.185.88.90:6801 socket closed (con state OPEN) Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: mds1 188.185.88.47:6801 connection reset Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: reset on mds1 Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds1 closed our session Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds1 reconnect start Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: mds2 188.185.88.90:6801 connection reset Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: reset on mds2 Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds2 closed our session Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds2 reconnect start Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds1 reconnect denied Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds2 reconnect denied Feb 08 10:20:21 hpc-qcd027.cern.ch kernel: ceph: get_quota_realm: ino (10004fe5035.fffffffffffffffe) null i_snap_realm Feb 08 10:20:51 hpc-qcd027.cern.ch kernel: ceph: get_quota_realm: ino (10004fe5035.fffffffffffffffe) null i_snap_realm Here are some logs from mds.0: # egrep '10.32.3.150|137564444' /var/log/ceph/ceph-mds.cephflax-mds-ca21a8a1c6.log 2021-02-08 09:16:46.875 7f9b22faa700 0 log_channel(cluster) log [WRN] : evicting unresponsive client hpc-qcd027.cern.ch:hpc (137564444), after 304.536 seconds 2021-02-08 09:17:28.326 7f9b28a6c700 0 --1- [v2:188.184.96.191:6800/1781566860,v1:188.184.96.191:6801/1781566860]
v1:10.32.3.150:0/3998218413 conn(0x562ac988b800 0x562e1a6e8800 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept we reset (peer sent cseq 1), sending RESETSESSION 2021-02-08 09:17:28.628 7f9b28a6c700 0 --1- [v2:188.184.96.191:6800/1781566860,v1:188.184.96.191:6801/1781566860] v1:10.32.3.150:0/3998218413 conn(0x5629ce1c6800 0x56274776f000 :6801 s=OPENED pgs=26571 cs=1 l=0).fault server, going to standby 2021-02-08 09:49:56.318 7f9b28a6c700 0 --1- [v2:188.184.96.191:6800/1781566860,v1:188.184.96.191:6801/1781566860] v1:10.32.3.150:0/3998218413 conn(0x5629f5eaa800 0x5627460ab800 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept peer reset, then tried to connect to us, replacing
compared with mds.1 where the reconnect succeeded: # egrep '10.32.3.150|137564444' /var/log/ceph/ceph-mds.cephflax-mds-370212ad58.log 2021-02-08 09:16:42.970 7fc98299b700 0 log_channel(cluster) log [WRN] : evicting unresponsive client hpc-qcd027.cern.ch:hpc (137564444), after 300.629 seconds 2021-02-08 09:17:28.327 7fc987c2f700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a652fea400 0x55a7220ba800 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept we reset (peer sent cseq 1), sending RESETSESSION 2021-02-08 09:17:28.414 7fc987c2f700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a791481000 0x55a6c7a2d800 :6801 s=OPENED pgs=26573 cs=1 l=0).fault server, going to standby 2021-02-08 10:05:12.810 7fc988430700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a75789d400 0x55a78695b000 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept peer reset, then tried to connect to us, replacing 2021-02-08 10:05:13.374 7fc97e192700 2 mds.1.server New client session: addr="v1:10.32.3.150:0/3998218413",elapsed=0.057278,throttled=0.000007,status="ACCEPTED",root="/hpcqcd" 2021-02-08 10:20:01.666 7fc98499f700 1 mds.1.242924 Evicting client session 137564444 (v1 10.32.3.150:0/3998218413) 2021-02-08 10:20:01.666 7fc98499f700 0 log_channel(cluster) log [INF] : Evicting client session 137564444 (v1:10.32.3.150:0/3998218413) 2021-02-08 10:20:02.343 7fc988430700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a7a5d81c00 0x55a7823d1000 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept we reset (peer sent cseq 2), sending RESETSESSION 2021-02-08 10:20:02.345 7fc988430700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a75bb6a000 0x55a744f69800 :6801 s=OPENED pgs=26588 cs=1 l=0).fault server, going to standby We have this in the mds config: mds session blacklist on evict = false mds session blacklist on timeout = false The clients are working fine after they are rebooted. Given the age of this thread -- maybe is this a known issue and already solved in newer kernels? Note that during this incident a few clients also crashed and rebooted -- we are still trying to get the kernel backtrace for those cases, to see if it matches https://tracker.ceph.com/issues/40862. Thanks! Dan [1] session ls: mds.cephflax-mds-ca21a8a1c6: [] mds.cephflax-mds-370212ad58: [ { "id": 137564444, "entity": { "name": { "type": "client", "num": 137564444 }, "addr": { "type": "v1", "addr": "10.32.3.150:0", "nonce": 3998218413 } }, "state": "open", "num_leases": 0, "num_caps": 0, "request_load_avg": 0, "uptime": 844.92158032299994, "requests_in_flight": 0, "completed_requests": 0, "reconnecting": false, "recall_caps": { "value": 0, "halflife": 60 }, "release_caps": { "value": 0, "halflife": 60 }, "recall_caps_throttle": { "value": 0, "halflife": 2.5 }, "recall_caps_throttle2o": { "value": 0, "halflife": 0.5 }, "session_cache_liveness": { "value": 0, "halflife": 300 }, "inst": "client.137564444 v1:10.32.3.150:0/3998218413", "completed_requests": [], "prealloc_inos": [], "used_inos": [], "client_metadata": { "features": "0x00000000000000ff", "entity_id": "hpc", "hostname": "hpc-qcd027.cern.ch", "kernel_version": "3.10.0-1127.19.1.el7.x86_64", "root": "/hpcqcd" } } ] mds.cephflax-mds-adccf51169: [ { "id": 137564444, "entity": { "name": { "type": "client", "num": 137564444 }, "addr": { "type": "v1", "addr": "10.32.3.150:0", "nonce": 3998218413 } }, "state": "open", "num_leases": 0, "num_caps": 0, "request_load_avg": 0, "uptime": 1761.964491447, "requests_in_flight": 0, "completed_requests": 0, "reconnecting": false, "recall_caps": { "value": 0, "halflife": 60 }, "release_caps": { "value": 0, "halflife": 60 }, "recall_caps_throttle": { "value": 0, "halflife": 2.5 }, "recall_caps_throttle2o": { "value": 0, "halflife": 0.5 }, "session_cache_liveness": { "value": 0, "halflife": 300 }, "inst": "client.137564444 v1:10.32.3.150:0/3998218413", "completed_requests": [], "prealloc_inos": [], "used_inos": [], "client_metadata": { "features": "0x00000000000000ff", "entity_id": "hpc", "hostname": "hpc-qcd027.cern.ch", "kernel_version": "3.10.0-1127.19.1.el7.x86_64", "root": "/hpcqcd" } } ] On Mon, Oct 14, 2019 at 12:03 PM Florian Pritz <florian.pritz@rise-world.com> wrote:
On Wed, Oct 02, 2019 at 10:24:41PM +0800, "Yan, Zheng" <ukernel@gmail.com> wrote:
Can you reproduce this. If you can, run 'ceph daemon mds.x session ls' before restart mds.
I just managed to run into this issue again. 'ceph daemon mds.x session ls' doesn't work because apparently our setup doesn't have the admin socket in the expected place. I've therefore used 'ceph tell mds.0 session ls' which I think should be the same expect for how the daemon is contacted.
When the issue happens and 2 clients are hanging, 'ceph tell mds.0 session ls' shows only 9 clients instead of 11. The hanging clients are missing from the list. Once they are rebooted they show up in the output.
On a potentially interesting note: The clients that were hanging this time are the same ones as last time. They aren't set up any differently from the others as far as I can tell though.
Florian _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
We found the vmcore and backtrace and created https://tracker.ceph.com/issues/49210 Cheers, Dan On Mon, Feb 8, 2021 at 10:58 AM Dan van der Ster <dan@vanderster.com> wrote:
Hi,
Sorry to ping this old thread, but we have a few kernel client nodes stuck like this after an outage on their network. MDS's are running v14.2.11 and the client has kernel 3.10.0-1127.19.1.el7.x86_64.
This is the first time at our lab that clients didn't reconnect after a network issue (but this might be the first large client network outage after we upgraded from luminous to nautilus).
It looks identical to Florian's issue:
Feb 08 10:07:23 hpc-qcd027.cern.ch kernel: libceph: mds0 10.32.5.17:6821 socket closed (con state NEGOTIATING) Feb 08 10:07:51 hpc-qcd027.cern.ch kernel: ceph: get_quota_realm: ino (10004fe5035.fffffffffffffffe) null i_snap_realm
The full kernel log | grep ceph is at https://termbin.com/zdwc
As of now, this client's mountpoint is "stuck" and it does not have a session open on mds.0, but has sessions on mds.1 and mds.2 (see below [1]).
I evicted this client from all mds's but the client didn't manage to reconnect:
Feb 08 10:20:01 hpc-qcd027.cern.ch kernel: libceph: mds1 188.185.88.47:6801 socket closed (con state OPEN) Feb 08 10:20:01 hpc-qcd027.cern.ch kernel: libceph: mds2 188.185.88.90:6801 socket closed (con state OPEN) Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: mds1 188.185.88.47:6801 connection reset Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: reset on mds1 Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds1 closed our session Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds1 reconnect start Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: mds2 188.185.88.90:6801 connection reset Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: libceph: reset on mds2 Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds2 closed our session Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds2 reconnect start Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds1 reconnect denied Feb 08 10:20:02 hpc-qcd027.cern.ch kernel: ceph: mds2 reconnect denied Feb 08 10:20:21 hpc-qcd027.cern.ch kernel: ceph: get_quota_realm: ino (10004fe5035.fffffffffffffffe) null i_snap_realm Feb 08 10:20:51 hpc-qcd027.cern.ch kernel: ceph: get_quota_realm: ino (10004fe5035.fffffffffffffffe) null i_snap_realm
Here are some logs from mds.0:
# egrep '10.32.3.150|137564444' /var/log/ceph/ceph-mds.cephflax-mds-ca21a8a1c6.log 2021-02-08 09:16:46.875 7f9b22faa700 0 log_channel(cluster) log [WRN] : evicting unresponsive client hpc-qcd027.cern.ch:hpc (137564444), after 304.536 seconds 2021-02-08 09:17:28.326 7f9b28a6c700 0 --1- [v2:188.184.96.191:6800/1781566860,v1:188.184.96.191:6801/1781566860]
v1:10.32.3.150:0/3998218413 conn(0x562ac988b800 0x562e1a6e8800 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept we reset (peer sent cseq 1), sending RESETSESSION 2021-02-08 09:17:28.628 7f9b28a6c700 0 --1- [v2:188.184.96.191:6800/1781566860,v1:188.184.96.191:6801/1781566860] v1:10.32.3.150:0/3998218413 conn(0x5629ce1c6800 0x56274776f000 :6801 s=OPENED pgs=26571 cs=1 l=0).fault server, going to standby 2021-02-08 09:49:56.318 7f9b28a6c700 0 --1- [v2:188.184.96.191:6800/1781566860,v1:188.184.96.191:6801/1781566860] v1:10.32.3.150:0/3998218413 conn(0x5629f5eaa800 0x5627460ab800 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept peer reset, then tried to connect to us, replacing
compared with mds.1 where the reconnect succeeded:
# egrep '10.32.3.150|137564444' /var/log/ceph/ceph-mds.cephflax-mds-370212ad58.log 2021-02-08 09:16:42.970 7fc98299b700 0 log_channel(cluster) log [WRN] : evicting unresponsive client hpc-qcd027.cern.ch:hpc (137564444), after 300.629 seconds 2021-02-08 09:17:28.327 7fc987c2f700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a652fea400 0x55a7220ba800 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept we reset (peer sent cseq 1), sending RESETSESSION 2021-02-08 09:17:28.414 7fc987c2f700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a791481000 0x55a6c7a2d800 :6801 s=OPENED pgs=26573 cs=1 l=0).fault server, going to standby 2021-02-08 10:05:12.810 7fc988430700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a75789d400 0x55a78695b000 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept peer reset, then tried to connect to us, replacing 2021-02-08 10:05:13.374 7fc97e192700 2 mds.1.server New client session: addr="v1:10.32.3.150:0/3998218413",elapsed=0.057278,throttled=0.000007,status="ACCEPTED",root="/hpcqcd" 2021-02-08 10:20:01.666 7fc98499f700 1 mds.1.242924 Evicting client session 137564444 (v1 10.32.3.150:0/3998218413) 2021-02-08 10:20:01.666 7fc98499f700 0 log_channel(cluster) log [INF] : Evicting client session 137564444 (v1:10.32.3.150:0/3998218413) 2021-02-08 10:20:02.343 7fc988430700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a7a5d81c00 0x55a7823d1000 :6801 s=ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_message_2 accept we reset (peer sent cseq 2), sending RESETSESSION 2021-02-08 10:20:02.345 7fc988430700 0 --1- [v2:188.185.88.47:6800/3666946863,v1:188.185.88.47:6801/3666946863] >> v1:10.32.3.150:0/3998218413 conn(0x55a75bb6a000 0x55a744f69800 :6801 s=OPENED pgs=26588 cs=1 l=0).fault server, going to standby
We have this in the mds config: mds session blacklist on evict = false mds session blacklist on timeout = false
The clients are working fine after they are rebooted.
Given the age of this thread -- maybe is this a known issue and already solved in newer kernels?
Note that during this incident a few clients also crashed and rebooted -- we are still trying to get the kernel backtrace for those cases, to see if it matches https://tracker.ceph.com/issues/40862.
Thanks!
Dan
[1] session ls: mds.cephflax-mds-ca21a8a1c6: [] mds.cephflax-mds-370212ad58: [ { "id": 137564444, "entity": { "name": { "type": "client", "num": 137564444 }, "addr": { "type": "v1", "addr": "10.32.3.150:0", "nonce": 3998218413 } }, "state": "open", "num_leases": 0, "num_caps": 0, "request_load_avg": 0, "uptime": 844.92158032299994, "requests_in_flight": 0, "completed_requests": 0, "reconnecting": false, "recall_caps": { "value": 0, "halflife": 60 }, "release_caps": { "value": 0, "halflife": 60 }, "recall_caps_throttle": { "value": 0, "halflife": 2.5 }, "recall_caps_throttle2o": { "value": 0, "halflife": 0.5 }, "session_cache_liveness": { "value": 0, "halflife": 300 }, "inst": "client.137564444 v1:10.32.3.150:0/3998218413", "completed_requests": [], "prealloc_inos": [], "used_inos": [], "client_metadata": { "features": "0x00000000000000ff", "entity_id": "hpc", "hostname": "hpc-qcd027.cern.ch", "kernel_version": "3.10.0-1127.19.1.el7.x86_64", "root": "/hpcqcd" } } ] mds.cephflax-mds-adccf51169: [ { "id": 137564444, "entity": { "name": { "type": "client", "num": 137564444 }, "addr": { "type": "v1", "addr": "10.32.3.150:0", "nonce": 3998218413 } }, "state": "open", "num_leases": 0, "num_caps": 0, "request_load_avg": 0, "uptime": 1761.964491447, "requests_in_flight": 0, "completed_requests": 0, "reconnecting": false, "recall_caps": { "value": 0, "halflife": 60 }, "release_caps": { "value": 0, "halflife": 60 }, "recall_caps_throttle": { "value": 0, "halflife": 2.5 }, "recall_caps_throttle2o": { "value": 0, "halflife": 0.5 }, "session_cache_liveness": { "value": 0, "halflife": 300 }, "inst": "client.137564444 v1:10.32.3.150:0/3998218413", "completed_requests": [], "prealloc_inos": [], "used_inos": [], "client_metadata": { "features": "0x00000000000000ff", "entity_id": "hpc", "hostname": "hpc-qcd027.cern.ch", "kernel_version": "3.10.0-1127.19.1.el7.x86_64", "root": "/hpcqcd" } } ]
On Mon, Oct 14, 2019 at 12:03 PM Florian Pritz <florian.pritz@rise-world.com> wrote:
On Wed, Oct 02, 2019 at 10:24:41PM +0800, "Yan, Zheng" <ukernel@gmail.com> wrote:
Can you reproduce this. If you can, run 'ceph daemon mds.x session ls' before restart mds.
I just managed to run into this issue again. 'ceph daemon mds.x session ls' doesn't work because apparently our setup doesn't have the admin socket in the expected place. I've therefore used 'ceph tell mds.0 session ls' which I think should be the same expect for how the daemon is contacted.
When the issue happens and 2 clients are hanging, 'ceph tell mds.0 session ls' shows only 9 clients instead of 11. The hanging clients are missing from the list. Once they are rebooted they show up in the output.
On a potentially interesting note: The clients that were hanging this time are the same ones as last time. They aren't set up any differently from the others as far as I can tell though.
Florian _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
participants (3)
-
Dan van der Ster
-
Florian Pritz
-
Yan, Zheng