Shibboleth session are dropped after upgrading to version SP 2.5.4

Thu Jul 2 01:26:12 EDT 2015

One more thing....When session is removed, the shibd.log file shows the
following messages.

2015-07-01 22:16:19 INFO Shibboleth.SessionCache [7]: new session created:
ID (_7020e2ae4d02020eee9eddd240d7da8b) IdP (
http://www.okta.com/nnnnnnnnnnnnnnnnnn)
Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address (nn.nn.nn.nn)

2015-07-01 22:17:22 INFO Shibboleth.SessionCache [29]: removed session
(_7020e2ae4d02020eee9eddd240d7da8b)

2015-07-01 22:17:23 INFO Shibboleth.SessionCache [15]: new session created:
ID (_5f925bc72f835e70b77c70eb977b8463) IdP (
http://www.okta.com/nnnnnnnnnnnnnnnnnn)
Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address (nn.nn.nn.nn)

2015-07-01 22:17:49 INFO Shibboleth.Listener [12]: detected socket closure,
shutting down worker thread

2015-07-01 22:17:51 INFO Shibboleth.Listener [32]: detected socket closure,
shutting down worker thread

2015-07-01 22:17:52 INFO Shibboleth.Listener [10]: detected socket closure,
shutting down worker thread

2015-07-01 22:17:54 INFO Shibboleth.Listener [27]: detected socket closure,
shutting down worker thread

2015-07-01 22:17:55 INFO Shibboleth.Listener [5]: detected socket closure,
shutting down worker thread

2015-07-01 22:17:56 INFO Shibboleth.Listener [29]: detected socket closure,
shutting down worker thread

Thanks

Nara

On Wed, Jul 1, 2015 at 9:07 PM, nr673 . <nara.rama.us at gmail.com> wrote:

> Thanks Scott. Appreciate your response.
>
> The incoming request has the shibsession cookie as you can see below.
>
> *******
> GET /zip_services/show HTTP/1.1
> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.9; rv:38.0)
> Gecko/20100101 Firefox/38.0
> Accept: text/html, */*
> Accept-Language: en-US,en;q=0.5
> Accept-Encoding: gzip, deflate
> X-Requested-With: XMLHttpRequest
> Referer: https://awsqa2.pfoperations.com/pf/pfdomain/promotions/index
> Cookie: __utma=169413937.2058668447.1435710020.1435719877.1435726863.4;
> __utmz=169413937.1435710020.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
> search_criteria=3600;
> _shibsession_64656661756c7468747470733a2f2f6177737161322e70666f7065726174696f6e732e636f6d=_f8234ffd7cf313bd26405f8c50605112;
> __utmb=169413937.12.10.1435726863; __utmc=169413937; __utmt=1
> Connection: keep-alive
> ********
>
> The response shows the redirection to IdP instead of getting the HTTP 200
> OK. Also, the shibboleth expires the shibsession cookie.
>
> ********
> HTTP/1.1 302 Found
> Cache-Control: private,no-store,no-cache,max-age=0
> Content-Type: text/html; charset=iso-8859-1
> Date: Wed, 01 Jul 2015 05:14:42 GMT
> Expires: Wed, 01 Jan 1997 12:00:00 GMT
> Location: https://nnnnnnnnn.okta.com/app/template_saml_2_0/8ed6b25a9d60
> ----------------------
> Set-Cookie:
> _shibsession_64656661756c7468747470733a2f2f6177737161322e70666f7065726174696f6e732e636f6d=;
> path=/; secure; HttpOnly; expires=Mon, 01 Jan 2001 00:00:00 GMT
> ---------------------
> Content-Length: 856
> Connection: keep-alive
> ********
>
> I have turned on debug messages for shibboleth. It does not show any
> reason why shibboleth is closing the session. The session got closed in 2
> mins.
>
> ********
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [117]: inserted record
> (id138583305896505261075050264) in context
> (_d1d2bdac5515cdc5c16493ddfa809e4e) with expiration (1435811017)
> 2015-07-01 20:23:37 INFO Shibboleth.SessionCache [117]: new session
> created: ID (_d1d2bdac5515cdc5c16493ddfa809e4e) IdP (
> http://www.okta.com/ssssssssssss)
> Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address ()
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [117]: deleted record
> (de8322461f299d6809ee6e5d1cd57a5125d7429f10ed2cdd580faebf81cd148a) in
> context (RelayState)
> 2015-07-01 20:23:37 DEBUG Shibboleth.SSO.SAML2 [117]: ACS returning via
> redirect to: https://qa2.aaa.com/home
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [138]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [138]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [144]: dispatching message
> (default::getHeaders::Application)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [144]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [144]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [135]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [135]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [99]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [99]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [110]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [110]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [84]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [84]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [140]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [140]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [48]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [48]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:37 DEBUG Shibboleth.Listener [136]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [136]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811017)
> 2015-07-01 20:23:38 DEBUG Shibboleth.Listener [143]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:23:38 DEBUG XMLTooling.StorageService [143]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811018)
> 2015-07-01 20:23:41 DEBUG Shibboleth.Listener [110]: dispatching message
> (touch::StorageService::SessionCache)
> 2015-07-01 20:23:41 DEBUG XMLTooling.StorageService [110]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811021)
> 2015-07-01 20:23:41 DEBUG Shibboleth.Listener [140]: dispatching message
> (touch::StorageService::SessionCache)
> 2015-07-01 20:23:41 DEBUG XMLTooling.StorageService [140]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811021)
> 2015-07-01 20:23:41 DEBUG Shibboleth.Listener [48]: dispatching message
> (touch::StorageService::SessionCache)
> 2015-07-01 20:23:41 DEBUG XMLTooling.StorageService [48]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811021)
> 2015-07-01 20:23:41 DEBUG Shibboleth.Listener [136]: dispatching message
> (touch::StorageService::SessionCache)
> 2015-07-01 20:23:41 DEBUG XMLTooling.StorageService [136]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811021)
> 2015-07-01 20:25:05 DEBUG Shibboleth.Listener [67]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:25:05 DEBUG XMLTooling.StorageService [67]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811105)
> 2015-07-01 20:25:05 DEBUG Shibboleth.Listener [141]: dispatching message
> (find::StorageService::SessionCache)
> 2015-07-01 20:25:05 DEBUG XMLTooling.StorageService [141]: updated
> expiration of valid records in context (_d1d2bdac5515cdc5c16493ddfa809e4e)
> to (1435811105)
> 2015-07-01 20:25:05 DEBUG Shibboleth.Listener [141]: dispatching message
> (remove::StorageService::SessionCache)
> 2015-07-01 20:25:05 INFO Shibboleth.SessionCache [141]: removed session
> (_d1d2bdac5515cdc5c16493ddfa809e4e)
> 2015-07-01 20:25:05 DEBUG Shibboleth.Listener [141]: dispatching message
> (default/Login::run::SAML2SI)
> 2015-07-01 20:25:05 DEBUG XMLTooling.StorageService [141]: inserted record
> (ffe592c0772aab4e6851b80be26a363d98bdb2d360f794986103477c0d6cfa52) in
> context (RelayState) with expiration (1435808105)
> ********
>
> Also, I saw the following messages in the log file. I do not know if it is
> useful for debugging.
>
>
> *******
> 2015-07-01 20:23:37 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [117]:
> evaluating message flow policy (replay checking on, expiration 60)
> 2015-07-01 20:23:37 DEBUG XMLTooling.StorageService [117]: inserted record
> (id138583305896505261075050264) in context (MessageFlow) with expiration
> (1435807657)
>
>
> 2015-07-01 20:23:37 DEBUG Shibboleth.SSO.SAML2 [117]: extracting pushed
> attributes...
> 2015-07-01 20:23:37 DEBUG Shibboleth.AttributeExtractor.XML [117]: unable
> to extract attributes, unknown XML object type: saml2p:Response
> 2015-07-01 20:23:37 DEBUG Shibboleth.AttributeExtractor.XML [117]:
> skipping unmapped NameID with format
> (urn:oasis:names:tc:SAML:1.1:nameid-format:emailAddress)
> 2015-07-01 20:23:37 DEBUG Shibboleth.AttributeExtractor.XML [117]: unable
> to extract attributes, unknown XML object type: saml2:AuthnStatement
> 2015-07-01 20:23:37 DEBUG Shibboleth.AttributeDecoder.String [117]:
> decoding SimpleAttribute (FirstName) from SAML 2 Attribute (FirstName) with
> 1 value(s)
> 2015-07-01 20:23:37 DEBUG Shibboleth.AttributeDecoder.String [117]:
> decoding SimpleAttribute (LastName) from SAML 2 Attribute (LastName) with 1
> value(s)
> 2015-07-01 20:23:37 DEBUG Shibboleth.AttributeDecoder.String [117]:
> decoding SimpleAttribute (Email) from SAML 2 Attribute (Email) with 1
> value(s)
> 2015-07-01 20:23:37 DEBUG Shibboleth.AttributeDecoder.String [117]:
> decoding SimpleAttribute (UserName) from SAML 2 Attribute (UserName) with 1
> value(s)
> **********
>
> Sorry for the long message.
>
> Thanks
>
> Nara
>
>
>
>
> On Wed, Jul 1, 2015 at 5:18 PM, Cantor, Scott <cantor.2 at osu.edu> wrote:
>
>> On 7/1/15, 8:13 PM, "users on behalf of nr673 ." <
>> users-bounces at shibboleth.net on behalf of nara.rama.us at gmail.com> wrote:
>>
>>
>> >
>> >But, we still see the shibsession expiry issue. Appreciate any feedbacks
>> on this issue.
>>
>> If it's refusing to accept the session, the log(s) wlll tell you why. If
>> it doesn't log anything, then it is not getting any session cookie to
>> process, which is not anything the SP has any control over.
>>
>> There is/was no change in the software in any way related to this.
>>
>> -- Scott
>>
>> --
>> To unsubscribe from this list send an email to
>> users-unsubscribe at shibboleth.net
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20150701/55cd2ef6/attachment.html>