<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
</head>
<body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; color: rgb(0, 0, 0); font-size: 14px; font-family: Calibri, sans-serif; ">
<div>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.</div>
<div><br>
</div>
<div>So here's a log snippet:</div>
<div><br>
</div>
<div>
<div>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]</div>
<div>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.</div>
<div>00:04:37.523 - INFO [Clareity-Audit:1410] - [http-18780-93:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - 20130408T070437Z|xxxx|http://serviceprovicer|http://acsurlvalue|false|false|||</div>
</div>
<div>
<div>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</div>
<div>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|</div>
<div>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</div>
<div>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</div>
<div>00:04:40.917 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:574] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Unbinding LoginContext</div>
<div>00:04:40.918 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:600] - [http-18780-99:] [1.2.3.4] [7071A3BE1A2A84C87B6EA59106F1B20D] - Expiring LoginContext cookie</div>
<div>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</div>
<div>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</div>
<div>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</div>
<div>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.</div>
<div>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.</div>
<div>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'</div>
</div>
<div><br>
</div>
<div>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.</div>
<div><br>
</div>
<div>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).</div>
<div><br>
</div>
<div>Thoughts? Other things I should look at?</div>
<div><br>
</div>
<div>Btw, the log lines is the client IP address and the Tomcat JSESSION ID value as well as the Shib session ID.</div>
<div><br>
</div>
<div>thanks,</div>
<div><br>
</div>
<div>Paul</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
</body>
</html>