AuthnFailed response from UsernamePassword handler

David Langenberg davel at uchicago.edu
Fri Dec 7 11:05:16 EST 2012 

Hi All,

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.

What follows is the relevant logs from a session going south like this:

18:10:48.840 - DEBUG [PROTOCOL_MESSAGE:113] -
<?xml version="1.0" encoding="UTF-8"?><samlp:AuthnRequest
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"
AssertionConsumerServiceURL="
https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST" Destination="
https://shibboleth2.uchicago.edu/idp/profile/SAML
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">
   <saml:Issuer xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">
https://timespace.uchicago.edu</saml:Issuer>
   <samlp:NameIDPolicy AllowCreate="1"/>
</samlp:AuthnRequest>

18:10:48.840 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for https://timespace.uchicago.edu
18:10:48.840 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134]
- No custom relying party configuration found for
https://timespace.uchicago.edu, looking up configuration based on metadata
groups.
18:10:48.857 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://timespace.uchicago.edu. Using default relying party
configuration.
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
18:10:48.858 - DEBUG [org.opensaml.util.storage.ReplayCache:92] -
Attempting to acquire lock for replay cache check
18:10:48.858 - DEBUG [org.opensaml.util.storage.ReplayCache:94] - Lock
acquired
18:10:48.858 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: replay!
https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611e
18:10:48.859 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
18:10:48.859 - DEBUG [org.opensaml.util.storage.ReplayCache:105] - Message
ID _e142079a08a65fc4f87fd5efa1c9611e was not a replay
18:10:48.859 - DEBUG [org.opensaml.util.storage.ReplayCache:132] - Writing
message ID https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611eto
replay cache with expiration time 2012-12-06T18:15:48.859-06:00
18:10:48.859 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:288] -
storageService.put: replay!
https://timespace.uchicago.edu_e142079a08a65fc4f87fd5efa1c9611eorg.opensaml.util.storage.ReplayCacheEntry@78590ca3
18:10:48.860 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:395] -
put writes global value.
18:10:48.860 - INFO
[org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:100]
- SAML protocol message was not signed, skipping XML signature processing
18:10:48.860 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64]
- Evaluating simple signature rule of type:
org.opensaml.saml2.binding.security.SAML2HTTPRedirectDeflateSignatureRule
18:10:48.860 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:87]
- HTTP request was not signed via simple signature mechanism, skipping
18:10:48.860 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64]
- Evaluating simple signature rule of type:
org.opensaml.saml2.binding.security.SAML2HTTPPostSimpleSignRule
18:10:48.861 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:81]
- Rule can not handle this request, skipping processing
18:10:48.861 - INFO
[org.opensaml.ws.transport.http.HttpServletRequestAdapter:130] - Wrapped
HTTP servlet request did not contain a client certificate
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
18:10:48.861 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:85] - Successfully
decoded message.
18:10:48.861 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:191] -
Checking SAML message intended destination endpoint against receiver
endpoint
18:10:48.861 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:210] -
Intended message destination endpoint:
https://shibboleth2.uchicago.edu/idp/profile/SAML2/Redirect/SSO
18:10:48.861 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:211] - Actual
message receiver endpoint:
https://shibboleth2.uchicago.edu/idp/profile/SAML2/Redirect/SSO
18:10:48.862 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:219] - SAML
message intended destination endpoint matched recipient endpoint
18:10:48.862 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:358]
- Decoded request from relying party 'https://timespace.uchicago.edu'
18:10:48.877 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for https://timespace.uchicago.edu
18:10:48.877 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134]
- No custom relying party configuration found for
https://timespace.uchicago.edu, looking up configuration based on metadata
groups.
18:10:48.892 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://timespace.uchicago.edu. Using default relying party
configuration.
18:10:48.893 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:224]
- Creating login context and transferring control to authentication engine
18:10:48.893 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:94] -
storageService.contains: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
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
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 at 48c86153
18:10:48.894 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:419] -
put will not write global value.
18:10:48.894 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:467] -
put writes local value.
18:10:48.894 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:237]
- Redirecting user to authentication engine at
https://shibboleth2.uchicago.edu:443/idp/AuthnEngine
18:10:50.019 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get:
session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d
18:10:50.020 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
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
18:10:50.020 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -
Processing incoming request
18:10:50.020 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.021 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns
edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 48c86153
18:10:50.021 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] -
Beginning user authentication process.
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 at 64900079,
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 2a0f3b83,
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 2a0f3b83,
http://id.incommon.org/assurance/silver=edu.uchicago.shibboleth.authn.provider.AssuranceLoginHandler@4e0c2b07
}
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
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 at 2a0f3b83,
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 2a0f3b83,
http://id.incommon.org/assurance/silver=edu.uchicago.shibboleth.authn.provider.AssuranceLoginHandler@4e0c2b07
}
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
18:10:50.022 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66]
- Redirecting to https://shibboleth2.uchicago.edu:443/idp/Authn/UserPassword
18:10:50.172 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get:
session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d
18:10:50.172 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get:
session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d
18:10:50.173 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
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
18:10:50.173 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -
Processing incoming request
18:10:50.173 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.174 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns
edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 48c86153
18:10:50.174 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:514] -
Completing user authentication process
18:10:50.174 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:585] -
Validating authentication was performed successfully
18:10:50.174 - ERROR
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:618] -
No user identified by login handler.
18:10:50.175 - ERROR
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:563] -
Authentication failed with the error:
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationException: No
user identified by login handler.
        at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.validateSuccessfulAuthentication(AuthenticationEngine.java:619)
[shibboleth-identityprovider-2.3.8.jar:na]
        at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.completeAuthentication(AuthenticationEngine.java:537)
[shibboleth-identityprovider-2.3.8.jar:na]
        at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.service(AuthenticationEngine.java:225)
[shibboleth-identityprovider-2.3.8.jar:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[servlet-api.jar:na]
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
[catalina.jar:6.0.29]
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.29]
        at
unimr.shib2.UniMrMemcachedServletFilter.doFilter(UniMrMemcachedServletFilter.java:56)
[unimr-memcached-idp2.3-rev151.jar:na]
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
[catalina.jar:6.0.29]
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.29]
        at
edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50)
[shibboleth-identityprovider-2.3.8.jar:na]
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
[catalina.jar:6.0.29]
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.29]
        at
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:81)
[shibboleth-identityprovider-2.3.8.jar:na]
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
[catalina.jar:6.0.29]
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.29]
        at
edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52)
[shibboleth-common-1.3.7.jar:na]
18:10:50.175 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] -
Returning control to profile handler
18:10:50.175 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.176 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns
edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 48c86153
18:10:50.176 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] -
Redirecting user to profile handler at
https://shibboleth2.uchicago.edu:443/idp/profile/SAML2/Redirect/SSO
18:10:50.275 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
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
18:10:50.276 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.276 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get:
session!4368da0d2a9c9b44290c7175ab41c35e0032cce1d44295b55db57cff2910973d
18:10:50.277 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns
edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 48c86153
18:10:50.278 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
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
18:10:50.278 - INFO [Shibboleth-Access:74] -
20121207T001050Z|98.206.165.207|shibboleth2.uchicago.edu:443
|/profile/SAML2/Redirect/SSO|
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
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
18:10:50.279 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.280 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns
edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 48c86153
18:10:50.280 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:574] -
Unbinding LoginContext
18:10:50.281 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:600] -
Expiring LoginContext cookie
18:10:50.281 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:480] -
storageService.remove: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
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
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
18:10:50.311 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.312 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
18:10:50.312 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No
login context in storage service
18:10:50.313 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.313 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
18:10:50.314 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No
login context in storage service
18:10:50.314 - DEBUG
[edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:348] - No
relying party, nothing to display
18:10:50.315 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.315 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
18:10:50.316 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No
login context in storage service
18:10:50.316 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.317 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
18:10:50.317 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No
login context in storage service
18:10:50.318 - DEBUG
[edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:93] - No
relying party, nothing to display
18:10:50.318 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.319 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
18:10:50.319 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No
login context in storage service
18:10:50.319 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] -
storageService.get: loginContexts!5f716bf6-9e1e-4aa6-97c4-6271cf5f8961
18:10:50.320 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] -
get returns null
18:10:50.321 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No
login context in storage service
18:10:50.321 - DEBUG
[edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:93] - No
relying party, nothing to display
18:10:50.321 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150]
- Redirecting to login page /login.jsp
18:10:50.334 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for https://timespace.uchicago.edu
18:10:50.334 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134]
- No custom relying party configuration found for
https://timespace.uchicago.edu, looking up configuration based on metadata
groups.
18:10:50.351 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://timespace.uchicago.edu. Using default relying party configuration.
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]
18:10:50.368 - DEBUG
[org.opensaml.saml2.binding.AuthnResponseEndpointSelector:114] - Removing
endpoint https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/ECP because its
binding urn:oasis:names:tc:SAML:2.0:bindings:PAOS is not supported
18:10:50.368 - DEBUG
[org.opensaml.saml2.binding.AuthnResponseEndpointSelector:114] - Removing
endpoint https://kakashi.uchicago.edu/Shibboleth.sso/SAML/POST because its
binding urn:oasis:names:tc:SAML:1.0:profiles:browser-post is not supported
18:10:50.369 - DEBUG
[org.opensaml.saml2.binding.AuthnResponseEndpointSelector:114] - Removing
endpoint https://kakashi.uchicago.edu/Shibboleth.sso/SAML/Artifact because
its binding urn:oasis:names:tc:SAML:1.0:profiles:artifact-01 is not
supported
18:10:50.369 - DEBUG
[org.opensaml.saml2.binding.AuthnResponseEndpointSelector:69] - Selecting
endpoint by ACS URL 'https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST'
and protocol binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' for
request '_e142079a08a65fc4f87fd5efa1c9611e' from entity '
https://timespace.uchicago.edu'
18:10:50.369 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:778]
- Encoding response to SAML request _e142079a08a65fc4f87fd5efa1c9611e from
relying party https://timespace.uchicago.edu
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
18:10:50.369 - DEBUG
[org.opensaml.saml2.binding.encoding.HTTPPostEncoder:124] - Invoking
Velocity template to create POST body
18:10:50.369 - DEBUG
[org.opensaml.saml2.binding.encoding.HTTPPostEncoder:158] - Encoding action
url of 'https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST' with
encoded value 'https&#x3a;&#x2f;&#x2f;kakashi.uchicago.edu
&#x2f;Shibboleth.sso&#x2f;SAML2&#x2f;POST'
18:10:50.370 - DEBUG
[org.opensaml.saml2.binding.encoding.HTTPPostEncoder:161] - Marshalling and
Base64 encoding SAML message
18:10:50.370 - DEBUG
[org.opensaml.ws.message.encoder.BaseMessageEncoder:97] - Marshalling
message
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'
18:10:50.371 - DEBUG [PROTOCOL_MESSAGE:74] -
<?xml version="1.0" encoding="UTF-8"?><saml2p:Response
xmlns:saml2p="urn:oasis:names:tc:SAML:2.0:protocol" Destination="
https://kakashi.uchicago.edu/Shibboleth.sso/SAML2/POST"
ID="_ee81262fd395f2c86097573f16aa0ec1"
InResponseTo="_e142079a08a65fc4f87fd5efa1c9611e"
IssueInstant="2012-12-07T00:10:50.369Z" Version="2.0">
   <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:
uchicago.edu</saml2:Issuer>
   <saml2p:Status>
      <saml2p:StatusCode
Value="urn:oasis:names:tc:SAML:2.0:status:Responder">
         <saml2p:StatusCode
Value="urn:oasis:names:tc:SAML:2.0:status:AuthnFailed"/>
      </saml2p:StatusCode>
   </saml2p:Status>
</saml2p:Response>

18:10:50.371 - DEBUG
[org.opensaml.ws.message.encoder.BaseMessageEncoder:56] - Successfully
encoded message.
18:10:50.371 - INFO [Shibboleth-Audit:989] -
20121207T001050Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_e142079a08a65fc4f87fd5efa1c9611e|
https://timespace.uchicago.edu
|urn:mace:shibboleth:2.0:profiles:saml2:sso|urn:mace:incommon:uchicago.edu
|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_ee81262fd395f2c86097573f16aa0ec1||||||

Any ideas? Suggestions?

Thanks

Dave

-- 
David Langenberg
Identity & Access Management
The University of Chicago
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20121207/34fc895e/attachment-0001.html

More information about the users mailing list