By: Mahendran Mookkiah user 06 Feb 2020 at 4:02 a.m. CST

9 Responses
Mahendran Mookkiah gravatar
## Precondition * Setup SP (https://simplesamlphp.org/) with IDP metadata from gluu IDP url http://gluu.domain/idp/shibboleth * Get SP metadata * Add SAML Trust Relationship (TR) with with SP metadata and configure relying party with SAML2SSO profile ## Expected Behavior When SAML request arrives oxshibboleth, it should to redirect to login screen and after succesful login, oxshibboleth should redirect the request to SP with SAML response. ## Actual Behavior When SAML request arrives oxshibboleth it is redirecting the request to oxauth with a client_id which is not recognized by oxauth. This result to error json respnse in the screen. ## Logs I can see oxshiboleth log getting this request ``` 2020-02-06 09:16:35,545 - DEBUG [PROTOCOL_MESSAGE:127] - <samlp:AuthnRequest AssertionConsumerServiceURL="https://sp.domain/simplesaml/module.php/saml/sp/saml2-acs.php/default-sp" Destination="https://gluu.domain/idp/profile/SAML2/Redirect/SSO" ID="_0b75b7056e1f1b6479a074049115ad7dd742bd599f" IssueInstant="2020-02-06T09:16:34Z" ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST" Version="2.0" xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion" xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"> <saml:Issuer>https://sp.domain/simplesaml/module.php/saml/sp/metadata.php/default-sp</saml:Issuer> <samlp:NameIDPolicy Format="urn:oasis:names:tc:SAML:2.0:nameid-format:transient"/> </samlp:AuthnRequest> ``` After some log statements (looks normal to me) I see redirect url is generated ``` 2020-02-06 09:16:35,752 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:115] - Profile Action InitializeAuthenticationContext: Created authentication context: AuthenticationContext{initiationInstant=2020-02-06T09:16:35.752Z, isPassive=false, forceAuthn=false, hintedName=null, potentialFlows=[], activeResults=[], attemptedFlow=null, signaledFlowId=null, authenticationStateMap={}, resultCacheable=true, initialAuthenticationResult=null, authenticationResult=null, completionInstant=1970-01-01T00:00:00.000Z} 2020-02-06 09:16:35,759 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.ProcessRequestedAuthnContext:174] - Profile Action ProcessRequestedAuthnContext: AuthnRequest did not contain a RequestedAuthnContext, nothing to do 2020-02-06 09:16:35,766 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:200] - Profile Action PopulateAuthenticationContext: Installed 1 potential authentication flows into AuthenticationContext 2020-02-06 09:16:35,772 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client 2020-02-06 09:16:35,785 - DEBUG [net.shibboleth.idp.authn.impl.InitializeRequestedPrincipalContext:152] - Profile Action InitializeRequestedPrincipalContext: Profile configuration did not supply any default authentication methods 2020-02-06 09:16:35,786 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile Action FilterFlowsByForcedAuthn: Request does not have forced authentication requirement, nothing to do 2020-02-06 09:16:35,787 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do 2020-02-06 09:16:35,794 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:255] - Profile Action SelectAuthenticationFlow: No specific Principals requested 2020-02-06 09:16:35,795 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:290] - Profile Action SelectAuthenticationFlow: No usable active results available, selecting an inactive flow 2020-02-06 09:16:35,795 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/oxAuth 2020-02-06 09:16:37,080 - DEBUG [org.gluu.oxauth.client.OpenIdClient:263] - oxAuth authorization code: 'null' 2020-02-06 09:16:37,080 - DEBUG [org.gluu.oxauth.client.OpenIdClient:266] - Is authorization request: 'false' 2020-02-06 09:16:37,081 - DEBUG [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:118] - Initiating oxAuth login redirect 2020-02-06 09:16:37,082 - DEBUG [org.gluu.oxauth.client.OpenIdClient:234] - oxAuth redirection Url: 'https://gluu.domain/oxauth/restv1/authorize?response_type=code&client_id=%40%21D50B.5011.F718.9A77%210001%215E4A.7A3B%210008%21B1E2.822E&scope=openid+email+user_name&redirect_uri=https%3A%2F%2Fgluu.domain%2Fidp%2FAuthn%2FoxAuth&state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJjb252ZXJzYXRpb24iOiJlOXMxIiwic3RhdGUiOiJNeDk3aDhhQ3hwIn0.&nonce=kkEs3N59Q2&entityId=https://sp.domain/simplesaml/module.php/saml/sp/metadata.php/default-sp' 2020-02-06 09:16:37,082 - DEBUG [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:188] - Generated redirection Url 2020-02-06 09:16:37,082 - DEBUG [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:190] - loginUrl: https://gluu.domain/oxauth/restv1/authorize?response_type=code&client_id=%40%21D50B.5011.F718.9A77%210001%215E4A.7A3B%210008%21B1E2.822E&scope=openid+email+user_name&redirect_uri=https%3A%2F%2Fgluu.domain%2Fidp%2FAuthn%2FoxAuth&state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJjb252ZXJzYXRpb24iOiJlOXMxIiwic3RhdGUiOiJNeDk3aDhhQ3hwIn0.&nonce=kkEs3N59Q2&entityId=https://sp.domain/simplesaml/module.php/saml/sp/metadata.php/default-sp ``` This redirect results into error with below message. ``` {"error":"unauthorized_client","error_description":"The client is not authorized to request an access token using this method.","state":"eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJjb252ZXJzYXRpb24iOiJlOXMxIiwic3RhdGUiOiJNeDk3aDhhQ3hwIn0."} ``` Please shed some light on how oxshibboleth gets this client_id and/or how to make oxauth to authrize this client to proceed to login screen.

By Mohit Mali staff 06 Feb 2020 at 6:05 a.m. CST

Mohit Mali gravatar
Hi Mahendran, Thank you for reaching out gluu support , Let me help you on this , can you test the saml by using the following steps. 1) Go to https://sptest.iamshowcase.com/ 2) Navigate to instruction --> Idp inititated SSO. 3) download the meta data xml 4) Login to gluu server 5) Add trust relationship with downloaded metadata 6) configured nameid (if requried) 7) back to https://sptest.iamshowcase.com/ 8) place the content of https://yourgluuserver/idp/shibboleth. 9) on completion you will get the link to test SSO 10) Test the SSO flow. Thanks and Regards Mohit Mali

By Mahendran Mookkiah user 06 Feb 2020 at 10:34 a.m. CST

Mahendran Mookkiah gravatar
As per the instruction I have configured TR with iamshowcase SP and got the url. Configured to release attributes - First Name, Last Name, Username, Email Configured RP with SAML2SSO when I do GET request, I see below error in the browser. Web Login Service - Unsupported Request The application you have accessed is not registered for use with this service. Get request and response: ``` GET https://sptest.iamshowcase.com/ixs?idp=052a6966dfc99ae3302f48eeab16c820f22ffaf0 HTTP/1.1 Upgrade-Insecure-Requests: 1 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.130 Safari/537.36 Sec-Fetch-User: ?1 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 Sec-Fetch-Site: none Sec-Fetch-Mode: navigate Accept-Encoding: gzip, deflate, br Accept-Language: en-US,en;q=0.9,ta;q=0.8 Cookie: _sm_au_c=kaVESAHFtz3EP13/4wBVMT/mjLZnyMRak2VP+QXcIf5IgAAAAflKHwBID94gdpoEzCtoKDqH9jGhL75042rdOECQGF/8=; _ga=GA1.2.1333813428.1580954667; _gid=GA1.2.1949474665.1580954667 HTTP/1.1 302 302 Date: Thu, 06 Feb 2020 16:06:44 GMT Server: Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips PHP/5.4.16 Pragma: no-cache Cache-Control: no-cache Expires: Thu, 01 Jan 1970 00:00:00 GMT Set-Cookie: JSESSIONID=85C6A9504B719FC7F798106553F1C3D7; Path=/; HttpOnly Location: https://gluu.domain/idp/profile/SAML2/Redirect/SSO?SAMLRequest=fVHRTsJAEPyV5t7pnQUpXChJlRhJIBBaffBte13gYntXb6%2Fq51sKRnzhcTOzMzuzM4K6amTa%2BqPZ4UeL5IPvujIkeyBhrTPSAmmSBmok6ZXM0vVKRqGQjbPeKluxq5XbG0CEzmtrWPBkncLeN2F7qAhZsFwkDIr7UuB0NAWFYxhiHAHABEU8nMaxEvF%2BMsFhAUXR0YlaXBryYHzCIhGJgYgGYpzfjaUYy9HojQWLLpA2cLJM2NH7hiTnh6ptw%2FdShZU96A5XFCrrGq7LhneZ9rpCfjo54jsstUPleZZtWJD%2BXv9oDbU1ugzdp1b4slv9iVPjO89QQ01H%2B6WAsBOvOShiQbC9NPagTanN4XZZxZlE8jnPt4PtJss7heAVHfVpOgqbz06dy74JN1%2Bm6%2BziOePXwHn6%2F%2Bb5Dw%3D%3D Content-Type: text/html;charset=UTF-8 Content-Length: 0 Access-Control-Allow-Origin: * ``` The idp-process.log shows ``` 2020-02-06 16:12:33,470 - DEBUG [org.opensaml.core.xml.util.XMLObjectSupport:313] - XMLObject already had cached DOM, returning that element 2020-02-06 16:12:33,471 - DEBUG [PROTOCOL_MESSAGE:127] - <samlp:AuthnRequest AssertionConsumerServiceURL="https://sptest.iamshowcase.com/acs" Destination="https://gluu.domain/idp/profile/SAML2/Redirect/SSO" ForceAuthn="false" ID="a8433a7efbf487fb3f7e88e71eb685a57ff3bcb14" IssueInstant="2020-02-06T16:12:33Z" ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST" Version="2.0" xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion" xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"> <saml:Issuer>IAMShowcase</saml:Issuer> </samlp:AuthnRequest> 2020-02-06 16:12:33,471 - DEBUG [org.opensaml.messaging.decoder.servlet.BaseHttpServletRequestXMLMessageDecoder:76] - Successfully decoded message from HttpServletRequest. 2020-02-06 16:12:33,472 - DEBUG [org.opensaml.profile.action.impl.DecodeMessage:68] - Profile Action DecodeMessage: Incoming request decoded into a message of type org.opensaml.saml.saml2.core.impl.AuthnRequestImpl 2020-02-06 16:12:33,473 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.CheckMessageVersionHandler' on INBOUND message context 2020-02-06 16:12:33,474 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-06 16:12:33,474 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-06 16:12:33,475 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml1.binding.impl.SAML1ArtifactRequestIssuerHandler' on INBOUND message context 2020-02-06 16:12:33,475 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-06 16:12:33,475 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-06 16:12:33,476 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLProtocolAndRoleHandler' on INBOUND message context 2020-02-06 16:12:33,476 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-06 16:12:33,476 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-06 16:12:33,477 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler' on INBOUND message context 2020-02-06 16:12:33,478 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-06 16:12:33,478 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-06 16:12:33,478 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:434] - Metadata Resolver FilesystemMetadataResolver SiteSP1: Metadata backing store does not contain any EntityDescriptors with the ID: IAMShowcase 2020-02-06 16:12:33,479 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractBatchMetadataResolver:162] - Metadata Resolver FilesystemMetadataResolver SiteSP1: Resolved 0 candidates via EntityIdCriterion: EntityIdCriterion [id=IAMShowcase] 2020-02-06 16:12:33,479 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:586] - Metadata Resolver FilesystemMetadataResolver SiteSP1: Candidates iteration was empty, nothing to filter via predicates 2020-02-06 16:12:33,479 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:260] - Resolved no EntityDescriptors via underlying MetadataResolver, returning empty collection 2020-02-06 16:12:33,480 - INFO [org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler:128] - Message Handler: No metadata returned for IAMShowcase in role {urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor with protocol urn:oasis:names:tc:SAML:2.0:protocol 2020-02-06 16:12:33,480 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler' on INBOUND message context 2020-02-06 16:12:33,480 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-06 16:12:33,481 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-06 16:12:33,481 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler:110] - Message Handler: No metadata context found, nothing to do 2020-02-06 16:12:33,481 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeRelyingPartyContextFromSAMLPeer:132] - Profile Action InitializeRelyingPartyContextFromSAMLPeer: Attaching RelyingPartyContext based on SAML peer IAMShowcase 2020-02-06 16:12:33,482 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:293] - Resolving relying party configuration 2020-02-06 16:12:33,482 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:299] - Profile request is unverified, returning configuration shibboleth.UnverifiedRelyingParty 2020-02-06 16:12:33,482 - DEBUG [net.shibboleth.idp.profile.impl.SelectRelyingPartyConfiguration:136] - Profile Action SelectRelyingPartyConfiguration: Found relying party configuration shibboleth.UnverifiedRelyingParty for request 2020-02-06 16:12:33,483 - WARN [net.shibboleth.idp.profile.impl.SelectProfileConfiguration:111] - Profile Action SelectProfileConfiguration: Profile http://shibboleth.net/ns/profiles/saml2/sso/browser is not available for RP configuration shibboleth.UnverifiedRelyingParty (RPID IAMShowcase) 2020-02-06 16:12:33,484 - WARN [org.opensaml.profile.action.impl.LogEvent:105] - A non-proceed event occurred while processing the request: InvalidProfileConfiguration 2020-02-06 16:12:33,484 - DEBUG [org.opensaml.saml.common.profile.logic.DefaultLocalErrorPredicate:154] - No SAMLBindingContext or binding URI available, error must be handled locally 2020-02-06 16:12:33,489 - DEBUG [org.apache.velocity:100] - No class specified for #evaluate() context, so #set calls will now alter the global context and no longer be local. This is a change from earlier versions due to VELOCITY-704. If you need references within #evaluate to stay local, please use the automatically provided $evaluate namespace instead (e.g. #set($evaluate.foo = 'bar') and $evaluate.foo). ```

By Mohit Mali staff 10 Feb 2020 at 4:58 a.m. CST

Mohit Mali gravatar
Hi Mahendran, I have just tested it with sptest , its working fine for me , you can check screenshot. Please send me screenshot or short video of what you are doing so i can figured it out what goes wrong. Thanks and Regards Mohit Mali

By Mahendran Mookkiah user 11 Feb 2020 at 3:21 a.m. CST

Mahendran Mookkiah gravatar
Hi @Mohit.Mali, Once I did a fresh setup with release 3.1.6.sp1, I see it started working. Then I compared with previous instance (which uses version 3.1.4.Final). I noticed the OpenID connect "IDP Client" is missing on the problematic environment. May be it is missing in older version or I would have deleted. I will try creating the IDP Client by referring the configuration from new instance and let you know if that solved the problem or not. I wonder, how oxshibboleth picks up a client ID which is not shown OIDC clients list (identity/client/clientInventory.htm) for redirecting to oxauth. https://gluu.domain/oxauth/restv1/authorize?response_type=code&client_id=%40%21D50B.5011.F718.9A77%210001%215E4A.7A3B%210008%21B1E2.822E Please help me where I can find the client ID in opendj/oxshibboleth as I may need to update one I create the new IDP Client. Thanks, Mahendran.

By Mohit Mali staff 13 Feb 2020 at 12:07 a.m. CST

Mohit Mali gravatar
hi Mahendran, Can you please let me know what you are trying to achieve ? SAML SSO or OPENID CONNECT ? Thanks and Regards Mohit Mali

By Mahendran Mookkiah user 14 Feb 2020 at 3:05 a.m. CST

Mahendran Mookkiah gravatar
I am trying to achieve SAML SSO. Here is the reason why I am looking at OIDC.. in the first log we see ``` 2020-02-06 09:16:37,081 - DEBUG [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:118] - Initiating oxAuth login redirect ``` which end up building a redirect url with client ID which is not authorized client_id=%40%21D50B.5011.F718.9A77%210001%215E4A.7A3B%210008%21B1E2.822E Thats the reason I started looking for where this client is configured..

By Mohit Mali staff 14 Feb 2020 at 3:46 a.m. CST

Mohit Mali gravatar
Hi Mahendran Mookkiah, For SAML you don't need to look at openid connect , SAML SSO is independent as i mentioned above steps are working without openid connect. Thanks and regards Mohit Mali

By Mahendran Mookkiah user 14 Feb 2020 at 4:22 a.m. CST

Mahendran Mookkiah gravatar
HI Mohit Mali, Thanks for clarification. On the new setup I dont see the redirection URL building in log ``` 2020-02-14 09:55:32,333 - DEBUG [net.shibboleth.idp.authn.impl.InitializeRequestedPrincipalContext:152] - Profile Action InitializeRequestedPrincipalContext: Profile configuration did not supply any default authentication methods 2020-02-14 09:55:32,334 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile Action FilterFlowsByForcedAuthn: Request does not have forced authentication requirement, nothing to do 2020-02-14 09:55:32,335 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do 2020-02-14 09:55:32,336 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:255] - Profile Action SelectAuthenticationFlow: No specific Principals requested 2020-02-14 09:55:32,337 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:290] - Profile Action SelectAuthenticationFlow: No usable active results available, selecting an inactive flow 2020-02-14 09:55:32,338 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/oxAuth 2020-02-14 09:55:42,364 - INFO [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:130] - Procession authorization response 2020-02-14 09:55:42,527 - INFO [org.gluu.oxauth.client.OpenIdClient:412] - Using default claims to attributes mapping 2020-02-14 09:55:42,527 - INFO [org.gluu.idp.externalauth.AuthenticatedNameTranslator:59] - Created an IdP subject instance with principals containing attributes for admin 2020-02-14 09:55:42,644 - INFO [net.shibboleth.idp.authn.impl.ValidateExternalAuthentication:138] - Profile Action ValidateExternalAuthentication: External authentication succeeded for Subject: [IdPAttributePrincipal{attribute=IdPAttribute{id=username, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=admin}]}}, IdPAttributePrincipal{attribute=IdPAttribute{id=email, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=admin@my-domain.com}]}}, UsernamePrincipal{username=admin}] ``` What I see the difference is the my problematic instance shows authorization code is null but the new instance is not having that log. ``` 2020-02-06 09:16:37,080 - DEBUG [org.gluu.oxauth.client.OpenIdClient:263] - oxAuth authorization code: 'null' ``` When I perform the test flow, in SAML-tracer I see the redirection happens to get my credential in gluu login page. This is triggered by idp ``` GET https://gluuhost/idp/Authn/oxAuth?conversation=e6s1 HTTP/1.1 Upgrade-Insecure-Requests: 1 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.130 Safari/537.36 Sec-Fetch-User: ?1 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 Sec-Fetch-Site: none Sec-Fetch-Mode: navigate Accept-Encoding: gzip, deflate, br Accept-Language: en-US,en;q=0.9,ta;q=0.8 Cookie: JSESSIONID=node0lkhhfdltioyh13lpqeq4cij3i6.node0; shib_idp_session=5be828677cf9b6abf229aae95342e830614dcdcbff489d06a16a73778d70e634; _ga=GA1.2.353957393.1553614989; clientchoice=DesktopClient; org.gluu.i18n.Locale=en; _gid=GA1.2.209083095.1581596237; session_id=c5865d52-9989-4d59-9c1f-8823f7aff4b0; session_state=0c23517bcb36c820e664f0f3ac5fa993049f7aef56ad2ef4c1294288fee4782c.c79605af-afe8-4b43-8de5-0f13440503ac; opbs=5c1bd595-8c9b-44e5-9ee6-288fd6920de9 HTTP/1.1 302 Found Server: nginx/1.13.12 Date: Fri, 14 Feb 2020 09:55:32 GMT Transfer-Encoding: chunked Connection: keep-alive Location: https://gluuhost/oxauth/restv1/authorize?response_type=code&client_id=%40%210F61.CF58.1D2F.263B%210001%21115E.7A8A%210008%21EA6E.B178&scope=openid+email+user_name&redirect_uri=https%3A%2F%2Fgluuhost%2Fidp%2FAuthn%2FoxAuth&state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJjb252ZXJzYXRpb24iOiJlNnMxIiwic3RhdGUiOiJ3aEdCVnNPTjRiIn0.&nonce=VA5wsyKyg8&entityId=IAMShowcase Strict-Transport-Security: max-age=15724800; includeSubDomains ``` in this redirection, the client id is the ID of "IDP Client". To learn, let me delete the IDP Client in my good instance and see if it breaks and get back to you Thanks, Mahendran.

By Mahendran Mookkiah user 14 Feb 2020 at 7:29 a.m. CST

Mahendran Mookkiah gravatar
I am able to reproduce the problem by deleting IDP Client. So it is a broken environment and now we know the reason. Please see the log below... Now I took a screenshot of IDP Client before deleting. I can create new client but it will endup with new client_id. I think I should open separate thread asking how I fix when I IDP Client is deleted by mistake. Thanks Mohit for your support. ``` 2020-02-14 13:22:07,819 - DEBUG [org.opensaml.profile.action.impl.DecodeMessage:64] - Profile Action DecodeMessage: Decoding message using message decoder of type org.opensaml.saml.saml2.binding.decoding.impl.HTTPRedirectDeflateDecoder for this request 2020-02-14 13:22:07,820 - DEBUG [org.opensaml.messaging.decoder.servlet.BaseHttpServletRequestXMLMessageDecoder:66] - Beginning to decode message from HttpServletRequest 2020-02-14 13:22:07,820 - DEBUG [org.opensaml.messaging.decoder.servlet.BaseHttpServletRequestXMLMessageDecoder:68] - HttpServletRequest indicated Content-Type: null 2020-02-14 13:22:07,821 - DEBUG [org.opensaml.saml.saml2.binding.decoding.impl.HTTPRedirectDeflateDecoder:99] - Decoded RelayState: null 2020-02-14 13:22:07,821 - DEBUG [org.opensaml.saml.saml2.binding.decoding.impl.HTTPRedirectDeflateDecoder:131] - Base64 decoding and inflating SAML message 2020-02-14 13:22:07,822 - DEBUG [org.opensaml.core.xml.util.XMLObjectSupport:227] - Parsing InputStream into DOM document 2020-02-14 13:22:07,823 - DEBUG [org.opensaml.core.xml.util.XMLObjectSupport:238] - Unmarshalling DOM parsed from InputStream 2020-02-14 13:22:07,824 - DEBUG [org.opensaml.core.xml.util.XMLObjectSupport:250] - InputStream succesfully unmarshalled 2020-02-14 13:22:07,824 - DEBUG [org.opensaml.saml.saml2.binding.decoding.impl.HTTPRedirectDeflateDecoder:114] - Decoded SAML message 2020-02-14 13:22:07,825 - DEBUG [org.opensaml.core.xml.util.XMLObjectSupport:310] - Marshalling XMLObject 2020-02-14 13:22:07,825 - DEBUG [org.opensaml.core.xml.util.XMLObjectSupport:313] - XMLObject already had cached DOM, returning that element 2020-02-14 13:22:07,826 - DEBUG [PROTOCOL_MESSAGE:127] - <samlp:AuthnRequest AssertionConsumerServiceURL="https://sptest.iamshowcase.com/acs" Destination="https://gluuhost/idp/profile/SAML2/Redirect/SSO" ForceAuthn="false" ID="aaeb1419b2cf05e398a303c9ffd891b7347a2e1ae" IssueInstant="2020-02-14T13:22:07Z" ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST" Version="2.0" xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion" xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"> <saml:Issuer>IAMShowcase</saml:Issuer> </samlp:AuthnRequest> 2020-02-14 13:22:07,826 - DEBUG [org.opensaml.messaging.decoder.servlet.BaseHttpServletRequestXMLMessageDecoder:76] - Successfully decoded message from HttpServletRequest. 2020-02-14 13:22:07,827 - DEBUG [org.opensaml.profile.action.impl.DecodeMessage:68] - Profile Action DecodeMessage: Incoming request decoded into a message of type org.opensaml.saml.saml2.core.impl.AuthnRequestImpl 2020-02-14 13:22:07,828 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.CheckMessageVersionHandler' on INBOUND message context 2020-02-14 13:22:07,829 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,829 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,830 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml1.binding.impl.SAML1ArtifactRequestIssuerHandler' on INBOUND message context 2020-02-14 13:22:07,830 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,831 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,832 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLProtocolAndRoleHandler' on INBOUND message context 2020-02-14 13:22:07,832 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,832 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,834 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler' on INBOUND message context 2020-02-14 13:22:07,835 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,835 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,836 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractBatchMetadataResolver:162] - Metadata Resolver FilesystemMetadataResolver SiteSP1: Resolved 1 candidates via EntityIdCriterion: EntityIdCriterion [id=IAMShowcase] 2020-02-14 13:22:07,836 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:590] - Metadata Resolver FilesystemMetadataResolver SiteSP1: Attempting to filter candidate EntityDescriptors via resolved Predicates 2020-02-14 13:22:07,837 - DEBUG [net.shibboleth.utilities.java.support.resolver.CriterionPredicateRegistry:94] - Registry did not locate Predicate implementation registered for Criterion class org.opensaml.core.criterion.EntityIdCriterion 2020-02-14 13:22:07,837 - DEBUG [net.shibboleth.utilities.java.support.resolver.CriterionPredicateRegistry:94] - Registry did not locate Predicate implementation registered for Criterion class org.opensaml.saml.criterion.EntityRoleCriterion 2020-02-14 13:22:07,837 - DEBUG [net.shibboleth.utilities.java.support.resolver.CriterionPredicateRegistry:94] - Registry did not locate Predicate implementation registered for Criterion class org.opensaml.saml.criterion.ProtocolCriterion 2020-02-14 13:22:07,838 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractMetadataResolver:612] - Metadata Resolver FilesystemMetadataResolver SiteSP1: After predicate filtering 1 EntityDescriptors remain 2020-02-14 13:22:07,838 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:264] - Resolved 1 source EntityDescriptors 2020-02-14 13:22:07,839 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:275] - Resolved 1 RoleDescriptor candidates via role criteria, performing predicate filtering 2020-02-14 13:22:07,839 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:376] - Attempting to filter candidate RoleDescriptors via resolved Predicates 2020-02-14 13:22:07,840 - DEBUG [net.shibboleth.utilities.java.support.resolver.CriterionPredicateRegistry:94] - Registry did not locate Predicate implementation registered for Criterion class org.opensaml.core.criterion.EntityIdCriterion 2020-02-14 13:22:07,840 - DEBUG [net.shibboleth.utilities.java.support.resolver.CriterionPredicateRegistry:94] - Registry did not locate Predicate implementation registered for Criterion class org.opensaml.saml.criterion.EntityRoleCriterion 2020-02-14 13:22:07,841 - DEBUG [net.shibboleth.utilities.java.support.resolver.CriterionPredicateRegistry:94] - Registry did not locate Predicate implementation registered for Criterion class org.opensaml.saml.criterion.ProtocolCriterion 2020-02-14 13:22:07,841 - DEBUG [org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:398] - After predicate filtering 1 RoleDescriptors remain 2020-02-14 13:22:07,841 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler:144] - Message Handler: org.opensaml.saml.common.messaging.context.SAMLMetadataContext added to MessageContext as child of org.opensaml.saml.common.messaging.context.SAMLPeerEntityContext 2020-02-14 13:22:07,842 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler' on INBOUND message context 2020-02-14 13:22:07,843 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,843 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,843 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler:130] - Message Handler: Selecting default AttributeConsumingService, if any 2020-02-14 13:22:07,844 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:186] - Resolving AttributeConsumingService candidates from SPSSODescriptor 2020-02-14 13:22:07,844 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:141] - AttributeConsumingService candidate list was empty, can not select service 2020-02-14 13:22:07,845 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler:138] - Message Handler: No AttributeConsumingService selected 2020-02-14 13:22:07,845 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeRelyingPartyContextFromSAMLPeer:132] - Profile Action InitializeRelyingPartyContextFromSAMLPeer: Attaching RelyingPartyContext based on SAML peer IAMShowcase 2020-02-14 13:22:07,846 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:293] - Resolving relying party configuration 2020-02-14 13:22:07,846 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:305] - Checking if relying party configuration EntityNames[IAMShowcase,] is applicable 2020-02-14 13:22:07,847 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:307] - Relying party configuration EntityNames[IAMShowcase,] is applicable 2020-02-14 13:22:07,847 - DEBUG [net.shibboleth.idp.profile.impl.SelectRelyingPartyConfiguration:136] - Profile Action SelectRelyingPartyConfiguration: Found relying party configuration EntityNames[IAMShowcase,] for request 2020-02-14 13:22:07,848 - DEBUG [org.opensaml.profile.action.impl.PopulateSignatureValidationParameters:142] - Profile Action PopulateSignatureValidationParameters: Resolving SignatureValidationParameters for request 2020-02-14 13:22:07,849 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureValidationParametersResolver:92] - Resolved SignatureValidationParameters: 2020-02-14 13:22:07,849 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureValidationParametersResolver:94] - Algorithm whitelist: [] 2020-02-14 13:22:07,849 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureValidationParametersResolver:95] - Algorithm blacklist: [http://www.w3.org/2001/04/xmldsig-more#hmac-md5, http://www.w3.org/2001/04/xmldsig-more#md5, http://www.w3.org/2001/04/xmldsig-more#rsa-md5] 2020-02-14 13:22:07,850 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureValidationParametersResolver:97] - SignatureTrustEngine: present 2020-02-14 13:22:07,850 - DEBUG [org.opensaml.profile.action.impl.PopulateSignatureValidationParameters:163] - Profile Action PopulateSignatureValidationParameters: Resolved SignatureValidationParameters 2020-02-14 13:22:07,851 - DEBUG [org.opensaml.profile.action.impl.PopulateClientTLSValidationParameters:144] - Profile Action PopulateClientTLSValidationParameters: Resolving ClientTLSValidationParameters for request 2020-02-14 13:22:07,851 - DEBUG [org.opensaml.profile.action.impl.PopulateClientTLSValidationParameters:165] - Profile Action PopulateClientTLSValidationParameters: Resolved ClientTLSValidationParameters 2020-02-14 13:22:07,852 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.PopulateProfileInterceptorContext:126] - Profile Action PopulateProfileInterceptorContext: Installing flow intercept/security-policy/saml2-sso into interceptor context 2020-02-14 13:22:07,854 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do 2020-02-14 13:22:07,854 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:101] - Profile Action SelectProfileInterceptorFlow: Checking flow intercept/security-policy/saml2-sso for applicability... 2020-02-14 13:22:07,855 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:84] - Profile Action SelectProfileInterceptorFlow: Selecting flow intercept/security-policy/saml2-sso 2020-02-14 13:22:07,856 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler' on INBOUND message context 2020-02-14 13:22:07,857 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,857 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,858 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:157] - Message Handler: Checking SAML message intended destination endpoint against receiver endpoint 2020-02-14 13:22:07,858 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:190] - Message Handler: Intended message destination endpoint: https://gluuhost/idp/profile/SAML2/Redirect/SSO 2020-02-14 13:22:07,859 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:191] - Message Handler: Actual message receiver endpoint: https://gluuhost/idp/profile/SAML2/Redirect/SSO 2020-02-14 13:22:07,859 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:204] - Message Handler: SAML message intended destination endpoint matched recipient endpoint 2020-02-14 13:22:07,860 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.MessageReplaySecurityHandler' on INBOUND message context 2020-02-14 13:22:07,861 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,861 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,862 - DEBUG [org.opensaml.saml.common.binding.security.impl.MessageReplaySecurityHandler:152] - Message Handler: Evaluating message replay for message ID 'aaeb1419b2cf05e398a303c9ffd891b7347a2e1ae', issue instant '2020-02-14T13:22:07.000Z', entityID 'IAMShowcase' 2020-02-14 13:22:07,863 - DEBUG [org.opensaml.storage.AbstractMapBackedStorageService:318] - Read failed, key 'aaeb1419b2cf05e398a303c9ffd891b7347a2e1ae' not found in context 'org.opensaml.saml.common.binding.security.impl.MessageReplaySecurityHandler' 2020-02-14 13:22:07,863 - DEBUG [org.opensaml.storage.ReplayCache:136] - Value 'aaeb1419b2cf05e398a303c9ffd891b7347a2e1ae' was not a replay, adding to cache with expiration time 1581686707000 2020-02-14 13:22:07,864 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.MessageLifetimeSecurityHandler' on INBOUND message context 2020-02-14 13:22:07,865 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,865 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,866 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.security.impl.SAML2AuthnRequestsSignedSecurityHandler' on INBOUND message context 2020-02-14 13:22:07,867 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,867 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,868 - DEBUG [org.opensaml.saml.saml2.binding.security.impl.SAML2AuthnRequestsSignedSecurityHandler:80] - SPSSODescriptor for entity ID 'IAMShowcase' does not require AuthnRequests to be signed 2020-02-14 13:22:07,869 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.SAMLProtocolMessageXMLSignatureSecurityHandler' on INBOUND message context 2020-02-14 13:22:07,870 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,870 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,871 - DEBUG [org.opensaml.saml.common.binding.security.impl.SAMLProtocolMessageXMLSignatureSecurityHandler:102] - Message Handler: SAML protocol message was not signed, skipping XML signature processing 2020-02-14 13:22:07,872 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPRedirectDeflateSignatureSecurityHandler' on INBOUND message context 2020-02-14 13:22:07,872 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,873 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,873 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:148] - Message Handler: Evaluating simple signature rule of type: org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPRedirectDeflateSignatureSecurityHandler 2020-02-14 13:22:07,874 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:157] - Message Handler: HTTP request was not signed via simple signature mechanism, skipping 2020-02-14 13:22:07,875 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPPostSimpleSignSecurityHandler' on INBOUND message context 2020-02-14 13:22:07,875 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,876 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,876 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:148] - Message Handler: Evaluating simple signature rule of type: org.opensaml.saml.saml2.binding.security.impl.SAML2HTTPPostSimpleSignSecurityHandler 2020-02-14 13:22:07,877 - DEBUG [org.opensaml.saml.common.binding.security.impl.BaseSAMLSimpleSignatureSecurityHandler:151] - Message Handler: Handler can not handle this request, skipping processing 2020-02-14 13:22:07,878 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:174] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.CheckMandatoryIssuer' on INBOUND message context 2020-02-14 13:22:07,879 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.AuthnRequestImpl' 2020-02-14 13:22:07,879 - DEBUG [org.opensaml.messaging.handler.AbstractMessageHandler:148] - Message Handler: Activation condition for handler returned true 2020-02-14 13:22:07,880 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.WriteProfileInterceptorResultToStorage:68] - Profile Action WriteProfileInterceptorResultToStorage: No results available from interceptor context, nothing to store 2020-02-14 13:22:07,881 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do 2020-02-14 13:22:07,881 - 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 2020-02-14 13:22:07,882 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:80] - Profile Action SelectProfileInterceptorFlow: No flows available to choose from 2020-02-14 13:22:07,883 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeOutboundMessageContext:149] - Profile Action InitializeOutboundMessageContext: Initialized outbound message context 2020-02-14 13:22:07,884 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:375] - Profile Action PopulateBindingAndEndpointContexts: Attempting to resolve endpoint of type {urn:oasis:names:tc:SAML:2.0:metadata}AssertionConsumerService for outbound message 2020-02-14 13:22:07,885 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:516] - Profile Action PopulateBindingAndEndpointContexts: Populating template endpoint for resolution from SAML AuthnRequest 2020-02-14 13:22:07,885 - DEBUG [org.opensaml.saml.common.binding.AbstractEndpointResolver:220] - Endpoint Resolver org.opensaml.saml.common.binding.impl.DefaultEndpointResolver: Returning 1 candidate endpoints of type {urn:oasis:names:tc:SAML:2.0:metadata}AssertionConsumerService 2020-02-14 13:22:07,886 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:418] - Profile Action PopulateBindingAndEndpointContexts: Resolved endpoint at location https://sptest.iamshowcase.com/acs using binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST 2020-02-14 13:22:07,887 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:387] - No AttributeConsumingService was resolved, won't be able to determine delegation requested status via metadata 2020-02-14 13:22:07,888 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:520] - No AttributeConsumingService was available 2020-02-14 13:22:07,888 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:505] - Delegation request was not explicitly indicated, using default value: NOT_REQUESTED 2020-02-14 13:22:07,889 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:294] - Issuance of a delegated Assertion is not in effect, skipping further processing 2020-02-14 13:22:07,890 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:184] - Profile Action PopulateSignatureSigningParameters: Signing enabled 2020-02-14 13:22:07,891 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:197] - Profile Action PopulateSignatureSigningParameters: Resolving SignatureSigningParameters for request 2020-02-14 13:22:07,891 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:229] - Profile Action PopulateSignatureSigningParameters: Adding metadata to resolution criteria for signing/digest algorithms 2020-02-14 13:22:07,892 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#rsa-sha256': supported 2020-02-14 13:22:07,893 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#ecdsa-sha256': supported 2020-02-14 13:22:07,894 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#rsa-sha256': supported 2020-02-14 13:22:07,895 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#rsa-sha384': supported 2020-02-14 13:22:07,895 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#rsa-sha512': supported 2020-02-14 13:22:07,896 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2000/09/xmldsig#rsa-sha1': supported 2020-02-14 13:22:07,897 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#ecdsa-sha256': supported 2020-02-14 13:22:07,898 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#ecdsa-sha384': supported 2020-02-14 13:22:07,898 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#ecdsa-sha512': supported 2020-02-14 13:22:07,899 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#ecdsa-sha1': supported 2020-02-14 13:22:07,900 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2000/09/xmldsig#dsa-sha1': supported 2020-02-14 13:22:07,901 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#hmac-sha256': supported 2020-02-14 13:22:07,901 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#hmac-sha384': supported 2020-02-14 13:22:07,902 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmldsig-more#hmac-sha512': supported 2020-02-14 13:22:07,903 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2000/09/xmldsig#hmac-sha1': supported 2020-02-14 13:22:07,904 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#sha256': supported 2020-02-14 13:22:07,904 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureSigningParametersResolver:149] - Resolved SignatureSigningParameters: 2020-02-14 13:22:07,905 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureSigningParametersResolver:153] - Signing credential with key algorithm: RSA 2020-02-14 13:22:07,906 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureSigningParametersResolver:158] - Signature algorithm URI: http://www.w3.org/2001/04/xmldsig-more#rsa-sha256 2020-02-14 13:22:07,906 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureSigningParametersResolver:160] - Signature KeyInfoGenerator: present 2020-02-14 13:22:07,907 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureSigningParametersResolver:162] - Reference digest method algorithm URI: http://www.w3.org/2001/04/xmlenc#sha256 2020-02-14 13:22:07,908 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureSigningParametersResolver:163] - Canonicalization algorithm URI: http://www.w3.org/2001/10/xml-exc-c14n# 2020-02-14 13:22:07,908 - DEBUG [org.opensaml.xmlsec.impl.BasicSignatureSigningParametersResolver:164] - HMAC output length: null 2020-02-14 13:22:07,909 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:237] - Profile Action PopulateSignatureSigningParameters: Resolved SignatureSigningParameters 2020-02-14 13:22:07,911 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:184] - Profile Action PopulateSignatureSigningParameters: Signing enabled 2020-02-14 13:22:07,912 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:197] - Profile Action PopulateSignatureSigningParameters: Resolving SignatureSigningParameters for request 2020-02-14 13:22:07,912 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:211] - Profile Action PopulateSignatureSigningParameters: Found existing SecurityParametersContext to copy from 2020-02-14 13:22:07,913 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:305] - Profile Action PopulateEncryptionParameters: Encryption for assertions (true), identifiers (false), attributes(false) 2020-02-14 13:22:07,914 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:315] - Profile Action PopulateEncryptionParameters: Resolving EncryptionParameters for request 2020-02-14 13:22:07,914 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:380] - Profile Action PopulateEncryptionParameters: Adding entityID to resolution criteria 2020-02-14 13:22:07,915 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:391] - Profile Action PopulateEncryptionParameters: Adding role metadata to resolution criteria 2020-02-14 13:22:07,915 - DEBUG [org.opensaml.saml.security.impl.MetadataCredentialResolver:259] - Resolving credentials from supplied RoleDescriptor using usage: ENCRYPTION. Effective entityID was: IAMShowcase 2020-02-14 13:22:07,916 - DEBUG [org.opensaml.security.credential.criteria.impl.EvaluableCredentialCriteriaRegistry:81] - Registry located evaluable criteria class org.opensaml.security.credential.criteria.impl.EvaluableEntityIDCredentialCriterion for criteria class org.opensaml.core.criterion.EntityIdCriterion 2020-02-14 13:22:07,917 - DEBUG [org.opensaml.security.credential.criteria.impl.EvaluableCredentialCriteriaRegistry:96] - Registry could not locate evaluable criteria for criteria class org.opensaml.saml.criterion.RoleDescriptorCriterion 2020-02-14 13:22:07,917 - DEBUG [org.opensaml.security.credential.criteria.impl.EvaluableCredentialCriteriaRegistry:96] - Registry could not locate evaluable criteria for criteria class org.opensaml.saml.criterion.EntityRoleCriterion 2020-02-14 13:22:07,918 - DEBUG [org.opensaml.security.credential.criteria.impl.EvaluableCredentialCriteriaRegistry:81] - Registry located evaluable criteria class org.opensaml.security.credential.criteria.impl.EvaluableUsageCredentialCriterion for criteria class org.opensaml.security.criteria.UsageCriterion 2020-02-14 13:22:07,919 - DEBUG [org.opensaml.security.credential.criteria.impl.EvaluableCredentialCriteriaRegistry:96] - Registry could not locate evaluable criteria for criteria class org.opensaml.saml.criterion.ProtocolCriterion 2020-02-14 13:22:07,919 - DEBUG [org.opensaml.security.credential.criteria.impl.EvaluableCredentialCriteriaRegistry:96] - Registry could not locate evaluable criteria for criteria class org.opensaml.xmlsec.criterion.EncryptionConfigurationCriterion 2020-02-14 13:22:07,920 - DEBUG [org.opensaml.security.credential.criteria.impl.EvaluableCredentialCriteriaRegistry:96] - Registry could not locate evaluable criteria for criteria class org.opensaml.xmlsec.criterion.EncryptionOptionalCriterion 2020-02-14 13:22:07,920 - DEBUG [org.opensaml.saml.security.impl.SAMLMetadataEncryptionParametersResolver:186] - Could not resolve encryption parameters based on SAML metadata, falling back to locally configured credentials and algorithms 2020-02-14 13:22:07,921 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#rsa-oaep-mgf1p': supported 2020-02-14 13:22:07,922 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#rsa-oaep-mgf1p': supported 2020-02-14 13:22:07,922 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#kw-aes128': supported 2020-02-14 13:22:07,923 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#kw-aes192': supported 2020-02-14 13:22:07,924 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#kw-aes256': supported 2020-02-14 13:22:07,925 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#kw-tripledes': supported 2020-02-14 13:22:07,925 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#aes128-cbc': supported 2020-02-14 13:22:07,926 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#aes128-cbc': supported 2020-02-14 13:22:07,926 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#aes192-cbc': supported 2020-02-14 13:22:07,927 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#aes256-cbc': supported 2020-02-14 13:22:07,928 - DEBUG [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:106] - Runtime support eval for algorithm URI 'http://www.w3.org/2001/04/xmlenc#tripledes-cbc': supported 2020-02-14 13:22:07,928 - DEBUG [org.opensaml.xmlsec.impl.BasicEncryptionParametersResolver:246] - Validation failure: Failed to resolve both a data and a key encryption credential 2020-02-14 13:22:07,929 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:331] - Profile Action PopulateEncryptionParameters: Failed to resolve EncryptionParameters 2020-02-14 13:22:07,930 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:345] - Profile Action PopulateEncryptionParameters: Resolver returned no EncryptionParameters 2020-02-14 13:22:07,930 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:346] - Profile Action PopulateEncryptionParameters: Encryption is optional, ignoring inability to encrypt 2020-02-14 13:22:07,931 - DEBUG [org.opensaml.profile.action.impl.PopulateDecryptionParameters:139] - Profile Action PopulateDecryptionParameters: Resolving DecryptionParameters for request 2020-02-14 13:22:07,932 - DEBUG [org.opensaml.xmlsec.impl.BasicDecryptionParametersResolver:93] - Resolved DecryptionParameters: 2020-02-14 13:22:07,932 - DEBUG [org.opensaml.xmlsec.impl.BasicDecryptionParametersResolver:95] - Algorithm whitelist: [] 2020-02-14 13:22:07,933 - DEBUG [org.opensaml.xmlsec.impl.BasicDecryptionParametersResolver:96] - Algorithm blacklist: [http://www.w3.org/2001/04/xmlenc#rsa-1_5] 2020-02-14 13:22:07,933 - DEBUG [org.opensaml.xmlsec.impl.BasicDecryptionParametersResolver:98] - Data KeyInfoCredentialResolver: null 2020-02-14 13:22:07,934 - DEBUG [org.opensaml.xmlsec.impl.BasicDecryptionParametersResolver:100] - KEK KeyInfoCredentialResolver: present 2020-02-14 13:22:07,935 - DEBUG [org.opensaml.xmlsec.impl.BasicDecryptionParametersResolver:102] - EncryptedKeyResolver: present 2020-02-14 13:22:07,935 - DEBUG [org.opensaml.profile.action.impl.PopulateDecryptionParameters:161] - Profile Action PopulateDecryptionParameters: Resolved DecryptionParameters 2020-02-14 13:22:07,938 - DEBUG [net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:144] - Profile Action ExtractSubjectFromRequest: No Subject NameID/NameIdentifier in message needs inbound processing 2020-02-14 13:22:07,939 - DEBUG [org.opensaml.saml.common.profile.impl.VerifyChannelBindings:154] - Profile Action VerifyChannelBindings: No channel bindings found to verify, nothing to do 2020-02-14 13:22:07,941 - DEBUG [org.opensaml.profile.action.AbstractConditionalProfileAction:79] - Profile Action PopulateECPContext: Activation condition for action returned false 2020-02-14 13:22:07,942 - DEBUG [org.opensaml.storage.impl.client.PopulateClientStorageLoadContext:117] - Profile Action PopulateClientStorageLoadContext: No ClientStorageServices require loading, nothing to do 2020-02-14 13:22:07,942 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:115] - Profile Action InitializeAuthenticationContext: Created authentication context: AuthenticationContext{initiationInstant=2020-02-14T13:22:07.942Z, isPassive=false, forceAuthn=false, hintedName=null, potentialFlows=[], activeResults=[], attemptedFlow=null, signaledFlowId=null, authenticationStateMap={}, resultCacheable=true, initialAuthenticationResult=null, authenticationResult=null, completionInstant=1970-01-01T00:00:00.000Z} 2020-02-14 13:22:07,943 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.ProcessRequestedAuthnContext:174] - Profile Action ProcessRequestedAuthnContext: AuthnRequest did not contain a RequestedAuthnContext, nothing to do 2020-02-14 13:22:07,945 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:200] - Profile Action PopulateAuthenticationContext: Installed 1 potential authentication flows into AuthenticationContext 2020-02-14 13:22:07,946 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedSessionManager:798] - Performing primary lookup on session ID 4d5c5994d4566a14ef5763945a850411e43fd98e8746ee93516923e86e97a8d7 2020-02-14 13:22:07,947 - DEBUG [org.opensaml.storage.AbstractMapBackedStorageService:312] - Read failed, context '4d5c5994d4566a14ef5763945a850411e43fd98e8746ee93516923e86e97a8d7' not found 2020-02-14 13:22:07,947 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedSessionManager:806] - Primary lookup failed for session ID 4d5c5994d4566a14ef5763945a850411e43fd98e8746ee93516923e86e97a8d7 2020-02-14 13:22:07,948 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client 2020-02-14 13:22:07,949 - DEBUG [net.shibboleth.idp.authn.impl.InitializeRequestedPrincipalContext:152] - Profile Action InitializeRequestedPrincipalContext: Profile configuration did not supply any default authentication methods 2020-02-14 13:22:07,950 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile Action FilterFlowsByForcedAuthn: Request does not have forced authentication requirement, nothing to do 2020-02-14 13:22:07,951 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do 2020-02-14 13:22:07,952 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:255] - Profile Action SelectAuthenticationFlow: No specific Principals requested 2020-02-14 13:22:07,953 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:290] - Profile Action SelectAuthenticationFlow: No usable active results available, selecting an inactive flow 2020-02-14 13:22:07,953 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/oxAuth 2020-02-14 13:22:08,055 - DEBUG [org.gluu.oxauth.client.OpenIdClient:292] - oxAuth authorization code: 'null' 2020-02-14 13:22:08,055 - DEBUG [org.gluu.oxauth.client.OpenIdClient:295] - Is authorization request: 'false' 2020-02-14 13:22:08,056 - DEBUG [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:125] - Initiating oxAuth login redirect 2020-02-14 13:22:08,056 - DEBUG [org.gluu.oxauth.client.OpenIdClient:244] - oxAuth redirection Url: 'https://gluuhost/oxauth/restv1/authorize?response_type=code&client_id=%40%210F61.CF58.1D2F.263B%210001%21115E.7A8A%210008%21EA6E.B178&scope=openid+email+user_name&redirect_uri=https%3A%2F%2Fgluuhost%2Fidp%2FAuthn%2FoxAuth&state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJjb252ZXJzYXRpb24iOiJlMnMxIiwic3RhdGUiOiJQSk53TmxNQWpFIn0.&nonce=XUFSj8nsOD&entityId=IAMShowcase' 2020-02-14 13:22:08,057 - DEBUG [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:195] - Generated redirection Url 2020-02-14 13:22:08,057 - DEBUG [org.gluu.idp.externalauth.ShibOxAuthAuthServlet:197] - loginUrl: https://gluuhost/oxauth/restv1/authorize?response_type=code&client_id=%40%210F61.CF58.1D2F.263B%210001%21115E.7A8A%210008%21EA6E.B178&scope=openid+email+user_name&redirect_uri=https%3A%2F%2Fgluuhost%2Fidp%2FAuthn%2FoxAuth&state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJjb252ZXJzYXRpb24iOiJlMnMxIiwic3RhdGUiOiJQSk53TmxNQWpFIn0.&nonce=XUFSj8nsOD&entityId=IAMShowcase ```