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 <[email protected]>
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 <[email protected]>
Signed-off-by: Trond Myklebust <[email protected]>
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
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 <[email protected]>
> 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 <[email protected]>
> Signed-off-by: Trond Myklebust <[email protected]>
>
> 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
>
Hi Bryan,
It is actually one of autofs + NIS, mounts that is failing.
--
Dmitry
On Mar 30, 2011, at 2:03 PM, Bryan Schumaker <[email protected]> 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 <[email protected]>
>> 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 <[email protected]>
>> Signed-off-by: Trond Myklebust <[email protected]>
>>
>> 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
>>
>
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
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
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.
>
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
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
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