Shibboleth SP | Logout Intermittent Issues

Tue Mar 2 21:01:31 UTC 2021

Kshitij,

The logs are a little confusing the way you've supplied them.

The first one indicates that the SP doesn't find an existing session in the cache when logout is being called because it's been purged after 15 minutes elapsed(900 seconds), so it's falling back to the Local logout.

In the second log, I see no evidence that the user ever came back from the first authentication request.  No assertion is logged and no session is created.  It's just an AuthnRequest that was issued, logout for what I guess is a different session(and it seems to be attempting a local logout before doing a federated logout -- do you have <Logout>SAML2 Local</Logout> configured in shibboleth2.xml, or did you switch the order there?[1]), and then the marshalling of elements to issue another AuthnRequest.

What I'd really like to see is a coherent log from session creation to logout attempt, from beginning to end, of where it worked, and a second log where you can reproduce the issue, also end to end.

Sorry I can't help more with just this, and I hope you can get those logs,
Nate.

[1]: https://wiki.shibboleth.net/confluence/display/SP3/Logout

--------
Signet, Inc.
The Art of Access ®

https://www.signet.id

-----Original message-----
From: Chug, Kshitij (NIH/CIT) [C]
Sent: Tuesday, March 2 2021, 11:44 am
To: Nate Klingenstein; Shib Users
Subject: RE: Shibboleth SP | Logout Intermittent Issues

Thanks Nate for looking into this issue:

2021-02-28 16:53:10 DEBUG XMLTooling.StorageService [14] [default]: inserted record (session) in context (_b7da25c292ac8919557f0ab1b5525e1d) with expiration (1614550090)
2021-02-28 16:53:10 DEBUG XMLTooling.StorageService [14] [default]: updated record (1f0e1079-f355-4e5b-a547-24ca77388fac) in context (NameID) with expiration (1614550090)
2021-02-28 16:53:10 INFO Shibboleth.SessionCache [14] [default]: new session created: ID (_b7da25c292ac8919557f0ab1b5525e1d) IdP (https://idp.int.identitysandbox.gov/api/saml <https://idp.int.identitysandbox.gov/api/saml>) Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address (10.180.47.201)
2021-02-28 16:53:10 DEBUG Shibboleth.SSO.SAML2 [14] [default]: ACS returning via redirect to: https://federationdev.nih.gov/ShibAuth/initiatelogin?target=https%253A%252F%252Fniaidcrmsval%252Eniaid%252Enih%252Egov%252FNCRMS%252FMain%252FAuthLoginGov%252Easpx <https://federationdev.nih.gov/ShibAuth/initiatelogin?target=https%253A%252F%252Fniaidcrmsval%252Eniaid%252Enih%252Egov%252FNCRMS%252FMain%252FAuthLoginGov%252Easpx>
2021-02-28 16:53:10 DEBUG Shibboleth.Listener [14] [default]: dispatching message (find::StorageService::SessionCache)
2021-02-28 16:53:10 DEBUG XMLTooling.StorageService [14] [default]: updated expiration of valid records in context (_b7da25c292ac8919557f0ab1b5525e1d) to (1614550090)
2021-02-28 16:53:10 DEBUG Shibboleth.Listener [14] [default]: dispatching message (touch::StorageService::SessionCache)
2021-02-28 16:53:10 DEBUG XMLTooling.StorageService [14] [default]: updated expiration of valid records in context (_b7da25c292ac8919557f0ab1b5525e1d) to (1614550090)
2021-02-28 16:53:11 DEBUG Shibboleth.Listener [14] [default]: dispatching message (touch::StorageService::SessionCache)
2021-02-28 16:53:11 DEBUG XMLTooling.StorageService [14] [default]: updated expiration of valid records in context (_b7da25c292ac8919557f0ab1b5525e1d) to (1614550091)
2021-02-28 16:53:11 DEBUG Shibboleth.Listener [14] [default]: dispatching message (touch::StorageService::SessionCache)
2021-02-28 16:53:11 DEBUG XMLTooling.StorageService [14] [default]: updated expiration of valid records in context (_b7da25c292ac8919557f0ab1b5525e1d) to (1614550091)
2021-02-28 16:53:11 DEBUG Shibboleth.Listener [14] [default]: dispatching message (touch::StorageService::SessionCache)
2021-02-28 16:53:11 DEBUG XMLTooling.StorageService [14] [default]: updated expiration of valid records in context (_b7da25c292ac8919557f0ab1b5525e1d) to (1614550091)
2021-02-28 17:05:54 INFO XMLTooling.StorageService : purged 4 expired record(s) from storage
2021-02-28 17:08:16 DEBUG Shibboleth.Listener [14] [default]: dispatching message (remove::StorageService::SessionCache)
2021-02-28 17:08:16 INFO Shibboleth.SessionCache [14] [default]: removed session (_b7da25c292ac8919557f0ab1b5525e1d)
2021-02-28 17:08:16 DEBUG Shibboleth.Listener [14] [default]: dispatching message (default/Logout::run::LocalLI)
2021-02-28 17:08:16 DEBUG Shibboleth.SessionCache [14] [default]: searching for session (_b7da25c292ac8919557f0ab1b5525e1d)
2021-02-28 17:20:52 INFO OpenSAML.MetadataProvider.XML : reloading remote resource...

Thanks again. Kshitij
-----Original Message-----
From: Nate Klingenstein <ndk at signet.id <mailto:ndk at signet.id>> 
Sent: Monday, March 1, 2021 3:48 PM
To: Shib Users <users at shibboleth.net <mailto:users at shibboleth.net>>
Cc: Chug, Kshitij (NIH/CIT) [C] <kshitij.chug at nih.gov <mailto:kshitij.chug at nih.gov>>
Subject: RE: Shibboleth SP | Logout Intermittent Issues

Kshitij,

I'm not aware of anything wrong with the SAML Logout implementation in the SP.  We'll need more information about the issue you're having and some logs capturing the intermittent issue to really be of any help to you.

Take care,
Nate.

--------
Signet, Inc.
The Art of Access ®

https://www.signet.id <https://www.signet.id>

-----Original message-----
From: Chug, Kshitij (NIH/CIT) [C] via users
Sent: Monday, March 1 2021, 1:45 pm
To: Shib Users
Cc: Chug, Kshitij (NIH/CIT) [C]
Subject: Shibboleth SP | Logout Intermittent Issues

Hi All,

We are seeing an intermittent issue.

Shibb SP does not initiate the Single Logout intermittently. Is there any known issue or can someone suggest some solution/configuration changes to avoid logout issues?

Thanks,

Kshitij Chug

--

For Consortium Member technical support, see https://wiki.shibboleth.net/confluence/x/coFAAg <https://wiki.shibboleth.net/confluence/x/coFAAg>

To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net <mailto:users-unsubscribe at shibboleth.net>