02:52:21.969 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority:263] - Attribute transientId was not encoded (filtered by query, or no SAML2AttributeEncoder attached). 02:52:21.969 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority:247] - Encoded attribute eduPersonTargetedID with encoder of type edu.internet2.middleware.shibboleth.common.attribute.encoding.provider.SAML2XMLObjectAttributeEncoder 02:52:21.969 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority:247] - Encoded attribute telephoneNumber with encoder of type edu.internet2.middleware.shibboleth.common.attribute.encoding.provider.SAML2StringAttributeEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:527] - Filtering out potential name identifier attributes which can not be encoded by edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute uid, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute eduPersonAffiliation, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute eduPersonPrincipalName, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute surname, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute eduPersonScopedAffiliation, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute givenName, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute eduPersonEntitlement, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute commonName, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:541] - Retaining attribute transientId which may be encoded to via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.970 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute eduPersonTargetedID, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:546] - Removing attribute telephoneNumber, it can not be encoded via edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:483] - Attempting to select name identifier attribute for relying party 'https://iam.eu-de.otc.t-systems.com' that requires format 'urn:oasis:names:tc:SAML:2.0:nameid-format:transient' 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:566] - Filtering out potential name identifier attributes which do not support one of the following formats: [urn:oasis:names:tc:SAML:2.0:nameid-format:transient] 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:585] - Retaining attribute transientId which may be encoded as a name identifier of format urn:oasis:names:tc:SAML:2.0:nameid-format:transient 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:690] - Selecting attribute to be encoded as a name identifier by encoder of type edu.internet2.middleware.shibboleth.common.attribute.encoding.SAML2NameIDEncoder 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:717] - Selecting the first attribute that can be encoded in to a name identifier 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:501] - Name identifier for relying party 'https://iam.eu-de.otc.t-systems.com' will be built from attribute 'transientId' 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:868] - Using attribute 'transientId' supporting NameID format 'urn:oasis:names:tc:SAML:2.0:nameid-format:transient' to create the NameID for relying party 'https://iam.eu-de.otc.t-systems.com' 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:572] - Determining if SAML assertion to relying party 'https://iam.eu-de.otc.t-systems.com' should be signed 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:653] - IdP relying party configuration 'default' indicates to sign assertions: true 02:52:21.971 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:583] - Determining signing credntial for assertion to relying party 'https://iam.eu-de.otc.t-systems.com' 02:52:21.972 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:599] - Signing assertion to relying party https://iam.eu-de.otc.t-systems.com 02:52:21.979 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:274] - Attempting to encrypt assertion to relying party 'https://iam.eu-de.otc.t-systems.com' 02:52:21.980 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:279] - Assertion to be encrypted is: https://idp.testshib.org/idp/shibboleth ga0HnNd5YiQesYFhnB3dxrCy6uzYMrRnCeOCvufvHvc= gRl8eo0c/RYXKTn4sxAklaRvTfX1MXcxEB5+NI+SuQjE2Z9q0lilf2+S0g1dgM4sch1DfOqxOdF+Zx2KbD4bFGQjAEr0FMqMdhN3XMZoU41Z4Q6kT0gdp2COIbWOzp4pO8EQaDIYPepvGL2x9SGCgtysZSWbIwyxDftUJnjuuQ4Ag21j604HTNG9mrgGfC8pSNhSPj5t4r4Tn5jgVteXE9wvnpysF6sQFP6Mq1bix2Ae0ZryG/uz8m1vT8lBjY4FGdD7dJjaG+aBubgvd5/t/8V5LLrPlsBkxwltvqHY6urMl4AfQQ66ZdZmYEgLNOSMY0DMUHA02j+6ptgPfb9XWQ== MIIDAzCCAeugAwIBAgIVAPX0G6LuoXnKS0Muei006mVSBXbvMA0GCSqGSIb3DQEBCwUAMBsxGTAX BgNVBAMMEGlkcC50ZXN0c2hpYi5vcmcwHhcNMTYwODIzMjEyMDU0WhcNMzYwODIzMjEyMDU0WjAb MRkwFwYDVQQDDBBpZHAudGVzdHNoaWIub3JnMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKC AQEAg9C4J2DiRTEhJAWzPt1S3ryhm3M2P3hPpwJwvt2q948vdTUxhhvNMuc3M3S4WNh6JYBs53R+ YmjqJAII4ShMGNEmlGnSVfHorex7IxikpuDPKV3SNf28mCAZbQrX+hWA+ann/uifVzqXktOjs6Dd zdBnxoVhniXgC8WCJwKcx6JO/hHsH1rG/0DSDeZFpTTcZHj4S9MlLNUtt5JxRzV/MmmB3ObaX0CM qsSWUOQeE4nylSlp5RWHCnx70cs9kwz5WrflnbnzCeHU2sdbNotBEeTHot6a2cj/pXlRJIgPsrL/ 4VSicPZcGYMJMPoLTJ8mdy6mpR6nbCmP7dVbCIm/DQIDAQABoz4wPDAdBgNVHQ4EFgQUUfaDa2mP i24x09yWp1OFXmZ2GPswGwYDVR0RBBQwEoIQaWRwLnRlc3RzaGliLm9yZzANBgkqhkiG9w0BAQsF AAOCAQEASKKgqTxhqBzROZ1eVy++si+eTTUQZU4+8UywSKLia2RattaAPMAcXUjO+3cYOQXLVASd lJtt+8QPdRkfp8SiJemHPXC8BES83pogJPYEGJsKo19l4XFJHPnPy+Dsn3mlJyOfAa8RyWBS80u5 lrvAcr2TJXt9fXgkYs7BOCigxtZoR8flceGRlAZ4p5FPPxQR6NDYb645jtOTMVr3zgfjP6Wh2dt+ 2p04LG7ENJn8/gEwtXVuXCsPoSCDx9Y0QmyXTJNdV1aB0AhORkWPlFYwp+zOyOIR+3m1+pqWFpn0 eT/HrxpdKa74FA3R2kq4R7dXe4G0kUgXTdqXMLRKhDgdmA== _32ff64f1de1fa2d03572543676be6721 https://iam.eu-de.otc.t-systems.com aE5SE3vm3leAHfAQjvjtkbKMLRJJlpZa9lt11MF5MFM= urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport alterego Member alterego@testshib.org Ego Member@testshib.org Alter urn:mace:dir:entitlement:common-lib-terms Alter Ego uriWcdYVZHXvGc6b8noOU8Ecaxs= 555-5555 02:52:21.982 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:796] - Encoding response to SAML request _3uvvkbjw3xk8g85j47tf9hipc5vzthg7c9nz from relying party https://iam.eu-de.otc.t-systems.com 02:52:21.983 - INFO [Shibboleth-Audit:1028] - 20181025T065221Z|urn:oasis:names:tc:SAML:2.0:bindings:SOAP|_3uvvkbjw3xk8g85j47tf9hipc5vzthg7c9nz|https://iam.eu-de.otc.t-systems.com|urn:oasis:names:tc:SAML:2.0:profiles:SSO:ecp|https://idp.testshib.org/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:SOAP|_858c8f41d4f3083172b4c469e02f124b|alterego||uid,eduPersonAffiliation,eduPersonPrincipalName,surname,eduPersonScopedAffiliation,givenName,eduPersonEntitlement,commonName,transientId,eduPersonTargetedID,telephoneNumber,|_32ff64f1de1fa2d03572543676be6721|| 02:53:09.934 - INFO [Shibboleth-Access:73] - 20181025T065309Z|171.49.140.111|idp.testshib.org:443|/profile/SAML2/Redirect/SSO| 02:53:09.934 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO 02:53:09.934 - 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 02:53:09.935 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - LoginContext key cookie was not present in request 02:53:09.935 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:188] - Incoming request does not contain a login context, processing as first leg of request 02:53:09.935 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:366] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect' 02:53:09.938 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://www.testshib.org 02:53:09.938 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://www.testshib.org, looking up configuration based on metadata groups. 02:53:09.939 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://www.testshib.org. Using default relying party configuration. 02:53:09.940 - WARN [org.opensaml.saml2.binding.security.SAML2AuthnRequestsSignedRule:81] - SPSSODescriptor role metadata for entityID 'https://www.testshib.org' could not be resolved 02:53:09.940 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:387] - Decoded request from relying party 'https://www.testshib.org' 02:53:09.941 - WARN [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:305] - No metadata for relying party https://www.testshib.org, treating party as anonymous 02:53:09.941 - WARN [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:222] - SAML 2 SSO profile is not configured for relying party https://www.testshib.org 02:54:34.849 - INFO [Shibboleth-Access:73] - 20181025T065434Z|47.99.79.28|idp.testshib.org:443|/profile/SAML2/Redirect/SSO| 02:54:34.849 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO 02:54:34.849 - 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 02:54:34.849 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - LoginContext key cookie was not present in request 02:54:34.849 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:188] - Incoming request does not contain a login context, processing as first leg of request 02:54:34.849 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:366] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect' 02:54:34.851 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://meta.vgtu.lt/shibboleth 02:54:34.852 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://meta.vgtu.lt/shibboleth, looking up configuration based on metadata groups. 02:54:34.852 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://meta.vgtu.lt/shibboleth. Using default relying party configuration. 02:54:34.852 - WARN [org.opensaml.saml2.binding.security.SAML2AuthnRequestsSignedRule:81] - SPSSODescriptor role metadata for entityID 'https://meta.vgtu.lt/shibboleth' could not be resolved 02:54:34.853 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:387] - Decoded request from relying party 'https://meta.vgtu.lt/shibboleth' 02:54:34.853 - WARN [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:305] - No metadata for relying party https://meta.vgtu.lt/shibboleth, treating party as anonymous 02:54:34.853 - WARN [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:222] - SAML 2 SSO profile is not configured for relying party https://meta.vgtu.lt/shibboleth 02:54:36.473 - INFO [Shibboleth-Access:73] - 20181025T065436Z|171.49.140.111|idp.testshib.org:443|/profile/SAML2/Redirect/SSO| 02:54:36.473 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO 02:54:36.473 - 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 02:54:36.473 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - LoginContext key cookie was not present in request 02:54:36.473 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:188] - Incoming request does not contain a login context, processing as first leg of request 02:54:36.473 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:366] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect' 02:54:36.475 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for http://localhost/simplesamlphp-1.16.2/www/module.php/saml/sp/metadata.php/default-sp 02:54:36.475 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for http://localhost/simplesamlphp-1.16.2/www/module.php/saml/sp/metadata.php/default-sp, looking up configuration based on metadata groups. 02:54:36.475 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for http://localhost/simplesamlphp-1.16.2/www/module.php/saml/sp/metadata.php/default-sp. Using default relying party configuration. 02:54:36.476 - WARN [org.opensaml.common.binding.security.MessageReplayRule:99] - Replay detected of message '_5676d4906a2c1f0f0eebe23de05454ecdffb48a2bd' from issuer http://localhost/simplesamlphp-1.16.2/www/module.php/saml/sp/metadata.php/default-sp 02:54:36.476 - WARN [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:406] - Message did not meet security requirements org.opensaml.ws.security.SecurityPolicyException: Rejecting replayed message ID '_5676d4906a2c1f0f0eebe23de05454ecdffb48a2bd' from issuer http://localhost/simplesamlphp-1.16.2/www/module.php/saml/sp/metadata.php/default-sp at org.opensaml.common.binding.security.MessageReplayRule.evaluate(MessageReplayRule.java:100) ~[opensaml-2.6.0.jar:na] at org.opensaml.ws.security.provider.BasicSecurityPolicy.evaluate(BasicSecurityPolicy.java:51) ~[openws-1.5.0.jar:na] at org.opensaml.ws.message.decoder.BaseMessageDecoder.processSecurityPolicy(BaseMessageDecoder.java:132) ~[openws-1.5.0.jar:na] at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:83) ~[openws-1.5.0.jar:na] at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:70) ~[opensaml-2.6.0.jar:na] at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler.java:386) [shibboleth-identityprovider-2.4.0.jar:na] at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfileHandler.java:211) [shibboleth-identityprovider-2.4.0.jar:na] at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandler.java:189) [shibboleth-identityprovider-2.4.0.jar:na] at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandler.java:90) [shibboleth-identityprovider-2.4.0.jar:na] at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:83) [shibboleth-common-1.4.0.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.36] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.36] at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50) [shibboleth-identityprovider-2.4.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.36] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.36] at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:87) [shibboleth-identityprovider-2.4.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.36] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.36] at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52) [shibboleth-common-1.4.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.36] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.36] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219) [catalina.jar:6.0.36] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina.jar:6.0.36] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:470) [catalina.jar:6.0.36] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina.jar:6.0.36] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:6.0.36] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina.jar:6.0.36] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) [catalina.jar:6.0.36] at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190) [tomcat-coyote.jar:6.0.36] at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:311) [tomcat-coyote.jar:6.0.36] at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:776) [tomcat-coyote.jar:6.0.36] at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:705) [tomcat-coyote.jar:6.0.36] at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:898) [tomcat-coyote.jar:6.0.36] at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) [tomcat-coyote.jar:6.0.36] at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55] 02:55:10.643 - INFO [Shibboleth-Access:73] - 20181025T065510Z|196.245.218.210|idp.testshib.org:443|/profile/SAML2/Redirect/SSO| 02:55:10.644 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO 02:55:10.644 - 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 02:55:10.644 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - LoginContext key cookie was not present in request 02:55:10.645 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:188] - Incoming request does not contain a login context, processing as first leg of request 02:55:10.645 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:366] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect' 02:55:10.649 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://we.love.cheetos/om/nom 02:55:10.649 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://we.love.cheetos/om/nom, looking up configuration based on metadata groups. 02:55:10.651 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://we.love.cheetos/om/nom. Using default relying party configuration. 02:55:10.652 - WARN [org.opensaml.saml2.binding.security.SAML2AuthnRequestsSignedRule:81] - SPSSODescriptor role metadata for entityID 'https://we.love.cheetos/om/nom' could not be resolved 02:55:10.653 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:387] - Decoded request from relying party 'https://we.love.cheetos/om/nom' 02:55:10.654 - WARN [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:305] - No metadata for relying party https://we.love.cheetos/om/nom, treating party as anonymous 02:55:10.654 - WARN [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:222] - SAML 2 SSO profile is not configured for relying party https://we.love.cheetos/om/nom 03:00:15.027 - INFO [Shibboleth-Access:73] - 20181025T070015Z|220.128.220.152|idp.testshib.org:443|/profile/SAML2/Redirect/SSO| 03:00:15.028 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO 03:00:15.028 - 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 03:00:15.028 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - LoginContext key cookie was not present in request 03:00:15.028 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:188] - Incoming request does not contain a login context, processing as first leg of request 03:00:15.029 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:366] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect' 03:00:15.034 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://sp.example.org/shibboleth 03:00:15.035 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://sp.example.org/shibboleth, looking up configuration based on metadata groups. 03:00:15.036 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://sp.example.org/shibboleth. Using default relying party configuration. 03:00:15.037 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:387] - Decoded request from relying party 'https://sp.example.org/shibboleth' 03:00:15.039 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://sp.example.org/shibboleth 03:00:15.039 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://sp.example.org/shibboleth, looking up configuration based on metadata groups. 03:00:15.040 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://sp.example.org/shibboleth. Using default relying party configuration. 03:00:15.041 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:226] - Creating login context and transferring control to authentication engine 03:00:15.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:181] - Storing LoginContext to StorageService partition loginContexts, key f55e77b85919e4b5023b65ac5d8b45d73f860088a47fa8d9ecdc54c51682bcc9 03:00:15.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:240] - Redirecting user to authentication engine at https://idp.testshib.org:443/idp/AuthnEngine 03:00:15.460 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request 03:00:15.461 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] - Beginning user authentication process. 03:00:15.461 - 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@356564a7, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@13b32b54} 03:00:15.461 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:332] - Filtering out previous session login handler because there is no existing IdP session 03:00:15.461 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:385] - Forced authentication is required, filtering possible login handlers accordingly 03:00:15.461 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:406] - Authentication handlers remaining after forced authentication requirement filtering: {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@13b32b54} 03:00:15.461 - 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@13b32b54} 03:00:15.461 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:497] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler 03:00:15.461 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66] - Redirecting to https://idp.testshib.org:443/idp/Authn/UserPassword 03:00:16.094 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150] - Redirecting to login page /login.jsp 03:00:22.503 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:170] - Attempting to authenticate user myself 03:00:22.503 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180] - useFirstPass = false 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181] - tryFirstPass = false 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182] - storePass = false 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183] - clearPass = false 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184] - setLdapPrincipal = true 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185] - setLdapDnPrincipal = false 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186] - setLdapCredential = true 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187] - defaultRole = [] 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188] - principalGroupName = null 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189] - roleGroupName = null 03:00:22.504 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77] - userRoleAttribute = [eduPersonAffiliation] 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83] - Created authenticator: edu.vt.middleware.ldap.auth.AuthenticatorConfig@268043128::env={java.naming.provider.url=ldap://idp.testshib.org:389, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory} 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN using userField 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the following parameters: 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = ou=people,dc=testshib,dc=org 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter = (uid={0}) 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs = [myself] 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls = javax.naming.directory.SearchControls@66f9c379 03:00:22.505 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@179071c0] 03:00:22.506 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with the following parameters: 03:00:22.506 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - authtype = simple 03:00:22.506 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - dn = null 03:00:22.506 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - credential = 03:00:22.508 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with the following parameters: 03:00:22.508 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - authtype = simple 03:00:22.508 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - dn = uid=myself,ou=people,dc=testshib,dc=org 03:00:22.508 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - credential = 03:00:22.509 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication succeeded for dn: uid=myself,ou=people,dc=testshib,dc=org 03:00:22.509 - DEBUG [edu.vt.middleware.ldap.jaas.JaasAuthenticator:215] - Returning attributes: 03:00:22.509 - DEBUG [edu.vt.middleware.ldap.jaas.JaasAuthenticator:216] - [eduPersonAffiliation] 03:00:22.510 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN using userField 03:00:22.510 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the following parameters: 03:00:22.510 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = ou=people,dc=testshib,dc=org 03:00:22.510 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter = (uid={0}) 03:00:22.510 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs = [myself] 03:00:22.510 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls = javax.naming.directory.SearchControls@67eb9164 03:00:22.510 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@179071c0] 03:00:22.511 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:223] - Committed the following principals: [myself[eduPersonAffiliation[Member, Staff]]] 03:00:22.511 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:229] - Committed the following roles: [Member, Staff] 03:00:22.511 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:178] - Successfully authenticated user myself 03:00:22.511 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:144] - Returning control to authentication engine 03:00:22.511 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request 03:00:22.511 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:514] - Completing user authentication process 03:00:22.511 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:585] - Validating authentication was performed successfully 03:00:22.511 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:696] - Updating session information for principal myself 03:00:22.511 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:700] - Creating shibboleth session for principal myself 03:00:22.512 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:815] - Adding IdP session cookie to HTTP response 03:00:22.512 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:715] - Recording authentication and service information in Shibboleth session for principal: myself 03:00:22.512 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:560] - User myself authenticated with method urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport 03:00:22.512 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] - Returning control to profile handler 03:00:22.512 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] - Redirecting user to profile handler at https://idp.testshib.org:443/idp/profile/SAML2/Redirect/SSO 03:00:22.723 - INFO [Shibboleth-Access:73] - 20181025T070022Z|220.128.220.152|idp.testshib.org:443|/profile/SAML2/Redirect/SSO| 03:00:22.723 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO 03:00:22.723 - 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 03:00:22.723 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:588] - Unbinding LoginContext 03:00:22.723 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:614] - Expiring LoginContext cookie 03:00:22.723 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:625] - Removed LoginContext, with key f55e77b85919e4b5023b65ac5d8b45d73f860088a47fa8d9ecdc54c51682bcc9, from StorageService partition loginContexts 03:00:22.723 - 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 03:00:22.725 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://sp.example.org/shibboleth 03:00:22.725 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://sp.example.org/shibboleth, looking up configuration based on metadata groups. 03:00:22.725 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://sp.example.org/shibboleth. Using default relying party configuration. 03:00:22.725 - WARN [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:206] - Relying party 'https://sp.example.org/shibboleth' requested the response to be returned to endpoint with ACS URL 'http://220.128.220.152/Shibboleth.sso/SAML2/POST' 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 03:00:22.726 - ERROR [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:447] - No return endpoint available for relying party https://sp.example.org/shibboleth