keycloak spnego authentication fails with "The underlying mechanism context has not been initialized", "result = ACCEPT_INCOMPLETE"

Question

I am struggling to setup keycloak with ldap adapter for active directory, and spnego support. It is a test setup, everything is running on the same VM with Windows Server 2016 as operating system. The ldap adapter with kerberos integration seems to be correctly configured - user synchronization and kerberos authentication are working.

However, when trying to use Windows integrated authentication (spnego) with Chrome, the browser shows the login page.

In order to get the thing working, I would like to better understand the following log messages I get in keycloak. Of course, any other suggestions about what might be the core problem are also very much appreciated!

16:50:06,194 INFO  [stdout] (default task-5) Debug is  true storeKey true useTicketCache false useKeyTab true doNotPrompt true ticketCache is null isInitiator false KeyTab is C:\keycloak\standalone\configuration\keycloak.keytab refreshKrb5Config is false principal is HTTP/keycloak.local@KEYCLOAK.LOCAL tryFirstPass is false useFirstPass is false storePass is false clearPass is false
16:50:06,210 INFO  [stdout] (default task-5) principal is HTTP/keycloak.local@KEYCLOAK.LOCAL
16:50:06,210 INFO  [stdout] (default task-5) Will use keytab
16:50:06,210 INFO  [stdout] (default task-5) Commit Succeeded
16:50:06,210 INFO  [stdout] (default task-5)
16:50:06,225 INFO  [stdout] (default task-5) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:50:06,225 INFO  [stdout] (default task-5) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:50:06,225 INFO  [stdout] (default task-5) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:50:06,225 INFO  [stdout] (default task-5) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:50:06,225 INFO  [stdout] (default task-5) Entered SpNegoContext.acceptSecContext with state=STATE_NEW
16:50:06,225 INFO  [stdout] (default task-5) SpNegoContext.acceptSecContext: receiving token = a0 75 30 73 a0 30 30 2e 06 0a 2b 06 01 04 01 82 37 02 02 0a 06 09 2a 86 48 82 f7 12 01 02 02 06 09 2a 86 48 86 f7 12 01 02 02 06 0a 2b 06 01 04 01 82 37 02 02 1e a2 3f 04 3d 4e 54 4c 4d 53 53 50 00 01 00 00 00 97 b2 08 e2 08 00 08 00 35 00 00 00 0d 00 0d 00 28 00 00 00 0a 00 39 38 00 00 00 0f 50 50 4b 45 59 43 4c 4f 41 4b 32 32 30 4b 45 59 43 4c 4f 41 4b
16:50:06,225 INFO  [stdout] (default task-5) SpNegoToken NegTokenInit: reading Mechanism Oid = 1.3.6.1.4.1.311.2.2.10
16:50:06,225 INFO  [stdout] (default task-5) SpNegoToken NegTokenInit: reading Mechanism Oid = 1.2.840.48018.1.2.2
16:50:06,225 INFO  [stdout] (default task-5) SpNegoToken NegTokenInit: reading Mechanism Oid = 1.2.840.113554.1.2.2
16:50:06,225 INFO  [stdout] (default task-5) SpNegoToken NegTokenInit: reading Mechanism Oid = 1.3.6.1.4.1.311.2.2.30
16:50:06,225 INFO  [stdout] (default task-5) SpNegoToken NegTokenInit: reading Mech Token
16:50:06,225 INFO  [stdout] (default task-5) SpNegoContext.acceptSecContext: received token of type = SPNEGO NegTokenInit
16:50:06,225 INFO  [stdout] (default task-5) SpNegoContext: negotiated mechanism = 1.2.840.113554.1.2.2
16:50:06,225 INFO  [stdout] (default task-5) The underlying mechanism context has not been initialized
16:50:06,225 INFO  [stdout] (default task-5) SpNegoContext.acceptSecContext: mechanism wanted = 1.2.840.113554.1.2.2
16:50:06,225 INFO  [stdout] (default task-5) SpNegoContext.acceptSecContext: negotiated result = ACCEPT_INCOMPLETE
16:50:06,225 INFO  [stdout] (default task-5) SpNegoContext.acceptSecContext: sending token of type = SPNEGO NegTokenTarg
16:50:06,225 INFO  [stdout] (default task-5) SpNegoContext.acceptSecContext: sending token = a1 14 30 12 a0 03 0a 01 01 a1 0b 06 09 2a 86 48 86 f7 12 01 02 02
16:50:06,225 INFO  [stdout] (default task-5) The underlying mechanism context has not been initialized
16:50:06,225 INFO  [stdout] (default task-5) The underlying mechanism context has not been initialized
16:50:06,225 INFO  [stdout] (default task-5)            [Krb5LoginModule]: Entering logout
16:50:06,225 INFO  [stdout] (default task-5)            [Krb5LoginModule]: logged out Subject

My interpretation so far:

From this post I concluded that the "receiving token" is a NTLM token. keycloak does not support NTLM, so it requests a token according to "Mechanism Oid = 1.2.840.48018.1.2.2" from the browser. But then the negotiation somehow stalls.

Questions:

• What is the meaning of "The underlying mechanism context has not been initialized"? Is this an indication that some configuration is missing?

• What is the meaning of "SpNegoContext.acceptSecContext: negotiated result = ACCEPT_INCOMPLETE"? Does it mean that the negotiation has failed, or that more information is required?

Additional information:

• Keycloak version is 7.0.0

• Chrome, Firefox and IE behave the same, so I think they delegate the spnego negotiation to the OS.

• I start the browsers on the host where keycloak is running. There are posts 1, 2 that suggest that having client and server on the same machine can lead to a NTLM token.

• The logs above are the ones I get when accessing keycloak by localhost. When I'm using the IP address or the fully qualified host name, I get an exception instead:

16:44:08,698 INFO  [stdout] (default task-2) Debug is  true storeKey true useTicketCache false useKeyTab true doNotPrompt true ticketCache is null isInitiator false KeyTab is C:\keycloak\standalone\configuration\keycloak.keytab refreshKrb5Config is false principal is HTTP/keycloak.local@KEYCLOAK.LOCAL tryFirstPass is false useFirstPass is false storePass is false clearPass is false
16:44:08,704 INFO  [stdout] (default task-2) principal is HTTP/keycloak.local@KEYCLOAK.LOCAL
16:44:08,705 INFO  [stdout] (default task-2) Will use keytab
16:44:08,705 INFO  [stdout] (default task-2) Commit Succeeded
16:44:08,705 INFO  [stdout] (default task-2)
16:44:08,706 INFO  [stdout] (default task-2) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:44:08,707 INFO  [stdout] (default task-2) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:44:08,709 INFO  [stdout] (default task-2) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:44:08,711 INFO  [stdout] (default task-2) Found KeyTab C:\keycloak\standalone\configuration\keycloak.keytab for HTTP/keycloak.local@KEYCLOAK.LOCAL
16:44:08,712 WARN  [org.keycloak.federation.kerberos.impl.SPNEGOAuthenticator] (default task-2) SPNEGO login failed: java.security.PrivilegedActionException: GSSException: Defective token detected (Mechanism level: GSSHeader did not find the right tag)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Unknown Source)
        at org.keycloak.federation.kerberos.impl.SPNEGOAuthenticator.authenticate(SPNEGOAuthenticator.java:68)
        at org.keycloak.storage.ldap.LDAPStorageProvider.authenticate(LDAPStorageProvider.java:692)
[...]

Answer 1

Following this: https://community.cloudera.com/t5/Community-Articles/User-authentication-from-Windows-Workstation-to-HDP-Realm/ta-p/245957

I realised switching "sspi" to false worked for Firefox but I guess thats only fighting the symptom and a workaround because Chrome and IE still got the same issue.