Spring-security-oauth: 2.2.1 introduces error logging for each bad credential error - please revise

Created on 20 Jan 2018 · 11Comments · Source: spring-projects/spring-security-oauth

We try to have only real errors in our log file on error level. this can be temporary errors like db connection issues or permanent errors which could be probably a bug in our system. errors produced by bad requests from the client (e.g. bad credentials, bad requests, 4xx HTTP errors) should not be logged on error level.
With 2.2.1 all ClientAuthenticationExceptions are logged on error level and with stacktrace attached. this can lead to a very high volume of log entries. Please revise this change. Thanks!

enhancement

Source

gbrehmer

Most helpful comment

@gbrehmer After re-visiting this, I agree the logging was set too high of a severity level. I've adjusted it via 3148a7d. Changed to warn level and one of them to info, all without the Exception to avoid the stacktrace flooding the log. This will go into the upcoming 2.3 release.

jgrandja on 1 Feb 2018

👍4

All 11 comments

@gbrehmer Are you referring to this commit and associated issue #1232?

jgrandja on 22 Jan 2018

Yes :)

gbrehmer on 22 Jan 2018

@gbrehmer The changes in this commit makes sense given that the methods that are logging are @ExceptionHandler methods and therefore should log to error instead of info which it was doing previous to this change. You can always adjust the logging level in your logging configuration if you don't want to see errors.
Closing this issue and leaving things as is.

jgrandja on 24 Jan 2018

Please discuss this change a little more :)
I think most of the applications have set warn or error level as root / default log level in production. So each of them now have tons of loglines about bad requests including long stacktraces from clients in their logfile after bugfix version update. Now we can not distinguish between real error situations like unexpected situations. wrong credentials are expected situations. In the mentioned commit I did not find any arguments, why this change is absolutely needed. Prior this change you are able to opt-in this log messages by enable the info log level for TokenEndpoint. But now it is not possible for the user of the library to distinguish between client and server errors or expcted and unexpected errors. What would you say if ClientAuthenticationExceptions are handled by an additional exceptionhandler, which log his errors on debug or info level? I didn't have a full overview about the matching cases of each exception class. But exceptions usually raised as part of real world use cases of the API-usage should not be logged on error level.
Yes also client exceptions can indicate wrong API usage, which is important if client is developed by the same team or part of the same product. But I think this should be then part of a special opt-in logging configuration.

e.g.: InvalidGrantExceptions generated by ResourceOwnerPasswordTokenGranter

gbrehmer on 24 Jan 2018

I'm not in agreement with these comments...

errors produced by bad requests from the client (e.g. bad credentials, bad requests, 4xx HTTP errors) should not be logged on error level. With 2.2.1 all ClientAuthenticationExceptions are logged on error level and with stacktrace attached. this can lead to a very high volume of log entries...

Now we can not distinguish between real error situations like unexpected situations. wrong credentials are expected situations.

The Token Endpoint is a protected resource and therefore confidential clients must first authenticate with the Authorization Server in order to attempt to obtain an Access Token. Clients must be configured with the correct credentials or they will never get an access token. This may be a developer or configuration error in the application. I can appreciate that user's can accidentally enter their wrong password but when it comes to clients authenticating the configuration must be correct or nothing will work.

The fact that you say the log entries grow from bad requests from client (e.g. bad credentials) would be very suspicious to me and I would expect some kind of logging or alerting from the system as this very well could be a penetration happening to the system. What if a malicious user is attempting a "Credentials-Guessing Attack" would you not want this logged for further analysis? I definitely would and I'm sure the infosec team within your org would too.

The bottom line is that if your log is growing a lot from access to the Token Endpoint than it can result from at least these 2 reasons:

1) The Token Endpoint is not being used correctly by your OAuth clients. If this is the case than you need to correct this on the development and/or configuration end of things.

2) Or it's coming from an external user/system that may be maliciously trying to gain access to the system by attempting to get an access token, for example, a Credentials-Guessing Attacks

Hopefully this makes sense now? If you still do not agree than please provide the exact use cases that you do not agree with and an example of your log entry that you feel should not be logged.

jgrandja on 26 Jan 2018

We are using the password flow. Yes you can argue, that this flow should not be used for enduser interaction, but it’s one of the defaults from very popular jhipster framework and in our use case the most efficient one (no SSO between different sites required, only token based auth required with refresh token support).

example log message with 2.2.1 (client uses oauth/token endpoint):

[32m.[0m2018-01-20 07:50:58.799 ERROR 99 --- [tp1184694332-16,] o.s.s.o.provider.endpoint.TokenEndpoint  : Handling error: InvalidGrantException, Bad credentials

org.springframework.security.oauth2.common.exceptions.InvalidGrantException: Bad credentials
    at org.springframework.security.oauth2.provider.password.ResourceOwnerPasswordTokenGranter.getOAuth2Authentication(ResourceOwnerPasswordTokenGranter.java:79)
    at org.springframework.security.oauth2.provider.token.AbstractTokenGranter.getAccessToken(AbstractTokenGranter.java:70)
    at org.springframework.security.oauth2.provider.token.AbstractTokenGranter.grant(AbstractTokenGranter.java:65)
    at org.springframework.security.oauth2.provider.CompositeTokenGranter.grant(CompositeTokenGranter.java:38)
    at org.springframework.security.oauth2.config.annotation.web.configurers.AuthorizationServerEndpointsConfigurer$4.grant(AuthorizationServerEndpointsConfigurer.java:561)
    at org.springframework.security.oauth2.provider.CompositeTokenGranter.grant(CompositeTokenGranter.java:38)
    at org.springframework.security.oauth2.provider.endpoint.TokenEndpoint.postAccessToken(TokenEndpoint.java:132)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1650)
    at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:111)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:206)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:96)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:215)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.oauth2.provider.client.ClientCredentialsTokenEndpointFilter.successfulAuthentication(ClientCredentialsTokenEndpointFilter.java:131)
    at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:240)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at xxx.config.logging.HttpErrorFilter.doFilterInternal(HttpErrorFilter.java:27)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at xxx.logging.AppVersionMdcLoggerFilter.doFilterInternal(AppVersionMdcLoggerFilter.java:52)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
    at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:241)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
    at org.eclipse.jetty.server.Server.handle(Server.java:561)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:334)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:104)
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
    at java.lang.Thread.run(Thread.java:745)

gbrehmer on 30 Jan 2018

As per spec in Section 5.2 Error Response, it states:

invalid_grant
The provided authorization grant (e.g., authorization
code, resource owner credentials) or refresh token is
invalid, expired, revoked, does not match the redirection
URI used in the authorization request, or was issued to
another client.

In your scenario, the authorization grant is the resource owner credentials and so if it's invalid than the AuthenticationManager will throw a BadCredentialsException and the error response returned would contain invalid_grant as the error_code. This is the expected behaviour and is a client error.

You mentioned that the log grows quite a bit so this would be alarming to me as the first thing I would suspect is a Credentials-Guessing Attack of user credentials and I would expect this to be logged so the internal monitoring system would pick these log entries up and trigger some kind of alert.

jgrandja on 31 Jan 2018

We can not use 2.2.1 in production because of this change, so our findings based on integration test results.
Login errors are already monitored by checking HTTP response status code statistics from individual endpoints. There is a normal volume of wrong credential errors, because of typos or e.g. user tries accidentally credentials from another system. Each of these cases should not be generate an security alert, because they are false positives. I assume that like me you also sometimes make typos in your username and password. So these calls are not part of any attack.
So for us an alarming level is reached, if there are unnormal peaks or the "background noise of auth exceptions" ( = http status code from token-endpoint) is bumped to another level which can not be argued by an increasing user base. But to get this information, we don't need 100 lines of log per case. The only solution we currently have is to disable the TokenEndpoint logger.

gbrehmer on 31 Jan 2018

You mentioned ...