10:16:42.562 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Looking up relying party configuration for https://soadev.nih.gov/sp
10:16:42.562 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:130] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Custom relying party configuration found for https://soadev.nih.gov/sp
10:16:42.568 - INFO [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:130] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Validation of request simple signature succeeded
10:16:42.568 - INFO [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:132] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Authentication via request simple signature succeeded for context issuer entity ID https://soadev.nih.gov/sp
10:16:42.569 - INFO [org.opensaml.ws.transport.http.HttpServletRequestAdapter:130] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Wrapped HTTP servlet request did not contain a client certificate
10:16:42.569 - INFO [org.opensaml.ws.security.provider.ClientCertAuthRule:104] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Inbound message transport did not contain a peer credential, skipping client certificate authentication
10:16:42.569 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:333] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Decoded request from relying party 'https://soadev.nih.gov/sp'
10:16:42.569 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Looking up relying party configuration for https://soadev.nih.gov/sp
10:16:42.570 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:130] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Custom relying party configuration found for https://soadev.nih.gov/sp
10:16:42.570 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:203] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Creating login context and transferring control to authentication engine
10:16:42.571 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Storing LoginContext to StorageService partition loginContexts, key 8ef607f3-023f-426a-a382-d6027656872c
10:16:42.571 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:216] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Redirecting user to authentication engine at https://test.login.ufl.edu:443/idp/AuthnEngine
10:16:42.887 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Processing incoming request
10:16:42.887 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Beginning user authentication process.
10:16:42.887 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:286] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Filtering configured LoginHandlers: {urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler@25e4e6db, http://id.incommon.org/assurance/bronze=edu.ufl.shibboleth.authn.provider.UF_LoginHandler@56f0474c, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@38d8fb2b, http://id.incommon.org/assurance/silver=edu.ufl.shibboleth.authn.provider.UF_LoginHandler@56f0474c}
10:16:42.887 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:291] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Filtering possible login handlers by requested authentication methods: [urn:oasis:names:tc:SAML:2.0:ac:classes:Kerberos, http://id.incommon.org/assurance/silver, http://id.incommon.org/assurance/bronze, urn:oasis:names:tc:SAML:2.0:ac:classes:Password, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport]
10:16:42.888 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:335] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Filtering out previous session login handler because there is no existing IdP session
10:16:42.888 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:467] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Selecting appropriate login handler from filtered set {http://id.incommon.org/assurance/bronze=edu.ufl.shibboleth.authn.provider.UF_LoginHandler@56f0474c, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@38d8fb2b, http://id.incommon.org/assurance/silver=edu.ufl.shibboleth.authn.provider.UF_LoginHandler@56f0474c}
10:16:42.888 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:500] - idpSessionId[],JSESSIONID[0622F518A80751958EC1052A62E4F32D],clientIP[10.228.33.54] - Authenticating user with login handler of type edu.ufl.shibboleth.authn.provider.UF_LoginHandler