Hi All,<div><br></div><div>We're running IdP 2.3.8 and occasionally are seeing some odd responses being sent back to SPs from the UsernamePassword login handler. This happens rarely, maybe 3-6 times per day. The issue is the IdP is sending an AuthnFailed response back to the SP. Ordinarily in our setup if a user fails to authN they just get sent back to the login screen again. Our setup is fairly stock with the exception that we replaced the default storage service with the memcache storage service. </div>
<div>
<div><br></div><div>What follows is the relevant logs from a session going south like this:</div><div><br></div><div><div>18:10:48.840 - DEBUG [PROTOCOL_MESSAGE:113] - </div><div><?xml version="1.0" encoding="UTF-8"?><samlp:AuthnRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" AssertionConsumerServiceURL="<a href="https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST">https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST</a>" Destination="<a href="https://shibboleth2.uchicago.edu/idp/profile/SAML">https://shibboleth2.uchicago.edu/idp/profile/SAML</a></div>
<div>2/Redirect/SSO" ID="_e142079a08a65fc4f87fd5efa1c9611e" IssueInstant="2012-12-07T00:10:39Z" ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST" Version="2.0"></div>
<div> <saml:Issuer xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion"><a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a></saml:Issuer></div><div> <samlp:NameIDPolicy AllowCreate="1"/></div>
<div></samlp:AuthnRequest></div><div><br></div><div>18:10:48.840 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a></div>
<div>18:10:48.840 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>, looking up configuration based on metadata </div>
<div>groups.</div><div>18:10:48.857 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>. Using default relying party </div>
<div>configuration.</div><div>18:10:48.857 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:130] - Evaluating security policy of type 'edu.internet2.middleware.shibboleth.common.security.ShibbolethSecurityPolicy' for decoded message</div>
<div>18:10:48.858 - DEBUG [org.opensaml.util.storage.ReplayCache:92] - Attempting to acquire lock for replay cache check</div><div>18:10:48.858 - DEBUG [org.opensaml.util.storage.ReplayCache:94] - Lock acquired</div><div>
18:10:48.858 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: replay!<a href="https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611e">https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611e</a></div>
<div>18:10:48.859 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div><div>18:10:48.859 - DEBUG [org.opensaml.util.storage.ReplayCache:105] - Message ID _e142079a08a65fc4f87fd5efa1c9611e was not a replay</div>
<div>18:10:48.859 - DEBUG [org.opensaml.util.storage.ReplayCache:132] - Writing message ID <a href="https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611e">https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611e</a> to replay cache with expiration time 2012-12-06T18:15:48.859-06:00</div>
<div>18:10:48.859 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:288] - storageService.put: replay!<a href="https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611e">https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611e</a> org.opensaml.util.storage.ReplayCacheEntry@78590ca3</div>
<div>18:10:48.860 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:395] - put writes global value.</div><div>18:10:48.860 - INFO [org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:100] - SAML protocol message was not signed, skipping XML signature processing</div>
<div>18:10:48.860 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64] - Evaluating simple signature rule of type: org.opensaml.saml2.binding.security.SAML2HTTPRedirectDeflateSignatureRule</div>
<div>18:10:48.860 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:87] - HTTP request was not signed via simple signature mechanism, skipping</div><div>18:10:48.860 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64] - Evaluating simple signature rule of type: org.opensaml.saml2.binding.security.SAML2HTTPPostSimpleSignRule</div>
<div>18:10:48.861 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:81] - Rule can not handle this request, skipping processing</div><div>18:10:48.861 - INFO [org.opensaml.ws.transport.http.HttpServletRequestAdapter:130] - Wrapped HTTP servlet request did not contain a client certificate</div>
<div>18:10:48.861 - INFO [org.opensaml.ws.security.provider.ClientCertAuthRule:104] - Inbound message transport did not contain a peer credential, skipping client certificate authentication</div><div>18:10:48.861 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:85] - Successfully decoded message.</div>
<div>18:10:48.861 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:191] - Checking SAML message intended destination endpoint against receiver endpoint</div><div>18:10:48.861 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:210] - Intended message destination endpoint: <a href="https://shibboleth2.uchicago.edu/idp/profile/SAML2/Redirect/SSO">https://shibboleth2.uchicago.edu/idp/profile/SAML2/Redirect/SSO</a></div>
<div>18:10:48.861 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:211] - Actual message receiver endpoint: <a href="https://shibboleth2.uchicago.edu/idp/profile/SAML2/Redirect/SSO">https://shibboleth2.uchicago.edu/idp/profile/SAML2/Redirect/SSO</a></div>
<div>18:10:48.862 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:219] - SAML message intended destination endpoint matched recipient endpoint</div><div>18:10:48.862 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:358] - Decoded request from relying party '<a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>'</div>
<div>18:10:48.877 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a></div>
<div>18:10:48.877 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>, looking up configuration based on metadata </div>
<div>groups.</div><div>18:10:48.892 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>. Using default relying party </div>
<div>configuration.</div><div>18:10:48.893 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:224] - Creating login context and transferring control to authentication engine</div><div>18:10:48.893 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:94] - storageService.contains: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div>
<div>18:10:48.893 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:167] - Storing LoginContext to StorageService partition loginContexts, key 5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div><div>18:10:48.894 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:288] - storageService.put: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961 edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry@48c86153</div>
<div>18:10:48.894 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:419] - put will not write global value.</div><div>18:10:48.894 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:467] - put writes local value.</div>
<div>18:10:48.894 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:237] - Redirecting user to authentication engine at <a href="https://shibboleth2.uchicago.edu:443/idp/AuthnEngine">https://shibboleth2.uchicago.edu:443/idp/AuthnEngine</a></div>
<div>18:10:50.019 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d</div><div>18:10:50.020 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div>
<div>18:10:50.020 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No session associated with session ID NDM2OGRhMGQyYTljOWI0NDI5MGM3MTc1YWI0MWMzNWUwMDMyY2NlMWQ0NDI5NWI1NWRiNTdjZmYyOTEwOTczZA== - session must have timed out</div>
<div>18:10:50.020 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request</div><div>18:10:50.020 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div>
<div>18:10:50.021 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry@48c86153</div></div><div><div>18:10:50.021 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] - Beginning user authentication process.</div>
<div>18:10:50.021 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:283] - Filtering configured LoginHandlers: {urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler@64900079, urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@2a0f3b83, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@2a0f3b83, <a href="http://id.incommon.org/assurance/silver=edu.uchicago.shibboleth.authn.provider.AssuranceLoginHandler@4e0c2b07">http://id.incommon.org/assurance/silver=edu.uchicago.shibboleth.authn.provider.AssuranceLoginHandler@4e0c2b07</a>}</div>
<div>18:10:50.021 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:332] - Filtering out previous session login handler because there is no existing IdP session</div><div>18:10:50.021 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:464] - Selecting appropriate login handler from filtered set {urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@2a0f3b83, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@2a0f3b83, <a href="http://id.incommon.org/assurance/silver=edu.uchicago.shibboleth.authn.provider.AssuranceLoginHandler@4e0c2b07">http://id.incommon.org/assurance/silver=edu.uchicago.shibboleth.authn.provider.AssuranceLoginHandler@4e0c2b07</a>}</div>
<div>18:10:50.021 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:497] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler</div>
<div>18:10:50.022 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66] - Redirecting to <a href="https://shibboleth2.uchicago.edu:443/idp/Authn/UserPassword">https://shibboleth2.uchicago.edu:443/idp/Authn/UserPassword</a></div>
<div>18:10:50.172 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d</div><div>18:10:50.172 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d</div>
<div>18:10:50.173 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div><div>18:10:50.173 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No session associated with session ID NDM2OGRhMGQyYTljOWI0NDI5MGM3MTc1YWI0MWMzNWUwMDMyY2NlMWQ0NDI5NWI1NWRiNTdjZmYyOTEwOTczZA== - session must have timed out</div>
<div>18:10:50.173 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request</div><div>18:10:50.173 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div>
<div>18:10:50.174 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry@48c86153</div><div>18:10:50.174 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:514] - Completing user authentication process</div>
<div>18:10:50.174 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:585] - Validating authentication was performed successfully</div><div>18:10:50.174 - ERROR [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:618] - No user identified by login handler.</div>
<div>18:10:50.175 - ERROR [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:563] - Authentication failed with the error:</div><div>edu.internet2.middleware.shibboleth.idp.authn.AuthenticationException: No user identified by login handler.</div>
<div> at edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.validateSuccessfulAuthentication(AuthenticationEngine.java:619) [shibboleth-identityprovider-2.3.8.jar:na]</div><div> at edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.completeAuthentication(AuthenticationEngine.java:537) [shibboleth-identityprovider-2.3.8.jar:na]</div>
<div> at edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.service(AuthenticationEngine.java:225) [shibboleth-identityprovider-2.3.8.jar:na]</div><div> at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) [servlet-api.jar:na]</div>
<div> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) [catalina.jar:6.0.29]</div><div> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.29]</div>
<div> at unimr.shib2.UniMrMemcachedServletFilter.doFilter(UniMrMemcachedServletFilter.java:56) [unimr-memcached-idp2.3-rev151.jar:na]</div><div> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.29]</div>
<div> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.29]</div><div> at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50) [shibboleth-identityprovider-2.3.8.jar:na]</div>
<div> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.29]</div><div> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.29]</div>
<div> at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:81) [shibboleth-identityprovider-2.3.8.jar:na]</div><div> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.29]</div>
<div> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.29]</div><div> at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52) [shibboleth-common-1.3.7.jar:na]</div>
</div><div><div>18:10:50.175 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] - Returning control to profile handler</div><div>18:10:50.175 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div>
<div>18:10:50.176 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry@48c86153</div><div>18:10:50.176 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] - Redirecting user to profile handler at <a href="https://shibboleth2.uchicago.edu:443/idp/profile/SAML2/Redirect/SSO">https://shibboleth2.uchicago.edu:443/idp/profile/SAML2/Redirect/SSO</a></div>
<div>18:10:50.275 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div><div>18:10:50.275 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No session associated with session ID NDM2OGRhMGQyYTljOWI0NDI5MGM3MTc1YWI0MWMzNWUwMDMyY2NlMWQ0NDI5NWI1NWRiNTdjZmYyOTEwOTczZA== - session must have timed out</div>
<div>18:10:50.276 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div><div>18:10:50.276 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d</div>
<div>18:10:50.277 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry@48c86153</div><div>18:10:50.278 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div>
<div>18:10:50.278 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No session associated with session ID NDM2OGRhMGQyYTljOWI0NDI5MGM3MTc1YWI0MWMzNWUwMDMyY2NlMWQ0NDI5NWI1NWRiNTdjZmYyOTEwOTczZA== - session must have timed out</div>
<div>18:10:50.278 - INFO [Shibboleth-Access:74] - 20121207T001050Z|98.206.165.207|shibboleth2.uchicago.edu:443|/profile/SAML2/Redirect/SSO|</div><div>18:10:50.279 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO</div>
<div>18:10:50.279 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:97] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler</div>
<div>18:10:50.279 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div><div>18:10:50.280 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry@48c86153</div>
<div>18:10:50.280 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:574] - Unbinding LoginContext</div><div>18:10:50.281 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:600] - Expiring LoginContext cookie</div>
<div>18:10:50.281 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:480] - storageService.remove: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div><div>18:10:50.282 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:611] - Removed LoginContext, with key 5f716bf6-9e1e-4aa6-97c4-6271cf5f8961, from StorageService partition loginContexts</div>
<div>18:10:50.282 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:176] - Incoming request contains a login context and indicates there was an error authenticating the principal, processing second leg of request</div>
<div>18:10:50.311 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div><div>18:10:50.312 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div>
<div>18:10:50.312 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service</div><div>18:10:50.313 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div>
<div>18:10:50.313 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div><div>18:10:50.314 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service</div>
<div>18:10:50.314 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:348] - No relying party, nothing to display</div><div>18:10:50.315 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div>
<div>18:10:50.315 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div><div>18:10:50.316 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service</div>
<div>18:10:50.316 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div><div>18:10:50.317 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div>
<div>18:10:50.317 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service</div><div>18:10:50.318 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:93] - No relying party, nothing to display</div>
<div>18:10:50.318 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div><div>18:10:50.319 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div>
<div>18:10:50.319 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service</div><div>18:10:50.319 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961</div>
</div><div><div>18:10:50.320 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns null</div><div>18:10:50.321 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service</div>
<div>18:10:50.321 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:93] - No relying party, nothing to display</div><div>18:10:50.321 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150] - Redirecting to login page /login.jsp</div>
<div>18:10:50.334 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a></div>
<div>18:10:50.334 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>, looking up configuration based on metadata groups.</div>
<div>18:10:50.351 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>. Using default relying party configuration.</div>
<div>18:10:50.368 - DEBUG [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:99] - Filtering peer endpoints. Supported peer endpoint bindings: [urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST-SimpleSign, urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST, urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Artifact]</div>
<div>18:10:50.368 - DEBUG [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:114] - Removing endpoint <a href="https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/ECP">https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/ECP</a> because its binding urn:oasis:names:tc:SAML:2.0:bindings:PAOS is not supported</div>
<div>18:10:50.368 - DEBUG [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:114] - Removing endpoint <a href="https://kakashi.uchicago.edu/Shibboleth.sso/SAML/POST">https://kakashi.uchicago.edu/Shibboleth.sso/SAML/POST</a> because its binding urn:oasis:names:tc:SAML:1.0:profiles:browser-post is not supported</div>
<div>18:10:50.369 - DEBUG [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:114] - Removing endpoint <a href="https://kakashi.uchicago.edu/Shibboleth.sso/SAML/Artifact">https://kakashi.uchicago.edu/Shibboleth.sso/SAML/Artifact</a> because its binding urn:oasis:names:tc:SAML:1.0:profiles:artifact-01 is not supported</div>
<div>18:10:50.369 - DEBUG [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:69] - Selecting endpoint by ACS URL '<a href="https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST">https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST</a>' and protocol binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' for request '_e142079a08a65fc4f87fd5efa1c9611e' from entity '<a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>'</div>
<div>18:10:50.369 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:778] - Encoding response to SAML request _e142079a08a65fc4f87fd5efa1c9611e from relying party <a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a></div>
<div>18:10:50.369 - DEBUG [org.opensaml.ws.message.encoder.BaseMessageEncoder:49] - Beginning encode message to outbound transport of type: org.opensaml.ws.transport.http.HttpServletResponseAdapter</div><div>18:10:50.369 - DEBUG [org.opensaml.saml2.binding.encoding.HTTPPostEncoder:124] - Invoking Velocity template to create POST body</div>
<div>18:10:50.369 - DEBUG [org.opensaml.saml2.binding.encoding.HTTPPostEncoder:158] - Encoding action url of '<a href="https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST">https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST</a>' with encoded value 'https&#x3a;&#x2f;&#x2f;<a href="http://kakashi.uchicago.edu">kakashi.uchicago.edu</a>&#x2f;Shibboleth.sso&#x2f;SAML2&#x2f;POST'</div>
<div>18:10:50.370 - DEBUG [org.opensaml.saml2.binding.encoding.HTTPPostEncoder:161] - Marshalling and Base64 encoding SAML message</div><div>18:10:50.370 - DEBUG [org.opensaml.ws.message.encoder.BaseMessageEncoder:97] - Marshalling message</div>
<div>18:10:50.370 - DEBUG [org.opensaml.saml2.binding.encoding.HTTPPostEncoder:184] - Setting RelayState parameter to: 'ss:mem:eff8d9afb7f243f18a7368a1b3d1f82b579e8203ecdaa3b8ab6c680158b22394', encoded as 'ss&#x3a;mem&#x3a;eff8d9afb7f243f18a7368a1b3d1f82b579e8203ecdaa3b8ab6c680158b22394'</div>
<div>18:10:50.371 - DEBUG [PROTOCOL_MESSAGE:74] - </div><div><?xml version="1.0" encoding="UTF-8"?><saml2p:Response xmlns:saml2p="urn:oasis:names:tc:SAML:2.0:protocol" Destination="<a href="https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST">https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST</a>" ID="_ee81262fd395f2c86097573f16aa0ec1" InResponseTo="_e142079a08a65fc4f87fd5efa1c9611e" IssueInstant="2012-12-07T00:10:50.369Z" Version="2.0"></div>
<div> <saml2:Issuer xmlns:saml2="urn:oasis:names:tc:SAML:2.0:assertion" Format="urn:oasis:names:tc:SAML:2.0:nameid-format:entity">urn:mace:incommon:<a href="http://uchicago.edu">uchicago.edu</a></saml2:Issuer></div>
<div> <saml2p:Status></div><div> <saml2p:StatusCode Value="urn:oasis:names:tc:SAML:2.0:status:Responder"></div><div> <saml2p:StatusCode Value="urn:oasis:names:tc:SAML:2.0:status:AuthnFailed"/></div>
<div> </saml2p:StatusCode></div><div> </saml2p:Status></div><div></saml2p:Response></div><div><br></div><div>18:10:50.371 - DEBUG [org.opensaml.ws.message.encoder.BaseMessageEncoder:56] - Successfully encoded message.</div>
<div>18:10:50.371 - INFO [Shibboleth-Audit:989] - 20121207T001050Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_e142079a08a65fc4f87fd5efa1c9611e|<a href="https://timespace.uchicago.edu">https://timespace.uchicago.edu</a>|urn:mace:shibboleth:2.0:profiles:saml2:sso|urn:mace:incommon:<a href="http://uchicago.edu">uchicago.edu</a>|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_ee81262fd395f2c86097573f16aa0ec1||||||</div>
</div><div><br></div><div>Any ideas? Suggestions?</div><div><br></div><div>Thanks</div><div><br></div><div>Dave</div><div><br></div>-- <br>David Langenberg<div>Identity & Access Management</div><div>The University of Chicago</div>
<br>
</div>