Multi-homed NFS client does not select correct service principal

[chucklever]

The NFSv4.0 callback client in the Linux NFS server invokes gssproxy (somehow) to acquire the credential for its callback channel.

On multi-homed systems, GSSX_ARG_ACQUIRE_CRED always selects the principal associated with "uname -n". When creating an NFS client on alternate network interfaces, GSSX_ARG_ACQUIRE_CRED needs to select the principal associated with that interface, not the one associated with "uname -n".

[simo5]

The target is generally controlled by the calling code.

In this case I assume rpc.gssd is being invoked. Gss-proxy has no idea what interface is used because it is removed from direct knowledge of which interfaces its client is working with.

Can you identify exactly what path is being used?
setting debug log to level 3 and providing a trace of the failing callback would help determine if this is something that can be dealt with configuration or if it is the calling code that needs to be adjusted.

[simo5]

Just to be clear gssproxy does not use uname -a, either it gets a gss_name for the credential to acquire, or it will parse the keytab and select the first appropriate principal.
Unless the krb5_principal option is set, in which case it will try that if no gss_name is being passed in by the caller.

[chucklever]

I can't tell who is making the request to acquire the credential. gssd appears to have the correct principal name: "manet.ib.1015granger.net" but the argument for the ACQUIRE_CRED call is "manet.1015granger.net". I can't determine who is the caller. (This is from an earlier session; I can't recall if debug_level was set to 2 or 3 at this time).

Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: creating client nfsd4_cb/clnt28
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: scanning client nfsd4_cb/clnt28
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: destroying client nfsd4_cb/clnt27
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: freeing client nfsd4_cb/clnt27
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: 
                                                      handle_gssd_upcall(0x7fdebd2f5840): 'mech=krb5 uid=0 target=nfs@morisot.1015granger.net service=nfs srchost=manet.ib.1015granger.net enctypes=18,17,16,3,1,2' (nfsd4_cb/clnt28)
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: start_upcall_thread(0x7fdebd2f5840): created thread id 0x7fdeb6ffd640
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: krb5_use_machine_creds(0x7fdeb6ffd640): uid 0 tgtname nfs@morisot.1015granger.net
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: find_keytab_entry(0x7fdeb6ffd640): Success getting keytab entry for 'nfs/manet.ib.1015granger.net@1015GRANGER.NET'
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: gssd_get_single_krb5_cred(0x7fdeb6ffd640): Credentials in CC 'FILE:/tmp/krb5ccmachine_1015GRANGER.NET' are good until Tue Sep 20 16:35:20 2022
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: gssd_get_single_krb5_cred(0x7fdeb6ffd640): Credentials in CC 'FILE:/tmp/krb5ccmachine_1015GRANGER.NET' are good until Tue Sep 20 16:14:07 2022
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: gssd_get_single_krb5_cred(0x7fdeb6ffd640): Credentials in CC 'FILE:/tmp/krb5ccmachine_1015GRANGER.NET' are good until Tue Sep 20 16:35:20 2022
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: Connection matched service nfs-client
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0,socket: (null)
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]:     GSSX_ARG_ACQUIRE_CRED( call_ctx: { "" [  ] } input_cred_handle: { "nfs/manet.1015granger.net@1015GRANGER.NET" [ { "nfs/manet.1015granger.net@1015GRANGER.NET" { 1 2 840 113554 1 2 2 } INITIATE 83137 0 } ] [ ...........Q0...... ] 0 } add_cred: 0 desired_name: <Null> time_req: 4294967295 desired_mechs: { { 1 2 840 113554 1 2 2 } } cred_usage: INITIATE initiator_time_req: 0 acceptor_time_req: 0 )
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]:     GSSX_RES_ACQUIRE_CRED( status: { 0 { 1 2 840 113554 1 2 2 } 0 "" "" [  ] } output_cred_handle: { "nfs/manet.1015granger.net@1015GRANGER.NET" [ { "nfs/manet.1015granger.net@1015GRANGER.NET" { 1 2 840 113554 1 2 2 } INITIATE 83137 0 } ] [ ...........Q0...... ] 0 } )
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: create_auth_rpc_client(0x7fdeb6ffd640): creating tcp client for server morisot.ib.1015granger.net
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: DEBUG: port already set to 37259
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: create_auth_rpc_client(0x7fdeb6ffd640): creating context with server nfs@morisot.1015granger.net
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: Connection matched service nfs-client
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 0,socket: (null)
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]:     GSSX_ARG_INIT_SEC_CONTEXT( call_ctx: { "" [  ] } context_handle: <Null> cred_handle: { "nfs/manet.1015granger.net@1015GRANGER.NET" [ { "nfs/manet.1015granger.net@1015GRANGER.NET" { 1 2 840 113554 1 2 2 } INITIATE 83137 0 [ { [ krb5.set.allowed... ] [ ................... ] } ] } ] [ ...........Q0...... ] 0 } target_name: "nfs@morisot.1015granger.net" mech_type: { 1 2 840 113554 1 2 2 } req_flags: 2 time_req: 0 input_cb: <Null> input_token: <Null> [ { [ sync.modified.cr... ] [ 64656661756c740 ] } ] )
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: Credentials allowed by configuration
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]:     GSSX_RES_INIT_SEC_CONTEXT( status: { 1 { 1 2 840 113554 1 2 2 } 0 "The routine must be called again to complete its function" "" [  ] } context_handle: { [ ......H............ ] [  ] 0 { 1 2 840 113554 1 2 2 } "" "" 0 306 1 0 } output_token: [ ........H.......... ] )
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: Connection matched service nfs-client
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 0,socket: (null)
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]:     GSSX_ARG_INIT_SEC_CONTEXT( call_ctx: { "" [  ] } context_handle: { [ ......H............ ] [  ] 0 { 1 2 840 113554 1 2 2 } "" "" 0 306 1 0 } cred_handle: { "nfs/manet.1015granger.net@1015GRANGER.NET" [ { "nfs/manet.1015granger.net@1015GRANGER.NET" { 1 2 840 113554 1 2 2 } INITIATE 83137 0 [ { [ krb5.set.allowed... ] [ ................... ] } ] } ] [ ...........Q0...... ] 0 } target_name: "nfs@morisot.1015granger.net" mech_type: { 1 2 840 113554 1 2 2 } req_flags: 2 time_req: 0 input_cb: <Null> input_token: [ .......H........... ] [ { [ sync.modified.cr... ] [ 64656661756c740 ] } ] )
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]: [CID 11][2022/09/20 14:19:16]: Credentials allowed by configuration
Sep 20 10:19:16 manet.1015granger.net gssproxy[996]:     GSSX_RES_INIT_SEC_CONTEXT( status: { 0 { 1 2 840 113554 1 2 2 } 0 "" "" [  ] } context_handle: { [ ......H............ ] [  ] 0 { 1 2 840 113554 1 2 2 } "nfs/manet.1015granger.net@1015GRANGER.NET" "nfs/morisot.1015granger.net@1015GRANGER.NET" 15308 306 1 1 } output_token: <Null> )
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: DEBUG: serialize_krb5_ctx: lucid version!
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: prepare_krb5_rfc4121_buffer: protocol 1
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: do_downcall(0x7fdeb6ffd640): lifetime_rec=4h:15m:8s acceptor=nfs@morisot.1015granger.net

[simo5]

Ths is the caller:
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: gssd_get_single_krb5_cred(0x7fdeb6ffd640): Credentials in CC 'FILE:/tmp/krb5ccmachine_1015GRANGER.NET' are good until Tue Sep 20 16:35:20 2022

rpc.gssd process 1004

Do not know why rpc.gssd is crawling the keytab and then calling the wrong name.

can you: klist -kt /et/krb5.keytab ?
(or whatever file the keytab is in)

[chucklever]

It's a mystery. find_keytab_entry() claims to be picking up nfs/manet.ib.1015granger.net, which is the correct principal for this context.

[root@manet ~]# klist -ke
Keytab name: FILE:/etc/krb5.keytab
KVNO Principal
---- --------------------------------------------------------------------------
   1 nfs/manet.1015granger.net@1015GRANGER.NET (aes256-cts-hmac-sha1-96) 
   1 nfs/manet.1015granger.net@1015GRANGER.NET (aes128-cts-hmac-sha1-96) 
   1 nfs/manet.ib.1015granger.net@1015GRANGER.NET (aes256-cts-hmac-sha1-96) 
   1 nfs/manet.ib.1015granger.net@1015GRANGER.NET (aes128-cts-hmac-sha1-96) 
[root@manet ~]#

[chucklever]

I added a debugging printf just after the krb5_unparse_name() call site in gssd_get_single_krb5_cred(). Seems to confirm that gssd has the correct principal name.

Sep 20 14:36:06 manet.1015granger.net rpc.gssd[996]: cel: principal 'nfs/manet.ib.1015granger.net@1015GRANGER.NET' using keytab 'FILE:/etc/krb5.keytab'

[simo5]

Can you point me at the place you see this in the code?
a quick glance I do not see a place where gss_acquire_cred() is called from rpc.gssd with a target name.

[chucklever]

I've instrumented gssd. gssd_get_single_krb5_cred() invokes the library function krb5_get_init_creds_keytab() with the longer, correct principal as the third argument. Subsequently I see in the log the GSSX_ARG_ACQUIRE_CRED call with the shorter, incorrect principal.

So at this point I believe that gssd is not invoking gss_acquire_cred() directly for client side context establishment.

[simo5]

That's what I thought, this is a gssd bug.
gssproxy can try to paper over some things, but it can't divine which, of multiple principals, the application want's to use.

[chucklever]

Not a gssd bug, it’s a library bug. As I said, gssd provides the exact principal it wants to krb5_get_init_creds_keytab().

[simo5]

If you open a bug somwhere against it would be nice if you could link it here, so I can turn this issue into a discussion for other with the same issue to discover.

[chucklever]

Understood. I'm first looking for possible library configuration settings that might help.

[chucklever]

Fedora bugzilla 2128804 has been filed to seek assistance with debugging the mysterious API behavior.

[sesse]

We're seeing a very similar issue; if /etc/krb5.keytab has a bunch of SPNs (including e.g.
host/server.example.org@AD.EXAMPLE.ORG), gssproxy chooses to authenticate with the first one, which gives the dreaded “Client not found in Kerberos database” (since there's simply no such AD user; it's an SPN). We needed to remove every single one except SERVER$@AD.EXAMPLE.ORG before gssproxy would work, let alone impersonation. (Perhaps this works with Microsoft AD, I don't have a way to test—we're using Samba 4 as DC.)

This happens even if we set krb5_principal in gssproxy.conf.

[sesse]

The call chain here seems to be: gp_rpc_execute() → gp_acquire_cred() → gp_add_krb5_creds() → gss_acquire_cred_from() → gss_add_cred_from() → acquire_cred_from() → acquire_init_cred(), and acquire_init_cred() looks at whether cred->name is set or not, and it not calls get_name_from_client_keytab(), which calls k5_kt_get_principal(), which has this comment:

/*
 * In a couple of places we need to get a principal name from a keytab: when
 * verifying credentials against a keytab, and when querying the name of a
 * default GSS acceptor cred.  Keytabs do not have the concept of a default
 * principal like ccaches do, so for now we just return the first principal
 * listed in the keytab, or an error if it's not iterable.  In the future we
 * could consider elevating this to a public API and giving keytab types an
 * operation to return a default principal, and maybe extending the file format
 * and tools to support it.  Returns KRB5_KT_NOTFOUND if the keytab is empty
 * or non-iterable.
 */

So that explains why the first one is chosen (with really bad consequences if it's an SPN and not the actual computer principal!).

Now, why desired_name isn't set, I don't know. Even more so when I have set krb5_principal in the config file. That should happen in gp_add_krb5_creds() (via gp_get_cred_environment()). But I wonder if the logic in gp_get_cred_environment() specifies that we don't actually use svc->krb5.principal (the parsed value of krb5_principal) when impersonation is used. Someone who actually knows the code will have to understand that better…