[keycloak-user] Introspection of RPT fails

Tue Jul 10 11:33:47 EDT 2018

Will check this out. Thanks for the report.

On Tue, Jul 10, 2018 at 4:57 AM, stefan.wachter <stefan.wachter at bosch-si.com
> wrote:

> Hi,
>
> I have difficulties in determining the cause why introspection of an RPT
> fails. The RPT can be introspected a couple of times before it fails. In
> the log shown below I grepped for "task-26" that seems to have handled
> the failed introspection request.
>
> I have the impression that the problem is related to token refreshments.
> If the "Access Token Lifespan" is set to a smaller value (e.g. 1
> minute), then the failure happens earlier. In particular, it seems that
> after the SECOND set of token refreshments the introspection fails. In
> detail:
>
> There are 3 tokens (together with their refresh tokens) involved:
>
> 1. An IdToken that is used for logging into the web application. The
> IdToken is used when a Ticket is exchanged for an RPT (the IdToken is
> set as the "claim_token" parameter in the token request).
>
> 2. An RPT.
>
> 3. A PAT
>
> When a request hits the application after the tokens have expired the
> first time all tokens are refreshed in turn and the introspection
> succeedes. Yet, if a request hits the application after the tokens have
> expired the second time then all tokens are refreshed again (using the
> refresh tokens that were returned on the first refreshment). The
> following RPT introspection however, fails.
>
> Has anyone experienced the same failure?
>
> Thanks for you attention
>
> Stefan
>
>
>
> 06:46:12,779 DEBUG
> [org.keycloak.authorization.protection.introspect.RPTIntrospectionProvider]
>
> (default task-26) Introspecting requesting party token
> 06:46:12,779 TRACE [org.keycloak.keys.DefaultKeyManager] (default
> task-26) Active key found: realm=device
> kid=t00ewHrCADcXjvvIFBWQrZnOWiBTVBoyt0-UOzBP7w0 algorithm=RS256
> 06:46:12,779 TRACE [org.keycloak.keys.DefaultKeyManager] (default
> task-26) Active key found: realm=device
> kid=ae1f030a-b3a5-4c9a-875a-a0802119fa2a algorithm=HS256
> 06:46:12,779 TRACE [org.keycloak.keys.DefaultKeyManager] (default
> task-26) Active key found: realm=device
> kid=2aefcc15-33cf-45f6-a4bf-88535501712c algorithm=AES
> 06:46:12,779 TRACE [org.keycloak.keys.DefaultKeyManager] (default
> task-26) Active key realm=device
> kid=t00ewHrCADcXjvvIFBWQrZnOWiBTVBoyt0-UOzBP7w0 algorithm=RS256
> 06:46:12,780 TRACE
> [org.infinispan.interceptors.InvocationContextInterceptor] (default
> task-26) Invoked with command GetKeyValueCommand
> {key=device.client.query.by.clientId.web-gui, flags=null} and
> InvocationContext
> [org.infinispan.context.SingleKeyNonTxInvocationContext at 6cb8a247]
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Exists in context? null
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Retrieved from container
> ImmortalCacheEntry{key=device.client.query.by.clientId.web-gui, value=0}
> (ignoreOwnership=false, isLocal=true)
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Wrap device.client.query.by.clientId.web-gui for read.
> Entry=ImmortalCacheEntry{key=device.client.query.by.clientId.web-gui,
> value=0}
> 06:46:12,780 TRACE [org.infinispan.interceptors.CallInterceptor]
> (default task-26) Executing command: GetKeyValueCommand
> {key=device.client.query.by.clientId.web-gui, flags=null}.
> 06:46:12,780 TRACE
> [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default
> task-26) Release locks for keys=[]. owner=null
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.RealmCacheSession] (default
> task-26) client by name cache hit: web-gui
> 06:46:12,780 TRACE
> [org.infinispan.interceptors.InvocationContextInterceptor] (default
> task-26) Invoked with command GetKeyValueCommand
> {key=b5f94341-0d4c-4280-94e1-10b6771cd66c, flags=null} and
> InvocationContext
> [org.infinispan.context.SingleKeyNonTxInvocationContext at 3a2141a6]
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Exists in context? null
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Retrieved from container
> ImmortalCacheEntry{key=b5f94341-0d4c-4280-94e1-10b6771cd66c, value=0}
> (ignoreOwnership=false, isLocal=true)
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Wrap b5f94341-0d4c-4280-94e1-10b6771cd66c for read.
> Entry=ImmortalCacheEntry{key=b5f94341-0d4c-4280-94e1-10b6771cd66c,
> value=0}
> 06:46:12,780 TRACE [org.infinispan.interceptors.CallInterceptor]
> (default task-26) Executing command: GetKeyValueCommand
> {key=b5f94341-0d4c-4280-94e1-10b6771cd66c, flags=null}.
> 06:46:12,780 TRACE
> [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default
> task-26) Release locks for keys=[]. owner=null
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.RealmCacheSession] (default
> task-26) client by id cache hit: web-gui
> 06:46:12,780 TRACE
> [org.infinispan.interceptors.InvocationContextInterceptor] (default
> task-26) Invoked with command GetKeyValueCommand {key=device,
> flags=null} and InvocationContext
> [org.infinispan.context.SingleKeyNonTxInvocationContext at 2f9442f3]
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Exists in context? null
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Retrieved from container ImmortalCacheEntry{key=device,
> value=0} (ignoreOwnership=false, isLocal=true)
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Wrap device for read. Entry=ImmortalCacheEntry{key=device,
> value=0}
> 06:46:12,780 TRACE [org.infinispan.interceptors.CallInterceptor]
> (default task-26) Executing command: GetKeyValueCommand {key=device,
> flags=null}.
> 06:46:12,780 TRACE
> [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default
> task-26) Release locks for keys=[]. owner=null
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.RealmCacheSession] (default
> task-26) by id cache hit: device
> 06:46:12,780 TRACE
> [org.infinispan.interceptors.InvocationContextInterceptor] (default
> task-26) Invoked with command GetKeyValueCommand
> {key=b5f94341-0d4c-4280-94e1-10b6771cd66c, flags=null} and
> InvocationContext
> [org.infinispan.context.SingleKeyNonTxInvocationContext at 30227841]
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Exists in context? null
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Retrieved from container
> ImmortalCacheEntry{key=b5f94341-0d4c-4280-94e1-10b6771cd66c, value=0}
> (ignoreOwnership=false, isLocal=true)
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Wrap b5f94341-0d4c-4280-94e1-10b6771cd66c for read.
> Entry=ImmortalCacheEntry{key=b5f94341-0d4c-4280-94e1-10b6771cd66c,
> value=0}
> 06:46:12,780 TRACE [org.infinispan.interceptors.CallInterceptor]
> (default task-26) Executing command: GetKeyValueCommand
> {key=b5f94341-0d4c-4280-94e1-10b6771cd66c, flags=null}.
> 06:46:12,780 TRACE
> [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default
> task-26) Release locks for keys=[]. owner=null
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.RealmCacheSession] (default
> task-26) client by id cache hit: web-gui
> 06:46:12,780 TRACE
> [org.infinispan.interceptors.InvocationContextInterceptor] (default
> task-26) Invoked with command GetKeyValueCommand {key=device,
> flags=null} and InvocationContext
> [org.infinispan.context.SingleKeyNonTxInvocationContext at 19214e98]
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Exists in context? null
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Retrieved from container ImmortalCacheEntry{key=device,
> value=0} (ignoreOwnership=false, isLocal=true)
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Wrap device for read. Entry=ImmortalCacheEntry{key=device,
> value=0}
> 06:46:12,780 TRACE [org.infinispan.interceptors.CallInterceptor]
> (default task-26) Executing command: GetKeyValueCommand {key=device,
> flags=null}.
> 06:46:12,780 TRACE
> [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default
> task-26) Release locks for keys=[]. owner=null
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.RealmCacheSession] (default
> task-26) by id cache hit: device
> 06:46:12,780 DEBUG
> [org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider]
> (default task-26)
> getUserSessionWithPredicate(a3320548-da14-4e0c-adc1-5616c9d0c23b): found
> in local cache
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.UserCacheSession] (default
> task-26) getuserById d22c43c4-04fb-4756-82d6-fc9fe3bd9e8c
> 06:46:12,780 TRACE
> [org.infinispan.interceptors.InvocationContextInterceptor] (default
> task-26) Invoked with command GetKeyValueCommand
> {key=d22c43c4-04fb-4756-82d6-fc9fe3bd9e8c, flags=null} and
> InvocationContext
> [org.infinispan.context.SingleKeyNonTxInvocationContext at 29bd006b]
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Exists in context? null
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Retrieved from container
> ImmortalCacheEntry{key=d22c43c4-04fb-4756-82d6-fc9fe3bd9e8c, value=0}
> (ignoreOwnership=false, isLocal=true)
> 06:46:12,780 TRACE [org.infinispan.container.EntryFactoryImpl] (default
> task-26) Wrap d22c43c4-04fb-4756-82d6-fc9fe3bd9e8c for read.
> Entry=ImmortalCacheEntry{key=d22c43c4-04fb-4756-82d6-fc9fe3bd9e8c,
> value=0}
> 06:46:12,780 TRACE [org.infinispan.interceptors.CallInterceptor]
> (default task-26) Executing command: GetKeyValueCommand
> {key=d22c43c4-04fb-4756-82d6-fc9fe3bd9e8c, flags=null}.
> 06:46:12,780 TRACE
> [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default
> task-26) Release locks for keys=[]. owner=null
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.UserCacheSession] (default
> task-26) getuserById d22c43c4-04fb-4756-82d6-fc9fe3bd9e8c
> 06:46:12,780 TRACE
> [org.keycloak.models.cache.infinispan.UserCacheSession] (default
> task-26) return managedusers
> 06:46:12,781 TRACE [org.keycloak.events] (default task-26)
> type=INTROSPECT_TOKEN_ERROR, realmId=device, clientId=resource-server,
> userId=null, ipAddress=139.15.216.71, error=invalid_request,
> detail='Failed to introspect token.', client_auth_method=client-secret,
> requestUri=https://keycloak.apps.de1.bosch-iot-cloud.com/
> auth/realms/device/protocol/openid-connect/token/introspect,
> cookies=[]
>
> --
>
> Best regards,
>
> *Stefan Wachter
> INST-ICM/BSV-BS*
>
> Tel.  +49(711)811-58477
>
> *Be**QIK
> *
>
> _______________________________________________
> keycloak-user mailing list
> keycloak-user at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/keycloak-user