SLO session lookup failure

[Julian Williams]

Dear all,

I'd appreciate some more help with this problem that is still ongoing
(thanks to all who have helped so far). This is the same problem as
discussed in my previous thread "Transientid and session timeout" but
I've changed the subject to reflect the actual problem (since we've been
enlightened that Transientid and possibly also session timeout are not
significant to the problem).

To recap, we get a repeatable SessionNotFound error during SLO when it
happens after 30min of inactivity.

To give a bit of context, SLO has not been something that we have
supported in the past but it is now being used in connection with our
migration of email to Office365 and the "sign out" button that appears
in most of the MS portals. SLO then happens via our ADFS 4 service which
then sends a SAML logout request to our Shibboleth IdP (which is acting
in the role of claims provider to the ADFS service). This normally works
fine, at least clearing the sessions out from ADFS and the Shib IdP but
if this is attempted 30min after the login it fails at the IdP which
then reports the error back to ADFS which presents it as a rather
unhelpful error message to the user.

An example of errors logged in the idp-process.log is below:

2018-02-20 16:08:50,115 - DEBUG
[net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:144] -
Profile Action ExtractSubjectFromRequest: No Subject
NameID/NameIdentifier in message needs inbound processing
2018-02-20 16:08:50,278 - DEBUG
[net.shibboleth.idp.session.impl.StorageBackedSessionManager:743] -
Performing secondary lookup on service ID
http://sts-stg.fed.ox.ac.uk/adfs/services/trust and key
lfy/VcLhM1E7V4PZEF3FlUvt3DA=
2018-02-20 16:08:50,279 - DEBUG
[net.shibboleth.idp.session.impl.StorageBackedSessionManager:765] -
Secondary lookup failed on service ID
http://sts-stg.fed.ox.ac.uk/adfs/services/trust and key
lfy/VcLhM1E7V4PZEF3FlUvt3DA=
2018-02-20 16:08:50,279 - INFO
[net.shibboleth.idp.saml.saml2.profile.impl.ProcessLogoutRequest:315] -
Profile Action ProcessLogoutRequest: No active session(s) found matching
LogoutRequest
2018-02-20 16:08:50,306 - WARN
[org.opensaml.profile.action.impl.LogEvent:76] - An error event occurred
while processing the request: SessionNotFound


This error doesn't happen if a SLO is attempted under 30min after the
initial login.

However, if we bounce the test IdP in between the authentication and the
logout request, we see the error straight away (e.g. <5min after login).
This still seems to point to an issue with server side session storage
even though we have configured our IdP to use client side session
storage. So that is strange.

We have compared the SAML logout request provided by ADFS (as logged in
the IdP log) for both a success & failure case and we can't see anything
wrong with the request that ADFS is providing.

This is an example of what we see for a success case:

2018-02-20 15:16:13,029 - DEBUG [PROTOCOL_MESSAGE:121] -
<?xml version="1.0" encoding="UTF-8"?>
<samlp:LogoutRequest
    Consent="urn:oasis:names:tc:SAML:2.0:consent:unspecified"

Destination="https://idp.iamtest.ox.ac.uk/idp/profile/SAML2/Redirect/SLO"
    ID="_2c434375-f900-4e5e-9528-84cf9043f798"
    IssueInstant="2018-02-20T15:16:12.079Z" Version="2.0"
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol">
    <Issuer
xmlns="urn:oasis:names:tc:SAML:2.0:assertion">http://sts-stg.fed.ox.ac.uk/adfs/services/trust</Issuer>
    <NameID
        Format="urn:oasis:names:tc:SAML:2.0:nameid-format:persistent"
        NameQualifier="https://idp.iamtest.ox.ac.uk/shibboleth"

SPNameQualifier="http://sts-stg.fed.ox.ac.uk/adfs/services/trust"
xmlns="urn:oasis:names:tc:SAML:2.0:assertion">lfy/VcLhM1E7V4PZEF3FlUvt3DA=</NameID>

<samlp:SessionIndex>_fde11f4aed98c52877f1dfb2b6d50908</samlp:SessionIndex>
</samlp:LogoutRequest>


And this is an example of a failure case:


2018-02-20 16:08:49,863 - DEBUG [PROTOCOL_MESSAGE:121] -
<?xml version="1.0" encoding="UTF-8"?>
<samlp:LogoutRequest
    Consent="urn:oasis:names:tc:SAML:2.0:consent:unspecified"

Destination="https://idp.iamtest.ox.ac.uk/idp/profile/SAML2/Redirect/SLO"
    ID="_d88843d6-3154-4e6e-bfff-2c98562c8617"
    IssueInstant="2018-02-20T16:08:49.782Z" Version="2.0"
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol">
    <Issuer
xmlns="urn:oasis:names:tc:SAML:2.0:assertion">http://sts-stg.fed.ox.ac.uk/adfs/services/trust</Issuer>
    <NameID
        Format="urn:oasis:names:tc:SAML:2.0:nameid-format:persistent"
        NameQualifier="https://idp.iamtest.ox.ac.uk/shibboleth"

SPNameQualifier="http://sts-stg.fed.ox.ac.uk/adfs/services/trust"
xmlns="urn:oasis:names:tc:SAML:2.0:assertion">lfy/VcLhM1E7V4PZEF3FlUvt3DA=</NameID>

<samlp:SessionIndex>_b0e2c2ac3add4cc63bc05e90fb4f13f9</samlp:SessionIndex>
</samlp:LogoutRequest>


In both cases we have checked that the SessionIndex matches that
provided by the IdP in the AuthnStatement contained within the SAML
assertion sent to ADFS after the login.

Currently we have the following timeouts set in idp.properties but none
of these seem to change the time at which the SLO error starts occurring:

idp.session.timeout = PT8H
idp.session.slop = PT8H
idp.session.defaultSPlifetime = PT8H


How should we go about looking at this problem further?

Even though we have the IdP logging turned up we don't seem to have much
in the IdP logs about the session data it is retrieving from the client
side and so why the session lookup is failing. Is there a way we can get
more debug for this? Perhaps there is something in our session cache's
storage configuration that needs tweaking to affect this behaviour. Any
suggestions please?


Thanks in advance.


Julian



-- 
Julian Williams (Systems Developer, Identity and Access Management)
IT Services, University of Oxford