Mysterious NFS mount timeouts

[Fabio Massimo Di Nitto]

In an ltsp environment (using initramfs), mounting / might take longer than 2
attempts in a second.
Specially in cases in which the switch, to which server and clients are
connected, is either overloaded
or negotiating the port speed. The result is a client not being able to mount
the real nfs root
and panic.
From some test machines i have here a good timeout is never less than 15 secs.
(on an tg3 gigabit connected to a 10Mb port, it takes around 9 secs to negotiate
port speed/duplex
+ the time to resend the dhcp request that is exponential from the previous
failed request).

Fabio

[Matt Zimmerman (mdz)]

What error messages do you see when this happens?

In an LTSP environment we have a problem where sometimes (seems racy) the root
NFS filesystem can never be mounted, and the kernel prints "NFS server <blah>
not responding" forever

[Fabio Massimo Di Nitto (fabbione)]

(In reply to comment #1)
> What error messages do you see when this happens?
>
> In an LTSP environment we have a problem where sometimes (seems racy) the root
> NFS filesystem can never be mounted, and the kernel prints "NFS server <blah>
> not responding" forever

IT claimed that the server was not reachable and paniced for not being able to
mount.

Fabio

[Matt Zimmerman (mdz)]

IT = the kernel?

or IT = nfsmount?

The message I am seeing is from the kernel, and therefore I do not believe that
it has to do with nfsmount itself, but perhaps the initialization of the network
card.

[Matt Zimmerman (mdz)]

This looks to me like a kernel issue. If I add a sleep (5 seconds) before the
nfsmount call, I am no longer able to reproduce the problem.
Also, when it does occur, it loops forever timing out, and never finishes the mount.

It seems like some sort of race between initializing the network device and
doing the NFS mount.

[Fabio Massimo Di Nitto (fabbione)]

The kernel has nothing to do with it. My hack solution to make this always working
was to run a tcpdump session on the server and see that the client was connecting
and while the server was answering, the client did timeout.

If this is a race condition, than it's due to something not loading the driver
in time
or not waiting for the stuff to be configured properly before using them.

[Matt Zimmerman (mdz)]

(In reply to comment #5)
> The kernel has nothing to do with it. My hack solution to make this always working
> was to run a tcpdump session on the server and see that the client was connecting
> and while the server was answering, the client did timeout.

What did you see in the tcpdump session which showed that it was nfsmount and
not the kernel which was responsible for the traffic?

> If this is a race condition, than it's due to something not loading the driver
> in time or not waiting for the stuff to be configured properly before using them.

The driver is obviously loaded and working, because the interface exists and
DHCP worked. ipconfig does DHCP and configures the interface before exiting.
Where is it that you feel it should wait?

Adding a sleep before attempting the NFS mount, as I have done to work around
this problem, is not the correct solution.

[Fabio Massimo Di Nitto (fabbione)]

(In reply to comment #6)
> (In reply to comment #5)
> > The kernel has nothing to do with it. My hack solution to make this always
working
> > was to run a tcpdump session on the server and see that the client was
connecting
> > and while the server was answering, the client did timeout.
>
> What did you see in the tcpdump session which showed that it was nfsmount and
> not the kernel which was responsible for the traffic?

the client was connecting to the server, the server was answering and the client
did timeout.

>
> > If this is a race condition, than it's due to something not loading the driver
> > in time or not waiting for the stuff to be configured properly before using
them.
>
> The driver is obviously loaded and working, because the interface exists and
> DHCP worked.

Yes. This is right. so the kernel did it's part of configuring the interface.

> ipconfig does DHCP and configures the interface before exiting.
> Where is it that you feel it should wait?
>

ipconfig is ok.

> Adding a sleep before attempting the NFS mount, as I have done to work around
> this problem, is not the correct solution.

nfsmount in klibc, simply timesout too fast. It attempts 3 times very fast to
mount /
and fails immediatly with the timeout error. A normal nfs client does a few attempts
with longer "sleeps" between attempts.

Fabio

[Matt Zimmerman (mdz)]

(In reply to comment #7)
> > What did you see in the tcpdump session which showed that it was nfsmount and
> > not the kernel which was responsible for the traffic?
>
> the client was connecting to the server, the server was answering and the client
> did timeout.

There are two clients involved: the nfsmount userland program, and the kernel.
Which one was involved in a transaction when you observed this behaviour?

> > Adding a sleep before attempting the NFS mount, as I have done to work around
> > this problem, is not the correct solution.
>
> nfsmount in klibc, simply timesout too fast. It attempts 3 times very fast to
> mount /
> and fails immediatly with the timeout error. A normal nfs client does a few
attempts
> with longer "sleeps" between attempts.

That isn't what I see in the code:

#define TIMEOUT_MS 3000
#define MAX_TRIES 100
[...]
        for (i = 0; i < MAX_TRIES; i++) {
                int timeout_ms = TIMEOUT_MS + (lrand48() % (TIMEOUT_MS / 2));

Furthermore, I don't think that nfsmount prints any error messages about
timeouts, unless debugging is enabled:

                                DEBUG(("Timeout #%d\n", i + 1));

The error message "%s: server %s not responding, still trying" (which is the one
that I see) is written to the console by Linux, and not by any part of klibc.

[Fabio Massimo Di Nitto (fabbione)]

(In reply to comment #8)
> (In reply to comment #7)
> > > What did you see in the tcpdump session which showed that it was nfsmount and
> > > not the kernel which was responsible for the traffic?
> >
> > the client was connecting to the server, the server was answering and the client
> > did timeout.
>
> There are two clients involved: the nfsmount userland program, and the kernel.
> Which one was involved in a transaction when you observed this behaviour?

Oh hmm i didn't check this so carefully.

>
> > > Adding a sleep before attempting the NFS mount, as I have done to work around
> > > this problem, is not the correct solution.
> >
> > nfsmount in klibc, simply timesout too fast. It attempts 3 times very fast to
> > mount /
> > and fails immediatly with the timeout error. A normal nfs client does a few
> attempts
> > with longer "sleeps" between attempts.
>
> That isn't what I see in the code:
>
> #define TIMEOUT_MS 3000
> #define MAX_TRIES 100
> [...]
> for (i = 0; i < MAX_TRIES; i++) {
> int timeout_ms = TIMEOUT_MS + (lrand48() % (TIMEOUT_MS / 2));
>
> Furthermore, I don't think that nfsmount prints any error messages about
> timeouts, unless debugging is enabled:
>
> DEBUG(("Timeout #%d\n", i + 1));
>
> The error message "%s: server %s not responding, still trying" (which is the one
> that I see) is written to the console by Linux, and not by any part of klibc.

Yes but that's not the one i see. The kernel just fails immediatly to mount /
and the command
that is issued to mount / is from klibc.. iirc there were one or two initrafms
scripts executed
before that, but i will check again as soon as i can get the setup back.

Fabio

[Matt Zimmerman (mdz)]

(In reply to comment #9)
> > The error message "%s: server %s not responding, still trying" (which is the one
> > that I see) is written to the console by Linux, and not by any part of klibc.
>
> Yes but that's not the one i see. The kernel just fails immediatly to mount /
> and the command
> that is issued to mount / is from klibc.. iirc there were one or two initrafms
> scripts executed
> before that, but i will check again as soon as i can get the setup back.

OK, then it sounds like we are seeing different bugs, because I see the above
error from the kernel. I am very curious to know the exact message that you see.

[Fabio Massimo Di Nitto (fabbione)]

This is what i see here (manual copy):

Begin: Running /scripts/nfs-premount
Done
nfs: server 192.168.100.1 not responding, time out
nfs: server 192.168.100.1 not responding, time out
mount: I/O error
short read: 0 < 28
Begin: Running /scripts/nfs-bottom ...
Done.
Done.
Begin: Running /scripts/init-bottom ...
Done.
run-init: current directory on the same filesystem as the root: error 0
Kernel panic - not syncing: Attempted to kill init!

[Matt Zimmerman (mdz)]

OK, then that is the same as what I see, and it looks like a kernel issue. That
timeout message is coming from the kernel.

Ben, any ideas how we could trace this further?

[Daniel Carrera (dcarrera)]

I've experienced this problem too. After rebooting the client and server many
times, this is the pattern I see:

1. Reboot the server.
2. Boot client.
3. Kernel panic.
4. Reboot client.
5. Successful boot process.

Any subsequent client reboot is successful, until the server reboots again.

Cheers,
Daniel.

[Ben Collins (ben-collins)]

Yeah, I found the kernel message. Comes from sunrpc. No idea how to trace this.
RPC is voodoo that I hate getting into.

Fabio, you say you see the client and server communicating and then it still fails?

Can you do Daniel's "fix" and see if the tcpdump is somehow different on
negotiation when it works compared to when it fails?

From what it sounds like, the server is getting the client request, but the
client is not getting the ack back from the server. This would sound to me like
the kernel IP stack is not fully configured at this point, in some way. Since
Matt can work around it with a sleep before mounting, this seems to make sense.
However, Daniel's reboot workaround makes me feel uneasy about that assumption.

In Daniel's case there is no difference in the client after a reboot, just that
the server has gone through one failure.

Anyone tried this with something other than a Linux nfs server? Is the nfs
server the userspace or kernel nfsd?

[Matt Zimmerman (mdz)]

Jim McQuillan from LTSP mentioned this article:
http://wiki.ltsp.org/twiki/bin/view/Ltsp/NFS#NFS_Server_not_responding
Could someone who can reproduce this problem try lowering rsize/wsize and see if
that helps?

(In reply to comment #14)
> From what it sounds like, the server is getting the client request, but the
> client is not getting the ack back from the server. This would sound to me like
> the kernel IP stack is not fully configured at this point, in some way.

If the problem were something like this, I'd expect it to eventually retry and
succeed. The strange part of all this is that it never recovers. Can you think
of any explanation for that, or anyplace we could forward this issue?

In my case I have only tried knfsd.

[Jesper Krogh (jesper)]

I can confirm this bug.. I get it in both stages and the client can even drop a successful NFS-mount on
a fully running client.

I tried adding MOPTS=nolock,ro,wsize=2048,rsize=2048 (as suggested on the LTSP wiki)

 to the pxelinux.cfg/default file but the client doesn't seem to respect it. I've found the exact mount
options by doing a:
cat /proc/mounts on the client.

[Jesper Krogh (jesper)]

I have the same problem. I've hacked the pxelinux.cfg/default to give the kernel "rsize=8192,wsize=8192" as
boot parameters and the ramdisk to mount the NFS with the same options. This did not solve the problem. If
the client successfully boots, i cannot get a reasonable terminal for 5 minutes.

[Jesper Krogh (jesper)]

(In reply to comment #17)
> I have the same problem. I've hacked the pxelinux.cfg/default to give the
kernel "rsize=8192,wsize=8192" as
> boot parameters and the ramdisk to mount the NFS with the same options. This
did not solve the problem. If
> the client successfully boots, i cannot get a reasonable terminal for 5 minutes.
>

Failed to mention that this is an Breezy ltsp setup.

[Matt Zimmerman (mdz)]

MOPTS is a parameter specific to the traditional LTSP boot process; it won't
have any effect on Ubuntu. There is currently no convenient way to pass extra
NFS mount options on Ubuntu (I didn't know about this feature of LTSP until now).

Oliver will be performing some tests to see if rsize/wsize works around the
problem, and if so, we will make it the default.

[Oliver Grawert (ogra)]

i tried with editing /usr/share/initramfs-tools/scripts/nfs and changing the line:
nfsmount ${roflag} ${NFSROOT} ${rootmnt}
to
nfsmount -o rsize=2048,wsize=2048 ${roflag} ${NFSROOT} ${rootmnt}
(afterwards sudo dpkg-reconfigure linux-image-`uname -r` and
sudo ltsp-update-kernels outside the chroot)

didnt change a thing here :-/
i additionally tried nolock as well as different sizes (1024, 4096 and 8192)

i rather suspect the problem on the server side...

[Oliver Grawert (ogra)]

YAY,YAY,YAY, adding "-o retrans=10" to
/opt/ltsp/i386/usr/share/initramfs-tools/scripts/nfs solves it !!!

[Matt Zimmerman (mdz)]

initramfs-tools 0.32 contains changes which we hope will alleviate this problem:

initramfs-tools (0.32) breezy; urgency=low
[...]
  * scripts/nfs (mountroot): New variable: NFSOPTS, default to
    -o retranfs=10, hopefully closes 12942. The can be
    overridden in the initramfs.conf file.
    Thanks to Oliver Grawert for testing this!

To test it, execute these commands:

sudo chroot /opt/ltsp/i386 apt-get update
sudo chroot /opt/ltsp/i386 apt-get dist-upgrade
sudo chroot /opt/ltsp/i386 dpkg -l initramfs-tools # verify that you have >= 0.32
sudo chroot /opt/ltsp/i386 dpkg-reconfigure linux-image-2.6.12-9-386
sudo ltsp-update-kernels

Please test this as soon as possible and let us know if the problem recurs.

[Matt Zimmerman (mdz)]

It is very important that we know whether this resolves the problem for the
impending 5.10 release. Please test!

[Fabio Massimo Di Nitto (fabbione)]

working on it right now..

[Fabio Massimo Di Nitto (fabbione)]

yup.. it's working like a charm now :)))

Fabio

[Matt Zimmerman (mdz)]

(In reply to comment #25)
> yup.. it's working like a charm now :)))

Thanks.

[Jesper Krogh (jesper)]

From a 10 minutes test in my setup.. It has solved the problem completely.

[Matt Zimmerman (mdz)]

According to Oliver, and contradicting comment #21, this bug seems to still be
present. Reopened.

[Ben Collins (ben-collins)]

(In reply to comment #28)
> According to Oliver, and contradicting comment #21, this bug seems to still be
> present. Reopened.

Even in dapper?

[Oliver Grawert (ogra)]

yes, even in dapper, i removed the sleep 3 before nfsmount from initramfs in
dapper, it was only a workaround we used in breezy, the real prob of timing out
clients on first mount attempt is still there, it doesnt time out on the second
boot of a thin client... i'll do a tcpdump and ethereal session the next days ...

[xtsbdu3reyrbrmroezob (xtsbdu3reyrbrmroezob)]

I see the same problem in Breezy :-( I get a reply from the NFS server on some rpc or nfs call, then the client waits about 80 seconds before the final two calls to mount the system occur! But the last two calls from the client are very quick and the process terminates successfully -- but that wait period in between is killer!!! I checked the nfs script and it already has the suggested retrans fix above, and that is obviously not doing anything...

[xtsbdu3reyrbrmroezob (xtsbdu3reyrbrmroezob)]

Interesting to note that someone else says adding hosts to the server's /etc/hosts file fixed their issue (bug #28166). However. I tried it and it did not:
https://launchpad.net/distros/ubuntu/+source/nfs-utils/+bug/28166

What is going on here? How can I get around this mouting issue? And I hope tht it is only an issue with mounting and that there won't be delays in accessing the file system after it is mounted. Anyone seen that type of activity as well? I ask only because I've been having issues with LDAP+GDM, and some are rreporting weird things with that as well...not sure if it could be tied in any way to this bug -- but it's wort a shot mentioning it...

[xtsbdu3reyrbrmroezob (xtsbdu3reyrbrmroezob)]

here's the error im getting in /var/log/messages from the kernel:

nfs warning: mount version older than kernel

Then followed by these errors multiple times (4 times i believe):
server localhsot not responding, timed out
rpc: failed to contact portmanp (errno -5)

changing retrans does not change the time it takes for the mount command to finish. In factm the time command shows a solid 1m45s for these value of retrans --> 10, 3, 0. The question is, with this info, does ti give you guys any better idea???

[xtsbdu3reyrbrmroezob (xtsbdu3reyrbrmroezob)]

Cuuld this bug (bug #24421) be the cause for all our concerns!?!??? Seems like portmap is using binding localhost even when we are mounting remote NFS shares!
https://launchpad.net/distros/ubuntu/+source/portmap/+bug/24421

[xtsbdu3reyrbrmroezob (xtsbdu3reyrbrmroezob)]

$ sudo aptitude install portmap

That fixed my problem. Now NFS mounts in under 1 second :-) Thanks to this find via googling:
http://ubuntuforums.org/showthread.php?t=77274

[Matt Zimmerman (mdz)]

On Wed, Jan 25, 2006 at 07:52:18AM -0000, Kristian Hermansen wrote:
> Public bug report changed:
> https://launchpad.net/malone/bugs/19196
>
> Comment:
> $ sudo aptitude install portmap
>
> That fixed my problem. Now NFS mounts in under 1 second :-) Thanks to this find via googling:
> http://ubuntuforums.org/showthread.php?t=77274

nfs-kernel-server depends on nfs-common which depends on portmap. How did
you not have it installed?

You seem to be experiencing a different problem than the one described in
the original bug report.

--
 - mdz

[Martin Kreiner (languste)]

regarding to the original bug, when mounting an nfs-root with nfsmount:

is there any way to reproduce this bug without having a busy/missconfigured switch in between?

and @Oliver Grawert is the bug still present when you use the busybox mount (which is still included in busybox-initramfs-1.01-4ubuntu1tcos1):

--- scripts/nfs.org 2006-01-27 21:54:00.092757473 +0000
+++ scripts/nfs 2006-01-27 21:54:39.846412979 +0000
@@ -33,7 +33,7 @@
                roflag="-o rw"
        fi

- nfsmount ${roflag} ${NFSOPTS} ${NFSROOT} ${rootmnt}
+ mount -o nolock ${roflag} ${NFSOPTS} ${NFSROOT} ${rootmnt}

        [ "$quiet" != "y" ] && log_begin_msg "Running /scripts/nfs-bottom"
        run_scripts /scripts/nfs-bottom

[Oliver Grawert (ogra)]

it happens to me even with a crossover cable in dapper, no need for broken switches ;)

will try the busybox mount suggestion and report back soon...

[Oliver Grawert (ogra)]

please commit the above fix to the nfs script, its fixing the issue

[Matt Zimmerman (mdz)]

Colin noted that you should remember to use -o nolock, since no portmapper will be available. Since it's a read-only mount anyway, this shouldn't present any problems.

[Martin Kreiner (languste)]

just to straighten it out:

if my above patch fixes the "Mysterious NFS mount timeouts" the bug would be either in klibc's nfsmount or it's a package install problem. which version of the klibc package you are using, oliver?
the current version klibc-1.1.16-1ubuntu1 has the nolock option (NFS_MOUNT_NONLM=no NetworkLockManager) as default in usr/kinit/nfsmount/main.c:

static struct nfs_mount_data mount_data = {
        ...
        .flags = NFS_MOUNT_NONLM | NFS_MOUNT_VER3 | NFS_MOUNT_TCP,
        ...
}

in my dapper environment nfsmount is mounting the nfs-root with the option nolock set and works as expected.
what happens if you change back from busybox-mount to klibc's nfsmount with nolock option forced:

- mount -o nolock ${roflag} ${NFSOPTS} ${NFSROOT} ${rootmnt}
+ nfsmount -o nolock ${roflag} ${NFSOPTS} ${NFSROOT} ${rootmnt}

(you could set NFSOPTS="-o retrans=10,nolock" in "/etc/mkinitramfs/initramfs.conf" as well instead)

martin

[Matt Zimmerman (mdz)]

Date: Tue, 31 Jan 2006 11:55:11 +0000
Source: initramfs-tools
Binary: initramfs-tools
Architecture: source
Version: 0.40ubuntu17
Distribution: dapper
Urgency: low
Maintainer: Jeff Bailey <email address hidden>
Changed-By: Adam Conrad <email address hidden>
Description:
 initramfs-tools - tools for generating an initramfs
Changes:
 initramfs-tools (0.40ubuntu17) dapper; urgency=low
 .
   * Make auto_add_modules take an argument, so you can use it to add only
     some of the auto* modules (like "net" or "ide"), and create a "netboot"
     option that only includes base and net (Closes launchpad.net/26426)
   * Change the nfs script to use "mount -o nolock" instead of "nfsmount",
     to fix some timeouts for ltsp NFS roots (Closes launchpad.net/19196)

[Matt Zimmerman (mdz)]

If this change fares well in Dapper, it should be considered for backporting to Breezy

[Matt Zimmerman (mdz)]

Any feedback from Dapper users? Is this suitable for backporting?

[Oliver Grawert (ogra)]

at least for what i hear in #edubuntu it solved the issue for testers so far ... i could include it in the breezy-updates upload i'll make for the dependency fix in ltsp

[Matt Zimmerman (mdz)]

On Fri, Feb 10, 2006 at 05:10:44PM -0000, Oliver Grawert wrote:
> Public bug report changed:
> https://launchpad.net/malone/bugs/19196
>
> Comment:
> at least for what i hear in #edubuntu it solved the issue for testers so
> far ... i could include it in the breezy-updates upload i'll make for
> the dependency fix in ltsp

It would be a good idea to have Breezy users test the fix first.

--
 - mdz

[Oliver Grawert (ogra)]

yes, i mixed up the packages anyway, indeed i wont make a initramfs-tools upload to -updates ... thats inifintys terrain ... i'll try to find some more breezy users to test (i had one in #ltsp, worked fine for him)

[Joel Franco (joel-franco)]

Hi All,

I have "NFS not responding" and i have tried tcp,nfsvers=3,rsize and wsize stuffs but nothing have worked to me.

However, i changed the autodetect connection of my GigaBit Switch (PowerConnect 5224) of the port in which the machine was in trouble to manual (100 Full Duplex) and all started to work perfect. The problem appears to be with the switch.

I hope this help someone with the same problem.

[]s

[Matt Zimmerman (mdz)]

Is this still a pressing issue in Breezy, justifying a backport? If so, please go ahead, otherwise it can wait for the Dapper release, which is not far off now.

[Marco Rodrigues (gothicx)]

Breezy support is over.. Today it's Breezy End Of Life!