Important JWT validation messages get lost in debug log level

[madmas]

Version

• vert.x core: 3.8.2
• vert.x auth: 3.8.2

Context

I encountered an exception which looks suspicious while setting up a backend-service implemented with quarkus secured with the openid-connect extension which relies on vertx.

While the error persisted, I only got the message

2019-10-13 21:04:42,837 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-14) HTTP Request to /api/hello failed, error id: 483566ce-9289-4e39-a490-4d1d32905689-14: io.vertx.core.impl.NoStackTraceThrowable: Expired Token

After @sberyozkin pointed me to the right code, I could find out by debugging that in fact my keycloak-server and the machine running the service were not in sync regarding the time and that caused a token "issued in the future". Thus the validation in https://github.com/vert-x3/vertx-auth/blob/master/vertx-jwt/src/main/java/io/vertx/ext/jwt/JWT.java#L243 failed.

The exception is then catched at https://github.com/vert-x3/vertx-auth/blob/master/vertx-auth-oauth2/src/main/java/io/vertx/ext/auth/oauth2/impl/OAuth2UserImpl.java#L231 and the details (which are important to find out whats going on) only logged on debug level.

OAuth2AuthProviderImpl then resolves the future only with the generic error "Token expired" as not details were provided back.

Do you have a reproducer?

(it's a little more complex but I describe the crutial points here)

• setup keycloak with 2 clients, on plubic authentication (that is used to generate a token) and a "backend" using "bearer only"
• let the keycloak system run a little bit in the future (~20s were enough in my case)
• implement a client web app that serves a UI, triggers the login and stores the token issued.
• This app uses the token then to access a backend service implemented with Quarkus (or just vert.x itself) that is secured by keycloak and depends on a valid token.
• the token validation will fail as the token used is from the future and thus rejected.
• see "Token expired" in the log - while other frameworks validate just fine. after knowing why, it seems easy, but with more detailled log output error-investigation could be much more enjoyable ;-)

Extra

• see https://github.com/quarkusio/quarkus/issues/4553 as reference

[pmlopes]

Yes we could improve the error messages (would you like to contribute them?) On the other hand look at the leeway configuration where we allow some time drifting while validating the token specifically for clock synchronization issues.

[stuartwdouglas]

We can't log full stack traces for invalid tokens by default, it opens up an DOS vector where an attacker can send a massive amount of requests with expired tokens which will cause massive disk IO due to all the logging and potentially exhaust disk space.

[madmas]

Well, "full stack" is not necessary, i think, but propagating the details from https://github.com/vert-x3/vertx-auth/blob/master/vertx-jwt/src/main/java/io/vertx/ext/jwt/JWT.java#L235 https://github.com/vert-x3/vertx-auth/blob/master/vertx-jwt/src/main/java/io/vertx/ext/jwt/JWT.java#L243 https://github.com/vert-x3/vertx-auth/blob/master/vertx-jwt/src/main/java/io/vertx/ext/jwt/JWT.java#L251 so they apprear in the log would be very helpful, i think

[pmlopes]

Please reopen is still relevant.