quarkusquarkus-oidc

How does one diagnose Quarkus REST service OIDC errors (specifically 403 forbidden)?


I am trying to secure a Quarkus (v 1.13.7) REST service using OIDC bearer. I am following their Using OpenID Connect to Protect Service Applications guide but I'm not having much luck.

Whenever I include Authorization: Bearer {validAccessToken} in the headers of my request to protected resources (using @RolesAllowed annotations), I get a 403 Forbidden response with an empty body. If I ommit this header, I can access unprotected resources just fine but protected resources, unsuprisingly, give 401 Unauthorized, again with an empty body.

This is the application properties I use:

# DB configuration
quarkus.datasource.db-kind = postgresql
quarkus.datasource.username = bla
quarkus.datasource.password = bla_bla
quarkus.hibernate-orm.database.generation = update
quarkus.datasource.jdbc.url = jdbc:postgresql://blablabla

# Logging
%dev.quarkus.log.level=ALL
%dev.quarkus.log.category."io.quarkus.oidc".level=FINEST
%dev.quarkus.log.category."io.quarkus.security".level=FINEST

# OIDC config
demo.oidc-provider=valid.provider.url.com/bla
demo.oidc-clientid=validClientId
demo.oidc-clientsecret=validClientSecret
demo.oidc-issuer=${demo.oidc-provider}

quarkus.oidc.application-type=service
quarkus.oidc.auth-server-url=${demo.oidc-provider}
quarkus.oidc.client-id=${demo.oidc-clientid}
quarkus.oidc.credentials.client-secret.value=${demo.oidc-clientsecret}
quarkus.oidc.token.issuer=${demo.oidc-issuer}

quarkus.oidc.authentication.user-info-required=true
quarkus.oidc.roles.source=userinfo
quarkus.oidc.roles.role-claim-path=userroles
quarkus.oidc.discovery-enabled=false
quarkus.oidc.introspection-path=/introspect
quarkus.oidc.user-info-path=/userinfo

Notice the logging section. Despite it being configured to log everything, this is all it prints when I get a 403 response:

2021-08-04 11:22:10,147 FINEST [io.ver.ext.web.imp.RouterImpl] (vert.x-eventloop-thread-6) Router: 1653352852 accepting request GET http://localhost:8080/my/api/resource/path
2021-08-04 11:22:10,171 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Route matches: RouteState{path='null', order=-2147483648, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.VertxHttpRecorder$5@76ec9770], failureHandlers=null, added=true, pattern=null, groups=null, useNormalisedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=false}
2021-08-04 11:22:10,171 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Calling the  handler
2021-08-04 11:22:10,200 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Route matches: RouteState{path='null', order=-200, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2@79d5df9a], failureHandlers=null, added=true, pattern=null, groups=null, useNormalisedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=false}
2021-08-04 11:22:10,202 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Calling the  handler
2021-08-04 11:22:10,203 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Route matches: RouteState{path='null', order=-100, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$3@1e4e05ec], failureHandlers=null, added=true, pattern=null, groups=null, useNormalisedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=false}
2021-08-04 11:22:10,206 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Calling the  handler
2021-08-04 11:22:10,207 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Route matches: RouteState{path='null', order=-2, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.VertxHttpRecorder$4@6bf0fbda], failureHandlers=null, added=true, pattern=null, groups=null, useNormalisedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=false}
2021-08-04 11:22:10,208 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Calling the  handler
2021-08-04 11:22:10,209 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Route matches: RouteState{path='null', order=10000, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.vertx.http.runtime.StaticResourcesRecorder$$Lambda$785/0x0000000800786840@6ed633ec, io.quarkus.vertx.http.runtime.StaticResourcesRecorder$$Lambda$785/0x0000000800786840@57426aed, io.quarkus.vertx.http.runtime.StaticResourcesRecorder$$Lambda$789/0x0000000800785840@7d171a43], failureHandlers=null, added=true, pattern=null, groups=null, useNormalisedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=false, exclusive=false, exactPath=false}
2021-08-04 11:22:10,210 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Calling the  handler
2021-08-04 11:22:10,210 FINEST [io.ver.ext.web.han.imp.StaticHandlerImpl] (vert.x-eventloop-thread-6) File to serve is /my/api/resource/path
2021-08-04 11:22:10,215 FINEST [io.ver.ext.web.han.imp.StaticHandlerImpl] (vert.x-eventloop-thread-6) File to serve is /my/api/resource/path
2021-08-04 11:22:10,218 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Route matches: RouteState{path='/', order=10001, enabled=true, methods=null, consumes=null, emptyBodyPermittedWithConsumes=false, produces=null, contextHandlers=[io.quarkus.resteasy.runtime.standalone.VertxRequestHandler@43d422b0], failureHandlers=null, added=true, pattern=null, groups=null, useNormalisedPath=true, namedGroupsInRegex=null, virtualHostPattern=null, pathEndsWithSlash=true, exclusive=false, exactPath=false}
2021-08-04 11:22:10,219 FINEST [io.ver.ext.web.imp.RoutingContextImplBase] (vert.x-eventloop-thread-6) Calling the  handler
2021-08-04 11:22:10,222 DEBUG [org.jbo.res.res.i18n] (executor-thread-1) RESTEASY002315: PathInfo: /my/api/resource/path

Maybe to someone, somewhere, the above messages are usefull. To me, useful they are not. Interestingly, if the token was expired, I would actually get a message indicating this.

How on God's green Earth (or whatever deity and planet attributes you prefer) am I supposed to diagnose this problem?

I already tried using Quarkus exception mapping to try and catch the problem and inspect the exception, but no matter how I configure the exception mapping, it never gets called. According to issue #8570 on the quarkus git repo:

[...] to map authentication failures as well as authorisation then you need to disable proactive auth, and then you can use an exception mapper for the resulting AuthenticationFailedException, as it will be generated from the interceptor rather than early in security handling.

So I added quarkus.http.auth.proactive=false to my app properties and now Quarkus returns a 500 Internal Error which says that it can't call getIdentity() on I don't know what thread and that I should instead inject this identity or other some such. The thing is, I'm not trying to get this identity anywhere (not yet, atleast), so this failure is in their own internal code. I therefore gave up on trying to use exception mapping.

Edit: I should also mention that the OIDC information (client id, urls, etc.) are valid. I use them in my Angular app and they work just fine.


Solution

  • At this moment the OidcProvider class which validates the tokens delegate some validation into the underlying jose-jwt validator.

    By enabling the following logging categories it is possible to see some information rearding why a token may be not valid:

    quarkus.log.category."io.quarkus.oidc".level=TRACE
    
    # The category io.quarkus.oidc already contains the errors generated by the jose-jwt library
    

    The errors that will appear are generally regarding configuration errors, expired tokens or invalid signatures. You are not going to be able to see an error regarding roles allowed to access a resource.

    So the cause for some 403 errors will appear, and for other don't.

    Typically what I check for when I had 403 errors in the past while developing new applications is ensure that the audience, the claims, and the roles (groups) are correctly present in the token issued by the provider. Most of the times the error is one of those three not being correctly set.

    I'm going to open a enhancement to unify or at least include as much errors as possible or improve the documentation regarding this topic.

    Maybe they can do something about it or point us in a better direction.