[keycloak-user] Introspection of RPT fails

Tue Jul 10 04:13:58 EDT 2018

Hi Stefan,

I had exactly the same issue with keycloak-3.4.3.Final and 
keycloak-4.0.0.Final. Not sure what may be causing it but I worked 
around it by taking a look at 
https://github.com/iperdomo/keycloak-oauth2-instrospection/blob/master/test.sh

This did the trick for me:

curl -s \
      -d "client_id=validator" \
      -d "client_secret=dd3214ca-eb0a-49ea-94ad-3761f575b11b" \
      -d "token=${ACCESS_TOKEN}" \
      -d "token_type_hint=access_token" \
http://localhost:8080/auth/realms/introspection/protocol/openid-connect/token/introspect

Happy to hear a better answer to this.

Thanks,
Daniel.

On 10/07/18 09:57, stefan.wachter 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=[]
>