By: Pawel Pietrzynski named 18 Sep 2019 at 11:55 a.m. CDT

2 Responses
Pawel Pietrzynski gravatar
## Expected behaviour When an "acr" is invalidated and a new "acr" is selected, the new "acr" processing is started, all methods are called with the same step. Moreover it should be obvious what step does the new "acr" begin at, whether it's step 1 always or continuing the previous step. ## Current behaviour **getPageForStep** is called with old ACR step **prepareForStep** is called with new ACR step ``` INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. authenticate for step 1 called INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. attemptAuthentication INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. attemptAuthentication. Updating user 110897723 INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. attemptAuthentication. Authentication for 110897723 returned True DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:291) - Executing python 'getApiVersion' authenticator method DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:207) - Executing python 'getNextStep' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getNextStep called with step 1 INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport DEBUG getNextStep. returning -1 DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getExtraParametersForStep called with step 2 DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:179) - Executing python 'getCountAuthenticationSteps' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getCountAuthenticationSteps called DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:277) - Executing python 'getPageForStep' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getPageForStep called with step 2 DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getExtraParametersForStep called with step 2 DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:384) - Validating acr_values: 'passport_social' DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:151) - Executing python 'isValidAuthenticationMethod' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. isValidAuthenticationMethod called INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport DEBUG. isValidAuthenticationMethod, returning False WARN [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:388) - Current acr_values: 'passport_social' isn't valid DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:165) - Executing python 'getAlternativeAuthenticationMethod' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getAlternativeAuthenticationMethod called DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:277) - Executing python 'getPageForStep' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - IDP Chooser. getPageForStep called for step '2' DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:384) - Validating acr_values: 'idp_chooser_loa2' DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:151) - Executing python 'isValidAuthenticationMethod' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - IDP Chooser. isValidAuthenticationMethod called INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - IDP Chooser. isValidAuthenticationMethod: new_acr_value retrieved = 'None' DEBUG [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:249) - Executing python 'prepareForStep' authenticator method INFO [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - IDP Chooser. prepareForStep called for step '1' ```

By Aliaksandr Samuseu staff 18 Sep 2019 at 1:03 p.m. CDT

Aliaksandr Samuseu gravatar
Hi, Pawel. >When an "acr" is invalidated and a new "acr" is selected, the new "acr" processing is started, all methods are called with the same step Could you elaborate? What do you mean by "invalidated" and "selected" here? Sharing your script, or providing some code snippets with comments would help.

By Pawel Pietrzynski named 18 Sep 2019 at 1:29 p.m. CDT

Pawel Pietrzynski gravatar
The best thing is the flow in total ... I think the code would be more confusing than helpful at this point and I've added "METHOD called" messages in all of my code for debugging, so you can follow the trail The sequence is as described: 1. The user goes on IDP Chooser module 2. The user chooses passport_social and google as provider 3. The ACR gets changed through invalidation to passport_social and google authentication gets executed 4. When finished the ACR gets invalidated again and the user is sent back to IDP Chooser module for further processing As you can see in the last few lines the step in IDP Chooser to get the page is 2 while the preare method is passed 1. ``` DEBUG (ExternalAuthenticationService:277) - Executing python 'getPageForStep' authenticator method INFO (PythonService:240) - IDP Chooser. getPageForStep called for step '1' DEBUG (ExternalAuthenticationService:384) - Validating acr_values: 'idp_chooser_loa2' DEBUG (ExternalAuthenticationService:151) - Executing python 'isValidAuthenticationMethod' authenticator method INFO (PythonService:240) - IDP Chooser. isValidAuthenticationMethod called INFO (PythonService:240) - IDP Chooser. isValidAuthenticationMethod: new_acr_value retrieved = 'None' DEBUG (ExternalAuthenticationService:249) - Executing python 'prepareForStep' authenticator method INFO (PythonService:240) - IDP Chooser. prepareForStep called for step '1' INFO (PythonService:240) - IDP Chooser. prepareForStep. got session 'SessionState... {... sessionAttributes={auth_step=1, acr=idp_chooser_loa2,...}' DEBUG (ExternalAuthenticationService:263) - Executing python 'getExtraParametersForStep' authenticator method INFO (PythonService:240) - IDP Chooser. getExtraParametersForStep called for step '1' DEBUG (ExternalAuthenticationService:193) - Executing python 'authenticate' authenticator method INFO (PythonService:240) - IDP Chooser. authenticate called for step '1' INFO (PythonService:240) - IDP Chooser. getSwitchValueFromAuth called INFO (PythonService:240) - IDP Chooser. getAcrValueFromAuth called INFO (PythonService:240) - IDP Chooser. getAcrValueFromAuth: fetched new_acr_provider_value 'passport_social:google' INFO (PythonService:240) - IDP Chooser. authenticate: setting new_acr_value = 'passport_social' INFO (PythonService:240) - IDP Chooser. authenticate: setting new_acr_provider = 'google' DEBUG (ExternalAuthenticationService:291) - Executing python 'getApiVersion' authenticator method DEBUG (ExternalAuthenticationService:207) - Executing python 'getNextStep' authenticator method INFO (PythonService:240) - IDP Chooser. getNextStep called for step '1' (returns -1) DEBUG (ExternalAuthenticationService:263) - Executing python 'getExtraParametersForStep' authenticator method INFO (PythonService:240) - IDP Chooser. getExtraParametersForStep called for step '2' DEBUG (ExternalAuthenticationService:179) - Executing python 'getCountAuthenticationSteps' authenticator method INFO (PythonService:240) - IDP Chooser. getCountAuthenticationSteps called DEBUG (ExternalAuthenticationService:277) - Executing python 'getPageForStep' authenticator method INFO (PythonService:240) - IDP Chooser. getPageForStep called for step '2' DEBUG (ExternalAuthenticationService:263) - Executing python 'getExtraParametersForStep' authenticator method INFO (PythonService:240) - IDP Chooser. getExtraParametersForStep called for step '2' DEBUG (ExternalAuthenticationService:384) - Validating acr_values: 'idp_chooser_loa2' DEBUG (ExternalAuthenticationService:151) - Executing python 'isValidAuthenticationMethod' authenticator method INFO (PythonService:240) - IDP Chooser. isValidAuthenticationMethod called INFO (PythonService:240) - IDP Chooser. isValidAuthenticationMethod: new_acr_value retrieved = 'passport_social' WARN (ExternalAuthenticationService:388) - Current acr_values: 'idp_chooser_loa2' isn't valid DEBUG (ExternalAuthenticationService:165) - Executing python 'getAlternativeAuthenticationMethod' authenticator method INFO (PythonService:240) - IDP Chooser. getAlternativeAuthenticationMethod called INFO (PythonService:240) - IDP Chooser. getAlternativeAuthenticationMethod: new_acr_value retrieved = 'passport_social' DEBUG (ExternalAuthenticationService:277) - Executing python 'getPageForStep' authenticator method INFO (PythonService:240) - Passport. getPageForStep called with step 2 DEBUG (ExternalAuthenticationService:384) - Validating acr_values: 'passport_social' DEBUG (ExternalAuthenticationService:151) - Executing python 'isValidAuthenticationMethod' authenticator method INFO (PythonService:240) - Passport. isValidAuthenticationMethod called DEBUG (ExternalAuthenticationService:249) - Executing python 'prepareForStep' authenticator method INFO (PythonService:240) - Passport. prepareForStep called for step 1 INFO (PythonService:240) - Passport. prepareForStep. got session 'SessionState { sessionAttributes={ auth_step_passed_1=true, auth_step=1, acr=passport_social, ...}' INFO (PythonService:240) - Passport. prepareForStep. Setting selectedProvider from session = 'google' [...] DEBUG (ExternalAuthenticationService:263) - Executing python 'getExtraParametersForStep' authenticator method INFO (PythonService:240) - Passport. getExtraParametersForStep called with step 1 DEBUG (ExternalAuthenticationService:193) - Executing python 'authenticate' authenticator method INFO (PythonService:240) - Passport. authenticate for step 1 called [...] INFO (PythonService:240) - Passport. attemptAuthentication. Authentication for 110897723880575006868 returned True DEBUG (ExternalAuthenticationService:291) - Executing python 'getApiVersion' authenticator method DEBUG (ExternalAuthenticationService:207) - Executing python 'getNextStep' authenticator method INFO (PythonService:240) - Passport. getNextStep called with step 1 INFO (PythonService:240) - Passport DEBUG getNextStep. returning -1 DEBUG (ExternalAuthenticationService:263) - Executing python 'getExtraParametersForStep' authenticator method INFO (PythonService:240) - Passport. getExtraParametersForStep called with step 2 DEBUG (ExternalAuthenticationService:179) - Executing python 'getCountAuthenticationSteps' authenticator method INFO (PythonService:240) - Passport. getCountAuthenticationSteps called DEBUG (ExternalAuthenticationService:277) - Executing python 'getPageForStep' authenticator method INFO (PythonService:240) - Passport. getPageForStep called with step 2 DEBUG (ExternalAuthenticationService:263) - Executing python 'getExtraParametersForStep' authenticator method INFO (PythonService:240) - Passport. getExtraParametersForStep called with step 2 DEBUG (ExternalAuthenticationService:384) - Validating acr_values: 'passport_social' DEBUG (ExternalAuthenticationService:151) - Executing python 'isValidAuthenticationMethod' authenticator method INFO (PythonService:240) - Passport. isValidAuthenticationMethod called WARN (ExternalAuthenticationService:388) - Current acr_values: 'passport_social' isn't valid DEBUG (ExternalAuthenticationService:165) - Executing python 'getAlternativeAuthenticationMethod' authenticator method INFO (PythonService:240) - Passport. getAlternativeAuthenticationMethod called DEBUG (ExternalAuthenticationService:277) - Executing python 'getPageForStep' authenticator method >>> >>> THIS IS THE CALL THAT IS THE ISSUE >>> INFO (PythonService:240) - IDP Chooser. getPageForStep called for step '2' >>> >>> THE CALL ABOVE IS THE ISSUE WITH STEP = 2 >>> DEBUG (ExternalAuthenticationService:384) - Validating acr_values: 'idp_chooser_loa2' DEBUG (ExternalAuthenticationService:151) - Executing python 'isValidAuthenticationMethod' authenticator method INFO (PythonService:240) - IDP Chooser. isValidAuthenticationMethod called INFO (PythonService:240) - IDP Chooser. isValidAuthenticationMethod: new_acr_value retrieved = 'None' DEBUG (ExternalAuthenticationService:249) - Executing python 'prepareForStep' authenticator method >>> >>> THE CALL BELOW IS THEN MADE WITH STEP = 1 >>> INFO (PythonService:240) - IDP Chooser. prepareForStep called for step '1' INFO (PythonService:240) - IDP Chooser. prepareForStep. got session 'SessionState {sessionAttributes={ auth_step_passed_1=true, auth_step=1, acr=idp_chooser_loa2, }' DEBUG (ExternalAuthenticationService:263) - Executing python 'getExtraParametersForStep' authenticator method INFO (PythonService:240) - IDP Chooser. getExtraParametersForStep called for step '1' ```