9:57 a.m.
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@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@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@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@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@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@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/devi...,
cookies=[]
--
Best regards,
*Stefan Wachter
INST-ICM/BSV-BS*
Tel. +49(711)811-58477
*Be**QIK
*