Re: persistent, quasi-random -ESTALE at mount time

Re: persistent, quasi-random -ESTALE at mount time

[George Spelvin]

For what it's worth, I'm seeing the same problem.

The server was just rebooted with 2.6.38-rc3, and the client reported
"STALE NFS file handle".  I wish I understood why; I thought the point
of a stateless protocol was that it could survive server reboots.

Anyway, I found all the affected processes, killed them, unmounted,
tried to remount, and lo and behold:

mount("server:/path/dir", "/client/dir", "nfs", MS_RDONLY|MS_NOSUID|MS_NODEV|MS_NOEXEC, "addr=ww.xx.yy.zz,vers=3,proto=tcp,mountvers=3,mountproto=tcp,mountport=2050") = -1 ESTALE (Stale NFS file handle)

The server is just logging
send(10, "<29>Feb  1 22:39:49 mountd[4167]: authenticated mount request from $CLIENT:912 for /path/dir (/path/dir)", 125, MSG_NOSIGNAL) = 125

/proc/fs/nfs/exports is reporting:
/path/dir   *.dom.ain,client.dom.ain(ro,root_squash,async,wdelay,no_subtree_check,uuid=3210ba59:586b43f2:8780109f:d915f4ab)

Debian packaged nfs utilities 1.2.2-4 on both server and client.  32 bits in both cases.  (Server is
running a 64-bit kernel, but 32-bit userland.)

It worked immediately before the reboot (when the server was runnign 2.6.26-rcX).


"exportfs -a" several times did NOT fix it, but restarting mountd and nfsd
("/etc/init.d/nfs-kernel-server restart") fixed it.


Anyway, quite annoying.  Unfortunately, that's a server I don't like to reboot.
(But I can restart the NFS server safely if that would help testing.)

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Tue, Feb 01, 2011 at 10:56:36PM -0500, George Spelvin wrote:
> For what it's worth, I'm seeing the same problem.
> 
> The server was just rebooted with 2.6.38-rc3, and the client reported
> "STALE NFS file handle".  I wish I understood why; I thought the point
> of a stateless protocol was that it could survive server reboots.
> 
> Anyway, I found all the affected processes, killed them, unmounted,
> tried to remount, and lo and behold:
> 
> mount("server:/path/dir", "/client/dir", "nfs", MS_RDONLY|MS_NOSUID|MS_NODEV|MS_NOEXEC, "addr=ww.xx.yy.zz,vers=3,proto=tcp,mountvers=3,mountproto=tcp,mountport=2050") = -1 ESTALE (Stale NFS file handle)
> 
> The server is just logging
> send(10, "<29>Feb  1 22:39:49 mountd[4167]: authenticated mount request from $CLIENT:912 for /path/dir (/path/dir)", 125, MSG_NOSIGNAL) = 125
> 
> /proc/fs/nfs/exports is reporting:
> /path/dir   *.dom.ain,client.dom.ain(ro,root_squash,async,wdelay,no_subtree_check,uuid=3210ba59:586b43f2:8780109f:d915f4ab)
> 
> Debian packaged nfs utilities 1.2.2-4 on both server and client.  32 bits in both cases.  (Server is
> running a 64-bit kernel, but 32-bit userland.)
> 
> It worked immediately before the reboot (when the server was runnign 2.6.26-rcX).
> 
> 
> "exportfs -a" several times did NOT fix it, but restarting mountd and nfsd
> ("/etc/init.d/nfs-kernel-server restart") fixed it.
> 
> 
> Anyway, quite annoying.  Unfortunately, that's a server I don't like to reboot.
> (But I can restart the NFS server safely if that would help testing.)

So the reboot was for an upgrade from 2.6.26-rcX to 2.6.38-rc3?  I
wonder if a reboot (or just a server restart) without changing kernels
would see the same problem?

In which case some change in the filehandle format or perhaps in the way
the uuid's are calculated might explain the problem.

We work quite hard to ensure that filehandles returned from older nfsd's
will still be accepted by newer ones.  But that doesn't mean there
couldn't failed at that somehow in some case....

If you manage to reproduce the problem, /proc/fs/nfs/exports before and
after the reboot would be interesting, and ideally also a network trace
showing traffic before and after the reboot (including the operation
that returned the STALE error).

--b.

Re: persistent, quasi-random -ESTALE at mount time

[George Spelvin]

> So the reboot was for an upgrade from 2.6.26-rcX to 2.6.38-rc3?  I
> wonder if a reboot (or just a server restart) without changing kernels
> would see the same problem?

Whoops, typo.  It was from 2.6.36-rcX (I think -rc5, but it's scrolled
off the logs), not .26.

> We work quite hard to ensure that filehandles returned from older nfsd's
> will still be accepted by newer ones.  But that doesn't mean there
> couldn't failed at that somehow in some case....

I understand that sometimes there's an incompatible server change, but
I don't ever remember a Linux-linux nfs mount surviving a server
reboot.

However, the problem I'm complaining about here is more alarming.  With
a clean client, attempting to *mount* is failing with -ESTALE.

> If you manage to reproduce the problem, /proc/fs/nfs/exports before and
> after the reboot would be interesting, and ideally also a network trace
> showing traffic before and after the reboot (including the operation
> that returned the STALE error).

Can do.  How much detail do you want in the packet trace?  Is -vvv
enough, or do you want -X as well?

Thank you very much for the response; I'll try to reproduce and
capture the problem.
-- 
	-Colib

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Wed, Feb 02, 2011 at 11:28:14PM -0500, George Spelvin wrote:
> > So the reboot was for an upgrade from 2.6.26-rcX to 2.6.38-rc3?  I
> > wonder if a reboot (or just a server restart) without changing kernels
> > would see the same problem?
> 
> Whoops, typo.  It was from 2.6.36-rcX (I think -rc5, but it's scrolled
> off the logs), not .26.
> 
> > We work quite hard to ensure that filehandles returned from older nfsd's
> > will still be accepted by newer ones.  But that doesn't mean there
> > couldn't failed at that somehow in some case....
> 
> I understand that sometimes there's an incompatible server change, but
> I don't ever remember a Linux-linux nfs mount surviving a server
> reboot.
> 
> However, the problem I'm complaining about here is more alarming.  With
> a clean client, attempting to *mount* is failing with -ESTALE.

Oh, apologies, I missed that.

> > If you manage to reproduce the problem, /proc/fs/nfs/exports before and
> > after the reboot would be interesting, and ideally also a network trace
> > showing traffic before and after the reboot (including the operation
> > that returned the STALE error).
> 
> Can do.  How much detail do you want in the packet trace?  Is -vvv
> enough, or do you want -X as well?

Actually, the raw packet data would be most useful; so something like:

	tcpdump -s0 -wtmp.pcap

then send me tmp.pcap.

And the contents of

	/proc/net/rpc/nfsd.fh/content
	/proc/net/rpc/nfsd.export/content

after the failure.

--b.

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Wed, Feb 02, 2011 at 11:28:14PM -0500, George Spelvin wrote:
> > So the reboot was for an upgrade from 2.6.26-rcX to 2.6.38-rc3?  I
> > wonder if a reboot (or just a server restart) without changing kernels
> > would see the same problem?
> 
> Whoops, typo.  It was from 2.6.36-rcX (I think -rc5, but it's scrolled
> off the logs), not .26.
> 
> > We work quite hard to ensure that filehandles returned from older nfsd's
> > will still be accepted by newer ones.  But that doesn't mean there
> > couldn't failed at that somehow in some case....
> 
> I understand that sometimes there's an incompatible server change, but

Separate from the current problem, but: no, that shouldn't be true.  If
you find a case where a kernel upgrade causes clients to fail, that's a
bug and we'd like to know about it.

> I don't ever remember a Linux-linux nfs mount surviving a server
> reboot.

Ouch.  I do test that regularly, and haven't seen problems.  Again, if
you have reproduceable problem, I'd appreciate details.--b.

Re: persistent, quasi-random -ESTALE at mount time

[Nix]

On 3 Feb 2011, J. Bruce Fields stated:

> Ouch.  I do test that regularly, and haven't seen problems.  Again, if
> you have reproduceable problem, I'd appreciate details.--b.

I can give you a packet dump from my (completely reproducible) failure
with the same symptoms, if you like. (Again, it is fixed by running
exportfs repeatedly, each time fixing another few mounts: currently,
I have to run it six times.)

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Thu, Feb 03, 2011 at 08:30:48AM +0000, Nix wrote:
> On 3 Feb 2011, J. Bruce Fields stated:
> 
> > Ouch.  I do test that regularly, and haven't seen problems.  Again, if
> > you have reproduceable problem, I'd appreciate details.--b.
> 
> I can give you a packet dump from my (completely reproducible) failure
> with the same symptoms, if you like. (Again, it is fixed by running
> exportfs repeatedly, each time fixing another few mounts: currently,
> I have to run it six times.)

That would be great, thanks.  And could you collect the contents of
/proc/net/rpc/{nfsd.fh,nfsd.export}/content at the same time?  (I think
you already sent some; but I'd be curious to match them up with the
packet trace.)  Also, the output of "blkid" might help diagnose any
problems with uuid's.

(Also, I think it's probably a totally different problem, but I found a
problem yesterday with out-of-date uuid information that appears to be
due to selinux preventing rpc.mountd from opening block devices; are you
using selinux, and if so does turning it off (setenforce 0) help?)

--b.

Re: persistent, quasi-random -ESTALE at mount time

[Nix]

On 3 Feb 2011, J. Bruce Fields uttered the following:

> On Thu, Feb 03, 2011 at 08:30:48AM +0000, Nix wrote:
>> I can give you a packet dump from my (completely reproducible) failure
>> with the same symptoms, if you like. (Again, it is fixed by running
>> exportfs repeatedly, each time fixing another few mounts: currently,
>> I have to run it six times.)
>
> That would be great, thanks.  And could you collect the contents of
> /proc/net/rpc/{nfsd.fh,nfsd.export}/content at the same time?  (I think
> you already sent some; but I'd be curious to match them up with the
> packet trace.)  Also, the output of "blkid" might help diagnose any
> problems with uuid's.

I jinxed it. I just recompiled and the problem went away. The only
differences between the old and new kernel are a so-far-entirely-
unconfigured IPv6 setup (so nothing but link-local private addresses, no
routing, nothing) and a new compiler (4.5.x rather than 4.4.x).

Which of these caused the change in behaviour I do not yet know, but
will try to figure out (by turning IPv6 off again and seeing if
the problem recurs).

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Sun, Feb 06, 2011 at 06:54:46PM +0000, Nix wrote:
> On 3 Feb 2011, J. Bruce Fields uttered the following:
> > On Thu, Feb 03, 2011 at 08:30:48AM +0000, Nix wrote:
> >> I can give you a packet dump from my (completely reproducible) failure
> >> with the same symptoms, if you like. (Again, it is fixed by running
> >> exportfs repeatedly, each time fixing another few mounts: currently,
> >> I have to run it six times.)
> >
> > That would be great, thanks.  And could you collect the contents of
> > /proc/net/rpc/{nfsd.fh,nfsd.export}/content at the same time?  (I think
> > you already sent some; but I'd be curious to match them up with the
> > packet trace.)  Also, the output of "blkid" might help diagnose any
> > problems with uuid's.
> 
> I jinxed it. I just recompiled and the problem went away. The only
> differences between the old and new kernel are a so-far-entirely-
> unconfigured IPv6 setup (so nothing but link-local private addresses, no
> routing, nothing) and a new compiler (4.5.x rather than 4.4.x).
> 
> Which of these caused the change in behaviour I do not yet know, but
> will try to figure out (by turning IPv6 off again and seeing if
> the problem recurs).

OK, thanks.

--b.

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Thu, Feb 03, 2011 at 11:16:29AM -0800, David Brodbeck wrote:
> On Wed, Feb 2, 2011 at 8:28 PM, George Spelvin <linux@horizon.com> wrote:
> 
> > I don't ever remember a Linux-linux nfs mount surviving a server
> > reboot.
> >
> 
> I do it semi-regularly and it *usually* works...but I never reboot the
> server unless I'm prepared to reboot hung clients, just in case.
> 
> Actually, I've seen more problems with Solaris-Linux NFSv4 mounts.  For a
> while there was a pretty good chance that rebooting a server would result in
> state recovery failure loops on the client.  I see less of that lately, but
> I'm also doing fewer server reboots...

There have been some recovery bugs fixed; if you know of any more,
details would be welcomed.

--b.

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Fri, Dec 17, 2010 at 08:45:34PM +0000, Nix wrote:
> On 2 Oct 2010, J. Bruce Fields stated:
> 
> > On Fri, Oct 01, 2010 at 11:41:42PM +0100, Nix wrote:
> >> I mean, yes, we can work around it by killing rpc.mountd and restarting
> >> it as soon as the server has booted, but, well, yuck, no thanks, too
> >> much of a kludge. I'll have a concentrated hunt for the bug soon (once I
> >> can reproduce it without rebooting the single largest machine I have
> >> root on!)
> >
> > OK, thanks for the persistence, and apologies that I can't think of
> > anything off the top of my head (and haven't had the time to try and
> > look more closely).  I'll look forward to anything more you can figure
> > out....
> 
> This is still happening. Just by chance (while checking to see if adding
> unique fsids to every line fixed it: no) I spotted something
> interesting, which I think points to the cause.
> 
> You don't need to repeatedly kill rpc.mountd and restart it at all to
> fix things. You just have to run exportfs many times!
> 
> Here are dumps of /proc/fs/nfs/exports on boot (after a single exportfs -ra),
> then after a subsequent one, then another:
...
> If exportfs is not correctly exporting everything to the kernel when
> run, that would pretty much explain the cause of spontaneous -ESTALEs on
> reboot, because rebooting clears the mount table: if a single exportfs
> is failing to properly refill it, mountd is going to say -ESTALE about
> everything it forgot to put back in.

Note that the contents of /proc/fs/nfs/exports represent the kernel's
cached view of the exports, *not* the entire export table; when a client
requests an export which the kernel does not know about, the kernel
makes an upcall to mountd to get the relevant export entry.  All
exportfs does is clear the kernel's cache so that subsequent upcalls
will get the new information.

So it's normal that the contents of /porc/fs/nfs/exports would be
incomplete immediately after running exportfs.

--b.

> 
> 
> I'll scatter debugging through exportfs and try to see what it's doing
> wrong.

Re: persistent, quasi-random -ESTALE at mount time

[Nix]

On 2 Oct 2010, J. Bruce Fields stated:

> On Fri, Oct 01, 2010 at 11:41:42PM +0100, Nix wrote:
>> I mean, yes, we can work around it by killing rpc.mountd and restarting
>> it as soon as the server has booted, but, well, yuck, no thanks, too
>> much of a kludge. I'll have a concentrated hunt for the bug soon (once I
>> can reproduce it without rebooting the single largest machine I have
>> root on!)
>
> OK, thanks for the persistence, and apologies that I can't think of
> anything off the top of my head (and haven't had the time to try and
> look more closely).  I'll look forward to anything more you can figure
> out....

This is still happening. Just by chance (while checking to see if adding
unique fsids to every line fixed it: no) I spotted something
interesting, which I think points to the cause.

You don't need to repeatedly kill rpc.mountd and restart it at all to
fix things. You just have to run exportfs many times!

Here are dumps of /proc/fs/nfs/exports on boot (after a single exportfs -ra),
then after a subsequent one, then another:

# Version 1.1
# Path Client(Flags) # IPs
/var/state/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=17,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
/usr/share/xplanet	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=9,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/httpd/htdocs/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=18,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/xemacs	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=8,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/texlive	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=7,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/nethack	mutilate.wkstn.nix(rw,root_squash,async,wdelay,fsid=10,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/lib/X11/fonts	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=12,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/clamav	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=19,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/doc	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=5,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/src	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=16,uuid=333950aa:8e3f440a:bc94d0cc:4adae198)

# Version 1.1
# Path Client(Flags) # IPs
/var/state/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=17,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
/usr/share/xplanet	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=9,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/etc/shai-hulud	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=15,uuid=6c0f7fa7:d6c24054:bff33a87:8460bdc7)
/usr/share/httpd/htdocs/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=18,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/xemacs	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=8,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/home/.spindle.srvr.nix/nix/Graphics/Photos	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=3,uuid=78c50891:aaac452b:8b4fa769:9565a21e)
/usr/share/texlive	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=7,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/nethack	mutilate.wkstn.nix(rw,root_squash,async,wdelay,fsid=10,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/var/log.real	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=14,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
/usr/lib/X11/fonts	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=12,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/clamav	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=19,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/home/.spindle.srvr.nix	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=1,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
/usr/doc	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=5,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/src	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=16,uuid=333950aa:8e3f440a:bc94d0cc:4adae198)
/usr/info	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=6,uuid=5cccc224:a92440ee:b4450447:3898c2ec)

# Version 1.1
# Path Client(Flags) # IPs
/var/state/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=17,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
/usr/share/xplanet	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=9,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/etc/shai-hulud	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=15,uuid=6c0f7fa7:d6c24054:bff33a87:8460bdc7)
/usr/share/httpd/htdocs/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=18,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/xemacs	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=8,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/home/.spindle.srvr.nix/nix/Graphics/Photos	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=3,uuid=78c50891:aaac452b:8b4fa769:9565a21e)
/usr/share/texlive	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,fsid=7,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/nethack	mutilate.wkstn.nix(rw,root_squash,async,wdelay,fsid=10,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/var/log.real	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=14,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
/home/.spindle.srvr.nix/nix/Mail/nnmh/spambox-verified	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=2,uuid=52d386c2:b6384034:8bd4e199:5e3237bb)
/usr/lib/X11/fonts	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=12,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/share/clamav	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=19,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/home/.spindle.srvr.nix	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=1,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
/pkg/non-free	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=11,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/usr/doc	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=5,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
/home/.spindle.srvr.nix	fold.srvr.nix(rw,root_squash,async,wdelay,no_subtree_check,fsid=1,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
/usr/src	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,fsid=16,uuid=333950aa:8e3f440a:bc94d0cc:4adae198)
/usr/info	mutilate.wkstn.nix(ro,root_squash,async,wdelay,fsid=6,uuid=5cccc224:a92440ee:b4450447:3898c2ec)

If exportfs is not correctly exporting everything to the kernel when
run, that would pretty much explain the cause of spontaneous -ESTALEs on
reboot, because rebooting clears the mount table: if a single exportfs
is failing to properly refill it, mountd is going to say -ESTALE about
everything it forgot to put back in.


I'll scatter debugging through exportfs and try to see what it's doing
wrong.

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Fri, Oct 01, 2010 at 11:41:42PM +0100, Nix wrote:
> On 1 Oct 2010, J. Bruce Fields spake thusly:
> 
> > On Thu, Sep 23, 2010 at 10:03:36PM +0100, Nix wrote:
> >> I'll say.
> >
> > Sorry for the slow response; have you figured out anything more?
> 
> Not yet. I try not to reboot the server except at weekends... I'll
> try to hook things up with a more rebootable machine as an NFS
> server (perhaps via qemu) so I can look into this without so much
> disruption.
> 
> >> I flipped RPC debug on and rebooted the client next. The server said:
> >> 
> >> Sep 23 21:33:15 spindle warning: [  127.385537] RPC:       Want update, refage=120, age=0
> >> Sep 23 21:33:15 spindle warning: [  127.536779] RPC:       Want update, refage=120, age=0
> >> [repeated 40 times]
> >> 
> >> When it connected, the server said
> >> 
> >> Sep 23 21:34:23 spindle warning: [  195.696257] RPC:       Want update, refage=120, age=68
> > ...
> >> Sep 23 21:34:38 spindle warning: [  210.766205] RPC:       Want update, refage=120, age=83
> >> 
> >> Now, the rpc/*/content files had grown again, and even the -ESTALEd
> >> filesystems, like /home/.spindle.srvr.nix, are represented once more:
> >
> > I'm a little confused.  Are you saying that in this case the client did
> > get ESTALE's?
> 
> Yes. Bizarre, isn't it? -ESTALE, but here the filesystems are! Note that
> if you try to reboot again, you still get -ESTALE: only restarting
> rpc.mountd seems to fix it.
> 
> >> I restarted rpc.mountd and the client, so it mounted correctly. Here's a
> >
> > And then here the problems was cleared and you didn't see any more of
> > them?
> 
> Yes, until the server got rebooted again.
> 
> I mean, yes, we can work around it by killing rpc.mountd and restarting
> it as soon as the server has booted, but, well, yuck, no thanks, too
> much of a kludge. I'll have a concentrated hunt for the bug soon (once I
> can reproduce it without rebooting the single largest machine I have
> root on!)

OK, thanks for the persistence, and apologies that I can't think of
anything off the top of my head (and haven't had the time to try and
look more closely).  I'll look forward to anything more you can figure
out....

--b.

Re: persistent, quasi-random -ESTALE at mount time

[Nix]

On 1 Oct 2010, J. Bruce Fields spake thusly:

> On Thu, Sep 23, 2010 at 10:03:36PM +0100, Nix wrote:
>> I'll say.
>
> Sorry for the slow response; have you figured out anything more?

Not yet. I try not to reboot the server except at weekends... I'll
try to hook things up with a more rebootable machine as an NFS
server (perhaps via qemu) so I can look into this without so much
disruption.

>> I flipped RPC debug on and rebooted the client next. The server said:
>> 
>> Sep 23 21:33:15 spindle warning: [  127.385537] RPC:       Want update, refage=120, age=0
>> Sep 23 21:33:15 spindle warning: [  127.536779] RPC:       Want update, refage=120, age=0
>> [repeated 40 times]
>> 
>> When it connected, the server said
>> 
>> Sep 23 21:34:23 spindle warning: [  195.696257] RPC:       Want update, refage=120, age=68
> ...
>> Sep 23 21:34:38 spindle warning: [  210.766205] RPC:       Want update, refage=120, age=83
>> 
>> Now, the rpc/*/content files had grown again, and even the -ESTALEd
>> filesystems, like /home/.spindle.srvr.nix, are represented once more:
>
> I'm a little confused.  Are you saying that in this case the client did
> get ESTALE's?

Yes. Bizarre, isn't it? -ESTALE, but here the filesystems are! Note that
if you try to reboot again, you still get -ESTALE: only restarting
rpc.mountd seems to fix it.

>> I restarted rpc.mountd and the client, so it mounted correctly. Here's a
>
> And then here the problems was cleared and you didn't see any more of
> them?

Yes, until the server got rebooted again.

I mean, yes, we can work around it by killing rpc.mountd and restarting
it as soon as the server has booted, but, well, yuck, no thanks, too
much of a kludge. I'll have a concentrated hunt for the bug soon (once I
can reproduce it without rebooting the single largest machine I have
root on!)

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Thu, Sep 23, 2010 at 10:03:36PM +0100, Nix wrote:
> On 22 Sep 2010, J. Bruce Fields verbalised:
> 
> > On Tue, Sep 21, 2010 at 09:28:13PM +0100, Nix wrote:
> >> Sep 21 20:51:39 spindle info: auth_unix_ip: inbuf 'nfsd 192.168.16.20'
> >> Sep 21 20:51:39 spindle info: auth_unix_ip: client 0x1f3dde0 'mutilate.wkstn.nix'
> >> Sep 21 20:51:39 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x014000000000000095bd22c2253c456f8e36b6cfb9ecd4ef'
> >
> > 7 is FSID_UUID16_INUM.
> >
> >> Sep 21 20:51:39 spindle info: nfsd_fh: found (nil) path (null)
> >
> > And mountd didn't find any filesystem matching the given uuid.  That's
> > strange.
> 
> I'll say.

Sorry for the slow response; have you figured out anything more?

Looking through your data quickly:

...
> Now I rebooted the server, leaving the client running (actually two are
> connected right now: 'fold' is my firewall. I think you can probably
> ignore it.) Post-reboot, it looked like this:
> 
> ,----
> | #uid cnt: gids...
> | # expiry=1285274048 refcnt=1 flags=3
> | # 1000 0:
> | #class IP domain
> | # expiry=1285275728 refcnt=2 flags=1
> | nfsd 192.168.16.20 mutilate.wkstn.nix
> | #path domain(flags)
> | #domain fsidtype fsid [path]
> | # expiry=2147483647 refcnt=1 flags=3
> | # mutilate.wkstn.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9
> `----
> 
> I flipped RPC debug on and rebooted the client next. The server said:
> 
> Sep 23 21:33:15 spindle warning: [  127.385537] RPC:       Want update, refage=120, age=0
> Sep 23 21:33:15 spindle warning: [  127.536779] RPC:       Want update, refage=120, age=0
> [repeated 40 times]
> 
> When it connected, the server said
> 
> Sep 23 21:34:23 spindle warning: [  195.696257] RPC:       Want update, refage=120, age=68
...
> Sep 23 21:34:38 spindle warning: [  210.766205] RPC:       Want update, refage=120, age=83
> 
> Now, the rpc/*/content files had grown again, and even the -ESTALEd
> filesystems, like /home/.spindle.srvr.nix, are represented once more:

I'm a little confused.  Are you saying that in this case the client did
get ESTALE's?

> I restarted rpc.mountd and the client, so it mounted correctly. Here's a

And then here the problems was cleared and you didn't see any more of
them?

--b.

Re: persistent, quasi-random -ESTALE at mount time

[Nix]

On 22 Sep 2010, J. Bruce Fields verbalised:

> On Tue, Sep 21, 2010 at 09:28:13PM +0100, Nix wrote:
>> Sep 21 20:51:39 spindle info: auth_unix_ip: inbuf 'nfsd 192.168.16.20'
>> Sep 21 20:51:39 spindle info: auth_unix_ip: client 0x1f3dde0 'mutilate.wkstn.nix'
>> Sep 21 20:51:39 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x014000000000000095bd22c2253c456f8e36b6cfb9ecd4ef'
>
> 7 is FSID_UUID16_INUM.
>
>> Sep 21 20:51:39 spindle info: nfsd_fh: found (nil) path (null)
>
> And mountd didn't find any filesystem matching the given uuid.  That's
> strange.

I'll say.

(The uuid of this filesystem is 95bd22c2-253c-456f-8e36-b6cfb9ecd4ef,
which looks just right.)

(btw, my libuuid comes from 61ef2474c24c80a5bf0e24ba85a7506fd7651a5c in
the e2fsprogs maint branch; my libblkid is from util-linux-ng commit
2c26d56ff524bdd9b7bbb45d19e47e67bb2b8d30 (2.18-plus-a-tiny-bit).

These work everywhere else, and indeed they seem to work with
nfs-utils... after a restart. (Obviously, by the time rpc.mountd is
running, LVM has long since been started, local filesystems mounted, and
all the uuids needed for said filesystems should damn well be visible.)

>> I'll try a packet capture next (time to use --port, I guess).

Oops. Forgot. Next time. :)

> The output of
>
> 	rpcdebug -m rpc -s cache
> 	more /proc/net/*/content

(assuming you meant /proc/net/rpc/*/content)

> after a failed startup might be interesting too.

Here. The normal case, first:

,----
| #uid cnt: gids...
| # expiry=1285273838 refcnt=1 flags=3
| # 0 0:
| # expiry=1285273838 refcnt=1 flags=3
| # 1000 0:
| #class IP domain
| # expiry=1285274634 refcnt=1 flags=1
| nfsd 192.168.14.1 fold.srvr.nix
| # expiry=1285275315 refcnt=2 flags=1
| nfsd 192.168.16.20 mutilate.wkstn.nix
| # expiry=2147483647 refcnt=1 flags=1
| nfsd 0.0.0.0 -test-client-
| #path domain(flags)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/doc	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /var/state/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/share/xplanet	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /etc/shai-hulud	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=6c0f7fa7:d6c24054:bff33a87:8460bdc7)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/share/clamav	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/src	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=333950aa:8e3f440a:bc94d0cc:4adae198)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/share/xemacs	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /home/.spindle.srvr.nix/nix/Graphics/Photos	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=78c50891:aaac452b:8b4fa769:9565a21e)
| # expiry=1285275315 refcnt=1 flags=1
| /home/.spindle.srvr.nix/nix/Mail/nnmh/spambox-verified	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=52d386c2:b6384034:8bd4e199:5e3237bb)
| # expiry=1285274634 refcnt=1 flags=1
| /home/.spindle.srvr.nix	fold.srvr.nix(rw,root_squash,async,wdelay,no_subtree_check,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
| # expiry=1285275315 refcnt=1 flags=1
| /var/log.real	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/lib/X11/fonts	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/share/texlive	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/share/httpd/htdocs/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /usr/info	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275315 refcnt=1 flags=1
| /home/.spindle.srvr.nix	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
| # expiry=1285275315 refcnt=1 flags=1
| /pkg/non-free	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=07799ff5:baef4492:875dc737:30d6149e)
| #domain fsidtype fsid [path]
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000e01e00000000a77f0f6c5440c2d6873af3bfc7bd6084 /etc/shai-hulud
| # expiry=2147483647 refcnt=1 flags=1
| fold.srvr.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9 /home/.spindle.srvr.nix
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000c001000000006b6ecbb545439ded3545d6ab19256ef5 /var/log.real
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 6 0xc286d352344038b699e1d48bbb37325e /home/.spindle.srvr.nix/nix/Mail/nnmh/spambox-verified
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000120010000000024c2cc5cee4024a9470445b4ecc29838 /usr/info
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000c001000000001e1d2b5e18f3665c0000000000000000 /var/log.real
| # expiry=2147483647 refcnt=1 flags=1
| fold.srvr.nix 6 0x9108c5782b45acaa69a74f8b1ea26595 /home/.spindle.srvr.nix/nix/Graphics/Photos
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 6 0xaa5039330a443f8eccd094bc98e1da4a /usr/src
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0001200100000000e889c66391bc82020000000000000000 /usr/info
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000653d0000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/clamav
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000a0010000000024c2cc5cee4024a9470445b4ecc29838 /usr/doc
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 6 0x9108c5782b45acaa69a74f8b1ea26595 /home/.spindle.srvr.nix/nix/Graphics/Photos
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 6 0xf59f79079244efba37c75d879e14d630 /pkg/non-free
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9 /home/.spindle.srvr.nix
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000e01e00000000d3fc452052a2fd930000000000000000 /etc/shai-hulud
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0008a002000000006b6ecbb545439ded3545d6ab19256ef5 /var/state/munin
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 6 0x802458c28a39500c0000000000000000 /pkg/non-free
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000075af0000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/httpd/htdocs/munin
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x00004001000000001b8b940d9cd091800000000000000000 /home/.spindle.srvr.nix
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000065820000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/xemacs
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000a51840000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/texlive
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000065850000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/xplanet
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x00086de80000000024c2cc5cee4024a9470445b4ecc29838 /usr/lib/X11/fonts
`----

Now I rebooted the server, leaving the client running (actually two are
connected right now: 'fold' is my firewall. I think you can probably
ignore it.) Post-reboot, it looked like this:

,----
| #uid cnt: gids...
| # expiry=1285274048 refcnt=1 flags=3
| # 1000 0:
| #class IP domain
| # expiry=1285275728 refcnt=2 flags=1
| nfsd 192.168.16.20 mutilate.wkstn.nix
| #path domain(flags)
| #domain fsidtype fsid [path]
| # expiry=2147483647 refcnt=1 flags=3
| # mutilate.wkstn.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9
`----

I flipped RPC debug on and rebooted the client next. The server said:

Sep 23 21:33:15 spindle warning: [  127.385537] RPC:       Want update, refage=120, age=0
Sep 23 21:33:15 spindle warning: [  127.536779] RPC:       Want update, refage=120, age=0
[repeated 40 times]

When it connected, the server said

Sep 23 21:34:23 spindle warning: [  195.696257] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.696605] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.711495] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.711741] RPC:       Want update, refage=120, age=0
Sep 23 21:34:23 spindle warning: [  195.712224] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.712753] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.713279] RPC:       Want update, refage=120, age=68
[repeated eleven times, mostly with seven repetitions, sometimes with eight]
Sep 23 21:34:23 spindle warning: [  195.800687] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.801247] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.801776] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.802316] RPC:       Want update, refage=120, age=68
Sep 23 21:34:23 spindle warning: [  195.802834] RPC:       Want update, refage=120, age=68
Sep 23 21:34:24 spindle warning: [  196.701890] RPC:       Want update, refage=120, age=69
Sep 23 21:34:24 spindle warning: [  196.702235] RPC:       Want update, refage=120, age=69
Sep 23 21:34:24 spindle warning: [  196.778129] RPC:       Want update, refage=120, age=69
Sep 23 21:34:24 spindle warning: [  196.778471] RPC:       Want update, refage=120, age=69
Sep 23 21:34:26 spindle warning: [  198.703264] RPC:       Want update, refage=120, age=71
Sep 23 21:34:26 spindle warning: [  198.703606] RPC:       Want update, refage=120, age=71
Sep 23 21:34:26 spindle warning: [  198.778288] RPC:       Want update, refage=120, age=71
Sep 23 21:34:26 spindle warning: [  198.778632] RPC:       Want update, refage=120, age=71
[...]
Sep 23 21:34:30 spindle warning: [  202.701820] RPC:       Want update, refage=120, age=75
Sep 23 21:34:30 spindle warning: [  202.702162] RPC:       Want update, refage=120, age=75
Sep 23 21:34:30 spindle warning: [  202.775312] RPC:       Want update, refage=120, age=75
Sep 23 21:34:30 spindle warning: [  202.775650] RPC:       Want update, refage=120, age=75
Sep 23 21:34:35 spindle warning: [  207.562434] RPC:       Want update, refage=120, age=0
Sep 23 21:34:35 spindle warning: [  207.562784] RPC:       Want update, refage=120, age=0
Sep 23 21:34:35 spindle warning: [  207.563032] RPC:       Want update, refage=120, age=0
[...]
Sep 23 21:34:38 spindle warning: [  210.693953] RPC:       Want update, refage=120, age=83
Sep 23 21:34:38 spindle warning: [  210.694135] RPC:       Want update, refage=120, age=83
Sep 23 21:34:38 spindle warning: [  210.766049] RPC:       Want update, refage=120, age=83
Sep 23 21:34:38 spindle warning: [  210.766205] RPC:       Want update, refage=120, age=83

Now, the rpc/*/content files had grown again, and even the -ESTALEd
filesystems, like /home/.spindle.srvr.nix, are represented once more:

,----
| #uid cnt: gids...
| # expiry=1285274115 refcnt=1 flags=3
| # 0 0:
| # expiry=1285274195 refcnt=1 flags=3
| # 1000 0:
| #class IP domain
| # expiry=1285275875 refcnt=3 flags=1
| nfsd 192.168.14.1 fold.srvr.nix
| # expiry=1285275878 refcnt=2 flags=1
| nfsd 192.168.16.20 mutilate.wkstn.nix
| #path domain(flags)
| # expiry=1285275878 refcnt=1 flags=1
| /pkg/non-free	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=07799ff5:baef4492:875dc737:30d6149e)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/src	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=333950aa:8e3f440a:bc94d0cc:4adae198)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/share/clamav	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275878 refcnt=1 flags=1
| /home/.spindle.srvr.nix	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
| # expiry=1285275863 refcnt=1 flags=1
| /var/log.real	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
| # expiry=1285275875 refcnt=1 flags=1
| /home/.spindle.srvr.nix	fold.srvr.nix(rw,root_squash,async,wdelay,no_subtree_check,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/share/texlive	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275863 refcnt=1 flags=1
| /var/state/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/info	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275863 refcnt=1 flags=1
| /etc/shai-hulud	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=6c0f7fa7:d6c24054:bff33a87:8460bdc7)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/share/xplanet	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/share/xemacs	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/doc	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/lib/X11/fonts	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| # expiry=1285275863 refcnt=1 flags=1
| /usr/share/httpd/htdocs/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
| #domain fsidtype fsid [path]
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000a0010000000024c2cc5cee4024a9470445b4ecc29838 /usr/doc
| # expiry=2147483647 refcnt=1 flags=3
| # mutilate.wkstn.nix 6 0xf59f79079244efba37c75d879e14d630
| # expiry=2147483647 refcnt=1 flags=3
| # mutilate.wkstn.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9
| # expiry=2147483647 refcnt=1 flags=1
| fold.srvr.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9 /home/.spindle.srvr.nix
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000653d0000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/clamav
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000c001000000006b6ecbb545439ded3545d6ab19256ef5 /var/log.real
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000120010000000024c2cc5cee4024a9470445b4ecc29838 /usr/info
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 6 0xaa5039330a443f8eccd094bc98e1da4a /usr/src
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0000e01e00000000a77f0f6c5440c2d6873af3bfc7bd6084 /etc/shai-hulud
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000065820000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/xemacs
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000a51840000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/texlive
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000065850000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/xplanet
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x00086de80000000024c2cc5cee4024a9470445b4ecc29838 /usr/lib/X11/fonts
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x000075af0000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/httpd/htdocs/munin
| # expiry=2147483647 refcnt=1 flags=1
| mutilate.wkstn.nix 7 0x0008a002000000006b6ecbb545439ded3545d6ab19256ef5 /var/state/munin
`----

I restarted rpc.mountd and the client, so it mounted correctly. Here's a
diff of the rpc/*/content files in this last stage. Some lines differ
only in times, but many are new:

--- rpc-content.post-server-reboot	2010-09-23 21:33:06.957968742 +0100
+++ rpc-content.back-to-normal	2010-09-23 21:37:17.397020536 +0100
@@ -1,10 +1,76 @@
 #uid cnt: gids...
-# expiry=1285274048 refcnt=1 flags=3
+# expiry=1285274237 refcnt=1 flags=3
 # 1000 0:
 #class IP domain
-# expiry=1285275728 refcnt=2 flags=1
+# expiry=1285276012 refcnt=2 flags=1
 nfsd 192.168.16.20 mutilate.wkstn.nix
 #path domain(flags)
+# expiry=1285276012 refcnt=1 flags=1
+/home/.spindle.srvr.nix/nix/Graphics/Photos	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=78c50891:aaac452b:8b4fa769:9565a21e)
+# expiry=1285276012 refcnt=1 flags=1
+/pkg/non-free	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=07799ff5:baef4492:875dc737:30d6149e)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/src	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=333950aa:8e3f440a:bc94d0cc:4adae198)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/share/clamav	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
+# expiry=1285276011 refcnt=1 flags=1
+/home/.spindle.srvr.nix	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=95bd22c2:253c456f:8e36b6cf:b9ecd4ef)
+# expiry=1285276012 refcnt=1 flags=1
+/var/log.real	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
+# expiry=1285276011 refcnt=1 flags=1
+/home/.spindle.srvr.nix/nix/Mail/nnmh/spambox-verified	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,no_subtree_check,uuid=52d386c2:b6384034:8bd4e199:5e3237bb)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/share/texlive	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
+# expiry=1285276012 refcnt=1 flags=1
+/var/state/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=b5cb6e6b:ed9d4345:abd64535:f56e2519)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/info	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
+# expiry=1285276012 refcnt=1 flags=1
+/etc/shai-hulud	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=6c0f7fa7:d6c24054:bff33a87:8460bdc7)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/share/xplanet	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/share/xemacs	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/doc	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/lib/X11/fonts	mutilate.wkstn.nix(ro,root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
+# expiry=1285276012 refcnt=1 flags=1
+/usr/share/httpd/htdocs/munin	mutilate.wkstn.nix(rw,no_root_squash,async,wdelay,uuid=5cccc224:a92440ee:b4450447:3898c2ec)
 #domain fsidtype fsid [path]
-# expiry=2147483647 refcnt=1 flags=3
-# mutilate.wkstn.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 6 0x9108c5782b45acaa69a74f8b1ea26595 /home/.spindle.srvr.nix/nix/Graphics/Photos
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x0000a0010000000024c2cc5cee4024a9470445b4ecc29838 /usr/doc
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 6 0xf59f79079244efba37c75d879e14d630 /pkg/non-free
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x0000400100000000c222bd956f453c25cfb6368eefd4ecb9 /home/.spindle.srvr.nix
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x0000653d0000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/clamav
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x0000c001000000006b6ecbb545439ded3545d6ab19256ef5 /var/log.real
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 6 0xc286d352344038b699e1d48bbb37325e /home/.spindle.srvr.nix/nix/Mail/nnmh/spambox-verified
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x000120010000000024c2cc5cee4024a9470445b4ecc29838 /usr/info
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 6 0xaa5039330a443f8eccd094bc98e1da4a /usr/src
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x0000e01e00000000a77f0f6c5440c2d6873af3bfc7bd6084 /etc/shai-hulud
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x000065820000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/xemacs
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x00004001000000001b8b940d9cd091800000000000000000 /home/.spindle.srvr.nix
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x000a51840000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/texlive
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x000065850000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/xplanet
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x00086de80000000024c2cc5cee4024a9470445b4ecc29838 /usr/lib/X11/fonts
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x000075af0000000024c2cc5cee4024a9470445b4ecc29838 /usr/share/httpd/htdocs/munin
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 7 0x0008a002000000006b6ecbb545439ded3545d6ab19256ef5 /var/state/munin
+# expiry=2147483647 refcnt=1 flags=1
+mutilate.wkstn.nix 6 0x802458c28a39500c0000000000000000 /pkg/non-free

Re: persistent, quasi-random -ESTALE at mount time

[J. Bruce Fields]

On Tue, Sep 21, 2010 at 09:28:13PM +0100, Nix wrote:
> I've noticed since at least 2.6.34 and possibly before (I only booted
> 2.6.33 and .34 once, so it's hard to remember) that initial mounts from
> my NFSv3 server are failing with -ESTALE.
> 
> This is only intermittent: sometimes, everything works. But, more often
> than that, I get an -ESTALE on some or all of the filesystems (again,
> the choice appears consistent but with no rhyme or reason to it:
> /usr/info and /pkg/non-free? /var/log.real and /home/.spindle.srvr.nix? 
> But /usr/doc always mounts OK, even though it is pretty much identical
> to /usr/info in all respects: same server mount point and everything):
> and, upon rebooting the server, I find that some of all of the
> previously correctly mounted filesystems are now returning -ESTALE as
> well. Unmounting and remounting them doesn't help: I just get more
> ESTALEs, which leads to an endless sequence of e.g. this:
> 
> mount.nfs: trying 192.168.14.15 prog 100003 vers 3 prot TCP port 2049
> mount.nfs: trying 192.168.14.15 prog 100005 vers 3 prot UDP port 33976
> mount.nfs: timeout set for Tue Sep 21 20:40:06 2010
> mount.nfs: trying text-based options 'hard,acl,vers=3,addr=192.168.14.15'
> mount.nfs: prog 100003, trying vers=3, prot=6
> mount.nfs: prog 100005, trying vers=3, prot=17
> spindle:/home/.spindle.srvr.nix on /home/.spindle.srvr.nix type nfs (rw,hard,acl,vers=3)
> 
> What *does* help is restarting rpc.mountd on the server. Everything
> works after that. Further, it seems to work if the client is stuck in
> the middle of rebooting for the entire time the server is rebooting:
> i.e. if the client starts rebooting first and ends rebooting later.
> (However, I do this very rarely, so I have few instances to reason from:
> this may be erroneous.)
> 
> Daemon boot order is as recommended, i.e.
> 
> mount /proc/fs/nfsd
> /usr/sbin/exportfs -ra
> /usr/sbin/portmap -t /var/lib/portmap
> /usr/sbin/rpc.mountd
> /usr/sbin/rpc.statd --no-notify
> /usr/sbin/rpc.nfsd 16
> /usr/sbin/sm-notify
> 
> On the client, we have
> 
> /usr/sbin/portmap -t /var/lib/portmap
> /usr/sbin/rpc.statd --no-notify
> /usr/sbin/sm-notify
> 
> (then we mount away... and it often fails with -ESTALE)
> 
> The client and server are running identical kernels (from 2.6.34 to
> 2.6.35.5), and identical versions of the nfs-utils (seen with 1.2.2-rc7
> up to tip-of-master). They're both nearly-identical 64-bit Nehalems (one
> is an i7 920, the other an L5520) with bags of RAM (12Gb up, mostly
> unused). All the filesystems being exported are ext4, all mounted with
> 
> defaults,nobarrier,relatime,nosuid,nodev,journal_async_commit,commit=30,user_xattr,acl
> 
> (yes, nobarrier is safe, the server has a battery-backed RAID array).
> 
> (Back in the day (pre-2.6.33) this problem wasn't present, and the
> filesystems are all older than that, so I doubt it's purely FS-related.)
> 
> 
> Debugging output from a failing rpc.mountd:
> 
> Sep 21 20:51:18 spindle info: v4root_create: path '/'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home'
> Sep 21 20:51:18 spindle info: v4root_create: path '/'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home'
> Sep 21 20:51:18 spindle info: v4root_create: path '/'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail/nnmh'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail/nnmh'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Graphics'
> Sep 21 20:51:18 local@spindle info: Last message 'v4root_create: path ' repeated 1 times, supressed by syslog-ng on spindle.srvr.nix
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr'
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share'
> Sep 21 20:51:18 spindle info: v4root_create: path '/pkg'
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr/lib'
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr/lib/X11'
> Sep 21 20:51:18 spindle info: v4root_create: path '/var'
> Sep 21 20:51:18 spindle info: v4root_create: path '/etc'
> Sep 21 20:51:18 spindle info: v4root_create: path '/var/state'
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share/httpd'
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share/httpd/htdocs'
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr'
> Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share'
> Sep 21 20:51:18 spindle info: v4root_create: path '/trees'
> Sep 21 20:51:18 spindle info: v4root_create: path '/'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix'
> Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix'
> Sep 21 20:51:19 spindle notice: Version 1.2.2 starting
> Sep 21 20:51:19 spindle warning: Flags: 
> Sep 21 20:51:23 spindle notice: Version 1.2.2 starting
> 
> (now I started rebooting the client: I suspect this is unmounting
> activity)
> 
> Sep 21 20:51:39 spindle info: auth_unix_ip: inbuf 'nfsd 192.168.16.20'
> Sep 21 20:51:39 spindle info: auth_unix_ip: client 0x1f3dde0 'mutilate.wkstn.nix'
> Sep 21 20:51:39 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x014000000000000095bd22c2253c456f8e36b6cfb9ecd4ef'

7 is FSID_UUID16_INUM.

> Sep 21 20:51:39 spindle info: nfsd_fh: found (nil) path (null)

And mountd didn't find any filesystem matching the given uuid.  That's
strange.

> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01400000000000000d948b1b8091d09c0000000000000000'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f316c0 path /home/.spindle.srvr.nix
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01c0000000000000b5cb6e6bed9d4345abd64535f56e2519'
> Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x1ee00000000000006c0f7fa7d6c24054bff33a878460bdc7'
> Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01200100000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01a00000000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2f6e0 path /usr/doc
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x82650000000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2e6f0 path /usr/share/xemacs
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x85650000000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2e1a0 path /usr/share/xplanet
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x84510a00000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2ec40 path /usr/share/texlive
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \xe86d0800000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2d1b0 path /usr/lib/X11/fonts
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 6 \x07799ff5baef4492875dc73730d6149e'
> Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 6 \x333950aa8e3f440abc94d0cc4adae198'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2bc70 path /usr/src
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x02a0080000000000b5cb6e6bed9d4345abd64535f56e2519'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2b720 path /var/state/munin
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \xaf750000000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2b1f0 path /usr/share/httpd/htdocs/munin
> Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x3d650000000000005cccc224a92440eeb44504473898c2ec'
> Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2ace0 path /usr/share/clamav
> 
> (client reboot underway. from here on, I'll only show one of the
> filesystems that failed to mount, rather than all of them.)
> 
> Sep 21 20:51:53 mutilate info: Switching to runlevel: 6
> Sep 21 20:52:56 spindle info: from_local: updating local if addr list
> Sep 21 20:52:56 spindle info: from_local: checked 14 local if addrs; incoming address not found
> Sep 21 20:52:56 spindle info: check_default: access by 192.168.16.20 ALLOWED
> Sep 21 20:52:56 spindle info: Received NULL request from 192.168.16.20
> Sep 21 20:52:56 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:56 spindle info: Received NULL request from 192.168.16.20
> Sep 21 20:52:56 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:56 spindle info: Received MNT3(/home/.spindle.srvr.nix) request from 192.168.16.20
> Sep 21 20:52:56 spindle notice: authenticated mount request from 192.168.16.20:673 for /home/.spindle.srvr.nix (/home/.spindle.srvr.nix)
> [identical messages for all the other filesystems]
> Sep 21 20:52:57 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:57 spindle info: Received NULL request from 192.168.16.20
> Sep 21 20:52:57 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:57 spindle info: Received NULL request from 192.168.16.20
> Sep 21 20:52:57 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:57 spindle info: Received MNT3(/home/.spindle.srvr.nix) request from 192.168.16.20
> Sep 21 20:52:57 spindle notice: authenticated mount request from 192.168.16.20:976 for /home/.spindle.srvr.nix (/home/.spindle.srvr.nix)
> [identical messages for the subset of those mounts that got -ESTALE]
> Sep 21 20:52:59 spindle notice: authenticated mount request from 192.168.16.20:820 for /home/.spindle.srvr.nix (/home/.spindle.srvr.nix)
> Sep 21 20:52:59 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:59 spindle info: Received NULL request from 192.168.16.20
> Sep 21 20:52:59 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:59 spindle info: Received NULL request from 192.168.16.20
> Sep 21 20:52:59 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
> Sep 21 20:52:59 spindle info: Received MNT3(/var/log.real) request from 192.168.16.20
> [repeat forever]
> 
> which all looks fine to me apart from the way the mount persistently
> fails despite the server saying it's OK.
> 
> Upon restart, it Just Works.
> 
> Any idea what the cause of this one might be? It's... mystifying. The
> 'fails only if just rebooted' part is particularly bizarre, as if
> rpc.mountd *really* wants to start after rpc.nfsd or something.
> 
> 
> I'll try a packet capture next (time to use --port, I guess).

The output of

	rpcdebug -m rpc -s cache
	more /proc/net/*/content

after a failed startup might be interesting too.

--b.

persistent, quasi-random -ESTALE at mount time

[Nix]

I've noticed since at least 2.6.34 and possibly before (I only booted
2.6.33 and .34 once, so it's hard to remember) that initial mounts from
my NFSv3 server are failing with -ESTALE.

This is only intermittent: sometimes, everything works. But, more often
than that, I get an -ESTALE on some or all of the filesystems (again,
the choice appears consistent but with no rhyme or reason to it:
/usr/info and /pkg/non-free? /var/log.real and /home/.spindle.srvr.nix? 
But /usr/doc always mounts OK, even though it is pretty much identical
to /usr/info in all respects: same server mount point and everything):
and, upon rebooting the server, I find that some of all of the
previously correctly mounted filesystems are now returning -ESTALE as
well. Unmounting and remounting them doesn't help: I just get more
ESTALEs, which leads to an endless sequence of e.g. this:

mount.nfs: trying 192.168.14.15 prog 100003 vers 3 prot TCP port 2049
mount.nfs: trying 192.168.14.15 prog 100005 vers 3 prot UDP port 33976
mount.nfs: timeout set for Tue Sep 21 20:40:06 2010
mount.nfs: trying text-based options 'hard,acl,vers=3,addr=192.168.14.15'
mount.nfs: prog 100003, trying vers=3, prot=6
mount.nfs: prog 100005, trying vers=3, prot=17
spindle:/home/.spindle.srvr.nix on /home/.spindle.srvr.nix type nfs (rw,hard,acl,vers=3)

What *does* help is restarting rpc.mountd on the server. Everything
works after that. Further, it seems to work if the client is stuck in
the middle of rebooting for the entire time the server is rebooting:
i.e. if the client starts rebooting first and ends rebooting later.
(However, I do this very rarely, so I have few instances to reason from:
this may be erroneous.)

Daemon boot order is as recommended, i.e.

mount /proc/fs/nfsd
/usr/sbin/exportfs -ra
/usr/sbin/portmap -t /var/lib/portmap
/usr/sbin/rpc.mountd
/usr/sbin/rpc.statd --no-notify
/usr/sbin/rpc.nfsd 16
/usr/sbin/sm-notify

On the client, we have

/usr/sbin/portmap -t /var/lib/portmap
/usr/sbin/rpc.statd --no-notify
/usr/sbin/sm-notify

(then we mount away... and it often fails with -ESTALE)

The client and server are running identical kernels (from 2.6.34 to
2.6.35.5), and identical versions of the nfs-utils (seen with 1.2.2-rc7
up to tip-of-master). They're both nearly-identical 64-bit Nehalems (one
is an i7 920, the other an L5520) with bags of RAM (12Gb up, mostly
unused). All the filesystems being exported are ext4, all mounted with

defaults,nobarrier,relatime,nosuid,nodev,journal_async_commit,commit=30,user_xattr,acl

(yes, nobarrier is safe, the server has a battery-backed RAID array).

(Back in the day (pre-2.6.33) this problem wasn't present, and the
filesystems are all older than that, so I doubt it's purely FS-related.)


Debugging output from a failing rpc.mountd:

Sep 21 20:51:18 spindle info: v4root_create: path '/'
Sep 21 20:51:18 spindle info: v4root_create: path '/home'
Sep 21 20:51:18 spindle info: v4root_create: path '/'
Sep 21 20:51:18 spindle info: v4root_create: path '/home'
Sep 21 20:51:18 spindle info: v4root_create: path '/'
Sep 21 20:51:18 spindle info: v4root_create: path '/home'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail/nnmh'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Mail/nnmh'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix/Graphics'
Sep 21 20:51:18 local@spindle info: Last message 'v4root_create: path ' repeated 1 times, supressed by syslog-ng on spindle.srvr.nix
Sep 21 20:51:18 spindle info: v4root_create: path '/usr'
Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share'
Sep 21 20:51:18 spindle info: v4root_create: path '/pkg'
Sep 21 20:51:18 spindle info: v4root_create: path '/usr/lib'
Sep 21 20:51:18 spindle info: v4root_create: path '/usr/lib/X11'
Sep 21 20:51:18 spindle info: v4root_create: path '/var'
Sep 21 20:51:18 spindle info: v4root_create: path '/etc'
Sep 21 20:51:18 spindle info: v4root_create: path '/var/state'
Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share/httpd'
Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share/httpd/htdocs'
Sep 21 20:51:18 spindle info: v4root_create: path '/usr'
Sep 21 20:51:18 spindle info: v4root_create: path '/usr/share'
Sep 21 20:51:18 spindle info: v4root_create: path '/trees'
Sep 21 20:51:18 spindle info: v4root_create: path '/'
Sep 21 20:51:18 spindle info: v4root_create: path '/home'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix'
Sep 21 20:51:18 spindle info: v4root_create: path '/home/.spindle.srvr.nix/nix'
Sep 21 20:51:19 spindle notice: Version 1.2.2 starting
Sep 21 20:51:19 spindle warning: Flags: 
Sep 21 20:51:23 spindle notice: Version 1.2.2 starting

(now I started rebooting the client: I suspect this is unmounting
activity)

Sep 21 20:51:39 spindle info: auth_unix_ip: inbuf 'nfsd 192.168.16.20'
Sep 21 20:51:39 spindle info: auth_unix_ip: client 0x1f3dde0 'mutilate.wkstn.nix'
Sep 21 20:51:39 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x014000000000000095bd22c2253c456f8e36b6cfb9ecd4ef'
Sep 21 20:51:39 spindle info: nfsd_fh: found (nil) path (null)
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01400000000000000d948b1b8091d09c0000000000000000'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f316c0 path /home/.spindle.srvr.nix
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01c0000000000000b5cb6e6bed9d4345abd64535f56e2519'
Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x1ee00000000000006c0f7fa7d6c24054bff33a878460bdc7'
Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01200100000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x01a00000000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2f6e0 path /usr/doc
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x82650000000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2e6f0 path /usr/share/xemacs
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x85650000000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2e1a0 path /usr/share/xplanet
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x84510a00000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2ec40 path /usr/share/texlive
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \xe86d0800000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2d1b0 path /usr/lib/X11/fonts
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 6 \x07799ff5baef4492875dc73730d6149e'
Sep 21 20:51:42 spindle info: nfsd_fh: found (nil) path (null)
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 6 \x333950aa8e3f440abc94d0cc4adae198'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2bc70 path /usr/src
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x02a0080000000000b5cb6e6bed9d4345abd64535f56e2519'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2b720 path /var/state/munin
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \xaf750000000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2b1f0 path /usr/share/httpd/htdocs/munin
Sep 21 20:51:42 spindle info: nfsd_fh: inbuf 'mutilate.wkstn.nix 7 \x3d650000000000005cccc224a92440eeb44504473898c2ec'
Sep 21 20:51:42 spindle info: nfsd_fh: found 0x1f2ace0 path /usr/share/clamav

(client reboot underway. from here on, I'll only show one of the
filesystems that failed to mount, rather than all of them.)

Sep 21 20:51:53 mutilate info: Switching to runlevel: 6
Sep 21 20:52:56 spindle info: from_local: updating local if addr list
Sep 21 20:52:56 spindle info: from_local: checked 14 local if addrs; incoming address not found
Sep 21 20:52:56 spindle info: check_default: access by 192.168.16.20 ALLOWED
Sep 21 20:52:56 spindle info: Received NULL request from 192.168.16.20
Sep 21 20:52:56 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:56 spindle info: Received NULL request from 192.168.16.20
Sep 21 20:52:56 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:56 spindle info: Received MNT3(/home/.spindle.srvr.nix) request from 192.168.16.20
Sep 21 20:52:56 spindle notice: authenticated mount request from 192.168.16.20:673 for /home/.spindle.srvr.nix (/home/.spindle.srvr.nix)
[identical messages for all the other filesystems]
Sep 21 20:52:57 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:57 spindle info: Received NULL request from 192.168.16.20
Sep 21 20:52:57 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:57 spindle info: Received NULL request from 192.168.16.20
Sep 21 20:52:57 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:57 spindle info: Received MNT3(/home/.spindle.srvr.nix) request from 192.168.16.20
Sep 21 20:52:57 spindle notice: authenticated mount request from 192.168.16.20:976 for /home/.spindle.srvr.nix (/home/.spindle.srvr.nix)
[identical messages for the subset of those mounts that got -ESTALE]
Sep 21 20:52:59 spindle notice: authenticated mount request from 192.168.16.20:820 for /home/.spindle.srvr.nix (/home/.spindle.srvr.nix)
Sep 21 20:52:59 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:59 spindle info: Received NULL request from 192.168.16.20
Sep 21 20:52:59 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:59 spindle info: Received NULL request from 192.168.16.20
Sep 21 20:52:59 spindle info: check_default: access by 192.168.16.20 ALLOWED (cached)
Sep 21 20:52:59 spindle info: Received MNT3(/var/log.real) request from 192.168.16.20
[repeat forever]

which all looks fine to me apart from the way the mount persistently
fails despite the server saying it's OK.

Upon restart, it Just Works.

Any idea what the cause of this one might be? It's... mystifying. The
'fails only if just rebooted' part is particularly bizarre, as if
rpc.mountd *really* wants to start after rpc.nfsd or something.


I'll try a packet capture next (time to use --port, I guess).