Transientid and session timeout

[Julian Williams]

Many thanks for everyone's help with this so far.

On 19/02/18 14:17, Cantor, Scott wrote:
>> So apart from idp.session.timeout, we are wondering what else is 
>> governing the session timeout?
> 
> There isn't any evidence the session has timed out, this is a logout
> issue, not a timeout issue.

OK. Point taken. Our theory that this was a timeout issue matched our
(limited) evidence with testing and we inferred wrongly that the logged
message matched our theory.

> 
>> We are using client side sessions and the transientid is, I
>> believe, used to identify these sessions.
> 
> The NameID, whatever it is, is what's used, and if it's not a
> Shibboleth SP, the usual reason is that it's not sending back the
> right NameID.

In our case the SP is ADFS. Whilst we could easily blame that we can now
see from the trace logs that ADFS returns a correct NameID but that it
is a persistent id, which is actually what our IdP provided it as a
NameID in the authentication response. Our current thinking is that this
is the route of our problem. In our environment the IdP won't be able to
lookup a session based on a persistent id as they are dynamically
created/non-reversible and we don't use a backend data store for
sessions. So perhaps we need to change our config so that we use the
trasient-id as a NameID for this particular SP.

> 
>> So we are wondering whether there is a 60min inherent timeout in
>> the transientids that we are using
> 
> Not relevant.

OK thanks for clearing that up. We were just guessing at that.

> 
>> there is a way that we can influence that? For instance is the 
>> transientid timeout governed by the idp.authn.defaultLifetime and
>> do we need to increase that to get an equivalent increase in the
>> transientid timeout?
> 
> It's not governed by that and it doesn't relate to this,
> authentication policy is not connected to the maintenance of data
> about SP sessions.
> 
> idp.session.defaultSPlifetime is really the core property governing
> this, bounded by the session timeout and slop values. The IdP doesn't
> know how long the SP will actually hold on to things, which makes it
> impossible in the general case to do anything but pick a number and
> use it.

OK. So idp.session.defaultSPlifetime which by default is 2 hours is
something we need to consider.

After testing this further yesterday (with logging set to trace) we now
realise that we get the SLO error much sooner than 60min. In fact we
think it is happening after 30min (of inactivity).

For a successful logout we get the following:

2018-02-20 06:52:10,153 - DEBUG
[net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:144] -
Profile Action ExtractSubjectFromRequest: No Subject
NameID/NameIdentifier in message needs inbound processing
2018-02-20 06:52:10,160 - 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 06:52:10,161 - DEBUG
[net.shibboleth.idp.session.impl.StorageBackedSessionManager:707] -
Performing primary lookup on session ID
0010d24617b34d39e7b1e2fb2d0cbffc106e46c4b733788041114fa5a4d12bd0
2018-02-20 06:52:10,168 - DEBUG
[net.shibboleth.idp.session.impl.StorageBackedIdPSession:607] - Loading
SPSession for service http://sts-stg.fed.ox.ac.uk/adfs/services/trust in
session 0010d24617b34d39e7b1e2fb2d0cbffc106e46c4b733788041114fa5a4d12bd0

So both the secondary & primary lookup are succeeding.

On a failure we get:

2018-02-19 15:06:59,096 - DEBUG
[net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:144] -
Profile Action ExtractSubjectFromRequest: No Subject
NameID/NameIdentifier in message needs inbound processing
2018-02-19 15:06:59,201 - 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-19 15:06:59,202 - 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-19 15:06:59,202 - INFO
[net.shibboleth.idp.saml.saml2.profile.impl.ProcessLogoutRequest:315] -
Profile Action ProcessLogoutRequest: No active session(s) found matching
LogoutRequest
2018-02-19 15:06:59,209 - WARN
[org.opensaml.profile.action.impl.LogEvent:76] - An error event occurred
while processing the request: SessionNotFound


So that seems to imply that the persistent-id is used as the secondary
lookup and that for a period of time that succeeds (we think 30min) and
thereafter it fails. So it looks like some of the session data is server
side and not all client side as we were assuming. This is on a single
node IdP where we are testing (our production environment has 3 nodes so
this is likely going to introduce more problems).



Cheers,
Julian


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