[ https://issues.apache.org/jira/browse/AMBARI-25127?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
amarnath reddy pappu reassigned AMBARI-25127: --------------------------------------------- Assignee: amarnath reddy pappu > 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)