* Re: nfs-root: destructive call to __detach_mounts /dev [not found] <20150731114230.GA31037@geggus.net> @ 2015-07-31 14:27 ` Eric W. Biederman 2015-08-14 11:01 ` Sven Geggus 0 siblings, 1 reply; 4+ messages in thread From: Eric W. Biederman @ 2015-07-31 14:27 UTC (permalink / raw) To: Sven Geggus; +Cc: linux-kernel, trond.myklebust, linux-nfs I have added the linux-nfs list to hopefully add a wider interested audience. Sven Geggus <lists@fuchsschwanzdomain.de> writes: > Hello, > > I have a couple of machines running Debian GNU/Linux 8 using an NFS-ro-mounted > root filesystem. > > The systems seem to get bitten by VFS changes in some (unfortunaly > somewhat difficult to reproduce) circumstances. > > The effect is, that /dev (dectmpfs) gets unmounted for some strange reason. > > I added the following debug code to fs/namespace.c > > printk(KERN_DEBUG "%s: %s\n", __func__, dentry->d_name.name); > dump_stack(); > > And this is what I get if one of those events happen: The only way to get to d_invalidate in lookup_fast is if d_revalidate fails. Which yields two functions to look at: nfs_lookup_revalidate and nfs4_lookup_revalidate If what is being revalidated is a mount point nfs4_lookup_revalidate calls nfs_lookup_revalidate. So nfs_lookup_revalidate is the only interesting function. The last round of this was with readdir having problems and invalidating the dcache. So now apparently we are down to something weird happening in revalidate. I don't understand the what nfs_lookup_revalidate is doing particularly well. However it appears that if you enable the kconfig SUNRPC_DEBUG option there will be more relevant information. I am not certain what more to print out that SUNRPC_DEBUG won't, but I have verified that SUNRPC_DEBUG will report when a failure path is hit in nfs_lookup_revalidate and which failure path was hit (out_bad or out_error). Which should be sufficient to start narrowing down what is happening even further. I hope that helps a little bit in tracking down what is happening. Eric > __detach_mounts: dev > CPU: 1 PID: 5551 Comm: modtrack Not tainted 4.1.3-debug-00287-g0fe8050-dirty #1 > Hardware name: Dell Inc. Precision WorkStation T3400 /0TP412, BIOS A03 01/31/2008 > ffff880127183c18 ffff880127183bc8 ffffffff815605f8 ffff88012bc4fcb0 > ffff880126c16198 ffff880127183bf8 ffffffff81106cf7 000000000000000f > ffff880126c16198 ffff880127183c18 ffff880127183d00 ffff880127183c48 > Call Trace: > [<ffffffff815605f8>] dump_stack+0x4c/0x6e > [<ffffffff81106cf7>] __detach_mounts+0x2b/0x12c > [<ffffffff810ffbb6>] d_invalidate+0x9a/0xc8 > [<ffffffff810f6b13>] lookup_fast+0x1f5/0x26f > [<ffffffff810f6dba>] do_last.isra.43+0xd6/0x9fb > [<ffffffff810f916e>] path_openat+0x1d1/0x53e > [<ffffffff810f9f41>] ? user_path_at_empty+0x63/0x93 > [<ffffffff810f9fe6>] do_filp_open+0x35/0x85 > [<ffffffff811f1893>] ? find_next_zero_bit+0x17/0x1d > [<ffffffff81104225>] ? __alloc_fd+0xdd/0xef > [<ffffffff810ec966>] do_sys_open+0x146/0x1d5 > [<ffffffff810eca1f>] SyS_openat+0xf/0x11 > [<ffffffff81565a17>] system_call_fastpath+0x12/0x6a > > Regards > > Sven > > P.S.: Kernel is vanilla 4.1.3 with aufs patches, but aufs is not related in > this problem. ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfs-root: destructive call to __detach_mounts /dev 2015-07-31 14:27 ` nfs-root: destructive call to __detach_mounts /dev Eric W. Biederman @ 2015-08-14 11:01 ` Sven Geggus 2015-08-14 15:07 ` Eric W. Biederman 0 siblings, 1 reply; 4+ messages in thread From: Sven Geggus @ 2015-08-14 11:01 UTC (permalink / raw) To: Eric W. Biederman; +Cc: linux-kernel, trond.myklebust, linux-nfs On 31-07-15 09:27 Eric W. Biederman wrote: > I have added the linux-nfs list to hopefully add a wider interested > audience. ... which made your mail get burried in my linux-nfs mailinglist folder :( But I finaly found it. > If what is being revalidated is a mount point nfs4_lookup_revalidate > calls nfs_lookup_revalidate. So nfs_lookup_revalidate is the only > interesting function. OK. > I don't understand the what nfs_lookup_revalidate is doing particularly > well. Neither do I. Here is what I get from a broken machine (Kernel 4.1.5) using "rpcdebug -m nfs -s lookupcache": The mountpoint which got unmounted in this case is /proc not /dev, but the stack-trace points to the same place. Aug 14 11:49:37 banthonytwarog kernel: NFS: nfs_lookup_revalidate(/proc) is valid Aug 14 11:49:37 banthonytwarog kernel: NFS: nfs_lookup_revalidate(/proc) is invalid Aug 14 11:49:37 banthonytwarog kernel: NFSROOT __detach_mounts: proc Aug 14 11:49:37 banthonytwarog kernel: CPU: 2 PID: 28350 Comm: modtrack Tainted: P W O 4.1.5-lomac3-00293-gfdd763a #6 Aug 14 11:49:37 banthonytwarog kernel: Hardware name: System manufacturer System Product Name/P8H67, BIOS 3506 03/02/2012 Aug 14 11:49:37 banthonytwarog kernel: ffff8800d9b93bb8 ffff8800d9b93b78 ffffffff81560488 00000000446c446c Aug 14 11:49:37 banthonytwarog kernel: ffff88040c427d98 ffff8800d9b93b98 ffffffff81106d36 00000000000000a2 Aug 14 11:49:37 banthonytwarog kernel: ffff88040c427d98 ffff8800d9b93be8 ffffffff810ffc0c 00000000d9b93c08 Aug 14 11:49:37 banthonytwarog kernel: Call Trace: Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff81560488>] dump_stack+0x4c/0x6e Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff81106d36>] __detach_mounts+0x20/0xdf Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810ffc0c>] d_invalidate+0x9a/0xc8 Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f6b60>] lookup_fast+0x1f5/0x26f Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f5a44>] ? __inode_permission+0x37/0x95 Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f7c02>] link_path_walk+0x204/0x749 Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f4db2>] ? terminate_walk+0x10/0x2e Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f75e7>] ? do_last.isra.43+0x8b6/0x9fb Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f846f>] path_init+0x328/0x337 Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f919a>] path_openat+0x1b0/0x53e Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810fa073>] do_filp_open+0x75/0x85 Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff8110427b>] ? __alloc_fd+0xdd/0xef Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810ec9b3>] do_sys_open+0x146/0x1d5 Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810d1c5c>] ? vm_munmap+0x4b/0x59 Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810eca5b>] SyS_open+0x19/0x1b Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff81565897>] system_call_fastpath+0x12/0x6a I suppose, that the first two lines are particularly interesting as we have "is valid" and a fraction of a second later we have "is invalid" at the same mountpoint. To me this looks like a job for the NFS client maintainers now, right? Sven -- Exploits and holes are a now a necessary protection against large corporate interests. (Alan Cox) /me is giggls@ircnet, http://sven.gegg.us/ on the Web ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfs-root: destructive call to __detach_mounts /dev 2015-08-14 11:01 ` Sven Geggus @ 2015-08-14 15:07 ` Eric W. Biederman 2015-08-17 12:37 ` Sven Geggus 0 siblings, 1 reply; 4+ messages in thread From: Eric W. Biederman @ 2015-08-14 15:07 UTC (permalink / raw) To: Sven Geggus; +Cc: linux-kernel, trond.myklebust, linux-nfs Sven Geggus <lists@fuchsschwanzdomain.de> writes: > On 31-07-15 09:27 Eric W. Biederman wrote: > >> I have added the linux-nfs list to hopefully add a wider interested >> audience. > > ... which made your mail get burried in my linux-nfs mailinglist folder :( > But I finaly found it. > >> If what is being revalidated is a mount point nfs4_lookup_revalidate >> calls nfs_lookup_revalidate. So nfs_lookup_revalidate is the only >> interesting function. > > OK. > >> I don't understand the what nfs_lookup_revalidate is doing particularly >> well. > > Neither do I. > > Here is what I get from a broken machine (Kernel 4.1.5) using > "rpcdebug -m nfs -s lookupcache": > > The mountpoint which got unmounted in this case is /proc not /dev, but the > stack-trace points to the same place. > > Aug 14 11:49:37 banthonytwarog kernel: NFS: nfs_lookup_revalidate(/proc) is valid > Aug 14 11:49:37 banthonytwarog kernel: NFS: nfs_lookup_revalidate(/proc) is invalid > Aug 14 11:49:37 banthonytwarog kernel: NFSROOT __detach_mounts: proc > Aug 14 11:49:37 banthonytwarog kernel: CPU: 2 PID: 28350 Comm: modtrack Tainted: P W O 4.1.5-lomac3-00293-gfdd763a #6 > Aug 14 11:49:37 banthonytwarog kernel: Hardware name: System manufacturer System Product Name/P8H67, BIOS 3506 03/02/2012 > Aug 14 11:49:37 banthonytwarog kernel: ffff8800d9b93bb8 ffff8800d9b93b78 ffffffff81560488 00000000446c446c > Aug 14 11:49:37 banthonytwarog kernel: ffff88040c427d98 ffff8800d9b93b98 ffffffff81106d36 00000000000000a2 > Aug 14 11:49:37 banthonytwarog kernel: ffff88040c427d98 ffff8800d9b93be8 ffffffff810ffc0c 00000000d9b93c08 > Aug 14 11:49:37 banthonytwarog kernel: Call Trace: > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff81560488>] dump_stack+0x4c/0x6e > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff81106d36>] __detach_mounts+0x20/0xdf > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810ffc0c>] d_invalidate+0x9a/0xc8 > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f6b60>] lookup_fast+0x1f5/0x26f > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f5a44>] ? __inode_permission+0x37/0x95 > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f7c02>] link_path_walk+0x204/0x749 > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f4db2>] ? terminate_walk+0x10/0x2e > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f75e7>] ? do_last.isra.43+0x8b6/0x9fb > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f846f>] path_init+0x328/0x337 > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810f919a>] path_openat+0x1b0/0x53e > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810fa073>] do_filp_open+0x75/0x85 > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff8110427b>] ? __alloc_fd+0xdd/0xef > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810ec9b3>] do_sys_open+0x146/0x1d5 > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810d1c5c>] ? vm_munmap+0x4b/0x59 > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff810eca5b>] SyS_open+0x19/0x1b > Aug 14 11:49:37 banthonytwarog kernel: [<ffffffff81565897>] system_call_fastpath+0x12/0x6a > > I suppose, that the first two lines are particularly interesting as we have > "is valid" and a fraction of a second later we have "is invalid" at the same > mountpoint. That does sound interesting. > To me this looks like a job for the NFS client maintainers now, right? My educated but unsupported guess would be that there is likely something funny going on with attributes somewhere like there was with nfs_prime_dcache. At a quick look the failure possibilities are: nfs_lookup_verify_inode failing, NFS_STALE(inode) being true, NFS_PROTO(dir)->lookup failing, nfs_compare_fh failing, nfs_refresh_inode failing, I expect what needs to happen now is to drill down into nfs_lookup_revalidate especially into the branches that can lead to out_bad and add some print statments so that it becomes clear just what conditions are causing nfs_lookup_invalidate to fail. I don't have a clue what the issue would be but I would start with something like the patch below. That will help narrow it down even further. And there are still enough possibilities that I don't think anyone has enough information yet to figure out what is going on from first principles. Eric diff --git a/fs/nfs/dir.c b/fs/nfs/dir.c index 547308a5ec6f..97c70c887b23 100644 --- a/fs/nfs/dir.c +++ b/fs/nfs/dir.c @@ -1167,7 +1167,7 @@ static int nfs_lookup_revalidate(struct dentry *dentry, unsigned int flags) return -ECHILD; if (NFS_STALE(inode)) - goto out_bad; + goto out_bad1; error = -ENOMEM; fhandle = nfs_alloc_fhandle(); @@ -1183,11 +1183,11 @@ static int nfs_lookup_revalidate(struct dentry *dentry, unsigned int flags) error = NFS_PROTO(dir)->lookup(dir, &dentry->d_name, fhandle, fattr, label); trace_nfs_lookup_revalidate_exit(dir, dentry, flags, error); if (error) - goto out_bad; + goto out_bad2; if (nfs_compare_fh(NFS_FH(inode), fhandle)) - goto out_bad; + goto out_bad3; if ((error = nfs_refresh_inode(inode, fattr)) != 0) - goto out_bad; + goto out_bad4; nfs_setsecurity(inode, fattr, label); @@ -1210,6 +1210,8 @@ out_set_verifier: __func__, dentry); return 1; out_zap_parent: + dfprintk(LOOKUPCACHE "NFS: %s(%pd2): nfs_lookup_verify_inode() failed\n", + __func__, dentry); nfs_zap_caches(dir); out_bad: WARN_ON(flags & LOOKUP_RCU); @@ -1233,6 +1235,22 @@ out_zap_parent: dfprintk(LOOKUPCACHE, "NFS: %s(%pd2) is invalid\n", __func__, dentry); return 0; +out_bad1: + dfprintk(LOOKUPCACHE, "NFS: %s(%pd2): NFS_STALE(inode)\n", + __func__, dentry); + goto out_bad; +out_bad2: + dfprintk(LOOKUPCACHE, "NFS: %s(%pd2): NFS_PROTO(dir)->lookup -> %u\n", + __func__, dentry, error); + goto out_bad; +out_bad3: + dfprintk(LOOKUPCACHE, "NFS: %s(%pd2): nfs_compare_fh() failed\n", + __func__, dentry); + goto out_bad; +out_bad4: + dfprintk(LOOKUPCACHE "NFS: %s(%pd2): nfs_refresh_inode() -> %u\n", + __func__, dentry, error); + goto out_bad; out_error: WARN_ON(flags & LOOKUP_RCU); nfs_free_fattr(fattr); ^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: nfs-root: destructive call to __detach_mounts /dev 2015-08-14 15:07 ` Eric W. Biederman @ 2015-08-17 12:37 ` Sven Geggus 0 siblings, 0 replies; 4+ messages in thread From: Sven Geggus @ 2015-08-17 12:37 UTC (permalink / raw) To: Eric W. Biederman; +Cc: linux-kernel, trond.myklebust, linux-nfs Eric W. Biederman wrote: > I don't have a clue what the issue would be but I would start with > something like the patch below. OK using it I got the following... This time with /dev on another machine (same nfs root-fs): Aug 17 13:57:04 dhcp195 kernel: NFS: nfs_lookup_revalidate(/dev): nfs_lookup_verify_inode() failed Aug 17 13:57:04 dhcp195 kernel: NFS: nfs_lookup_revalidate(/dev) is invalid Aug 17 13:57:04 dhcp195 kernel: NFSROOT __detach_mounts: dev Aug 17 13:57:04 dhcp195 kernel: CPU: 3 PID: 32644 Comm: modtrack Tainted: P O 4.1.6-lomac1-00296-gfeae456 #7 Aug 17 13:57:04 dhcp195 kernel: Hardware name: System manufacturer System Product Name/P7P55D, BIOS 1807 07/22/2010 Aug 17 13:57:04 dhcp195 kernel: ffff88021315bc18 ffff88021315bbd8 ffffffff81560638 000000000000b413 Aug 17 13:57:04 dhcp195 kernel: ffff880216460f18 ffff88021315bbf8 ffffffff81106e1f 000000000000001b Aug 17 13:57:04 dhcp195 kernel: ffff880216460f18 ffff88021315bc48 ffffffff810ffcf5 0000000005dd05dd Aug 17 13:57:04 dhcp195 kernel: Call Trace: Aug 17 13:57:04 dhcp195 kernel: [<ffffffff81560638>] dump_stack+0x4c/0x6e Aug 17 13:57:04 dhcp195 kernel: [<ffffffff81106e1f>] __detach_mounts+0x20/0xdf Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810ffcf5>] d_invalidate+0x9a/0xc8 Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810f6c49>] lookup_fast+0x1f5/0x26f Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810f6ef0>] do_last.isra.43+0xd6/0x9fb Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810f92a4>] path_openat+0x1d1/0x53e Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810fa077>] ? user_path_at_empty+0x63/0x93 Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810fa11c>] do_filp_open+0x35/0x85 Aug 17 13:57:04 dhcp195 kernel: [<ffffffff811f1aa9>] ? find_next_zero_bit+0x17/0x1d Aug 17 13:57:04 dhcp195 kernel: [<ffffffff81104364>] ? __alloc_fd+0xdd/0xef Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810eca9c>] do_sys_open+0x146/0x1d5 Aug 17 13:57:04 dhcp195 kernel: [<ffffffff810ecb55>] SyS_openat+0xf/0x11 Aug 17 13:57:04 dhcp195 kernel: [<ffffffff81565a57>] system_call_fastpath+0x12/0x6a So this looks like I would need to add some debug output to "nfs_lookup_verify_inode" then right? Sven -- Why are there so many Unix-haters-handbooks and not even one Microsoft-Windows-haters handbook? Gurer vf ab arrq sbe n unaqobbx gb ungr Zvpebfbsg Jvaqbjf! /me is giggls@ircnet, http://sven.gegg.us/ on the Web ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2015-08-17 12:37 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <20150731114230.GA31037@geggus.net>
2015-07-31 14:27 ` nfs-root: destructive call to __detach_mounts /dev Eric W. Biederman
2015-08-14 11:01 ` Sven Geggus
2015-08-14 15:07 ` Eric W. Biederman
2015-08-17 12:37 ` Sven Geggus
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox