login context vs session

[Paul Hethmon]

So perhaps a dev question, but we'll try here first. I'm seeing an occasional situation where a user is going through login, has been authenticated, and I've returned control back to the authentication engine to create the SAML response. During that process, Shib is loosing the user and I end up with a SAML response with out any nameID or attributes. I can see in the logs where the attribute resolution starts and the principal value is already "null". So no mystery as to why the response is empty. I just can't figure out why the principal is lost.

So here's a log snippet:

00:04:37.522 - DEBUG [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1298] - [http-18780-93:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Saving firstname = [Smith] for [xxxx]
00:04:37.523 - INFO [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1389] - [http-18780-93:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - xxxx -- Normal authentication redirect for user.
00:04:37.523 - INFO [Clareity-Audit:1410] - [http-18780-93:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - 20130408T070437Z|xxxx|http://serviceprovicer|http://acsurlvalue|false|false|||
00:04:40.917 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - No session associated with session ID MWFhOWJlOWMwNTgzMzlhMTEyY2VmYWFjNzdjNWVhZDlmNjI2MTNlYWE5MDRkM2FhNmZmYzg5N2MxNTFmY2U0Mw== - session must have timed out
00:04:40.917 - INFO [Shibboleth-Access:74] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - 20130408T070440Z| 1.2.3.4 |idp.xxxx.clareitysecurity.net:80|/profile/SAML2/POST/SSO|
00:04:40.917 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/POST/SSO
00:04:40.917 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:97] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
00:04:40.917 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:574] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Unbinding LoginContext
00:04:40.918 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:600] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Expiring LoginContext cookie
00:04:40.918 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:611] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Removed LoginContext, with key 9d28335f-d690-48ff-8cce-65a91eaed763, from StorageService partition loginContexts
00:04:40.918 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:176] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Incoming request contains a login context and indicates principal was authenticated, processing second leg of request
00:04:40.918 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Looking up relying party configuration for http://serviceprovicer
00:04:40.918 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - No custom relying party configuration found for http://serviceprovicer, looking up configuration based on metadata groups.
00:04:40.918 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - No custom or group-based relying party configuration found for http://serviceprovicer. Using default relying party configuration.
00:04:40.919 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:474] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Resolving attributes for principal 'null' for SAML request from relying party 'http://serviceprovicer'

It's been sanitized to protect my guilt. For this customer, I am not keeping sessions. So I have the session time in internal.xml set to a very low value, 2500 ms. My theory is that the storage sweeper comes through occasionally timing with my login process and kills the session and I lose the principal.

So, do I need to keep a session for a longer minimum period of time? Say on the order of 4 or 5 minutes? Previous session handling is turned off and I've turned down the session timer just to prevent re-use of the browser session by different users (shared computer model).

Thoughts? Other things I should look at?

Btw, the log lines is the client IP address and the Tomcat JSESSION ID value as well as the Shib session ID.

thanks,

Paul



-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20130409/d5faf09a/attachment.html