[
https://issues.apache.org/jira/browse/AMBARI-25127?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16809915#comment-16809915
]
Sean Roberts commented on AMBARI-25127:
---------------------------------------
Robert - Correct. The act of turning it on doesn't cause the flooding. It's
that any authentication that happens results in this large amount of extra
logging. There should be nothing related to SPNEGO logged unless the
browser "Negotiates" to use SPNEGO. And even then it shouldn't give a whole
stackTrace for a failed authentication.
> ambari-server.log flooded if client not able to authenticate through kerberos
> -----------------------------------------------------------------------------
>
> Key: AMBARI-25127
> URL: https://issues.apache.org/jira/browse/AMBARI-25127
> Project: Ambari
> Issue Type: Bug
> Components: ambari-server
> Affects Versions: 2.7.3
> Reporter: Sean Roberts
> Assignee: amarnath reddy pappu
> Priority: Major
>
> With SPNEGO enabled for Ambari-Server, ambari-server.log is flooded with
> every auth failure. _(See log output below)_.
> This is making ambari-server.log impossible to review and fills rapidly.
> REQUEST: ambari-server.log should not contain auth failures, especially not
> full traces of them. JWT items should also likely be exluded from
> ambari-server.log.
> More detail:
> - on every unauthenticated page load, Ambari makes the client attempt to auth
> with Kerberos "negotiate".
> - if that fails it falls back to other authentication mechanisms (user/pass
> prompt or knoxsso).
> - however, each of those failed auths results in this huge amount of logs in
> `ambari-server`.log.
> - for a failed or successful auth, the only log should be a single line in
> `ambari-audit.log`
> ambari-server.log: *1 second* from a single client on a new Ambari. Imagine
> this on a busy ambari-server (scroll within the code block to see the big
> kerberos error).
> {code}
> 2019-01-24 04:46:02,749 INFO [ambari-client-thread-260388]
> AmbariJwtAuthenticationFilter:265 - hadoop-jwt cookie has been found and is
> being processed
> 2019-01-24 04:46:02,749 INFO [ambari-client-thread-260388]
> AmbariJwtAuthenticationFilter:265 - hadoop-jwt cookie has been found and is
> being processed
> 2019-01-24 04:46:02,750 INFO [ambari-client-thread-260388]
> AmbariJwtAuthenticationFilter:265 - hadoop-jwt cookie has been found and is
> being processed
> 2019-01-24 04:46:02,750 WARN [ambari-client-thread-260388]
> AmbariJwtAuthenticationFilter:399 - JWT expiration date validation failed.
> 2019-01-24 04:46:02,750 INFO [ambari-client-thread-260388]
> AmbariJwtAuthenticationFilter:294 - Expiration validation failed.
> 2019-01-24 04:46:02,750 WARN [ambari-client-thread-260388]
> AmbariJwtAuthenticationFilter:201 - JWT authentication failed - Invalid JWT
> token
> 2019-01-24 04:46:02,750 INFO [ambari-client-thread-260388]
> AmbariAuthenticationEventHandlerImpl:136 - Failed to authenticate an unknown
> user: Invalid JWT token
> 2019-01-24 04:46:02,756 WARN [ambari-client-thread-259406]
> AmbariKerberosAuthenticationFilter:149 - Negotiate Header was invalid:
> Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==
> org.springframework.security.authentication.BadCredentialsException: Kerberos
> validation not successful
> at
> org.springframework.security.kerberos.authentication.sun.SunJaasKerberosTicketValidator.validateTicket(SunJaasKerberosTicketValidator.java:71)
> at
> org.apache.ambari.server.security.authentication.kerberos.AmbariKerberosTicketValidator.validateTicket(AmbariKerberosTicketValidator.java:85)
> at
> org.apache.ambari.server.security.authentication.kerberos.AmbariKerberosAuthenticationProvider.authenticate(AmbariKerberosAuthenticationProvider.java:73)
> at
> org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:174)
> at
> org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:199)
> at
> org.springframework.security.config.annotation.web.configuration.WebSecurityConfigurerAdapter$AuthenticationManagerDelegator.authenticate(WebSecurityConfigurerAdapter.java:494)
> at
> org.springframework.security.kerberos.web.authentication.SpnegoAuthenticationProcessingFilter.doFilter(SpnegoAuthenticationProcessingFilter.java:145)
> at
> org.apache.ambari.server.security.authentication.kerberos.AmbariKerberosAuthenticationFilter.doFilter(AmbariKerberosAuthenticationFilter.java:179)
> at
> org.apache.ambari.server.security.authentication.AmbariDelegatingAuthenticationFilter.doFilter(AmbariDelegatingAuthenticationFilter.java:123)
> at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
> at
> org.apache.ambari.server.security.authorization.AmbariUserAuthorizationFilter.doFilter(AmbariUserAuthorizationFilter.java:95)
> 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:66)
> 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:1642)
> at
> org.apache.ambari.server.api.MethodOverrideFilter.doFilter(MethodOverrideFilter.java:73)
> at
> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
> at
> org.apache.ambari.server.api.AmbariPersistFilter.doFilter(AmbariPersistFilter.java:53)
> at
> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
> at
> org.apache.ambari.server.security.AbstractSecurityHeaderFilter.doFilter(AbstractSecurityHeaderFilter.java:130)
> at
> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
> at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:51)
> at
> org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
> at
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
> at
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
> 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:257)
> at
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
> at
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
> at
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1340)
> at
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
> 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:201)
> at
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1242)
> at
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
> at
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:740)
> at
> org.apache.ambari.server.controller.AmbariHandlerList.processHandlers(AmbariHandlerList.java:221)
> at
> org.apache.ambari.server.controller.AmbariHandlerList.processHandlers(AmbariHandlerList.java:210)
> at
> org.apache.ambari.server.controller.AmbariHandlerList.handle(AmbariHandlerList.java:140)
> at
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
> at org.eclipse.jetty.server.Server.handle(Server.java:503)
> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
> at
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
> at
> org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
> at
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:411)
> at
> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:305)
> at
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
> at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
> at
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.security.PrivilegedActionException: GSSException: Defective
> token detected (Mechanism level: GSSHeader did not find the right tag)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:422)
> at
> org.springframework.security.kerberos.authentication.sun.SunJaasKerberosTicketValidator.validateTicket(SunJaasKerberosTicketValidator.java:68)
> ... 71 more
> Caused by: GSSException: Defective token detected (Mechanism level: GSSHeader
> did not find the right tag)
> at sun.security.jgss.GSSHeader.<init>(GSSHeader.java:97)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:306)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:285)
> at
> org.springframework.security.kerberos.authentication.sun.SunJaasKerberosTicketValidator$KerberosValidateAction.run(SunJaasKerberosTicketValidator.java:170)
> at
> org.springframework.security.kerberos.authentication.sun.SunJaasKerberosTicketValidator$KerberosValidateAction.run(SunJaasKerberosTicketValidator.java:153)
> ... 74 more
> 2019-01-24 04:46:02,756 INFO [ambari-client-thread-259406]
> AmbariAuthenticationEventHandlerImpl:136 - Failed to authenticate an unknown
> user: Kerberos validation not successful
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
