Hi Kevin,
thanks for your reply. Attached is all the information I have been able
to gather thus far (kernel and daemon logs).
Kevin Coffman (kwc@xxxxxxxxx on 2011-10-21 10:33 -0400):
> On Thu, Oct 20, 2011 at 7:23 PM, Arno Schuring
> <aelschuring@xxxxxxxxxxx> wrote:
> >
> > I've been running a succesful NFS4 setup at home for a year now, but
> > incorporating krb5 security has so far proven fruitless. I believe
> > the Kerberos side of the equation is no longer causing problems; it
> > is used for user authentication too, and nfs security contexts seem
> > to work properly. As said above, the mount request for any Kerberos
> > mount gets halted somewhere in flight:
[..]
> > [600472.772226] nfsd: connect from 172.22.21.8, port=46257
> > [600472.772300] svc: svc_setup_socket created deda1a00 (inet
> > df948900) [600473.431966] svc_recv: found XPT_CLOSE
> > [600473.431982] svc: svc_delete_xprt(deda1a00)
> > [600473.432114] svc: transport deda1a00 is dead, not enqueued
> >
>
> You should be seeing syslog messages if not, but I'll ask anyway.
> You've got rpc.gssd configured and running on the client, and if this
> is a linux server, rpc.svcgssd configured and running on the server.
> ("Configured" more or less means you've got a keytab.) If they are
> running, what does their output look like? (Perhaps using "-vvv" to
> get detailed output.)
In this case I'm trying with a local mount, so client==server. The gssd
logs invariably end with the following lines:
rpc.gssd[26133]: creating context with server nfs@xxxxxxxxxxxxxxx
rpc.gssd[28189]: DEBUG: serialize_krb5_ctx: lucid version!
rpc.gssd[28189]: prepare_krb5_rfc1964_buffer: serializing keys with
enctype 4 and length 8
rpc.gssd[28189]: doing downcall
[ then nothing until I kill the mount process ]
In the svcgssd logs, nothing stands out to me. It all appears proper
to the untrained eye:
rpc.svcgssd[26188]: handling null request
rpc.svcgssd[26188]: sname = nfs/genie.loos.site@xxxxxxxxx
rpc.svcgssd[26188]: libnfsidmap: using (default) domain: loos.site
rpc.svcgssd[26188]: DEBUG: serialize_krb5_ctx: lucid version!
rpc.svcgssd[26188]: prepare_krb5_rfc1964_buffer: serializing keys with
enctype 4 and length 8
rpc.svcgssd[26188]: doing downcall
rpc.svcgssd[26188]: mech: krb5, hndl len: 4, ctx len 85, timeout:
1319183270 (35999 from now), clnt: nfs@xxxxxxxxxxxxxxx, uid: -1, gid:
-1, num aux grps: 0:
rpc.svcgssd[26188]: sending null reply
rpc.svcgssd[26188]: finished handling null request
Regards,
ArnoOct 20 23:47:50 genie rpc.idmapd[26204]: New client: 80
Oct 20 23:47:50 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:47:50 genie rpc.idmapd[26204]: Opened /var/lib/nfs/rpc_pipefs/nfs/clnt80/idmap
Oct 20 23:47:50 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:47:50 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:47:50 genie rpc.idmapd[26204]: New client: 81
Oct 20 23:47:50 genie rpc.gssd[26133]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt80)
Oct 20 23:47:50 genie rpc.gssd[26133]: handle_gssd_upcall: 'mech=krb5 uid=0 '
Oct 20 23:47:50 genie rpc.gssd[26133]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt80)
Oct 20 23:47:50 genie rpc.gssd[26133]: process_krb5_upcall: service is '<null>'
Oct 20 23:47:50 genie rpc.gssd[26133]: Full hostname for 'genie.loos.site' is 'genie.loos.site'
Oct 20 23:47:50 genie rpc.gssd[26133]: Full hostname for 'genie.loos.site' is 'genie.loos.site'
Oct 20 23:47:50 genie rpc.gssd[26133]: Key table entry not found while getting keytab entry for 'root/genie.loos.site@'
Oct 20 23:47:50 genie rpc.gssd[26133]: Success getting keytab entry for 'nfs/genie.loos.site@'
Oct 20 23:47:50 genie krb5kdc[15110]: AS_REQ (7 etypes {18 17 16 23 1 3 2}) 172.22.21.8: NEEDED_PREAUTH: nfs/genie.loos.site@xxxxxxxxx for krbtgt/LOOS.SITE@xxxxxxxxx, Additional pre-authentication required
Oct 20 23:47:50 genie krb5kdc[15110]: AS_REQ (7 etypes {18 17 16 23 1 3 2}) 172.22.21.8: ISSUE: authtime 1319147270, etypes {rep=1 tkt=18 ses=18}, nfs/genie.loos.site@xxxxxxxxx for krbtgt/LOOS.SITE@xxxxxxxxx
Oct 20 23:47:50 genie rpc.gssd[26133]: Successfully obtained machine credentials for principal 'nfs/genie.loos.site@xxxxxxxxx' stored in ccache 'FILE:/tmp/krb5cc_machine_LOOS.SITE'
Oct 20 23:47:50 genie rpc.gssd[26133]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_LOOS.SITE' are good until 1319183270
Oct 20 23:47:50 genie rpc.gssd[26133]: using FILE:/tmp/krb5cc_machine_LOOS.SITE as credentials cache for machine creds
Oct 20 23:47:50 genie rpc.gssd[26133]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_machine_LOOS.SITE
Oct 20 23:47:50 genie rpc.gssd[26133]: creating context using fsuid 0 (save_uid 0)
Oct 20 23:47:50 genie rpc.gssd[26133]: creating tcp client for server genie.loos.site
Oct 20 23:47:50 genie rpc.gssd[26133]: DEBUG: port already set to 2049
Oct 20 23:47:50 genie rpc.gssd[26133]: creating context with server nfs@xxxxxxxxxxxxxxx
Oct 20 23:47:51 genie krb5kdc[15110]: TGS_REQ (7 etypes {18 17 16 23 1 3 2}) 172.22.21.8: ISSUE: authtime 1319147270, etypes {rep=18 tkt=1 ses=1}, nfs/genie.loos.site@xxxxxxxxx for nfs/genie.loos.site@xxxxxxxxx
Oct 20 23:47:51 genie rpc.svcgssd[26188]: leaving poll
Oct 20 23:47:51 genie rpc.svcgssd[26188]: handling null request
Oct 20 23:47:51 genie rpc.svcgssd[26188]: sname = nfs/genie.loos.site@xxxxxxxxx
Oct 20 23:47:51 genie rpc.svcgssd[26188]: libnfsidmap: using (default) domain: loos.site
Oct 20 23:47:51 genie rpc.svcgssd[26188]: libnfsidmap: loaded plugin /usr/lib/libnfsidmap/nsswitch.so for method nsswitch
Oct 20 23:47:51 genie nslcd[1259]: [625c6d] nslcd_passwd_byname(nfs/genie.loos.site): invalid user name
Oct 20 23:47:51 genie rpc.svcgssd[26188]: DEBUG: serialize_krb5_ctx: lucid version!
Oct 20 23:47:51 genie rpc.svcgssd[26188]: prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
Oct 20 23:47:51 genie rpc.svcgssd[26188]: doing downcall
Oct 20 23:47:51 genie rpc.svcgssd[26188]: mech: krb5, hndl len: 4, ctx len 85, timeout: 1319183270 (35999 from now), clnt: nfs@xxxxxxxxxxxxxxx, uid: -1, gid: -1, num aux grps: 0:
Oct 20 23:47:51 genie rpc.svcgssd[26188]: sending null reply
Oct 20 23:47:51 genie rpc.svcgssd[26188]: writing message: \x \x6082023206092a864886f71201020201006e8202213082021da003020105a10302010ea20703050020000000a382014d6182014930820145a003020105a10b1b094c4f4f532e53495445a221301fa003020103a11830161b036e66731b0f67656e69652e6c6f6f732e73697465a382010c30820108a003020101a103020102a281fb0481f8ce3a7a6904c0e5231523f1df46aff97f72a916f2490880b147f12630ce6e88585dafe8af3796140b7f1a95b0373c41010174ad17cbefb97d6aa1b366fcd04a172ed3a92bebcccb36e19410fc47b44fe51f4e7c3e1991ccc00198565b748848daaa8106dc93d2b3323f2a3aeda70bdc4f89033f54c3ca9739c6c7804b6951b6623649bed18968708f8649782c212d8cbbd2761f9e199c4475a1e3183cb295db24c1c538684aa9631bc535639a3f016bda9799ba2b591e70103f105ec3061f9468dbafe09b1fa4705b7530253cd602e3122effb562bd2c1cd64eb0d548015e9ebf670aeb222ba60ab9dad0f51657e9981864031c2bb1a136d3a481b63081b3a003020101a281ab0481a8a2f5bf88f8f4f98407b7b43b495e9c2c689ebe95295868187ce071a96488bd917a45925869bee752d59eae4b50e39c9de669e5e7e7f2b05d560c751fcc5655e935d8c31898b2321a692903e96d830148a3de0bd2f81f71701d1e6ff0df3e7de1f49ac3919aa392b897e07f98b41dc99cc919b504452f910a1be55180cca6a7c14f8af3def2ce12def8ca6d7bdb8b1447271d482fa6920fb02ab113c75821e54669c9ac5eb7bcf917 1319147331 0 0 \x01000000 \x607006092a864886f71201020202006f61305fa003020105a10302010fa2533051a003020101a24a04489223de969a87b450168fe4c6c58f461510434adf6c87786d56fb7ac9e8f1918ecba6794e146e3210dc6925629da9b6c797d7aef3211bf845e15b8226bfe69d59983efc34a626f5a1
Oct 20 23:47:51 genie rpc.svcgssd[26188]: finished handling null request
Oct 20 23:47:51 genie rpc.svcgssd[26188]: entering poll
Oct 20 23:47:51 genie rpc.gssd[26133]: DEBUG: serialize_krb5_ctx: lucid version!
Oct 20 23:47:51 genie rpc.gssd[26133]: prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
Oct 20 23:47:51 genie rpc.gssd[26133]: doing downcall
Oct 20 23:47:51 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:48:18 genie rpc.idmapd[26204]: Stale client: 81
Oct 20 23:48:18 genie rpc.idmapd[26204]: #011-> closed /var/lib/nfs/rpc_pipefs/nfs/clnt81/idmap
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfs/clnt81
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:48:18 genie rpc.idmapd[26204]: Stale client: 80
Oct 20 23:48:18 genie rpc.idmapd[26204]: #011-> closed /var/lib/nfs/rpc_pipefs/nfs/clnt80/idmap
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfsd4_cb/clnt7d
Oct 20 23:48:18 genie rpc.gssd[26133]: destroying client /var/lib/nfs/rpc_pipefs/nfs/clnt80
Oct 20 23:47:50 genie kernel: [600472.037146] --> nfs4_create_server()
Oct 20 23:47:50 genie kernel: [600472.037179] --> nfs4_init_server()
Oct 20 23:47:50 genie kernel: [600472.037193] --> nfs4_set_client()
Oct 20 23:47:50 genie kernel: [600472.037208] --> nfs_get_client(genie,v4)
Oct 20 23:47:50 genie kernel: [600472.037225] RPC: looking up machine cred
Oct 20 23:47:50 genie kernel: [600472.037248] --> nfs_get_client() = de825e00 [new]
Oct 20 23:47:50 genie kernel: [600472.037284] RPC: set up xprt to 172.22.21.8 (port 2049) via tcp
Oct 20 23:47:50 genie kernel: [600472.037307] RPC: created transport c3966000 with 16 slots
Oct 20 23:47:50 genie kernel: [600472.037327] RPC: creating nfs client for genie (xprt c3966000)
Oct 20 23:47:50 genie kernel: [600472.037823] RPC: creating GSS authenticator for client de639900
Oct 20 23:47:50 genie kernel: [600472.040355] RPC: rpc_release_client(de639900)
Oct 20 23:47:50 genie kernel: [600472.045656] RPC: 0 holding NULL cred bf3ecc2c
Oct 20 23:47:50 genie kernel: [600472.045685] RPC: new task initialized, procpid 26217
Oct 20 23:47:50 genie kernel: [600472.045702] RPC: allocated task c39f93c0
Oct 20 23:47:50 genie kernel: [600472.045718] RPC: 435 __rpc_execute flags=0x280
Oct 20 23:47:50 genie kernel: [600472.045736] RPC: 435 call_start nfs4 proc NULL (sync)
Oct 20 23:47:50 genie kernel: [600472.045752] RPC: 435 call_reserve (status 0)
Oct 20 23:47:50 genie kernel: [600472.045770] RPC: 435 reserved req d6911000 xid 664da781
Oct 20 23:47:50 genie kernel: [600472.045787] RPC: 435 call_reserveresult (status 0)
Oct 20 23:47:50 genie kernel: [600472.045803] RPC: 435 call_allocate (status 0)
Oct 20 23:47:50 genie kernel: [600472.045821] RPC: 435 allocated buffer of size 92 at dfb78800
Oct 20 23:47:50 genie kernel: [600472.045840] RPC: 435 call_bind (status 0)
Oct 20 23:47:50 genie kernel: [600472.045856] RPC: 435 call_connect xprt c3966000 is not connected
Oct 20 23:47:50 genie kernel: [600472.045875] RPC: 435 xprt_connect xprt c3966000 is not connected
Oct 20 23:47:50 genie kernel: [600472.045896] RPC: 435 sleep_on(queue "xprt_pending" time 60015056)
Oct 20 23:47:50 genie kernel: [600472.045915] RPC: 435 added to queue c39661d0 "xprt_pending"
Oct 20 23:47:50 genie kernel: [600472.045933] RPC: 435 setting alarm for 60000 ms
Oct 20 23:47:50 genie kernel: [600472.045949] RPC: xs_connect scheduled xprt c3966000
Oct 20 23:47:50 genie kernel: [600472.045974] RPC: 435 sync task going to sleep
Oct 20 23:47:50 genie kernel: [600472.046023] RPC: xs_bind4 0.0.0.0:935: ok (0)
Oct 20 23:47:50 genie kernel: [600472.046044] RPC: worker connecting xprt c3966000 via tcp to 172.22.21.8 (port 2049)
Oct 20 23:47:50 genie kernel: [600472.046164] RPC: xs_tcp_state_change client c3966000...
Oct 20 23:47:50 genie kernel: [600472.046189] RPC: state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
Oct 20 23:47:50 genie kernel: [600472.046210] RPC: 435 __rpc_wake_up_task (now 60015056)
Oct 20 23:47:50 genie kernel: [600472.046226] RPC: 435 disabling timer
Oct 20 23:47:50 genie kernel: [600472.046242] RPC: 435 removed from queue c39661d0 "xprt_pending"
Oct 20 23:47:50 genie kernel: [600472.046265] RPC: __rpc_wake_up_task done
Oct 20 23:47:50 genie kernel: [600472.046329] svc: socket df94ba80 TCP (listen) state change 10
Oct 20 23:47:50 genie kernel: [600472.046354] svc: transport de4ace00 served by daemon c0f0b000
Oct 20 23:47:50 genie kernel: [600472.046384] RPC: c3966000 connect status 115 connected 1 sock state 1
Oct 20 23:47:50 genie kernel: [600472.046414] svc: tcp_accept de4ace00 sock ccd38000
Oct 20 23:47:50 genie kernel: [600472.046444] nfsd: connect from 172.22.21.8, port=935
Oct 20 23:47:50 genie kernel: [600472.046461] svc: svc_setup_socket ccfd7780
Oct 20 23:47:50 genie kernel: [600472.046479] setting up TCP socket for reading
Oct 20 23:47:50 genie kernel: [600472.046497] svc: socket de825400(inet df94a880), write_space busy=1
Oct 20 23:47:50 genie kernel: [600472.046517] svc: svc_setup_socket created de825400 (inet df94a880)
Oct 20 23:47:50 genie kernel: [600472.046540] svc: transport de825400 served by daemon dee34000
Oct 20 23:47:50 genie kernel: [600472.046564] svc: transport de4ace00 served by daemon c0f0a000
Oct 20 23:47:50 genie kernel: [600472.046588] svc: transport de4ace00 busy, not enqueued
Oct 20 23:47:50 genie kernel: [600472.046607] svc: server c0f0b000 waiting for data (to = 360000)
Oct 20 23:47:50 genie kernel: [600472.046637] svc: server dee34000, pool 0, transport de825400, inuse=2
Oct 20 23:47:50 genie kernel: [600472.046659] svc: tcp_recv de825400 data 1 conn 0 close 0
Oct 20 23:47:50 genie kernel: [600472.046678] svc: socket de825400(inet df94a880), write_space busy=1
Oct 20 23:47:50 genie kernel: [600472.046696] svc: transport de825400 busy, not enqueued
Oct 20 23:47:50 genie kernel: [600472.046718] svc: socket de825400 recvfrom(de8255c4, 4) = -11
Oct 20 23:47:50 genie kernel: [600472.046735] RPC: TCP recv_record got EAGAIN
Oct 20 23:47:50 genie kernel: [600472.046749] svc: got len=-11
Oct 20 23:47:50 genie kernel: [600472.046763] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:50 genie kernel: [600472.046790] svc: tcp_accept de4ace00 sock ccd38000
Oct 20 23:47:50 genie kernel: [600472.046820] svc: server c0f0a000 waiting for data (to = 360000)
Oct 20 23:47:50 genie kernel: [600472.046846] RPC: 435 sync task resuming
Oct 20 23:47:50 genie kernel: [600472.046862] RPC: 435 xprt_connect_status: retrying
Oct 20 23:47:50 genie kernel: [600472.046880] RPC: 435 call_connect_status (status -11)
Oct 20 23:47:50 genie kernel: [600472.046897] RPC: 435 call_transmit (status 0)
Oct 20 23:47:50 genie kernel: [600472.046912] RPC: 435 xprt_prepare_transmit
Oct 20 23:47:50 genie kernel: [600472.046928] RPC: 435 rpc_xdr_encode (status 0)
Oct 20 23:47:50 genie kernel: [600472.046946] RPC: 435 marshaling NULL cred bf3ecc2c
Oct 20 23:47:50 genie kernel: [600472.046965] RPC: 435 using AUTH_NULL cred bf3ecc2c to wrap rpc data
Oct 20 23:47:50 genie kernel: [600472.046984] RPC: 435 xprt_transmit(44)
Oct 20 23:47:50 genie kernel: [600472.047044] svc: socket df94a880 TCP data ready (svsk de825400)
Oct 20 23:47:50 genie kernel: [600472.047069] svc: transport de825400 served by daemon c0f0a000
Oct 20 23:47:50 genie kernel: [600472.047128] svc: server c0f0a000, pool 0, transport de825400, inuse=2
Oct 20 23:47:50 genie kernel: [600472.047153] svc: tcp_recv de825400 data 1 conn 0 close 0
Oct 20 23:47:50 genie kernel: [600472.047177] svc: socket de825400 recvfrom(de8255c8, 0) = 4
Oct 20 23:47:50 genie kernel: [600472.047195] svc: TCP record, 40 bytes
Oct 20 23:47:50 genie kernel: [600472.047215] svc: socket de825400 recvfrom(dec71008, 4088) = 8
Oct 20 23:47:50 genie kernel: [600472.047238] svc: socket de825400 recvfrom(dec71028, 4056) = 32
Oct 20 23:47:50 genie kernel: [600472.047256] svc: TCP complete record (40 bytes)
Oct 20 23:47:50 genie kernel: [600472.047274] svc: transport de825400 served by daemon dee34000
Oct 20 23:47:50 genie kernel: [600472.047295] svc: got len=40
Oct 20 23:47:50 genie kernel: [600472.047312] svc: svc_authenticate (0)
Oct 20 23:47:50 genie kernel: [600472.047333] svc: transport de825400 busy, not enqueued
Oct 20 23:47:50 genie kernel: [600472.047349] svc: calling dispatcher
Oct 20 23:47:50 genie kernel: [600472.047405] svc: socket de825400 sendto([df3fc000 28... ], 28) = 28 (addr 172.22.21.8, port=935)
Oct 20 23:47:50 genie kernel: [600472.047436] svc: transport de825400 busy, not enqueued
Oct 20 23:47:50 genie kernel: [600472.047455] svc: server c0f0a000 waiting for data (to = 360000)
Oct 20 23:47:50 genie kernel: [600472.047486] svc: server dee34000, pool 0, transport de825400, inuse=2
Oct 20 23:47:50 genie kernel: [600472.047508] svc: tcp_recv de825400 data 1 conn 0 close 0
Oct 20 23:47:50 genie kernel: [600472.047530] svc: socket de825400 recvfrom(de8255c4, 4) = -11
Oct 20 23:47:50 genie kernel: [600472.047546] RPC: TCP recv_record got EAGAIN
Oct 20 23:47:50 genie kernel: [600472.047561] svc: got len=-11
Oct 20 23:47:50 genie kernel: [600472.047574] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:50 genie kernel: [600472.047902] RPC: xs_tcp_data_ready...
Oct 20 23:47:50 genie kernel: [600472.047926] RPC: xs_tcp_data_recv started
Oct 20 23:47:50 genie kernel: [600472.047944] RPC: reading TCP record fragment of length 24
Oct 20 23:47:50 genie kernel: [600472.047961] RPC: reading XID (4 bytes)
Oct 20 23:47:50 genie kernel: [600472.047977] RPC: reading request with XID 664da781
Oct 20 23:47:50 genie kernel: [600472.047994] RPC: reading CALL/REPLY flag (4 bytes)
Oct 20 23:47:50 genie kernel: [600472.048010] RPC: read reply XID 664da781
Oct 20 23:47:50 genie kernel: [600472.048027] RPC: XID 664da781 read 16 bytes
Oct 20 23:47:50 genie kernel: [600472.048045] RPC: xprt = c3966000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
Oct 20 23:47:50 genie kernel: [600472.048070] RPC: 435 xid 664da781 complete (24 bytes received)
Oct 20 23:47:50 genie kernel: [600472.048088] RPC: xs_tcp_data_recv done
Oct 20 23:47:50 genie kernel: [600472.048148] RPC: xs_tcp_send_request(44) = 44
Oct 20 23:47:50 genie kernel: [600472.048167] RPC: 435 xmit complete
Oct 20 23:47:50 genie kernel: [600472.048185] RPC: wake_up_next(c396616c "xprt_resend")
Oct 20 23:47:50 genie kernel: [600472.048203] RPC: wake_up_next(c3966108 "xprt_sending")
Oct 20 23:47:50 genie kernel: [600472.048223] RPC: 435 call_status (status 24)
Oct 20 23:47:50 genie kernel: [600472.048238] RPC: 435 call_decode (status 24)
Oct 20 23:47:50 genie kernel: [600472.048256] RPC: 435 validating NULL cred bf3ecc2c
Oct 20 23:47:50 genie kernel: [600472.048274] RPC: 435 using AUTH_NULL cred bf3ecc2c to unwrap rpc data
Oct 20 23:47:50 genie kernel: [600472.048293] RPC: 435 call_decode result 0
Oct 20 23:47:50 genie kernel: [600472.048308] RPC: 435 return 0, status 0
Oct 20 23:47:50 genie kernel: [600472.048322] RPC: 435 release task
Oct 20 23:47:50 genie kernel: [600472.048340] RPC: freeing buffer of size 92 at dfb78800
Oct 20 23:47:50 genie kernel: [600472.048359] RPC: 435 release request d6911000
Oct 20 23:47:50 genie kernel: [600472.048375] RPC: wake_up_next(c3966234 "xprt_backlog")
Oct 20 23:47:50 genie kernel: [600472.048394] RPC: 435 releasing NULL cred bf3ecc2c
Oct 20 23:47:50 genie kernel: [600472.048410] RPC: rpc_release_client(de639900)
Oct 20 23:47:50 genie kernel: [600472.048426] RPC: 435 freeing task
Oct 20 23:47:50 genie kernel: [600472.051474] svc: initialising pool 0 for NFSv4 callback
Oct 20 23:47:50 genie kernel: [600472.051508] RPC: unregistering [1073741824, 1, ''] with local rpcbind
Oct 20 23:47:50 genie kernel: [600472.051549] RPC: set up xprt to 127.0.0.1 (port 111) via udp
Oct 20 23:47:50 genie kernel: [600472.051574] RPC: created transport def54000 with 16 slots
Oct 20 23:47:50 genie kernel: [600472.051593] RPC: creating rpcbind client for localhost (xprt def54000)
Oct 20 23:47:50 genie kernel: [600472.051620] RPC: creating UNIX authenticator for client de639e00
Oct 20 23:47:50 genie kernel: [600472.051644] RPC: 0 looking up UNIX cred
Oct 20 23:47:50 genie kernel: [600472.051658] RPC: looking up UNIX cred
Oct 20 23:47:50 genie kernel: [600472.051675] RPC: new task initialized, procpid 26217
Oct 20 23:47:50 genie kernel: [600472.051692] RPC: allocated task c39f93c0
Oct 20 23:47:50 genie kernel: [600472.051707] RPC: 436 __rpc_execute flags=0x280
Oct 20 23:47:50 genie kernel: [600472.051725] RPC: 436 call_start rpcbind4 proc UNSET (sync)
Oct 20 23:47:50 genie kernel: [600472.051743] RPC: 436 call_reserve (status 0)
Oct 20 23:47:50 genie kernel: [600472.051760] RPC: 436 reserved req d6913000 xid 25fd7bd4
Oct 20 23:47:50 genie kernel: [600472.051777] RPC: 436 call_reserveresult (status 0)
Oct 20 23:47:50 genie kernel: [600472.051794] RPC: 436 call_allocate (status 0)
Oct 20 23:47:50 genie kernel: [600472.051811] RPC: 436 allocated buffer of size 484 at def55800
Oct 20 23:47:50 genie kernel: [600472.051829] RPC: 436 call_bind (status 0)
Oct 20 23:47:50 genie kernel: [600472.051845] RPC: 436 call_connect xprt def54000 is not connected
Oct 20 23:47:50 genie kernel: [600472.051864] RPC: 436 xprt_connect xprt def54000 is not connected
Oct 20 23:47:50 genie kernel: [600472.051883] RPC: 436 xprt_cwnd_limited cong = 0 cwnd = 256
Oct 20 23:47:50 genie kernel: [600472.051903] RPC: 436 sleep_on(queue "xprt_pending" time 60015056)
Oct 20 23:47:50 genie kernel: [600472.051923] RPC: 436 added to queue def541d0 "xprt_pending"
Oct 20 23:47:50 genie kernel: [600472.051940] RPC: 436 setting alarm for 5000 ms
Oct 20 23:47:50 genie kernel: [600472.051957] RPC: xs_connect scheduled xprt def54000
Oct 20 23:47:50 genie kernel: [600472.051983] RPC: 436 sync task going to sleep
Oct 20 23:47:50 genie kernel: [600472.052028] RPC: xs_bind4 0.0.0.0:843: ok (0)
Oct 20 23:47:50 genie kernel: [600472.052048] RPC: worker connecting xprt def54000 via udp to 127.0.0.1 (port 111)
Oct 20 23:47:50 genie kernel: [600472.052074] RPC: 436 __rpc_wake_up_task (now 60015056)
Oct 20 23:47:50 genie kernel: [600472.052091] RPC: 436 disabling timer
Oct 20 23:47:50 genie kernel: [600472.052106] RPC: 436 removed from queue def541d0 "xprt_pending"
Oct 20 23:47:50 genie kernel: [600472.052128] RPC: __rpc_wake_up_task done
Oct 20 23:47:50 genie kernel: [600472.052148] RPC: 436 sync task resuming
Oct 20 23:47:50 genie kernel: [600472.052164] RPC: 436 xprt_connect_status: connection established
Oct 20 23:47:50 genie kernel: [600472.052183] RPC: 436 call_connect_status (status 0)
Oct 20 23:47:50 genie kernel: [600472.052199] RPC: 436 call_transmit (status 0)
Oct 20 23:47:50 genie kernel: [600472.052214] RPC: 436 xprt_prepare_transmit
Oct 20 23:47:50 genie kernel: [600472.052230] RPC: 436 rpc_xdr_encode (status 0)
Oct 20 23:47:50 genie kernel: [600472.052248] RPC: 436 marshaling UNIX cred deee8280
Oct 20 23:47:50 genie kernel: [600472.052267] RPC: 436 using AUTH_UNIX cred deee8280 to wrap rpc data
Oct 20 23:47:50 genie kernel: [600472.052289] RPC: 436 encoding RPCB_UNSET call (1073741824, 1, '', '')
Oct 20 23:47:50 genie kernel: [600472.052310] RPC: 436 xprt_transmit(96)
Oct 20 23:47:50 genie kernel: [600472.052464] RPC: xs_udp_send_request(96) = 96
Oct 20 23:47:50 genie kernel: [600472.052487] RPC: 436 xmit complete
Oct 20 23:47:50 genie kernel: [600472.052503] RPC: 436 sleep_on(queue "xprt_pending" time 60015057)
Oct 20 23:47:50 genie kernel: [600472.052524] RPC: 436 added to queue def541d0 "xprt_pending"
Oct 20 23:47:50 genie kernel: [600472.052541] RPC: 436 setting alarm for 5000 ms
Oct 20 23:47:50 genie kernel: [600472.052559] RPC: 436 sync task going to sleep
Oct 20 23:47:50 genie kernel: [600472.054876] RPC: xs_udp_data_ready...
Oct 20 23:47:50 genie kernel: [600472.054908] RPC: cong 256, cwnd was 256, now 512
Oct 20 23:47:50 genie kernel: [600472.054928] RPC: wake_up_next(def5416c "xprt_resend")
Oct 20 23:47:50 genie kernel: [600472.054946] RPC: wake_up_next(def54108 "xprt_sending")
Oct 20 23:47:50 genie kernel: [600472.054966] RPC: 436 xid 25fd7bd4 complete (28 bytes received)
Oct 20 23:47:50 genie kernel: [600472.054984] RPC: 436 __rpc_wake_up_task (now 60015057)
Oct 20 23:47:50 genie kernel: [600472.055000] RPC: 436 disabling timer
Oct 20 23:47:50 genie kernel: [600472.055016] RPC: 436 removed from queue def541d0 "xprt_pending"
Oct 20 23:47:50 genie kernel: [600472.055042] RPC: __rpc_wake_up_task done
Oct 20 23:47:50 genie kernel: [600472.065171] RPC: 436 sync task resuming
Oct 20 23:47:50 genie kernel: [600472.065199] RPC: 436 call_status (status 28)
Oct 20 23:47:50 genie kernel: [600472.065215] RPC: 436 call_decode (status 28)
Oct 20 23:47:50 genie kernel: [600472.065234] RPC: 436 validating UNIX cred deee8280
Oct 20 23:47:50 genie kernel: [600472.065252] RPC: 436 using AUTH_UNIX cred deee8280 to unwrap rpc data
Oct 20 23:47:50 genie kernel: [600472.065273] RPC: 436 RPCB_UNSET call succeeded
Oct 20 23:47:50 genie kernel: [600472.065289] RPC: 436 call_decode result 0
Oct 20 23:47:50 genie kernel: [600472.065304] RPC: 436 return 0, status 0
Oct 20 23:47:50 genie kernel: [600472.065318] RPC: 436 release task
Oct 20 23:47:50 genie kernel: [600472.065338] RPC: freeing buffer of size 484 at def55800
Oct 20 23:47:50 genie kernel: [600472.065358] RPC: 436 release request d6913000
Oct 20 23:47:50 genie kernel: [600472.065373] RPC: wake_up_next(def54234 "xprt_backlog")
Oct 20 23:47:50 genie kernel: [600472.065393] RPC: 436 releasing UNIX cred deee8280
Oct 20 23:47:50 genie kernel: [600472.065409] RPC: rpc_release_client(de639e00)
Oct 20 23:47:50 genie kernel: [600472.065426] RPC: 436 freeing task
Oct 20 23:47:50 genie kernel: [600472.065440] RPC: shutting down rpcbind client for localhost
Oct 20 23:47:50 genie kernel: [600472.065458] RPC: rpc_release_client(de639e00)
Oct 20 23:47:50 genie kernel: [600472.065474] RPC: destroying rpcbind client for localhost
Oct 20 23:47:50 genie kernel: [600472.065494] RPC: destroying transport def54000
Oct 20 23:47:50 genie kernel: [600472.065511] RPC: xs_destroy xprt def54000
Oct 20 23:47:50 genie kernel: [600472.065528] RPC: xs_close xprt def54000
Oct 20 23:47:50 genie kernel: [600472.065557] RPC: disconnected transport def54000
Oct 20 23:47:50 genie kernel: [600472.065580] svc: __svc_unregister(NFSv4 callbackv1), error 0
Oct 20 23:47:50 genie kernel: [600472.065601] svc: creating transport tcp[20490]
Oct 20 23:47:50 genie kernel: [600472.065622] svc: svc_create_socket(NFSv4 callback, 6, 0.0.0.0, port=20490)
Oct 20 23:47:50 genie kernel: [600472.065680] svc: svc_setup_socket ccfd7d80
Oct 20 23:47:50 genie kernel: [600472.065699] setting up TCP socket for listening
Oct 20 23:47:50 genie kernel: [600472.065716] svc: svc_setup_socket created df930e00 (inet df949680)
Oct 20 23:47:50 genie kernel: [600472.065736] NFS: Callback listener port = 20490 (af 2)
Oct 20 23:47:50 genie kernel: [600472.065752] svc: creating transport tcp[20490]
Oct 20 23:47:50 genie kernel: [600472.065772] svc: svc_create_socket(NFSv4 callback, 6, 0000:0000:0000:0000:0000:0000:0000:0000, port=20490)
Oct 20 23:47:50 genie kernel: [600472.065834] svc: svc_setup_socket df47a180
Oct 20 23:47:50 genie kernel: [600472.065852] setting up TCP socket for listening
Oct 20 23:47:50 genie kernel: [600472.065869] svc: svc_setup_socket created df930a00 (inet d4b88000)
Oct 20 23:47:50 genie kernel: [600472.065888] NFS: Callback listener port = 20490 (af 10)
Oct 20 23:47:50 genie kernel: [600472.068027] svc: svc_destroy(NFSv4 callback, 2)
Oct 20 23:47:50 genie kernel: [600472.068056] <-- nfs4_set_client() = 0 [new de825e00]
Oct 20 23:47:50 genie kernel: [600472.068232] <-- nfs4_init_server() = 0
Oct 20 23:47:50 genie kernel: [600472.068266] --> nfs4_path_walk(,,/)
Oct 20 23:47:50 genie kernel: [600472.068684] RPC: 0 looking up RPCSEC_GSS cred
Oct 20 23:47:50 genie kernel: [600472.068707] RPC: looking up RPCSEC_GSS cred
Oct 20 23:47:50 genie kernel: [600472.068724] RPC: gss_create_cred for uid 0, flavor 390003
Oct 20 23:47:50 genie kernel: [600472.068744] RPC: gss_upcall for uid 0
Oct 20 23:47:50 genie kernel: [600472.068764] RPC: gss_find_upcall found nothing
Oct 20 23:47:50 genie kernel: [600472.068792] svc: server d6913000 waiting for data (to = 2147483647)
Oct 20 23:47:50 genie kernel: [600472.772055] svc: socket df94ba80 TCP (listen) state change 10
Oct 20 23:47:50 genie kernel: [600472.772096] svc: transport de4ace00 served by daemon dee34000
Oct 20 23:47:50 genie kernel: [600472.772170] svc: tcp_accept de4ace00 sock ccd38000
Oct 20 23:47:50 genie kernel: [600472.772203] nfsd: connect from unprivileged port: 172.22.21.8, port=46257
Oct 20 23:47:50 genie kernel: [600472.772226] nfsd: connect from 172.22.21.8, port=46257
Oct 20 23:47:50 genie kernel: [600472.772243] svc: svc_setup_socket ccc2b600
Oct 20 23:47:50 genie kernel: [600472.772261] setting up TCP socket for reading
Oct 20 23:47:50 genie kernel: [600472.772280] svc: socket deda1a00(inet df948900), write_space busy=1
Oct 20 23:47:50 genie kernel: [600472.772300] svc: svc_setup_socket created deda1a00 (inet df948900)
Oct 20 23:47:50 genie kernel: [600472.772322] svc: transport deda1a00 served by daemon c0f0a000
Oct 20 23:47:50 genie kernel: [600472.772411] svc: transport de4ace00 served by daemon c0f0b000
Oct 20 23:47:50 genie kernel: [600472.772438] svc: transport de4ace00 busy, not enqueued
Oct 20 23:47:50 genie kernel: [600472.772458] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:50 genie kernel: [600472.772915] svc: server c0f0a000, pool 0, transport deda1a00, inuse=2
Oct 20 23:47:50 genie kernel: [600472.772942] svc: tcp_recv deda1a00 data 1 conn 0 close 0
Oct 20 23:47:50 genie kernel: [600472.772962] svc: socket deda1a00(inet df948900), write_space busy=1
Oct 20 23:47:50 genie kernel: [600472.772981] svc: transport deda1a00 busy, not enqueued
Oct 20 23:47:50 genie kernel: [600472.773004] svc: socket deda1a00 recvfrom(deda1bc4, 4) = -11
Oct 20 23:47:50 genie kernel: [600472.773020] RPC: TCP recv_record got EAGAIN
Oct 20 23:47:50 genie kernel: [600472.773035] svc: got len=-11
Oct 20 23:47:50 genie kernel: [600472.773050] svc: server c0f0a000 waiting for data (to = 360000)
Oct 20 23:47:50 genie kernel: [600472.773080] svc: tcp_accept de4ace00 sock ccd38000
Oct 20 23:47:50 genie kernel: [600472.773110] svc: server c0f0b000 waiting for data (to = 360000)
Oct 20 23:47:51 genie kernel: [600473.384481] svc: socket df948900 TCP data ready (svsk deda1a00)
Oct 20 23:47:51 genie kernel: [600473.384524] svc: transport deda1a00 served by daemon dee34000
Oct 20 23:47:51 genie kernel: [600473.384644] svc: server dee34000, pool 0, transport deda1a00, inuse=2
Oct 20 23:47:51 genie kernel: [600473.384670] svc: tcp_recv deda1a00 data 1 conn 0 close 0
Oct 20 23:47:51 genie kernel: [600473.384696] svc: socket deda1a00 recvfrom(deda1bc8, 0) = 4
Oct 20 23:47:51 genie kernel: [600473.384713] svc: TCP record, 632 bytes
Oct 20 23:47:51 genie kernel: [600473.384734] svc: socket deda1a00 recvfrom(c3953008, 4088) = 8
Oct 20 23:47:51 genie kernel: [600473.384760] svc: socket deda1a00 recvfrom(c3953278, 3464) = 624
Oct 20 23:47:51 genie kernel: [600473.384778] svc: TCP complete record (632 bytes)
Oct 20 23:47:51 genie kernel: [600473.384797] svc: transport deda1a00 served by daemon c0f0b000
Oct 20 23:47:51 genie kernel: [600473.384820] svc: got len=632
Oct 20 23:47:51 genie kernel: [600473.384837] svc: svc_authenticate (6)
Oct 20 23:47:51 genie kernel: [600473.384852] RPC: svcauth_gss: argv->iov_len = 604
Oct 20 23:47:51 genie kernel: [600473.384918] svc: svc_process dropit
Oct 20 23:47:51 genie kernel: [600473.384935] svc: xprt deda1a00 dropped request
Oct 20 23:47:51 genie kernel: [600473.384955] svc: transport deda1a00 busy, not enqueued
Oct 20 23:47:51 genie kernel: [600473.384974] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:51 genie kernel: [600473.385008] svc: server c0f0b000, pool 0, transport deda1a00, inuse=3
Oct 20 23:47:51 genie kernel: [600473.385030] svc: tcp_recv deda1a00 data 1 conn 0 close 0
Oct 20 23:47:51 genie kernel: [600473.385092] svc: socket deda1a00 recvfrom(deda1bc4, 4) = -11
Oct 20 23:47:51 genie kernel: [600473.385112] RPC: TCP recv_record got EAGAIN
Oct 20 23:47:51 genie kernel: [600473.385127] svc: got len=-11
Oct 20 23:47:51 genie kernel: [600473.385142] svc: server c0f0b000 waiting for data (to = 360000)
Oct 20 23:47:51 genie kernel: [600473.410873] RPC: Successfully imported new context.
Oct 20 23:47:51 genie kernel: [600473.411373] revisit queued
Oct 20 23:47:51 genie kernel: [600473.411400] svc: transport deda1a00 served by daemon c0f0b000
Oct 20 23:47:51 genie kernel: [600473.411950] svc: server c0f0b000, pool 0, transport deda1a00, inuse=2
Oct 20 23:47:51 genie kernel: [600473.411978] svc: transport deda1a00 served by daemon dee34000
Oct 20 23:47:51 genie kernel: [600473.412003] svc: got len=632
Oct 20 23:47:51 genie kernel: [600473.412021] svc: svc_authenticate (6)
Oct 20 23:47:51 genie kernel: [600473.412036] RPC: svcauth_gss: argv->iov_len = 604
Oct 20 23:47:51 genie kernel: [600473.412074] RPC: gss_krb5_seal
Oct 20 23:47:51 genie kernel: [600473.412134] RPC: krb5_encrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.412165] RPC: krb5_encrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.412298] svc: socket deda1a00 sendto([df2dd000 208... ], 208) = 208 (addr 172.22.21.8, port=46257)
Oct 20 23:47:51 genie kernel: [600473.412334] svc: transport deda1a00 busy, not enqueued
Oct 20 23:47:51 genie kernel: [600473.412467] svc: server c0f0b000 waiting for data (to = 360000)
Oct 20 23:47:51 genie kernel: [600473.412503] svc: server dee34000, pool 0, transport deda1a00, inuse=2
Oct 20 23:47:51 genie kernel: [600473.412526] svc: tcp_recv deda1a00 data 0 conn 0 close 0
Oct 20 23:47:51 genie kernel: [600473.412549] svc: socket deda1a00 recvfrom(deda1bc4, 4) = -11
Oct 20 23:47:51 genie kernel: [600473.412566] RPC: TCP recv_record got EAGAIN
Oct 20 23:47:51 genie kernel: [600473.412580] svc: got len=-11
Oct 20 23:47:51 genie kernel: [600473.412594] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:51 genie kernel: [600473.429159] RPC: gss_find_upcall found msg deda1c00
Oct 20 23:47:51 genie kernel: [600473.429229] RPC: Successfully imported new context.
Oct 20 23:47:51 genie kernel: [600473.429258] RPC: gss_pipe_downcall returning 109
Oct 20 23:47:51 genie kernel: [600473.429299] RPC: gss_create_upcall for uid 0 result 0
Oct 20 23:47:51 genie kernel: [600473.429322] RPC: new task initialized, procpid 26217
Oct 20 23:47:51 genie kernel: [600473.429340] RPC: allocated task c39f93c0
Oct 20 23:47:51 genie kernel: [600473.429356] RPC: 437 __rpc_execute flags=0x80
Oct 20 23:47:51 genie kernel: [600473.429374] RPC: 437 call_start nfs4 proc LOOKUP_ROOT (sync)
Oct 20 23:47:51 genie kernel: [600473.429408] RPC: 437 call_reserve (status 0)
Oct 20 23:47:51 genie kernel: [600473.429428] RPC: 437 reserved req d6911000 xid 674da781
Oct 20 23:47:51 genie kernel: [600473.429446] RPC: 437 call_reserveresult (status 0)
Oct 20 23:47:51 genie kernel: [600473.429462] RPC: 437 call_allocate (status 0)
Oct 20 23:47:51 genie kernel: [600473.429480] RPC: 437 allocated buffer of size 3712 at d6915000
Oct 20 23:47:51 genie kernel: [600473.429499] RPC: 437 call_bind (status 0)
Oct 20 23:47:51 genie kernel: [600473.429514] RPC: 437 call_connect xprt c3966000 is connected
Oct 20 23:47:51 genie kernel: [600473.429533] RPC: 437 call_transmit (status 0)
Oct 20 23:47:51 genie kernel: [600473.429548] RPC: 437 xprt_prepare_transmit
Oct 20 23:47:51 genie kernel: [600473.429564] RPC: 437 rpc_xdr_encode (status 0)
Oct 20 23:47:51 genie kernel: [600473.429581] RPC: 437 marshaling RPCSEC_GSS cred df1f9300
Oct 20 23:47:51 genie kernel: [600473.429598] RPC: 437 gss_marshal
Oct 20 23:47:51 genie kernel: [600473.429612] RPC: gss_krb5_seal
Oct 20 23:47:51 genie kernel: [600473.429669] RPC: krb5_encrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.429702] RPC: krb5_encrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.429723] RPC: 437 using AUTH_GSS cred df1f9300 to wrap rpc data
Oct 20 23:47:51 genie kernel: [600473.429742] RPC: 437 gss_wrap_req
Oct 20 23:47:51 genie kernel: [600473.429756] encode_compound: tag=
Oct 20 23:47:51 genie kernel: [600473.429772] RPC: 437 gss_wrap_req returning 0
Oct 20 23:47:51 genie kernel: [600473.429788] RPC: 437 xprt_transmit(144)
Oct 20 23:47:51 genie kernel: [600473.429863] svc: socket df94a880 TCP data ready (svsk de825400)
Oct 20 23:47:51 genie kernel: [600473.429890] svc: transport de825400 served by daemon c0f0b000
Oct 20 23:47:51 genie kernel: [600473.429926] RPC: xs_tcp_send_request(144) = 144
Oct 20 23:47:51 genie kernel: [600473.429944] RPC: 437 xmit complete
Oct 20 23:47:51 genie kernel: [600473.429961] RPC: 437 sleep_on(queue "xprt_pending" time 60015194)
Oct 20 23:47:51 genie kernel: [600473.429981] RPC: 437 added to queue c39661d0 "xprt_pending"
Oct 20 23:47:51 genie kernel: [600473.429999] RPC: 437 setting alarm for 60000 ms
Oct 20 23:47:51 genie kernel: [600473.430018] RPC: wake_up_next(c396616c "xprt_resend")
Oct 20 23:47:51 genie kernel: [600473.430036] RPC: wake_up_next(c3966108 "xprt_sending")
Oct 20 23:47:51 genie kernel: [600473.430054] RPC: 437 sync task going to sleep
Oct 20 23:47:51 genie kernel: [600473.430134] svc: server c0f0b000, pool 0, transport de825400, inuse=2
Oct 20 23:47:51 genie kernel: [600473.430161] svc: tcp_recv de825400 data 1 conn 0 close 0
Oct 20 23:47:51 genie kernel: [600473.430187] svc: socket de825400 recvfrom(de8255c8, 0) = 4
Oct 20 23:47:51 genie kernel: [600473.430204] svc: TCP record, 140 bytes
Oct 20 23:47:51 genie kernel: [600473.430225] svc: socket de825400 recvfrom(c39f7008, 4088) = 8
Oct 20 23:47:51 genie kernel: [600473.430249] svc: socket de825400 recvfrom(c39f708c, 3956) = 132
Oct 20 23:47:51 genie kernel: [600473.430267] svc: TCP complete record (140 bytes)
Oct 20 23:47:51 genie kernel: [600473.430286] svc: transport de825400 served by daemon dee34000
Oct 20 23:47:51 genie kernel: [600473.430309] svc: got len=140
Oct 20 23:47:51 genie kernel: [600473.430326] svc: svc_authenticate (6)
Oct 20 23:47:51 genie kernel: [600473.430341] RPC: svcauth_gss: argv->iov_len = 112
Oct 20 23:47:51 genie kernel: [600473.430365] RPC: krb5_read_token
Oct 20 23:47:51 genie kernel: [600473.430411] RPC: krb5_encrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.430429] RPC: krb5_get_seq_num:
Oct 20 23:47:51 genie kernel: [600473.430451] RPC: gss_k5decrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.430469] RPC: gss_krb5_seal
Oct 20 23:47:51 genie kernel: [600473.430505] RPC: krb5_encrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.430533] RPC: krb5_encrypt returns 0
Oct 20 23:47:51 genie kernel: [600473.430583] svc: svc_process dropit
Oct 20 23:47:51 genie kernel: [600473.430599] svc: xprt de825400 dropped request
Oct 20 23:47:51 genie kernel: [600473.430618] svc: transport de825400 busy, not enqueued
Oct 20 23:47:51 genie kernel: [600473.430637] svc: server c0f0b000 waiting for data (to = 360000)
Oct 20 23:47:51 genie kernel: [600473.430672] svc: server dee34000, pool 0, transport de825400, inuse=3
Oct 20 23:47:51 genie kernel: [600473.430694] svc: tcp_recv de825400 data 1 conn 0 close 0
Oct 20 23:47:51 genie kernel: [600473.430717] svc: socket de825400 recvfrom(de8255c4, 4) = -11
Oct 20 23:47:51 genie kernel: [600473.430733] RPC: TCP recv_record got EAGAIN
Oct 20 23:47:51 genie kernel: [600473.430748] svc: got len=-11
Oct 20 23:47:51 genie kernel: [600473.430762] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:51 genie kernel: [600473.431850] svc: socket df948900 TCP (connected) state change 8 (svsk deda1a00)
Oct 20 23:47:51 genie kernel: [600473.431887] svc: transport deda1a00 served by daemon dee34000
Oct 20 23:47:51 genie kernel: [600473.431912] svc: socket df948900 TCP data ready (svsk deda1a00)
Oct 20 23:47:51 genie kernel: [600473.431931] svc: transport deda1a00 busy, not enqueued
Oct 20 23:47:51 genie kernel: [600473.431966] svc_recv: found XPT_CLOSE
Oct 20 23:47:51 genie kernel: [600473.431982] svc: svc_delete_xprt(deda1a00)
Oct 20 23:47:51 genie kernel: [600473.431997] svc: svc_tcp_sock_detach(deda1a00)
Oct 20 23:47:51 genie kernel: [600473.432013] svc: svc_sock_detach(deda1a00)
Oct 20 23:47:51 genie kernel: [600473.432114] svc: transport deda1a00 is dead, not enqueued
Oct 20 23:47:51 genie kernel: [600473.432136] svc: svc_sock_free(deda1a00)
Oct 20 23:47:51 genie kernel: [600473.432165] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:58 genie kernel: [600480.250341] svc: socket df948d80 TCP data ready (svsk de4ac000)
Oct 20 23:47:58 genie kernel: [600480.250379] svc: transport de4ac000 served by daemon dee34000
Oct 20 23:47:58 genie kernel: [600480.250432] svc: server dee34000, pool 0, transport de4ac000, inuse=2
Oct 20 23:47:58 genie kernel: [600480.250456] svc: tcp_recv de4ac000 data 1 conn 0 close 0
Oct 20 23:47:58 genie kernel: [600480.250484] svc: socket de4ac000 recvfrom(de4ac1c8, 0) = 4
Oct 20 23:47:58 genie kernel: [600480.250502] svc: TCP record, 152 bytes
Oct 20 23:47:58 genie kernel: [600480.250523] svc: socket de4ac000 recvfrom(c3953008, 4088) = 8
Oct 20 23:47:58 genie kernel: [600480.250549] svc: socket de4ac000 recvfrom(c3953098, 3944) = 144
Oct 20 23:47:58 genie kernel: [600480.250567] svc: TCP complete record (152 bytes)
Oct 20 23:47:58 genie kernel: [600480.250586] svc: transport de4ac000 served by daemon c0f0b000
Oct 20 23:47:58 genie kernel: [600480.250609] svc: got len=152
Oct 20 23:47:58 genie kernel: [600480.250627] svc: svc_authenticate (1)
Oct 20 23:47:58 genie kernel: [600480.250653] svc: calling dispatcher
Oct 20 23:47:58 genie kernel: [600480.250749] svc: socket de4ac000 sendto([c3845000 48... ], 48) = 48 (addr 172.22.21.203, port=706)
Oct 20 23:47:58 genie kernel: [600480.250783] svc: transport de4ac000 busy, not enqueued
Oct 20 23:47:58 genie kernel: [600480.250804] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:47:58 genie kernel: [600480.250839] svc: server c0f0b000, pool 0, transport de4ac000, inuse=2
Oct 20 23:47:58 genie kernel: [600480.250862] svc: tcp_recv de4ac000 data 1 conn 0 close 0
Oct 20 23:47:58 genie kernel: [600480.250884] svc: socket de4ac000 recvfrom(de4ac1c4, 4) = -11
Oct 20 23:47:58 genie kernel: [600480.250900] RPC: TCP recv_record got EAGAIN
Oct 20 23:47:58 genie kernel: [600480.250956] svc: got len=-11
Oct 20 23:47:58 genie kernel: [600480.250975] svc: server c0f0b000 waiting for data (to = 360000)
Oct 20 23:48:03 genie kernel: [600485.902454] RPC: unx_free_cred deecb900
Oct 20 23:48:18 genie kernel: [600500.662413] RPC: 437 got signal
Oct 20 23:48:18 genie kernel: [600500.662441] RPC: 437 __rpc_wake_up_task (now 60017918)
Oct 20 23:48:18 genie kernel: [600500.662457] RPC: 437 disabling timer
Oct 20 23:48:18 genie kernel: [600500.662475] RPC: 437 removed from queue c39661d0 "xprt_pending"
Oct 20 23:48:18 genie kernel: [600500.662493] RPC: __rpc_wake_up_task done
Oct 20 23:48:18 genie kernel: [600500.662508] RPC: 437 sync task resuming
Oct 20 23:48:18 genie kernel: [600500.662524] RPC: 437 return -512, status -512
Oct 20 23:48:18 genie kernel: [600500.662539] RPC: 437 release task
Oct 20 23:48:18 genie kernel: [600500.662558] RPC: freeing buffer of size 3712 at d6915000
Oct 20 23:48:18 genie kernel: [600500.662578] RPC: 437 release request d6911000
Oct 20 23:48:18 genie kernel: [600500.662594] RPC: wake_up_next(c3966234 "xprt_backlog")
Oct 20 23:48:18 genie kernel: [600500.662613] RPC: 437 releasing RPCSEC_GSS cred df1f9300
Oct 20 23:48:18 genie kernel: [600500.662631] RPC: rpc_release_client(de639e00)
Oct 20 23:48:18 genie kernel: [600500.662648] RPC: 437 freeing task
Oct 20 23:48:18 genie kernel: [600500.662664] nfs4_get_root: getroot error = 512
Oct 20 23:48:18 genie kernel: [600500.662679] --> nfs_free_server()
Oct 20 23:48:18 genie kernel: [600500.662694] RPC: shutting down nfs client for genie
Oct 20 23:48:18 genie kernel: [600500.662710] RPC: rpc_release_client(de639e00)
Oct 20 23:48:18 genie kernel: [600500.662726] RPC: destroying nfs client for genie
Oct 20 23:48:18 genie kernel: [600500.662793] RPC: rpc_release_client(de639900)
Oct 20 23:48:18 genie kernel: [600500.662815] --> nfs_put_client({1})
Oct 20 23:48:18 genie kernel: [600500.662830] --> nfs_free_client(4)
Oct 20 23:48:18 genie kernel: [600500.664081] svc: server d6913000, no data yet
Oct 20 23:48:18 genie kernel: [600500.666814] svc: svc_destroy(NFSv4 callback, 1)
Oct 20 23:48:18 genie kernel: [600500.666845] svc: svc_delete_xprt(df930a00)
Oct 20 23:48:18 genie kernel: [600500.666860] svc: svc_tcp_sock_detach(df930a00)
Oct 20 23:48:18 genie kernel: [600500.666875] svc: svc_sock_detach(df930a00)
Oct 20 23:48:18 genie kernel: [600500.666891] svc: svc_sock_free(df930a00)
Oct 20 23:48:18 genie kernel: [600500.666928] svc: svc_delete_xprt(df930e00)
Oct 20 23:48:18 genie kernel: [600500.666943] svc: svc_tcp_sock_detach(df930e00)
Oct 20 23:48:18 genie kernel: [600500.666958] svc: svc_sock_detach(df930e00)
Oct 20 23:48:18 genie kernel: [600500.666973] svc: svc_sock_free(df930e00)
Oct 20 23:48:18 genie kernel: [600500.667001] RPC: unregistering [1073741824, 1, ''] with local rpcbind
Oct 20 23:48:18 genie kernel: [600500.667044] RPC: set up xprt to 127.0.0.1 (port 111) via udp
Oct 20 23:48:18 genie kernel: [600500.667068] RPC: created transport c39c4000 with 16 slots
Oct 20 23:48:18 genie kernel: [600500.667088] RPC: creating rpcbind client for localhost (xprt c39c4000)
Oct 20 23:48:18 genie kernel: [600500.667114] RPC: creating UNIX authenticator for client de639e00
Oct 20 23:48:18 genie kernel: [600500.667138] RPC: 0 looking up UNIX cred
Oct 20 23:48:18 genie kernel: [600500.667152] RPC: looking up UNIX cred
Oct 20 23:48:18 genie kernel: [600500.667169] RPC: new task initialized, procpid 26217
Oct 20 23:48:18 genie kernel: [600500.667186] RPC: allocated task c0cc6500
Oct 20 23:48:18 genie kernel: [600500.667202] RPC: 438 __rpc_execute flags=0x280
Oct 20 23:48:18 genie kernel: [600500.667219] RPC: 438 call_start rpcbind4 proc UNSET (sync)
Oct 20 23:48:18 genie kernel: [600500.667237] RPC: 438 call_reserve (status 0)
Oct 20 23:48:18 genie kernel: [600500.667255] RPC: 438 reserved req df957000 xid 0d86ad6c
Oct 20 23:48:18 genie kernel: [600500.667272] RPC: 438 call_reserveresult (status 0)
Oct 20 23:48:18 genie kernel: [600500.667289] RPC: 438 call_allocate (status 0)
Oct 20 23:48:18 genie kernel: [600500.667307] RPC: 438 allocated buffer of size 484 at de7a7000
Oct 20 23:48:18 genie kernel: [600500.667326] RPC: 438 call_bind (status 0)
Oct 20 23:48:18 genie kernel: [600500.667342] RPC: 438 call_connect xprt c39c4000 is not connected
Oct 20 23:48:18 genie kernel: [600500.667361] RPC: 438 xprt_connect xprt c39c4000 is not connected
Oct 20 23:48:18 genie kernel: [600500.667381] RPC: 438 xprt_cwnd_limited cong = 0 cwnd = 256
Oct 20 23:48:18 genie kernel: [600500.667400] RPC: 438 sleep_on(queue "xprt_pending" time 60017918)
Oct 20 23:48:18 genie kernel: [600500.667420] RPC: 438 added to queue c39c41d0 "xprt_pending"
Oct 20 23:48:18 genie kernel: [600500.667438] RPC: 438 setting alarm for 5000 ms
Oct 20 23:48:18 genie kernel: [600500.667455] RPC: xs_connect scheduled xprt c39c4000
Oct 20 23:48:18 genie kernel: [600500.667480] RPC: 438 sync task going to sleep
Oct 20 23:48:18 genie kernel: [600500.667529] RPC: xs_bind4 0.0.0.0:949: ok (0)
Oct 20 23:48:18 genie kernel: [600500.667550] RPC: worker connecting xprt c39c4000 via udp to 127.0.0.1 (port 111)
Oct 20 23:48:18 genie kernel: [600500.667576] RPC: 438 __rpc_wake_up_task (now 60017918)
Oct 20 23:48:18 genie kernel: [600500.667593] RPC: 438 disabling timer
Oct 20 23:48:18 genie kernel: [600500.667609] RPC: 438 removed from queue c39c41d0 "xprt_pending"
Oct 20 23:48:18 genie kernel: [600500.667630] RPC: __rpc_wake_up_task done
Oct 20 23:48:18 genie kernel: [600500.668293] RPC: 438 sync task resuming
Oct 20 23:48:18 genie kernel: [600500.668317] RPC: 438 xprt_connect_status: connection established
Oct 20 23:48:18 genie kernel: [600500.668406] RPC: 438 call_connect_status (status 0)
Oct 20 23:48:18 genie kernel: [600500.668433] RPC: 438 call_transmit (status 0)
Oct 20 23:48:18 genie kernel: [600500.668450] RPC: 438 xprt_prepare_transmit
Oct 20 23:48:18 genie kernel: [600500.668467] RPC: 438 rpc_xdr_encode (status 0)
Oct 20 23:48:18 genie kernel: [600500.668485] RPC: 438 marshaling UNIX cred deee8280
Oct 20 23:48:18 genie kernel: [600500.668505] RPC: 438 using AUTH_UNIX cred deee8280 to wrap rpc data
Oct 20 23:48:18 genie kernel: [600500.668527] RPC: 438 encoding RPCB_UNSET call (1073741824, 1, '', '')
Oct 20 23:48:18 genie kernel: [600500.668548] RPC: 438 xprt_transmit(96)
Oct 20 23:48:18 genie kernel: [600500.668614] RPC: xs_udp_send_request(96) = 96
Oct 20 23:48:18 genie kernel: [600500.668634] RPC: 438 xmit complete
Oct 20 23:48:18 genie kernel: [600500.668650] RPC: 438 sleep_on(queue "xprt_pending" time 60017918)
Oct 20 23:48:18 genie kernel: [600500.668670] RPC: 438 added to queue c39c41d0 "xprt_pending"
Oct 20 23:48:18 genie kernel: [600500.668688] RPC: 438 setting alarm for 5000 ms
Oct 20 23:48:18 genie kernel: [600500.668706] RPC: 438 sync task going to sleep
Oct 20 23:48:18 genie kernel: [600500.669141] RPC: xs_udp_data_ready...
Oct 20 23:48:18 genie kernel: [600500.669174] RPC: cong 256, cwnd was 256, now 512
Oct 20 23:48:18 genie kernel: [600500.669194] RPC: wake_up_next(c39c416c "xprt_resend")
Oct 20 23:48:18 genie kernel: [600500.669213] RPC: wake_up_next(c39c4108 "xprt_sending")
Oct 20 23:48:18 genie kernel: [600500.669233] RPC: 438 xid 0d86ad6c complete (28 bytes received)
Oct 20 23:48:18 genie kernel: [600500.669251] RPC: 438 __rpc_wake_up_task (now 60017918)
Oct 20 23:48:18 genie kernel: [600500.669267] RPC: 438 disabling timer
Oct 20 23:48:18 genie kernel: [600500.669283] RPC: 438 removed from queue c39c41d0 "xprt_pending"
Oct 20 23:48:18 genie kernel: [600500.669307] RPC: __rpc_wake_up_task done
Oct 20 23:48:18 genie kernel: [600500.669374] RPC: 438 sync task resuming
Oct 20 23:48:18 genie kernel: [600500.669395] RPC: 438 call_status (status 28)
Oct 20 23:48:18 genie kernel: [600500.669410] RPC: 438 call_decode (status 28)
Oct 20 23:48:18 genie kernel: [600500.669428] RPC: 438 validating UNIX cred deee8280
Oct 20 23:48:18 genie kernel: [600500.669446] RPC: 438 using AUTH_UNIX cred deee8280 to unwrap rpc data
Oct 20 23:48:18 genie kernel: [600500.669467] RPC: 438 RPCB_UNSET call succeeded
Oct 20 23:48:18 genie kernel: [600500.669482] RPC: 438 call_decode result 0
Oct 20 23:48:18 genie kernel: [600500.669498] RPC: 438 return 0, status 0
Oct 20 23:48:18 genie kernel: [600500.669511] RPC: 438 release task
Oct 20 23:48:18 genie kernel: [600500.669530] RPC: freeing buffer of size 484 at de7a7000
Oct 20 23:48:18 genie kernel: [600500.669549] RPC: 438 release request df957000
Oct 20 23:48:18 genie kernel: [600500.669565] RPC: wake_up_next(c39c4234 "xprt_backlog")
Oct 20 23:48:18 genie kernel: [600500.669584] RPC: 438 releasing UNIX cred deee8280
Oct 20 23:48:18 genie kernel: [600500.669601] RPC: rpc_release_client(de639e00)
Oct 20 23:48:18 genie kernel: [600500.669617] RPC: 438 freeing task
Oct 20 23:48:18 genie kernel: [600500.669632] RPC: shutting down rpcbind client for localhost
Oct 20 23:48:18 genie kernel: [600500.669650] RPC: rpc_release_client(de639e00)
Oct 20 23:48:18 genie kernel: [600500.669666] RPC: destroying rpcbind client for localhost
Oct 20 23:48:18 genie kernel: [600500.669685] RPC: destroying transport c39c4000
Oct 20 23:48:18 genie kernel: [600500.669702] RPC: xs_destroy xprt c39c4000
Oct 20 23:48:18 genie kernel: [600500.669718] RPC: xs_close xprt c39c4000
Oct 20 23:48:18 genie kernel: [600500.669746] RPC: disconnected transport c39c4000
Oct 20 23:48:18 genie kernel: [600500.669769] svc: __svc_unregister(NFSv4 callbackv1), error 0
Oct 20 23:48:18 genie kernel: [600500.669825] RPC: shutting down nfs client for genie
Oct 20 23:48:18 genie kernel: [600500.669845] RPC: rpc_release_client(de639900)
Oct 20 23:48:18 genie kernel: [600500.669863] RPC: destroying GSS authenticator c3a33544 flavor 390003
Oct 20 23:48:18 genie kernel: [600500.669889] RPC: 0 holding RPCSEC_GSS cred df1f9300
Oct 20 23:48:18 genie kernel: [600500.669906] RPC: new task initialized, procpid 26217
Oct 20 23:48:18 genie kernel: [600500.669922] RPC: allocated task c0cc6500
Oct 20 23:48:18 genie kernel: [600500.669938] RPC: 439 __rpc_execute flags=0x281
Oct 20 23:48:18 genie kernel: [600500.669955] RPC: 439 call_start nfs4 proc NULL (async)
Oct 20 23:48:18 genie kernel: [600500.669973] RPC: 439 call_reserve (status 0)
Oct 20 23:48:18 genie kernel: [600500.669991] RPC: 439 reserved req d6911000 xid 684da781
Oct 20 23:48:18 genie kernel: [600500.670008] RPC: 439 call_reserveresult (status 0)
Oct 20 23:48:18 genie kernel: [600500.670024] RPC: 439 call_allocate (status 0)
Oct 20 23:48:18 genie kernel: [600500.670042] RPC: 439 allocated buffer of size 3116 at df957000
Oct 20 23:48:18 genie kernel: [600500.670060] RPC: 439 call_bind (status 0)
Oct 20 23:48:18 genie kernel: [600500.670076] RPC: 439 call_connect xprt c3966000 is connected
Oct 20 23:48:18 genie kernel: [600500.670094] RPC: 439 call_transmit (status 0)
Oct 20 23:48:18 genie kernel: [600500.670109] RPC: 439 xprt_prepare_transmit
Oct 20 23:48:18 genie kernel: [600500.670125] RPC: 439 rpc_xdr_encode (status 0)
Oct 20 23:48:18 genie kernel: [600500.670143] RPC: 439 marshaling RPCSEC_GSS cred df1f9300
Oct 20 23:48:18 genie kernel: [600500.670160] RPC: 439 gss_marshal
Oct 20 23:48:18 genie kernel: [600500.670174] RPC: gss_krb5_seal
Oct 20 23:48:18 genie kernel: [600500.670235] RPC: krb5_encrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.670266] RPC: krb5_encrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.670288] RPC: 439 using AUTH_GSS cred df1f9300 to wrap rpc data
Oct 20 23:48:18 genie kernel: [600500.670307] RPC: 439 gss_wrap_req
Oct 20 23:48:18 genie kernel: [600500.670321] RPC: 439 gss_wrap_req returning 0
Oct 20 23:48:18 genie kernel: [600500.670336] RPC: 439 xprt_transmit(108)
Oct 20 23:48:18 genie kernel: [600500.670412] svc: socket df94a880 TCP data ready (svsk de825400)
Oct 20 23:48:18 genie kernel: [600500.670438] svc: transport de825400 served by daemon c0f0b000
Oct 20 23:48:18 genie kernel: [600500.670495] svc: server c0f0b000, pool 0, transport de825400, inuse=3
Oct 20 23:48:18 genie kernel: [600500.670520] svc: tcp_recv de825400 data 1 conn 0 close 0
Oct 20 23:48:18 genie kernel: [600500.670546] svc: socket de825400 recvfrom(de8255c8, 0) = 4
Oct 20 23:48:18 genie kernel: [600500.670563] svc: TCP record, 104 bytes
Oct 20 23:48:18 genie kernel: [600500.670584] svc: socket de825400 recvfrom(c39f7008, 4088) = 8
Oct 20 23:48:18 genie kernel: [600500.670609] svc: socket de825400 recvfrom(c39f7068, 3992) = 96
Oct 20 23:48:18 genie kernel: [600500.670627] svc: TCP complete record (104 bytes)
Oct 20 23:48:18 genie kernel: [600500.670646] svc: transport de825400 served by daemon dee34000
Oct 20 23:48:18 genie kernel: [600500.670668] svc: got len=104
Oct 20 23:48:18 genie kernel: [600500.670685] svc: svc_authenticate (6)
Oct 20 23:48:18 genie kernel: [600500.670700] RPC: svcauth_gss: argv->iov_len = 76
Oct 20 23:48:18 genie kernel: [600500.670724] RPC: krb5_read_token
Oct 20 23:48:18 genie kernel: [600500.670768] RPC: krb5_encrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.670786] RPC: krb5_get_seq_num:
Oct 20 23:48:18 genie kernel: [600500.670809] RPC: gss_k5decrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.670828] RPC: gss_krb5_seal
Oct 20 23:48:18 genie kernel: [600500.670863] RPC: krb5_encrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.670890] RPC: krb5_encrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.670954] svc: socket de825400 sendto([c393d000 68... ], 68) = 68 (addr 172.22.21.8, port=935)
Oct 20 23:48:18 genie kernel: [600500.670986] svc: transport de825400 busy, not enqueued
Oct 20 23:48:18 genie kernel: [600500.671006] svc: server c0f0b000 waiting for data (to = 360000)
Oct 20 23:48:18 genie kernel: [600500.671041] svc: server dee34000, pool 0, transport de825400, inuse=3
Oct 20 23:48:18 genie kernel: [600500.671063] svc: tcp_recv de825400 data 1 conn 0 close 0
Oct 20 23:48:18 genie kernel: [600500.671085] svc: socket de825400 recvfrom(de8255c4, 4) = -11
Oct 20 23:48:18 genie kernel: [600500.671102] RPC: TCP recv_record got EAGAIN
Oct 20 23:48:18 genie kernel: [600500.671117] svc: got len=-11
Oct 20 23:48:18 genie kernel: [600500.671131] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:48:18 genie kernel: [600500.682781] RPC: xs_tcp_data_ready...
Oct 20 23:48:18 genie kernel: [600500.682813] RPC: xs_tcp_data_recv started
Oct 20 23:48:18 genie kernel: [600500.682831] RPC: reading TCP record fragment of length 64
Oct 20 23:48:18 genie kernel: [600500.682849] RPC: reading XID (4 bytes)
Oct 20 23:48:18 genie kernel: [600500.682865] RPC: reading reply for XID 684da781
Oct 20 23:48:18 genie kernel: [600500.682881] RPC: reading CALL/REPLY flag (4 bytes)
Oct 20 23:48:18 genie kernel: [600500.682897] RPC: read reply XID 684da781
Oct 20 23:48:18 genie kernel: [600500.682915] RPC: XID 684da781 read 56 bytes
Oct 20 23:48:18 genie kernel: [600500.682933] RPC: xprt = c3966000, tcp_copied = 64, tcp_offset = 64, tcp_reclen = 64
Oct 20 23:48:18 genie kernel: [600500.682959] RPC: 439 xid 684da781 complete (64 bytes received)
Oct 20 23:48:18 genie kernel: [600500.682977] RPC: xs_tcp_data_recv done
Oct 20 23:48:18 genie kernel: [600500.683023] RPC: xs_tcp_send_request(108) = 108
Oct 20 23:48:18 genie kernel: [600500.683042] RPC: 439 xmit complete
Oct 20 23:48:18 genie kernel: [600500.683060] RPC: wake_up_next(c396616c "xprt_resend")
Oct 20 23:48:18 genie kernel: [600500.683079] RPC: wake_up_next(c3966108 "xprt_sending")
Oct 20 23:48:18 genie kernel: [600500.683099] RPC: 439 call_status (status 64)
Oct 20 23:48:18 genie kernel: [600500.683114] RPC: 439 call_decode (status 64)
Oct 20 23:48:18 genie kernel: [600500.683132] RPC: 439 validating RPCSEC_GSS cred df1f9300
Oct 20 23:48:18 genie kernel: [600500.683149] RPC: 439 gss_validate
Oct 20 23:48:18 genie kernel: [600500.683163] RPC: krb5_read_token
Oct 20 23:48:18 genie kernel: [600500.683220] RPC: krb5_encrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.683238] RPC: krb5_get_seq_num:
Oct 20 23:48:18 genie kernel: [600500.683261] RPC: gss_k5decrypt returns 0
Oct 20 23:48:18 genie kernel: [600500.683279] RPC: 439 gss_validate: gss_verify_mic succeeded.
Oct 20 23:48:18 genie kernel: [600500.683299] RPC: 439 using AUTH_GSS cred df1f9300 to unwrap rpc data
Oct 20 23:48:18 genie kernel: [600500.683319] RPC: 439 gss_unwrap_resp returning 0
Oct 20 23:48:18 genie kernel: [600500.683335] RPC: 439 call_decode result 0
Oct 20 23:48:18 genie kernel: [600500.683350] RPC: 439 return 0, status 0
Oct 20 23:48:18 genie kernel: [600500.683364] RPC: 439 release task
Oct 20 23:48:18 genie kernel: [600500.683383] RPC: freeing buffer of size 3116 at df957000
Oct 20 23:48:18 genie kernel: [600500.683403] RPC: 439 release request d6911000
Oct 20 23:48:18 genie kernel: [600500.683419] RPC: wake_up_next(c3966234 "xprt_backlog")
Oct 20 23:48:18 genie kernel: [600500.683438] RPC: 439 releasing RPCSEC_GSS cred df1f9300
Oct 20 23:48:18 genie kernel: [600500.683455] RPC: rpc_release_client(de639900)
Oct 20 23:48:18 genie kernel: [600500.683472] RPC: 439 freeing task
Oct 20 23:48:18 genie kernel: [600500.683487] RPC: gss_delete_sec_context deleting d697da40
Oct 20 23:48:18 genie kernel: [600500.685720] RPC: destroying nfs client for genie
Oct 20 23:48:18 genie kernel: [600500.685777] RPC: destroying transport c3966000
Oct 20 23:48:18 genie kernel: [600500.685796] RPC: xs_destroy xprt c3966000
Oct 20 23:48:18 genie kernel: [600500.686301] RPC: xs_close xprt c3966000
Oct 20 23:48:18 genie kernel: [600500.686377] svc: socket df94a880 TCP (connected) state change 8 (svsk de825400)
Oct 20 23:48:18 genie kernel: [600500.686406] svc: transport de825400 served by daemon dee34000
Oct 20 23:48:18 genie kernel: [600500.686433] svc: socket df94a880 TCP data ready (svsk de825400)
Oct 20 23:48:18 genie kernel: [600500.686452] svc: transport de825400 busy, not enqueued
Oct 20 23:48:18 genie kernel: [600500.686485] svc_recv: found XPT_CLOSE
Oct 20 23:48:18 genie kernel: [600500.686501] svc: svc_delete_xprt(de825400)
Oct 20 23:48:18 genie kernel: [600500.686516] svc: svc_tcp_sock_detach(de825400)
Oct 20 23:48:18 genie kernel: [600500.686531] svc: svc_sock_detach(de825400)
Oct 20 23:48:18 genie kernel: [600500.686629] svc: transport de825400 is dead, not enqueued
Oct 20 23:48:18 genie kernel: [600500.686653] svc: server dee34000 waiting for data (to = 360000)
Oct 20 23:48:18 genie kernel: [600500.686686] RPC: disconnected transport c3966000
Oct 20 23:48:18 genie kernel: [600500.686709] <-- nfs_free_client()
Oct 20 23:48:18 genie kernel: [600500.686725] <-- nfs_free_server()
Oct 20 23:48:18 genie kernel: [600500.686739] <-- nfs4_create_server() = error -512
Oct 20 23:48:18 genie kernel: [600500.686760] <-- nfs4_get_sb() = -512 [error]
Oct 20 23:48:18 genie kernel: [600500.702377] RPC: gss_free_cred df1f9300
Oct 20 23:48:18 genie kernel: [600500.702405] RPC: gss_free_ctx
