Multi-homed NFS client does not select correct service principal

[gssapi]

Multi-homed NFS client does not select correct service principal

[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 [email protected] 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 [email protected]
Sep 20 10:19:16 manet.1015granger.net rpc.gssd[1004]: find_keytab_entry(0x7fdeb6ffd640): Success getting keytab entry for 'nfs/[email protected]'
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/[email protected]" [ { "nfs/[email protected]" { 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/[email protected]" [ { "nfs/[email protected]" { 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 [email protected]
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/[email protected]" [ { "nfs/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE 83137 0 [ { [ krb5.set.allowed... ] [ ................... ] } ] } ] [ ...........Q0...... ] 0 } target_name: "[email protected]" 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/[email protected]" [ { "nfs/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE 83137 0 [ { [ krb5.set.allowed... ] [ ................... ] } ] } ] [ ...........Q0...... ] 0 } target_name: "[email protected]" 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/[email protected]" "nfs/[email protected]" 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 [email protected]

[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/[email protected] (aes256-cts-hmac-sha1-96) 
   1 nfs/[email protected] (aes128-cts-hmac-sha1-96) 
   1 nfs/[email protected] (aes256-cts-hmac-sha1-96) 
   1 nfs/[email protected] (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/[email protected]' 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.