Broken service after idpv4 upgrade
Paul B. Henson
henson at cpp.edu
Sat Feb 20 02:13:00 UTC 2021
So we finally rolled out our v4 upgrade last night, which overall went pretty smoothly. There were a couple hiccups that were quickly isolated to known issues, service providers that didn't support the newer encryption default and needed to be configured to use the old one, and CAS services that tried to make callbacks using TLSv1.0 which we no longer support.
But there is a broken service that has left me stumped as to what is going on. Basically, when you attempt to authenticate, you are directed to the idp:
{"Response Headers (1.020 KB)":{"headers":[{"name":"Content-Encoding","value":"gzip"},{"name":"Date","value":"Sat, 20 Feb 2021 01:36:24 GMT"},{"name":"Location","value":"https://idp.cpp.edu/idp/profile/SAML2/Redirect/SSO?SAMLRequest=pZNRb9sgEMff9yks3mMcXGcZil1ZiSpFyjY3bvqwl4jiS4KEweNw2n77YVfZspeqUp9Ax939%2F%2FwOFrcvrY7O4FBZk5NpnJAIjLSNMsec7B7uJnNyW3xZoGh1x8ven8wWfveAPioRwflQtrQG%2BxZcDe6sJOy2m5ycvO%2BQUyq7btI51dr4ZNFDE8OLVk9O4dHZvoulbel4vB%2Biwr3SsD7DEx30NvaoDIlWQUwZ4UeDl76qCcVdF0PTD%2FvQxB6UBlqX3zeMbqFRDqSndf2TRHfWSRit5%2BQgNAKJ1quc7DORykTK%2BSzNmkwm6Ty7aeDbTSKEZF%2Bz2ZCGlUBUZ8iJd%2F0YwB7WBr0wPicsYdNJwiYseUimPJ1xlsXpfPaLRI8XoGwAGhAb5CPCnPTOcCtQITeiBeRe8sE0D5k83MJbaTUpRuB8lHNX9e%2BXi8tESPFZ%2Fsl0WW7qfbWrFvTKypsv1vEfQXy9qqxW8jUqtbbPSwfC%2FwUVmLfCv293iKhmchhTuXfCoALjSVRXQ%2Fv7Xmh1UOA%2B%2F5r%2B3eZ6GOyj06DFG4T%2FP0DxBw%3D%3D&RelayState=https%3A%2F%2Fcpp-primo.hosted.exlibrisgroup.com%2Fprimo-explore%2Fsearch%3Fvid%3D01CALS_PUP%26lang%3Den_US%26isIframeSSO%3Dtrue%26from-new-ui%3D1%26authenticationProfile%3D01CALS_PUP%2BShibboleth"},{"name":"Server","value":"Apache-Coyote/1.1"},{"name":"Transfer-Encoding","value":"chunked"},{"name":"vary","value":"accept-encoding"}]}}
The idp then redirects to:
Location: https://idp.cpp.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1
Then, with no request for a username/password or authentication, the browser ends up back at the service with an error message from the service same something didn't work. The request to https://idp.cpp.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1 doesn't show any response data in SAML tracer or Firefox network tracing, so I'm not sure at this point how the browser ends up back at the service.
I cranked up debugging, included at the bottom of the message. Basically, the last messages seen are:
2021-02-19 17:23:06,034 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.impl.ExtractProxiedRequestersHandler' on INBOUND message context
2021-02-19 17:23:06,034 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,157 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request
Then nothing else. I compared this to a SAML transaction that worked, and the next message after this in debugging output was:
2021-02-19 17:25:56,968 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.ui.csrf.impl.CSRFTokenFlowExecutionListener:165] - Event 'proceed' signaled from view 'LocalStorageRead' requires a CSRF token
There are no errors or warnings in the log output, and I don't see anything that jumps out at me is broken, it just doesn't ask for authentication.
Hopefully more knowledgeable eyes than mine will see the root cause for this strange behavior? Much thanks...
2021-02-19 17:23:05,986 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:243] - Profile Action PopulateAuditContext: Adding 1 value for field 'ST'
2021-02-19 17:23:05,987 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:51] - Exposing ProfileRequestContext in servlet request
2021-02-19 17:23:05,988 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.saml2.binding.decoding.impl.HTTPRedirectDeflateDecoder:99] - Decoded RelayState: https://cpp-primo.hosted.exlibrisgroup.com/primo-explore/search?vid=01CALS_PUP&lang=en_US&isIframeSSO=true&from-new-ui=1&authenticationProfile=01CALS_PUP+Shibboleth
2021-02-19 17:23:05,988 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.saml2.binding.decoding.impl.HTTPRedirectDeflateDecoder:133] - Base64 decoding and inflating SAML message
2021-02-19 17:23:05,990 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.saml2.binding.decoding.impl.HTTPRedirectDeflateDecoder:109] - Decoded SAML message
2021-02-19 17:23:05,991 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [PROTOCOL_MESSAGE:124] -
<?xml version="1.0" encoding="UTF-8"?><samlp:AuthnRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" AssertionConsumerServiceURL="https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/samlLogin" Destination="https://idp.cpp.edu/idp/profile/SAML2/Redirect/SSO" ForceAuthn="false" ID="_219b1484ecc4502e4e7b76866aa87bd4" IsPassive="true" IssueInstant="2021-02-20T01:23:05.118Z" Version="2.0">
<saml:Issuer xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP</saml:Issuer>
<saml2p:NameIDPolicy xmlns:saml2p="urn:oasis:names:tc:SAML:2.0:protocol" AllowCreate="true" Format="urn:oasis:names:tc:SAML:2.0:nameid-format:transient" SPNameQualifier="https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP"/>
</samlp:AuthnRequest>
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:243] - Profile Action PopulateAuditContext: Adding 1 value for field 'XX'
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'II' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'pasv' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'PSPQ' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:243] - Profile Action PopulateAuditContext: Adding 1 value for field 'b'
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'D' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'fauth' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'I' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'p' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'SPQ' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'pf' not included in audit format
2021-02-19 17:23:05,994 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'SM' not included in audit format
2021-02-19 17:23:05,995 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.CheckMessageVersionHandler' on INBOUND message context
2021-02-19 17:23:05,995 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:05,996 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml1.binding.impl.SAML1ArtifactRequestIssuerHandler' on INBOUND message context
2021-02-19 17:23:05,996 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:05,996 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.saml1.binding.impl.SAML1ArtifactRequestIssuerHandler:79] - Message Handler: Request message not set, or not of an applicable type
2021-02-19 17:23:05,996 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLProtocolAndRoleHandler' on INBOUND message context
2021-02-19 17:23:05,997 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:05,998 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler' on INBOUND message context
2021-02-19 17:23:05,998 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:05,998 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:748] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Found entityID in criteria: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:05,998 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:669] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Resolved criteria to entityID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:05,998 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:455] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Metadata backing store does not contain any EntityDescriptors with the ID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:05,999 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:684] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Did not find requested metadata in backing store, attempting to resolve dynamically
2021-02-19 17:23:05,999 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:801] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Resolving from origin source based on entityID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:05,999 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:455] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Metadata backing store does not contain any EntityDescriptors with the ID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:05,999 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:837] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Resolving metadata dynamically for entity ID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:05,999 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.LocalDynamicMetadataResolver:120] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Attempting to load from local source manager with generated key '25b44613f7efa4b50a2d58141af1879e75d208be.xml'
2021-02-19 17:23:06,002 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.LocalDynamicMetadataResolver:126] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Found no target in local source manager with key '25b44613f7efa4b50a2d58141af1879e75d208be.xml'
2021-02-19 17:23:06,002 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:849] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: No metadata was fetched from the origin source
2021-02-19 17:23:06,002 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:455] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Metadata backing store does not contain any EntityDescriptors with the ID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:06,002 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:606] - Metadata Resolver LocalDynamicMetadataResolver cpp-saml: Candidates iteration was empty, nothing to filter via predicates
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:455] - Metadata Resolver FilesystemMetadataResolver cpp-cas: Metadata backing store does not contain any EntityDescriptors with the ID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractBatchMetadataResolver:178] - Metadata Resolver FilesystemMetadataResolver cpp-cas: Resolved 0 candidates via EntityIdCriterion: EntityIdCriterion [id=https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP]
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:606] - Metadata Resolver FilesystemMetadataResolver cpp-cas: Candidates iteration was empty, nothing to filter via predicates
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:455] - Metadata Resolver FileBackedHTTPMetadataResolver ADFSTrust: Metadata backing store does not contain any EntityDescriptors with the ID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractBatchMetadataResolver:178] - Metadata Resolver FileBackedHTTPMetadataResolver ADFSTrust: Resolved 0 candidates via EntityIdCriterion: EntityIdCriterion [id=https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP]
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:606] - Metadata Resolver FileBackedHTTPMetadataResolver ADFSTrust: Candidates iteration was empty, nothing to filter via predicates
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:748] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: Found entityID in criteria: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:669] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: Resolved criteria to entityID: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractDynamicMetadataResolver:692] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: Found requested metadata in backing store
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:610] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: Attempting to filter candidate EntityDescriptors via resolved Predicates
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:615] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: Resolved 0 Predicates: []
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:623] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: CriteriaSet did NOT contain SatisfyAnyCriterion
2021-02-19 17:23:06,003 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:627] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: Effective satisyAny value: false
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:632] - Metadata Resolver FunctionDrivenDynamicHTTPMetadataResolver incommon-mdq: After predicate filtering 1 EntityDescriptors remain
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:267] - Resolved 1 source EntityDescriptors
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:277] - Resolved 1 RoleDescriptor candidates via role criteria, performing predicate filtering
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:378] - Attempting to filter candidate RoleDescriptors via resolved Predicates
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:383] - Resolved 0 Predicates: []
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:391] - CriteriaSet did NOT contain SatisfyAnyCriterion
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:395] - Effective satisyAny value: false
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:400] - After predicate filtering 1 RoleDescriptors remain
2021-02-19 17:23:06,004 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler:183] - Message Handler: org.opensaml.saml.common.messaging.context.SAMLMetadataContext added to MessageContext as child of org.opensaml.saml.common.messaging.context.SAMLPeerEntityContext
2021-02-19 17:23:06,005 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler' on INBOUND message context
2021-02-19 17:23:06,005 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,005 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler:154] - Message Handler: Selecting default AttributeConsumingService, if any
2021-02-19 17:23:06,005 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:186] - Resolving AttributeConsumingService candidates from SPSSODescriptor
2021-02-19 17:23:06,005 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:141] - AttributeConsumingService candidate list was empty, can not select service
2021-02-19 17:23:06,005 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler:163] - Message Handler: No AttributeConsumingService selected
2021-02-19 17:23:06,006 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.saml.saml2.profile.impl.MapRequestedAttributesInAttributeConsumingService:108] - Profile Action MapRequestedAttributesInAttributeConsumingService: AttributeConsumingServiceContext not found
2021-02-19 17:23:06,006 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeRelyingPartyContextFromSAMLPeer:131] - Profile Action InitializeRelyingPartyContextFromSAMLPeer: Attaching RelyingPartyContext based on SAML peer https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:06,008 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:249] - Resolving relying party configuration
2021-02-19 17:23:06,008 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:269] - No relying party configurations are applicable, returning the default configuration shibboleth.DefaultRelyingParty
2021-02-19 17:23:06,008 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.SelectRelyingPartyConfiguration:136] - Profile Action SelectRelyingPartyConfiguration: Found relying party configuration shibboleth.DefaultRelyingParty for request
2021-02-19 17:23:06,012 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:228] - Profile Action PopulateAuditContext: Skipping field 'IDP' not included in audit format
2021-02-19 17:23:06,012 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:243] - Profile Action PopulateAuditContext: Adding 1 value for field 'SP'
2021-02-19 17:23:06,012 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'securityConfiguration'
2021-02-19 17:23:06,013 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'securityConfiguration'
2021-02-19 17:23:06,013 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.PopulateProfileInterceptorContext:116] - Profile Action PopulateProfileInterceptorContext: Installing flow intercept/security-policy/saml2-sso into interceptor context
2021-02-19 17:23:06,015 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2021-02-19 17:23:06,015 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:101] - Profile Action SelectProfileInterceptorFlow: Checking flow intercept/security-policy/saml2-sso for applicability...
2021-02-19 17:23:06,015 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:84] - Profile Action SelectProfileInterceptorFlow: Selecting flow intercept/security-policy/saml2-sso
2021-02-19 17:23:06,016 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler' on INBOUND message context
2021-02-19 17:23:06,016 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,016 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:156] - Message Handler: Checking SAML message intended destination endpoint against receiver endpoint
2021-02-19 17:23:06,016 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:188] - Message Handler: Intended message destination endpoint: https://idp.cpp.edu/idp/profile/SAML2/Redirect/SSO
2021-02-19 17:23:06,016 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:189] - Message Handler: Actual message receiver endpoint: https://idp.cpp.edu/idp/profile/SAML2/Redirect/SSO
2021-02-19 17:23:06,016 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:202] - Message Handler: SAML message intended destination endpoint matched recipient endpoint
2021-02-19 17:23:06,017 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.MessageReplaySecurityHandler' on INBOUND message context
2021-02-19 17:23:06,017 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,017 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.MessageReplaySecurityHandler:154] - Message Handler: Evaluating message replay for message ID '_219b1484ecc4502e4e7b76866aa87bd4', issue instant '2021-02-20T01:23:05.118Z', entityID 'https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP'
2021-02-19 17:23:06,018 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.MessageLifetimeSecurityHandler' on INBOUND message context
2021-02-19 17:23:06,018 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,018 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.security.impl.SAML2AuthnRequestsSignedSecurityHandler' on INBOUND message context
2021-02-19 17:23:06,018 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,019 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.saml2.binding.security.impl.SAML2AuthnRequestsSignedSecurityHandler:82] - SPSSODescriptor for entity ID 'https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP' does not require AuthnRequests to be signed
2021-02-19 17:23:06,019 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'ignoreRequestSignatures'
2021-02-19 17:23:06,019 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.SAMLProtocolMessageXMLSignatureSecurityHandler' on INBOUND message context
2021-02-19 17:23:06,019 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,019 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.SAMLProtocolMessageXMLSignatureSecurityHandler:103] - Message Handler: SAML protocol message was not signed, skipping XML signature processing
2021-02-19 17:23:06,020 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:264] - Returning cached property 'ignoreRequestSignatures'
2021-02-19 17:23:06,020 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPRedirectDeflateSignatureSecurityHandler' on INBOUND message context
2021-02-19 17:23:06,020 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,020 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:149] - Message Handler: Evaluating simple signature rule of type: org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPRedirectDeflateSignatureSecurityHandler
2021-02-19 17:23:06,020 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:158] - Message Handler: HTTP request was not signed via simple signature mechanism, skipping
2021-02-19 17:23:06,021 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:264] - Returning cached property 'ignoreRequestSignatures'
2021-02-19 17:23:06,021 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPPostSimpleSignSecurityHandler' on INBOUND message context
2021-02-19 17:23:06,021 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,021 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:149] - Message Handler: Evaluating simple signature rule of type: org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPPostSimpleSignSecurityHandler
2021-02-19 17:23:06,021 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:152] - Message Handler: Handler can not handle this request, skipping
2021-02-19 17:23:06,021 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.CheckMandatoryIssuer' on INBOUND message context
2021-02-19 17:23:06,021 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,022 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.WriteProfileInterceptorResultToStorage:69] - Profile Action WriteProfileInterceptorResultToStorage: No results available from interceptor context, nothing to store
2021-02-19 17:23:06,022 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:65] - Profile Action SelectProfileInterceptorFlow: Moving completed flow intercept/security-policy/saml2-sso to completed set, selecting next one
2021-02-19 17:23:06,022 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:80] - Profile Action SelectProfileInterceptorFlow: No flows available to choose from
2021-02-19 17:23:06,022 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeOutboundMessageContext:153] - Profile Action InitializeOutboundMessageContext: Initialized outbound message context
2021-02-19 17:23:06,023 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'skipEndpointValidationWhenSigned'
2021-02-19 17:23:06,023 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:385] - Profile Action PopulateBindingAndEndpointContexts: Attempting to resolve endpoint of type {urn:oasis:names:tc:SAML:2.0:metadata}AssertionConsumerService for outbound message
2021-02-19 17:23:06,023 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:400] - Profile Action PopulateBindingAndEndpointContexts: Candidate outbound bindings: [urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST, urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST-SimpleSign]
2021-02-19 17:23:06,023 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:518] - Profile Action PopulateBindingAndEndpointContexts: Populating template endpoint for resolution from SAML AuthnRequest
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.AbstractEndpointResolver:218] - Endpoint Resolver org.opensaml.saml.common.binding.impl.DefaultEndpointResolver: Returning 2 candidate endpoints of type {urn:oasis:names:tc:SAML:2.0:metadata}AssertionConsumerService
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.DefaultEndpointResolver:126] - Endpoint Resolver org.opensaml.saml.common.binding.impl.DefaultEndpointResolver: Neither candidate endpoint location 'https://calstate-primoprod.hosted.exlibrisgroup.com/primo_library/libweb/samlLogin' nor response location 'null' matched 'https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/samlLogin'
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:428] - Profile Action PopulateBindingAndEndpointContexts: Resolved endpoint at location https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/samlLogin using binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'allowDelegation'
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:382] - No AttributeConsumingService was resolved, won't be able to determine delegation requested status via metadata
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:515] - No AttributeConsumingService was available
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:500] - Delegation request was not explicitly indicated, using default value: NOT_REQUESTED
2021-02-19 17:23:06,024 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:289] - Issuance of a delegated Assertion is not in effect, skipping further processing
2021-02-19 17:23:06,025 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'signResponses'
2021-02-19 17:23:06,025 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:210] - Profile Action PopulateSignatureSigningParameters: Signing enabled
2021-02-19 17:23:06,025 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.PopulateSignatureSigningParametersHandler:192] - Message Handler: Signing enabled
2021-02-19 17:23:06,025 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.PopulateSignatureSigningParametersHandler:204] - Message Handler: Resolving SignatureSigningParameters for request
2021-02-19 17:23:06,025 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'securityConfiguration'
2021-02-19 17:23:06,026 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.PopulateSignatureSigningParametersHandler:234] - Message Handler: Adding metadata to resolution criteria for signing/digest algorithms
2021-02-19 17:23:06,026 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.binding.impl.PopulateSignatureSigningParametersHandler:245] - Message Handler: Resolved SignatureSigningParameters
2021-02-19 17:23:06,028 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'signAssertions'
2021-02-19 17:23:06,028 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:213] - Profile Action PopulateSignatureSigningParameters: Signing not enabled
2021-02-19 17:23:06,028 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'encryptNameIDs'
2021-02-19 17:23:06,028 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'encryptionOptional'
2021-02-19 17:23:06,028 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'encryptAssertions'
2021-02-19 17:23:06,028 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'encryptAttributes'
2021-02-19 17:23:06,029 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'securityConfiguration'
2021-02-19 17:23:06,029 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:292] - Profile Action PopulateEncryptionParameters: Encryption for assertions (true), identifiers (false), attributes(false)
2021-02-19 17:23:06,029 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:302] - Profile Action PopulateEncryptionParameters: Resolving EncryptionParameters for request
2021-02-19 17:23:06,029 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:367] - Profile Action PopulateEncryptionParameters: Adding entityID to resolution criteria
2021-02-19 17:23:06,029 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:378] - Profile Action PopulateEncryptionParameters: Adding role metadata to resolution criteria
2021-02-19 17:23:06,029 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.security.impl.MetadataCredentialResolver:258] - Resolving credentials from supplied RoleDescriptor using usage: ENCRYPTION. Effective entityID was: https://cpp-primo.hosted.exlibrisgroup.com/primo_library/libweb/01CALS_PUP
2021-02-19 17:23:06,029 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.security.impl.MetadataCredentialResolver:350] - Resolved cached credentials from KeyDescriptor object metadata
2021-02-19 17:23:06,030 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.security.impl.SAMLMetadataEncryptionParametersResolver:150] - Evaluating key transport encryption credential from SAML metadata of type: RSA
2021-02-19 17:23:06,030 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.security.impl.SAMLMetadataEncryptionParametersResolver:382] - Evaluating SAML metadata EncryptionMethod algorithm for data encryption: http://www.w3.org/2001/04/xmlenc#aes128-cbc
2021-02-19 17:23:06,030 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.security.impl.SAMLMetadataEncryptionParametersResolver:387] - Resolved data encryption algorithm URI from SAML metadata EncryptionMethod: http://www.w3.org/2001/04/xmlenc#aes128-cbc
2021-02-19 17:23:06,030 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [org.opensaml.saml.security.impl.SAMLMetadataEncryptionParametersResolver:327] - Evaluating SAML metadata EncryptionMethod algorithm for key transport: http://www.w3.org/2001/04/xmlenc#aes128-cbc
2021-02-19 17:23:06,030 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.security.impl.SAMLMetadataEncryptionParametersResolver:350] - Could not resolve key transport algorithm based on SAML metadata, falling back to locally configured algorithms
2021-02-19 17:23:06,030 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:318] - Profile Action PopulateEncryptionParameters: Resolved EncryptionParameters
2021-02-19 17:23:06,030 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.config.AbstractMetadataDrivenConfigurationLookupStrategy:322] - No applicable mapped tag, applying default strategy for 'securityConfiguration'
2021-02-19 17:23:06,032 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:143] - Profile Action ExtractSubjectFromRequest: No Subject NameID/NameIdentifier in message needs inbound processing
2021-02-19 17:23:06,033 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [org.opensaml.saml.common.profile.impl.VerifyChannelBindings:156] - Profile Action VerifyChannelBindings: No channel bindings found to verify, nothing to do
2021-02-19 17:23:06,034 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:169] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.impl.ExtractProxiedRequestersHandler' on INBOUND message context
2021-02-19 17:23:06,034 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:190] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl'
2021-02-19 17:23:06,157 - 10.104.223.243/node0wiu272su6wgh1w0qphwvw5bac772 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request
--
Paul B. Henson | (909) 979-6361 | http://www.cpp.edu/~henson/
Operating Systems and Network Analyst | henson at cpp.edu
California State Polytechnic University | Pomona CA 91768
More information about the users
mailing list