On Sun, Jan 27, 2008 at 11:37:59PM -0500, Erez Zadok wrote:
> In message <[EMAIL PROTECTED]>, "J. Bruce Fields" writes:
> > On Mon, Jan 21, 2008 at 05:08:28PM -0500, bfields wrote:
> > > On Mon, Jan 21, 2008 at 03:28:51PM -0500, Erez Zadok wrote:
> > > >
> > > > Here you go. See the tcpdump in here:
> > > >
> > > > http://agora.fsl.cs.sunysb.edu/tmp/nfs/
> > > >
> > > > I captured it on an x86_64 machine using
> > > >
> > > > tcpdump -s 0 -i lo -w tcpdump2
> > > >
> > > > And it shows near the very end the ESTALE error.
> > >
> > > Yep, thanks! So frame 107855 has the MNT reply that returns the
> > > filehandle in question, which is used in an ACCESS call in frame 107855
> > > that gets an ESTALE. Looks like an unhappy server!
> > >
> > > > Do you think this could be related to nfs-utils? I find that I can
> > > > easily
> > > > trigger this problem on an FC7 machine with nfs-utils-1.1.0-4.fc7
> > > > (within
> > > > 10-30 runs of the above loop); but so far I cannot trigger the problem
> > > > on an
> > > > FC6 machine with nfs-utils-1.0.10-14.fc6 (even after 300+ runs of the
> > > > above
> > > > loop).
> > >
> > > Yes, it's quite likely, though on a quick skim through the git logs I
> > > don't see an obviously related commit...
> >
> > It might help to turn on rpc cache debugging:
> >
> > echo 2048 >/proc/sys/sunrpc/rpc_debug
> >
> > and then capture the contents of the /proc/net/rpc/*/content files just
> > after the failure.
> >
> > Possibly even better, though it'll produce a lot of stuff:
> >
> > strace -p `pidof rpc.mountd` -s4096 -otmp
> >
> > and then pass along "tmp".
>
> You can find both an strace and content files in
>
> http://agora.fsl.cs.sunysb.edu/tmp/nfs/
The "content" files are all empty. That can't be right....
But anyway the strace does show a problem: grepping for reads and
writes to fd 5, which (based on the traffic) must be
/proc/net/rpc/nfsd.fh/channel, what you see is the kernel repeatedly
asking whether the server has exported a filesystem with a given uuid
(the big hex blob) to localhost.localdomain. And mountd responds with
an export each time:....
1295 read(5, "localhost.localdomain 6 \\x2527c026ed8b49b6a2138c0ef212af45\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x2527c026ed8b49b6a2138c0ef212af45
2147483647 /n/export/b5 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x4a5b1c28abc84cc3abd6e072738b2418\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x4a5b1c28abc84cc3abd6e072738b2418
2147483647 /n/export/b6 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x46177ac6944a41fda30a0cfb7adf0694\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x46177ac6944a41fda30a0cfb7adf0694
2147483647 /n/export/b0 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x040be43d3d2a4433979d321ac075f6e5\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x040be43d3d2a4433979d321ac075f6e5
2147483647 /n/export/b1 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\xeac197ca26b444eeaf67c1f6cd92c24b\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\xeac197ca26b444eeaf67c1f6cd92c24b
2147483647 /n/export/b2 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x8e07ea5612584a19ba209780971f3221\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x8e07ea5612584a19ba209780971f3221
2147483647 /n/export/b3 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\xa509393cc478496a9c0eec09681a5033\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\xa509393cc478496a9c0eec09681a5033
2147483647 /n/export/b4 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x46177ac6944a41fda30a0cfb7adf0694\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x46177ac6944a41fda30a0cfb7adf0694
2147483647 /n/export/b0 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x040be43d3d2a4433979d321ac075f6e5\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x040be43d3d2a4433979d321ac075f6e5
2147483647 /n/export/b1 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\xeac197ca26b444eeaf67c1f6cd92c24b\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\xeac197ca26b444eeaf67c1f6cd92c24b
2147483647 /n/export/b2 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x8e07ea5612584a19ba209780971f3221\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x8e07ea5612584a19ba209780971f3221
2147483647 /n/export/b3 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\xa509393cc478496a9c0eec09681a5033\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\xa509393cc478496a9c0eec09681a5033
2147483647 /n/export/b4 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\xb97fa10332784bd2848a979af256ec61\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\xb97fa10332784bd2848a979af256ec61
2147483647 /n/export/b5 \n", 84) = 84
1295 read(5, "localhost.localdomain 6 \\x27a0f76db3fe44198a82d6370c63383f\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x27a0f76db3fe44198a82d6370c63383f
2147483647 /n/export/b6 \n", 84) = 84
.... except the last:
1295 read(5, "localhost.localdomain 6 \\x46177ac6944a41fda30a0cfb7adf0694\n",
128) = 59
1295 write(5, "localhost.localdomain 6 \\x46177ac6944a41fda30a0cfb7adf0694
2147483647 \n", 71) = 71
Here suddenly it's claiming there is no such export, even though it
actually identified it as /n/export/b0 just above.
What this means is that "found" is false in the check:
if (found)
qword_print(f, found_path);
at the end of nfs-utils/utils/mountd/cache.c:nfsd_fh(). Note that we're
in the FSID_UUID16_INUM case (that's the "6" in the reads and writes
above.
Anyway, it's clearly a bug in mountd someplace. Maybe in the blkid
library. Maybe a comparison of the strace leading up to the two results
would yield something?
I'm out of steam....
--b.
>
> > And then of course if the regression is in nfs-utils then there's always
> > a git-bisect as the debugging tool of last-resort: assuming you can
> > reproduce the same regression between nfs-utils-1-0-10 and
> > nfs-utils-1-1-0 from git://linux-nfs.org/nfs-utils, then all you'd need
> > to do is clone that repo and do
> >
> > git bisect start
> > git bisect good nfs-utils-1-0-10
> > git bisect bad nfs-utils-1-1-0
> >
> > And it shouldn't take more than 8 tries.
> >
> > Sorry for not having any more clever suggestions....
> >
> > --b.
>
> I tried to bisect nfs-utils but it didn't work. First, the latest version
> of nfs-utils didn't configure for me. It complained
>
> Unable to locate information required to use librpcsecgss. If you
> have pkgconfig installed, you might try setting environment variable
> PKG_CONFIG_PATH to /usr/local/lib/pkgconfig
>
> The above appears to be an error if you don't have librpcsecgss API >=
> 0.10. But mine, on FC7. is 0.11. (I'm using a vanilla FC7.)
>
> So I ran configure --disable-gss and was finally able to build the utils.
> But then, I was having mount.nfs hanging often; stracing it revealed that
> mount(2) was getting EACESS as if the dir wasn't exported (but exportfs said
> it was). I don't know if disabling gss at configure time could have
> resulted in these hangs.
>
> I continued and tried a few more intermediate versions in the bisection, and
> several of them failed to compile and/or configure and/or autogen.sh.
>
> So I don't know what else I can do; this bug may have to be fixed the hard
> way. (BTW, I can get you a self contained VMware image that'll show the
> bug, if you'd like.)
>
> Cheers,
> Erez.
-
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
