Description of problem: Fedora 16 kernels more recent than 3.3.7 are causing us problems when acting as an NFS4 sec=sys,root_no_squash client to a RHEL 6.2 and/or RHEL 6.3 server. In particular, about 80% of the users and groups show up as 4294967294 in a ls -l of the NFS mount, even though all the uids and gids show up properly on the file server. The users and groups who show up as 4294967294 does not appear to be consistent between reboots of the client. On the server, I am seeing messages of the form rpc.idmapd[954]: nss_getpwnam: name '8011' not found in domain 'arlut.utexas.edu' where 8011 is a uid or gid. /etc/idmapd.conf is identical on the server and the client. I have tried this with the last two versions of the nfs-utils package, as well as the libnfsidmap package in Fedora 16 Testing Updates. There is no observed difference in behavior, but rolling back the client to the 3.3.7 kernel package makes things work again. From doing a wireshark examination of the NFS packets, it appears that 3.3.7 is sending proper names (user.edu) in the packets, while 3.4.2 and later are sending uids and gids instead. Version-Release number of selected component (if applicable): 3.4.2, 3.4.3, 3.4.4
I misspoke. kernel-3.3.7-1.fc16.x86_64 and kernel-3.3.8-1.fc16.x86_64, kernel-3.4.2-1.fc16.x86_64 and kernel-3.4.4-3.fc16 from testing updates do not.
Er, kernel-3.3.7-1.fc16.x86_64 and kernel-3.3.8-1.fc16.x86_64 work. kernel-3.4.2-1.fc16.x86_64 and kernel-3.4.4-3.fc16 do not.
Perhaps this is really the following rhel 6.2 / 6.3 bug? https://bugzilla.redhat.com/show_bug.cgi?id=823848
Er, no, bug #823848 is a RHEL client bug, not a RHEL server bug, never mind. Obviously, Fedora started sending raw uids/gids for nfs4 sec=sys in the 3.4 kernels, based on the work discussed in https://lkml.org/lkml/2012/1/9/384 I'm guessing this is a RHEL 6.3 bug, but I haven't done a start to finish wireshark analysis to make sure that Fedora is being sensible on its end.
I'm a little confused by your description of the problem: "On the server, I am seeing messages of the form rpc.idmapd[954]: nss_getpwnam: name '8011' not found in domain 'arlut.utexas.edu'" That suggests that the server was having trouble mapping something sent to it by the client, for example when the client did a chown or setacl. But elsewhere you describe the problem as being with "ls -l", which would concern mapping of names being sent from server to client. So, when you say certain kernels work or don't work--are you varying the client kernel, the server kernel, or both? And when you say that "3.3.7 is sending proper names"--are you talking about setattr call,s or getattr replies? I assume the latter, and the quoted rpc.idmapd message was actually from the client not the server? In which case: does turning off the nfsd.nfs4_disable_idmapping module parameter on the server fix the problem?
"I'm a little confused by your description of the problem:" Sure. ""On the server, I am seeing messages of the form rpc.idmapd[954]: nss_getpwnam: name '8011' not found in domain 'arlut.utexas.edu'" That suggests that the server was having trouble mapping something sent to it by the client, for example when the client did a chown or setacl. But elsewhere you describe the problem as being with "ls -l", which would concern mapping of names being sent from server to client." I agree. However, I am seeing both. "So, when you say certain kernels work or don't work--are you varying the client kernel, the server kernel, or both?" I have tried the four Fedora kernels mentioned above on the client, and I have seen the same problem both before and after updating the server from the latest 6.2 RPMs to the latest 6.3 ones. "And when you say that "3.3.7 is sending proper names"--are you talking about setattr call,s or getattr replies? I assume the latter, and the quoted rpc.idmapd message was actually from the client not the server?" No, I'm talking about calls from the client to the server. I.e., setattr call, open, lock, etc. Not the getattr replies. The rpc.idmapd message is from the server, not the client. On the client, I see stuff like this: Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: libnfsidmap: using domain: ARLUT.UTEXAS.EDU Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: libnfsidmap: Realms list: 'ARLUT.UTEXAS.EDU' Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: libnfsidmap: processing 'Method' list Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: rpc.idmapd: libnfsidmap: using domain: ARLUT.UTEXAS.EDU Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: libnfsidmap: loaded plugin /lib64/libnfsidmap/nsswitch.so for method nsswitch Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: rpc.idmapd: libnfsidmap: Realms list: 'ARLUT.UTEXAS.EDU' Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: rpc.idmapd: libnfsidmap: processing 'Method' list Jul 5 15:51:20 xportal1 rpc.idmapd[78542]: rpc.idmapd: libnfsidmap: loaded plugin /lib64/libnfsidmap/nsswitch.so for method nsswitch Jul 5 15:51:20 xportal1 rpc.idmapd[78543]: Expiration time is 600 seconds. Jul 5 15:51:20 xportal1 rpc.idmapd[78543]: nfsdopenone: Opening /proc/net/rpc/nfs4.nametoid/channel failed: errno 2 (No such file or directory) Jul 5 15:51:20 xportal1 rpc.idmapd[78543]: New client: 6 Jul 5 15:51:20 xportal1 rpc.idmapd[78543]: Opened /var/lib/nfs/rpc_pipefs//nfs/clnt6/idmap Jul 5 15:51:20 xportal1 rpc.idmapd[78543]: New client: 7 "In which case: does turning off the nfsd.nfs4_disable_idmapping module parameter on the server fix the problem?" I'm afraid I won't be able to try that until after hours this evening.
I should mention that we had previously been seeing the system in an unstable configuration, seemingly due to the leap second bug. During the time we were struggling with that, I saw instances of the following in the logs: Jul 2 12:39:19 xportal1 kernel: [ 1986.307232] IP: [<ffffffff81262776>] __key_link_end+0x16/0x90 Jul 2 12:39:19 xportal1 kernel: [ 1986.307258] PGD 0 Jul 2 12:39:19 xportal1 kernel: [ 1986.307267] Oops: 0000 [#1] SMP Jul 2 12:39:19 xportal1 kernel: [ 1986.307282] CPU 16 Jul 2 12:39:19 xportal1 kernel: [ 1986.307289] Modules linked in: nfs fscache auth_rpcgss nfs_acl lockd ip6t_REJECT nf_conntrack_ipv6 nf_conntrack_ipv4 nf_defrag_ipv6 nf_defrag_ipv4 xt_state ip6table_filter nf_conntrack ip6_tables serio_raw coretemp dcdbas microcode uinpu\ t iTCO_wdt i7core_edac iTCO_vendor_support ixgbe ses edac_core dca enclosure mdio acpi_power_meter bnx2 sunrpc crc32c_intel ghash_clmulni_intel megaraid_sas [last unloaded: scsi_wait_scan] Jul 2 12:39:19 xportal1 kernel: [ 1986.307458] Jul 2 12:39:19 xportal1 kernel: [ 1986.307464] Pid: 1691, comm: rpc.idmapd Not tainted 3.4.2-1.fc16.x86_64 #1 Dell Inc. PowerEdge R810/0TT6JF Jul 2 12:39:19 xportal1 kernel: [ 1986.307494] RIP: 0010:[<ffffffff81262776>] [<ffffffff81262776>] __key_link_end+0x16/0x90 Jul 2 12:39:19 xportal1 kernel: [ 1986.307517] RSP: 0018:ffff88101955dd68 EFLAGS: 00010202 Jul 2 12:39:19 xportal1 kernel: [ 1986.307531] RAX: 00000000fffffff0 RBX: ffff881027bfaf00 RCX: ffff881027bfaf00 Jul 2 12:39:19 xportal1 kernel: [ 1986.307548] RDX: 0000000000000001 RSI: 0000070100000701 RDI: ffff881027bfaf00 Jul 2 12:39:19 xportal1 kernel: [ 1986.307565] RBP: ffff88101955dd88 R08: ffff880f4172dec0 R09: ffff88101955ddb0 Jul 2 12:39:19 xportal1 kernel: [ 1986.307641] R10: 000000000000000a R11: 0000000000000246 R12: ffff881027bfaf00 Jul 2 12:39:19 xportal1 kernel: [ 1986.307715] R13: 0000000000000006 R14: ffff88101955de75 R15: ffff880f4172dec0 Jul 2 12:39:19 xportal1 kernel: [ 1986.307794] FS: 00007f39644c7700(0000) GS:ffff88103f900000(0000) knlGS:0000000000000000 Jul 2 12:39:19 xportal1 kernel: [ 1986.307934] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Jul 2 12:39:19 xportal1 kernel: [ 1986.308009] CR2: 0000070100000701 CR3: 0000001019506000 CR4: 00000000000007e0 Jul 2 12:39:19 xportal1 kernel: [ 1986.308082] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Jul 2 12:39:19 xportal1 kernel: [ 1986.308157] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Jul 2 12:39:19 xportal1 kernel: [ 1986.308234] Process rpc.idmapd (pid: 1691, threadinfo ffff88101955c000, task ffff88101a3c5c40) Jul 2 12:39:19 xportal1 kernel: [ 1986.308369] Stack: Jul 2 12:39:19 xportal1 kernel: [ 1986.308435] ffff881027bfaf00 0000000000000006 ffff88101955de75 ffff880eb67ba580 Jul 2 12:39:19 xportal1 kernel: [ 1986.308574] ffff88101955ddd8 ffffffff81260996 ffff88101955dde8 ffff880ffffffff0 Jul 2 12:39:19 xportal1 kernel: [ 1986.308714] ffff881000000040 0000000000000001 ffff8810224f31d0 ffff880eb67ba570 Jul 2 12:39:19 xportal1 kernel: [ 1986.308860] Call Trace: Jul 2 12:39:19 xportal1 kernel: [ 1986.308930] [<ffffffff81260996>] key_instantiate_and_link+0x76/0xa0 Jul 2 12:39:19 xportal1 kernel: [ 1986.309028] [<ffffffffa01dd62b>] idmap_pipe_downcall+0x1cb/0x1e0 [nfs] Jul 2 12:39:19 xportal1 kernel: [ 1986.309120] [<ffffffffa004af57>] rpc_pipe_write+0x67/0x90 [sunrpc] Jul 2 12:39:19 xportal1 kernel: [ 1986.309198] [<ffffffff8117f833>] vfs_write+0xb3/0x180 Jul 2 12:39:19 xportal1 kernel: [ 1986.309272] [<ffffffff8117fb5a>] sys_write+0x4a/0x90 Jul 2 12:39:19 xportal1 kernel: [ 1986.309351] [<ffffffff815f92ce>] ? do_device_not_available+0xe/0x10 Jul 2 12:39:19 xportal1 kernel: [ 1986.309427] [<ffffffff81600329>] system_call_fastpath+0x16/0x1b Jul 2 12:39:19 xportal1 kernel: [ 1986.309499] Code: c3 0f 1f 40 00 0f b7 50 12 48 89 74 d0 18 66 83 40 12 01 5d c3 55 48 89 e5 53 48 83 ec 18 66 66 66 66 90 48 85 f6 48 89 fb 74 70 <48> 83 3e 00 74 6c 48 81 fe e0 fe c5 81 74 4b 48 85 d2 74 11 f6 Jul 2 12:39:19 xportal1 kernel: [ 1986.309849] RIP [<ffffffff81262776>] __key_link_end+0x16/0x90 Jul 2 12:39:19 xportal1 kernel: [ 1986.309924] RSP <ffff88101955dd68> Jul 2 12:39:19 xportal1 kernel: [ 1986.309992] CR2: 0000070100000701 Jul 2 12:39:19 xportal1 kernel: [ 1986.310541] ---[ end trace 04ea72096ca295e7 ]--- So perhaps it is possible that rpc.idmapd left part of the system in an inconsistent state, wrt /proc/net/rpc/nfs4.nametoid/channel?
After reverting back to kernel-3.3.8-1.fc16.x86_64, the rpc.idmapd startup looks like this: Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: libnfsidmap: using domain: ARLUT.UTEXAS.EDU Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: libnfsidmap: Realms list: 'ARLUT.UTEXAS.EDU' Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: libnfsidmap: processing 'Method' list Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: libnfsidmap: loaded plugin /lib64/libnfsidmap/nsswitch.so for method nsswitch Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: rpc.idmapd: libnfsidmap: using domain: ARLUT.UTEXAS.EDU Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: rpc.idmapd: libnfsidmap: Realms list: 'ARLUT.UTEXAS.EDU' Jul 6 00:29:55 xportal1 rpc.idmapd[1596]: Expiration time is 600 seconds. Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: rpc.idmapd: libnfsidmap: processing 'Method' list Jul 6 00:29:55 xportal1 rpc.idmapd[1596]: nfsdopenone: Opening /proc/net/rpc/nfs4.nametoid/channel failed: errno 2 (No such file or directory) Jul 6 00:29:55 xportal1 rpc.idmapd[1592]: rpc.idmapd: libnfsidmap: loaded plugin /lib64/libnfsidmap/nsswitch.so for method nsswitch
With no mention of /var/lib/nfs/rpc_pipefs//nfs/clnt6/idmap in the latter case.
Finally, I should note that I have a pair of twin Fedora 16 clients behaving in this way, so it's not something limited to one system.
Ah, and in response to the abrts in rpc.imapd, above, I did edit /etc/request-key.conf to add the line create id_resolver * * /usr/sbin/nfsidmap -v -v -t 600 %k %d as the second line in the file, just after create dns_resolver * * /sbin/key.dns_resolver %k this seemed to stop the rpc.imapd abrts.
Gah, sorry, I've been the worst possible bug reporter on this. We were running under kernel-3.3.8-1.fc16.x86_64, and we got hit by the leap second bug. At that point, I upgraded to kernel-3.4.2-1.fc16.x86_64 and started seeing the abrt from rpc.idmapd. At that point I edited /etc/request-key.conf, which stopped the abrts, but left us with the idmapping misbehavior. I then rolled back to kernel-3.3.8-1.fc16.x86_64 and things are now operational, with /etc/request-key.conf as above.
I can arrange to upgrade to the kernel-3.4.4-3.fc16 in testing and undo my edit to /etc/request-key.conf, to see if the abrt still persists.
(In reply to comment #7) > During the time we were struggling with that, I saw instances of the > following in the logs: > > > Jul 2 12:39:19 xportal1 kernel: [ 1986.307232] IP: [<ffffffff81262776>] > __key_link_end+0x16/0x90 ... That doesn't look familiar. Was there anything in the logs just before this line? (I'd normally expect another line or two of explanation before this.) Also, was this the very first such backtrace in the logs?
Ups, sorry, I left the line above it off: Jul 2 12:39:19 xportal1 kernel: [ 1986.307206] BUG: unable to handle kernel paging request at 0000070100000701 And yes, this was the first.
Ref lkml: https://lkml.org/lkml/2012/6/1/67
Looks like that was fixed upstream by b1027439dff8446 "NFS: Force the legacy idmapper to be single threaded".
I couldn't find that in either Linus' or the Linux-nfs git repos. From the lkml discussion, it seemed that putting the id_resolver line in /etc/request-key.conf should have worked around the multithreaded problem with idmapper. Is there perhaps a second issue here with the /usr/sbin/nfsidmap upcall program, or did the NFS patch fix something that impinges on the use of id_resolver?
FWIW I'm seeing this too on fedora 16 with, Linux zorg 3.4.4-4.fc16.x86_64 #1 SMP Thu Jul 5 20:01:38 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux Jul 13 20:53:31 zorg kernel: [131167.121578] Pid: 1054, comm: rpc.idmapd Not tainted 3.4.4-4.fc16.x86_64 #1 Acer Aspire Z5700/Aspire Z5700 Jul 13 20:53:31 zorg kernel: [131167.121615] RIP: 0010:[<ffffffff81266746>] [<ffffffff81266746>] __key_link_end+0x16/0x90 Jul 13 20:53:31 zorg kernel: [131167.121646] RSP: 0018:ffff8801b3721d68 EFLAGS: 00010202 Jul 13 20:53:31 zorg kernel: [131167.121665] RAX: 00000000fffffff0 RBX: ffff880196df9f00 RCX: ffff880196df9f00 Jul 13 20:53:31 zorg kernel: [131167.121689] RDX: 0000000000000001 RSI: 0000079100000791 RDI: ffff880196df9f00 Jul 13 20:53:31 zorg kernel: [131167.121713] RBP: ffff8801b3721d88 R08: 0000000100000034 R09: ffff8801b3721db0 Jul 13 20:53:31 zorg kernel: [131167.121737] R10: 000000000000000a R11: 0000000000000246 R12: ffff880196df9f00 Jul 13 20:53:31 zorg kernel: [131167.121760] R13: 0000000000000005 R14: ffff8801b3721e75 R15: 0000000100000034 Jul 13 20:53:31 zorg kernel: [131167.121784] FS: 00007f38f4fd3700(0000) GS:ffff8801bfc40000(0000) knlGS:0000000000000000 Jul 13 20:53:31 zorg kernel: [131167.121810] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Jul 13 20:53:31 zorg kernel: [131167.121829] CR2: 0000079100000791 CR3: 00000001978ff000 CR4: 00000000000007e0 Jul 13 20:53:31 zorg kernel: [131167.121853] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Jul 13 20:53:31 zorg kernel: [131167.121877] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Jul 13 20:53:31 zorg kernel: [131167.121901] Process rpc.idmapd (pid: 1054, threadinfo ffff8801b3720000, task ffff8801b2ec0000) Jul 13 20:53:31 zorg kernel: [131167.121931] Stack: Jul 13 20:53:31 zorg kernel: [131167.121946] ffff880196df9f00 0000000000000005 ffff8801b3721e75 ffff8801b1f90a00 Jul 13 20:53:31 zorg kernel: [131167.121995] ffff8801b3721dd8 ffffffff81264966 ffff8801b3721de8 00000001fffffff0 Jul 13 20:53:31 zorg kernel: [131167.122043] ffff8801b2073b80 0000000000000001 ffff8801988138b0 ffff8801b1f906a0 Jul 13 20:53:31 zorg kernel: [131167.122092] Call Trace: Jul 13 20:53:31 zorg kernel: [131167.122111] [<ffffffff81264966>] key_instantiate_and_link+0x76/0xa0 Jul 13 20:53:31 zorg kernel: [131167.122165] [<ffffffffa068a62b>] idmap_pipe_downcall+0x1cb/0x1e0 [nfs] Jul 13 20:53:31 zorg kernel: [131167.122219] [<ffffffffa01a1f67>] rpc_pipe_write+0x67/0x90 [sunrpc] Jul 13 20:53:31 zorg kernel: [131167.122255] [<ffffffff811837c3>] vfs_write+0xb3/0x180 Jul 13 20:53:31 zorg kernel: [131167.122284] [<ffffffff81183aea>] sys_write+0x4a/0x90 Jul 13 20:53:31 zorg kernel: [131167.122315] [<ffffffff816043e9>] system_call_fastpath+0x16/0x1b Jul 13 20:53:31 zorg kernel: [131167.122347] Code: c3 0f 1f 40 00 0f b7 50 12 48 89 74 d0 18 66 83 40 12 01 5d c3 55 48 89 e5 53 48 83 ec 18 66 66 66 66 90 48 85 f6 48 89 fb 74 70 <48> 83 3e 00 74 6c 48 81 fe a0 ff c5 81 74 4b 48 85 d2 74 11 f6 Jul 13 20:53:31 zorg kernel: [131167.122649] RIP [<ffffffff81266746>] __key_link_end+0x16/0x90 Jul 13 20:53:31 zorg kernel: [131167.122684] RSP <ffff8801b3721d68> Jul 13 20:53:31 zorg kernel: [131167.122704] CR2: 0000079100000791 Jul 13 20:53:31 zorg kernel: [131167.193422] ---[ end trace 70b8899b3cb9fa5d ]---
After googling a bit it seems that keyutils-1.5.5 fixes this issue. I've compiled and installed the tarball on my fedora 16 machine (the rpm is keyutils-1.5.2-1). http://people.redhat.com/dhowells/keyutils/
ah, great. thanks for testing!
I had the same Oops this morning using the updated version of keyutils. I'm now mounting my nfs mountpoints with nfsvers=3 The one thing I did notice is that each time it happens I'm attempting to attach a file in gmail using chrome. Was this ticket meant to be closed?
sorry, I misinterpreted comment 20 as this being fixed.
This looks pretty similar to bug 838730. Probably a dupe?
Yup, looks identical to 838730.
*** This bug has been marked as a duplicate of bug 838730 ***