10:43:52.957 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:180] - No session associated with session ID 6e2423f5e46fde5d27824b6ed5a0d6948ad2345529a4ecb0991f2e77bf4c74ba - session must have timed out
10:43:52.957 - INFO [Shibboleth-Access:73] - 20170130T154352Z|104.129.194.133|idp.testshib.org:443|/profile/SAML2/POST/SSO|
10:43:52.958 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/POST/SSO
10:43:52.958 - 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
10:43:52.958 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - LoginContext key cookie was not present in request
10:43:52.958 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:188] - Incoming request does not contain a login context, processing as first leg of request
10:43:52.959 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:366] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST'
10:43:52.970 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for cloudfoundry-saml-login
10:43:52.970 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for cloudfoundry-saml-login, looking up configuration based on metadata groups.
10:43:52.973 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for cloudfoundry-saml-login. Using default relying party configuration.
10:43:52.982 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:387] - Decoded request from relying party 'cloudfoundry-saml-login'
10:43:52.983 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for cloudfoundry-saml-login
10:43:52.983 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for cloudfoundry-saml-login, looking up configuration based on metadata groups.
10:43:52.984 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for cloudfoundry-saml-login. Using default relying party configuration.
10:43:52.984 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:226] - Creating login context and transferring control to authentication engine
10:43:52.984 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:181] - Storing LoginContext to StorageService partition loginContexts, key ea96fe677285b8333eef42378fb5fa51353fc7d2d66420100cd5f4e69b5ae277
10:43:52.985 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:240] - Redirecting user to authentication engine at https://idp.testshib.org:443/idp/AuthnEngine
10:43:53.166 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:180] - No session associated with session ID 6e2423f5e46fde5d27824b6ed5a0d6948ad2345529a4ecb0991f2e77bf4c74ba - session must have timed out
10:43:53.167 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request
10:43:53.167 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] - Beginning user authentication process.
10:43:53.167 - 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@10e3a27d, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@50c0c534}
10:43:53.167 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:332] - Filtering out previous session login handler because there is no existing IdP session
10:43:53.167 - 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:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@50c0c534}
10:43:53.167 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:497] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler
10:43:53.167 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66] - Redirecting to https://idp.testshib.org:443/idp/Authn/UserPassword
10:43:53.245 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:180] - No session associated with session ID 6e2423f5e46fde5d27824b6ed5a0d6948ad2345529a4ecb0991f2e77bf4c74ba - session must have timed out
10:43:53.250 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150] - Redirecting to login page /login.jsp
10:43:53.349 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:180] - No session associated with session ID 6e2423f5e46fde5d27824b6ed5a0d6948ad2345529a4ecb0991f2e77bf4c74ba - session must have timed out
10:43:53.437 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:180] - No session associated with session ID 6e2423f5e46fde5d27824b6ed5a0d6948ad2345529a4ecb0991f2e77bf4c74ba - session must have timed out
10:44:02.557 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:180] - No session associated with session ID 6e2423f5e46fde5d27824b6ed5a0d6948ad2345529a4ecb0991f2e77bf4c74ba - session must have timed out
10:44:02.558 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:170] - Attempting to authenticate user myself
10:44:02.558 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180] - useFirstPass = false
10:44:02.559 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181] - tryFirstPass = false
10:44:02.559 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182] - storePass = false
10:44:02.559 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183] - clearPass = false
10:44:02.560 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184] - setLdapPrincipal = true
10:44:02.560 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185] - setLdapDnPrincipal = false
10:44:02.560 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186] - setLdapCredential = true
10:44:02.561 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187] - defaultRole = []
10:44:02.561 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188] - principalGroupName = null
10:44:02.561 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189] - roleGroupName = null
10:44:02.562 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77] - userRoleAttribute = [eduPersonAffiliation]
10:44:02.562 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83] - Created authenticator: edu.vt.middleware.ldap.auth.AuthenticatorConfig@983538530::env={java.naming.provider.url=ldap://idp.testshib.org:389, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
10:44:02.563 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN using userField
10:44:02.563 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the following parameters:
10:44:02.564 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] -   dn = ou=people,dc=testshib,dc=org
10:44:02.564 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] -   filter = (uid={0})
10:44:02.564 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] -   filterArgs = [myself]
10:44:02.565 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] -   searchControls = javax.naming.directory.SearchControls@44925cff
10:44:02.565 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] -   handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@65178c84]
10:44:02.566 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with the following parameters:
10:44:02.566 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] -   authtype = simple
10:44:02.566 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] -   dn = null
10:44:02.567 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] -   credential = <suppressed>
10:44:02.571 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with the following parameters:
10:44:02.571 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] -   authtype = simple
10:44:02.572 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] -   dn = uid=myself,ou=people,dc=testshib,dc=org
10:44:02.572 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] -   credential = <suppressed>
10:44:02.574 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication succeeded for dn: uid=myself,ou=people,dc=testshib,dc=org
10:44:02.574 - DEBUG [edu.vt.middleware.ldap.jaas.JaasAuthenticator:215] - Returning attributes: 
10:44:02.574 - DEBUG [edu.vt.middleware.ldap.jaas.JaasAuthenticator:216] -     [eduPersonAffiliation]
10:44:02.576 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN using userField
10:44:02.577 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the following parameters:
10:44:02.577 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] -   dn = ou=people,dc=testshib,dc=org
10:44:02.577 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] -   filter = (uid={0})
10:44:02.578 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] -   filterArgs = [myself]
10:44:02.578 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] -   searchControls = javax.naming.directory.SearchControls@421d8575
10:44:02.578 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] -   handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@65178c84]
10:44:02.581 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:223] - Committed the following principals: [myself[eduPersonAffiliation[Member, Staff]]]
10:44:02.581 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:229] - Committed the following roles: [Member, Staff]
10:44:02.582 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:178] - Successfully authenticated user myself
10:44:02.582 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:144] - Returning control to authentication engine
10:44:02.582 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request
10:44:02.583 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:514] - Completing user authentication process
10:44:02.583 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:585] - Validating authentication was performed successfully
10:44:02.583 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:696] - Updating session information for principal myself
10:44:02.584 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:700] - Creating shibboleth session for principal myself
10:44:02.584 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:815] - Adding IdP session cookie to HTTP response
10:44:02.585 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:715] - Recording authentication and service information in Shibboleth session for principal: myself
10:44:02.585 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:560] - User myself authenticated with method urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
10:44:02.585 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] - Returning control to profile handler
10:44:02.586 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] - Redirecting user to profile handler at https://idp.testshib.org:443/idp/profile/SAML2/POST/SSO
10:44:02.677 - INFO [Shibboleth-Access:73] - 20170130T154402Z|104.129.194.133|idp.testshib.org:443|/profile/SAML2/POST/SSO|
10:44:02.677 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/POST/SSO
10:44:02.678 - 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
10:44:02.678 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:588] - Unbinding LoginContext
10:44:02.678 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:614] - Expiring LoginContext cookie
10:44:02.678 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:625] - Removed LoginContext, with key ea96fe677285b8333eef42378fb5fa51353fc7d2d66420100cd5f4e69b5ae277, from StorageService partition loginContexts
10:44:02.678 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:172] - Incoming request contains a login context and indicates principal was authenticated, processing second leg of request
10:44:02.680 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for cloudfoundry-saml-login
10:44:02.681 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for cloudfoundry-saml-login, looking up configuration based on metadata groups.
10:44:02.681 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for cloudfoundry-saml-login. Using default relying party configuration.
10:44:02.683 - WARN [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:206] - Relying party 'cloudfoundry-saml-login' requested the response to be returned to endpoint with ACS URL 'http://10.104.24.65/Logon/saml/SSO/alias/cloudfoundry-saml-login'  and binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' however no endpoint, with that URL and using a supported binding,  can be found in the relying party's metadata 
10:44:02.683 - ERROR [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:447] - No return endpoint available for relying party cloudfoundry-saml-login