HttpSession NullPointerException on Apache Tomcat 8.5.4

Mon Jul 25 11:25:55 EDT 2016

Greetings All -

Last week, after updating our production Shibboleth IdP cluster to the latest stable version of Apache Tomcat (8.5.4), we started receiving intermittent reports of clients encountering unhandled exceptions at the IdP while trying to log in to relying parties. These errors did not manifest during our testing due to the relatively light load on our test cluster. Over a twelve hour span of production operations, approximately 236 NullPointerExceptions were logged.

Once we were made aware of these issues, we upped our loggers to DEBUG, captured as much diagnostic information from production as possible, and then rolled back to Apache Tomcat 8.0.36.

Our environment (at the time of these errors) was as follows:

Windows Server 2012 R2
Oracle Java Server JRE 8u92b14
Apache Tomcat 8.5.4

These issues occurred intermittently, with no discernable pattern as to particular clients, times of day, or relying parties. However, they always occurred in/after net.shibboleth.idp.session.impl.UpdateSessionWithSPSession, when attempting to add a new SPsession. DEBUG level logs from the IdP process log are as follows:

2016-07-19 12:24:22,547 DEBUG {https-jsse-nio-443-exec-22} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] net.shibboleth.idp.session.impl.UpdateSessionWithSPSession:156 Profile Action UpdateSessionWithSPSession: Adding new SPSession for relying party [REDACTED] to existing session [REDACTED]

2016-07-19 12:24:22,547 ERROR {https-jsse-nio-443-exec-22} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] net.shibboleth.idp.saml.profile:-1 Uncaught runtime exception
net.shibboleth.utilities.java.support.logic.ConstraintViolationException: HttpSession cannot be null
                at net.shibboleth.utilities.java.support.logic.Constraint.isNotNull(Constraint.java:227)

2016-07-19 12:24:22,547 WARN  {https-jsse-nio-443-exec-22} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] org.opensaml.profile.action.impl.LogEvent:76 An error event occurred while processing the request: RuntimeException

2016-07-19 12:24:22,547 ERROR {https-jsse-nio-443-exec-22} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] java.lang.NullPointerException:76
java.lang.NullPointerException: null

2016-07-19 12:24:22,547 ERROR {https-jsse-nio-443-exec-14} [,,] java.lang.RuntimeException:76
java.lang.RuntimeException: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState at 171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction at d41ddbc targetAction = [EvaluateAction at 2cdb0c49 expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction at 247039e0 targetAction = [EvaluateAction at 4679c0df expression = opensamlProfileRequestContext, resultExpression = requestScope.profileRequestContext], attributes = map[[empty]]], [AnnotatedAction at 45d65991 targetAction = [EvaluateAction at 311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes = map[[empty]]], [AnnotatedAction at 14812cdc targetAction = [EvaluateAction at 1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction at 6b9bb165 targetAction = [EvaluateAction at 70d5aac expression = flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction at 1af7615d targetAction = [EvaluateAction at 35e37899 expression = flowRequestContext.getActiveFlow().getApplicationContext().containsBean('shibboleth.CustomViewContext') ? flowRequestContext.getActiveFlow().getApplicationContext().getBean('shibboleth.CustomViewContext') : null, resultExpression = requestScope.custom], attributes = map[[empty]]]], exceptionHandlerSet = list[net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler at 345e7d9], finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter at 5e0b064e, outputMapper = [null]] is not a view state - programmer error
                at net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler.handle(RethrowingFlowExecutionExceptionHandler.java:40)
Caused by: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState at 171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction at d41ddbc targetAction = [EvaluateAction at 2cdb0c49 expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction at 247039e0 targetAction = [EvaluateAction at 4679c0df expression = opensamlProfileRequestContext, resultExpression = requestScope.profileRequestContext], attributes = map[[empty]]], [AnnotatedAction at 45d65991 targetAction = [EvaluateAction at 311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes = map[[empty]]], [AnnotatedAction at 14812cdc targetAction = [EvaluateAction at 1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction at 6b9bb165 targetAction = [EvaluateAction at 70d5aac expression = flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction at 1af7615d targetAction = [EvaluateAction at 35e37899 expression = flowRequestContext.getActiveFlow().getApplicationContext().containsBean('shibboleth.CustomViewContext') ? flowRequestContext.getActiveFlow().getApplicationContext().getBean('shibboleth.CustomViewContext') : null, resultExpression = requestScope.custom], attributes = map[[empty]]]], exceptionHandlerSet = list[net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler at 345e7d9], finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter at 5e0b064e, outputMapper = [null]] is not a view state - programmer error
                at org.springframework.webflow.engine.Flow.getCurrentViewState(Flow.java:633)

2016-07-19 12:24:23,829 ERROR {https-jsse-nio-443-exec-3} [,XXX.XXX.XXX.XXX,FE24456F78C379F245B77804A89731D4] org.springframework.webflow.execution.repository.FlowExecutionRestorationFailureException:76
org.springframework.webflow.execution.repository.FlowExecutionRestorationFailureException: A problem occurred restoring the flow execution with key 'e1s1'
                at org.springframework.webflow.execution.repository.impl.DefaultFlowExecutionRepository.getFlowExecution(DefaultFlowExecutionRepository.java:113)
Caused by: org.springframework.webflow.execution.repository.snapshot.SnapshotNotFoundException: No flow execution snapshot could be found with id '1'; perhaps the snapshot has been removed?
                at org.springframework.webflow.execution.repository.impl.SimpleFlowExecutionSnapshotGroup.getSnapshot(SimpleFlowExecutionSnapshotGroup.java:73)

2016-07-19 12:24:25,532 ERROR {https-jsse-nio-443-exec-8} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] java.lang.RuntimeException:76
java.lang.RuntimeException: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState at 171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction at d41ddbc targetAction = [EvaluateAction at 2cdb0c49 expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction at 247039e0 targetAction = [EvaluateAction at 4679c0df expression = opensamlProfileRequestContext, resultExpression = requestScope.profileRequestContext], attributes = map[[empty]]], [AnnotatedAction at 45d65991 targetAction = [EvaluateAction at 311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes = map[[empty]]], [AnnotatedAction at 14812cdc targetAction = [EvaluateAction at 1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction at 6b9bb165 targetAction = [EvaluateAction at 70d5aac expression = flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction at 1af7615d targetAction = [EvaluateAction at 35e37899 expression = flowRequestContext.getActiveFlow().getApplicationContext().containsBean('shibboleth.CustomViewContext') ? flowRequestContext.getActiveFlow().getApplicationContext().getBean('shibboleth.CustomViewContext') : null, resultExpression = requestScope.custom], attributes = map[[empty]]]], exceptionHandlerSet = list[net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler at 345e7d9], finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter at 5e0b064e, outputMapper = [null]] is not a view state - programmer error
                at net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler.handle(RethrowingFlowExecutionExceptionHandler.java:40)
Caused by: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState at 171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction at d41ddbc targetAction = [EvaluateAction at 2cdb0c49 expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction at 247039e0 targetAction = [EvaluateAction at 4679c0df expression = opensamlProfileRequestContext, resultExpression = requestScope.profileRequestContext], attributes = map[[empty]]], [AnnotatedAction at 45d65991 targetAction = [EvaluateAction at 311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes = map[[empty]]], [AnnotatedAction at 14812cdc targetAction = [EvaluateAction at 1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction at 6b9bb165 targetAction = [EvaluateAction at 70d5aac expression = flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction at 1af7615d targetAction = [EvaluateAction at 35e37899 expression = flowRequestContext.getActiveFlow().getApplicationContext().containsBean('shibboleth.CustomViewContext') ? flowRequestContext.getActiveFlow().getApplicationContext().getBean('shibboleth.CustomViewContext') : null, resultExpression = requestScope.custom], attributes = map[[empty]]]], exceptionHandlerSet = list[net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler at 345e7d9], finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter at 5e0b064e, outputMapper = [null]] is not a view state - programmer error
                at org.springframework.webflow.engine.Flow.getCurrentViewState(Flow.java:633)

The Apache Tomcat access log for this particular event is as follows (SAMLRequest and client IP redacted):

2016-07-19 12:24:21,829 INFO  {https-jsse-nio-443-exec-17} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] XXX.XXX.XXX.XXX 443 "GET /idp/profile/SAML2/Redirect/SSO?SAMLRequest= [REDACTED] HTTP/1.1" 302 -
2016-07-19 12:24:21,844 INFO  {https-jsse-nio-443-exec-9} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] XXX.XXX.XXX.XXX 443 "GET /idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 200 4403
2016-07-19 12:24:21,891 INFO  {https-jsse-nio-443-exec-6} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] XXX.XXX.XXX.XXX 443 "GET /idp/bs-3.3.6/bootstrap.min.css HTTP/1.1" 304 -
2016-07-19 12:24:21,954 INFO  {https-jsse-nio-443-exec-22} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] XXX.XXX.XXX.XXX 443 "GET /idp/css/simple-login.css HTTP/1.1" 304 -
2016-07-19 12:24:22,016 INFO  {https-jsse-nio-443-exec-10} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] XXX.XXX.XXX.XXX 443 "GET /idp/bs-3.3.6/bootstrap.min.js HTTP/1.1" 304 -
2016-07-19 12:24:22,047 INFO  {https-jsse-nio-443-exec-7} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] XXX.XXX.XXX.XXX 443 "GET /idp/images/uiowa-dome.png HTTP/1.1" 304 -
2016-07-19 12:24:22,282 INFO  {https-jsse-nio-443-exec-22} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] XXX.XXX.XXX.XXX 443 "POST /idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 400 -
1969-12-31 17:59:59,00-1 INFO  {https-jsse-nio-443-exec-22} [,-,-] - -1 "-" 500 -

We made no changes to our IdP configuration during the Tomcat upgrade, and only updated Tomcat's server.xml to explicitly use the JSSE-based HTTP connector, to maintain parity with our Tomcat 8.0.36 deployment.

The Tomcat project is pushing users in the direction of the 8.5.X branch (advertising it as latest stable) and will no longer be updating the 8.0.X branch as of later this year. While they claim compatibility with the 8.0.X release branch, the 8.5.X branch is technically based on the 9.0 branch, which was then selectively rolled back to match 8.0.X while still including certain refactoring and new features.

At this point, I've about reached the limit my troubleshooting capabilities, being neither a Shibboleth developer, a Spring framework developer, nor a Tomcat project developer. Given that the issue could be coming from any of these three components, I figured I'd kick this one open to this list to see if anyone else has experienced these issues, and to make the Shibboleth developers aware of the problem. If I recall correctly, testing on Tomcat is less frequent and extensive than testing on Jetty.

If this is a conversation better suited to the developers list, I'd be happy to take it over there.

Best,
Michael Domingues
University of Iowa
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20160725/98832043/attachment-0001.html>