Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Critical
-
Resolution: Fixed
-
Affects Version/s: 6.5.0, 6.5.1, 6.5.2, 7.0.0-micsvc-1.0.2
-
Fix Version/s: 6.5.3, 7.0.0, 7.0.0-micsvc-1.0.3
-
Component/s: None
-
Labels:
-
Environment:OS : OSX-Mojave 10.14.5
jdk : openjdk-11.0.4
IG: 7.0.0-SNAPSHOT 23c6661e703
OpenAM: 7.0.0-SNAPSHOT 9c65209f1fd
-
Sprint:2019.17 - IG / Microservices, 2020.01 - IG / Microservices
-
Story Points:3
-
Flagged:Impediment
Description
When accessing 2 times the same route, with the same fake token, the second access does not generate a call to AM to verify the token validity (and next calls do generate calls to AM).
This issue is NOT systematic (although occurs around 50% of the time)
Route generating the issue
{
"MyCapture": "all",
"condition": "${matches(request.uri.path, '^/OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection')}",
"handler": {
"config": {
"filters": [
{
"config": {
"accessTokenResolver": {
"config": {
"_defaultTimeout": null,
"_maximumSize": null,
"_maximumTimeToCache": null,
"delegate": {
"config": {
"amService": "AmService-1",
"providerHandler": {
"MyCapture": "all",
"config": {
"filters": [
{
"config": {
"add": {
"Authorization": [
"Basic ${encodeBase64('test_OAuth2ResourceServerFilter:password')}"
]
},
"messageType": "request"
},
"type": "HeaderFilter"
}
],
"handler": "ReverseProxyHandler"
},
"type": "Chain"
}
},
"type": "TokenIntrospectionAccessTokenResolver"
},
"enabled": true
},
"name": "CacheAccessTokenResolver-1",
"type": "CacheAccessTokenResolver"
},
"realm": "/filters_realm",
"requireHttps": false,
"scopes": [
"openid",
"profile"
]
},
"type": "OAuth2ResourceServerFilter"
}
],
"handler": {
"config": {
"entity": "{\"test_result\": \"successful\", \"oauth2_token_info\": ${contexts.oauth2.accessToken.asJsonValue().toString()}}",
"headers": {
"Content-Type": [
"application/json"
]
},
"reason": "Found",
"status": 418
},
"name": "myAccessViaOAuth2",
"type": "StaticResponseHandler"
}
},
"type": "Chain"
},
"heap": [
{
"config": {
"agent": {
"passwordSecretId": "agent.secret.id",
"username": "ig_agent"
},
"amHandler": {
"capture": "all",
"config": {
"delegate": "ClientHandler"
},
"type": "Delegate"
},
"notifications": {
"enabled": true,
"reconnectDelay": "5 s"
},
"realm": "/filters_realm",
"sessionCache": {
"enabled": false
},
"ssoTokenHeader": "filters_cookie",
"url": "http://openam.example.com:8084/openam",
"version": "7.0.0"
},
"name": "AmService-1",
"type": "AmService"
}
]
}
Here is what we can find in the logs
route-system.log (we can see 1 warning corresponding to the first request)
2019-12-02T11:15:16,097Z | INFO | main | o.f.o.s.OpenIGInitializer | @system | Reading the configuration from /Users/jcdevil/Dev/Forgerock/Stash/PyForge/results/20191202-121415/Filters/openig/ig_instance_dir/config/admin.json
2019-12-02T11:15:16,468Z | INFO | main | o.f.o.s.OpenIGInitializer | @system | IG environment:
2019-12-02T11:15:16,468Z | INFO | main | o.f.o.s.OpenIGInitializer | @system | - instance directory: /Users/jcdevil/Dev/Forgerock/Stash/PyForge/results/20191202-121415/Filters/openig/ig_instance_dir
2019-12-02T11:15:16,469Z | INFO | main | o.f.o.s.OpenIGInitializer | @system | - temporary directory: /Users/jcdevil/Dev/Forgerock/Stash/PyForge/results/20191202-121415/Filters/openig/ig_instance_dir/tmp
2019-12-02T11:15:16,836Z | WARN | main | o.f.o.s.OpenIGInitializer | @system | The product is running in DEVELOPMENT mode - by default, all endpoints are open and accessible. Do not use this mode for a production environment. To switch to PRODUCTION mode, remove or set the top-level attribute '"mode": "PRODUCTION"' to '/Users/jcdevil/Dev/Forgerock/Stash/PyForge/results/20191202-121415/Filters/openig/ig_instance_dir/config/admin.json'
2019-12-02T11:15:18,856Z | INFO | main | o.f.api.models.Items | @system | Asked for Items for annotated type, but type does not have required RequestHandler annotation. No api descriptor will be available for class org.forgerock.monitoring.DropwizardMetricsCollectionResourceProvider
2019-12-02T11:15:18,858Z | INFO | main | o.f.a.m.Resource | @system | Asked for Resource for annotated type, but type does not have required RequestHandler annotation. No api descriptor will be available for class org.forgerock.monitoring.DropwizardMetricsCollectionResourceProvider
2019-12-02T11:15:19,350Z | INFO | main | o.f.o.s.OpenIGInitializer | @system | Reading the configuration from /Users/jcdevil/Dev/Forgerock/Stash/PyForge/results/20191202-121415/Filters/openig/ig_instance_dir/config/config.json
2019-12-02T11:15:19,591Z | INFO | main | o.a.j.s.TldScanner | @system | At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
2019-12-02T11:15:20,842Z | WARN | main | o.f.o.j.JwtSessionManager$Heaplet | @system | JWT session support has been enabled but no encryption keys have been configured. A temporary key pair will be used but this means that OpenIG will not be able to decrypt any JWT session cookies after a configuration change, a server restart, nor will it be able to decrypt JWT session cookies encrypted by another OpenIG server.
2019-12-02T11:15:20,843Z | WARN | main | o.f.o.j.JwtSessionManager$Heaplet | @system | No shared secret have been configured for JWT session authenticity verification.A temporary key will be used but this means that OpenIG will not be able to verify any JWT session cookies after a configuration change, a server restart, nor will it be able to verify JWT session cookies signed by another OpenIG server.
2019-12-02T11:15:20,943Z | WARN | main | o.f.o.h.r.RouterHandler | @system | Prefer to declare to declare the scanInterval configuration setting as a duration like this : "1 seconds".
2019-12-02T11:15:20,963Z | WARN | main | o.f.o.h.GenericHeaplet | @system | The heap object name ('MyMainRouter') has been transformed to a URL-friendly name ('mymainrouter') that is exposed in endpoint URLs. To prevent this message, consider renaming your heap object with the transformed name, or provide your own appropriate value.
2019-12-02T11:15:21,089Z | INFO | main | o.f.o.h.r.RouterHandler | @system | Routes endpoint available at '/openig/api/system/objects/mymainrouter/routes'
2019-12-02T11:19:33,630Z | INFO | pool-5-thread-1 | o.f.o.o.AmServiceHeaplet | @system | DEPRECATED [/heap/0/config] No 'secretsProvider' defined, fallback to route's secrets
2019-12-02T11:19:33,800Z | INFO | pool-5-thread-1 | o.f.o.d.c.C.c.{Delegate}/heap/0/config/amHandler | @system |
--- (request) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-34 --->
POST http://openam.example.com:8084/openam/json/realms/root/realms/filters_realm/authenticate?authIndexType=module&authIndexValue=Application HTTP/1.1
Accept-API-Version: resource=2.0
Content-Length: 165
Content-Type: application/json; charset=UTF-8
[entity]
2019-12-02T11:19:34,354Z | INFO | I/O dispatcher 25 | o.f.o.d.c.C.c.{Delegate}/heap/0/config/amHandler | @system |
<--- (response) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-34 ---
HTTP/1.1 200 OK
Cache-Control: private
Cache-Control: no-cache, no-store, must-revalidate
Content-API-Version: resource=2.1
Content-Length: 180
Content-Type: application/json
Date: Mon, 02 Dec 2019 11:19:34 GMT
Expires: 0
Pragma: no-cache
Set-Cookie: amlbcookie=01; Path=/; Domain=example.com
Set-Cookie: filters_cookie=XlEwzJWNi0deKdgMWnC97b3vJ30.*AAJTSQACMDEAAlNLABxsSmQ1VktDVTV0ZjhySUZ0Y3VocWZPdFVYd1E9AAR0eXBlAANDVFMAAlMxAAA.*; Path=/; Domain=example.com
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
[entity]
2019-12-02T11:19:35,226Z | WARN | pool-5-thread-1 | o.f.o.h.r.RouteBuilder | @system | Route name ('OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection') has been transformed to a URL-friendly name ('oauth2resourceserverfilter_cacheaccesstokenresolverwithtokenintrospection') that is exposed in endpoint URLs. To prevent this message, consider renaming your route with the transformed name, or provide your own appropriate value.
2019-12-02T11:19:35,340Z | INFO | pool-5-thread-1 | o.f.o.a.NoOpAuditService | @system | This is a no-op placeholder AuditService, it should be overridden in the heap if real auditing services are required.
2019-12-02T11:19:35,352Z | INFO | pool-5-thread-1 | o.f.o.h.r.RouterHandler | @system | Loaded the route with id 'OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection' registered with the name 'OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection'
2019-12-02T11:19:35,365Z | INFO | pool-5-thread-1 | o.f.o.h.r.RouterHandler | @system | Deployed the route with id 'OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection' named 'OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection'
2019-12-02T11:19:37,237Z | WARN | I/O dispatcher 17 | c.g.b.c.c.LocalAsyncCache | @system | Exception thrown during asynchronous load
org.forgerock.http.oauth2.AccessTokenException: Access token returned by authorization server is not currently active
at org.forgerock.http.oauth2.resolver.TokenIntrospectionAccessTokenResolver.lambda$buildAccessToken$0(TokenIntrospectionAccessTokenResolver.java:109)
at org.forgerock.util.CloseSilentlyFunction.apply(CloseSilentlyFunction.java:53)
at org.forgerock.util.CloseSilentlyFunction.apply(CloseSilentlyFunction.java:29)
at org.forgerock.util.promise.PromiseImpl.lambda$then$2(PromiseImpl.java:346)
at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:538)
at org.forgerock.util.promise.PromiseImpl.setState(PromiseImpl.java:579)
at org.forgerock.util.promise.PromiseImpl.tryHandleResult(PromiseImpl.java:267)
at org.forgerock.util.promise.PromiseImpl.handleResult(PromiseImpl.java:217)
at org.forgerock.util.promise.PromiseImpl.lambda$then$2(PromiseImpl.java:346)
at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:538)
at org.forgerock.util.promise.PromiseImpl.setState(PromiseImpl.java:579)
at org.forgerock.util.promise.PromiseImpl.tryHandleResult(PromiseImpl.java:267)
at org.forgerock.util.promise.PromiseImpl.handleResult(PromiseImpl.java:217)
at org.forgerock.util.promise.PromiseImpl.lambda$then$2(PromiseImpl.java:346)
at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:538)
at org.forgerock.util.promise.PromiseImpl.setState(PromiseImpl.java:579)
at org.forgerock.util.promise.PromiseImpl.tryHandleResult(PromiseImpl.java:267)
at org.forgerock.util.promise.PromiseImpl.handleResult(PromiseImpl.java:217)
at org.forgerock.util.promise.PromiseImpl.lambda$then$2(PromiseImpl.java:346)
at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:538)
at org.forgerock.util.promise.PromiseImpl.setState(PromiseImpl.java:579)
at org.forgerock.util.promise.PromiseImpl.tryHandleResult(PromiseImpl.java:267)
at org.forgerock.util.promise.PromiseImpl.handleResult(PromiseImpl.java:217)
at org.forgerock.util.promise.PromiseImpl.lambda$then$2(PromiseImpl.java:346)
at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:538)
at org.forgerock.util.promise.PromiseImpl.setState(PromiseImpl.java:579)
at org.forgerock.util.promise.PromiseImpl.tryHandleResult(PromiseImpl.java:267)
at org.forgerock.util.promise.PromiseImpl.handleResult(PromiseImpl.java:217)
at org.forgerock.util.promise.PromiseImpl.lambda$then$2(PromiseImpl.java:346)
at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:538)
at org.forgerock.util.promise.PromiseImpl.setState(PromiseImpl.java:579)
at org.forgerock.util.promise.PromiseImpl.tryHandleResult(PromiseImpl.java:267)
at org.forgerock.util.promise.PromiseImpl.handleResult(PromiseImpl.java:217)
at org.forgerock.util.promise.PromiseImpl.lambda$then$2(PromiseImpl.java:346)
at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:538)
at org.forgerock.util.promise.PromiseImpl.setState(PromiseImpl.java:579)
at org.forgerock.util.promise.PromiseImpl.tryHandleResult(PromiseImpl.java:267)
at org.forgerock.util.promise.PromiseImpl.handleResult(PromiseImpl.java:217)
at org.forgerock.http.apache.async.AsyncResponseHttpClient$EntityCompletionPromiseResponseConsumer.responseCompleted(AsyncResponseHttpClient.java:147)
at org.forgerock.http.apache.async.MdcAwareHttpAsyncResponseConsumer.responseCompleted(MdcAwareHttpAsyncResponseConsumer.java:64)
at org.apache.http.impl.nio.client.MainClientExec.responseCompleted(MainClientExec.java:383)
at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseCompleted(DefaultClientExchangeHandlerImpl.java:172)
at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(HttpAsyncRequestExecutor.java:448)
at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(HttpAsyncRequestExecutor.java:338)
at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:265)
at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114)
at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:591)
at java.base/java.lang.Thread.run(Thread.java:834)
2019-12-02T11:19:41,322Z | INFO | pool-5-thread-1 | o.f.o.d.c.C.c.{Delegate}/heap/0/config/amHandler | @system |
--- (request) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-49 --->
POST http://openam.example.com:8084/openam/json/realms/root/sessions?_action=logout HTTP/1.1
Accept-API-Version: protocol=2.1,resource=3.0
Content-Length: 4
Content-Type: application/json; charset=UTF-8
filters_cookie: XlEwzJWNi0deKdgMWnC97b3vJ30.*AAJTSQACMDEAAlNLABxsSmQ1VktDVTV0ZjhySUZ0Y3VocWZPdFVYd1E9AAR0eXBlAANDVFMAAlMxAAA.*
[entity]
2019-12-02T11:19:41,327Z | INFO | pool-5-thread-1 | o.f.o.h.r.RouterHandler | @system | Unloaded the route with id 'OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection'
2019-12-02T11:19:41,328Z | INFO | pool-5-thread-1 | o.f.o.h.r.RouterHandler | @system | Undeployed the route with id 'OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection'
2019-12-02T11:19:41,452Z | INFO | I/O dispatcher 25 | o.f.o.d.c.C.c.{Delegate}/heap/0/config/amHandler | @system |
<--- (response) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-49 ---
HTTP/1.1 200 OK
Cache-Control: private
Cache-Control: no-cache, no-store, must-revalidate
Content-API-Version: resource=3.2
Content-Length: 36
Content-Type: application/json; charset=UTF-8
Date: Mon, 02 Dec 2019 11:19:41 GMT
Expires: 0
Pragma: no-cache
Set-Cookie: filters_cookie=""; Expires=Thu, 01 Jan 1970 00:00:00 GMT; Path=/; Domain=example.com
Set-Cookie: amlbcookie=LOGOUT; Expires=Thu, 01 Jan 1970 00:00:10 GMT; Path=/; Domain=example.com
X-Content-Type-Options: nosniff
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
[entity]
route-OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection.log
we can see that the second request does not generate a request to AM
2019-12-02T11:19:37,161Z | INFO | http-nio-8083-exec-7 | o.f.o.d.c.C.M.top-level-handler | @OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection |
--- (request) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-39 --->
GET http://openig.example.com:8083/OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection HTTP/1.1
accept: */*
accept-encoding: gzip, deflate
authorization: Bearer ******MY***FAKE***TOKEN******
connection: keep-alive
host: openig.example.com:8083
user-agent: python-requests/2.22.0
Context's content as JSON:
attributes:
2019-12-02T11:19:37,183Z | INFO | http-nio-8083-exec-7 | o.f.o.d.c.C.M.{Chain}/handler/config/filters/0/config/accessTokenResolver/config/delegate/config/providerHandler | @OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection |
--- (request) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-39 --->
POST http://openam.example.com:8084/openam/oauth2/realms/root/realms/filters_realm/introspect HTTP/1.1
Accept: application/json
Content-Length: 64
Content-Type: application/x-www-form-urlencoded
token=******MY***FAKE***TOKEN******&token_type_hint=access_token
Context's content as JSON:
attributes:
2019-12-02T11:19:37,218Z | INFO | I/O dispatcher 17 | o.f.o.d.c.C.M.{Chain}/handler/config/filters/0/config/accessTokenResolver/config/delegate/config/providerHandler | @OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection |
<--- (response) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-39 ---
HTTP/1.1 200 OK
Content-Length: 16
Content-Type: application/json; charset=UTF-8
Date: Mon, 02 Dec 2019 11:19:36 GMT
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
{"active":false}
Context's content :
attributes:
2019-12-02T11:19:37,229Z | INFO | I/O dispatcher 17 | o.f.o.d.c.C.M.top-level-handler | @OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection |
<--- (response) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-39 ---
HTTP/1.1 401 Unauthorized
WWW-Authenticate: Bearer realm="/filters_realm",error_description="The access token provided is expired, revoked, malformed, or invalid for other reasons.",error="invalid_token"
Context's content :
attributes:
2019-12-02T11:19:37,248Z | INFO | http-nio-8083-exec-9 | o.f.o.d.c.C.M.top-level-handler | @OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection |
--- (request) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-41 --->
GET http://openig.example.com:8083/OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection HTTP/1.1
accept: */*
accept-encoding: gzip, deflate
authorization: Bearer ******MY***FAKE***TOKEN******
connection: keep-alive
host: openig.example.com:8083
user-agent: python-requests/2.22.0
Context's content as JSON:
attributes:
2019-12-02T11:19:37,256Z | INFO | http-nio-8083-exec-9 | o.f.o.d.c.C.M.top-level-handler | @OAuth2ResourceServerFilter_CacheAccessTokenResolverWithTokenIntrospection |
<--- (response) id:fc41db4b-6fa5-475b-b7b2-04c0d672a150-41 ---
HTTP/1.1 401 Unauthorized
WWW-Authenticate: Bearer realm="/filters_realm",error_description="The access token provided is expired, revoked, malformed, or invalid for other reasons.",error="invalid_token"
Context's content :
attributes:
QA info :
1 - git pull PyForge
2 -
./cleanup.py -f
3 -
./ configure.py
4 - launch the following commands (on Linux/Mac), in the PyForge root directory :
export PYFORGE_ROOT_DIR=`pwd`; source PyBot/OpenIG/tools/.qa_tools ppth
5 - launch the tests with the following alias (notice that some tags are currently not available but will be created ) :
rig -s Filters/OAuth2ResourceServerFilter/AccesstokenResolver/Cache/CATRWithTokenIntrospection -t When_Accessing_Route_With_Fake_Token_Then_Resource_Should_Not_Be_Accessed_Nor_Cached -n
Servers are then available for checks... (NB : test may have been modified, to expect the current error)
6 -
./cleanup.py -f