| Summary: | SPNEGO auth failures are leading to stack trace prints of PrivilegedActionExceptions | ||
|---|---|---|---|
| Product: | Tomcat 7 | Reporter: | Arunav Sanyal <arunav.sanyal91> |
| Component: | Catalina | Assignee: | Tomcat Developers Mailing List <dev> |
| Status: | RESOLVED FIXED | ||
| Severity: | normal | ||
| Priority: | P2 | ||
| Version: | 7.0.53 | ||
| Target Milestone: | --- | ||
| Hardware: | PC | ||
| OS: | All | ||
| Attachments: | GNU Unified diff format of proposed fix | ||
A stack trace to see what exactly is going on here would be helpful. I suspect, to be safe, we'll only want to log at debug if the cause of the PrivilegedActionException is an instance of GSSException. Thanks Mark Here is an example stack trace from our installation of tomcat along with a few of our webapps defined. Node is starting in kerberos mode. 2014-Jan-30 13:26:24.074 Starting Tomcat on HTTP port [64960]. [2014-Jan-30 13:26:24.241] Domain service init method is called. [2014-Jan-30 13:26:44.916] Enabling master Core services. [2014-Jan-30 13:26:44.925] Domain Configuration service init method is called. [2014-Jan-30 13:26:47.015] Log service init method is called. [2014-Jan-30 13:26:47.081] User Management service init method is called. [2014-Jan-30 13:26:48.500] Edr service init method is called. [2014-Jan-30 13:26:49.760] Called the alert domain function init method. [2014-Jan-30 13:26:49.888] Licensing service init method is called. [2014-Jan-30 13:26:50.014] Monitoring service init method is called. [2014-Jan-30 13:26:50.105] Plugin Registry service init method is called. [2014-Jan-30 13:26:50.121] Master Core services enabled. [2014-Jan-30 13:26:50.728] LogServiceAgent init method is called. Jan 31, 2014 4:16:59 PM org.apache.catalina.authenticator.SpnegoAuthenticator authenticate SEVERE: Unable to login as the service principal javax.security.auth.login.LoginException: Clock skew too great (37) at com.sun.security.auth.module.Krb5LoginModule.attemptAuthentication(Krb5LoginModule.java:763) at com.sun.security.auth.module.Krb5LoginModule.login(Krb5LoginModule.java:584) at sun.reflect.GeneratedMethodAccessor224.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at javax.security.auth.login.LoginContext.invoke(LoginContext.java:784) at javax.security.auth.login.LoginContext.access$000(LoginContext.java:203) at javax.security.auth.login.LoginContext$4.run(LoginContext.java:698) at javax.security.auth.login.LoginContext$4.run(LoginContext.java:696) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:695) at javax.security.auth.login.LoginContext.login(LoginContext.java:594) at org.apache.catalina.authenticator.SpnegoAuthenticator.authenticate(SpnegoAuthenticator.java:214) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:574) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:603) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744) Caused by: KrbException: Clock skew too great (37) at sun.security.krb5.KrbKdcRep.check(KrbKdcRep.java:95) at sun.security.krb5.KrbAsRep.decrypt(KrbAsRep.java:159) at sun.security.krb5.KrbAsRep.decryptUsingKeyTab(KrbAsRep.java:121) at sun.security.krb5.KrbAsReqBuilder.resolve(KrbAsReqBuilder.java:288) at sun.security.krb5.KrbAsReqBuilder.action(KrbAsReqBuilder.java:364) at com.sun.security.auth.module.Krb5LoginModule.attemptAuthentication(Krb5LoginModule.java:735) ... 23 more Jan 31, 2014 4:16:59 PM org.apache.catalina.authenticator.SpnegoAuthenticator authenticate SEVERE: Unable to login as the service principal javax.security.auth.login.LoginException: Clock skew too great (37) at com.sun.security.auth.module.Krb5LoginModule.attemptAuthentication(Krb5LoginModule.java:763) at com.sun.security.auth.module.Krb5LoginModule.login(Krb5LoginModule.java:584) at sun.reflect.GeneratedMethodAccessor224.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at javax.security.auth.login.LoginContext.invoke(LoginContext.java:784) at javax.security.auth.login.LoginContext.access$000(LoginContext.java:203) at javax.security.auth.login.LoginContext$4.run(LoginContext.java:698) at javax.security.auth.login.LoginContext$4.run(LoginContext.java:696) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:695) at javax.security.auth.login.LoginContext.login(LoginContext.java:594) at org.apache.catalina.authenticator.SpnegoAuthenticator.authenticate(SpnegoAuthenticator.java:214) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:574) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:603) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744) Caused by: KrbException: Clock skew too great (37) at sun.security.krb5.KrbKdcRep.check(KrbKdcRep.java:95) at sun.security.krb5.KrbAsRep.decrypt(KrbAsRep.java:159) at sun.security.krb5.KrbAsRep.decryptUsingKeyTab(KrbAsRep.java:121) at sun.security.krb5.KrbAsReqBuilder.resolve(KrbAsReqBuilder.java:288) at sun.security.krb5.KrbAsReqBuilder.action(KrbAsReqBuilder.java:364) at com.sun.security.auth.module.Krb5LoginModule.attemptAuthentication(Krb5LoginModule.java:735) ... 23 more Yes you are right. It should be logged at debug only when its an instance of GSSException. However in practice I have seen any other underlying reason for PrivilegedActionException because the Actions can only throw GSSExceptions. Should I still go ahead and ascertain the cause and log only when underlying cause is GSSException. The previous comment indicated when loginexception is caught. I think that needs to be addressed as well. However for this particular issue an example would be:- May 06, 2014 3:22:56 PM org.apache.catalina.authenticator.SpnegoAuthenticator authenticate SEVERE: Unable to login as the service principal 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:415) at org.apache.catalina.authenticator.SpnegoAuthenticator.authenticate(SpnegoAuthenticator.java:242) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:573) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:315) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744) 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 sun.security.jgss.spnego.SpNegoContext.GSS_acceptSecContext(SpNegoContext.java:871) at sun.security.jgss.spnego.SpNegoContext.acceptSecContext(SpNegoContext.java:544) at sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:342) at sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:285) at org.apache.catalina.authenticator.SpnegoAuthenticator$AcceptAction.run(SpnegoAuthenticator.java:327) at org.apache.catalina.authenticator.SpnegoAuthenticator$AcceptAction.run(SpnegoAuthenticator.java:314) ... 14 more I think the LoginExceptions need to stay at error level. They indicate a general problem with SPNEGO auth and it is likely that any attempts to authenticate users will fail. The exceptions triggered by user login failures should be reduced to debug. I have applied a patch that should do this to 8.0.x for 8.0.7 onwards and to 7.0.x for 7.0.54 onwards. |
Created attachment 31620 [details] GNU Unified diff format of proposed fix In the event of a privilegedactionexception in SpnegoAuthenticator, the error is always logged. Hence the stack trace of the error always appears in catalina.out. This leads to spurious logs even when debugging is not enabled In the event of GSSException, its logged only when debugging is enabled. It is imperative to note that The privilegedactions are AcceptAction and action both of which only have the capacity to throw GSSException. Hence I am suggesting a fix which logs privileged action exception only when debugging is enabled in tomcat. This is added as an attachment and is a unified diff of the SpnegoAuthenticator before and after the change. Please let me know if you have any doubts about the fix or if you need a sample catalina.out highlighting the problem.