<div dir="ltr">Context:<div>- Setting up a NativeSP against an IDP-Initiated-only server (out of my control).</div><div>- Apache2.2, mod-shib 2.3 &amp; 2.4 tested, same end result (mpm-prefork).</div><div><br></div><div>About 70% of the time, a session initiates cleanly:</div><div><br></div><div><div>2014-12-11 02:04:50 DEBUG XMLTooling.StorageService [12]: inserted record (session) in context (_87ec0cc30f106cc6a9d28b7472075454) with expiration (1418267090)</div><div>2014-12-11 02:04:50 DEBUG XMLTooling.StorageService [12]: updated record (testcc13) in context (NameID) with expiration (1418292290)</div><div>2014-12-11 02:04:50 DEBUG XMLTooling.StorageService [12]: inserted record (Nu.59rXxpHP9IPu7DESRinv0lZC) in context (_87ec0cc30f106cc6a9d28b7472075454) with expiration (1418267090)</div><div>2014-12-11 02:04:50 INFO Shibboleth.SessionCache [12]: new session created: ID (_87ec0cc30f106cc6a9d28b7472075454) IdP (XYZ) Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address (10.157.50.61)</div><div>2014-12-11 02:04:50 INFO Shibboleth.SessionCache [12]: cookieBadness((null)): 27076856; _87ec0cc30f106cc6a9d28b7472075454; path=/</div><div>2014-12-11 02:04:50 DEBUG Shibboleth.SSO.SAML2 [12]: ACS returning via redirect to: <a href="https://qa1.climate.com/sso/">https://qa1.climate.com/sso/</a></div><div>2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message (default::getHeaders::Application)</div><div>2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext3 (ID: _87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267090; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267090; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454) to (1418267091)</div><div>2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message (touch::StorageService::SessionCache)</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified version 1</div><div>2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID: _87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454) to (1418267091)</div><div>2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message (touch::StorageService::SessionCache)</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified version 1</div><div>2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID: _87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454) to (1418267091)</div><div>2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message (touch::StorageService::SessionCache)</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified version 1</div><div>2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID: _87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454) to (1418267091)</div><div>2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message (touch::StorageService::SessionCache)</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified version 1</div><div>2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID: _87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263491; 1418267091; 1418267091</div><div>2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454) to (1418267091)</div><div><br></div><div>==&gt; /var/log/shibboleth/transaction.log &lt;==</div><div>2014-12-11 02:04:50 INFO Shibboleth-TRANSACTION [12]: New session (ID: _87ec0cc30f106cc6a9d28b7472075454) with (applicationId: default) for principal from (IdP: XYZ) at (ClientAddress: 10.157.50.61) with (NameIdentifier: testcc13) using (Protocol: urn:oasis:names:tc:SAML:2.0:protocol) from (AssertionID: Nu.59rXxpHP9IPu7DESRinv0lZC)</div><div>2014-12-11 02:04:50 INFO Shibboleth-TRANSACTION [12]: Cached the following attributes with session (ID: _87ec0cc30f106cc6a9d28b7472075454) for (applicationId: default) {</div><div>2014-12-11 02:04:50 INFO Shibboleth-TRANSACTION [12]: <span class="" style="white-space:pre">        </span>entity-id (1 values)</div><div>2014-12-11 02:04:50 INFO Shibboleth-TRANSACTION [12]: }</div></div><div><br></div><div><br></div><div>(Excuse some additional debugging statements I&#39;ve added to try and trace this);</div><div><br></div><div>Occasionally, the requests end up on different (connections? threads?), and those sessions get quickly aborted:</div><div><br></div><div><div>2014-12-11 02:04:56 DEBUG OpenSAML.MessageDecoder.SAML2 [11]: extracting issuer from SAML 2.0 protocol message</div><div>2014-12-11 02:04:56 DEBUG OpenSAML.MessageDecoder.SAML2 [11]: message from (XYZ)</div><div>2014-12-11 02:04:56 DEBUG OpenSAML.MessageDecoder.SAML2 [11]: searching metadata for message issuer...</div><div>2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [11]: evaluating message flow policy (replay checking on, expiration 60)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: Empty context</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record (tLxEvEggkAVMJopSxCwWfjIEUz4) in context (MessageFlow) with expiration (1418263735)</div><div>2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [11]: validating signature profile</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.TrustEngine.ExplicitKey [11]: attempting to validate signature with the peer&#39;s credentials</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.TrustEngine.ExplicitKey [11]: signature validated with credential</div><div>2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [11]: signature verified against message issuer</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: processing message against SAML 2.0 SSO profile</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: extracting issuer from SAML 2.0 assertion</div><div>2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [11]: evaluating message flow policy (replay checking on, expiration 60)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: Empty context</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record (tYf6nrCmh-.jYQZv5mYesIO04Y2) in context (MessageFlow) with expiration (1418263735)</div><div>2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.BearerConfirmation [11]: assertion satisfied bearer confirmation requirements</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: SSO profile processing completed successfully</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: extracting pushed attributes...</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.AttributeDecoder.String [11]: decoding SimpleAttribute (entity-id) from SAML 2 NameID with Format (urn:oasis:names:tc:SAML:2.0:nameid-format:entity)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.AttributeFilter [11]: filtering 1 attribute(s) from (XYZ)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.AttributeFilter [11]: applying filtering rule(s) for attribute (entity-id) from (XYZ)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: resolving attributes...</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.AttributeResolver.Query [11]: attempting SAML 2.0 attribute query</div><div>2014-12-11 02:04:56 WARN Shibboleth.AttributeResolver.Query [11]: no SAML 2 AttributeAuthority role found in metadata</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SessionCache [11]: creating new session</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: Empty context</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SessionCache [11]: storing new session...</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record (session) in context (_8ffdfea62caae74a5c1d22260859a983) with expiration (1418267096)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: updated record (testcc13) in context (NameID) with expiration (1418292296)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record (tYf6nrCmh-.jYQZv5mYesIO04Y2) in context (_8ffdfea62caae74a5c1d22260859a983) with expiration (1418267096)</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [11]: new session created: ID (_8ffdfea62caae74a5c1d22260859a983) IdP (XYZ) Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address (10.4.18.99)</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [11]: cookieBadness((null)): 28164792; _8ffdfea62caae74a5c1d22260859a983; path=/</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: ACS returning via redirect to: <a href="https://qa1.climate.com/sso/">https://qa1.climate.com/sso/</a></div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: UpdateContext3 (ID: _8ffdfea62caae74a5c1d22260859a983); 1418263496; 3600</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263496; 1418267096; 1418267096</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Record expiration: 1418263496; 1418267096; 1418267096</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: updated expiration of valid records in context (_8ffdfea62caae74a5c1d22260859a983) to (1418267096)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (remove::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: remove session:: (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: removed session (_8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message (find::StorageService::SessionCache)</div><div>2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context</div><div>2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div><br></div><div>==&gt; /var/log/shibboleth/transaction.log &lt;==</div><div>2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [11]: New session (ID: _8ffdfea62caae74a5c1d22260859a983) with (applicationId: default) for principal from (IdP: XYZ) at (ClientAddress: 10.4.18.99) with (NameIdentifier: testcc13) using (Protocol: urn:oasis:names:tc:SAML:2.0:protocol) from (AssertionID: tYf6nrCmh-.jYQZv5mYesIO04Y2)</div><div>2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [11]: Cached the following attributes with session (ID: _8ffdfea62caae74a5c1d22260859a983) for (applicationId: default) {</div><div>2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [11]: <span class="" style="white-space:pre">        </span>entity-id (1 values)</div><div>2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [11]: }</div><div>2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [12]: Destroyed session (applicationId: default) (ID: _8ffdfea62caae74a5c1d22260859a983)</div><div><br></div></div><div><br></div><div>Such that by the time the redirect occurs, shibd&#39;s expired the session (presumably) and can no longer look up the attribute.</div><div><br></div><div>In all cases, the NotBefore and NotAfter are well spread around the time of the incident, and my ability to keep tracing this seems to have hit a wall, as I can&#39;t readily identify any /cause/ of the session being removed, and my best guess (some undocumented/hard-to-find cache race condition) isn&#39;t proving out in any obvious way.</div><div><br></div><div>The only distinction I can readily find (other than the obvious termination of a session) seems to be whether the thread/pid/whatever ID stays constant through the transaction:</div><div><br></div><div><div>2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [<b>11</b>]: ACS returning via redirect to: <a href="https://qa1.climate.com/sso/">https://qa1.climate.com/sso/</a></div><div>2014-12-11 02:04:56 DEBUG Shibboleth.Listener [<b>12</b>]: dispatching message (find::StorageService::SessionCache)</div></div><div><br></div><div>If they don&#39;t match, *kerpow*.</div><div><br></div><div>At this point I&#39;m inclined to push back to at least enable SP-initiated support so in the broken session case I can at least retry the session setup, but wanted to reach out and see if anyone has any bright ideas on this particular one.  (Due to the age of the system, testing 2.5 is non-trivial in my environment).</div><div><br></div><div>(Currently using the in-memory cache, tried briefly w/ memcache, no visible improvement;  I&#39;m inclined to believe this is in IDP-initiated flows, but all the rest of my deployments are permitted IDP/SP initiated, so... add salt as desired).</div><div><br></div><div>Thanks for any thoughts,</div><div><br></div><div>James D. Nurmi</div><div><br></div><div><br></div></div>