* 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected)
@ 2011-03-30 20:38 Dmitry Torokhov
2011-03-30 21:03 ` Bryan Schumaker
0 siblings, 1 reply; 9+ messages in thread
From: Dmitry Torokhov @ 2011-03-30 20:38 UTC (permalink / raw)
To: linux-kernel; +Cc: Bryan Schumaker, Trond Myklebust
Hi,
The following commit appears to the open preventng me from mounting some
of my NFS shares (not all, of them, just some):
8f70e95f9f4159184f557a1db60c909d7c1bd2e3 is the first bad commit
commit 8f70e95f9f4159184f557a1db60c909d7c1bd2e3
Author: Bryan Schumaker <bjschuma@netapp.com>
Date: Thu Mar 24 17:12:31 2011 +0000
NFS: Determine initial mount security
When sec=<something> is not presented as a mount option,
we should attempt to determine what security flavor the
server is using.
Signed-off-by: Bryan Schumaker <bjschuma@netapp.com>
Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com>
Here is the bisect log:
[dtor@dtor-ws linus]$ git bisect log
git bisect start
# good: [4bbba111d94781d34081c37856bbc5eb33f6c72a] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound-2.6
git bisect good 4bbba111d94781d34081c37856bbc5eb33f6c72a
# bad: [0ce790e7d736cedc563e1fb4e998babf5a4dbc3d] Linux 2.6.39-rc1
git bisect bad 0ce790e7d736cedc563e1fb4e998babf5a4dbc3d
# good: [e285c1746accb80620e511f9c72e9893beeedc0e] Merge branch 'drm-core-next' of git://git.kernel.org/pub/scm/linux/kernel/git/airlied/drm-2.6
git bisect good e285c1746accb80620e511f9c72e9893beeedc0e
# bad: [8d49a77568d1105ff3e64aec484dac059f54824e] Merge branch 'for-2.6.39/drivers' of git://git.kernel.dk/linux-2.6-block
git bisect bad 8d49a77568d1105ff3e64aec484dac059f54824e
# bad: [5aafdea448fb86412a6f8e46df518c1545d32436] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jbarnes/pci-2.6
git bisect bad 5aafdea448fb86412a6f8e46df518c1545d32436
# bad: [9458ea567a72ebd3852c2d764d32c0f2fb61d0df] MIPS: IP22/IP28: Convert to new irq_chip functions
git bisect bad 9458ea567a72ebd3852c2d764d32c0f2fb61d0df
# good: [ae005cbed12d0b340b04b59d6f5c56e710b3895d] Merge branch 'for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4
git bisect good ae005cbed12d0b340b04b59d6f5c56e710b3895d
# bad: [1685f3b158a244d4f6e205e67c84483fffcb2d9f] MIPS: SMTC: Move declaration of smtc_init_secondary to <asm/smtc.h>.
git bisect bad 1685f3b158a244d4f6e205e67c84483fffcb2d9f
# good: [988b6dceb0ae6d642587c8594529b94f6be0c5ea] NFSv4.1: remove GETATTR from ds commits
git bisect good 988b6dceb0ae6d642587c8594529b94f6be0c5ea
# good: [35124a0994fc02545b14b9fa3aad000b3331f1c0] Cleanup XDR parsing for LAYOUTGET, GETDEVICEINFO
git bisect good 35124a0994fc02545b14b9fa3aad000b3331f1c0
# bad: [8f70e95f9f4159184f557a1db60c909d7c1bd2e3] NFS: Determine initial mount security
git bisect bad 8f70e95f9f4159184f557a1db60c909d7c1bd2e3
# good: [7c5130588d691a3b34d02312f1bd1b6d56fe0100] NFS: lookup supports s alternate client
git bisect good 7c5130588d691a3b34d02312f1bd1b6d56fe0100
# good: [7ebb931598cd95cccea10d4bc4c0123a464ea565] NFS: use secinfo when crossing mountpoints
git bisect good 7ebb931598cd95cccea10d4bc4c0123a464ea565
^ permalink raw reply [flat|nested] 9+ messages in thread* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) 2011-03-30 20:38 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) Dmitry Torokhov @ 2011-03-30 21:03 ` Bryan Schumaker 0 siblings, 0 replies; 9+ messages in thread From: Bryan Schumaker @ 2011-03-30 21:03 UTC (permalink / raw) To: Dmitry Torokhov; +Cc: linux-kernel, Trond Myklebust Hi, Thanks for letting me know. What does your exports file look like, and which mounts do and don't work? Bryan On 03/30/2011 04:38 PM, Dmitry Torokhov wrote: > Hi, > > The following commit appears to the open preventng me from mounting some > of my NFS shares (not all, of them, just some): > > 8f70e95f9f4159184f557a1db60c909d7c1bd2e3 is the first bad commit > commit 8f70e95f9f4159184f557a1db60c909d7c1bd2e3 > Author: Bryan Schumaker <bjschuma@netapp.com> > Date: Thu Mar 24 17:12:31 2011 +0000 > > NFS: Determine initial mount security > > When sec=<something> is not presented as a mount option, > we should attempt to determine what security flavor the > server is using. > > Signed-off-by: Bryan Schumaker <bjschuma@netapp.com> > Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com> > > Here is the bisect log: > > [dtor@dtor-ws linus]$ git bisect log > git bisect start > # good: [4bbba111d94781d34081c37856bbc5eb33f6c72a] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound-2.6 > git bisect good 4bbba111d94781d34081c37856bbc5eb33f6c72a > # bad: [0ce790e7d736cedc563e1fb4e998babf5a4dbc3d] Linux 2.6.39-rc1 > git bisect bad 0ce790e7d736cedc563e1fb4e998babf5a4dbc3d > # good: [e285c1746accb80620e511f9c72e9893beeedc0e] Merge branch 'drm-core-next' of git://git.kernel.org/pub/scm/linux/kernel/git/airlied/drm-2.6 > git bisect good e285c1746accb80620e511f9c72e9893beeedc0e > # bad: [8d49a77568d1105ff3e64aec484dac059f54824e] Merge branch 'for-2.6.39/drivers' of git://git.kernel.dk/linux-2.6-block > git bisect bad 8d49a77568d1105ff3e64aec484dac059f54824e > # bad: [5aafdea448fb86412a6f8e46df518c1545d32436] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jbarnes/pci-2.6 > git bisect bad 5aafdea448fb86412a6f8e46df518c1545d32436 > # bad: [9458ea567a72ebd3852c2d764d32c0f2fb61d0df] MIPS: IP22/IP28: Convert to new irq_chip functions > git bisect bad 9458ea567a72ebd3852c2d764d32c0f2fb61d0df > # good: [ae005cbed12d0b340b04b59d6f5c56e710b3895d] Merge branch 'for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4 > git bisect good ae005cbed12d0b340b04b59d6f5c56e710b3895d > # bad: [1685f3b158a244d4f6e205e67c84483fffcb2d9f] MIPS: SMTC: Move declaration of smtc_init_secondary to <asm/smtc.h>. > git bisect bad 1685f3b158a244d4f6e205e67c84483fffcb2d9f > # good: [988b6dceb0ae6d642587c8594529b94f6be0c5ea] NFSv4.1: remove GETATTR from ds commits > git bisect good 988b6dceb0ae6d642587c8594529b94f6be0c5ea > # good: [35124a0994fc02545b14b9fa3aad000b3331f1c0] Cleanup XDR parsing for LAYOUTGET, GETDEVICEINFO > git bisect good 35124a0994fc02545b14b9fa3aad000b3331f1c0 > # bad: [8f70e95f9f4159184f557a1db60c909d7c1bd2e3] NFS: Determine initial mount security > git bisect bad 8f70e95f9f4159184f557a1db60c909d7c1bd2e3 > # good: [7c5130588d691a3b34d02312f1bd1b6d56fe0100] NFS: lookup supports s alternate client > git bisect good 7c5130588d691a3b34d02312f1bd1b6d56fe0100 > # good: [7ebb931598cd95cccea10d4bc4c0123a464ea565] NFS: use secinfo when crossing mountpoints > git bisect good 7ebb931598cd95cccea10d4bc4c0123a464ea565 > ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected)
@ 2011-03-30 22:31 Dmitry Torokhov
2011-03-31 16:23 ` Dmitry Torokhov
0 siblings, 1 reply; 9+ messages in thread
From: Dmitry Torokhov @ 2011-03-30 22:31 UTC (permalink / raw)
To: Bryan Schumaker; +Cc: linux-kernel@vger.kernel.org, Trond Myklebust
Hi Bryan,
It is actually one of autofs + NIS, mounts that is failing.
--
Dmitry
On Mar 30, 2011, at 2:03 PM, Bryan Schumaker <bjschuma@netapp.com> wrote:
> Hi,
>
> Thanks for letting me know. What does your exports file look like, and which mounts do and don't work?
>
> Bryan
>
> On 03/30/2011 04:38 PM, Dmitry Torokhov wrote:
>> Hi,
>>
>> The following commit appears to the open preventng me from mounting some
>> of my NFS shares (not all, of them, just some):
>>
>> 8f70e95f9f4159184f557a1db60c909d7c1bd2e3 is the first bad commit
>> commit 8f70e95f9f4159184f557a1db60c909d7c1bd2e3
>> Author: Bryan Schumaker <bjschuma@netapp.com>
>> Date: Thu Mar 24 17:12:31 2011 +0000
>>
>> NFS: Determine initial mount security
>>
>> When sec=<something> is not presented as a mount option,
>> we should attempt to determine what security flavor the
>> server is using.
>>
>> Signed-off-by: Bryan Schumaker <bjschuma@netapp.com>
>> Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com>
>>
>> Here is the bisect log:
>>
>> [dtor@dtor-ws linus]$ git bisect log
>> git bisect start
>> # good: [4bbba111d94781d34081c37856bbc5eb33f6c72a] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound-2.6
>> git bisect good 4bbba111d94781d34081c37856bbc5eb33f6c72a
>> # bad: [0ce790e7d736cedc563e1fb4e998babf5a4dbc3d] Linux 2.6.39-rc1
>> git bisect bad 0ce790e7d736cedc563e1fb4e998babf5a4dbc3d
>> # good: [e285c1746accb80620e511f9c72e9893beeedc0e] Merge branch 'drm-core-next' of git://git.kernel.org/pub/scm/linux/kernel/git/airlied/drm-2.6
>> git bisect good e285c1746accb80620e511f9c72e9893beeedc0e
>> # bad: [8d49a77568d1105ff3e64aec484dac059f54824e] Merge branch 'for-2.6.39/drivers' of git://git.kernel.dk/linux-2.6-block
>> git bisect bad 8d49a77568d1105ff3e64aec484dac059f54824e
>> # bad: [5aafdea448fb86412a6f8e46df518c1545d32436] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jbarnes/pci-2.6
>> git bisect bad 5aafdea448fb86412a6f8e46df518c1545d32436
>> # bad: [9458ea567a72ebd3852c2d764d32c0f2fb61d0df] MIPS: IP22/IP28: Convert to new irq_chip functions
>> git bisect bad 9458ea567a72ebd3852c2d764d32c0f2fb61d0df
>> # good: [ae005cbed12d0b340b04b59d6f5c56e710b3895d] Merge branch 'for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4
>> git bisect good ae005cbed12d0b340b04b59d6f5c56e710b3895d
>> # bad: [1685f3b158a244d4f6e205e67c84483fffcb2d9f] MIPS: SMTC: Move declaration of smtc_init_secondary to <asm/smtc.h>.
>> git bisect bad 1685f3b158a244d4f6e205e67c84483fffcb2d9f
>> # good: [988b6dceb0ae6d642587c8594529b94f6be0c5ea] NFSv4.1: remove GETATTR from ds commits
>> git bisect good 988b6dceb0ae6d642587c8594529b94f6be0c5ea
>> # good: [35124a0994fc02545b14b9fa3aad000b3331f1c0] Cleanup XDR parsing for LAYOUTGET, GETDEVICEINFO
>> git bisect good 35124a0994fc02545b14b9fa3aad000b3331f1c0
>> # bad: [8f70e95f9f4159184f557a1db60c909d7c1bd2e3] NFS: Determine initial mount security
>> git bisect bad 8f70e95f9f4159184f557a1db60c909d7c1bd2e3
>> # good: [7c5130588d691a3b34d02312f1bd1b6d56fe0100] NFS: lookup supports s alternate client
>> git bisect good 7c5130588d691a3b34d02312f1bd1b6d56fe0100
>> # good: [7ebb931598cd95cccea10d4bc4c0123a464ea565] NFS: use secinfo when crossing mountpoints
>> git bisect good 7ebb931598cd95cccea10d4bc4c0123a464ea565
>>
>
^ permalink raw reply [flat|nested] 9+ messages in thread* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) 2011-03-30 22:31 Dmitry Torokhov @ 2011-03-31 16:23 ` Dmitry Torokhov 2011-03-31 16:50 ` Dmitry Torokhov 0 siblings, 1 reply; 9+ messages in thread From: Dmitry Torokhov @ 2011-03-31 16:23 UTC (permalink / raw) To: Dmitry Torokhov Cc: Bryan Schumaker, linux-kernel@vger.kernel.org, Trond Myklebust Hi Bryan, On Wed, Mar 30, 2011 at 03:31:44PM -0700, Dmitry Torokhov wrote: > Hi Bryan, > > It is actually one of autofs + NIS, mounts that is failing. > Some more data about NFS problemi I am seeing. With an older kernel I get: [dtor@dtor-d630 ~]$ sudo mount -v build-toolchain:/toolchain /mnt/ mount: no type was given - I'll assume nfs because of the colon mount.nfs: timeout set for Thu Mar 31 09:17:38 2011 mount.nfs: trying text-based options 'vers=4,addr=10.17.52.98,clientaddr=10.20.94.47' mount.nfs: mount(2): Operation not permitted mount.nfs: trying text-based options 'addr=10.17.52.98' mount.nfs: prog 100003, trying vers=3, prot=6 mount.nfs: trying 10.17.52.98 prog 100003 vers 3 prot TCP port 2049 mount.nfs: prog 100005, trying vers=3, prot=17 mount.nfs: trying 10.17.52.98 prog 100005 vers 3 prot UDP port 693 build-toolchain:/toolchain on /mnt type nfs (rw) The failing kernel does it like this: [dtor@dtor-ws ~]$ sudo mount -v build-toolchain:/toolchain /mnt mount: no type was given - I'll assume nfs because of the colon mount.nfs: timeout set for Thu Mar 31 09:14:22 2011 mount.nfs: trying text-based options 'vers=4,addr=10.17.52.98,clientaddr=10.20.94.123' mount.nfs: mount(2): Resource temporarily unavailable mount.nfs: Resource temporarily unavailable And I can mount it successfully if I explicitly request V3: [dtor@dtor-ws ~]$ sudo mount -v -o nfsvers=3 build-toolchain:/toolchain /mnt/ mount: no type was given - I'll assume nfs because of the colon mount.nfs: timeout set for Thu Mar 31 09:22:57 2011 mount.nfs: trying text-based options 'nfsvers=3,addr=10.17.52.98' mount.nfs: prog 100003, trying vers=3, prot=6 mount.nfs: trying 10.17.52.98 prog 100003 vers 3 prot TCP port 2049 mount.nfs: prog 100005, trying vers=3, prot=17 mount.nfs: trying 10.17.52.98 prog 100005 vers 3 prot UDP port 693 build-toolchain:/toolchain on /mnt type nfs (rw,nfsvers=3) The mounts that succeed automatically with the newer kernel do like this: [dtor@dtor-ws ~]$ sudo mount -v pa-home:/home2 /mnt/ mount: no type was given - I'll assume nfs because of the colon mount.nfs: timeout set for Thu Mar 31 09:20:01 2011 mount.nfs: trying text-based options 'vers=4,addr=10.17.4.25,clientaddr=10.20.94.123' mount.nfs: mount(2): Protocol not supported mount.nfs: trying text-based options 'addr=10.17.4.25' mount.nfs: prog 100003, trying vers=3, prot=6 mount.nfs: trying 10.17.4.25 prog 100003 vers 3 prot TCP port 2049 mount.nfs: prog 100005, trying vers=3, prot=17 mount.nfs: trying 10.17.4.25 prog 100005 vers 3 prot UDP port 1234 pa-home:/home2 on /mnt type nfs (rw) I am not sure why in failing case we are seeing "resource temporarily unavailable" instead of "protocol not supported". Thanks. -- Dmitry ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) 2011-03-31 16:23 ` Dmitry Torokhov @ 2011-03-31 16:50 ` Dmitry Torokhov 2011-03-31 17:15 ` Bryan Schumaker 0 siblings, 1 reply; 9+ messages in thread From: Dmitry Torokhov @ 2011-03-31 16:50 UTC (permalink / raw) To: Bryan Schumaker; +Cc: linux-kernel@vger.kernel.org, Trond Myklebust On Thu, Mar 31, 2011 at 09:23:38AM -0700, Dmitry Torokhov wrote: > Hi Bryan, > > On Wed, Mar 30, 2011 at 03:31:44PM -0700, Dmitry Torokhov wrote: > > Hi Bryan, > > > > It is actually one of autofs + NIS, mounts that is failing. > > > > Some more data about NFS problemi I am seeing. With an older kernel I > get: > > [dtor@dtor-d630 ~]$ sudo mount -v build-toolchain:/toolchain /mnt/ > mount: no type was given - I'll assume nfs because of the colon > mount.nfs: timeout set for Thu Mar 31 09:17:38 2011 > mount.nfs: trying text-based options 'vers=4,addr=10.17.52.98,clientaddr=10.20.94.47' > mount.nfs: mount(2): Operation not permitted > mount.nfs: trying text-based options 'addr=10.17.52.98' > mount.nfs: prog 100003, trying vers=3, prot=6 > mount.nfs: trying 10.17.52.98 prog 100003 vers 3 prot TCP port 2049 > mount.nfs: prog 100005, trying vers=3, prot=17 > mount.nfs: trying 10.17.52.98 prog 100005 vers 3 prot UDP port 693 > build-toolchain:/toolchain on /mnt type nfs (rw) > > The failing kernel does it like this: > > [dtor@dtor-ws ~]$ sudo mount -v build-toolchain:/toolchain /mnt > mount: no type was given - I'll assume nfs because of the colon > mount.nfs: timeout set for Thu Mar 31 09:14:22 2011 > mount.nfs: trying text-based options 'vers=4,addr=10.17.52.98,clientaddr=10.20.94.123' > mount.nfs: mount(2): Resource temporarily unavailable > mount.nfs: Resource temporarily unavailable > > And I can mount it successfully if I explicitly request V3: > > [dtor@dtor-ws ~]$ sudo mount -v -o nfsvers=3 build-toolchain:/toolchain /mnt/ > mount: no type was given - I'll assume nfs because of the colon > mount.nfs: timeout set for Thu Mar 31 09:22:57 2011 > mount.nfs: trying text-based options 'nfsvers=3,addr=10.17.52.98' > mount.nfs: prog 100003, trying vers=3, prot=6 > mount.nfs: trying 10.17.52.98 prog 100003 vers 3 prot TCP port 2049 > mount.nfs: prog 100005, trying vers=3, prot=17 > mount.nfs: trying 10.17.52.98 prog 100005 vers 3 prot UDP port 693 > build-toolchain:/toolchain on /mnt type nfs (rw,nfsvers=3) > > The mounts that succeed automatically with the newer kernel do like > this: > > [dtor@dtor-ws ~]$ sudo mount -v pa-home:/home2 /mnt/ > mount: no type was given - I'll assume nfs because of the colon > mount.nfs: timeout set for Thu Mar 31 09:20:01 2011 > mount.nfs: trying text-based options 'vers=4,addr=10.17.4.25,clientaddr=10.20.94.123' > mount.nfs: mount(2): Protocol not supported > mount.nfs: trying text-based options 'addr=10.17.4.25' > mount.nfs: prog 100003, trying vers=3, prot=6 > mount.nfs: trying 10.17.4.25 prog 100003 vers 3 prot TCP port 2049 > mount.nfs: prog 100005, trying vers=3, prot=17 > mount.nfs: trying 10.17.4.25 prog 100005 vers 3 prot UDP port 1234 > pa-home:/home2 on /mnt type nfs (rw) > > I am not sure why in failing case we are seeing "resource temporarily > unavailable" instead of "protocol not supported". > And here is the kernel log with debuggig enabled. Sorry for multiple posts BTW. [ 2679.038558] NFS: nfs mount opts='vers=4,addr=10.17.52.98,clientaddr=10.20.94.123' [ 2679.038910] NFS: parsing nfs mount option 'vers=4' [ 2679.039126] NFS: parsing nfs mount option 'addr=10.17.52.98' [ 2679.039307] NFS: parsing nfs mount option 'clientaddr=10.20.94.123' [ 2679.039490] NFS: MNTPATH: '/toolchain' [ 2679.039659] --> nfs4_try_mount() [ 2679.039837] --> nfs4_create_server() [ 2679.040198] --> nfs4_init_server() [ 2679.040365] --> nfs4_set_client() [ 2679.040559] --> nfs_get_client(build-toolchain,v4) [ 2679.040733] RPC: looking up machine cred [ 2679.040909] NFS: get client cookie (0xffff8800685c3c00/0xffff88007a2c2e10) [ 2679.041143] RPC: set up xprt to 10.17.52.98 (port 2049) via tcp [ 2679.041324] RPC: created transport ffff88007a346000 with 16 slots [ 2679.041501] RPC: creating nfs client for build-toolchain (xprt ffff88007a346000) [ 2679.041895] RPC: creating UNIX authenticator for client ffff880067dfde00 [ 2679.042273] RPC: new task initialized, procpid 6568 [ 2679.042447] RPC: allocated task ffff880060c6d100 [ 2679.042618] RPC: 1843 __rpc_execute flags=0x680 [ 2679.042787] RPC: 1843 call_start nfs4 proc NULL (sync) [ 2679.042957] RPC: 1843 call_reserve (status 0) [ 2679.048338] RPC: 1843 reserved req ffff88007a2d6000 xid 094bb2b3 [ 2679.048513] RPC: 1843 call_reserveresult (status 0) [ 2679.048688] RPC: 1843 call_refresh (status 0) [ 2679.048860] RPC: 1843 holding NULL cred ffffffffa025da80 [ 2679.049060] RPC: 1843 refreshing NULL cred ffffffffa025da80 [ 2679.049243] RPC: 1843 call_refreshresult (status 0) [ 2679.049426] RPC: 1843 call_allocate (status 0) [ 2679.049635] RPC: 1843 allocated buffer of size 96 at ffff88007a343800 [ 2679.049819] RPC: 1843 call_bind (status 0) [ 2679.049990] RPC: 1843 call_connect xprt ffff88007a346000 is not connected [ 2679.050200] RPC: 1843 xprt_connect xprt ffff88007a346000 is not connected [ 2679.050379] RPC: 1843 sleep_on(queue "xprt_pending" time 4297346346) [ 2679.050556] RPC: 1843 added to queue ffff88007a346320 "xprt_pending" [ 2679.050732] RPC: 1843 setting alarm for 60000 ms [ 2679.050901] RPC: xs_connect scheduled xprt ffff88007a346000 [ 2679.051114] RPC: 1843 sync task going to sleep [ 2679.051312] RPC: xs_bind 0.0.0.0:1013: ok (0) [ 2679.051486] RPC: worker connecting xprt ffff88007a346000 via tcp to 10.17.52.98 (port 2049) [ 2679.051857] RPC: ffff88007a346000 connect status 115 connected 0 sock state 2 [ 2679.052997] RPC: xs_tcp_state_change client ffff88007a346000... [ 2679.053190] RPC: state 1 conn 0 dead 0 zapped -1 sk_shutdown 0 [ 2679.053361] RPC: 1843 __rpc_wake_up_task (now 4297346349) [ 2679.053529] RPC: 1843 disabling timer [ 2679.053696] RPC: 1843 removed from queue ffff88007a346320 "xprt_pending" [ 2679.053870] RPC: __rpc_wake_up_task done [ 2679.053961] RPC: 1843 sync task resuming [ 2679.053961] RPC: 1843 xprt_connect_status: retrying [ 2679.053961] RPC: 1843 call_connect_status (status -11) [ 2679.053961] RPC: 1843 call_transmit (status 0) [ 2679.053961] RPC: 1843 xprt_prepare_transmit [ 2679.053961] RPC: 1843 rpc_xdr_encode (status 0) [ 2679.055137] RPC: 1843 marshaling NULL cred ffffffffa025da80 [ 2679.055311] RPC: 1843 using AUTH_NULL cred ffffffffa025da80 to wrap rpc data [ 2679.055488] RPC: 1843 xprt_transmit(44) [ 2679.055687] RPC: xs_tcp_send_request(44) = 44 [ 2679.055866] RPC: 1843 xmit complete [ 2679.056068] RPC: 1843 sleep_on(queue "xprt_pending" time 4297346352) [ 2679.056245] RPC: 1843 added to queue ffff88007a346320 "xprt_pending" [ 2679.056421] RPC: 1843 setting alarm for 60000 ms [ 2679.056590] RPC: wake_up_next(ffff88007a346258 "xprt_resend") [ 2679.056761] RPC: wake_up_next(ffff88007a346190 "xprt_sending") [ 2679.056932] RPC: 1843 sync task going to sleep [ 2679.057243] RPC: xs_tcp_data_ready... [ 2679.057412] RPC: xs_tcp_data_recv started [ 2679.057580] RPC: reading TCP record fragment of length 24 [ 2679.057749] RPC: reading XID (4 bytes) [ 2679.057916] RPC: reading request with XID 094bb2b3 [ 2679.058122] RPC: reading CALL/REPLY flag (4 bytes) [ 2679.058299] RPC: read reply XID 094bb2b3 [ 2679.058467] RPC: XID 094bb2b3 read 16 bytes [ 2679.058635] RPC: xprt = ffff88007a346000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24 [ 2679.058966] RPC: 1843 xid 094bb2b3 complete (24 bytes received) [ 2679.059166] RPC: 1843 __rpc_wake_up_task (now 4297346355) [ 2679.059341] RPC: 1843 disabling timer [ 2679.059507] RPC: 1843 removed from queue ffff88007a346320 "xprt_pending" [ 2679.059684] RPC: __rpc_wake_up_task done [ 2679.059700] RPC: 1843 sync task resuming [ 2679.059709] RPC: 1843 call_status (status 24) [ 2679.059714] RPC: 1843 call_decode (status 24) [ 2679.059722] RPC: 1843 validating NULL cred ffffffffa025da80 [ 2679.059729] RPC: 1843 using AUTH_NULL cred ffffffffa025da80 to unwrap rpc data [ 2679.059734] RPC: 1843 call_decode result 0 [ 2679.059739] RPC: 1843 return 0, status 0 [ 2679.059742] RPC: 1843 release task [ 2679.061339] RPC: xs_tcp_data_recv done [ 2679.061344] RPC: freeing buffer of size 96 at ffff88007a343800 [ 2679.061353] RPC: 1843 release request ffff88007a2d6000 [ 2679.061358] RPC: wake_up_next(ffff88007a3463e8 "xprt_backlog") [ 2679.061364] RPC: rpc_release_client(ffff880067dfde00) [ 2679.061370] RPC: 1843 freeing task [ 2679.061477] svc: initialising pool 0 for NFSv4 callback [ 2679.061484] RPC: unregistering [1073741824, 4, ''] with local rpcbind [ 2679.061492] RPC: new task initialized, procpid 6568 [ 2679.061496] RPC: allocated task ffff88007a80e400 [ 2679.061502] RPC: 1844 __rpc_execute flags=0x680 [ 2679.061508] RPC: 1844 call_start rpcbind4 proc UNSET (sync) [ 2679.061514] RPC: 1844 call_reserve (status 0) [ 2679.061520] RPC: 1844 reserved req ffff88011a39e000 xid c856cbbf [ 2679.061525] RPC: 1844 call_reserveresult (status 0) [ 2679.061529] RPC: 1844 call_refresh (status 0) [ 2679.061533] RPC: 1844 looking up UNIX cred [ 2679.061536] RPC: looking up UNIX cred [ 2679.061543] RPC: 1844 refreshing UNIX cred ffff880078fb6300 [ 2679.061548] RPC: 1844 call_refreshresult (status 0) [ 2679.061552] RPC: 1844 call_allocate (status 0) [ 2679.061558] RPC: 1844 allocated buffer of size 488 at ffff88007aaa9000 [ 2679.061563] RPC: 1844 call_bind (status 0) [ 2679.061568] RPC: 1844 call_connect xprt ffff88011a1e0000 is not connected [ 2679.061574] RPC: 1844 xprt_connect xprt ffff88011a1e0000 is not connected [ 2679.061580] RPC: 1844 sleep_on(queue "xprt_pending" time 4297346357) [ 2679.061586] RPC: 1844 added to queue ffff88011a1e0320 "xprt_pending" [ 2679.061590] RPC: 1844 setting alarm for 60000 ms [ 2679.061596] RPC: xs_connect scheduled xprt ffff88011a1e0000 [ 2679.061611] RPC: 1844 sync task going to sleep [ 2679.061624] RPC: disconnecting xprt ffff88011a1e0000 to reuse port [ 2679.061636] RPC: xs_error_report client ffff88011a1e0000... [ 2679.061639] RPC: error 0 [ 2679.061643] RPC: 1844 __rpc_wake_up_task (now 4297346357) [ 2679.061646] RPC: 1844 disabling timer [ 2679.061651] RPC: 1844 removed from queue ffff88011a1e0320 "xprt_pending" [ 2679.061660] RPC: __rpc_wake_up_task done [ 2679.061666] RPC: disconnected transport ffff88011a1e0000 [ 2679.061672] RPC: worker connecting xprt ffff88011a1e0000 via tcp to 127.0.0.1 (port 111) [ 2679.061810] RPC: xs_tcp_state_change client ffff88011a1e0000... [ 2679.061816] RPC: state 1 conn 0 dead 0 zapped -1 sk_shutdown 0 [ 2679.061875] RPC: ffff88011a1e0000 connect status 115 connected 1 sock state 1 [ 2679.062854] RPC: 1844 sync task resuming [ 2679.062859] RPC: 1844 xprt_connect_status: retrying [ 2679.062863] RPC: 1844 call_connect_status (status -11) [ 2679.062868] RPC: 1844 call_transmit (status 0) [ 2679.062872] RPC: 1844 xprt_prepare_transmit [ 2679.062876] RPC: 1844 rpc_xdr_encode (status 0) [ 2679.062881] RPC: 1844 marshaling UNIX cred ffff880078fb6300 [ 2679.062888] RPC: 1844 using AUTH_UNIX cred ffff880078fb6300 to wrap rpc data [ 2679.062895] RPC: 1844 encoding RPCB_UNSET call (1073741824, 4, '', '') [ 2679.062900] RPC: 1844 xprt_transmit(140) [ 2679.063269] RPC: xs_tcp_data_ready... [ 2679.063274] RPC: xs_tcp_data_recv started [ 2679.063279] RPC: reading TCP record fragment of length 28 [ 2679.063283] RPC: reading XID (4 bytes) [ 2679.063288] RPC: reading request with XID c856cbbf [ 2679.063292] RPC: reading CALL/REPLY flag (4 bytes) [ 2679.063296] RPC: read reply XID c856cbbf [ 2679.063302] RPC: XID c856cbbf read 20 bytes [ 2679.063307] RPC: xprt = ffff88011a1e0000, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28 [ 2679.063313] RPC: 1844 xid c856cbbf complete (28 bytes received) [ 2679.063319] RPC: xs_tcp_data_recv done [ 2679.063334] RPC: xs_tcp_send_request(140) = 140 [ 2679.063338] RPC: 1844 xmit complete [ 2679.063344] RPC: wake_up_next(ffff88011a1e0258 "xprt_resend") [ 2679.063349] RPC: wake_up_next(ffff88011a1e0190 "xprt_sending") [ 2679.063354] RPC: 1844 call_status (status 28) [ 2679.063358] RPC: 1844 call_decode (status 28) [ 2679.063363] RPC: 1844 validating UNIX cred ffff880078fb6300 [ 2679.063368] RPC: 1844 using AUTH_UNIX cred ffff880078fb6300 to unwrap rpc data [ 2679.063373] RPC: 1844 RPCB_UNSET call succeeded [ 2679.063377] RPC: 1844 call_decode result 0 [ 2679.063381] RPC: 1844 return 0, status 0 [ 2679.063384] RPC: 1844 release task [ 2679.063390] RPC: freeing buffer of size 488 at ffff88007aaa9000 [ 2679.063396] RPC: 1844 release request ffff88011a39e000 [ 2679.063400] RPC: wake_up_next(ffff88011a1e03e8 "xprt_backlog") [ 2679.063405] RPC: rpc_release_client(ffff88011a88cc00) [ 2679.063410] RPC: 1844 freeing task [ 2679.063417] svc: __svc_unregister(NFSv4 callbackv4), error 0 [ 2679.063423] svc: creating transport tcp[0] [ 2679.063431] svc: svc_create_socket(NFSv4 callback, 6, 0.0.0.0, port=0) [ 2679.063468] svc: svc_setup_socket ffff880068ace940 [ 2679.063474] setting up TCP socket for listening [ 2679.063479] svc: svc_setup_socket created ffff880060cd3c00 (inet ffff880060c95100) [ 2679.063484] NFS: Callback listener port = 49824 (af 2) [ 2679.063488] svc: creating transport tcp[0] [ 2679.063494] svc: svc_create_socket(NFSv4 callback, 6, 0000:0000:0000:0000:0000:0000:0000:0000, port=0) [ 2679.063530] svc: svc_setup_socket ffff880068acf440 [ 2679.063535] setting up TCP socket for listening [ 2679.063539] svc: svc_setup_socket created ffff880060cd4000 (inet ffff88007a1132c0) [ 2679.063544] NFS: Callback listener port = 56626 (af 10) [ 2679.063680] svc: svc_destroy(NFSv4 callback, 2) [ 2679.063686] --> nfs_get_client() = ffff8800685c3c00 [new] [ 2679.063691] <-- nfs4_set_client() = 0 [new ffff8800685c3c00] [ 2679.063750] <-- nfs4_init_server() = 0 [ 2679.063755] --> nfs4_get_rootfh() [ 2679.063761] RPC: creating UNIX authenticator for client ffff880060cb9c00 [ 2679.063770] RPC: new task initialized, procpid 6568 [ 2679.063774] RPC: allocated task ffff88007a80e400 [ 2679.063778] RPC: 1845 __rpc_execute flags=0x80 [ 2679.063783] RPC: 1845 call_start nfs4 proc LOOKUP_ROOT (sync) [ 2679.063788] RPC: 1845 call_reserve (status 0) [ 2679.063793] RPC: 1845 reserved req ffff88007a2d6000 xid 0a4bb2b3 [ 2679.063797] RPC: 1845 call_reserveresult (status 0) [ 2679.063802] RPC: 1845 call_refresh (status 0) [ 2679.063805] RPC: 1845 looking up UNIX cred [ 2679.063809] RPC: looking up UNIX cred [ 2679.063814] RPC: 1845 refreshing UNIX cred ffff880078fb6300 [ 2679.063818] RPC: 1845 call_refreshresult (status 0) [ 2679.063823] RPC: 1845 call_allocate (status 0) [ 2679.063828] RPC: 1845 allocated buffer of size 1064 at ffff880078e61800 [ 2679.063832] RPC: 1845 call_bind (status 0) [ 2679.063837] RPC: 1845 call_connect xprt ffff88007a346000 is connected [ 2679.063841] RPC: 1845 call_transmit (status 0) [ 2679.063845] RPC: 1845 xprt_prepare_transmit [ 2679.063849] RPC: 1845 rpc_xdr_encode (status 0) [ 2679.063854] RPC: 1845 marshaling UNIX cred ffff880078fb6300 [ 2679.063859] RPC: 1845 using AUTH_UNIX cred ffff880078fb6300 to wrap rpc data [ 2679.063865] encode_compound: tag= [ 2679.063870] RPC: 1845 xprt_transmit(152) [ 2679.088332] svc: server ffff88007a48e000 waiting for data (to = 9223372036854775807) [ 2679.088703] RPC: xs_tcp_send_request(152) = 152 [ 2679.088880] RPC: 1845 xmit complete [ 2679.089101] RPC: 1845 sleep_on(queue "xprt_pending" time 4297346385) [ 2679.089293] RPC: 1845 added to queue ffff88007a346320 "xprt_pending" [ 2679.089472] RPC: 1845 setting alarm for 60000 ms [ 2679.089649] RPC: wake_up_next(ffff88007a346258 "xprt_resend") [ 2679.089820] RPC: wake_up_next(ffff88007a346190 "xprt_sending") [ 2679.089991] RPC: 1845 sync task going to sleep [ 2679.090050] RPC: xs_tcp_data_ready... [ 2679.090055] RPC: xs_tcp_data_recv started [ 2679.090059] RPC: reading TCP record fragment of length 44 [ 2679.090063] RPC: reading XID (4 bytes) [ 2679.090067] RPC: reading reply for XID 0a4bb2b3 [ 2679.090071] RPC: reading CALL/REPLY flag (4 bytes) [ 2679.090075] RPC: read reply XID 0a4bb2b3 [ 2679.090080] RPC: XID 0a4bb2b3 read 36 bytes [ 2679.090085] RPC: xprt = ffff88007a346000, tcp_copied = 44, tcp_offset = 44, tcp_reclen = 44 [ 2679.090091] RPC: 1845 xid 0a4bb2b3 complete (44 bytes received) [ 2679.090098] RPC: 1845 __rpc_wake_up_task (now 4297346386) [ 2679.090102] RPC: 1845 disabling timer [ 2679.090107] RPC: 1845 removed from queue ffff88007a346320 "xprt_pending" [ 2679.090111] RPC: __rpc_wake_up_task done [ 2679.090114] RPC: xs_tcp_data_recv done [ 2679.092850] RPC: 1845 sync task resuming [ 2679.093042] RPC: 1845 call_status (status 44) [ 2679.093222] RPC: 1845 call_decode (status 44) [ 2679.093389] RPC: 1845 validating UNIX cred ffff880078fb6300 [ 2679.093561] RPC: 1845 using AUTH_UNIX cred ffff880078fb6300 to unwrap rpc data [ 2679.093890] RPC: 1845 call_decode result -1 [ 2679.094093] RPC: 1845 return 0, status -1 [ 2679.094266] RPC: 1845 release task [ 2679.094437] RPC: freeing buffer of size 1064 at ffff880078e61800 [ 2679.094608] RPC: 1845 release request ffff88007a2d6000 [ 2679.094776] RPC: wake_up_next(ffff88007a3463e8 "xprt_backlog") [ 2679.094945] RPC: rpc_release_client(ffff880060cb9c00) [ 2679.095151] RPC: 1845 freeing task [ 2679.095329] RPC: new task initialized, procpid 6568 [ 2679.095499] RPC: allocated task ffff88007a80e400 [ 2679.095669] RPC: 1846 __rpc_execute flags=0x80 [ 2679.095837] RPC: 1846 call_start nfs4 proc LOOKUP_ROOT (sync) [ 2679.096041] RPC: 1846 call_reserve (status 0) [ 2679.096215] RPC: 1846 reserved req ffff88007a2d6000 xid 0b4bb2b3 [ 2679.096386] RPC: 1846 call_reserveresult (status 0) [ 2679.096554] RPC: 1846 call_refresh (status 0) [ 2679.096722] RPC: 1846 looking up NULL cred [ 2679.096888] RPC: looking up NULL cred [ 2679.097091] RPC: 1846 refreshing NULL cred ffffffffa025da80 [ 2679.097268] RPC: 1846 call_refreshresult (status 0) [ 2679.097438] RPC: 1846 call_allocate (status 0) [ 2679.097606] RPC: 1846 allocated buffer of size 764 at ffff880078e61800 [ 2679.097779] RPC: 1846 call_bind (status 0) [ 2679.097945] RPC: 1846 call_connect xprt ffff88007a346000 is connected [ 2679.098152] RPC: 1846 call_transmit (status 0) [ 2679.098325] RPC: 1846 xprt_prepare_transmit [ 2679.098494] RPC: 1846 rpc_xdr_encode (status 0) [ 2679.098661] RPC: 1846 marshaling NULL cred ffffffffa025da80 [ 2679.098832] RPC: 1846 using AUTH_NULL cred ffffffffa025da80 to wrap rpc data [ 2679.099032] encode_compound: tag= [ 2679.099202] RPC: 1846 xprt_transmit(80) [ 2679.099396] RPC: xs_tcp_send_request(80) = 80 [ 2679.099564] RPC: 1846 xmit complete [ 2679.099730] RPC: 1846 sleep_on(queue "xprt_pending" time 4297346395) [ 2679.099902] RPC: 1846 added to queue ffff88007a346320 "xprt_pending" [ 2679.100111] RPC: 1846 setting alarm for 60000 ms [ 2679.100293] RPC: wake_up_next(ffff88007a346258 "xprt_resend") [ 2679.100466] RPC: wake_up_next(ffff88007a346190 "xprt_sending") [ 2679.100636] RPC: 1846 sync task going to sleep [ 2679.101060] RPC: xs_tcp_data_ready... [ 2679.101235] RPC: xs_tcp_data_recv started [ 2679.101403] RPC: reading TCP record fragment of length 44 [ 2679.101573] RPC: reading XID (4 bytes) [ 2679.101740] RPC: reading reply for XID 0b4bb2b3 [ 2679.101908] RPC: reading CALL/REPLY flag (4 bytes) [ 2679.102031] RPC: read reply XID 0b4bb2b3 [ 2679.102031] RPC: XID 0b4bb2b3 read 36 bytes [ 2679.102031] RPC: xprt = ffff88007a346000, tcp_copied = 44, tcp_offset = 44, tcp_reclen = 44 [ 2679.102031] RPC: 1846 xid 0b4bb2b3 complete (44 bytes received) [ 2679.102031] RPC: 1846 __rpc_wake_up_task (now 4297346398) [ 2679.102031] RPC: 1846 disabling timer [ 2679.102031] RPC: 1846 removed from queue ffff88007a346320 "xprt_pending" [ 2679.102031] RPC: __rpc_wake_up_task done [ 2679.103470] RPC: 1846 sync task resuming [ 2679.103475] RPC: 1846 call_status (status 44) [ 2679.103479] RPC: 1846 call_decode (status 44) [ 2679.103484] RPC: 1846 validating NULL cred ffffffffa025da80 [ 2679.103489] RPC: 1846 using AUTH_NULL cred ffffffffa025da80 to unwrap rpc data [ 2679.103494] RPC: 1846 call_decode result -1 [ 2679.103498] RPC: 1846 return 0, status -1 [ 2679.103501] RPC: 1846 release task [ 2679.102031] RPC: xs_tcp_data_recv done [ 2679.105115] RPC: freeing buffer of size 764 at ffff880078e61800 [ 2679.105121] RPC: 1846 release request ffff88007a2d6000 [ 2679.105126] RPC: wake_up_next(ffff88007a3463e8 "xprt_backlog") [ 2679.105131] RPC: rpc_release_client(ffff880060cb9c00) [ 2679.105135] RPC: 1846 freeing task [ 2679.105140] nfs4_get_rootfh: getroot error = 11 [ 2679.105144] <-- nfs4_get_rootfh() = -11 [ 2679.105147] --> nfs_free_server() [ 2679.116035] RPC: shutting down nfs client for build-toolchain [ 2679.116209] RPC: rpc_release_client(ffff880060cb9c00) [ 2679.116378] RPC: destroying nfs client for build-toolchain [ 2679.116588] RPC: rpc_release_client(ffff880067dfde00) [ 2679.116762] --> nfs_put_client({1}) [ 2679.116929] --> nfs_free_client(4) [ 2679.117134] svc: server ffff88007a48e000, no data yet [ 2679.117359] svc: svc_destroy(NFSv4 callback, 1) [ 2679.117529] svc: svc_delete_xprt(ffff880060cd4000) [ 2679.117696] svc: svc_tcp_sock_detach(ffff880060cd4000) [ 2679.117865] svc: svc_sock_detach(ffff880060cd4000) [ 2679.118074] svc: svc_sock_free(ffff880060cd4000) [ 2679.118266] svc: svc_delete_xprt(ffff880060cd3c00) [ 2679.118433] svc: svc_tcp_sock_detach(ffff880060cd3c00) [ 2679.118602] svc: svc_sock_detach(ffff880060cd3c00) [ 2679.118771] svc: svc_sock_free(ffff880060cd3c00) [ 2679.118946] RPC: unregistering [1073741824, 4, ''] with local rpcbind [ 2679.119157] RPC: new task initialized, procpid 6568 [ 2679.119333] RPC: allocated task ffff88007a80e400 [ 2679.119504] RPC: 1847 __rpc_execute flags=0x680 [ 2679.119672] RPC: 1847 call_start rpcbind4 proc UNSET (sync) [ 2679.119842] RPC: 1847 call_reserve (status 0) [ 2679.120039] RPC: 1847 reserved req ffff88011a39e000 xid c956cbbf [ 2679.120217] RPC: 1847 call_reserveresult (status 0) [ 2679.120387] RPC: 1847 call_refresh (status 0) [ 2679.120554] RPC: 1847 looking up UNIX cred [ 2679.120720] RPC: looking up UNIX cred [ 2679.120888] RPC: 1847 refreshing UNIX cred ffff880078fb6300 [ 2679.121093] RPC: 1847 call_refreshresult (status 0) [ 2679.121269] RPC: 1847 call_allocate (status 0) [ 2679.121439] RPC: 1847 allocated buffer of size 488 at ffff880078e66800 [ 2679.121611] RPC: 1847 call_bind (status 0) [ 2679.121778] RPC: 1847 call_connect xprt ffff88011a1e0000 is connected [ 2679.121950] RPC: 1847 call_transmit (status 0) [ 2679.122153] RPC: 1847 xprt_prepare_transmit [ 2679.122327] RPC: 1847 rpc_xdr_encode (status 0) [ 2679.122498] RPC: 1847 marshaling UNIX cred ffff880078fb6300 [ 2679.122669] RPC: 1847 using AUTH_UNIX cred ffff880078fb6300 to wrap rpc data [ 2679.122843] RPC: 1847 encoding RPCB_UNSET call (1073741824, 4, '', '') [ 2679.123040] RPC: 1847 xprt_transmit(140) [ 2679.123253] RPC: xs_tcp_send_request(140) = 140 [ 2679.123425] RPC: 1847 xmit complete [ 2679.123594] RPC: xs_tcp_data_ready... [ 2679.123599] RPC: xs_tcp_data_recv started [ 2679.123604] RPC: reading TCP record fragment of length 28 [ 2679.123608] RPC: reading XID (4 bytes) [ 2679.123613] RPC: reading reply for XID c956cbbf [ 2679.123617] RPC: reading CALL/REPLY flag (4 bytes) [ 2679.123621] RPC: read reply XID c956cbbf [ 2679.123626] RPC: XID c956cbbf read 20 bytes [ 2679.123631] RPC: xprt = ffff88011a1e0000, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28 [ 2679.123637] RPC: 1847 xid c956cbbf complete (28 bytes received) [ 2679.123644] RPC: xs_tcp_data_recv done [ 2679.125634] RPC: wake_up_next(ffff88011a1e0258 "xprt_resend") [ 2679.125817] RPC: wake_up_next(ffff88011a1e0190 "xprt_sending") [ 2679.125990] RPC: 1847 call_status (status 28) [ 2679.126193] RPC: 1847 call_decode (status 28) [ 2679.131579] RPC: 1847 validating UNIX cred ffff880078fb6300 [ 2679.131750] RPC: 1847 using AUTH_UNIX cred ffff880078fb6300 to unwrap rpc data [ 2679.132108] RPC: 1847 RPCB_UNSET call succeeded [ 2679.132281] RPC: 1847 call_decode result 0 [ 2679.132448] RPC: 1847 return 0, status 0 [ 2679.132613] RPC: 1847 release task [ 2679.132780] RPC: freeing buffer of size 488 at ffff880078e66800 [ 2679.132951] RPC: 1847 release request ffff88011a39e000 [ 2679.133151] RPC: wake_up_next(ffff88011a1e03e8 "xprt_backlog") [ 2679.133329] RPC: rpc_release_client(ffff88011a88cc00) [ 2679.133501] RPC: 1847 freeing task [ 2679.133667] svc: __svc_unregister(NFSv4 callbackv4), error 0 [ 2679.133853] NFS: releasing client cookie (0xffff8800685c3c00/0xffff88007a2c2e10) [ 2679.134228] RPC: shutting down nfs client for build-toolchain [ 2679.134405] RPC: rpc_release_client(ffff880067dfde00) [ 2679.134574] RPC: destroying nfs client for build-toolchain [ 2679.134771] RPC: destroying transport ffff88007a346000 [ 2679.134948] RPC: xs_destroy xprt ffff88007a346000 [ 2679.135156] RPC: xs_close xprt ffff88007a346000 [ 2679.135358] RPC: disconnected transport ffff88007a346000 [ 2679.135535] <-- nfs_free_client() [ 2679.135716] <-- nfs_free_server() [ 2679.135880] <-- nfs4_create_server() = error -11 [ 2679.136096] <-- nfs4_try_mount() = -11 [error] Thanks. -- Dmitry ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) 2011-03-31 16:50 ` Dmitry Torokhov @ 2011-03-31 17:15 ` Bryan Schumaker 2011-03-31 17:19 ` Dmitry Torokhov 0 siblings, 1 reply; 9+ messages in thread From: Bryan Schumaker @ 2011-03-31 17:15 UTC (permalink / raw) To: Dmitry Torokhov; +Cc: linux-kernel@vger.kernel.org, Trond Myklebust Thanks for the log and extra info. What setting does the server use to export /toolchain? You can usually find this in /etc/exports, but it may be different for NIS. I would like to set up my NFS server in a similar way so I can try to reproduce what you're seeing. Thanks Bryan On 03/31/2011 12:50 PM, Dmitry Torokhov wrote: > On Thu, Mar 31, 2011 at 09:23:38AM -0700, Dmitry Torokhov wrote: >> Hi Bryan, >> >> On Wed, Mar 30, 2011 at 03:31:44PM -0700, Dmitry Torokhov wrote: >>> Hi Bryan, >>> >>> It is actually one of autofs + NIS, mounts that is failing. >>> >> >> Some more data about NFS problemi I am seeing. With an older kernel I >> get: >> >> [dtor@dtor-d630 ~]$ sudo mount -v build-toolchain:/toolchain /mnt/ >> mount: no type was given - I'll assume nfs because of the colon >> mount.nfs: timeout set for Thu Mar 31 09:17:38 2011 >> mount.nfs: trying text-based options 'vers=4,addr=10.17.52.98,clientaddr=10.20.94.47' >> mount.nfs: mount(2): Operation not permitted >> mount.nfs: trying text-based options 'addr=10.17.52.98' >> mount.nfs: prog 100003, trying vers=3, prot=6 >> mount.nfs: trying 10.17.52.98 prog 100003 vers 3 prot TCP port 2049 >> mount.nfs: prog 100005, trying vers=3, prot=17 >> mount.nfs: trying 10.17.52.98 prog 100005 vers 3 prot UDP port 693 >> build-toolchain:/toolchain on /mnt type nfs (rw) >> >> The failing kernel does it like this: >> >> [dtor@dtor-ws ~]$ sudo mount -v build-toolchain:/toolchain /mnt >> mount: no type was given - I'll assume nfs because of the colon >> mount.nfs: timeout set for Thu Mar 31 09:14:22 2011 >> mount.nfs: trying text-based options 'vers=4,addr=10.17.52.98,clientaddr=10.20.94.123' >> mount.nfs: mount(2): Resource temporarily unavailable >> mount.nfs: Resource temporarily unavailable >> >> And I can mount it successfully if I explicitly request V3: >> >> [dtor@dtor-ws ~]$ sudo mount -v -o nfsvers=3 build-toolchain:/toolchain /mnt/ >> mount: no type was given - I'll assume nfs because of the colon >> mount.nfs: timeout set for Thu Mar 31 09:22:57 2011 >> mount.nfs: trying text-based options 'nfsvers=3,addr=10.17.52.98' >> mount.nfs: prog 100003, trying vers=3, prot=6 >> mount.nfs: trying 10.17.52.98 prog 100003 vers 3 prot TCP port 2049 >> mount.nfs: prog 100005, trying vers=3, prot=17 >> mount.nfs: trying 10.17.52.98 prog 100005 vers 3 prot UDP port 693 >> build-toolchain:/toolchain on /mnt type nfs (rw,nfsvers=3) >> >> The mounts that succeed automatically with the newer kernel do like >> this: >> >> [dtor@dtor-ws ~]$ sudo mount -v pa-home:/home2 /mnt/ >> mount: no type was given - I'll assume nfs because of the colon >> mount.nfs: timeout set for Thu Mar 31 09:20:01 2011 >> mount.nfs: trying text-based options 'vers=4,addr=10.17.4.25,clientaddr=10.20.94.123' >> mount.nfs: mount(2): Protocol not supported >> mount.nfs: trying text-based options 'addr=10.17.4.25' >> mount.nfs: prog 100003, trying vers=3, prot=6 >> mount.nfs: trying 10.17.4.25 prog 100003 vers 3 prot TCP port 2049 >> mount.nfs: prog 100005, trying vers=3, prot=17 >> mount.nfs: trying 10.17.4.25 prog 100005 vers 3 prot UDP port 1234 >> pa-home:/home2 on /mnt type nfs (rw) >> >> I am not sure why in failing case we are seeing "resource temporarily >> unavailable" instead of "protocol not supported". >> > > And here is the kernel log with debuggig enabled. Sorry for multiple > posts BTW. > > [ 2679.038558] NFS: nfs mount opts='vers=4,addr=10.17.52.98,clientaddr=10.20.94.123' > [ 2679.038910] NFS: parsing nfs mount option 'vers=4' > [ 2679.039126] NFS: parsing nfs mount option 'addr=10.17.52.98' > [ 2679.039307] NFS: parsing nfs mount option 'clientaddr=10.20.94.123' > [ 2679.039490] NFS: MNTPATH: '/toolchain' > [ 2679.039659] --> nfs4_try_mount() > [ 2679.039837] --> nfs4_create_server() > [ 2679.040198] --> nfs4_init_server() > [ 2679.040365] --> nfs4_set_client() > [ 2679.040559] --> nfs_get_client(build-toolchain,v4) > [ 2679.040733] RPC: looking up machine cred > [ 2679.040909] NFS: get client cookie (0xffff8800685c3c00/0xffff88007a2c2e10) > [ 2679.041143] RPC: set up xprt to 10.17.52.98 (port 2049) via tcp > [ 2679.041324] RPC: created transport ffff88007a346000 with 16 slots > [ 2679.041501] RPC: creating nfs client for build-toolchain (xprt ffff88007a346000) > [ 2679.041895] RPC: creating UNIX authenticator for client ffff880067dfde00 > [ 2679.042273] RPC: new task initialized, procpid 6568 > [ 2679.042447] RPC: allocated task ffff880060c6d100 > [ 2679.042618] RPC: 1843 __rpc_execute flags=0x680 > [ 2679.042787] RPC: 1843 call_start nfs4 proc NULL (sync) > [ 2679.042957] RPC: 1843 call_reserve (status 0) > [ 2679.048338] RPC: 1843 reserved req ffff88007a2d6000 xid 094bb2b3 > [ 2679.048513] RPC: 1843 call_reserveresult (status 0) > [ 2679.048688] RPC: 1843 call_refresh (status 0) > [ 2679.048860] RPC: 1843 holding NULL cred ffffffffa025da80 > [ 2679.049060] RPC: 1843 refreshing NULL cred ffffffffa025da80 > [ 2679.049243] RPC: 1843 call_refreshresult (status 0) > [ 2679.049426] RPC: 1843 call_allocate (status 0) > [ 2679.049635] RPC: 1843 allocated buffer of size 96 at ffff88007a343800 > [ 2679.049819] RPC: 1843 call_bind (status 0) > [ 2679.049990] RPC: 1843 call_connect xprt ffff88007a346000 is not connected > [ 2679.050200] RPC: 1843 xprt_connect xprt ffff88007a346000 is not connected > [ 2679.050379] RPC: 1843 sleep_on(queue "xprt_pending" time 4297346346) > [ 2679.050556] RPC: 1843 added to queue ffff88007a346320 "xprt_pending" > [ 2679.050732] RPC: 1843 setting alarm for 60000 ms > [ 2679.050901] RPC: xs_connect scheduled xprt ffff88007a346000 > [ 2679.051114] RPC: 1843 sync task going to sleep > [ 2679.051312] RPC: xs_bind 0.0.0.0:1013: ok (0) > [ 2679.051486] RPC: worker connecting xprt ffff88007a346000 via tcp to 10.17.52.98 (port 2049) > [ 2679.051857] RPC: ffff88007a346000 connect status 115 connected 0 sock state 2 > [ 2679.052997] RPC: xs_tcp_state_change client ffff88007a346000... > [ 2679.053190] RPC: state 1 conn 0 dead 0 zapped -1 sk_shutdown 0 > [ 2679.053361] RPC: 1843 __rpc_wake_up_task (now 4297346349) > [ 2679.053529] RPC: 1843 disabling timer > [ 2679.053696] RPC: 1843 removed from queue ffff88007a346320 "xprt_pending" > [ 2679.053870] RPC: __rpc_wake_up_task done > [ 2679.053961] RPC: 1843 sync task resuming > [ 2679.053961] RPC: 1843 xprt_connect_status: retrying > [ 2679.053961] RPC: 1843 call_connect_status (status -11) > [ 2679.053961] RPC: 1843 call_transmit (status 0) > [ 2679.053961] RPC: 1843 xprt_prepare_transmit > [ 2679.053961] RPC: 1843 rpc_xdr_encode (status 0) > [ 2679.055137] RPC: 1843 marshaling NULL cred ffffffffa025da80 > [ 2679.055311] RPC: 1843 using AUTH_NULL cred ffffffffa025da80 to wrap rpc data > [ 2679.055488] RPC: 1843 xprt_transmit(44) > [ 2679.055687] RPC: xs_tcp_send_request(44) = 44 > [ 2679.055866] RPC: 1843 xmit complete > [ 2679.056068] RPC: 1843 sleep_on(queue "xprt_pending" time 4297346352) > [ 2679.056245] RPC: 1843 added to queue ffff88007a346320 "xprt_pending" > [ 2679.056421] RPC: 1843 setting alarm for 60000 ms > [ 2679.056590] RPC: wake_up_next(ffff88007a346258 "xprt_resend") > [ 2679.056761] RPC: wake_up_next(ffff88007a346190 "xprt_sending") > [ 2679.056932] RPC: 1843 sync task going to sleep > [ 2679.057243] RPC: xs_tcp_data_ready... > [ 2679.057412] RPC: xs_tcp_data_recv started > [ 2679.057580] RPC: reading TCP record fragment of length 24 > [ 2679.057749] RPC: reading XID (4 bytes) > [ 2679.057916] RPC: reading request with XID 094bb2b3 > [ 2679.058122] RPC: reading CALL/REPLY flag (4 bytes) > [ 2679.058299] RPC: read reply XID 094bb2b3 > [ 2679.058467] RPC: XID 094bb2b3 read 16 bytes > [ 2679.058635] RPC: xprt = ffff88007a346000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24 > [ 2679.058966] RPC: 1843 xid 094bb2b3 complete (24 bytes received) > [ 2679.059166] RPC: 1843 __rpc_wake_up_task (now 4297346355) > [ 2679.059341] RPC: 1843 disabling timer > [ 2679.059507] RPC: 1843 removed from queue ffff88007a346320 "xprt_pending" > [ 2679.059684] RPC: __rpc_wake_up_task done > [ 2679.059700] RPC: 1843 sync task resuming > [ 2679.059709] RPC: 1843 call_status (status 24) > [ 2679.059714] RPC: 1843 call_decode (status 24) > [ 2679.059722] RPC: 1843 validating NULL cred ffffffffa025da80 > [ 2679.059729] RPC: 1843 using AUTH_NULL cred ffffffffa025da80 to unwrap rpc data > [ 2679.059734] RPC: 1843 call_decode result 0 > [ 2679.059739] RPC: 1843 return 0, status 0 > [ 2679.059742] RPC: 1843 release task > [ 2679.061339] RPC: xs_tcp_data_recv done > [ 2679.061344] RPC: freeing buffer of size 96 at ffff88007a343800 > [ 2679.061353] RPC: 1843 release request ffff88007a2d6000 > [ 2679.061358] RPC: wake_up_next(ffff88007a3463e8 "xprt_backlog") > [ 2679.061364] RPC: rpc_release_client(ffff880067dfde00) > [ 2679.061370] RPC: 1843 freeing task > [ 2679.061477] svc: initialising pool 0 for NFSv4 callback > [ 2679.061484] RPC: unregistering [1073741824, 4, ''] with local rpcbind > [ 2679.061492] RPC: new task initialized, procpid 6568 > [ 2679.061496] RPC: allocated task ffff88007a80e400 > [ 2679.061502] RPC: 1844 __rpc_execute flags=0x680 > [ 2679.061508] RPC: 1844 call_start rpcbind4 proc UNSET (sync) > [ 2679.061514] RPC: 1844 call_reserve (status 0) > [ 2679.061520] RPC: 1844 reserved req ffff88011a39e000 xid c856cbbf > [ 2679.061525] RPC: 1844 call_reserveresult (status 0) > [ 2679.061529] RPC: 1844 call_refresh (status 0) > [ 2679.061533] RPC: 1844 looking up UNIX cred > [ 2679.061536] RPC: looking up UNIX cred > [ 2679.061543] RPC: 1844 refreshing UNIX cred ffff880078fb6300 > [ 2679.061548] RPC: 1844 call_refreshresult (status 0) > [ 2679.061552] RPC: 1844 call_allocate (status 0) > [ 2679.061558] RPC: 1844 allocated buffer of size 488 at ffff88007aaa9000 > [ 2679.061563] RPC: 1844 call_bind (status 0) > [ 2679.061568] RPC: 1844 call_connect xprt ffff88011a1e0000 is not connected > [ 2679.061574] RPC: 1844 xprt_connect xprt ffff88011a1e0000 is not connected > [ 2679.061580] RPC: 1844 sleep_on(queue "xprt_pending" time 4297346357) > [ 2679.061586] RPC: 1844 added to queue ffff88011a1e0320 "xprt_pending" > [ 2679.061590] RPC: 1844 setting alarm for 60000 ms > [ 2679.061596] RPC: xs_connect scheduled xprt ffff88011a1e0000 > [ 2679.061611] RPC: 1844 sync task going to sleep > [ 2679.061624] RPC: disconnecting xprt ffff88011a1e0000 to reuse port > [ 2679.061636] RPC: xs_error_report client ffff88011a1e0000... > [ 2679.061639] RPC: error 0 > [ 2679.061643] RPC: 1844 __rpc_wake_up_task (now 4297346357) > [ 2679.061646] RPC: 1844 disabling timer > [ 2679.061651] RPC: 1844 removed from queue ffff88011a1e0320 "xprt_pending" > [ 2679.061660] RPC: __rpc_wake_up_task done > [ 2679.061666] RPC: disconnected transport ffff88011a1e0000 > [ 2679.061672] RPC: worker connecting xprt ffff88011a1e0000 via tcp to 127.0.0.1 (port 111) > [ 2679.061810] RPC: xs_tcp_state_change client ffff88011a1e0000... > [ 2679.061816] RPC: state 1 conn 0 dead 0 zapped -1 sk_shutdown 0 > [ 2679.061875] RPC: ffff88011a1e0000 connect status 115 connected 1 sock state 1 > [ 2679.062854] RPC: 1844 sync task resuming > [ 2679.062859] RPC: 1844 xprt_connect_status: retrying > [ 2679.062863] RPC: 1844 call_connect_status (status -11) > [ 2679.062868] RPC: 1844 call_transmit (status 0) > [ 2679.062872] RPC: 1844 xprt_prepare_transmit > [ 2679.062876] RPC: 1844 rpc_xdr_encode (status 0) > [ 2679.062881] RPC: 1844 marshaling UNIX cred ffff880078fb6300 > [ 2679.062888] RPC: 1844 using AUTH_UNIX cred ffff880078fb6300 to wrap rpc data > [ 2679.062895] RPC: 1844 encoding RPCB_UNSET call (1073741824, 4, '', '') > [ 2679.062900] RPC: 1844 xprt_transmit(140) > [ 2679.063269] RPC: xs_tcp_data_ready... > [ 2679.063274] RPC: xs_tcp_data_recv started > [ 2679.063279] RPC: reading TCP record fragment of length 28 > [ 2679.063283] RPC: reading XID (4 bytes) > [ 2679.063288] RPC: reading request with XID c856cbbf > [ 2679.063292] RPC: reading CALL/REPLY flag (4 bytes) > [ 2679.063296] RPC: read reply XID c856cbbf > [ 2679.063302] RPC: XID c856cbbf read 20 bytes > [ 2679.063307] RPC: xprt = ffff88011a1e0000, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28 > [ 2679.063313] RPC: 1844 xid c856cbbf complete (28 bytes received) > [ 2679.063319] RPC: xs_tcp_data_recv done > [ 2679.063334] RPC: xs_tcp_send_request(140) = 140 > [ 2679.063338] RPC: 1844 xmit complete > [ 2679.063344] RPC: wake_up_next(ffff88011a1e0258 "xprt_resend") > [ 2679.063349] RPC: wake_up_next(ffff88011a1e0190 "xprt_sending") > [ 2679.063354] RPC: 1844 call_status (status 28) > [ 2679.063358] RPC: 1844 call_decode (status 28) > [ 2679.063363] RPC: 1844 validating UNIX cred ffff880078fb6300 > [ 2679.063368] RPC: 1844 using AUTH_UNIX cred ffff880078fb6300 to unwrap rpc data > [ 2679.063373] RPC: 1844 RPCB_UNSET call succeeded > [ 2679.063377] RPC: 1844 call_decode result 0 > [ 2679.063381] RPC: 1844 return 0, status 0 > [ 2679.063384] RPC: 1844 release task > [ 2679.063390] RPC: freeing buffer of size 488 at ffff88007aaa9000 > [ 2679.063396] RPC: 1844 release request ffff88011a39e000 > [ 2679.063400] RPC: wake_up_next(ffff88011a1e03e8 "xprt_backlog") > [ 2679.063405] RPC: rpc_release_client(ffff88011a88cc00) > [ 2679.063410] RPC: 1844 freeing task > [ 2679.063417] svc: __svc_unregister(NFSv4 callbackv4), error 0 > [ 2679.063423] svc: creating transport tcp[0] > [ 2679.063431] svc: svc_create_socket(NFSv4 callback, 6, 0.0.0.0, port=0) > [ 2679.063468] svc: svc_setup_socket ffff880068ace940 > [ 2679.063474] setting up TCP socket for listening > [ 2679.063479] svc: svc_setup_socket created ffff880060cd3c00 (inet ffff880060c95100) > [ 2679.063484] NFS: Callback listener port = 49824 (af 2) > [ 2679.063488] svc: creating transport tcp[0] > [ 2679.063494] svc: svc_create_socket(NFSv4 callback, 6, 0000:0000:0000:0000:0000:0000:0000:0000, port=0) > [ 2679.063530] svc: svc_setup_socket ffff880068acf440 > [ 2679.063535] setting up TCP socket for listening > [ 2679.063539] svc: svc_setup_socket created ffff880060cd4000 (inet ffff88007a1132c0) > [ 2679.063544] NFS: Callback listener port = 56626 (af 10) > [ 2679.063680] svc: svc_destroy(NFSv4 callback, 2) > [ 2679.063686] --> nfs_get_client() = ffff8800685c3c00 [new] > [ 2679.063691] <-- nfs4_set_client() = 0 [new ffff8800685c3c00] > [ 2679.063750] <-- nfs4_init_server() = 0 > [ 2679.063755] --> nfs4_get_rootfh() > [ 2679.063761] RPC: creating UNIX authenticator for client ffff880060cb9c00 > [ 2679.063770] RPC: new task initialized, procpid 6568 > [ 2679.063774] RPC: allocated task ffff88007a80e400 > [ 2679.063778] RPC: 1845 __rpc_execute flags=0x80 > [ 2679.063783] RPC: 1845 call_start nfs4 proc LOOKUP_ROOT (sync) > [ 2679.063788] RPC: 1845 call_reserve (status 0) > [ 2679.063793] RPC: 1845 reserved req ffff88007a2d6000 xid 0a4bb2b3 > [ 2679.063797] RPC: 1845 call_reserveresult (status 0) > [ 2679.063802] RPC: 1845 call_refresh (status 0) > [ 2679.063805] RPC: 1845 looking up UNIX cred > [ 2679.063809] RPC: looking up UNIX cred > [ 2679.063814] RPC: 1845 refreshing UNIX cred ffff880078fb6300 > [ 2679.063818] RPC: 1845 call_refreshresult (status 0) > [ 2679.063823] RPC: 1845 call_allocate (status 0) > [ 2679.063828] RPC: 1845 allocated buffer of size 1064 at ffff880078e61800 > [ 2679.063832] RPC: 1845 call_bind (status 0) > [ 2679.063837] RPC: 1845 call_connect xprt ffff88007a346000 is connected > [ 2679.063841] RPC: 1845 call_transmit (status 0) > [ 2679.063845] RPC: 1845 xprt_prepare_transmit > [ 2679.063849] RPC: 1845 rpc_xdr_encode (status 0) > [ 2679.063854] RPC: 1845 marshaling UNIX cred ffff880078fb6300 > [ 2679.063859] RPC: 1845 using AUTH_UNIX cred ffff880078fb6300 to wrap rpc data > [ 2679.063865] encode_compound: tag= > [ 2679.063870] RPC: 1845 xprt_transmit(152) > [ 2679.088332] svc: server ffff88007a48e000 waiting for data (to = 9223372036854775807) > [ 2679.088703] RPC: xs_tcp_send_request(152) = 152 > [ 2679.088880] RPC: 1845 xmit complete > [ 2679.089101] RPC: 1845 sleep_on(queue "xprt_pending" time 4297346385) > [ 2679.089293] RPC: 1845 added to queue ffff88007a346320 "xprt_pending" > [ 2679.089472] RPC: 1845 setting alarm for 60000 ms > [ 2679.089649] RPC: wake_up_next(ffff88007a346258 "xprt_resend") > [ 2679.089820] RPC: wake_up_next(ffff88007a346190 "xprt_sending") > [ 2679.089991] RPC: 1845 sync task going to sleep > [ 2679.090050] RPC: xs_tcp_data_ready... > [ 2679.090055] RPC: xs_tcp_data_recv started > [ 2679.090059] RPC: reading TCP record fragment of length 44 > [ 2679.090063] RPC: reading XID (4 bytes) > [ 2679.090067] RPC: reading reply for XID 0a4bb2b3 > [ 2679.090071] RPC: reading CALL/REPLY flag (4 bytes) > [ 2679.090075] RPC: read reply XID 0a4bb2b3 > [ 2679.090080] RPC: XID 0a4bb2b3 read 36 bytes > [ 2679.090085] RPC: xprt = ffff88007a346000, tcp_copied = 44, tcp_offset = 44, tcp_reclen = 44 > [ 2679.090091] RPC: 1845 xid 0a4bb2b3 complete (44 bytes received) > [ 2679.090098] RPC: 1845 __rpc_wake_up_task (now 4297346386) > [ 2679.090102] RPC: 1845 disabling timer > [ 2679.090107] RPC: 1845 removed from queue ffff88007a346320 "xprt_pending" > [ 2679.090111] RPC: __rpc_wake_up_task done > [ 2679.090114] RPC: xs_tcp_data_recv done > [ 2679.092850] RPC: 1845 sync task resuming > [ 2679.093042] RPC: 1845 call_status (status 44) > [ 2679.093222] RPC: 1845 call_decode (status 44) > [ 2679.093389] RPC: 1845 validating UNIX cred ffff880078fb6300 > [ 2679.093561] RPC: 1845 using AUTH_UNIX cred ffff880078fb6300 to unwrap rpc data > [ 2679.093890] RPC: 1845 call_decode result -1 > [ 2679.094093] RPC: 1845 return 0, status -1 > [ 2679.094266] RPC: 1845 release task > [ 2679.094437] RPC: freeing buffer of size 1064 at ffff880078e61800 > [ 2679.094608] RPC: 1845 release request ffff88007a2d6000 > [ 2679.094776] RPC: wake_up_next(ffff88007a3463e8 "xprt_backlog") > [ 2679.094945] RPC: rpc_release_client(ffff880060cb9c00) > [ 2679.095151] RPC: 1845 freeing task > [ 2679.095329] RPC: new task initialized, procpid 6568 > [ 2679.095499] RPC: allocated task ffff88007a80e400 > [ 2679.095669] RPC: 1846 __rpc_execute flags=0x80 > [ 2679.095837] RPC: 1846 call_start nfs4 proc LOOKUP_ROOT (sync) > [ 2679.096041] RPC: 1846 call_reserve (status 0) > [ 2679.096215] RPC: 1846 reserved req ffff88007a2d6000 xid 0b4bb2b3 > [ 2679.096386] RPC: 1846 call_reserveresult (status 0) > [ 2679.096554] RPC: 1846 call_refresh (status 0) > [ 2679.096722] RPC: 1846 looking up NULL cred > [ 2679.096888] RPC: looking up NULL cred > [ 2679.097091] RPC: 1846 refreshing NULL cred ffffffffa025da80 > [ 2679.097268] RPC: 1846 call_refreshresult (status 0) > [ 2679.097438] RPC: 1846 call_allocate (status 0) > [ 2679.097606] RPC: 1846 allocated buffer of size 764 at ffff880078e61800 > [ 2679.097779] RPC: 1846 call_bind (status 0) > [ 2679.097945] RPC: 1846 call_connect xprt ffff88007a346000 is connected > [ 2679.098152] RPC: 1846 call_transmit (status 0) > [ 2679.098325] RPC: 1846 xprt_prepare_transmit > [ 2679.098494] RPC: 1846 rpc_xdr_encode (status 0) > [ 2679.098661] RPC: 1846 marshaling NULL cred ffffffffa025da80 > [ 2679.098832] RPC: 1846 using AUTH_NULL cred ffffffffa025da80 to wrap rpc data > [ 2679.099032] encode_compound: tag= > [ 2679.099202] RPC: 1846 xprt_transmit(80) > [ 2679.099396] RPC: xs_tcp_send_request(80) = 80 > [ 2679.099564] RPC: 1846 xmit complete > [ 2679.099730] RPC: 1846 sleep_on(queue "xprt_pending" time 4297346395) > [ 2679.099902] RPC: 1846 added to queue ffff88007a346320 "xprt_pending" > [ 2679.100111] RPC: 1846 setting alarm for 60000 ms > [ 2679.100293] RPC: wake_up_next(ffff88007a346258 "xprt_resend") > [ 2679.100466] RPC: wake_up_next(ffff88007a346190 "xprt_sending") > [ 2679.100636] RPC: 1846 sync task going to sleep > [ 2679.101060] RPC: xs_tcp_data_ready... > [ 2679.101235] RPC: xs_tcp_data_recv started > [ 2679.101403] RPC: reading TCP record fragment of length 44 > [ 2679.101573] RPC: reading XID (4 bytes) > [ 2679.101740] RPC: reading reply for XID 0b4bb2b3 > [ 2679.101908] RPC: reading CALL/REPLY flag (4 bytes) > [ 2679.102031] RPC: read reply XID 0b4bb2b3 > [ 2679.102031] RPC: XID 0b4bb2b3 read 36 bytes > [ 2679.102031] RPC: xprt = ffff88007a346000, tcp_copied = 44, tcp_offset = 44, tcp_reclen = 44 > [ 2679.102031] RPC: 1846 xid 0b4bb2b3 complete (44 bytes received) > [ 2679.102031] RPC: 1846 __rpc_wake_up_task (now 4297346398) > [ 2679.102031] RPC: 1846 disabling timer > [ 2679.102031] RPC: 1846 removed from queue ffff88007a346320 "xprt_pending" > [ 2679.102031] RPC: __rpc_wake_up_task done > [ 2679.103470] RPC: 1846 sync task resuming > [ 2679.103475] RPC: 1846 call_status (status 44) > [ 2679.103479] RPC: 1846 call_decode (status 44) > [ 2679.103484] RPC: 1846 validating NULL cred ffffffffa025da80 > [ 2679.103489] RPC: 1846 using AUTH_NULL cred ffffffffa025da80 to unwrap rpc data > [ 2679.103494] RPC: 1846 call_decode result -1 > [ 2679.103498] RPC: 1846 return 0, status -1 > [ 2679.103501] RPC: 1846 release task > [ 2679.102031] RPC: xs_tcp_data_recv done > [ 2679.105115] RPC: freeing buffer of size 764 at ffff880078e61800 > [ 2679.105121] RPC: 1846 release request ffff88007a2d6000 > [ 2679.105126] RPC: wake_up_next(ffff88007a3463e8 "xprt_backlog") > [ 2679.105131] RPC: rpc_release_client(ffff880060cb9c00) > [ 2679.105135] RPC: 1846 freeing task > [ 2679.105140] nfs4_get_rootfh: getroot error = 11 > [ 2679.105144] <-- nfs4_get_rootfh() = -11 > [ 2679.105147] --> nfs_free_server() > [ 2679.116035] RPC: shutting down nfs client for build-toolchain > [ 2679.116209] RPC: rpc_release_client(ffff880060cb9c00) > [ 2679.116378] RPC: destroying nfs client for build-toolchain > [ 2679.116588] RPC: rpc_release_client(ffff880067dfde00) > [ 2679.116762] --> nfs_put_client({1}) > [ 2679.116929] --> nfs_free_client(4) > [ 2679.117134] svc: server ffff88007a48e000, no data yet > [ 2679.117359] svc: svc_destroy(NFSv4 callback, 1) > [ 2679.117529] svc: svc_delete_xprt(ffff880060cd4000) > [ 2679.117696] svc: svc_tcp_sock_detach(ffff880060cd4000) > [ 2679.117865] svc: svc_sock_detach(ffff880060cd4000) > [ 2679.118074] svc: svc_sock_free(ffff880060cd4000) > [ 2679.118266] svc: svc_delete_xprt(ffff880060cd3c00) > [ 2679.118433] svc: svc_tcp_sock_detach(ffff880060cd3c00) > [ 2679.118602] svc: svc_sock_detach(ffff880060cd3c00) > [ 2679.118771] svc: svc_sock_free(ffff880060cd3c00) > [ 2679.118946] RPC: unregistering [1073741824, 4, ''] with local rpcbind > [ 2679.119157] RPC: new task initialized, procpid 6568 > [ 2679.119333] RPC: allocated task ffff88007a80e400 > [ 2679.119504] RPC: 1847 __rpc_execute flags=0x680 > [ 2679.119672] RPC: 1847 call_start rpcbind4 proc UNSET (sync) > [ 2679.119842] RPC: 1847 call_reserve (status 0) > [ 2679.120039] RPC: 1847 reserved req ffff88011a39e000 xid c956cbbf > [ 2679.120217] RPC: 1847 call_reserveresult (status 0) > [ 2679.120387] RPC: 1847 call_refresh (status 0) > [ 2679.120554] RPC: 1847 looking up UNIX cred > [ 2679.120720] RPC: looking up UNIX cred > [ 2679.120888] RPC: 1847 refreshing UNIX cred ffff880078fb6300 > [ 2679.121093] RPC: 1847 call_refreshresult (status 0) > [ 2679.121269] RPC: 1847 call_allocate (status 0) > [ 2679.121439] RPC: 1847 allocated buffer of size 488 at ffff880078e66800 > [ 2679.121611] RPC: 1847 call_bind (status 0) > [ 2679.121778] RPC: 1847 call_connect xprt ffff88011a1e0000 is connected > [ 2679.121950] RPC: 1847 call_transmit (status 0) > [ 2679.122153] RPC: 1847 xprt_prepare_transmit > [ 2679.122327] RPC: 1847 rpc_xdr_encode (status 0) > [ 2679.122498] RPC: 1847 marshaling UNIX cred ffff880078fb6300 > [ 2679.122669] RPC: 1847 using AUTH_UNIX cred ffff880078fb6300 to wrap rpc data > [ 2679.122843] RPC: 1847 encoding RPCB_UNSET call (1073741824, 4, '', '') > [ 2679.123040] RPC: 1847 xprt_transmit(140) > [ 2679.123253] RPC: xs_tcp_send_request(140) = 140 > [ 2679.123425] RPC: 1847 xmit complete > [ 2679.123594] RPC: xs_tcp_data_ready... > [ 2679.123599] RPC: xs_tcp_data_recv started > [ 2679.123604] RPC: reading TCP record fragment of length 28 > [ 2679.123608] RPC: reading XID (4 bytes) > [ 2679.123613] RPC: reading reply for XID c956cbbf > [ 2679.123617] RPC: reading CALL/REPLY flag (4 bytes) > [ 2679.123621] RPC: read reply XID c956cbbf > [ 2679.123626] RPC: XID c956cbbf read 20 bytes > [ 2679.123631] RPC: xprt = ffff88011a1e0000, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28 > [ 2679.123637] RPC: 1847 xid c956cbbf complete (28 bytes received) > [ 2679.123644] RPC: xs_tcp_data_recv done > [ 2679.125634] RPC: wake_up_next(ffff88011a1e0258 "xprt_resend") > [ 2679.125817] RPC: wake_up_next(ffff88011a1e0190 "xprt_sending") > [ 2679.125990] RPC: 1847 call_status (status 28) > [ 2679.126193] RPC: 1847 call_decode (status 28) > [ 2679.131579] RPC: 1847 validating UNIX cred ffff880078fb6300 > [ 2679.131750] RPC: 1847 using AUTH_UNIX cred ffff880078fb6300 to unwrap rpc data > [ 2679.132108] RPC: 1847 RPCB_UNSET call succeeded > [ 2679.132281] RPC: 1847 call_decode result 0 > [ 2679.132448] RPC: 1847 return 0, status 0 > [ 2679.132613] RPC: 1847 release task > [ 2679.132780] RPC: freeing buffer of size 488 at ffff880078e66800 > [ 2679.132951] RPC: 1847 release request ffff88011a39e000 > [ 2679.133151] RPC: wake_up_next(ffff88011a1e03e8 "xprt_backlog") > [ 2679.133329] RPC: rpc_release_client(ffff88011a88cc00) > [ 2679.133501] RPC: 1847 freeing task > [ 2679.133667] svc: __svc_unregister(NFSv4 callbackv4), error 0 > [ 2679.133853] NFS: releasing client cookie (0xffff8800685c3c00/0xffff88007a2c2e10) > [ 2679.134228] RPC: shutting down nfs client for build-toolchain > [ 2679.134405] RPC: rpc_release_client(ffff880067dfde00) > [ 2679.134574] RPC: destroying nfs client for build-toolchain > [ 2679.134771] RPC: destroying transport ffff88007a346000 > [ 2679.134948] RPC: xs_destroy xprt ffff88007a346000 > [ 2679.135156] RPC: xs_close xprt ffff88007a346000 > [ 2679.135358] RPC: disconnected transport ffff88007a346000 > [ 2679.135535] <-- nfs_free_client() > [ 2679.135716] <-- nfs_free_server() > [ 2679.135880] <-- nfs4_create_server() = error -11 > [ 2679.136096] <-- nfs4_try_mount() = -11 [error] > > Thanks. > ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) 2011-03-31 17:15 ` Bryan Schumaker @ 2011-03-31 17:19 ` Dmitry Torokhov 2011-03-31 18:53 ` Bryan Schumaker 0 siblings, 1 reply; 9+ messages in thread From: Dmitry Torokhov @ 2011-03-31 17:19 UTC (permalink / raw) To: Bryan Schumaker; +Cc: linux-kernel@vger.kernel.org, Trond Myklebust On Thursday, March 31, 2011 10:15:41 am Bryan Schumaker wrote: > Thanks for the log and extra info. What setting does the server use to > export /toolchain? You can usually find this in /etc/exports, but it > may be different for NIS. I would like to set up my NFS server in a > similar way so I can try to reproduce what you're seeing. > Bryan, Unfortunately I do not have shell access to the NFS server. I can only provide data that can be collected from the client. [dtor@dtor-ws linus]$ showmount --exports build-toolchain Export list for build-toolchain: /apps * /trees * /toolchain * Thanks, Dmitry ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) 2011-03-31 17:19 ` Dmitry Torokhov @ 2011-03-31 18:53 ` Bryan Schumaker 2011-03-31 22:11 ` Dmitry Torokhov 0 siblings, 1 reply; 9+ messages in thread From: Bryan Schumaker @ 2011-03-31 18:53 UTC (permalink / raw) To: Dmitry Torokhov; +Cc: linux-kernel@vger.kernel.org, Trond Myklebust Hi If you apply this patch, does it fix the problem? Bryan diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c index dfd1e6d..9bf41ea 100644 --- a/fs/nfs/nfs4proc.c +++ b/fs/nfs/nfs4proc.c @@ -2204,8 +2204,6 @@ static int nfs4_lookup_root_sec(struct nfs_server *server, struct nfs_fh *fhandl goto out; } ret = nfs4_lookup_root(server, fhandle, info); - if (ret < 0) - ret = -EAGAIN; out: return ret; } @@ -2226,7 +2224,7 @@ static int nfs4_proc_get_root(struct nfs_server *server, struct nfs_fh *fhandle, for (i = 0; i < len; i++) { status = nfs4_lookup_root_sec(server, fhandle, info, flav_array[i]); - if (status == 0) + if (status != -EPERM) break; } if (status == 0) On 03/31/2011 01:19 PM, Dmitry Torokhov wrote: > On Thursday, March 31, 2011 10:15:41 am Bryan Schumaker wrote: >> Thanks for the log and extra info. What setting does the server use to >> export /toolchain? You can usually find this in /etc/exports, but it >> may be different for NIS. I would like to set up my NFS server in a >> similar way so I can try to reproduce what you're seeing. >> > > Bryan, > > Unfortunately I do not have shell access to the NFS server. I can only > provide data that can be collected from the client. > > [dtor@dtor-ws linus]$ showmount --exports build-toolchain > Export list for build-toolchain: > /apps * > /trees * > /toolchain * > > Thanks, > Dmitry ^ permalink raw reply related [flat|nested] 9+ messages in thread
* Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) 2011-03-31 18:53 ` Bryan Schumaker @ 2011-03-31 22:11 ` Dmitry Torokhov 0 siblings, 0 replies; 9+ messages in thread From: Dmitry Torokhov @ 2011-03-31 22:11 UTC (permalink / raw) To: Bryan Schumaker; +Cc: linux-kernel@vger.kernel.org, Trond Myklebust On Thursday, March 31, 2011 11:53:48 am Bryan Schumaker wrote: > Hi > > If you apply this patch, does it fix the problem? Yes, it does! Thank you for your help. -- Dmitry ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2011-03-31 22:11 UTC | newest] Thread overview: 9+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2011-03-30 20:38 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) Dmitry Torokhov 2011-03-30 21:03 ` Bryan Schumaker -- strict thread matches above, loose matches on Subject: below -- 2011-03-30 22:31 Dmitry Torokhov 2011-03-31 16:23 ` Dmitry Torokhov 2011-03-31 16:50 ` Dmitry Torokhov 2011-03-31 17:15 ` Bryan Schumaker 2011-03-31 17:19 ` Dmitry Torokhov 2011-03-31 18:53 ` Bryan Schumaker 2011-03-31 22:11 ` Dmitry Torokhov
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox