[LONG] Kerberized NFSv4: rpc.idmapd only "sees" root principal
Kevin Coffman
kwc at citi.umich.edu
Fri Oct 30 14:21:23 EDT 2009
What options are being used for rpc.gssd? If you are using the
default options, when root tries to access a file via NFS, the machine
credentials will always be used. (It doesn't matter if you kinit as
some other principal in Kerberos. Those credentials will not be used
for UID 0.)
Can you give me the exact commands (and by whom) you are doing to
test? What command or action is happening to cause the second context
negotiation which uses the user's credentials, and the third context
negotiation which uses machine credentials?
I do not understand why that third negotiation is failing (or why it
is happening).
If the answers to those questions doesn't reveal the issue, a packet
trace might be helpful.
K.C.
On Fri, Oct 30, 2009 at 1:00 PM, Holger Rauch <holger.rauch at empic.de> wrote:
> Hi Kevin,
>
> thanks for clarifying this. Saves me quite a lot of work (hopefully) :-)
> Please see my statements and the new log output below.
>
> On Fri, 30 Oct 2009, Kevin Coffman wrote:
>
>> The "server" you are talking about is the KDC?
>
> Yes. I only called it "server" because I was referring to the machine
> hosting the KDC, the kadmin server, the NFSv4 server, and the OpenLDAP
> server. (I know that's not a really clean way of doing things; host on
> which KDC and kadmin server are running shouldn't be running any
> additional services, but in this particular case the machine is a
> central file server).
>
>> [...]
>> Commenting out default_tgs_enctypes and default_tkt_enctypes in all
>> your krb5.conf files, and re-creating the nfs principal keytabs should
>> be enough.
>
> I did that. Apart from that, the interesting thing I noticed was that
> when I logged in as user from a console (e.g. ttyS0) and then doing
> "sudo mount /mnt/user", rpc.svcgssd correctly determines the auxiliary
> groups. When I login as root and run "kinit -f user" and then do
> "mount /mnt/user", rpc.svcgssd doesn't. Furthermore, it seems to me
> like rpc.idmapd is simply mapping "too early", i.e. *before*
> rpc.svcgssd determined the auxiliary groups.
>
> The most obvious changes in /var/log/daemon.log were these
>
> ===
>
> Oct 30 17:33:01 server rpc.gssd[13231]: WARNING: Failed to create krb5
> context for user with uid 0 for server server.my.domain
> Oct 30 17:33:01 server rpc.gssd[13231]: WARNING: Failed to create krb5
> context for user with uid 0 with credentials cache
> FILE:/tmp/krb5cc_machine_MYREALM for server server.my.domain
> Oct 30 17:33:01 server rpc.gssd[13231]: WARNING: Failed to create krb5
> context for user with uid 0 with any credentials cache for server
> server.my.domain
> Oct 30 17:33:01 server rpc.gssd[13231]: doing error downcall
> Oct 30 17:33:01 server rpc.gssd[13231]: Failed to write error downcall!
>
> ===
>
> Here's some additional info. First, the output of "klist -5ef"
>
> ===
>
> Ticket cache: FILE:/tmp/krb5cc_10006_bvwZdB
> Default principal: user at MYREALM
>
> Valid starting Expires Service principal
> 10/30/09 17:32:22 10/31/09 09:32:22 krbtgt/MYREALM at MYREALM
> renew until 10/31/09 09:32:22, Flags: FRIA
> Etype (skey, tkt): AES-256 CTS mode with 96-bit SHA-1
> HMAC, AES-256 CTS mode with 96-bit SHA-1 HMAC
> 10/30/09 17:32:41 10/31/09 09:32:22
> nfs/server.my.domain at MYREALM
> renew until 10/31/09 09:32:22,
> Flags: FRAT
> Etype (skey, tkt): DES cbc mode with CRC-32, DES cbc mode with
> CRC-32
>
> ===
>
> And here's the complete output of /var/log/daemon.log
> (the upcalls in between refer to my try of performing "touch blah"
> right below /mnt/user)
>
> ===
>
> Oct 30 17:32:36 server rpc.idmapd[13227]: New client: a
> Oct 30 17:32:36 server rpc.idmapd[13227]: New client: b
> Oct 30 17:32:36 server rpc.idmapd[13227]: Opened /var/lib/nfs/rpc_pipefs/nfs/clnta/idmap
> Oct 30 17:32:36 server rpc.gssd[13231]: handling krb5 upcall
> Oct 30 17:32:36 server rpc.gssd[13231]: Full hostname for 'server.my.domain' is 'server.my.domain'
> Oct 30 17:32:36 server rpc.gssd[13231]: Full hostname for 'server.my.domain' is 'server.my.domain'
> Oct 30 17:32:36 server rpc.gssd[13231]: Success getting keytab entry for 'root/server.my.domain at MYREALM'
> Oct 30 17:32:36 server rpc.gssd[13231]: Successfully obtained machine credentials for principal 'root/server.my.domain at MYREALM' stored in ccache 'FILE:/tmp/krb5cc_machine_MYREALM'
> Oct 30 17:32:36 server rpc.gssd[13231]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_MYREALM' are good until 1256977956
> Oct 30 17:32:36 server rpc.gssd[13231]: using FILE:/tmp/krb5cc_machine_MYREALM as credentials cache for machine creds
> Oct 30 17:32:36 server rpc.gssd[13231]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_machine_MYREALM
> Oct 30 17:32:36 server rpc.gssd[13231]: creating context using fsuid 0 (save_uid 0)
> Oct 30 17:32:36 server rpc.gssd[13231]: creating tcp client for server server.my.domain
> Oct 30 17:32:36 server rpc.gssd[13231]: creating context with server nfs at server.my.domain
> Oct 30 17:32:36 server rpc.svcgssd[13263]: leaving poll
> Oct 30 17:32:36 server rpc.svcgssd[13263]: handling null request
> Oct 30 17:32:36 server rpc.svcgssd[13263]: sname = root/server.my.domain at MYREALM
> Oct 30 17:32:36 server rpc.svcgssd[13263]: DEBUG: serialize_krb5_ctx: lucid version!
> Oct 30 17:32:36 server rpc.svcgssd[13263]: prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
> Oct 30 17:32:36 server rpc.svcgssd[13263]: doing downcall
> Oct 30 17:32:36 server rpc.svcgssd[13263]: mech: krb5, hndl len: 4, ctx len 85, timeout: 2147483647, uid: -1, gid: -1, num aux grps: 0:
> Oct 30 17:32:36 server rpc.svcgssd[13263]: sending null reply
> Oct 30 17:32:36 server rpc.svcgssd[13263]: writing message: \x \x6082020b06092a864886f71201020201006e8201fa308201f6a003020105a10302010ea20703050020000000a3820116618201123082010ea003020105a10f1b0d45522e4845495445432e4e4554a2283026a003020103a11f301d1b036e66731b16707261672d6f6c642e65722e6865697465632e6e6574a381cb3081c8a003020101a103020103a281bb0481b86a7ed3531ca20087607f9d1e5def55226e43cc216047ba37e9ecdaf09a5b43e661c7ca7390a38435546789751843508036eb842d0fd86b93454c333c701286a6805ad2f8c2a94534533ba441436b1376bf85402ec862f0818d23ac1a5472e8b9b97d6d692aba0065c8b0553de2a48f805870d75a96c52f536a87daf0c80b04402a127f33c11e56f2e314c11d5596b1603839aac5fbbb7ea2c779f186a8f835ac2f26e5ea683f0a2ac54c61d6f622f54c202cc38b3d6ee533a481c63081c3a003020101a281bb0481b8e307db7a3ccd195732f84236132682569ddef519aaf55952802a3bb1b9b145d3e8e303778c2584349dc8616d1b5b59d49eea12497de8df74b85d538aac06d55f89f7f486e166b3f2eee1130016c49bc7e0a947d8d60b23ef31efdc781c3bdbda4b4def8c05e06e98d6cb2c9036faaa14667f2972e716f9253417aed5acd698e26a8acfe97d12ee77a24210561da712a91390c251c5c38aaee8bd0389e21b0b7c76baefdf947687d02f2bb6dac257e234f7e220db84a156fe 2147483647 0 0 \x01000000 \x607006092a864886f71201020202006f61305fa003020105a10302010fa2533051a003020101a24a04485ef5c136943a2b7ce45b9b2ac90623196f693442524fcabafcc3e509dbc182ded07866985f7aa4e27c32f92a968da76351136840d9ce2b86e07aa708ed9f8a4d5e3701df7d0797d3
> Oct 30 17:32:36 server rpc.svcgssd[13263]: finished handling null request
> Oct 30 17:32:36 server rpc.svcgssd[13263]: entering poll
> Oct 30 17:32:36 server rpc.gssd[13231]: DEBUG: serialize_krb5_ctx: lucid version!
> Oct 30 17:32:36 server rpc.gssd[13231]: prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
> Oct 30 17:32:36 server rpc.gssd[13231]: doing downcall
> Oct 30 17:32:36 server rpc.idmapd[13227]: nfsdcb: authbuf=gss/krb5i authtype=user
> Oct 30 17:32:36 server rpc.idmapd[13227]: Server: (user) id "0" -> name "root at my.domain"
> Oct 30 17:32:36 server rpc.idmapd[13227]: nfsdcb: authbuf=gss/krb5i authtype=group
> Oct 30 17:32:36 server rpc.idmapd[13227]: Server: (group) id "0" -> name "root at my.domain"
> Oct 30 17:32:36 server rpc.idmapd[13227]: Client a: (user) name "root at my.domain" -> id "0"
> Oct 30 17:32:36 server rpc.idmapd[13227]: Client a: (group) name "root at my.domain" -> id "0"
>
> Oct 30 17:32:41 server rpc.gssd[13231]: handling krb5 upcall
> Oct 30 17:32:41 server rpc.gssd[13231]: getting credentials for client with uid 10006 for server server.my.domain
> Oct 30 17:32:41 server rpc.gssd[13231]: CC file 'krb5cc_machine_MYREALM' being considered
> Oct 30 17:32:41 server rpc.gssd[13231]: '/tmp/krb5cc_machine_MYREALM' owned by 0, not 10006
> Oct 30 17:32:41 server rpc.gssd[13231]: CC file 'krb5cc_10006_bvwZdB' being considered
> Oct 30 17:32:41 server rpc.gssd[13231]: CC file 'krb5cc_10006_bvwZdB' matches owner check and has mtime of 1256920342
> Oct 30 17:32:41 server rpc.gssd[13231]: using FILE:/tmp/krb5cc_10006_bvwZdB as credentials cache for client with uid 10006 for server server.my.domain
> Oct 30 17:32:41 server rpc.gssd[13231]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_10006_bvwZdB
> Oct 30 17:32:41 server rpc.gssd[13231]: creating context using fsuid 10006 (save_uid 0)
> Oct 30 17:32:41 server rpc.gssd[13231]: creating tcp client for server server.my.domain
> Oct 30 17:32:41 server rpc.gssd[13231]: creating context with server nfs at server.my.domain
> Oct 30 17:32:41 server rpc.svcgssd[13263]: leaving poll
> Oct 30 17:32:41 server rpc.svcgssd[13263]: handling null request
> Oct 30 17:32:41 server rpc.svcgssd[13263]: sname = user at MYREALM
> Oct 30 17:32:41 server rpc.svcgssd[13263]: DEBUG: serialize_krb5_ctx: lucid version!
> Oct 30 17:32:41 server rpc.svcgssd[13263]: prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
> Oct 30 17:32:41 server rpc.svcgssd[13263]: doing downcall
> Oct 30 17:32:41 server rpc.svcgssd[13263]: mech: krb5, hndl len: 4, ctx len 85, timeout: 2147483647, uid: 10006, gid: 10006, num aux grps: 9:
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 1) 10006
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 2) 10100
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 3) 10101
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 4) 10102
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 5) 10103
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 6) 10104
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 7) 10105
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 8) 10106
> Oct 30 17:32:41 server rpc.svcgssd[13263]: ( 9) 10110
> Oct 30 17:32:41 server rpc.svcgssd[13263]: sending null reply
> Oct 30 17:32:41 server rpc.svcgssd[13263]: writing message: \x \x608201eb06092a864886f71201020201006e8201da308201d6a003020105a10302010ea20703050020000000a382010e6182010a30820106a003020105a10f1b0d45522e4845495445432e4e4554a2283026a003020103a11f301d1b036e66731b16707261672d6f6c642e65722e6865697465632e6e6574a381c33081c0a003020101a103020103a281b30481b016440a3f474cc241b010bdc2793f2b44de3a64981a209f2b73a18fbe8cc60df14a99d95e251ce53b39d108dc1db73b1004c8a8d812d038494b617112ef98322d802d32ff76d71248da1357a2d3c5326704d3233ce8ec8c23c4dedbb5517095453a14fe54c8bb62da976d0bf2c061ef4ae0a5693b78abfefec15a3e9eb67b8ed234d7cadb58142fb905b9bd58e043790ffb2bfc1347fae846a9144781effaf0ddfd277cb790ead93b420053afa0117dfda481ae3081aba003020101a281a30481a0888f2c085cd42e9245839aee236add091e5bdc71993a8e75192e65b4720efb2fc363c8403d0419543417a439755de485204b7481c511c256883ce8da6f81ef9116009d281d3392964eae3692fccd506a3a7e99d7eb0df0af77db649984336daed78e79b5f9d8b8d278c1e32a90e77c20e592d8415ba4f42be72e0712b64b72414522612aa0e0b538e472be8d72062de5b37a76ab76a810599cb449a7993bac89 2147483647 0 0 \x02000000 \x607006092a864886f71201020202006f61305fa003020105a10302010fa2533051a003020101a24a0448fb4769e46175787b6249189d7e82243d1a25f1bb54c7ea2eec645aa85fd35da6f47477ea041696aa3a09ae18d1089a07e1e0bd0b4c813f2e9bdf312d7b5ed4905368faf732edbe3f
> Oct 30 17:32:41 server rpc.svcgssd[13263]: finished handling null request
> Oct 30 17:32:41 server rpc.svcgssd[13263]: entering poll
> Oct 30 17:32:41 server rpc.gssd[13231]: DEBUG: serialize_krb5_ctx: lucid version!
> Oct 30 17:32:41 server rpc.gssd[13231]: prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
> Oct 30 17:32:41 server rpc.gssd[13231]: doing downcall
>
> Oct 30 17:33:01 server rpc.gssd[13231]: handling krb5 upcall
> Oct 30 17:33:01 server rpc.gssd[13231]: Full hostname for 'server.my.domain' is 'server.my.domain'
> Oct 30 17:33:01 server rpc.gssd[13231]: Full hostname for 'server.my.domain' is 'server.my.domain'
> Oct 30 17:33:01 server rpc.gssd[13231]: Success getting keytab entry for 'root/server.my.domain at MYREALM'
> Oct 30 17:33:01 server rpc.gssd[13231]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_MYREALM' are good until 1256977956
> Oct 30 17:33:01 server rpc.gssd[13231]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_MYREALM' are good until 1256977956
> Oct 30 17:33:01 server rpc.gssd[13231]: using FILE:/tmp/krb5cc_machine_MYREALM as credentials cache for machine creds
> Oct 30 17:33:01 server rpc.gssd[13231]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_machine_MYREALM
> Oct 30 17:33:01 server rpc.gssd[13231]: creating context using fsuid 0 (save_uid 0)
> Oct 30 17:33:01 server rpc.gssd[13231]: creating tcp client for server server.my.domain
> Oct 30 17:33:01 server rpc.gssd[13231]: creating context with server nfs at server.my.domain
> Oct 30 17:33:01 server rpc.svcgssd[13263]: leaving poll
> Oct 30 17:33:01 server rpc.svcgssd[13263]: handling null request
> Oct 30 17:33:01 server rpc.svcgssd[13263]: sname = root/server.my.domain at MYREALM
> Oct 30 17:33:01 server rpc.svcgssd[13263]: DEBUG: serialize_krb5_ctx: lucid version!
> Oct 30 17:33:01 server rpc.svcgssd[13263]: prepare_krb5_rfc1964_buffer: serializing keys with enctype 4 and length 8
> Oct 30 17:33:01 server rpc.svcgssd[13263]: doing downcall
> Oct 30 17:33:01 server rpc.svcgssd[13263]: mech: krb5, hndl len: 4, ctx len 85, timeout: 2147483647, uid: -1, gid: -1, num aux grps: 0:
> Oct 30 17:33:01 server rpc.svcgssd[13263]: sending null reply
> Oct 30 17:33:01 server rpc.svcgssd[13263]: writing message: \x \x6082020b06092a864886f71201020201006e8201fa308201f6a003020105a10302010ea20703050020000000a3820116618201123082010ea003020105a10f1b0d45522e4845495445432e4e4554a2283026a003020103a11f301d1b036e66731b16707261672d6f6c642e65722e6865697465632e6e6574a381cb3081c8a003020101a103020103a281bb0481b86a7ed3531ca20087607f9d1e5def55226e43cc216047ba37e9ecdaf09a5b43e661c7ca7390a38435546789751843508036eb842d0fd86b93454c333c701286a6805ad2f8c2a94534533ba441436b1376bf85402ec862f0818d23ac1a5472e8b9b97d6d692aba0065c8b0553de2a48f805870d75a96c52f536a87daf0c80b04402a127f33c11e56f2e314c11d5596b1603839aac5fbbb7ea2c779f186a8f835ac2f26e5ea683f0a2ac54c61d6f622f54c202cc38b3d6ee533a481c63081c3a003020101a281bb0481b809031547bcf4690f66fc4ac40dee15546ba82269cc8359503e739a61721f3e57516e9818557061cd851eb0856b661b233aa153d4af808a2b03f9fe089526dcc7c96f9694bf063d87fe589bde166879eda24a713091a2b4962e69c64fc8ede714fe875bc0f108c2892a59be2a40069739bd6787a5d92055fcf1541f43d0d1701df406d1f87b9bad84c7d6226ebb4191c655c6611062475a3a6a346fe44185fcb5fcdc9e173bb8831ae41f9fa326f78bcd335f8f619319a6ff 2147483647 0 0 \x03000000 \x607006092a864886f71201020202006f61305fa003020105a10302010fa2533051a003020101a24a0448dd94df39a8531fed5e2cd5827500091ca62c3f38a80c15838198b72c2ef16a935a5698416eec2a063ce4d7b4045e769708cdde8ad789ff064f0502856f40d185d1e6866874bb295d
> Oct 30 17:33:01 server rpc.svcgssd[13263]: finished handling null request
> Oct 30 17:33:01 server rpc.svcgssd[13263]: entering poll
> Oct 30 17:33:01 server rpc.gssd[13231]: WARNING: Failed to create krb5 context for user with uid 0 for server server.my.domain
> Oct 30 17:33:01 server rpc.gssd[13231]: WARNING: Failed to create krb5 context for user with uid 0 with credentials cache FILE:/tmp/krb5cc_machine_MYREALM for server server.my.domain
> Oct 30 17:33:01 server rpc.gssd[13231]: WARNING: Failed to create krb5 context for user with uid 0 with any credentials cache for server server.my.domain
> Oct 30 17:33:01 server rpc.gssd[13231]: doing error downcall
> Oct 30 17:33:01 server rpc.gssd[13231]: Failed to write error downcall!
>
> ===
>
> Thanks & kind regards,
>
> Holger
>
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.9 (GNU/Linux)
>
> iEYEARECAAYFAkrrG6kACgkQbiVtWpZdKQLaSACfZXpTHj4KcCtl20/kyLv9qXu6
> 0bAAn3dHdt9OTMggKY/WA9IwqTkSadAO
> =bL6l
> -----END PGP SIGNATURE-----
>
>
More information about the NFSv4
mailing list