Token verification failed explanation #9820

ToshY · 2022-01-09T19:46:13Z

ToshY
Jan 9, 2022

Describe the bug

Keycloak gives me the error response invalid_token: Token verification failed.

When looking at where this error is thrown (here), it just doesn't really clarify for me what part of this "verification" could possibly cause this to occur, hence this issue.

I've setup Keycloak with docker compose, alongside with Traefik, to use OAuth2 for my Symfony 6 application.

The idea is as follows:

User goes to symfony-app-dashboard.local/connect/keycloak in the application gets redirect to keycloak.development.local to login (with the correct realm).
User logs in successfully and gets redirect back to symfony-app-dashboard.local/connect/keycloak/check to authenticate the user further.
The exception invalid_token: Token verification failed is thrown (found in the WWW-Authenticate header when dumping the Guzzle response)

The container for the application has access to keycloak through http://keycloak:8080, which is also setup as proxy in the knpuniversity/oauth2-client-bundle configuration.

Below the debug log from the keycloak container when refreshing the page once after the error occurred. It shows

2022-01-09T20:19:46.944103293+01:00 19:19:46,943 DEBUG [io.undertow.request] (default I/O-7) Matched prefix path /auth for path /auth/realms/symfony-app/protocol/openid-connect/auth
2022-01-09T20:19:46.944806903+01:00 19:19:46,944 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) new JtaTransactionWrapper
2022-01-09T20:19:46.944815769+01:00 19:19:46,944 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) was existing? false
2022-01-09T20:19:46.945286385+01:00 19:19:46,945 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) RESTEASY002315: PathInfo: /realms/symfony-app/protocol/openid-c
8000
onnect/auth
2022-01-09T20:19:46.945985275+01:00 19:19:46,945 DEBUG [org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] (default task-110) Hibernate RegisteredSynchronization successfully registered with JTA platform
2022-01-09T20:19:46.946656434+01:00 19:19:46,946 DEBUG [org.keycloak.protocol.oidc.endpoints.AuthorizationEndpointChecker] (default task-110) PKCE non-supporting Client
2022-01-09T20:19:46.946784342+01:00 19:19:46,946 DEBUG [org.keycloak.services.util.CookieHelper] (default task-110) AUTH_SESSION_ID cookie found in the request header
2022-01-09T20:19:46.946802676+01:00 19:19:46,946 DEBUG [org.keycloak.services.util.CookieHelper] (default task-110) AUTH_SESSION_ID cookie found in the cookie field
2022-01-09T20:19:46.946812163+01:00 19:19:46,946 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-110) Found AUTH_SESSION_ID cookie with value 88d75eaa-0881-4c3b-a301-8db2215dff8f.9612d0e401d0
2022-01-09T20:19:46.946995775+01:00 19:19:46,946 DEBUG [org.keycloak.services.util.CookieHelper] (default task-110) AUTH_SESSION_ID cookie found in the request header
2022-01-09T20:19:46.946999011+01:00 19:19:46,946 DEBUG [org.keycloak.services.util.CookieHelper] (default task-110) AUTH_SESSION_ID cookie found in the cookie field
2022-01-09T20:19:46.947014620+01:00 19:19:46,946 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-110) Found AUTH_SESSION_ID cookie with value 88d75eaa-0881-4c3b-a301-8db2215dff8f.9612d0e401d0
2022-01-09T20:19:46.947178405+01:00 19:19:46,947 DEBUG [org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider] (default task-110) getUserSessionWithPredicate(88d75eaa-0881-4c3b-a301-8db2215dff8f): remote cache not available
2022-01-09T20:19:46.947197040+01:00 19:19:46,947 DEBUG [org.keycloak.protocol.AuthorizationEndpointBase] (default task-110) Sent request to authz endpoint. We don't have root authentication session with ID '88d75eaa-0881-4c3b-a301-8db2215dff8f' but we have userSession.Re-created root authentication session with same ID. Client is: symfony-app-client . New authentication session tab ID: mZgSTxExvMc
2022-01-09T20:19:46.948066066+01:00 19:19:46,947 DEBUG [org.keycloak.authentication.AuthenticationProcessor] (default task-110) AUTHENTICATE
2022-01-09T20:19:46.948117792+01:00 19:19:46,947 DEBUG [org.keycloak.authentication.AuthenticationProcessor] (default task-110) AUTHENTICATE ONLY
2022-01-09T20:19:46.949480308+01:00 19:19:46,949 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-110) processFlow: browser
2022-01-09T20:19:46.949496509+01:00 19:19:46,949 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-110) check execution: 'auth-cookie', requirement: 'ALTERNATIVE'
2022-01-09T20:19:46.949498102+01:00 19:19:46,949 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-110) authenticator: auth-cookie
2022-01-09T20:19:46.949498612+01:00 19:19:46,949 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver] (default task-110) Going through the flow 'browser' for adding executions
2022-01-09T20:19:46.949499113+01:00 19:19:46,949 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver] (default task-110) Going through the flow 'forms' for adding executions
2022-01-09T20:19:46.949803330+01:00 19:19:46,949 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver] (default task-110) Selections when trying execution 'auth-cookie' : [ authSelection - auth-cookie,  authSelection - identity-provider-redirector,  authSelection - auth-username-password-form]
2022-01-09T20:19:46.949827935+01:00 19:19:46,949 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-110) invoke authenticator.authenticate: auth-cookie
2022-01-09T20:19:46.950864974+01:00 19:19:46,950 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-110) authenticator SUCCESS: auth-cookie
2022-01-09T20:19:46.951933903+01:00 19:19:46,951 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-110) Removing authSession '88d75eaa-0881-4c3b-a301-8db2215dff8f'. Expire restart cookie: true
2022-01-09T20:19:46.953036686+01:00 19:19:46,952 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (default task-110) Generated identifier: ac991232-7da4-4dda-8d0b-9278c69a9db2, using strategy: org.hibernate.id.Assigned
2022-01-09T20:19:46.953624902+01:00 19:19:46,953 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-110) Create login cookie - name: KEYCLOAK_IDENTITY, path: /auth/realms/symfony-app/, max-age: -1
2022-01-09T20:19:46.953922866+01:00 19:19:46,953 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-110) Expiring remember me cookie
2022-01-09T20:19:46.954099976+01:00 19:19:46,953 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-110) Expiring cookie: KEYCLOAK_REMEMBER_ME path: /auth/realms/symfony-app/
2022-01-09T20:19:46.954388191+01:00 19:19:46,954 DEBUG [org.keycloak.protocol.oidc.OIDCLoginProtocol] (default task-110) redirectAccessCode: state: ae1efdc171733835c8cf127ff3b7d94e
2022-01-09T20:19:46.956036658+01:00 19:19:46,955 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) JtaTransactionWrapper  commit
2022-01-09T20:19:46.956302463+01:00 19:19:46,956 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Processing flush-time cascades
2022-01-09T20:19:46.956559531+01:00 19:19:46,956 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Dirty checking collections
2022-01-09T20:19:46.956563158+01:00 19:19:46,956 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects
2022-01-09T20:19:46.956893823+01:00 19:19:46,956 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2022-01-09T20:19:46.956896799+01:00 19:19:46,956 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-110) Listing entities:
2022-01-09T20:19:46.957085660+01:00 19:19:46,956 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-110) org.keycloak.events.jpa.EventEntity{clientId=symfony-app-client, realmId=symfony-app, ipAddress=192.168.47.1, id=ac991232-7da4-4dda-8d0b-9278c69a9db2, sessionId=88d75eaa-0881-4c3b-a301-8db2215dff8f, time=1641755986952, error=null, type=LOGIN, userId=5331df2e-0782-45ee-95f0-936bb7f6ef4e, detailsJson={"auth_method":"openid-connect","auth_type":"code","response_type":"code","redirect_uri":"https://symfony-app-dashboard.local/connect/keycloak/check","consent":"no_consent_required","code_id":"88d75eaa-0881-4c3b-a301-8db2215dff8f","response_mode":"query","username":"j.doe"}}
2022-01-09T20:19:46.957320337+01:00 19:19:46,957 DEBUG [org.hibernate.SQL] (default task-110)
2022-01-09T20:19:46.957322982+01:00     insert
2022-01-09T20:19:46.957323573+01:00     into
2022-01-09T20:19:46.957324124+01:00         public.EVENT_ENTITY
2022-01-09T20:19:46.957324645+01:00         (CLIENT_ID, DETAILS_JSON, ERROR, IP_ADDRESS, REALM_ID, SESSION_ID, EVENT_TIME, TYPE, USER_ID, ID)
2022-01-09T20:19:46.957325146+01:00     values
2022-01-09T20:19:46.957325627+01:00         (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2022-01-09T20:19:46.957480034+01:00 19:19:46,957 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-110) KeycloakDS: getConnection(null, WrappedConnectionRequestInfo@6347b2ae[userName=symfony-app-keycloak]) [0/20]
2022-01-09T20:19:46.957662995+01:00 19:19:46,957 DEBUG [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (default task-110) java.sql.Connection#beginRequest has been invoked
2022-01-09T20:19:46.958051057+01:00 19:19:46,957 FINE  [org.postgresql.jdbc.PgConnection] (default task-110)   setAutoCommit = false
2022-01-09T20:19:46.958864040+01:00 19:19:46,958 DEBUG [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default task-110) Skipping aggressive release due to manual disabling
2022-01-09T20:19:46.959044275+01:00 19:19:46,958 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-110) Initiating JDBC connection release from afterStatement
2022-01-09T20:19:46.959332391+01:00 19:19:46,959 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (default task-110) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2022-01-09T20:19:46.960675781+01:00 19:19:46,960 DEBUG [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (default task-110) java.sql.Connection#endRequest has been invoked
2022-01-09T20:19:46.960767011+01:00 19:19:46,960 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-110) KeycloakDS: returnConnection(7c8fbde, false) [0/20]
2022-01-09T20:19:46.960875793+01:00 19:19:46,960 FINE  [org.postgresql.jdbc.PgConnection] (default task-110)   setAutoCommit = true
2022-01-09T20:19:46.960992601+01:00 19:19:46,960 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-110) Initiating JDBC connection release from afterTransaction
2022-01-09T20:19:46.961114878+01:00 19:19:46,961 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) JtaTransactionWrapper end
2022-01-09T20:19:46.961372227+01:00 19:19:46,961 DEBUG [org.keycloak.events] (default task-110) type=LOGIN, realmId=symfony-app, clientId=symfony-app-client, userId=5331df2e-0782-45ee-95f0-936bb7f6ef4e, ipAddress=192.168.47.1, auth_method=openid-connect, auth_type=code, response_type=code, redirect_uri=https://symfony-app-dashboard.local/connect/keycloak/check, consent=no_consent_required, code_id=88d75eaa-0881-4c3b-a301-8db2215dff8f, response_mode=query, username=j.doe, authSessionParentId=88d75eaa-0881-4c3b-a301-8db2215dff8f, authSessionTabId=mZgSTxExvMc
2022-01-09T20:19:47.075840044+01:00 19:19:47,075 DEBUG [io.undertow.request] (default I/O-1) Matched prefix path /auth for path /auth/realms/symfony-app/protocol/openid-connect/token
2022-01-09T20:19:47.076115969+01:00 19:19:47,075 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) new JtaTransactionWrapper
2022-01-09T20:19:47.076122842+01:00 19:19:47,076 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) was existing? false
2022-01-09T20:19:47.076434592+01:00 19:19:47,076 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) RESTEASY002315: PathInfo: /realms/symfony-app/protocol/openid-connect/token
2022-01-09T20:19:47.076904757+01:00 19:19:47,076 DEBUG [org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] (default task-110) Hibernate RegisteredSynchronization successfully registered with JTA platform
2022-01-09T20:19:47.076929954+01:00 19:19:47,076 DEBUG [org.keycloak.authentication.AuthenticationProcessor] (default task-110) AUTHENTICATE CLIENT
2022-01-09T20:19:47.076930976+01:00 19:19:47,076 DEBUG [org.keycloak.authentication.ClientAuthenticationFlow] (default task-110) client authenticator: client-secret
2022-01-09T20:19:47.076931567+01:00 19:19:47,076 DEBUG [org.keycloak.authentication.ClientAuthenticationFlow] (default task-110) client authenticator SUCCESS: client-secret
2022-01-09T20:19:47.076932078+01:00 19:19:47,076 DEBUG [org.keycloak.authentication.ClientAuthenticationFlow] (default task-110) Client symfony-app-client authenticated by client-secret
2022-01-09T20:19:47.077146226+01:00 19:19:47,077 DEBUG [org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider] (default task-110) getUserSessionWithPredicate(88d75eaa-0881-4c3b-a301-8db2215dff8f): found in local cache
2022-01-09T20:19:47.077866767+01:00 19:19:47,077 DEBUG [org.hibernate.SQL] (default task-110)
2022-01-09T20:19:47.077868941+01:00     select
2022-01-09T20:19:47.077869482+01:00         clientscop0_.ID as ID1_12_0_,
2022-01-09T20:19:47.077869983+01:00         clientscop0_.DESCRIPTION as DESCRIPT2_12_0_,
2022-01-09T20:19:47.077870464+01:00         clientscop0_.NAME as NAME3_12_0_,
2022-01-09T20:19:47.077870955+01:00         clientscop0_.PROTOCOL as PROTOCOL4_12_0_,
2022-01-09T20:19:47.077871416+01:00         clientscop0_.REALM_ID as REALM_ID5_12_0_
2022-01-09T20:19:47.077871877+01:00     from
2022-01-09T20:19:47.077872347+01:00         public.CLIENT_SCOPE clientscop0_
2022-01-09T20:19:47.077872818+01:00     where
2022-01-09T20:19:47.077873329+01:00         clientscop0_.ID=?
2022-01-09T20:19:47.077895581+01:00 19:19:47,077 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-110) KeycloakDS: getConnection(null, WrappedConnectionRequestInfo@6347b2ae[userName=symfony-app-keycloak]) [0/20]
2022-01-09T20:19:47.077896593+01:00 19:19:47,077 DEBUG [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (default task-110) java.sql.Connection#beginRequest has been invoked
2022-01-09T20:19:47.078083410+01:00 19:19:47,078 FINE  [org.postgresql.jdbc.PgConnection] (default task-110)   setAutoCommit = false
2022-01-09T20:19:47.079070045+01:00 19:19:47,078 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-110) Initiating JDBC connection release from afterStatement
2022-01-09T20:19:47.079414125+01:00 19:19:47,079 DEBUG [org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader] (default task-110) Done entity load : org.keycloak.models.jpa.entities.ClientScopeEntity#cb250c57-2aba-4c1a-9d34-0dd1daeabbf6
2022-01-09T20:19:47.081669051+01:00 19:19:47,081 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (default task-110) Generated identifier: 982a9f13-720a-439c-995c-ead673c4a344, using strategy: org.hibernate.id.Assigned
2022-01-09T20:19:47.081674842+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-01-09T20:19:47.081675573+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider
2022-01-09T20:19:47.081676104+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider
2022-01-09T20:19:47.081676615+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-01-09T20:19:47.081681674+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext,  Method : proceed
2022-01-09T20:19:47.081682215+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) WriterInterceptor: org.jboss.resteasy.security.doseta.DigitalSigningInterceptor
2022-01-09T20:19:47.081682686+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.security.doseta.i18n] (default task-110) Interceptor : org.jboss.resteasy.security.doseta.DigitalSigningInterceptor,  Method : aroundWriteTo
2022-01-09T20:19:47.081683157+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext,  Method : proceed
2022-01-09T20:19:47.081683648+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-01-09T20:19:47.081704427+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider
2022-01-09T20:19:47.081705399+01:00 19:19:47,081 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) Provider : org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider,  Method : writeTo
2022-01-09T20:19:47.081898017+01:00 19:19:47,081 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) JtaTransactionWrapper  commit
2022-01-09T20:19:47.081900071+01:00 19:19:47,081 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Processing flush-time cascades
2022-01-09T20:19:47.081900632+01:00 19:19:47,081 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Dirty checking collections
2022-01-09T20:19:47.081901133+01:00 19:19:47,081 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects
2022-01-09T20:19:47.081901634+01:00 19:19:47,081 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-110) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2022-01-09T20:19:47.081902115+01:00 19:19:47,081 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-110) Listing entities:
2022-01-09T20:19:47.081902746+01:00 19:19:47,081 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-110) org.keycloak.events.jpa.EventEntity{clientId=symfony-app-client, realmId=symfony-app, ipAddress=172.24.0.9, id=982a9f13-720a-439c-995c-ead673c4a344, sessionId=88d75eaa-0881-4c3b-a301-8db2215dff8f, time=1641755987081, error=null, type=CODE_TO_TOKEN, userId=5331df2e-0782-45ee-95f0-936bb7f6ef4e, detailsJson={"token_id":"782dac21-2951-4c54-838e-c192a107595d","grant_type":"authorization_code","refresh_token_type":"Refresh","scope":"profile symfony-app-scope roles","refresh_token_id":"321f2bfb-6267-40fd-9484-3c259791e4f1","code_id":"88d75eaa-0881-4c3b-a301-8db2215dff8f","client_auth_method":"client-secret"}}
2022-01-09T20:19:47.082001480+01:00 19:19:47,081 DEBUG [org.hibernate.SQL] (default task-110)
2022-01-09T20:19:47.082003133+01:00     insert
2022-01-09T20:19:47.082003654+01:00     into
2022-01-09T20:19:47.082004175+01:00         public.EVENT_ENTITY
2022-01-09T20:19:47.082004696+01:00         (CLIENT_ID, DETAILS_JSON, ERROR, IP_ADDRESS, REALM_ID, SESSION_ID, EVENT_TIME, TYPE, USER_ID, ID)
2022-01-09T20:19:47.082005176+01:00     values
2022-01-09T20:19:47.082005677+01:00         (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2022-01-09T20:19:47.082892848+01:00 19:19:47,082 DEBUG [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default task-110) Skipping aggressive release due to manual disabling
2022-01-09T20:19:47.082899370+01:00 19:19:47,082 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-110) Initiating JDBC connection release from afterStatement
2022-01-09T20:19:47.082902226+01:00 19:19:47,082 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (default task-110) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2022-01-09T20:19:47.083583243+01:00 19:19:47,083 DEBUG [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (default task-110) java.sql.Connection#endRequest has been invoked
2022-01-09T20:19:47.083587892+01:00 19:19:47,083 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-110) KeycloakDS: returnConnection(7c8fbde, false) [0/20]
2022-01-09T20:19:47.083588473+01:00 19:19:47,083 FINE  [org.postgresql.jdbc.PgConnection] (default task-110)   setAutoCommit = true
2022-01-09T20:19:47.083589004+01:00 19:19:47,083 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-110) Initiating JDBC connection release from afterTransaction
2022-01-09T20:19:47.083589565+01:00 19:19:47,083 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) JtaTransactionWrapper end
2022-01-09T20:19:47.083606817+01:00 19:19:47,083 DEBUG [org.keycloak.events] (default task-110) type=CODE_TO_TOKEN, realmId=symfony-app, clientId=symfony-app-client, userId=5331df2e-0782-45ee-95f0-936bb7f6ef4e, ipAddress=172.24.0.9, token_id=782dac21-2951-4c54-838e-c192a107595d, grant_type=authorization_code, refresh_token_type=Refresh, scope='profile symfony-app-scope roles', refresh_token_id=321f2bfb-6267-40fd-9484-3c259791e4f1, code_id=88d75eaa-0881-4c3b-a301-8db2215dff8f, client_auth_method=client-secret
2022-01-09T20:19:47.089985315+01:00 19:19:47,089 DEBUG [io.undertow.request] (default I/O-1) Matched prefix path /auth for path /auth/realms/symfony-app/protocol/openid-connect/userinfo
2022-01-09T20:19:47.090234769+01:00 19:19:47,090 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) new JtaTransactionWrapper
2022-01-09T20:19:47.090236863+01:00 19:19:47,090 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) was existing? false
2022-01-09T20:19:47.090400027+01:00 19:19:47,090 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) RESTEASY002315: PathInfo: /realms/symfony-app/protocol/openid-connect/userinfo
2022-01-09T20:19:47.090592745+01:00 19:19:47,090 DEBUG [org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] (default task-110) Hibernate RegisteredSynchronization successfully registered with JTA platform
2022-01-09T20:19:47.091644923+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-01-09T20:19:47.091649061+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider
2022-01-09T20:19:47.091649652+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider
2022-01-09T20:19:47.091650173+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-01-09T20:19:47.091650684+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext,  Method : proceed
2022-01-09T20:19:47.091651194+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) WriterInterceptor: org.jboss.resteasy.security.doseta.DigitalSigningInterceptor
2022-01-09T20:19:47.091693503+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.security.doseta.i18n] (default task-110) Interceptor : org.jboss.resteasy.security.doseta.DigitalSigningInterceptor,  Method : aroundWriteTo
2022-01-09T20:19:47.091695086+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext,  Method : proceed
2022-01-09T20:19:47.091701027+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-01-09T20:19:47.091701588+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) MessageBodyWriter: org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider
2022-01-09T20:19:47.091702099+01:00 19:19:47,091 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-110) Provider : org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider,  Method : writeTo
2022-01-09T20:19:47.091714723+01:00 19:19:47,091 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) JtaTransactionWrapper  commit
2022-01-09T20:19:47.091850074+01:00 19:19:47,091 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (default task-110) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2022-01-09T20:19:47.091852790+01:00 19:19:47,091 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-110) Initiating JDBC connection release from afterTransaction
2022-01-09T20:19:47.091866154+01:00 19:19:47,091 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-110) JtaTransactionWrapper end
2022-01-09T20:19:47.091876924+01:00 19:19:47,091 WARN  [org.keycloak.events] (default task-110) type=USER_INFO_REQUEST_ERROR, realmId=symfony-app, clientId=null, userId=null, ipAddress=172.24.0.9, error=invalid_token, auth_method=validate_access_token
2022-01-09T20:19:49.238237955+01:00 19:19:49,237 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) new JtaTransactionWrapper
2022-01-09T20:19:49.238259445+01:00 19:19:49,238 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) was existing? false
2022-01-09T20:19:49.238379810+01:00 19:19:49,238 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper  commit
2022-01-09T20:19:49.238382635+01:00 19:19:49,238 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper end
2022-01-09T20:19:49.238383316+01:00 19:19:49,238 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-2) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1953/0x000000084155d440

Version

16.1.0

Expected behavior

No token verification failure or adding a more descriptive reason for failing.

Actual behavior

invalid_token: Token verification failed

How to Reproduce?

Setup

Docker compose
- Keycloak: 16.1.0 (with Postgres 14-alpine)
- Traefik 2.5
- PHP 8.1 with Symfony 6, including the knpuniversity/oauth2-client-bundle and stevenmaguire/oauth2-keycloak libraries.

Anything else?

More information can be found in this SO issue I've created in a desperate attempt to find a solution.

Navigation Menu

Repository navigation

Token verification failed explanation #9820

Uh oh!

{{title}}

Uh oh!

Replies: 0 comments

Select a reply

Uh oh!

Token verification failed explanation #9820

Uh oh!

ToshY Jan 9, 2022

Describe the bug

Version

Expected behavior

Actual behavior

How to Reproduce?

Anything else?

Replies: 0 comments

ToshY
Jan 9, 2022