NativeSP, IDP-initiated, occasionally aborted flows.

Wed Dec 10 21:22:40 EST 2014

Context:
- Setting up a NativeSP against an IDP-Initiated-only server (out of my
control).
- Apache2.2, mod-shib 2.3 & 2.4 tested, same end result (mpm-prefork).

About 70% of the time, a session initiates cleanly:

2014-12-11 02:04:50 DEBUG XMLTooling.StorageService [12]: inserted record
(session) in context (_87ec0cc30f106cc6a9d28b7472075454) with expiration
(1418267090)
2014-12-11 02:04:50 DEBUG XMLTooling.StorageService [12]: updated record
(testcc13) in context (NameID) with expiration (1418292290)
2014-12-11 02:04:50 DEBUG XMLTooling.StorageService [12]: inserted record
(Nu.59rXxpHP9IPu7DESRinv0lZC) in context
(_87ec0cc30f106cc6a9d28b7472075454) with expiration (1418267090)
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)
2014-12-11 02:04:50 INFO Shibboleth.SessionCache [12]:
cookieBadness((null)): 27076856; _87ec0cc30f106cc6a9d28b7472075454; path=/
2014-12-11 02:04:50 DEBUG Shibboleth.SSO.SAML2 [12]: ACS returning via
redirect to: https://qa1.climate.com/sso/
2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message
(default::getHeaders::Application)
2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext3 (ID:
_87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267090; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267090; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated
expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454)
to (1418267091)
2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message
(touch::StorageService::SessionCache)
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified
version 1
2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID:
_87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated
expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454)
to (1418267091)
2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message
(touch::StorageService::SessionCache)
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified
version 1
2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID:
_87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated
expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454)
to (1418267091)
2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message
(touch::StorageService::SessionCache)
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified
version 1
2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID:
_87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated
expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454)
to (1418267091)
2014-12-11 02:04:51 DEBUG Shibboleth.Listener [12]: dispatching message
(touch::StorageService::SessionCache)
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Unmodified
version 1
2014-12-11 02:04:51 INFO Shibboleth.SessionCache [12]: UpdateContext4 (ID:
_87ec0cc30f106cc6a9d28b7472075454); 1418263491; 3600
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263491; 1418267091; 1418267091
2014-12-11 02:04:51 DEBUG XMLTooling.StorageService [12]: updated
expiration of valid records in context (_87ec0cc30f106cc6a9d28b7472075454)
to (1418267091)

==> /var/log/shibboleth/transaction.log <==
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)
2014-12-11 02:04:50 INFO Shibboleth-TRANSACTION [12]: Cached the following
attributes with session (ID: _87ec0cc30f106cc6a9d28b7472075454) for
(applicationId: default) {
2014-12-11 02:04:50 INFO Shibboleth-TRANSACTION [12]: entity-id (1 values)
2014-12-11 02:04:50 INFO Shibboleth-TRANSACTION [12]: }

(Excuse some additional debugging statements I've added to try and trace
this);

Occasionally, the requests end up on different (connections? threads?), and
those sessions get quickly aborted:

2014-12-11 02:04:56 DEBUG OpenSAML.MessageDecoder.SAML2 [11]: extracting
issuer from SAML 2.0 protocol message
2014-12-11 02:04:56 DEBUG OpenSAML.MessageDecoder.SAML2 [11]: message from
(XYZ)
2014-12-11 02:04:56 DEBUG OpenSAML.MessageDecoder.SAML2 [11]: searching
metadata for message issuer...
2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [11]:
evaluating message flow policy (replay checking on, expiration 60)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: Empty context
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record
(tLxEvEggkAVMJopSxCwWfjIEUz4) in context (MessageFlow) with expiration
(1418263735)
2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [11]:
validating signature profile
2014-12-11 02:04:56 DEBUG XMLTooling.TrustEngine.ExplicitKey [11]:
attempting to validate signature with the peer's credentials
2014-12-11 02:04:56 DEBUG XMLTooling.TrustEngine.ExplicitKey [11]:
signature validated with credential
2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [11]:
signature verified against message issuer
2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: processing message
against SAML 2.0 SSO profile
2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: extracting issuer from
SAML 2.0 assertion
2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [11]:
evaluating message flow policy (replay checking on, expiration 60)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: Empty context
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record
(tYf6nrCmh-.jYQZv5mYesIO04Y2) in context (MessageFlow) with expiration
(1418263735)
2014-12-11 02:04:56 DEBUG OpenSAML.SecurityPolicyRule.BearerConfirmation
[11]: assertion satisfied bearer confirmation requirements
2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: SSO profile processing
completed successfully
2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: extracting pushed
attributes...
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)
2014-12-11 02:04:56 DEBUG Shibboleth.AttributeFilter [11]: filtering 1
attribute(s) from (XYZ)
2014-12-11 02:04:56 DEBUG Shibboleth.AttributeFilter [11]: applying
filtering rule(s) for attribute (entity-id) from (XYZ)
2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: resolving attributes...
2014-12-11 02:04:56 DEBUG Shibboleth.AttributeResolver.Query [11]:
attempting SAML 2.0 attribute query
2014-12-11 02:04:56 WARN Shibboleth.AttributeResolver.Query [11]: no SAML 2
AttributeAuthority role found in metadata
2014-12-11 02:04:56 DEBUG Shibboleth.SessionCache [11]: creating new session
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: Empty context
2014-12-11 02:04:56 DEBUG Shibboleth.SessionCache [11]: storing new
session...
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record
(session) in context (_8ffdfea62caae74a5c1d22260859a983) with expiration
(1418267096)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: updated record
(testcc13) in context (NameID) with expiration (1418292296)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [11]: inserted record
(tYf6nrCmh-.jYQZv5mYesIO04Y2) in context
(_8ffdfea62caae74a5c1d22260859a983) with expiration (1418267096)
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)
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [11]:
cookieBadness((null)): 28164792; _8ffdfea62caae74a5c1d22260859a983; path=/
2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [11]: ACS returning via
redirect to: https://qa1.climate.com/sso/
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: UpdateContext3 (ID:
_8ffdfea62caae74a5c1d22260859a983); 1418263496; 3600
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263496; 1418267096; 1418267096
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Record
expiration: 1418263496; 1418267096; 1418267096
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: updated
expiration of valid records in context (_8ffdfea62caae74a5c1d22260859a983)
to (1418267096)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(remove::StorageService::SessionCache)
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: remove session::
(ID: _8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: removed session
(_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [12]: dispatching message
(find::StorageService::SessionCache)
2014-12-11 02:04:56 DEBUG XMLTooling.StorageService [12]: Empty context
2014-12-11 02:04:56 INFO Shibboleth.SessionCache [12]: Short circuit (ID:
_8ffdfea62caae74a5c1d22260859a983)

==> /var/log/shibboleth/transaction.log <==
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)
2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [11]: Cached the following
attributes with session (ID: _8ffdfea62caae74a5c1d22260859a983) for
(applicationId: default) {
2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [11]: entity-id (1 values)
2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [11]: }
2014-12-11 02:04:56 INFO Shibboleth-TRANSACTION [12]: Destroyed session
(applicationId: default) (ID: _8ffdfea62caae74a5c1d22260859a983)

Such that by the time the redirect occurs, shibd's expired the session
(presumably) and can no longer look up the attribute.

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't readily identify any /cause/ of the session being removed, and
my best guess (some undocumented/hard-to-find cache race condition) isn't
proving out in any obvious way.

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:

2014-12-11 02:04:56 DEBUG Shibboleth.SSO.SAML2 [*11*]: ACS returning via
redirect to: https://qa1.climate.com/sso/
2014-12-11 02:04:56 DEBUG Shibboleth.Listener [*12*]: dispatching message
(find::StorageService::SessionCache)

If they don't match, *kerpow*.

At this point I'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).

(Currently using the in-memory cache, tried briefly w/ memcache, no visible
improvement;  I'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).

Thanks for any thoughts,

James D. Nurmi
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20141210/8e474158/attachment-0001.html 