* sec=krb5 mounts never return
@ 2011-10-20 23:23 Arno Schuring
2011-10-21 14:33 ` Kevin Coffman
2011-10-25 22:00 ` Arno Schuring
0 siblings, 2 replies; 7+ messages in thread
From: Arno Schuring @ 2011-10-20 23:23 UTC (permalink / raw)
To: linux-nfs
Hello list,
tl;dr: mount calls with sec=krb5 never return. They appear to get
stalled in the kernel on "svc: transport is dead". I need to know
if this is a configuration issue, a kernel problem or a userland
problem, and how it can be resolved.
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:
# mount -vvv -t nfs4 -o sec=krb5 genie:/media /mnt
mount: fstab path: "/etc/fstab"
mount: mtab path: "/etc/mtab"
mount: lock path: "/etc/mtab~"
mount: temp path: "/etc/mtab.tmp"
mount: UID: 0
mount: eUID: 0
mount: spec: "genie:/media"
mount: node: "/mnt"
mount: types: "nfs4"
mount: opts: "sec=krb5"
mount: external mount: argv[0] = "/sbin/mount.nfs4"
mount: external mount: argv[1] = "genie:/media"
mount: external mount: argv[2] = "/mnt"
mount: external mount: argv[3] = "-v"
mount: external mount: argv[4] = "-o"
mount: external mount: argv[5] = "rw,sec=krb5"
mount.nfs4: timeout set for Sun Oct 16 22:52:10 2011
mount.nfs4: trying text-based options
'sec=krb5,addr=172.22.21.8,clientaddr=172.22.21.5'
And there it just seems to hang (the timeout is ignored completely)
until killed via signal or Ctrl-C. The same mount without sec=krb5
completes without issue:
# mount -v -t nfs4 genie:/media /mnt
mount.nfs4: timeout set for Thu Oct 20 23:48:55 2011
mount.nfs4: trying text-based options
'addr=172.22.21.8,clientaddr=172.22.21.8'
genie:/media on /mnt type nfs4 (rw)
The machine is running a fully updated Debian 6.0 (Squeeze). So far I
have only tried with one other client (also Squeeze) with similar
results. Relevant software versions: kernel 2.6.32 (armel) and
nfs-utils 1.2.2.
The only suggestion that Google has been able to give me was to verify
that the rpcsec_gss_krb5 was loaded, and it is:
$ lsmod|grep gss
rpcsec_gss_krb5 9026 5
auth_rpcgss 33334 4 rpcsec_gss_krb5,nfsd,nfs
sunrpc 171216 21 [..]
Reproducible with only these exports:
# exportfs -v
/srv/nfs 172.22.21.8(ro,wdelay,root_squash,no_subtree_check,fsid=0)
/srv/nfs gss/krb5(ro,wdelay,root_squash,no_subtree_check,fsid=0)
I can provide a full rpc_debug/svc_debug log if required. I'm not
attaching it now because it is somewhat large (well, 60k) and I'm not
even sure that user issues are on-topic for this list. What looks
suspicious to me is the following excerpt:
[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
I'd be grateful for any pointers,
Arno
(not subscribed, please keep me in CC)
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: sec=krb5 mounts never return
2011-10-20 23:23 sec=krb5 mounts never return Arno Schuring
@ 2011-10-21 14:33 ` Kevin Coffman
2011-10-21 20:10 ` Arno Schuring
2011-10-25 22:00 ` Arno Schuring
1 sibling, 1 reply; 7+ messages in thread
From: Kevin Coffman @ 2011-10-21 14:33 UTC (permalink / raw)
To: Arno Schuring; +Cc: linux-nfs
On Thu, Oct 20, 2011 at 7:23 PM, Arno Schuring <aelschuring@hotmail.com> wrote:
> Hello list,
>
> tl;dr: mount calls with sec=krb5 never return. They appear to get
> stalled in the kernel on "svc: transport is dead". I need to know
> if this is a configuration issue, a kernel problem or a userland
> problem, and how it can be resolved.
>
>
> 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:
>
> # mount -vvv -t nfs4 -o sec=krb5 genie:/media /mnt
> mount: fstab path: "/etc/fstab"
> mount: mtab path: "/etc/mtab"
> mount: lock path: "/etc/mtab~"
> mount: temp path: "/etc/mtab.tmp"
> mount: UID: 0
> mount: eUID: 0
> mount: spec: "genie:/media"
> mount: node: "/mnt"
> mount: types: "nfs4"
> mount: opts: "sec=krb5"
> mount: external mount: argv[0] = "/sbin/mount.nfs4"
> mount: external mount: argv[1] = "genie:/media"
> mount: external mount: argv[2] = "/mnt"
> mount: external mount: argv[3] = "-v"
> mount: external mount: argv[4] = "-o"
> mount: external mount: argv[5] = "rw,sec=krb5"
> mount.nfs4: timeout set for Sun Oct 16 22:52:10 2011
> mount.nfs4: trying text-based options
> 'sec=krb5,addr=172.22.21.8,clientaddr=172.22.21.5'
>
> And there it just seems to hang (the timeout is ignored completely)
> until killed via signal or Ctrl-C. The same mount without sec=krb5
> completes without issue:
> # mount -v -t nfs4 genie:/media /mnt
> mount.nfs4: timeout set for Thu Oct 20 23:48:55 2011
> mount.nfs4: trying text-based options
> 'addr=172.22.21.8,clientaddr=172.22.21.8'
> genie:/media on /mnt type nfs4 (rw)
>
> The machine is running a fully updated Debian 6.0 (Squeeze). So far I
> have only tried with one other client (also Squeeze) with similar
> results. Relevant software versions: kernel 2.6.32 (armel) and
> nfs-utils 1.2.2.
>
>
> The only suggestion that Google has been able to give me was to verify
> that the rpcsec_gss_krb5 was loaded, and it is:
> $ lsmod|grep gss
> rpcsec_gss_krb5 9026 5
> auth_rpcgss 33334 4 rpcsec_gss_krb5,nfsd,nfs
> sunrpc 171216 21 [..]
>
> Reproducible with only these exports:
> # exportfs -v
> /srv/nfs 172.22.21.8(ro,wdelay,root_squash,no_subtree_check,fsid=0)
> /srv/nfs gss/krb5(ro,wdelay,root_squash,no_subtree_check,fsid=0)
>
>
> I can provide a full rpc_debug/svc_debug log if required. I'm not
> attaching it now because it is somewhat large (well, 60k) and I'm not
> even sure that user issues are on-topic for this list. What looks
> suspicious to me is the following excerpt:
> [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
>
>
>
> I'd be grateful for any pointers,
> Arno
> (not subscribed, please keep me in CC)
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.)
K.C.
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: sec=krb5 mounts never return
2011-10-21 14:33 ` Kevin Coffman
@ 2011-10-21 20:10 ` Arno Schuring
2011-10-21 20:58 ` Kevin Coffman
0 siblings, 1 reply; 7+ messages in thread
From: Arno Schuring @ 2011-10-21 20:10 UTC (permalink / raw)
To: Kevin Coffman; +Cc: linux-nfs
[-- Attachment #1: Type: text/plain, Size: 2494 bytes --]
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@umich.edu on 2011-10-21 10:33 -0400):
> On Thu, Oct 20, 2011 at 7:23 PM, Arno Schuring
> <aelschuring@hotmail.com> 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@genie.loos.site
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@LOOS.SITE
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@genie.loos.site, uid: -1, gid:
-1, num aux grps: 0:
rpc.svcgssd[26188]: sending null reply
rpc.svcgssd[26188]: finished handling null request
Regards,
Arno
[-- Attachment #2: daemon.log --]
[-- Type: text/x-log, Size: 6770 bytes --]
Oct 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@LOOS.SITE for krbtgt/LOOS.SITE@LOOS.SITE, 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@LOOS.SITE for krbtgt/LOOS.SITE@LOOS.SITE
Oct 20 23:47:50 genie rpc.gssd[26133]: Successfully obtained machine credentials for principal 'nfs/genie.loos.site@LOOS.SITE' 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@genie.loos.site
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@LOOS.SITE for nfs/genie.loos.site@LOOS.SITE
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@LOOS.SITE
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@genie.loos.site, 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 \x6082023206092a864886f71201020201006e8202213082021da003020105a10302010ea20703050020000000a382014d6182014930820145a003020105a10b1b094c4f4f532e53495445a221301fa003020103a11830161b036e66731b0f67656e69652e6c6f6f732e73697465a382010c30820108a003020101a103020102a281fb0481f8ce3a7a6904c0e5231523f1df46aff97f72a916f2490880b147f12630ce6e88585dafe8af3796140b7f1a95b0373c41010174ad17cbefb97d6aa1b366fcd04a172ed3a92bebcccb36e19410fc47b44fe51f4e7c3e1991ccc00198565b748848daaa8106dc93d2b3323f2a3aeda70bdc4f89033f54c3ca9739c6c7804b6951b6623649bed18968708f8649782c212d8cbbd2761f9e199c4475a1e3183cb295db24c1c538684aa9631bc535639a3f016bda9799ba2b591e70103f105ec3061f9468dbafe09b1fa4705b7530253cd602e3122effb562bd2c1cd64eb0d548015e9ebf670aeb222ba60ab9dad0f51657e9981864031c2bb1a136d3a481b63081b3a003020101a281ab0481a8a2f5bf88f8f4f98407b7b43b495e9c2c689ebe95295868187ce071a96488bd917a45925869bee752d59eae4b50e39c9de669e5e7e7f2b05d560c751fcc5655e93!
5d8c31898b2321a692903e96d830148a3de0bd2f81f71701d1e6ff0df3e7de1f49ac3919aa392b897e07f98b41dc99cc919b504452f910a1be55180cca6a7c14f8af3def2ce12def8ca6d7bdb8b1447271d482fa6920fb02ab113c75821e54669c9ac5eb7bcf917 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
[-- Attachment #3: kern.log --]
[-- Type: text/x-log, Size: 53634 bytes --]
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: sec=krb5 mounts never return
2011-10-21 20:10 ` Arno Schuring
@ 2011-10-21 20:58 ` Kevin Coffman
2011-10-21 21:43 ` Douglas E. Engert
0 siblings, 1 reply; 7+ messages in thread
From: Kevin Coffman @ 2011-10-21 20:58 UTC (permalink / raw)
To: Arno Schuring; +Cc: linux-nfs
On Fri, Oct 21, 2011 at 4:10 PM, Arno Schuring <aelschuring@hotmail.com> wrote:
> 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@umich.edu on 2011-10-21 10:33 -0400):
>> On Thu, Oct 20, 2011 at 7:23 PM, Arno Schuring
>> <aelschuring@hotmail.com> 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@genie.loos.site
> 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@LOOS.SITE
> 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@genie.loos.site, uid: -1, gid:
> -1, num aux grps: 0:
> rpc.svcgssd[26188]: sending null reply
> rpc.svcgssd[26188]: finished handling null request
>
>
> Regards,
> Arno
The userland/daemon stuff all looks fine to me. I'm not as familiar
with the kernel logs. I believe the following kernel messages are
from the ^C:
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
I don't see anything obviously wrong.
K.C.
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: sec=krb5 mounts never return
2011-10-21 20:58 ` Kevin Coffman
@ 2011-10-21 21:43 ` Douglas E. Engert
2011-10-22 11:12 ` Arno Schuring
0 siblings, 1 reply; 7+ messages in thread
From: Douglas E. Engert @ 2011-10-21 21:43 UTC (permalink / raw)
To: Kevin Coffman; +Cc: Arno Schuring, linux-nfs
If the enctype=4 and length= 8 that sounds like DES.
You may need to add to the krb5.conf file,
allow_weak_crypto = yes
On 10/21/2011 3:58 PM, Kevin Coffman wrote:
> On Fri, Oct 21, 2011 at 4:10 PM, Arno Schuring<aelschuring@hotmail.com> wrote:
>> 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@umich.edu on 2011-10-21 10:33 -0400):
>>> On Thu, Oct 20, 2011 at 7:23 PM, Arno Schuring
>>> <aelschuring@hotmail.com> 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@genie.loos.site
>> 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@LOOS.SITE
>> 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@genie.loos.site, uid: -1, gid:
>> -1, num aux grps: 0:
>> rpc.svcgssd[26188]: sending null reply
>> rpc.svcgssd[26188]: finished handling null request
>>
>>
>> Regards,
>> Arno
>
> The userland/daemon stuff all looks fine to me. I'm not as familiar
> with the kernel logs. I believe the following kernel messages are
> from the ^C:
>
> 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
>
> I don't see anything obviously wrong.
>
> K.C.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
>
--
Douglas E. Engert <DEEngert@anl.gov>
Argonne National Laboratory
9700 South Cass Avenue
Argonne, Illinois 60439
(630) 252-5444
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: sec=krb5 mounts never return
2011-10-21 21:43 ` Douglas E. Engert
@ 2011-10-22 11:12 ` Arno Schuring
0 siblings, 0 replies; 7+ messages in thread
From: Arno Schuring @ 2011-10-22 11:12 UTC (permalink / raw)
To: linux-nfs
Douglas E. Engert (deengert@anl.gov on 2011-10-21 16:43 -0500):
> If the enctype=4 and length= 8 that sounds like DES.
> You may need to add to the krb5.conf file,
>
> allow_weak_crypto = yes
That's there. I'm not particularly happy about it, but it is my
understanding that 2.6.32 does not allow strong crypto for nfs4.
>
> On 10/21/2011 3:58 PM, Kevin Coffman wrote:
> >>
> >> 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@genie.loos.site
> >> 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@LOOS.SITE
> >> 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@genie.loos.site, uid: -1,
> >> gid: -1, num aux grps: 0:
> >> rpc.svcgssd[26188]: sending null reply
> >> rpc.svcgssd[26188]: finished handling null request
> >>
> > The userland/daemon stuff all looks fine to me. I'm not as familiar
> > with the kernel logs. I believe the following kernel messages are
> > from the ^C:
> >
Indeed. 23:47 is the mount command, 23:48 is the ^C. I see I did not
even allow 30s before killing, but I've had similar results even when
waiting minutes.
> >
> > I don't see anything obviously wrong.
Thanks. Any kernel wizards that want to take a stab at this? I can
provide more input if required, but kernel traces are hard to get
because this is a NAS without console.
Regards,
Arno
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: sec=krb5 mounts never return
2011-10-20 23:23 sec=krb5 mounts never return Arno Schuring
2011-10-21 14:33 ` Kevin Coffman
@ 2011-10-25 22:00 ` Arno Schuring
1 sibling, 0 replies; 7+ messages in thread
From: Arno Schuring @ 2011-10-25 22:00 UTC (permalink / raw)
To: linux-nfs
Arno Schuring (aelschuring@hotmail.com on 2011-10-21 01:23 +0200):
> Hello list,
>
> tl;dr: mount calls with sec=krb5 never return. They appear to get
> stalled in the kernel on "svc: transport is dead". I need to know
> if this is a configuration issue, a kernel problem or a userland
> problem, and how it can be resolved.
This appears to have been reported two months ago against Debian:
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=638157
And fixed over a year ago on this list:
http://www.spinics.net/lists/linux-nfs/msg14723.html
It's a wonderful world, isn't it?
Best wishes,
Arno
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2011-10-25 22:00 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2011-10-20 23:23 sec=krb5 mounts never return Arno Schuring
2011-10-21 14:33 ` Kevin Coffman
2011-10-21 20:10 ` Arno Schuring
2011-10-21 20:58 ` Kevin Coffman
2011-10-21 21:43 ` Douglas E. Engert
2011-10-22 11:12 ` Arno Schuring
2011-10-25 22:00 ` Arno Schuring
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).