Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1758713Ab1CaRPq (ORCPT ); Thu, 31 Mar 2011 13:15:46 -0400 Received: from mx2.netapp.com ([216.240.18.37]:29825 "EHLO mx2.netapp.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753108Ab1CaRPp (ORCPT ); Thu, 31 Mar 2011 13:15:45 -0400 X-IronPort-AV: E=Sophos;i="4.63,276,1299484800"; d="scan'208";a="536841521" Message-ID: <4D94B6BD.3010409@netapp.com> Date: Thu, 31 Mar 2011 13:15:41 -0400 From: Bryan Schumaker User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.2.15) Gecko/20110307 Lightning/1.0b2 Lanikai/3.1.9 MIME-Version: 1.0 To: Dmitry Torokhov CC: "linux-kernel@vger.kernel.org" , Trond Myklebust Subject: Re: 2.6.39-rc1 regression: NFS - unable to mount some shares (bisected) References: <8A85A9B4-D801-476F-B280-CE2B1D04277B@vmware.com> <20110331162338.GA32296@core.coreip.homeip.net> <20110331165035.GA6778@dtor-ws.eng.vmware.com> In-Reply-To: <20110331165035.GA6778@dtor-ws.eng.vmware.com> Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 27245 Lines: 469 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. > -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/