Re: trouble using kerberos between linux client and server

[Guillaume Rousse <Guillaume.Rousse@inria.fr>]

[-- Attachment #1: Type: text/plain, Size: 8089 bytes --]

Le 22/04/2010 08:15, Guillaume Rousse a écrit :
> Hello list.
> 
> I've been using kerberized NFS with NetApp filer without
> kerberos-specific troubles so far. However, I'm currently trying to
> setup a Linux kerberized server for the first time, and I'm facing
> Kerberos issues.
I managed to get rid of the two initial errors (failure to select the
correct key if more than one key was present in the keytab, and failure
to reply to pre-authentication request) by generating principals with
DES keys right from the start, instead of adding a DES key to an
already-existing principal later. There isn't any error in kerberos logs
anymore. However, mount still doesn't succeed, for unknown failure in
rpc.svcgssd (apparently):

May  3 22:07:07 loubianka rpc.svcgssd[5729]: leaving poll
May  3 22:07:07 loubianka rpc.svcgssd[5729]: handling null request
May  3 22:07:07 loubianka rpc.svcgssd[5729]: sname =
nfs/beria.zarb.home@ZARB.HOME
May  3 22:07:07 loubianka rpc.svcgssd[5729]: nfs4_gss_princ_to_ids:
calling nsswitch->princ_to_ids
May  3 22:07:07 loubianka rpc.svcgssd[5729]: nss_getpwnam: name
'nfs/beria.zarb.home@ZARB.HOME' domain '(null)': resulting localname
'nfs/beria.zarb.home'
May  3 22:07:07 loubianka rpc.svcgssd[5729]: nfs4_gss_princ_to_ids:
nsswitch->princ_to_ids returned -2
May  3 22:07:07 loubianka rpc.svcgssd[5729]: nfs4_gss_princ_to_ids:
final return value is -2
May  3 22:07:07 loubianka rpc.svcgssd[5729]: DEBUG: serialize_krb5_ctx:
lucid version!
May  3 22:07:07 loubianka rpc.svcgssd[5729]:
prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
May  3 22:07:07 loubianka rpc.svcgssd[5729]: doing downcall
May  3 22:07:07 loubianka rpc.svcgssd[5729]: mech: krb5, hndl len: 4,
ctx len 85, timeout: 1273002810 (85583 from now), clnt:
nfs@beria.zarb.home, uid: -1, gid: -1, num aux grps: 0:
May  3 22:07:07 loubianka rpc.svcgssd[5729]: qword_eol: fflush failed:
errno 95 (Operation not supported)
May  3 22:07:07 loubianka rpc.svcgssd[5729]: WARNING: error writing to
downcall channel /proc/net/rpc/auth.rpcsec.context/channel: Operation
not supported
May  3 22:07:07 loubianka rpc.svcgssd[5729]: sending null reply
May  3 22:07:07 loubianka rpc.svcgssd[5729]: writing message: \x
\x6082023606092a864886f71201020201006e82022530820221a003020105a10302010ea20703050020000000a38201516182014d30820149a003020105a10b1b095a4152422e484f4d45a2253023a003020103a11c301a1b036e66731b136c6f756269616e6b612e7a6172622e686f6d65a382010c30820108a003020101a103020102a281fb0481f87e4272c666342bb6b0b15e9cd002e38a80a61c6ff22f4c36906f55ed954826c7f5cf47f014d6994a4bbbb26c94b235bd2652e6887ee77b4efc90d1ff704e905ac0b25fc411f0f86208c533ed2c8d8c080dc04cd6498a50a23e15ba5035135cdb7517e89abda282bb258987aeb62c9555e406cf8c0461faf3eaf1d4b2cb9f62c9ea3bd67522294ecfc204247b46b96aa744dbc374bc5e371589a89bdfaee12a7865f97c1693cd42e581ce457df7400412580d2d3418e7c67f193adf19d8f9a2ee4101743ad50760d8cc36e778b936a7e2c11b11320a06b6399c8ab358853a4ad6e35ecca2f5974b224ec1c9c97262312043cdc8f938125492a481b63081b3a003020101a281ab0481a83ed20fcc8c164138b903cd084a73d8cb5443b925bb1574a976ea02cb5cc428b4045e246f9d4127c3bd85e23e319b9b538ae428951b05f02fd2fc550cb4189e8aeb6b9b8565393a6553f5d54b6ca2dbe6c1b8167e84d3612334969c9e

7adda30b4b9b0b516dfb95cc681c336ed961c67eb9ff5979d1cbe8b25346ee3b9b831e4dfb2886c3532cf265d38d5f0f425b1de71e715cb5577496e2fa57347ba24e8328fe60181cede1a8db
1272917287 0 0 \x08000000
\x607006092a864886f71201020202006f61305fa003020105a10302010fa2533051a003020101a24a0448dbfcd096f64638016b06d173c349533a18516fae606f6e49952bb4bcb47d4b90cdf2fe787d2522e3c52271f249e9c29a2566ddfffa27d562ba3e98c10f9ac30ca79127a244810e91
May  3 22:07:07 loubianka rpc.svcgssd[5729]: finished handling null request
May  3 22:07:07 loubianka rpc.svcgssd[5729]: entering poll

The same output appears twice for each attempt. Googling for 'qword_eol'
refers to changes in nfs-utils last year adding more logs message in
case of failure, and a strong feeling the issue occurs in server kernel
(2.6.33.2).

Here are clients logs:
May  3 22:07:14 beria rpc.gssd[17990]: handle_gssd_upcall: 'mech=krb5
uid=0 '
May  3 22:07:14 beria rpc.gssd[17990]: handling krb5 upcall
(/var/lib/nfs/rpc_pipefs/nfs/clnt6)
May  3 22:07:14 beria rpc.gssd[17990]: process_krb5_upcall: service is
'<null>'
May  3 22:07:14 beria rpc.gssd[17990]: Full hostname for
'loubianka.zarb.home' is 'loubianka.zarb.home'
May  3 22:07:14 beria rpc.gssd[17990]: Full hostname for
'beria.zarb.home' is 'beria.zarb.home'
May  3 22:07:14 beria rpc.gssd[17990]: Key table entry not found while
getting keytab entry for 'root/beria.zarb.home@ZARB.HOME'
May  3 22:07:14 beria rpc.gssd[17990]: Success getting keytab entry for
'nfs/beria.zarb.home@ZARB.HOME'
May  3 22:07:14 beria rpc.gssd[17990]: INFO: Credentials in CC
'FILE:/tmp/krb5cc_machine_ZARB.HOME' are good until 1273002810
May  3 22:07:14 beria rpc.gssd[17990]: INFO: Credentials in CC
'FILE:/tmp/krb5cc_machine_ZARB.HOME' are good until 1273002810
May  3 22:07:14 beria rpc.gssd[17990]: using
FILE:/tmp/krb5cc_machine_ZARB.HOME as credentials cache for machine creds
May  3 22:07:14 beria rpc.gssd[17990]: using environment variable to
select krb5 ccache FILE:/tmp/krb5cc_machine_ZARB.HOME
May  3 22:07:14 beria rpc.gssd[17990]: creating context using fsuid 0
(save_uid 0)
May  3 22:07:14 beria rpc.gssd[17990]: creating tcp client for server
loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: DEBUG: port already set to 2049
May  3 22:07:14 beria rpc.gssd[17990]: creating context with server
nfs@loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: WARNING: Failed to create krb5
context for user with uid 0 for server loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: WARNING: Failed to create machine
krb5 context with credentials cache FILE:/tmp/krb5cc_machine_ZARB.HOME
for server loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: WARNING: Machine cache is
prematurely expired or corrupted trying to recreate cache for server
loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: Full hostname for
'loubianka.zarb.home' is 'loubianka.zarb.home'
May  3 22:07:14 beria rpc.gssd[17990]: Full hostname for
'beria.zarb.home' is 'beria.zarb.home'
May  3 22:07:14 beria rpc.gssd[17990]: Key table entry not found while
getting keytab entry for 'root/beria.zarb.home@ZARB.HOME'
May  3 22:07:14 beria rpc.gssd[17990]: Success getting keytab entry for
'nfs/beria.zarb.home@ZARB.HOME'
May  3 22:07:14 beria rpc.gssd[17990]: INFO: Credentials in CC
'FILE:/tmp/krb5cc_machine_ZARB.HOME' are good until 1273002810
May  3 22:07:14 beria rpc.gssd[17990]: INFO: Credentials in CC
'FILE:/tmp/krb5cc_machine_ZARB.HOME' are good until 1273002810
May  3 22:07:14 beria rpc.gssd[17990]: using
FILE:/tmp/krb5cc_machine_ZARB.HOME as credentials cache for machine creds
May  3 22:07:14 beria rpc.gssd[17990]: using environment variable to
select krb5 ccache FILE:/tmp/krb5cc_machine_ZARB.HOME
May  3 22:07:14 beria rpc.gssd[17990]: creating context using fsuid 0
(save_uid 0)
May  3 22:07:14 beria rpc.gssd[17990]: creating tcp client for server
loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: DEBUG: port already set to 2049
May  3 22:07:14 beria rpc.gssd[17990]: creating context with server
nfs@loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: WARNING: Failed to create krb5
context for user with uid 0 for server loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: WARNING: Failed to create machine
krb5 context with credentials cache FILE:/tmp/krb5cc_machine_ZARB.HOME
for server loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: WARNING: Failed to create machine
krb5 context with any credentials cache for server loubianka.zarb.home
May  3 22:07:14 beria rpc.gssd[17990]: doing error downcall
May  3 22:07:14 beria rpc.gssd[17990]: destroying client
/var/lib/nfs/rpc_pipefs/nfs/clnt7
May  3 22:07:14 beria rpc.gssd[17990]: destroying client
/var/lib/nfs/rpc_pipefs/nfs/clnt6

I'm attaching network capture, even I can't figure additional
information from it by myself.
-- 
BOFH excuse #412:

Radial Telemetry Infiltration


[-- Attachment #2: out --]
[-- Type: application/octet-stream, Size: 4220 bytes --]