RHEL8 sssd-kcm can't accept credentials forwarded from sshd?

[James Ralston]

Now that RHEL8 is out, our site is again looking at whether it would
be feasible to change our default Kerberos credentials storage from
the kernel persistent keyring to sssd-kcm.

Unfortunately, the answer still seems to be no, as we haven't been
able to find a way to get Kerberos ticket forwarding
(GSSAPIDelegateCredentials, in OpenSSH parlance) working when using
sssd-kcm as the credentials storage mechanism on the target host (the
one the credentials are being delegated to).

With the target host (the one the credentials are being delegated to)
using "default_ccache_name = KEYRING:persistent:%{uid}" in krb5.conf,
this is what sshd debugging shows:

debug1: temporarily_use_uid: 123456789/987654321 (e=0/0)
debug3: ssh_krb5_cc_new_unique: called
debug3: ssh_krb5_get_cctemplate: called
debug3: ssh_krb5_expand_template: called, template = KEYRING:persistent:%{uid}
debug3: ssh_krb5_get_cctemplate: returning with ccname =
KEYRING:persistent:123456789
debug3: ssh_krb5_cc_new_unique: setting default ccname to
KEYRING:persistent:123456789
debug3: ssh_krb5_cc_new_unique: calling
cc_new_unique(KEYRING:persistent:123456789)
debug3: ssh_krb5_cc_new_unique: calling cc_switch()
debug1: restore_uid: 0/0

In contrast, with "default_ccache_name = KCM:" in /etc/krb5.conf:

debug1: temporarily_use_uid: 123456789/987654321 (e=0/0)
debug3: ssh_krb5_cc_new_unique: called
debug3: ssh_krb5_get_cctemplate: called
debug3: ssh_krb5_expand_template: called, template = KCM:
debug3: ssh_krb5_get_cctemplate: returning with ccname = KCM:
debug3: ssh_krb5_cc_new_unique: setting default ccname to KCM:
debug3: ssh_krb5_cc_new_unique: calling cc_new_unique(KCM:)
debug3: ssh_krb5_cc_new_unique: calling cc_switch()
ssh_krb5_cc_new_unique(): Matching credential not found
debug1: restore_uid: 0/0

So, when sssd-kcm is in use, ssh_krb5_expand_template() fails, instead
of returning what would be expect in this case, which (based on the
kernel persistent keyring case) would be "KCM:123456789".

sssd_kcm.log contains:

(Fri May 10 12:33:34 2019) [sssd[kcm]] [get_client_cred] (0x4000):
Client creds: euid[123456789] egid[987654321] pid[8661].
(Fri May 10 12:33:34 2019) [sssd[kcm]] [setup_client_idle_timer]
(0x4000): Idle timer re-set for client [0x560fd598dc10][14]
(Fri May 10 12:33:34 2019) [sssd[kcm]] [accept_fd_handler] (0x0400):
Client connected!
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_input_parse] (0x1000):
Received message with length 4
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_get_opt] (0x2000): The
client requested operation 3
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_cmd_send] (0x0400): KCM
operation GEN_NEW
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_cmd_send] (0x1000): 0
bytes on KCM input
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_op_queue_send] (0x0200):
Adding request by 123456789 to the wait queue
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_op_queue_get] (0x1000): No
existing queue for this ID
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_op_queue_send] (0x1000):
Queue was empty, running the request immediately
(Fri May 10 12:33:34 2019) [sssd[kcm]] [ccdb_secdb_nextid_send]
(0x1000): Generating a new ID
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_map_path] (0x1000):
Mapping prefix /kcm/
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_map_url_to_path] (0x1000):
User-specific KCM path is [/kcm/persistent/123456789/ccache/]
(Fri May 10 12:33:34 2019) [sssd[kcm]] [local_db_dn] (0x2000): Local
path for [persistent/123456789/ccache/] is
[cn=ccache,cn=123456789,cn=persistent,cn=kcm]
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_new_req] (0x1000):
Local DB path is persistent/123456789/ccache/
(Fri May 10 12:33:34 2019) [sssd[kcm]] [secdb_container_url_req]
(0x2000): Created request for URL /kcm/persistent/123456789/ccache/
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_list] (0x0400):
Listing keys at [persistent/123456789/ccache/]
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_list] (0x2000):
Searching for [(type=simple)] at
[cn=ccache,cn=123456789,cn=persistent,cn=kcm] with scope=subtree
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_list] (0x1000): No secrets found
(Fri May 10 12:33:34 2019) [sssd[kcm]] [ccdb_secdb_nextid_send]
(0x1000): Generated next ID 39355
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_ccdb_nextid_done]
(0x1000): generated 123456789:39355
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_op_gen_new_done] (0x1000):
Generated a new ID 123456789:39355
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_cmd_done] (0x0400): KCM
operation GEN_NEW returned [0]: Success
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_send_reply] (0x2000):
Sending a reply
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_output_construct]
(0x1000): Sending a reply with 20 bytes of payload
(Fri May 10 12:33:34 2019) [sssd[kcm]] [queue_removal_cb] (0x0200):
Removed queue for 123456789
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_send] (0x2000): All data sent!
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_input_parse] (0x1000):
Received message with length 20
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_get_opt] (0x2000): The
client requested operation 21
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_cmd_send] (0x0400): KCM
operation SET_DEFAULT_CACHE
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_cmd_send] (0x1000): 16
bytes on KCM input
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_op_queue_send] (0x0200):
Adding request by 123456789 to the wait queue
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_op_queue_get] (0x1000): No
existing queue for this ID
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_op_queue_send] (0x1000):
Queue was empty, running the request immediately
(Fri May 10 12:33:34 2019) [sssd[kcm]]
[kcm_op_set_default_ccache_send] (0x1000): Setting default ccache
123456789:39355
(Fri May 10 12:33:34 2019) [sssd[kcm]] [ccdb_secdb_uuid_by_name_send]
(0x2000): Translating name to UUID
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_map_path] (0x1000):
Mapping prefix /kcm/
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_map_url_to_path] (0x1000):
User-specific KCM path is [/kcm/persistent/123456789/ccache/]
(Fri May 10 12:33:34 2019) [sssd[kcm]] [local_db_dn] (0x2000): Local
path for [persistent/123456789/ccache/] is
[cn=ccache,cn=123456789,cn=persistent,cn=kcm]
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_new_req] (0x1000):
Local DB path is persistent/123456789/ccache/
(Fri May 10 12:33:34 2019) [sssd[kcm]] [secdb_container_url_req]
(0x2000): Created request for URL /kcm/persistent/123456789/ccache/
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_list] (0x0400):
Listing keys at [persistent/123456789/ccache/]
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_list] (0x2000):
Searching for [(type=simple)] at
[cn=ccache,cn=123456789,cn=persistent,cn=kcm] with scope=subtree
(Fri May 10 12:33:34 2019) [sssd[kcm]] [sss_sec_list] (0x1000): No secrets found
(Fri May 10 12:33:34 2019) [sssd[kcm]] [key_by_name] (0x0080): The
container was not found
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_ccdb_uuid_by_name_done]
(0x0040): Failed to resolve cache by UUID [1432158218]: No credentials
available
(Fri May 10 12:33:34 2019) [sssd[kcm]]
[kcm_op_set_default_ccache_getbyname_done] (0x0040): Cannot get ccache
by name [1432158218]: No credentials available
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_cmd_done] (0x0040): op
receive function failed [1432158218]: No credentials available
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_cmd_request_done]
(0x0040): KCM operation failed [1432158218]: No credentials available
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_reply_error] (0x0040): KCM
operation returs failure [1432158218]: No credentials available
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_failbuf_construct]
(0x1000): Sent reply with error -1765328243
(Fri May 10 12:33:34 2019) [sssd[kcm]] [queue_removal_cb] (0x0200):
Removed queue for 123456789
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_send] (0x2000): All data sent!
(Fri May 10 12:33:34 2019) [sssd[kcm]] [kcm_recv] (0x4000): Client
closed connection.
(Fri May 10 12:33:34 2019) [sssd[kcm]] [client_close_fn] (0x2000):
Terminated client [0x560fd598dc10][14]

So, sssd-kcm definitely failed.  This aligns with what sshd saw.

If I pre-create the cache on the target server (e.g., by running kinit
against a different principal) and repeat the experiment, sssd-kcm
still fails, but the debug output is slightly different:

(Fri May 10 12:56:27 2019) [sssd[kcm]] [get_client_cred] (0x4000):
Client creds: euid[123456789] egid[987654321] pid[8844].
(Fri May 10 12:56:27 2019) [sssd[kcm]] [setup_client_idle_timer]
(0x4000): Idle timer re-set for client [0x5589715428e0][14]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [accept_fd_handler] (0x0400):
Client connected!
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_input_parse] (0x1000):
Received message with length 4
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_get_opt] (0x2000): The
client requested operation 3
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_cmd_send] (0x0400): KCM
operation GEN_NEW
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_cmd_send] (0x1000): 0
bytes on KCM input
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_op_queue_send] (0x0200):
Adding request by 123456789 to the wait queue
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_op_queue_get] (0x1000): No
existing queue for this ID
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_op_queue_send] (0x1000):
Queue was empty, running the request immediately
(Fri May 10 12:56:27 2019) [sssd[kcm]] [ccdb_secdb_nextid_send]
(0x1000): Generating a new ID
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_map_path] (0x1000):
Mapping prefix /kcm/
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_map_url_to_path] (0x1000):
User-specific KCM path is [/kcm/persistent/123456789/ccache/]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [local_db_dn] (0x2000): Local
path for [persistent/123456789/ccache/] is
[cn=ccache,cn=123456789,cn=persistent,cn=kcm]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_new_req] (0x1000):
Local DB path is persistent/123456789/ccache/
(Fri May 10 12:56:27 2019) [sssd[kcm]] [secdb_container_url_req]
(0x2000): Created request for URL /kcm/persistent/123456789/ccache/
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_list] (0x0400):
Listing keys at [persistent/123456789/ccache/]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_list] (0x2000):
Searching for [(type=simple)] at
[cn=ccache,cn=123456789,cn=persistent,cn=kcm] with scope=subtree
(Fri May 10 12:56:27 2019) [sssd[kcm]] [local_dn_to_path] (0x2000):
Secrets path for
[cn=2c095c7e-978f-498c-aa46-f1641ac45545-123456789,cn=ccache,cn=123456789,cn=persistent,cn=kcm]
is [2c095c7e-978f-498c-aa46-f1641ac45545-123456789]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_list] (0x1000):
Returning 1 secrets
(Fri May 10 12:56:27 2019) [sssd[kcm]] [ccdb_secdb_nextid_send]
(0x1000): Generated next ID 39355
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_ccdb_nextid_done]
(0x1000): generated 123456789:39355
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_op_gen_new_done] (0x1000):
Generated a new ID 123456789:39355
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_cmd_done] (0x0400): KCM
operation GEN_NEW returned [0]: Success
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_send_reply] (0x2000):
Sending a reply
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_output_construct]
(0x1000): Sending a reply with 20 bytes of payload
(Fri May 10 12:56:27 2019) [sssd[kcm]] [queue_removal_cb] (0x0200):
Removed queue for 123456789
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_send] (0x2000): All data sent!
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_input_parse] (0x1000):
Received message with length 20
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_get_opt] (0x2000): The
client requested operation 21
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_cmd_send] (0x0400): KCM
operation SET_DEFAULT_CACHE
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_cmd_send] (0x1000): 16
bytes on KCM input
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_op_queue_send] (0x0200):
Adding request by 123456789 to the wait queue
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_op_queue_get] (0x1000): No
existing queue for this ID
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_op_queue_send] (0x1000):
Queue was empty, running the request immediately
(Fri May 10 12:56:27 2019) [sssd[kcm]]
[kcm_op_set_default_ccache_send] (0x1000): Setting default ccache
123456789:39355
(Fri May 10 12:56:27 2019) [sssd[kcm]] [ccdb_secdb_uuid_by_name_send]
(0x2000): Translating name to UUID
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_map_path] (0x1000):
Mapping prefix /kcm/
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_map_url_to_path] (0x1000):
User-specific KCM path is [/kcm/persistent/123456789/ccache/]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [local_db_dn] (0x2000): Local
path for [persistent/123456789/ccache/] is
[cn=ccache,cn=123456789,cn=persistent,cn=kcm]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_new_req] (0x1000):
Local DB path is persistent/123456789/ccache/
(Fri May 10 12:56:27 2019) [sssd[kcm]] [secdb_container_url_req]
(0x2000): Created request for URL /kcm/persistent/123456789/ccache/
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_list] (0x0400):
Listing keys at [persistent/123456789/ccache/]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_list] (0x2000):
Searching for [(type=simple)] at
[cn=ccache,cn=123456789,cn=persistent,cn=kcm] with scope=subtree
(Fri May 10 12:56:27 2019) [sssd[kcm]] [local_dn_to_path] (0x2000):
Secrets path for
[cn=2c095c7e-978f-498c-aa46-f1641ac45545-123456789,cn=ccache,cn=123456789,cn=persistent,cn=kcm]
is [2c095c7e-978f-498c-aa46-f1641ac45545-123456789]
(Fri May 10 12:56:27 2019) [sssd[kcm]] [sss_sec_list] (0x1000):
Returning 1 secrets
(Fri May 10 12:56:27 2019) [sssd[kcm]] [key_by_name] (0x2000): No key matched
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_ccdb_uuid_by_name_done]
(0x0040): Failed to resolve cache by UUID [1432158218]: No credentials
available
(Fri May 10 12:56:27 2019) [sssd[kcm]]
[kcm_op_set_default_ccache_getbyname_done] (0x0040): Cannot get ccache
by name [1432158218]: No credentials available
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_cmd_done] (0x0040): op
receive function failed [1432158218]: No credentials available
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_cmd_request_done]
(0x0040): KCM operation failed [1432158218]: No credentials available
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_reply_error] (0x0040): KCM
operation returs failure [1432158218]: No credentials available
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_failbuf_construct]
(0x1000): Sent reply with error -1765328243
(Fri May 10 12:56:27 2019) [sssd[kcm]] [queue_removal_cb] (0x0200):
Removed queue for 123456789
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_send] (0x2000): All data sent!
(Fri May 10 12:56:27 2019) [sssd[kcm]] [kcm_recv] (0x4000): Client
closed connection.
(Fri May 10 12:56:27 2019) [sssd[kcm]] [client_close_fn] (0x2000):
Terminated client [0x5589715428e0][14]

Before I dig into this further, or go file a support request with Red
Hat, has anyone been able to get sssd-kcm to successfully accept
forwarded credentials from sshd on RHEL8?  If so, what did you have to
set or tweak to get it to work?

[Jakub Hrozek]

On Fri, May 10, 2019 at 01:20:51PM -0400, James Ralston wrote:
>  Now that RHEL8 is out, our site is again looking at whether it would
>  be feasible to change our default Kerberos credentials storage from
>  the kernel persistent keyring to sssd-kcm. 
Which version is this? Is this RHEL-8 GA or one of the earlier
pre-release versions? Because the logs make it sound like
https://pagure.io/SSSD/sssd/issue/3873 which was fixed in time for
RHEL-8 GA.