RHEL6.5: NFS4 client unable to reconnect TCP connection with NetApp filer, NFS client TCP remains in TCP_SYN_SENT state
Environment
- Red Hat Enterprise Linux Server release 6.5 (NFS client)
- Seen on kernel 2.6.32-431.5.1.el6.x86_64
- NetApp NFS server
- NFSv4
Issue
nfs4 communication hangs and error messages "nfs: server foobar not responding, still trying" is showing in the logs. In some cases it will recover after 10-15 minutes in other only reboot will solve the problem.
Resolution
- If such an issue is experienced, please file a case with RedHat for further investigation, adding tcpdumps from both sides to the ticket (NFS-Server and NFS-Client)
Root Cause
- After some investigation of the network team, it turned out, a damaged security appliance was responsible for the mangling of the network packets. After the security appliance has been replaced, the issue didn't happen again.
- In general mangled network packets might be causing this.
Diagnostic Steps
General data gathering
- Gather a tcpdump from both the NFS client and NFS server at the time of the failure. Once the tcpdump is gathered on the NFS client, obtain a vmcore of the NFS client via sysrq-c
Summary of the analysis of both the tcpdumps and vmcore.
-
In short, it looks to me like something is mangling these 'SYN' TCP packets sent by the NFS client that by the time they reach the NFS server they are no longer SYN packets, but has 'ACK' set instead, so the NFS server probably just drops them. I'm not even sure how many differences there are - we may want to compare them byte by byte. At the very least, the NFS client side packets are 74 bytes and the NFS server side packets are 54 bytes, so something seems to be mangled and/or lost.
-
From the NFS client side dump we see the NFS client is sending TCP SYNs to try to establish the TCP connection. This also matches the vmcore as far as the NFS state, even down to the TCP port numbers of the RPC connection. So the NFS problems here appear to be clearly some strange networking / TCP level issue, where the NFS client is unable to communicate with the NFS server to re-establish a TCP connection.
-
Looks like the filer can't establish a connection when the initial request comes from a privileged (< 1024) port. Once the client uses a port > 1024 (34377 in the example), the connection can be established.
-
From the vmcore, it seems the issue occurred over 8 hours ago. Here's the timeline:
Sun Jul 6 01:18:06 CEST 2014 - estimated time of the NFS / TCP connectivity issue started between NFS client and NFS server
Sun Jul 6 10:00:21 CEST 2014 - time of the vmcore
Detailed analysis of vmcore and tcpdumps
- First, take a look at the vmcore. The vmcore shows the same thing as we saw in the first one, that of a system where processes are blocked and the oldest blocked task is waiting on NFS. We see "not responding, still trying" in the log, and the NFS transport is TCP, with the TCP state of TCP_SYN_SENT. NFS is definitely the victim here, just waiting on the transport to reconnect. Note that the time of the vmcore as listed in crash needs adjusted using https://access.redhat.com/solutions/752683
=== Analysis of vmcore ===
BEGIN: Basic vmcore analysis
Checking for RHEL version
- Found RHEL6 kernel 2.6.32-431.5.1.el6
- Check code at https://access.redhat.com/knowledge/sources/source_rpms/kernel-2.6.32-431.5.1.el6/tree/
sys output <begin>
KERNEL: /cores/retrace/repos/kernel/x86_64/usr/lib/debug/lib/modules/2.6.32-431.5.1.el6.x86_64/vmlinux
DUMPFILE: vmcore [PARTIAL DUMP]
CPUS: 12
DATE: Sun Jul 6 04:00:21 2014 <-------------------- localtime of the machine on which crash was run
UPTIME: 11 days, 11:27:27
LOAD AVERAGE: 218.01, 217.78, 217.30
TASKS: 772
NODENAME: localnode
RELEASE: 2.6.32-431.5.1.el6.x86_64
VERSION: #1 SMP Fri Jan 10 14:46:43 EST 2014
MACHINE: x86_64 (3066 Mhz)
MEMORY: 48 GB
PANIC: "[991957.854139] Oops: 0002 [#1] SMP " (check log for details)
crash> sys output <end>
Looking for tainted modules
Found 'no tainted modules' - NOTE: If this is a kernel crash it almost certain a kernel bug!!!
...
Checking for sysrq_handle_crash RIP
- Found RIP sysrq_handle_crash - Manual crash - hung system ?
Checking for specific hang indications in log
- Found 'nfs: server XYZ not responding' in log, Check https://access.redhat.com/site/solutions/28211
...
END: Basic vmcore analysis
BEGIN: Basic hung vmcore analysis
Showing oldest blocked pid (NOTE: some processes such as gablogd filtered out)
Oldest blocked pid: 18055
Checking last 10 blocked processes, how long they've been blocked
Blocked processes <begin>
[ 0 08:33:30.509] [UN] PID: 24461 TASK: ffff880b0e2e0080 CPU: 0 COMMAND: "sshd_cre"
[ 0 08:35:15.493] [UN] PID: 28366 TASK: ffff88095c72eaa0 CPU: 2 COMMAND: "sshd_cre"
[ 0 08:35:26.483] [UN] PID: 28364 TASK: ffff88095cf36080 CPU: 2 COMMAND: "sshd_cre_public"
[ 0 08:35:26.578] [UN] PID: 28362 TASK: ffff880aabdbf500 CPU: 4 COMMAND: "sshd_cre_public"
[ 0 08:35:36.020] [UN] PID: 28359 TASK: ffff8806ca228aa0 CPU: 2 COMMAND: "sshd_cre"
[ 0 08:36:22.391] [UN] PID: 28224 TASK: ffff880af7031500 CPU: 2 COMMAND: "sshd_cre_public"
[ 0 08:39:17.616] [UN] PID: 27817 TASK: ffff880aabdbe040 CPU: 2 COMMAND: "sshd_cre"
[ 0 08:39:20.141] [UN] PID: 27815 TASK: ffff880aabdbeaa0 CPU: 2 COMMAND: "sshd_cre_public"
[ 0 08:39:29.931] [UN] PID: 27813 TASK: ffff88081d60e080 CPU: 2 COMMAND: "sshd_cre"
[ 0 08:41:42.597] [UN] PID: 18055 TASK: ffff880b6e967540 CPU: 2 COMMAND: "sshd_cre"
crash> Blocked processes <end>
Backtrace of oldest blocked task or task triggering hung_task panic
backtrace <begin>
PID: 18055 TASK: ffff880b6e967540 CPU: 2 COMMAND: "sshd_cre"
#0 [ffff8807c4b7b798] schedule at ffffffff81527bd2
#1 [ffff8807c4b7b860] rpc_wait_bit_killable at ffffffffa02041b2 [sunrpc]
#2 [ffff8807c4b7b870] __wait_on_bit at ffffffff81528e7f
#3 [ffff8807c4b7b8c0] out_of_line_wait_on_bit at ffffffff81528f28
#4 [ffff8807c4b7b930] __rpc_execute at ffffffffa02046f5 [sunrpc]
#5 [ffff8807c4b7b9a0] rpc_execute at ffffffffa02049b1 [sunrpc]
#6 [ffff8807c4b7b9d0] rpc_run_task at ffffffffa01fb3a5 [sunrpc]
#7 [ffff8807c4b7b9f0] rpc_call_sync at ffffffffa01fb4c2 [sunrpc]
#8 [ffff8807c4b7ba50] _nfs4_call_sync at ffffffffa02b7abe [nfs]
#9 [ffff8807c4b7ba60] _nfs4_proc_access at ffffffffa02b67ec [nfs]
#10 [ffff8807c4b7bb40] nfs4_proc_access at ffffffffa02b68bb [nfs]
#11 [ffff8807c4b7bb90] nfs_do_access at ffffffffa029258c [nfs]
#12 [ffff8807c4b7bc20] nfs_permission at ffffffffa02926d8 [nfs]
#13 [ffff8807c4b7bc50] __link_path_walk at ffffffff81198c63
#14 [ffff8807c4b7bd30] path_walk at ffffffff81199e5a
#15 [ffff8807c4b7bd70] filename_lookup at ffffffff8119a06b
#16 [ffff8807c4b7bdb0] user_path_at at ffffffff8119b197
#17 [ffff8807c4b7be80] vfs_fstatat at ffffffff8118e9e0
#18 [ffff8807c4b7bee0] vfs_stat at ffffffff8118eb5b
#19 [ffff8807c4b7bef0] sys_newstat at ffffffff8118eb84
#20 [ffff8807c4b7bf80] system_call_fastpath at ffffffff8100b072
RIP: 00007fdbe7dc9065 RSP: 00007fff9cddeb28 RFLAGS: 00010246
RAX: 0000000000000004 RBX: ffffffff8100b072 RCX: 0000000000000000
RDX: 00007fff9cddfcf0 RSI: 00007fff9cddfcf0 RDI: 00007fdbeb9d4940
RBP: 0000000000000023 R8: 0000000000000000 R9: 0000000000000000
R10: 0000000000004000 R11: 0000000000000246 R12: 00007fff9cddfcf0
R13: 00007fdbeb9d4940 R14: 0000000000000000 R15: 00007fff9cddfcf0
ORIG_RAX: 0000000000000004 CS: 0033 SS: 002b
crash> backtrace <end>
Found nfs module in backtrace for pid 18055
...
Running ~/crash/macros/fs/nfs/rhel6-analyze-nfs
BEGIN: Last 50 lines of kernel log
(struct rpc_task *) 0xffff880bf55843c0
rpc_task.tk_rqstp = (struct rpc_rqst *)0xffff880bff6c8800 rpc_rqst.rq_xprt = (struct rpc_xprt *)0xffff880600172000
rpc_rqst: rq_xid = 0x82bde1b5
rpc_rqst: rq_retries = 2, rq_ntrans = 2, rq_bytes_sent = 0, (last_jiffies_update - rq_xtime)/10^9 = 250 seconds
(last_jiffies_update - tk_start)/10^9 = 31335 seconds, tk_start = 960312874029746, tk_timeouts = 0
tk_owner = 27396, tk_flags = 0x280, tk_status = 0, tk_runstate = 6, tk_timeout = 180000
tk_msg.rpc_proc->pname = ACCESS
tk_action = 0xffffffffa01f9500, &u.tk_work = 0xffff880bf5584448, tk_workqueue = (nil)
tk_priority = 1, tk_waitqueue = 0xffff880600172258 tk_waitqueue.name = xprt_pending
rpc_task.tk_client = 0xffff880bff6c8200 (cl_protname = nfs, cl_vers = 4, cl_server = foobar)
RPC Transport State Summary for (struct rpc_xprt *)0xffff880600172000
=====================================================================
rpc_xprt.state = 0x11 (For details, use 'rhel-rpc-xprt-states')
- WARNING: rpc_xprt.state bit 1 _NOT_ set (XPRT_CONNECTED) - check networking
rpc_xprt.prot = 6 (TCP)
- sock.__sk_common.skc_state = 2 (TCP_SYN_SENT)
- WARNING: skc_state != 1 - check networking!
RPC Transport other structures (struct rpc_xprt *)0xffff880600172000
=====================================================================
xprt.inet = (struct sock *)0xffff8805ff656e00
xprt.sock = (struct socket *)0xffff880602adcc00
xprt.sock = (struct tcp_sock *)0xffff8805ff656e00
Dest (IP:port) 10.139.19.208:2049
Src (IP:port) 10.139.19.76:813
rpc_xprt.xprt_net = (struct net *)0xffffffff81b18540
Slot table free list: (struct list_head *) 0xffff8806001723e8
Slot table entries: tcp = 2, udp = 16
snd_task = (struct rpc_task *)0xffff880bf55843c0
RPC wait queues
- binding (struct rpc_wait_queue *) 0xffff8806001720c8: qlen = 0, owner = 0
- sending (struct rpc_wait_queue *) 0xffff880600172190: qlen = 219, owner = 27396
- backlog (struct rpc_wait_queue *) 0xffff880600172320: qlen = 0, owner = 0
- pending (struct rpc_wait_queue *) 0xffff880600172258: qlen = 1, owner = 0
non-xprt queues
- delay_queue (struct rpc_wait_queue *)0xffffffffa0224e40 qlen = 0
crash>
END: Last 50 lines of kernel log
- Adjusting the vmcore DATE output using https://access.redhat.com/solutions/752683 we get the following time for the vmcore.
$ TZ="Europe/Berlin" date --date="Sun Jul 6 04:00:21 2014 EDT"
Sun Jul 6 10:00:21 CEST 2014
- Now from the oldest blocked task, and the NFS task in the vmcore, let's estimate when the problem occurred. The oldest NFS task was started 31335 seconds ago, and it's the one on the transport.
[ 0 08:41:42.597] [UN] PID: 18055 TASK: ffff880b6e967540 CPU: 2 COMMAND: "sshd_cre"
(last_jiffies_update - tk_start)/10^9 = 31335 seconds, tk_start = 960312874029746, tk_timeouts = 0
crash> pd (31335 / 60 / 60)
$1 = 8
crash> pd (31335 - 8*3600)
$2 = 2535
crash> pd (2535 / 60)
$3 = 42
crash> pd (2535 - 42 * 60)
$4 = 15
- So it looks like roughly 8 hours, 42 minutes and 15 seconds ago the NFS task was started, which is now stuck waiting for TCP reconnect. If we take the vmcore time and this time we get:
$ TZ="Europe/Berlin" date -d "Sun Jul 6 10:00:21 CEST 2014"-8hours-42minutes-15seconds
Sun Jul 6 01:18:06 CEST 2014 - estimated time of the NFS / TCP connectivity issue started
Sun Jul 6 10:00:21 CEST 2014 - time of the vmcore
- Now let's look at the NFS client side TCP dump. The TCP connection of interest is: 10.139.19.76:813 <--> 10.139.19.208:2049. We see this in the NFS client side tcpdump, and we see repeated SYN requests which are timing out. The tcpdump definitely matches the state of the vmcore, which shows NFS waiting on TCP to reconnect.
$ TZ="Europe/Berlin" tshark -tad -r tcpdump.pcap | grep TCP
tshark: The file "dump/01132126-tcpdump.pcap" appears to have been cut short in the middle of a packet.
6 2014-07-06 09:49:17.209648 10.139.19.76 -> 10.139.19.208 TCP 74 813 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990683371 TSecr=0 WS=64
8 2014-07-06 09:49:18.209626 10.139.19.76 -> 10.139.19.208 TCP 74 [TCP Retransmission] 813 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990684371 TSecr=0 WS=64
11 2014-07-06 09:49:20.209622 10.139.19.76 -> 10.139.19.208 TCP 74 [TCP Retransmission] 813 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990686371 TSecr=0 WS=64
16 2014-07-06 09:49:24.209617 10.139.19.76 -> 10.139.19.208 TCP 74 [TCP Retransmission] 813 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990690371 TSecr=0 WS=64
22 2014-07-06 09:49:32.209628 10.139.19.76 -> 10.139.19.208 TCP 74 [TCP Retransmission] 813 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990698371 TSecr=0 WS=64
29 2014-07-06 09:49:48.209624 10.139.19.76 -> 10.139.19.208 TCP 74 [TCP Retransmission] 813 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990714371 TSecr=0 WS=64
33 2014-07-06 09:50:03.307500 10.139.19.76 -> 10.139.19.208 TCP 74 34377 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990729468 TSecr=0 WS=128
34 2014-07-06 09:50:03.308070 10.139.19.208 -> 10.139.19.76 TCP 78 2049 > 34377 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=512 SACK_PERM=1 WS=2 TSval=2970647390 TSecr=990729468
35 2014-07-06 09:50:03.308093 10.139.19.76 -> 10.139.19.208 TCP 66 34377 > 2049 [ACK] Seq=1 Ack=1 Win=14720 Len=0 TSval=990729469 TSecr=2970647390
36 2014-07-06 09:50:07.556673 10.139.19.76 -> 10.139.19.208 TCP 68 34377 > 2049 [PSH, ACK] Seq=1 Ack=1 Win=14720 Len=2 TSval=990733718 TSecr=2970647390
37 2014-07-06 09:50:07.657662 10.139.19.208 -> 10.139.19.76 TCP 66 2049 > 34377 [ACK] Seq=1 Ack=3 Win=65940 Len=0 TSval=2970651740 TSecr=990733718
38 2014-07-06 09:50:07.787668 10.139.19.76 -> 10.139.19.208 TCP 68 34377 > 2049 [PSH, ACK] Seq=3 Ack=1 Win=14720 Len=2 TSval=990733949 TSecr=2970651740
- Now look at the NFS server side TCP dump. The NFS server is seeing something completely different, or the dumps somehow mangled, for packets 6, 8, 11, 16, etc. The NFS server is not seeing the 'SYN' flag set and it looks like the packet has been changed for these SYN packets. I'm not even sure these are the same packets though they appear to be due to the timestamps and all the other data and surrounding packets, and so I conclude they must be mangled somehow. But the sizes are even smaller at 54 bytes vs 74 bytes for the NFS client dump.
$ editcap -r vif2a_20140706_094741.trc.gz vif2a_20140706_094741.trc-1-38 1-38
Add_Selected: 1-38
Inclusive ... 1, 38
$ TZ="Europe/Berlin" tshark -tad -r vif2a_20140706_094741.trc-1-38 | grep TCP
6 2014-07-06 09:49:17.198526000 10.139.19.76 -> 10.139.19.208 TCP 54 813 > 2049 [ACK] Seq=1 Ack=1 Win=14600 Len=0
8 2014-07-06 09:49:18.198393000 10.139.19.76 -> 10.139.19.208 TCP 54 813 > 2049 [ACK] Seq=1 Ack=3875730313 Win=14600 Len=0
11 2014-07-06 09:49:20.198135000 10.139.19.76 -> 10.139.19.208 TCP 54 813 > 2049 [ACK] Seq=1 Ack=198961815 Win=14600 Len=0
16 2014-07-06 09:49:24.197671000 10.139.19.76 -> 10.139.19.208 TCP 54 813 > 2049 [ACK] Seq=1 Ack=3094146499 Win=14600 Len=0
22 2014-07-06 09:49:32.196768000 10.139.19.76 -> 10.139.19.208 TCP 54 813 > 2049 [ACK] Seq=1 Ack=1630579234 Win=14600 Len=0
29 2014-07-06 09:49:48.194916000 10.139.19.76 -> 10.139.19.208 TCP 54 813 > 2049 [ACK] Seq=1 Ack=4216384732 Win=14600 Len=0
33 2014-07-06 09:50:03.291283000 10.139.19.76 -> 10.139.19.208 TCP 74 34377 > 2049 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=990729468 TSecr=0 WS=128
34 2014-07-06 09:50:03.291339000 10.139.19.208 -> 10.139.19.76 TCP 78 2049 > 34377 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=512 SACK_PERM=1 WS=2 TSval=2970647390 TSecr=990729468
35 2014-07-06 09:50:03.291601000 10.139.19.76 -> 10.139.19.208 TCP 66 34377 > 2049 [ACK] Seq=1 Ack=1 Win=14720 Len=0 TSval=990729469 TSecr=2970647390
36 2014-07-06 09:50:07.539691000 10.139.19.76 -> 10.139.19.208 TCP 68 34377 > 2049 [PSH, ACK] Seq=1 Ack=1 Win=14720 Len=2 TSval=990733718 TSecr=2970647390
37 2014-07-06 09:50:07.640429000 10.139.19.208 -> 10.139.19.76 TCP 66 2049 > 34377 [ACK] Seq=1 Ack=3 Win=65940 Len=0 TSval=2970651740 TSecr=990733718
38 2014-07-06 09:50:07.770643000 10.139.19.76 -> 10.139.19.208 TCP 68 34377 > 2049 [PSH, ACK] Seq=3 Ack=1 Win=14720 Len=2 TSval=990733949 TSecr=2970651740
Analysis of tcpdumps
- All SYN requests from the client (10.139.19.76):
$ tcpdump 'tcp[13] & 2 != 0' -r tcpdump.pcap
reading from file 01132126-tcpdump.pcap, link-type EN10MB (Ethernet)
09:49:17.209648 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [S], seq 3142343194, win 14600, options [mss 1460,sackOK,TS val 990683371 ecr 0,nop,wscale 6], length 0
09:49:18.209626 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [S], seq 3142343194, win 14600, options [mss 1460,sackOK,TS val 990684371 ecr 0,nop,wscale 6], length 0
09:49:20.209622 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [S], seq 3142343194, win 14600, options [mss 1460,sackOK,TS val 990686371 ecr 0,nop,wscale 6], length 0
09:49:24.209617 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [S], seq 3142343194, win 14600, options [mss 1460,sackOK,TS val 990690371 ecr 0,nop,wscale 6], length 0
09:49:32.209628 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [S], seq 3142343194, win 14600, options [mss 1460,sackOK,TS val 990698371 ecr 0,nop,wscale 6], length 0
09:49:48.209624 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [S], seq 3142343194, win 14600, options [mss 1460,sackOK,TS val 990714371 ecr 0,nop,wscale 6], length 0
09:50:03.307500 IP 10.139.19.76.34377 > 10.139.19.208.nfs: Flags [S], seq 4122603935, win 14600, options [mss 1460,sackOK,TS val 990729468 ecr 0,nop,wscale 7], length 0
- All except the last request are seen on the filer like this:
$ tcpdump -s0 dst port nfs -r vif2a_20140706_094741.trc |less
reading from file vif2a_20140706_094741.trc, link-type EN10MB (Ethernet)
09:49:17.198526 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [.], ack 3611674827, win 14600, length 0
09:49:18.198393 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [.], ack 3875730313, win 14600, length 0
09:49:20.198135 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [.], ack 198961815, win 14600, length 0
09:49:24.197671 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [.], ack 3094146499, win 14600, length 0
09:49:32.196768 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [.], ack 1630579234, win 14600, length 0
09:49:48.194916 IP 10.139.19.76.813 > 10.139.19.208.nfs: Flags [.], ack 4216384732, win 14600, length 0
09:50:03.291283 IP 10.139.19.76.34377 > 10.139.19.208.nfs: Flags [S], seq 4122603935, win 14600, options [mss 1460,sackOK,TS val 990729468 ecr 0,nop,wscale 7], length 0
- The last request is than answered by the server with a syn-ack:
09:50:03.291339 IP 10.139.19.208.nfs > 10.139.19.76.34377: Flags [S.], seq 435293523, ack 4122603936, win 65535, options [mss 512,nop,nop,sackOK,nop,wscale 1,nop,nop,TS val 2970647390 ecr 990729468], length 0
- Which is than confirmed by the client with a final ACK:
09:50:03.308093 IP 10.139.19.76.34377 > 10.139.19.208.nfs: Flags [.], ack 1, win 115, options [nop,nop,TS val 990729469 ecr 2970647390], length 0
- Looks like the filer can't establish a connection when the initial request comes from a privileged (< 1024) port. Once the client uses a port > 1024 (34377 in the example), the connection can be established.
SBR
Product(s)
Components
Category
Tags
This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.