Is there nothing that can be done?  This is incredibly annoying.

I see nothing in that log that shows why the hang happens... 

Would it be possible to see what is, if anything, going over the wire?

Created attachment 1481270 [details]
tcpdump packet capture during the hang

Is it sufficient to capture everything going over port 2049/tcp?
If so then please see attached (it's a tcpdump packet capture file,
use “tcpdump -r log” to view).

It appears the client is trying to read a directory
that as a lot of files... Is that the case?

I should note that even stat-ing the directory causes the
hang.  The directory has quite a few files:

$ ls /mnt/scratch | wc -l
316

but I guess it's not that many ...

(In reply to Richard W.M. Jones from comment #5)
> I should note that even stat-ing the directory causes the
> hang.  The directory has quite a few files:
> 
> $ ls /mnt/scratch | wc -l
> 316
> 
> but I guess it's not that many ...

I agree... That is not many...

What are the mount options?

Who is the server (I'm assuming f28 is the client)?  

Does the nordirplus option help or hurt?

Does the same thing happen with v3?

The mount options specified in fstab are hard,intr

However those translate into quite a long list (presumably util-linux
or the kernel invents most of these):

onuma:/mnt/scratch on /mnt/scratch type nfs4 (rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.0.128,local_lock=none,addr=192.168.0.249)

Server is RHEL 6.9 (nfs-utils-1.2.3-75.el6.x86_64).

I don't have any way to test v3 since setting it up is a massive PITA
and incompatible with firewalling here.

This has worked since forever, with many many different clients, it
just started hanging recently, and only from this single client.

By the way, there is a second mount from the same server to the same
client which does *not* hang.  I didn't really pay attention to it before
because I rarely use it.

When I tried the mount command with nodirplus it failed in a very odd way:

# mount -t nfs -o hard,intr,nodirplus onuma:/mnt/scratch /mnt/scratch
mount.nfs: No route to host

But I can still ping the server and list files on the second mountpoint.

Pretty sure this is something to do with DNS as outlined in comment 0.

Removing nodirplus means I can mount it fine again.

That nodirplus thing makes no sense.  If DNS or some other networking is unreliable maybe that's randomly causing the mount to fail and the mount option is an accident.  Or maybe there's some reason the new mount is able to piggyback off an existing one when the mount options are the same avoiding the need for a DNS lookup and a new connection.

Are the logs in comment 0 from the NFS client or the NFS server?

readdir will need to do idmapping on both client and server.  On the server results from idmapd queries are cached 10 minutes, so a problem there might be about right to cause 5-10 minute hangs.  I'm not sure about the client.

Might be interesting to figure out how exactly ids get mapped to an from names on your system.  Or to compare /etc/idmapd.conf across server and working clients.  Or maybe strace idmapd.conf and see if something's hanging there.

/proc/net/rpc/nfs4.idtoname/content can tell you something about the status of nfsd upcalls to idmapd, a little more if you run "rpcdebug -m rpc -s cache" first.

Comment 0 is from the client.

DNS is fine on this network, and the NFS server has dozens of
other clients (including the same client / different mount!)
which have no problems.  Also this NFS server has been going
for years.

Having said that idmap / username mapping has never worked right
on any NFS v4 server I've configured, including this one.  I wish
there was a Just Work option for it.  All the files appear as
nobody.nobody on every client.

On the client:

$ cat /proc/net/rpc/nfs4.idtoname/content
cat: /proc/net/rpc/nfs4.idtoname/content: No such file or directory
$ cat /proc/net/rpc/nfs 
net 0 0 0 0
rpc 87721 3 87729
proc4 61 7 26927 1352 29 2067 23 0 18 2029 96 12 48710 4 4 147 54 41 346 2974 307 3 133 0 0 0 0 9 550 0 1839 21 0 0 0 0 15 0 0 6 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0

On the server:

# rpcdebug -m rpc -s cache
rpc        cache

# cat /proc/net/rpc/nfs4.idtoname/content
#domain type id [name]
# expiry=1536692544 refcnt=1 flags=1
* user 1000 rjones.org
# expiry=1536692544 refcnt=1 flags=1
* group 1000 rjones.org
# expiry=1536692544 refcnt=1 flags=1
* group 0 root.org
# expiry=1536692544 refcnt=1 flags=1
* user 0 root.org
# expiry=1536692297 refcnt=1 flags=1
* user 65534 nfsnobody.org
# expiry=1536692297 refcnt=1 flags=1
* group 65534 nfsnobody.org

(In reply to Richard W.M. Jones from comment #10)
> Having said that idmap / username mapping has never worked right
> on any NFS v4 server I've configured, including this one.  I wish
> there was a Just Work option for it.

For what it's worth, recent servers and clients default to using numeric uid's and gid's in the non-krb5 case, so if your setup Just Works for v3 it should for v4 as well.  But I think you'd need RHEL7 on the server for that.

Thanks for that output, I don't see any obvious explanation.

From a quick skim of the packet trace you supplied, it also looks to me like the server is responding quickly without any odd errors.

My theory that it's the server hanging in idmapping code doesn't look too likely.

I don't know.  I might strace the stat or ls process and verify that it's hanging in that system call, then do a sysrq-t dump or something to check what the kernel stack of the hung process.

There might be some idmapping hang on the client, I'm not sure how to recommend debugging that off the top of my head.

It's certainly hanging in stat(2):

1536702944.932908 stat("/mnt/scratch/",

[hangs here .. then]

                                         {st_mode=S_IFDIR|0777, st_size=45056, ...}) = 0
1536702995.240216 openat(AT_FDCWD, "/mnt/scratch/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
1536702995.247431 fstat(3, {st_mode=S_IFDIR|0777, st_size=45056, ...}) = 0

I'll see if I can get the kernel stack somehow.

Created attachment 1482477 [details]
sysrq t output

I'm not sure I understand how to read this.  Anyway the 'ls' command
is hung on the NFS mountpoint, and it should include a full stack
trace from that command.  There are a few other nfs* commands in
there too which might be interesting.

Oh, that is interesting, thanks.  Interesting snippets of the kernel stack of the 'ls':

[3029164.738696] ls              D    0 17191  17156 0x00000000
...
[3029164.738719]  call_usermodehelper_exec+0x12e/0x160
...
[3029164.738736]  request_key+0x3c/0x80
[3029164.738755]  nfs_idmap_get_key+0xac/0x1d0 [nfsv4]
[3029164.738771]  nfs_idmap_lookup_id+0x30/0x80 [nfsv4]
[3029164.738785]  nfs_map_name_to_uid+0x6a/0x110 [nfsv4]
[3029164.738796]  decode_getfattr_attrs+0xe12/0x10e0 [nfsv4]
...
[3029164.738945]  nfs4_proc_getattr+0x6c/0x100 [nfsv4]
...
[3029164.738971]  vfs_statx+0x89/0xe0
[3029164.738973]  __do_sys_newstat+0x39/0x70
[3029164.738976]  do_syscall_64+0x5b/0x160

So, yes, it's hung in a 'stat' sycall trying to resolve the name returned in an NFSv4 getattr result to an id, by running nfsidmap.

There's a man page nfsidmap(5) that explains what that command does.  Note as with idmapd on the server side, its results also have a default 10 minute timeout, so at a guess this hang is happening each time that time outs and the client has to make another upcall.  Looks like it also has a -v option.  I don't think there's a way to control how the kernel invokes it, so I think in the past I've debugged problems like this by moving /usr/sbin/nfsidmap somewhere else and replacing it by a shell script that adds debugging arguments and/or logs some output of its own before calling the "real" (moved) nfsidmap.

This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Fedora 28 changed to end-of-life (EOL) status on 2019-05-28. Fedora 28 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.