Bug 56523 - SPNEGO auth failures are leading to stack trace prints of PrivilegedActionExceptions
SPNEGO auth failures are leading to stack trace prints of PrivilegedActionExc...
Status: RESOLVED FIXED
Product: Tomcat 7
Classification: Unclassified
Component: Catalina
7.0.53
PC All
: P2 normal (vote)
: ---
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2014-05-14 09:54 UTC by Arunav Sanyal
Modified: 2014-05-14 21:36 UTC (History)
0 users



Attachments
GNU Unified diff format of proposed fix (697 bytes, text/plain)
2014-05-14 09:54 UTC, Arunav Sanyal
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Arunav Sanyal 2014-05-14 09:54:30 UTC
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.
Comment 1 Mark Thomas 2014-05-14 14:06:23 UTC
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.
Comment 2 Arunav Sanyal 2014-05-14 14:26:28 UTC
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.
Comment 3 Arunav Sanyal 2014-05-14 14:33:15 UTC
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
Comment 4 Mark Thomas 2014-05-14 21:36:15 UTC
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.