26 Sep
2019
26 Sep
'19
10:11 a.m.
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
28 Sep
28 Sep
7:49 p.m.
On Fri, Sep 27, 2019 at 1:12 AM Florian Pritz
<florian.pritz(a)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:
strange! did this client have multiple IPs?
> _______________________________________________
> ceph-users mailing list -- ceph-users(a)ceph.io
> To unsubscribe send an email to ceph-users-leave(a)ceph.io
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
29 Sep
29 Sep
5:21 a.m.
On Sun, Sep 29, 2019 at 10:49:58AM +0800, "Yan, Zheng" <ukernel(a)gmail.com>
wrote:
No, this client only has a single IP configured. The other clients also
only have a single IP each.
Florian
Hanging client
(10.1.67.49) kernel log:
strange! did this client have multiple IPs? 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
2 Oct
2 Oct
7:24 a.m.
On Sun, Sep 29, 2019 at 8:21 PM Florian Pritz
<florian.pritz(a)rise-world.com> wrote:
On Sun, Sep 29, 2019 at 10:49:58AM +0800, "Yan, Zheng"
<ukernel(a)gmail.com> wrote:
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
Hanging
client (10.1.67.49) kernel log:
strange! did this client have multiple IPs? 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
14 Oct
14 Oct
3:02 a.m.
On Wed, Oct 02, 2019 at 10:24:41PM +0800, "Yan, Zheng" <ukernel(a)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
8 Feb
8 Feb
1:58 a.m.
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(a)rise-world.com> wrote:
>
> On Wed, Oct 02, 2019 at 10:24:41PM +0800, "Yan, Zheng"
<ukernel(a)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(a)ceph.io
> To unsubscribe send an email to ceph-users-leave(a)ceph.io
2:20 a.m.
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(a)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(a)rise-world.com> wrote:
> >
> > On Wed, Oct 02, 2019 at 10:24:41PM +0800, "Yan, Zheng"
<ukernel(a)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(a)ceph.io
> > To unsubscribe send an email to ceph-users-leave(a)ceph.io
1171
days inactive
1672
days old
6 comments
3 participants
participants (3)
-
Dan van der Ster -
Florian Pritz -
Yan, Zheng