Improve logging in NimbusReactiveJwtDecoder

[ThomasHagelberg]

Catched exception should be logged before JwtException is thrown

Before a JwtException is thrown, the catched errorMsg should logged on an appropriate level. In order to quickly be able to identify the root cause in the event of a problem.

Current Behavior
Plugin:

• org.springframework.boot: 3.1.3

Artifacts:

• org.springframework.boot:spring-boot-starter-webflux:3.1.3
• org.springframework.security:spring-security-oauth2-jose:6.1.3

It simply throws:
throw new BadJwtException("Failed to validate the token", ex); which is used for logging in AuthenticationWebFilter at DEBUG level only

In a real world application, proper logging to monitor the application state is crucial. At the moment only a verbose message "Failed to validate the token" is logged at DEBUG level, which is not really used in prod profiles? Also the errorMsg doesn't provide any more information than the 401 Unauthorized response code that is returned regardless.

Context
After I got my NimbusReactiveJwtDecoder to work with jwks validation. I wanted to see how the implementation handles invalid scenarios, logging etc. And to my surprise, there is in practice no logging at all. There is a lot of exceptions carrying different messages, but eventually they all end up in the WebFilter as: "Authentication failed: Failed to validate the token".

Is it possible that the NimbusReactiveJwtDecoder actually log the catched exceptions?
One practical example is when the jwks public key signature is a mismatch from the private key used to sign the JWT that is used as Authorization Bearer:

Here you can see how the BadJWSException is thrown when the signature is invalid. Originally thrown from DefaultJWTProcessor in com.nimbusds.jwt.proc

This flow makes it really hard to use in production environment, because if any of these JwtExceptions would occur (due to invalid Jwt signatures being sent etc.), it would be of great value to see the reason for the actual exception, and preferably not at debug level. Either some bean config that enables additional logging or some other smart way would be hugely beneficial to have.

I'm more than happy to answer additional questions :)

I wish all of you to have a lovely week.
Sincerely, Thomas

[jzheaux]

Hi, @ThomasHagelberg, thanks for the suggestion. I agree that the logging should be more helpful by including the exception in the logs.

I think it should stay at DEBUG, though. Most of Spring Security's error-handling logging is at the DEBUG and TRACE levels since they may contain sensitive information. It's also true that we don't want to fill up your logs unnecessarily, and it's quite a bit easier for an application to temporarily turn up the logging level than it is to squash a logging message from Spring Security that it doesn't want to see.

Are you able to provide a PR to include the causing exception in the authentication failure log in AuthenticationWebFilter?

[ThomasHagelberg]

Hi and thanks for your answer @jzheaux. I will try to get a PR sorted.

[spring-projects-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[ThomasHagelberg]

Hi and sorry for asking @jzheaux, do you want the thrown exception message to be changed to what is originally thrown:

Or do you simply want the causing exception to be logged (in a proper way)?

Or do you want me to check what exception is thrown in JwtReactiveAuthenticationManager, and have some specific flow based on that?

[jzheaux]

No problem, @ThomasHagelberg! Thanks for asking.

I was thinking that we should add the causing exception to this line.

So:

(ex) -> logger.debug(LogMessage.format("Authentication failed: %s", ex.getMessage())));

would change to

(ex) -> logger.debug(LogMessage.format("Authentication failed: %s", ex.getMessage()), ex));

This would make so that the reason for the failure isn't lost.

[ThomasHagelberg]

Lovely, thanks for the reply @jzheaux

This is how it would look now:

Is the output too much, or is it ok to setup a PR? If ok, do you want the commit message as:
"Improves logging in AuthenticationWebFilter
Closes #14091"

I'm checking the contributing guide, but your feedback would be appreciated.

[jzheaux]

Sorry for the delay, @ThomasHagelberg. Yes, that looks typical for a DEBUG log to me.

The only tweak I'd make to the commit message is that we usually use the infinitive like this: "Improve Logging ..." instead of "Improves Logging ..."

[ThomasHagelberg]

Hi @jzheaux!

I apologize for the delay in opening the PR, I have been busy with new and different programming concepts recently. However, I'm now turning my attention back to the OIDC project. Wishing you a pleasant weekend in the meantime! :)