NetBSD Problem Report #50432

From  Sun Nov 15 21:06:48 2015
Return-Path: <>
Received: from ( [])
	(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
	(Client CN "", Issuer "Postmaster" (verified OK))
	by (Postfix) with ESMTPS id AE34EA654B
	for <>; Sun, 15 Nov 2015 21:06:48 +0000 (UTC)
Message-Id: <>
Date: Sun, 15 Nov 2015 22:06:42 +0100 (CET)
Subject: NFS client crashes or hangs kernel
X-Send-Pr-Version: 3.95

>Number:         50432
>Category:       kern
>Synopsis:       NFS client crashes or hangs kernel
>Confidential:   no
>Severity:       serious
>Priority:       high
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Sun Nov 15 21:10:00 +0000 2015
>Originator:     Rhialto
>Release:        NetBSD 7.0


System: NetBSD 7.0 NetBSD 7.0 (GENERIC.201509250726Z) amd64
Architecture: x86_64
Machine: amd64

Following a thread on current-users and tech-kern, I'm filing this PR so
that the issue doesn't get lost. No resolution was reached. I'm
summarizing the useful contents here.


NFS clients on NetBSD 7.0 (plain GENERIC kernel as distributed) seem to
have a problem with the queue of outstanding requests to the server
(nfs_reqq). As a result, either the kernel crashes because the queue is
traversed while it contains bogus pointers, or processes start to hang
on NFS I/O, because their I/O seemingly never completes. (The reply no
doubt was received, but could not be matched to an outstanding request
and was therefore dropped).

What I'm doing when this happens: I'm mounting a pkg_comp chroot which
is located on NFS. On top of it, I mount a local directory for temporary
files. But lots of NFS traffic still happens, mostly readonly, but
writing when it creates and installs the packages. The extra null mounts
that pkg_comp does may make things more fragile.

All mounts:

/dev/wd0a on / type ffs (local)
/dev/wd0f on /var type ffs (log, local)
/dev/wd0e on /usr type ffs (log, local)
/dev/wd0g on /home type ffs (log, local)
/dev/wd0h on /tmp type ffs (log, local)
kernfs on /kern type kernfs (local)
ptyfs on /dev/pts type ptyfs (local)
procfs on /proc type procfs (local)
procfs on /usr/pkg/emul/linux32/proc type procfs (read-only, local)
nfsserver:/mnt/vol1 on /mnt/vol1 type nfs
nfsserver:/mnt/scratch on /mnt/scratch type nfs
tmpfs on /var/shm type tmpfs (local)
/mnt/vol1/rhialto/cvs/src on /mnt/scratch/scratch/chroot/pkg_comp.amd64-7.0/default/usr/src type null (read-only)
/mnt/vol1/rhialto/cvs/pkgsrc on /mnt/scratch/scratch/chroot/pkg_comp.amd64-7.0/default/usr/pkgsrc type null (read-only)
/mnt/vol1/distfiles on /mnt/scratch/scratch/chroot/pkg_comp.amd64-7.0/default/pkg_comp/distfiles type null
/mnt/scratch/scratch/packages.amd64-7.0 on /mnt/scratch/scratch/chroot/pkg_comp.amd64-7.0/default/pkg_comp/packages type null
/home/rhialto/obj on /mnt/scratch/scratch/chroot/pkg_comp.amd64-7.0/default/pkg_comp/obj/pkgsrc type null (local)

The problem did not go away when I changed the mount from UDP to TCP.

Here is some debugging I've done on this.

I re-tried and with an original GENERIC 7.0 kernel it happened again and
now I have a crash dump. Its dmesg ends with this:

nfs server not responding
nfs server is alive again
fatal page fault in supervisor mode
trap type 6 code 0 rip ffffffff806b94b4 cs 8 rflags 10246 cr2 38 ilevel 2 rsp ff
curlwp 0xfffffe813fb39860 pid 0.5 lowest kstack 0xfffffe80b9fbf2c0
panic: trap
cpu0: Begin traceback...
vpanic() at netbsd:vpanic+0x13c
snprintf() at netbsd:snprintf
startlwp() at netbsd:startlwp
alltraps() at netbsd:alltraps+0x96
callout_softclock() at netbsd:callout_softclock+0x248
softint_dispatch() at netbsd:softint_dispatch+0x79
DDB lost frame for netbsd:Xsoftintr+0x4f, trying 0xfffffe80b9fc1ff0
Xsoftintr() at netbsd:Xsoftintr+0x4f
--- interrupt ---
cpu0: End traceback...

dumping to dev 0,1 (offset=199775, size=1023726):

pid 0.5 is this:

PID    LID S CPU     FLAGS       STRUCT LWP *               NAME WAIT
0    >   5 7   0       200   fffffe813fb39860          softclk/0

gdb (without debugging symbols) so far thinks this is in nfs_timer():

(gdb) kvm proc 0xfffffe813fb39860
0xffffffff806b9aab in nfs_timer ()
(gdb) bt
#0  0xffffffff806b9aab in nfs_timer ()
#1  0x0000000000000000 in ?? ()

with a rebuilt netbsd.gdb (hopefully the addresses match)

(gdb) target kvm netbsd.5.core
0xffffffff8063d735 in cpu_reboot (howto=howto@entry=260,
bootstr=bootstr@entry=0x0) at ../../../../arch/amd64/amd64/machdep.c:671
671                     dumpsys();
(gdb) bt
#0  0xffffffff8063d735 in cpu_reboot (howto=howto@entry=260,
bootstr=bootstr@entry=0x0) at ../../../../arch/amd64/amd64/machdep.c:671
#1  0xffffffff80865182 in vpanic (fmt=0xffffffff80d123b2 "trap",
fmt@entry=0xffffffff80d123d2 "otection fault",
ap=ap@entry=0xfffffe80b9fc1d10) at ../../../../kern/subr_prf.c:340
#2  0xffffffff8086523d in panic (fmt=fmt@entry=0xffffffff80d123d2
"otection fault") at ../../../../kern/subr_prf.c:256
#3  0xffffffff808a84d6 in trap (frame=0xfffffe80b9fc1e30) at
#4  0xffffffff80100f46 in alltraps ()
#5  0xffffffff806b94b4 in nfs_sigintr (nmp=0x0, rep=0xfffffe81163730a8,
l=0x0) at ../../../../nfs/nfs_socket.c:871
#6  0xffffffff806b9b0e in nfs_timer (arg=<optimized out>) at
#7  0xffffffff805e9458 in callout_softclock (v=<optimized out>) at
#8  0xffffffff805df84a in softint_execute (l=<optimized out>,
s=<optimized out>, si=<optimized out>) at
#9  softint_dispatch (pinned=<optimized out>, s=2) at
#10 0xffffffff8011402f in Xsoftintr ()

(gdb) kvm proc 0xfffffe813fb39860
nfs_timer (arg=<unavailable>) at ../../../../nfs/nfs_socket.c:735
735     {
(gdb) bt
#0  nfs_timer (arg=<unavailable>) at ../../../../nfs/nfs_socket.c:735
#1  0x0000000000000000 in ?? ()

nmp should not be NULL here... let's look at rep, where it comes from
via "nmp = rep->r_nmp;"

(gdb) print *(struct nfsreq *)0xfffffe81163730a8
$1 = {r_chain = {tqe_next = 0xfffffe811edcee40, tqe_prev = 0x1}, r_mreq = 0xffff8000028f9888, r_mrep = 0x0, r_md = 0x0, r_dpos = 0x0, r_nmp = 0x0, r_xid = 0, r_flags = 0, r_retry = 0, r_rexmit = 0, r_procnum = 0, r_rtt = 0, 
  r_lwp = 0x0}

well, r_chain.tqe_prev looks bogus (unless that's a special marker), so
let's look at tqe_next:

(gdb) print *((struct nfsreq *)0xfffffe81163730a8)->r_chain.tqe_next
$3 = {r_chain = {tqe_next = 0x0, tqe_prev = 0x15aa3c85d}, r_mreq = 0xbd83e8af8fe58282, r_mrep = 0x81e39981e3a781e3, r_md = 0xe39d81e38180e38c, r_dpos = 0x8890e5b4a0e5ae81, r_nmp = 0xe57baf81e3ab81e3, r_xid = 2179183259, 
  r_flags = -1565268289, r_retry = 0, r_rexmit = 0, r_procnum = 1520683101, r_rtt = 1, r_lwp = 0x80e39981e3a781e3}

well, even more bogus. Too bad that the next frame has its argument
optimized out...

This problem is very repeatable, usually within a few hours, but a few
times now it happened within half an hour.

It seems to me that somehow the nfs_reqq list gets corrupted. Then
either there is a crash when traversing it in nfs_timer() (occurring in
nfs_sigintr() due to being called with a bogus pointer), or there is a
hang when one of the NFS requests gets lost and never retried.

I tried it with a TCP mount for NFS. Still hangs, this time in a bit
under an hour of uptime.

So the cause is likely not packet loss.

Further looking into this by examining where nfs_reqq occurs:

nfs/nfs.h:extern TAILQ_HEAD(nfsreqhead, nfsreq) nfs_reqq;

nfs/nfs_clntsocket.c:         TAILQ_FOREACH(rep, &nfs_reqq, r_chain) {
nfs/nfs_clntsocket.c: TAILQ_INSERT_TAIL(&nfs_reqq, rep, r_chain);
nfs/nfs_clntsocket.c: TAILQ_REMOVE(&nfs_reqq, rep, r_chain);

Protected with

    s = splsoftnet();

for match #2 and #3 but #1 seems not protected by anything I can see
nearby. Maybe it is

    error = nfs_rcvlock(nmp, myrep);

if that makes any sense.
That function definitely does not use either splsoftnet() OR

nfs/nfs_socket.c:struct nfsreqhead nfs_reqq;
nfs/nfs_socket.c:     TAILQ_FOREACH(rp, &nfs_reqq, r_chain) {
nfs/nfs_socket.c:     TAILQ_FOREACH(rep, &nfs_reqq, r_chain) {

match #3 is protected with

    mutex_enter(softnet_lock);	/* XXX PR 40491 */

but none of the others (visibly nearby).

#2 is called from nfs_receive() which uses nfs_sndlock() which also
doesn't use either splsoftnet() OR mutex_enter(softnet_lock).

nfs/nfs_subs.c:       TAILQ_INIT(&nfs_reqq);

presumably doesn't need any extra protection.

softnet_lock is allocated as

./kern/uipc_socket.c:kmutex_t   *softnet_lock;
./kern/uipc_socket.c:   softnet_lock = mutex_obj_alloc(MUTEX_DEFAULT, IPL_NONE);

IPL_NONE seems inconsistent with splsoftnet().

I never studied the inner details of kernel locking, but the diversity
of protections of this list doesn't inspire trust at first sight.


And this is how far it got so far.

	Use pkg_comp with the chroot directory on an NFS-mounted volume.
	(see above for more details).
	Not known.

___ Olaf 'Rhialto' Seibert  -- The Doctor: No, 'eureka' is Greek for
\X/ rhialto/at/    -- 'this bath is too hot.'


NetBSD Home
NetBSD PR Database Search

(Contact us) $NetBSD: query-full-pr,v 1.39 2013/11/01 18:47:49 spz Exp $
$NetBSD:,v 1.8 2006/05/07 09:23:38 tsutsui Exp $
Copyright © 1994-2014 The NetBSD Foundation, Inc. ALL RIGHTS RESERVED.