spring-projects / spring-security

Spring Security
http://spring.io/projects/spring-security
Apache License 2.0
8.82k stars 5.9k forks source link

Improve logging in NimbusReactiveJwtDecoder #14091

Closed ThomasHagelberg closed 7 months ago

ThomasHagelberg commented 1 year ago

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:

Artifacts:

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

image

image

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 commented 11 months ago

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 commented 11 months ago

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

spring-projects-issues commented 10 months ago

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 commented 10 months ago

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

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

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

jzheaux commented 10 months ago

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 commented 10 months ago

Lovely, thanks for the reply @jzheaux

This is how it would look now: image

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 commented 9 months ago

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 commented 8 months ago

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! :)