Bug 60737 - NFS 'readdir loop' error on JFS
Summary: NFS 'readdir loop' error on JFS
Status: RESOLVED CODE_FIX
Alias: None
Product: File System
Classification: Unclassified
Component: JFS (show other bugs)
Hardware: x86-64 Linux
: P1 normal
Assignee: Dave Kleikamp
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-08-12 19:50 UTC by Christian Kujau
Modified: 2013-09-05 00:35 UTC (History)
4 users (show)

See Also:
Kernel Version: 3.11.0-rc5
Subsystem:
Regression: No
Bisected commit-id:


Attachments
set up file systems on the NFS server (2.05 KB, text/plain)
2013-08-12 19:50 UTC, Christian Kujau
Details
set up file systems on the NFS client (463 bytes, text/plain)
2013-08-12 19:50 UTC, Christian Kujau
Details
"tcpdump -s0 -w nfs.pcap" while running "find <DIR> -ls" on a directory producing those kernel messages (19.48 KB, application/octet-stream)
2013-08-12 19:56 UTC, Christian Kujau
Details
"tcpdump -s0 -w nfs_2.pcap" while running "find <DIR> -ls" on a directory producing those kernel messages (36.37 KB, application/octet-stream)
2013-08-12 21:48 UTC, Christian Kujau
Details
"tcpdump -s0 -w nfs_3.pcap" while running "find /mnt/disk_jfs/usr/share/terminfo/q/ -ls" (36.32 KB, application/octet-stream)
2013-08-14 23:14 UTC, Christian Kujau
Details
"tcpdump -s0 -w nfs_4.pcap" while running "find /mnt/disk_jfs/usr/share/terminfo/q/ -ls" (36.99 KB, application/octet-stream)
2013-08-14 23:56 UTC, Christian Kujau
Details
/var/log/messages from sid2 while mounting & running find (74.73 KB, text/plain)
2013-08-14 23:59 UTC, Christian Kujau
Details
jfs: avoid misuse of cookie value of 2 (4.13 KB, patch)
2013-08-15 03:47 UTC, Dave Kleikamp
Details | Diff
jfs: fix readdir cookie incompatibility with NFSv4 (3.05 KB, patch)
2013-08-15 20:42 UTC, Dave Kleikamp
Details | Diff

Description Christian Kujau 2013-08-12 19:50:28 UTC
Created attachment 107188 [details]
set up file systems on the NFS server

From the debian-kernel mailing list:

----------------
Jonathan McDowell and Karl Schmidt reported that when sharing a JFS
filesystem through NFS and Samba, NFS clients can report 'readdir loop'
and the directories in question then appear to have duplicate entries on
the client system.

This was seen with Linux 3.2 on the server and client.  The JFS
directory code is basically unchanged since then, but NFS has changed
somewhat.

The original bug reports were:
http://bugs.debian.org/685407#85
http://bugs.debian.org/714974

The log messages are:
[593351.877678] NFS: directory fs/nfsd contains a readdir loop.Please contact your server vendor.  The file: .nfs3proc.o.cmda.com has duplicate cookie 73
[593351.904689] NFS: directory fs/nfsd contains a readdir loop.Please contact your server vendor.  The file: .nfs3proc.o.cmda.com has duplicate cookie 73
[280774.570555] NFS: directory //accounting contains a readdir loop.Please contact your server vendor.  The file: .~lock.credit.rtf1.rtf# has duplicate cookie 199
----------------

Apparently only JFS seems to be affected now, test case for the server and the client is attached.

Bruce Fields mentioned:

----------------
It might be interesting to get a network trace (something like tcpdump
-s0 -wtmp.pcap; then "wireshark tmp.pcap" and look at the "cookie"
fields in the readdir calls and replies.  The server shouldn't return
the same one twice on one read through the directory.  And when the
client uses a cookie it should get the next entries, not
already-returned entries.)

You could also just run "strace -egetdents64 -v ls" on the server on
the exported filesystem, in a problem directory, and see if the offsets
are unique.
----------------

The pcap will be attached; lists only "getdents", not "getdents64", but maybe this test filesystem is too small (256MB) for this. However, "ls" on the server returns only unique offsets:

$ strace -egetdents -v ls /mnt/disk_jfs/usr/share/terminfo/q 2>&1 | egrep -o "d_off=[0-9]*" | sort | uniq -d
=> nothing
Comment 1 Christian Kujau 2013-08-12 19:50:53 UTC
Created attachment 107189 [details]
set up file systems on the NFS client
Comment 2 Christian Kujau 2013-08-12 19:56:36 UTC
Created attachment 107190 [details]
"tcpdump -s0 -w nfs.pcap" while running "find <DIR> -ls" on a directory producing those kernel messages
Comment 4 bfields 2013-08-12 21:13:19 UTC
(In reply to Christian Kujau from comment #2)
> Created attachment 107190 [details]
> "tcpdump -s0 -w nfs.pcap" while running "find <DIR> -ls" on a directory
> producing those kernel messages

There aren't any readdirs in there.  Maybe the directory contents are already cached--could you retry after unmounting and remounting the nfs filesystem?
Comment 5 Christian Kujau 2013-08-12 21:48:21 UTC
Created attachment 107196 [details]
"tcpdump -s0 -w nfs_2.pcap" while running "find <DIR> -ls" on a directory producing those kernel messages

I unmounted the NFS share on the client, unloaded the nfs/nfsv4 kernel module, did "sysctl -w vm.drop_caches=3" and mounted the share again, then ran "find /mnt/disk_jfs/usr/share/terminfo/q/ -ls", got two "readdir loop" messages. The share is mounted with:

sid2:/mnt/disk_jfs on /mnt/disk_jfs type nfs4 (rw,relatime,vers=4.0,rsize=8192,wsize=8192,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=192.168.0.137,local_lock=none,addr=192.168.0.138)
Comment 6 Dave Kleikamp 2013-08-14 21:17:03 UTC
Bruce,
I don't see duplicate cookies looking at the latest dump with wireshark. The readdir response looks good to me. I'd be happy to look at fixing anything in jfs if you can point out something I've missed.
Comment 7 bfields 2013-08-14 21:41:36 UTC
Yeah, I don't see the problem either: the trace has 3 pairs of readdirs, each pair consisting of one complete pass through the directory.  I checked the last pair quickly by hand and didn't see any repeats.  Spot-checking the others in a few places it looks to me like the same sequence of cookies is getting returned in each case.


Christian, do you have the exact "readdir loop" message from that run?  It probably wasn't the one from the original bug description since there's no cookie 73 in any of these replies.
Comment 8 Dave Kleikamp 2013-08-14 21:44:06 UTC
I checked the first two pairs of readdirs, and saw the same sequence of cookies. Didn't look as closely at the third, other than that it continued at the same cookie.
Comment 9 Trond Myklebust 2013-08-14 23:00:41 UTC
Another thing that you might want to check for is the use of cookie values
0, 1 or 2. Those 3 values are all reserved in NFSv4:
 - 0 - is used to rewind the readdir stream.
 - 1 and 2 are reserved for use as cookies for the "." and ".." entries on
   the client.

I know that at one point, Bryan was seeing looping due to JFS using cookie
values of 1 and 2, and nfsd passing those on verbatim to the NFS client.
Comment 10 Christian Kujau 2013-08-14 23:14:30 UTC
Created attachment 107202 [details]
"tcpdump -s0 -w nfs_3.pcap" while running "find /mnt/disk_jfs/usr/share/terminfo/q/ -ls"

Ran find over an affected directory on the NFS client and it produced 2 messages:

sid1$ find /mnt/disk_jfs/usr/share/terminfo/q/ -ls > find.ls
[  242.596777] NFS: directory terminfo/q contains a readdir loop.Please contact your server vendor.  The file: qvt119 has duplicate cookie 13
[  242.598224] NFS: directory terminfo/q contains a readdir loop.Please contact your server vendor.  The file: qvt119 has duplicate cookie 13

And the output from "find" doesn't look good too (non-unique inode numbers):

----------------------
sid1# sort -n find.ls | tail
   624    4 -rw-r--r--   1 root     root          586 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt101+
   626    0 lrwxrwxrwx   1 root     root            9 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt119-w -> qvt119+-w
   626    0 lrwxrwxrwx   1 root     root            9 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt119-w -> qvt119+-w
   626    0 lrwxrwxrwx   1 root     root            9 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt119-w -> qvt119+-w
   626    0 lrwxrwxrwx   1 root     root            9 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt119-w -> qvt119+-w
   627    0 lrwxrwxrwx   1 root     root            6 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt108 -> qvt101
   627    0 lrwxrwxrwx   1 root     root            6 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt108 -> qvt101
   627    0 lrwxrwxrwx   1 root     root            6 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt108 -> qvt101
   627    0 lrwxrwxrwx   1 root     root            6 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt108 -> qvt101
   627    0 lrwxrwxrwx   1 root     root            6 Jun 27  2012 /mnt/disk_jfs/usr/share/terminfo/q/qvt108 -> qvt101
----------------------
Comment 11 Christian Kujau 2013-08-14 23:56:33 UTC
Created attachment 107203 [details]
"tcpdump -s0 -w nfs_4.pcap" while running "find /mnt/disk_jfs/usr/share/terminfo/q/ -ls"

Sorry for the noise, I ran "find" over this directory again (after umount/mount) and had CONFIG_JFS_DEBUG=y and CONFIG_JFS_STATISTICS=y on the server and set /proc/fs/jfs/loglevel=4 (which, according to fs/jfs/jfs_debug.h is for "INFO" while 3 would is for DEBUG?), will attach that log also.
Comment 12 Christian Kujau 2013-08-14 23:59:36 UTC
Created attachment 107204 [details]
/var/log/messages from sid2 while mounting & running find

 1707  2013-08-14 16:48:56 mount -t nfs sid2:/mnt/disk_jfs /mnt/disk_jfs/
 1710  2013-08-14 16:49:52 find /mnt/disk_jfs/usr/share/terminfo/q/ -ls > find.ls
Comment 13 Christian Kujau 2013-08-15 00:01:39 UTC
Forgot the log from the client (sid1) for the last run (nfs_4.pcap):

Aug 14 16:49:53 sid1 kernel: [ 2711.000378] NFS: directory terminfo/q contains a readdir loop.Please contact your server vendor.  The file: qvt119ms/virtual/bdi/0:18 has duplicate cookie 13
Aug 14 16:49:53 sid1 kernel: [ 2711.002679] NFS: directory terminfo/q contains a readdir loop.Please contact your server vendor.  The file: qvt119ms/virtual/bdi/0:18 has duplicate cookie 13
Comment 14 Dave Kleikamp 2013-08-15 02:54:05 UTC
(In reply to Trond Myklebust from comment #9)
> Another thing that you might want to check for is the use of cookie values
> 0, 1 or 2. Those 3 values are all reserved in NFSv4:
>  - 0 - is used to rewind the readdir stream.
>  - 1 and 2 are reserved for use as cookies for the "." and ".." entries on
>    the client.
> 
> I know that at one point, Bryan was seeing looping due to JFS using cookie
> values of 1 and 2, and nfsd passing those on verbatim to the NFS client.

That may be a problem. JFS uses 0 and 1 for "." and ".." and 2 for the first entry created. Let me see if fixing that helps.
Comment 15 Dave Kleikamp 2013-08-15 03:47:32 UTC
Created attachment 107208 [details]
jfs: avoid misuse of cookie value of 2

This lightly-tested patch seems to fix the problem. I'll test it more thoroughly tomorrow.
Comment 16 Dave Kleikamp 2013-08-15 20:42:58 UTC
Created attachment 107210 [details]
jfs: fix readdir cookie incompatibility with NFSv4

First, sorry for missed close brace in the previous patch.

Second, I came up with a simpler patch that I like a little better.
Comment 17 Dave Kleikamp 2013-08-16 16:07:07 UTC
The patch has been pushed to linux-next. I will push it to mainline and the stable tree soon.

Note You need to log in before you can comment on or make changes to this bug.