Re: 2.6.39-rc1 regression: NFS - unable to mount some shares(bisected)
From: Dmitry Torokhov
Date: Thu Mar 31 2011 - 12:50:39 EST
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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/