goa-identity-service confused by multiple TGTs for the same Kerberos principal, spams sssd_kcm with requests, pegging the CPU

I noticed sssd_kcm was pegging my CPU. A bit of debugging revealed that it was spending all its time responding to requests from goa-identity-service which appears to be polling it in a tight loop.

Running with G_MESSAGES_DEBUG=all, we see the following logged over and over:

(process:28716): libgoaidentity-DEBUG: 12:23:04.659: GoaKerberosIdentityManager: Refreshing identities
(process:28716): libgoaidentity-DEBUG: 12:23:04.664: GoaIdentityService: could not ensure credentials for account Sam.Morris@AD.DOMAIN.EXAMPLE: GDBus.Error:org.gnome.   
OnlineAccounts.Error.NotAuthorized: No credentials found in the keyring
(process:28716): libgoaidentity-DEBUG: 12:23:04.692: GoaKerberosIdentityManager: refreshing identity 'user1@UNIX.AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.692: GoaKerberosIdentity: expiration alarm fired for identity user1@UNIX.AD.DOMAIN.EXAMPLE
(process:28716): libgoaidentity-DEBUG: 12:23:04.720: GoaKerberosIdentityManager: refreshing identity 'user3@UNIX.AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.737: GoaKerberosIdentityManager: refreshing identity 'user2@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.750: GoaKerberosIdentityManager: refreshing identity 'Sam.Morris@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.752: GoaIdentityService: identity Sam.Morris@AD.DOMAIN.EXAMPLE expired
(process:28716): libgoaidentity-DEBUG: 12:23:04.755: GoaIdentityService: could not ensure credentials for account Sam.Morris@AD.DOMAIN.EXAMPLE: GDBus.Error:org.gnome.   
OnlineAccounts.Error.NotAuthorized: No credentials found in the keyring
(process:28716): libgoaidentity-DEBUG: 12:23:04.762: GoaKerberosIdentityManager: refreshing identity 'Sam.Morris@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.778: GoaKerberosIdentityManager: refreshing identity 'Sam.Morris@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.780: GoaKerberosIdentityManager: identity unexpired
(process:28716): libgoaidentity-DEBUG: 12:23:04.780: GoaKerberosIdentityManager: identity 'Sam.Morris@AD.DOMAIN.EXAMPLE' refreshed
(process:28716): libgoaidentity-DEBUG: 12:23:04.781: GoaKerberosIdentityManager: Waiting for next operation
(process:28716): libgoaidentity-DEBUG: 12:23:04.782: GoaIdentityService: could not ensure credentials for account Sam.Morris@AD.DOMAIN.EXAMPLE: GDBus.Error:org.gnome.   
OnlineAccounts.Error.NotAuthorized: No credentials found in the keyring
(process:28716): libgoaidentity-DEBUG: 12:23:04.782: GoaKerberosIdentityManager: Refreshing identities
(process:28716): libgoaidentity-DEBUG: 12:23:04.807: GoaKerberosIdentityManager: refreshing identity 'user1@UNIX.AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.835: GoaKerberosIdentityManager: refreshing identity 'user3@UNIX.AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.859: GoaKerberosIdentityManager: refreshing identity 'user2@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.876: GoaKerberosIdentityManager: refreshing identity 'Sam.Morris@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.879: GoaIdentityService: identity Sam.Morris@AD.DOMAIN.EXAMPLE expired
(process:28716): libgoaidentity-DEBUG: 12:23:04.882: GoaIdentityService: could not ensure credentials for account Sam.Morris@AD.DOMAIN.EXAMPLE: GDBus.Error:org.gnome.   
OnlineAccounts.Error.NotAuthorized: No credentials found in the keyring
(process:28716): libgoaidentity-DEBUG: 12:23:04.890: GoaKerberosIdentityManager: refreshing identity 'Sam.Morris@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.890: GoaKerberosIdentity: expiration alarm fired for identity Sam.Morris@AD.DOMAIN.EXAMPLE
(process:28716): libgoaidentity-DEBUG: 12:23:04.907: GoaKerberosIdentityManager: refreshing identity 'Sam.Morris@AD.DOMAIN.EXAMPLE'
(process:28716): libgoaidentity-DEBUG: 12:23:04.909: GoaKerberosIdentityManager: identity unexpired
(process:28716): libgoaidentity-DEBUG: 12:23:04.909: GoaKerberosIdentityManager: identity 'Sam.Morris@AD.DOMAIN.EXAMPLE' refreshed
(process:28716): libgoaidentity-DEBUG: 12:23:04.910: GoaKerberosIdentityManager: Waiting for next operation

It seems goa_kerberos_identity_manager_thread_pool_func is being called with operation->type == OPERATION_TYPE_REFRESH in a tight loop.

I think GoaKerberosIdentityManager is confused by the TGTs in the KCM. It uses the Kerberos principal as the key in its hash tables, which causes collisions when it iterates through a KCM that contains more than one TGT for the same Kerberos principal:

$ klist -l
Principal name                 Cache name
--------------                 ----------
user1@UNIX.AD.DOMAIN.EXAMPLE         KCM:876099160:39355 (Expired)
user2@UNIX.AD.DOMAIN.EXAMPLE         KCM:876099160:92394 (Expired)
user1@AD.DOMAIN.EXAMPLE              KCM:876099160:84256 (Expired)
Sam.Morris@AD.DOMAIN.EXAMPLE          KCM:876099160
Sam.Morris@AD.DOMAIN.EXAMPLE          KCM:876099160:72049 (Expired)
Sam.Morris@AD.DOMAIN.EXAMPLE          KCM:876099160:22104

$ klist -A
Ticket cache: KCM:876099160:39355
Default principal: user2@UNIX.AD.DOMAIN.EXAMPLE

Valid starting     Expires            Service principal
17/09/19 09:28:49  18/09/19 09:28:22  HTTP/...@UNIX.AD.DOMAIN.EXAMPLE
17/09/19 09:28:31  18/09/19 09:28:22  krbtgt/UNIX.AD.DOMAIN.EXAMPLE@UNIX.AD.DOMAIN.EXAMPLE
17/09/19 10:43:11  18/09/19 09:28:22  host/...@UNIX.AD.DOMAIN.EXAMPLE

Ticket cache: KCM:876099160:92394
Default principal: user3@UNIX.AD.DOMAIN.EXAMPLE

Valid starting     Expires            Service principal
18/09/19 10:01:19  19/09/19 09:56:28  host/...@UNIX.AD.DOMAIN.EXAMPLE
18/09/19 09:57:01  19/09/19 09:56:28  krbtgt/UNIX.AD.DOMAIN.EXAMPLE@UNIX.AD.DOMAIN.EXAMPLE
18/09/19 09:57:07  19/09/19 09:56:28  HTTP/...@UNIX.AD.DOMAIN.EXAMPLE
18/09/19 10:01:24  19/09/19 09:56:28  host/...@UNIX.AD.DOMAIN.EXAMPLE

Ticket cache: KCM:876099160:84256
Default principal: user2@AD.DOMAIN.EXAMPLE

Valid starting     Expires            Service principal
23/08/19 18:15:53  24/08/19 01:41:44  krbtgt/UNIX.AD.DOMAIN.EXAMPLE@AD.DOMAIN.EXAMPLE
        renew until 24/08/19 15:41:25
23/08/19 15:41:44  24/08/19 01:41:44  krbtgt/AD.DOMAIN.EXAMPLE@AD.DOMAIN.EXAMPLE
        renew until 24/08/19 15:41:25
23/08/19 18:15:53  24/08/19 01:41:44  HTTP/...@UNIX.AD.DOMAIN.EXAMPLE
        renew until 24/08/19 15:41:25

Ticket cache: KCM:876099160
Default principal: Sam.Morris@AD.DOMAIN.EXAMPLE

Valid starting     Expires            Service principal
23/09/19 12:42:53  23/09/19 22:42:53  krbtgt/AD.DOMAIN.EXAMPLE@AD.DOMAIN.EXAMPLE
        renew until 24/09/19 12:42:52

Ticket cache: KCM:876099160:72049
Default principal: Sam.Morris@AD.DOMAIN.EXAMPLE

Valid starting     Expires            Service principal
18/09/19 17:00:56  19/09/19 03:00:56  krbtgt/AD.DOMAIN.EXAMPLE@AD.DOMAIN.EXAMPLE
        renew until 19/09/19 17:00:56

Ticket cache: KCM:876099160:22104
Default principal: Sam.Morris@AD.DOMAIN.EXAMPLE

Valid starting     Expires            Service principal
23/09/19 11:41:26  23/09/19 21:41:26  krbtgt/AD.DOMAIN.EXAMPLE@AD.DOMAIN.EXAMPLE
        renew until 24/09/19 11:41:26

Edited Sep 23, 2019 by Sam Morris