View Issue Details

IDProjectCategoryView StatusLast Update
0016160CentOS-7kernelpublic2019-06-07 12:17
Reporterakors 
PrioritynormalSeveritymajorReproducibilityrandom
Status newResolutionopen 
Platformx84_64OSCentOSOS Version7
Product Version7.6.1810 
Target VersionFixed in Version 
Summary0016160: NFSv4.1 client gets stuck in infinite loop, network flooded with SEQUENCE and NFS4ERR_SEQ_MISORDERED messages
Descriptione have observed multiple times that NFS4 mounts get stuck on a regular basis. On the client, all processes depending on the mount path are in an uninterruptible sleep state.
This situation can only be resolved by restarting the NFS server daemon, in which case I/O operations continue. It can not be resolved on the client,
since the processes involved are not killable.

The kernel versions of both the client and the server are 3.10.0-957.12.1.el7, but the same incident happened a Fedora 28 machine as an NFS server with a 4.17.3-200.fc28.x86_64 kernel.

This lockup appears somewhat regularly (twice a week for about 20 machines), but we do not know what triggers this condition.

As can be seen in the tcpdump capture and the rpcdebug info, the client makes SEQUENCE rpc calls, and the server always replies with sequence status SEQUENCE(NFS4ERR_SEQ_MISORDERED). This happens approximately every 200 microseconds, which leads to data rate of about 1 MiB/s up and down.


(server) # uname -a
Linux rcpedla4.rcpe.pharm.local 3.10.0-957.12.1.el7.x86_64 #1 SMP Mon Apr 29 14:59:59 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

(client) # uname -a
Linux rcpedla5.rcpe.pharm.local 3.10.0-957.12.1.el7.x86_64 #1 SMP Mon Apr 29 14:59:59 UTC 2019 x86_64 x86_64 x86_

Mount options on the client machine:

(client) # mount | grep 172.16.21.4
rcpedla4.rcpe.pharm.local:/share on /mnt/xpsnfs/rcpedla4 type nfs4 (rw,relatime,vers=4.1,rsize=8192,wsize=8192,namlen=255,soft,proto=tcp,timeo=600,retrans=2,sec=krb5,clientaddr=172.16.21.207,local_lock=none,addr=172.16.21.4)


Tasks in uninterruptible sleep on the client:

(client) # ps -eT -o 'state,pid,cmd' | grep '^D'
D 14700 /usr/sbin/automount --verbose --foreground --dont-check-daemon
D 15865 [xps]
D 39013 [172.16.21.4-man]

The [xps] thread with the PID 15865 is our in-house software that is trying to write to a file on a network mount.
The [172.16.21.4-man] thread with the PID 39013 seems to be a stuck kernel thread for NFS:

(client) # cat /proc/39013/stack
[<ffffffffc06e6f14>] rpc_wait_bit_killable+0x24/0xb0 [sunrpc]
[<ffffffffc06e6eed>] __rpc_wait_for_completion_task+0x2d/0x30 [sunrpc]
[<ffffffffc1de897d>] nfs4_proc_sequence+0x2d/0x80 [nfsv4]
[<ffffffffc1e00d86>] nfs4_state_manager+0x3d6/0x8d0 [nfsv4]
[<ffffffffc1e0129f>] nfs4_run_state_manager+0x1f/0x40 [nfsv4]
[<ffffffffb1cc1c71>] kthread+0xd1/0xe0
[<ffffffffb2375bf7>] ret_from_fork_nospec_end+0x0/0x39
[<ffffffffffffffff>] 0xffffffffffffffff


Here is the nfsstat on the server. Note the very high amount of sequence calls:

(server) # nfsstat -s
Server rpc stats:
calls badcalls badclnt badauth xdrcall
4269194569 204 0 204 0

Server nfs v4:
null compound
363 0% 4269155909 99%

Server nfs v4 operations:
op0-unused op1-unused op2-future access close commit
0 0% 0 0% 0 0% 810220 0% 103787 0% 374411 0%
create delegpurge delegreturn getattr getfh link
966 0% 0 0% 41772 0% 1351735040 13% 211403 0% 0 0%
lock lockt locku lookup lookup_root nverify
3 0% 0 0% 3 0% 208634 0% 0 0% 0 0%
open openattr open_conf open_dgrd putfh putpubfh
117594 0% 0 0% 0 0% 4 0% 2269724225 22% 0 0%
putrootfh read readdir readlink remove rename
314 0% 915007832 9% 3052882 0% 238 0% 30772 0% 40055 0%
renew restorefh savefh secinfo setattr setcltid
0 0% 0 0% 40056 0% 0 0% 14149 0% 0 0%
setcltidconf verify write rellockowner bc_ctl bind_conn
0 0% 0 0% 1349932540 13% 0 0% 0 0% 2 0%
exchange_id create_ses destroy_ses free_stateid getdirdeleg getdevinfo
569 0% 319 0% 308 0% 3 0% 0 0% 0 0%
getdevlist layoutcommit layoutget layoutreturn secinfononam sequence
0 0% 0 0% 0 0% 0 0% 0 0% 4269442959 42%
set_ssv test_stateid want_deleg destroy_clid reclaim_comp
0 0% 0 0% 0 0% 312 0% 314 0%


The following script was run on both the client and the server at a specific time (12:52) to obtain a tcpdump, rpcdebug info and a kernel stack trace:

-------8<--------8<--------8<--------8<--------8<--------8<--------8<----------

#!/bin/sh

PRIMARY_INTERFACE=$(ip link | grep UP | awk -F: '$0 !~ "lo|vir|wl|^[^0-9]"{print $2;getline}')
timeout 2 tcpdump -n -C 250M -s 0 -i ${PRIMARY_INTERFACE} -w /tmp/$(date -I)_$(hostname -s)-nfs.pcap host 172.16.21.4 and 172.16.21.207 &

rpcdebug -m nfs -s all
rpcdebug -m nfsd -s all
rpcdebug -m rpc -s all
rpcdebug -m nlm -s all

sleep 2

rpcdebug -m nfs -c all
rpcdebug -m nfsd -c all
rpcdebug -m rpc -c all
rpcdebug -m nlm -c all

echo t > /proc/sysrq-trigger

-------8<--------8<--------8<--------8<--------8<--------8<--------8<----------

The output for rpcdebug and the kernel stack trace was extracted from the journal and is attached in the files 2019-06-07_rcpedla5-kmesg.txt.gz (client) and 2019-06-07_rcpedla4-kmesg.txt.gz (server).

The tcpdump output is attached as the files 2019-06-07_rcpedla5-nfs.pcap.gz (client) an d the file 2019-06-07_rcpedla4-nfs.pcap.gz (server).
Here is extract from the client tcpdump. This message sequence repeats infinitely without interruption:

1 0.000000 172.16.21.207 172.16.21.4 NFS 254 V4 Call (Reply In 2) SEQUENCE
2 0.000061 172.16.21.4 172.16.21.207 NFS 182 V4 Reply (Call In 1) SEQUENCE Status: NFS4ERR_SEQ_MISORDERED
3 0.000178 172.16.21.207 172.16.21.4 NFS 254 V4 Call (Reply In 4) SEQUENCE
4 0.000241 172.16.21.4 172.16.21.207 NFS 182 V4 Reply (Call In 3) SEQUENCE Status: NFS4ERR_SEQ_MISORDERED
5 0.000409 172.16.21.207 172.16.21.4 NFS 254 V4 Call (Reply In 6) SEQUENCE
6 0.000469 172.16.21.4 172.16.21.207 NFS 182 V4 Reply (Call In 5) SEQUENCE Status: NFS4ERR_SEQ_MISORDERED

A kernel dump for this incident is not available. However, we have a kernel dump of an incident 2 weeks ago between other machines that showed identical symptoms. We would prefer to not share the whole kernel dump due to privacy concerns, however we are willing to extract information from that dump if that is requested.
Steps To Reproduce1. Set up automounts for NFSv4
2. Mount NFSv4 mounts
3. Use NFSv4 mounts
TagsNo tags attached.
abrt_hash
URL

Activities

akors

akors

2019-06-07 12:17

reporter  

2019-06-07_rcpedla4-kmesg.txt.gz (118,749 bytes)
2019-06-07_rcpedla4-nfs.pcap.gz (687,871 bytes)
2019-06-07_rcpedla5-kmesg.txt.gz (138,919 bytes)
2019-06-07_rcpedla5-nfs.pcap.gz (904,166 bytes)

Issue History

Date Modified Username Field Change
2019-06-07 12:17 akors New Issue
2019-06-07 12:17 akors File Added: 2019-06-07_rcpedla4-kmesg.txt.gz
2019-06-07 12:17 akors File Added: 2019-06-07_rcpedla4-nfs.pcap.gz
2019-06-07 12:17 akors File Added: 2019-06-07_rcpedla5-kmesg.txt.gz
2019-06-07 12:17 akors File Added: 2019-06-07_rcpedla5-nfs.pcap.gz