X.509 client certificate login not working beacuse of event type=LOGIN_ERROR with error=invalid_user_credentials #15660

psytester · 2022-11-23T20:37:02Z

psytester
< 10BC8 relative-time datetime="2022-11-23T19:44:07Z" class="no-wrap">Nov 23, 2022

I'm lost with my non working X.509 client certificate login on my Keycloak (version 20.0.1).

The logfile finally shows event type=LOGIN_ERROR with error=invalid_user_credentials

and before this:

[org.keycloak.authentication.DefaultAuthenticationFlow:491] [executor-thread-27] authenticator FAILED: direct-grant-auth-x509-username

I'm behind an apache reverse proxy and mTLS is done there.
The connection reverse proxy <----> keycloak is done without TLS.

related apache config for mTLS is working fine:

  # client certificate settings
  SSLVerifyClient require
  SSLOptions +ExportCertData +StrictRequire
  SSLVerifyDepth 10
  # client certificate CA file
  SSLCACertificateFile "/etc/httpd/conf/client_ca_chain.pem"

And passing certificate data to keycloak works well, too:

  # enrich request with client certificate PEM encoded
  RequestHeader set SSL_CLIENT_CERT "%{SSL_CLIENT_CERT}s"
  RequestHeader set SSL_CLIENT_CERT_CHAIN_0 "%{SSL_CLIENT_CERT_CHAIN_0}s"

Keycloak gets those additional HTTP Header:

SSL_CLIENT_CERT: -----BEGIN CERTIFICATE----- ...... -----END CERTIFICATE-----
SSL_CLIENT_CERT_CHAIN_0: -----BEGIN CERTIFICATE----- ...... -----END CERTIFICATE-----

In Keycloak I configured the part to fetch the certificate data:

spi-x509cert-lookup-provider=apache
spi-x509cert-lookup-apache-ssl-client-cert=SSL_CLIENT_CERT
spi-x509cert-lookup-apache-ssl-cert-chain-prefix=SSL_CLIENT_CERT_CHAIN
spi-x509cert-lookup-apache-certificate-chain-length=1

According to logfile event type=LOGIN_ERROR, the extract and user lookup of username based on subject serialnumber CERT1234567890 or e-mail works basically with my browser X.509 flow?!?

Flow details:
X509/Validate Username

with "Match SubjectDN using regular expression" and Regex "SERIALNUMBER=(.*?)(?:,|$)" to have the SN as account name

or with "Subject's Alternative Name E-mail" to have the e-mail as account name

and User mapping method = Username or Email

Nothing works for me and I don't get the reason.

Complete logfile of related X.509 login for username=CERT1234567890 lookup:

2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.AuthenticationProcessor:878] [executor-thread-27] AUTHENTICATE
2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.AuthenticationProcessor:1005] [executor-thread-27] AUTHENTICATE ONLY
2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow:231] [executor-thread-27] processFlow: browser X.509
2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow:372] [executor-thread-27] check execution: 'direct-grant-auth-x509-username', requirement: 'REQUIRED'
2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow:400] [executor-thread-27] authenticator: direct-grant-auth-x509-username
2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver:200] [executor-thread-27] Going through the flow 'browser X.509' for adding executions
2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver:112] [executor-thread-27] Selections when trying execution 'direct-grant-auth-x509-username' : [ authSelection - direct-grant-auth-x509-username]
2022-11-23 19:18:20,474 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow:445] [executor-thread-27] invoke authenticator.authenticate: direct-grant-auth-x509-username
2022-11-23 19:18:20,475 DEBUG [org.keycloak.services.x509.AbstractClientCertificateFromHttpHeadersLookup:104] [executor-thread-27] Found a valid x.509 certificate in "SSL_CLIENT_CERT" HTTP header
2022-11-23 19:18:20,475 DEBUG [org.keycloak.services.x509.AbstractClientCertificateFromHttpHeadersLookup:104] [executor-thread-27] Found a valid x.509 certificate in "SSL_CLIENT_CERT_CHAIN_0" HTTP header
2022-11-23 19:18:20,476 DEBUG [org.keycloak.services:481] [executor-thread-27] Extended Key Usage validation is not enabled.
2022-11-23 19:18:20,476 DEBUG [org.keycloak.services:513] [executor-thread-27] Certificate Policy validation is not enabled.
2022-11-23 19:18:20,476 DEBUG [org.keycloak.services:164] [executor-thread-27] UID Source: SUBJECTDN
2022-11-23 19:18:20,476 DEBUG [org.keycloak.services:165] [executor-thread-27] UID Extractor: org.keycloak.crypto.def.BCUserIdentityExtractorProvider
2022-11-23 19:18:20,477 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl:73] [executor-thread-27] `hibernate.connection.provider_disables_autocommit` was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
2022-11-23 19:18:20,477 DEBUG [org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl:177] [executor-thread-27] Hibernate RegisteredSynchronization successfully registered with JTA platform
2022-11-23 19:18:20,477 DEBUG [org.hibernate.SQL:144] [executor-thread-27] select userentity0_.ID as id1_72_, userentity0_.CREATED_TIMESTAMP as created_2_72_, userentity0_.EMAIL as email3_72_, userentity0_.EMAIL_CONSTRAINT as email_co4_72_, userentity0_.EMAIL_VERIFIED as email_ve5_72_, userentity0_.ENABLED as enabled6_72_, userentity0_.FEDERATION_LINK as federati7_72_, userentity0_.FIRST_NAME as first_na8_72_, userentity0_.LAST_NAME as last_nam9_72_, userentity0_.NOT_BEFORE as not_bef10_72_, userentity0_.REALM_ID as realm_i11_72_, userentity0_.SERVICE_ACCOUNT_CLIENT_LINK as service12_72_, userentity0_.USERNAME as usernam13_72_ from USER_ENTITY userentity0_ inner join USER_ATTRIBUTE attributes1_ on userentity0_.ID=attributes1_.USER_ID where userentity0_.REALM_ID=? and attributes1_.NAME=? and attributes1_.VALUE=?
2022-11-23 19:18:20,480 DEBUG [org.hibernate.SQL:144] [executor-thread-27] select federatedu0_.USER_ID as col_0_0_ from FED_USER_ATTRIBUTE federatedu0_ where federatedu0_.NAME=? and federatedu0_.VALUE=? and federatedu0_.REALM_ID=?
2022-11-23 19:18:20,480 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow:491] [executor-thread-27] authenticator FAILED: direct-grant-auth-x509-username
2022-11-23 19:18:20,480 DEBUG [org.keycloak.transaction.JtaTransactionWrapper:89] [executor-thread-27] JtaTransactionWrapper  commit
2022-11-23 19:18:20,481 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl:53] [executor-thread-27] On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2022-11-23 19:18:20,481 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl:160] [executor-thread-27] Initiating JDBC connection release from beforeTransactionCompletion
2022-11-23 19:18:20,481 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl:174] [executor-thread-27] Initiating JDBC connection release from afterTransaction
2022-11-23 19:18:20,481 DEBUG [org.keycloak.transaction.JtaTransactionWrapper:152] [executor-thread-27] JtaTransactionWrapper end

pretty printed for better reading:
2022-11-23 19:18:20,482 TRACE [org.keycloak.events:118] [executor-thread-27] type=LOGIN_ERROR,
realmId=5b9fb7b2-2b16-4019-8698-d84ace3aff0c,
clientId=realm-client-id,
userId=null,
ipAddress=10.3.23.20,
error=invalid_user_credentials,
x509_cert_subject_distinguished_name='C=DE,......,SERIALNUMBER=CERT1234567890',
auth_method=openid-connect,
auth_type=code,
x509_cert_issuer_distinguished_name='C=DE,.....',
response_type=code,
redirect_uri=https://applicationhostname/login/oauth2/code/keycloak,
code_id=0e4b71c8-be0e-4751-8577-e93bdbc9f44e,
response_mode=query,
x509_cert_serial_number=7371706,
username=CERT1234567890,
authSessionParentId=0e4b71c8-be0e-4751-8577-e93bdbc9f44e,
authSessionTabId=iidQHu9wdmA,
requestUri=https://applicationhostname/auth/realms/realm-name/protocol/openid-connect/auth?response_type=code&client_id=realm-client-id&scope=openid&state=kx30khADt5b1bySv7BT42lDmdQvQiZQ8-VB2uTKAQyw%3D&redirect_uri=https://applicationhostname/login/oauth2/code/keycloak&nonce=zbeJvIg6Jnx0bSdxLZxjuC3PJmt9M0u84vOBGiKY_IY,
cookies=[........]

Answered by psytester

Nov 23, 2022

ARGHH! One service reboot later it works now. But I understand neither the root cause nor the sympthoms.

View full answer

psytester · 2022-11-23T20:37:02Z

psytester
Nov 23, 2022
Author

ARGHH! One service reboot later it works now. But I understand neither the root cause nor the sympthoms.

1 reply

psytester Dec 13, 2022
Author

It works now for me. Maybe I was in a fault as found with admin ui issues https://github.com/keycloak/keycloak-ui/issues/3866 and https://github.com/keycloak/keycloak-ui/issues/3828

Navigation Menu

Repository navigation

X.509 client certificate login not working beacuse of event type=LOGIN_ERROR with error=invalid_user_credentials #15660

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 1 comment 1 reply

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

X.509 client certificate login not working beacuse of event type=LOGIN_ERROR with error=invalid_user_credentials #15660

Uh oh!

Uh oh!

psytester < 10BC8 relative-time datetime="2022-11-23T19:44:07Z" class="no-wrap">Nov 23, 2022

Replies: 1 comment · 1 reply

Uh oh!

psytester Nov 23, 2022 Author

Uh oh!

psytester Dec 13, 2022 Author

psytester
< 10BC8 relative-time datetime="2022-11-23T19:44:07Z" class="no-wrap">Nov 23, 2022

Replies: 1 comment 1 reply

psytester
Nov 23, 2022
Author

psytester Dec 13, 2022
Author