<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri",sans-serif;
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri",sans-serif;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal">Greetings All –<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Our environment (at the time of these errors) was as follows:<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Windows Server 2012 R2<o:p></o:p></p>
<p class="MsoNormal">Oracle Java Server JRE 8u92b14<o:p></o:p></p>
<p class="MsoNormal">Apache Tomcat 8.5.4<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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:<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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]<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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<o:p></o:p></p>
<p class="MsoNormal">net.shibboleth.utilities.java.support.logic.ConstraintViolationException: HttpSession cannot be null<o:p></o:p></p>
<p class="MsoNormal"> at net.shibboleth.utilities.java.support.logic.Constraint.isNotNull(Constraint.java:227)<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">2016-07-19 12:24:22,547 ERROR {https-jsse-nio-443-exec-22} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] java.lang.NullPointerException:76
<o:p></o:p></p>
<p class="MsoNormal">java.lang.NullPointerException: null<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">2016-07-19 12:24:22,547 ERROR {https-jsse-nio-443-exec-14} [,,] java.lang.RuntimeException:76
<o:p></o:p></p>
<p class="MsoNormal">java.lang.RuntimeException: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState@171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction@d41ddbc targetAction
= [EvaluateAction@2cdb0c49 expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction@247039e0 targetAction = [EvaluateAction@4679c0df expression = opensamlProfileRequestContext, resultExpression =
requestScope.profileRequestContext], attributes = map[[empty]]], [AnnotatedAction@45d65991 targetAction = [EvaluateAction@311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes
= map[[empty]]], [AnnotatedAction@14812cdc targetAction = [EvaluateAction@1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction@6b9bb165 targetAction
= [EvaluateAction@70d5aac expression = flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction@1af7615d targetAction = [EvaluateAction@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@345e7d9],
finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter@5e0b064e, outputMapper = [null]] is not a view state - programmer error<o:p></o:p></p>
<p class="MsoNormal"> at net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler.handle(RethrowingFlowExecutionExceptionHandler.java:40)<o:p></o:p></p>
<p class="MsoNormal">Caused by: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState@171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction@d41ddbc targetAction = [EvaluateAction@2cdb0c49
expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction@247039e0 targetAction = [EvaluateAction@4679c0df expression = opensamlProfileRequestContext, resultExpression = requestScope.profileRequestContext],
attributes = map[[empty]]], [AnnotatedAction@45d65991 targetAction = [EvaluateAction@311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes = map[[empty]]], [AnnotatedAction@14812cdc
targetAction = [EvaluateAction@1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction@6b9bb165 targetAction = [EvaluateAction@70d5aac expression
= flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction@1af7615d targetAction = [EvaluateAction@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@345e7d9],
finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter@5e0b064e, outputMapper = [null]] is not a view state - programmer error<o:p></o:p></p>
<p class="MsoNormal"> at org.springframework.webflow.engine.Flow.getCurrentViewState(Flow.java:633)<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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
<o:p></o:p></p>
<p class="MsoNormal">org.springframework.webflow.execution.repository.FlowExecutionRestorationFailureException: A problem occurred restoring the flow execution with key 'e1s1'<o:p></o:p></p>
<p class="MsoNormal"> at org.springframework.webflow.execution.repository.impl.DefaultFlowExecutionRepository.getFlowExecution(DefaultFlowExecutionRepository.java:113)<o:p></o:p></p>
<p class="MsoNormal">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?
<o:p></o:p></p>
<p class="MsoNormal"> at org.springframework.webflow.execution.repository.impl.SimpleFlowExecutionSnapshotGroup.getSnapshot(SimpleFlowExecutionSnapshotGroup.java:73)<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">2016-07-19 12:24:25,532 ERROR {https-jsse-nio-443-exec-8} [,XXX.XXX.XXX.XXX,B3E08A6789793B08F2BA17D5B20273AB] java.lang.RuntimeException:76
<o:p></o:p></p>
<p class="MsoNormal">java.lang.RuntimeException: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState@171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction@d41ddbc targetAction
= [EvaluateAction@2cdb0c49 expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction@247039e0 targetAction = [EvaluateAction@4679c0df expression = opensamlProfileRequestContext, resultExpression =
requestScope.profileRequestContext], attributes = map[[empty]]], [AnnotatedAction@45d65991 targetAction = [EvaluateAction@311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes
= map[[empty]]], [AnnotatedAction@14812cdc targetAction = [EvaluateAction@1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction@6b9bb165 targetAction
= [EvaluateAction@70d5aac expression = flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction@1af7615d targetAction = [EvaluateAction@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@345e7d9],
finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter@5e0b064e, outputMapper = [null]] is not a view state - programmer error<o:p></o:p></p>
<p class="MsoNormal"> at net.shibboleth.idp.profile.impl.RethrowingFlowExecutionExceptionHandler.handle(RethrowingFlowExecutionExceptionHandler.java:40)<o:p></o:p></p>
<p class="MsoNormal">Caused by: java.lang.IllegalStateException: You can only resume paused view states, and state [EndState@171ebeb7 id = 'ErrorView', flow = 'SAML2/Redirect/SSO', entryActionList = list[[AnnotatedAction@d41ddbc targetAction = [EvaluateAction@2cdb0c49
expression = environment, resultExpression = requestScope.environment], attributes = map[[empty]]], [AnnotatedAction@247039e0 targetAction = [EvaluateAction@4679c0df expression = opensamlProfileRequestContext, resultExpression = requestScope.profileRequestContext],
attributes = map[[empty]]], [AnnotatedAction@45d65991 targetAction = [EvaluateAction@311bac26 expression = T(net.shibboleth.utilities.java.support.codec.HTMLEncoder), resultExpression = requestScope.encoder], attributes = map[[empty]]], [AnnotatedAction@14812cdc
targetAction = [EvaluateAction@1c7669ab expression = flowRequestContext.getExternalContext().getNativeRequest(), resultExpression = requestScope.request], attributes = map[[empty]]], [AnnotatedAction@6b9bb165 targetAction = [EvaluateAction@70d5aac expression
= flowRequestContext.getExternalContext().getNativeResponse(), resultExpression = requestScope.response], attributes = map[[empty]]], [AnnotatedAction@1af7615d targetAction = [EvaluateAction@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@345e7d9],
finalResponseAction = org.springframework.webflow.action.ViewFactoryActionAdapter@5e0b064e, outputMapper = [null]] is not a view state - programmer error<o:p></o:p></p>
<p class="MsoNormal"> at org.springframework.webflow.engine.Flow.getCurrentViewState(Flow.java:633)<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">The Apache Tomcat access log for this particular event is as follows (SAMLRequest and client IP redacted):<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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 -<o:p></o:p></p>
<p class="MsoNormal">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<o:p></o:p></p>
<p class="MsoNormal">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 -<o:p></o:p></p>
<p class="MsoNormal">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 -<o:p></o:p></p>
<p class="MsoNormal">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 -<o:p></o:p></p>
<p class="MsoNormal">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 -<o:p></o:p></p>
<p class="MsoNormal">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 -<o:p></o:p></p>
<p class="MsoNormal">1969-12-31 17:59:59,00-1 INFO {https-jsse-nio-443-exec-22} [,-,-] - -1 "-" 500 –<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">If this is a conversation better suited to the developers list, I’d be happy to take it over there.
<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Best,<o:p></o:p></p>
<p class="MsoNormal">Michael Domingues<o:p></o:p></p>
<p class="MsoNormal">University of Iowa<o:p></o:p></p>
</div>
</body>
</html>