OIDC: 401 when access-token needs to be refreshed and user-info-required=true

[yoadey]

Describe the bug

We're using OIDC extension with storing all tokens (id, access and refresh token) in the q_session cookie. In the application, we require the userinfo also, so we set quarkus.oidc.authentication.user-info-required=true. When the access token expires and the userinfo is not cached (e.g. because of a server restart), we get a 401 as response.

Expected behavior

The access token is refreshed before the userinfo is retrieved and we are successfully authenticated

Actual behavior

The user info endpoint is called before the access token is refreshed and the exception of the call does not trigger the token to refresh, resulting in a 401 access denied

How to Reproduce?

1. Create an oidc application with following parameters:

   quarkus.oidc.auth-server-url=https://oidc-server.com
   quarkus.oidc.client-id=MY_CLIENT
   quarkus.oidc.application-type=web-app
   quarkus.oidc.authentication.user-info-required=true
   

2. Start the application and log in.
3. Restart the application.
4. Reload the page

Output of uname -a or ver

No response

Output of java -version

openjdk version "17.0.3" 2022-04-19 LTS

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.15.2

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.6

Additional information

Log from the 401 response:

2023-01-05 17:10:02,561 DEBUG [io.qua.oid.run.DefaultTenantConfigResolver] (vert.x-eventloop-thread-2) Registered TenantResolver has not provided the configuration for tenant 'Default', using the default tenant
2023-01-05 17:10:02,563 DEBUG [io.qua.oid.run.CodeAuthenticationMechanism] (vert.x-eventloop-thread-2) Session cookie is present, starting the reauthentication
2023-01-05 17:10:02,564 DEBUG [io.qua.oid.run.DefaultTenantConfigResolver] (vert.x-eventloop-thread-2) Registered TenantResolver has not provided the configuration for tenant 'Default', using the default tenant
2023-01-05 17:10:02,566 DEBUG [io.qua.oid.run.OidcIdentityProvider] (vert.x-eventloop-thread-2) Starting creating SecurityIdentity
2023-01-05 17:10:02,567 DEBUG [io.qua.oid.run.DefaultTenantConfigResolver] (vert.x-eventloop-thread-2) Registered TenantResolver has not provided the configuration for tenant 'Default', using the default tenant
2023-01-05 17:10:02,568 DEBUG [io.qua.oid.run.OidcIdentityProvider] (vert.x-eventloop-thread-2) Requesting UserInfo
2023-01-05 17:10:02,569 DEBUG [io.qua.oid.run.OidcProviderClient] (vert.x-eventloop-thread-2) Get UserInfo on: https://***********/oauth/userinfo auth: Bearer *******************
2023-01-05 17:10:02,637 DEBUG [io.qua.oid.run.OidcProviderClient] (vert.x-eventloop-thread-2) Request has failed: status: 401, error message: null
2023-01-05 17:10:02,647 ERROR [io.qua.oid.run.CodeAuthenticationMechanism] (vert.x-eventloop-thread-2) ID token verification failure: io.quarkus.oidc.OIDCException
2023-01-05 17:10:02,648 DEBUG [io.qua.ver.htt.run.sec.HttpSecurityRecorder] (vert.x-eventloop-thread-2) Authentication has failed, returning HTTP status 401
2023-01-05 17:10:02,650 DEBUG [io.ver.ext.web.RoutingContext] (vert.x-eventloop-thread-2) RoutingContext failure (500): io.quarkus.security.AuthenticationCompletionException
        at io.quarkus.oidc.runtime.CodeAuthenticationMechanism$5$1.apply(CodeAuthenticationMechanism.java:290)
        at io.quarkus.oidc.runtime.CodeAuthenticationMechanism$5$1.apply(CodeAuthenticationMechanism.java:270)
        at io.smallrye.context.impl.wrappers.SlowContextualFunction.apply(SlowContextualFunction.java:21)
        at io.smallrye.mutiny.operators.uni.UniOnFailureFlatMap$UniOnFailureFlatMapProcessor.performInnerSubscription(UniOnFailureFlatMap.java:92)
        at io.smallrye.mutiny.operators.uni.UniOnFailureFlatMap$UniOnFailureFlatMapProcessor.dispatch(UniOnFailureFlatMap.java:83)
        at io.smallrye.mutiny.operators.uni.UniOnFailureFlatMap$UniOnFailureFlatMapProcessor.onFailure(UniOnFailureFlatMap.java:60)
        at io.smallrye.mutiny.operators.uni.UniOperatorProcessor.onFailure(UniOperatorProcessor.java:55)
        at io.smallrye.mutiny.operators.uni.UniOperatorProcessor.onFailure(UniOperatorProcessor.java:55)
        at io.smallrye.mutiny.operators.uni.UniOperatorProcessor.onFailure(UniOperatorProcessor.java:55)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap$UniOnItemOrFailureFlatMapProcessor.onFailure(UniOnItemOrFailureFlatMap.java:67)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap$UniOnItemOrFailureFlatMapProcessor.onFailure(UniOnItemOrFailureFlatMap.java:67)
        at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownFailure$KnownFailureSubscription.forward(UniCreateFromKnownFailure.java:38)
        at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownFailure$KnownFailureSubscription.access$100(UniCreateFromKnownFailure.java:26)
        at io.smallrye.mutiny.operators.uni.builders.UniCreateFromKnownFailure.subscribe(UniCreateFromKnownFailure.java:23)
        at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap$UniOnItemOrFailureFlatMapProcessor.performInnerSubscription(UniOnItemOrFailureFlatMap.java:99)
        at io.smallrye.mutiny.operators.uni.UniOnItemOrFailureFlatMap$UniOnItemOrFailureFlatMapProcessor.onFailure(UniOnItemOrFailureFlatMap.java:65)
        at io.smallrye.mutiny.operators.uni.UniOperatorProcessor.onFailure(UniOperatorProcessor.java:55)
        at io.smallrye.mutiny.operators.uni.UniOperatorProcessor.onFailure(UniOperatorProcessor.java:55)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransform$UniOnItemTransformProcessor.onItem(UniOnItemTransform.java:40)
        at io.smallrye.mutiny.vertx.AsyncResultUni.lambda$subscribe$1(AsyncResultUni.java:35)
        at io.smallrye.mutiny.vertx.DelegatingHandler.handle(DelegatingHandler.java:25)
        at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse(HttpContext.java:397)
        at io.vertx.ext.web.client.impl.HttpContext.execute(HttpContext.java:384)
        at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:362)
        at io.vertx.ext.web.client.impl.HttpContext.fire(HttpContext.java:329)
        at io.vertx.ext.web.client.impl.HttpContext.dispatchResponse(HttpContext.java:291)
        at io.vertx.ext.web.client.impl.HttpContext.lambda$null$7(HttpContext.java:507)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:246)
        at io.vertx.core.impl.EventLoopContext.lambda$runOnContext$0(EventLoopContext.java:43)
        at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: io.quarkus.oidc.OIDCException
        at io.quarkus.oidc.runtime.OidcProviderClient.responseException(OidcProviderClient.java:204)
        at io.quarkus.oidc.runtime.OidcProviderClient.getString(OidcProviderClient.java:197)
        at io.quarkus.oidc.runtime.OidcProviderClient.getUserInfo(OidcProviderClient.java:176)
        at io.quarkus.oidc.runtime.OidcProviderClient.lambda$getUserInfo$1(OidcProviderClient.java:81)
        at io.smallrye.context.impl.wrappers.SlowContextualFunction.apply(SlowContextualFunction.java:21)
        at io.smallrye.mutiny.operators.uni.UniOnItemTransform$UniOnItemTransformProcessor.onItem(UniOnItemTransform.java:36)
        ... 19 more


2023-01-05 17:10:02,657 DEBUG [io.qua.mic.run.bin.ver.VertxHttpServerMetrics] (vert.x-eventloop-thread-2) requestRouted null HttpRequestMetric [initialPath=/, currentRoutePath=null, templatePath=null, request=io.vertx.core.http.impl.Http1xServerRequest@6af3714e]      
2023-01-05 17:10:02,659 DEBUG [io.qua.mic.run.bin.ver.VertxHttpServerMetrics] (vert.x-eventloop-thread-2) requestRouted null HttpRequestMetric [initialPath=/, currentRoutePath=null, templatePath=null, request=io.vertx.core.http.impl.Http1xServerRequest@6af3714e]      
2023-01-05 17:10:02,660 DEBUG [io.qua.mic.run.bin.ver.VertxHttpServerMetrics] (vert.x-eventloop-thread-2) responseEnd io.vertx.core.http.impl.Http1xServerResponse@3dc5fcac, HttpRequestMetric [initialPath=/, currentRoutePath=null, templatePath=null, request=io.vertx.core.http.impl.Http1xServerRequest@6af3714e]
2023-01-05 17:10:02,662 DEBUG [io.qua.ver.htt.run.ForwardedParser] (vert.x-eventloop-thread-2) Recalculated absoluteURI to http://localhost:8080/
2023-01-05 17:10:02,664 INFO  [io.qua.htt.access-log] (vert.x-eventloop-thread-2) 127.0.0.1 - - 05/Jan/2023:17:10:02 +0100 "GET / HTTP/1.1" 401 -

[quarkus-bot]

/cc @pedroigor(oidc), @sberyozkin(oidc)

[sberyozkin]

@yoadey

I think you need to add

quarkus.oidc.token.refresh-expired=true
quarkus.oidc.token.refresh-token-time-skew=30S 

(30S is just an example) - that would ensure the ID token is refreshed when it is about to expire or expired and the access token will be refreshed along the way.

The only problem is that it won't work in 2.15.2, as there the userinfo is checked before the ID token verification.
Can you please try the above properties with the main branch ?

[sberyozkin]

Ignore it please, that needs to be investigated/reviewed further

[sberyozkin]

I'll need to tweak the order of the verification depending on what role is played by UserInfo in this verification

[sberyozkin]

@yoadey Looking at it right now. So, in 2.15.x the order of the verification of the code flow access token is correct, but is not complete enough for such a token be refreshed (as opposed to the ID token) - but it does make sense to support refreshing both types of tokens since they are coming from the same code flow response. In 2.16 the order (that was my idea) got wrong for this case be supported - in 2.16 we now support the optional verification of the opaque/binary tokens based on the presence of UserInfo.

In my PR I'll restore the original 2.15 order of the code flow access token verification for the cases where UserInfo is not a prerequisite for verifying such tokens as well as add an expiration check for this type of token

[yoadey]

@sberyozkin Thank you very much for the fast response and reaction, really appreciate it!

These changes seem to solve the case I have, will upgrade as soon as the new Release is available.

[sberyozkin]

@yoadey Np, let us know please if that PR helps. Where I know it won't help yet is when we have a case with a provider like Azure returning an ID token plus a binary access token and it would have no introspection endpoint to verify this code flow access token.
The code flow response may also provide an access token expiry time but we do not retain this property in a cookie. I can investigate this option in a follow up PR a bit later, the tokens stored in a cookie have their signatures checked, a standalone expiry property would also need to be signed for it to be stored in a cookie

[quarkus-bot]

@sberyozkin triage/backport* labels may not be added to an issue. Please add them to the corresponding pull request.

This message is automatically generated by a bot.