By: Not Ce user 27 Feb 2020 at 9:38 a.m. CST

6 Responses
Not Ce gravatar
## Expected behaviour User enrolls SuperGluu on their device and enables 2FA. The user can login at https://gluu.local/casa with their credentials and gets a push notification on the configured device. ## Actual behaviour User enrolls SuperGluu on their device and enables 2FA. When trying to login, they get the message "Failed to authenticate" ## Additional information When the user enrolls OTPs, everything works as expected. ## Logs ### Logs when using OTP #### /opt/gluu/jetty/casa/logs/casa.log ``` 27-02 16:03:27.156 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:315- Sending /get-client-token request to oxd-server with payload {"opDiscoveryPath":null,"keyId":null,"authenticationMethod":null,"clientId":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","clientSecret":"784e0c1f-e761-4234-8145-693ca8bf20ac","opHost":"https://gluu.local","client_id":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","client_secret":"784e0c1f-e761-4234-8145-693ca8bf20ac","op_host":"https://gluu.local","op_discovery_path":null,"scope":["openid","profile","user_name","clientinfo","oxd"],"authentication_method":null,"algorithm":null,"key_id":null} 27-02 16:03:27.282 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"d52a4b17-acdc-4fa4-bd4d-b2b565a97f0b","expires_in":299,"scope":["openid","user_name","clientinfo","profile","oxd"]} 27-02 16:03:27.284 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:306- getPAT. token=d52a4b17-acdc-4fa4-bd4d-b2b565a97f0b 27-02 16:03:27.284 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:315- Sending /get-tokens-by-code request to oxd-server with payload {"oxdId":"0b7be594-c7e6-46f0-aeb8-159039e0576a","oxd_id":"0b7be594-c7e6-46f0-aeb8-159039e0576a","code":"4cd42525-58e6-46ae-bf21-fa654647f698","state":"uc5vq0sqkevgfgc2f61aqsi670","token":null} 27-02 16:03:27.589 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"3c010ba5-fd7f-4719-879e-3b978a372a57","expires_in":299,"id_token":"eyJraWQiOiJlYmI3N2JkNS1mNjUzLTRlMjItYjUyNy0wNTcwNTkyMTg2OGVfc2lnX3JzMjU2IiwidHlwIjoiSldUIiwiYWxnIjoiUlMyNTYifQ.eyJhdF9oYXNoIjoiZnRaS2pzOVJkUnM2aVBVN3hGYU9oUSIsImF1ZCI6IjE1MWJiMzc3LWM1ODctNGYxOC05ZjJmLTc4ODNkOGE0YTFjNCIsImFjciI6ImNhc2EiLCJzdWIiOiI3eGRQTUp1bzVsaHhySGgzSWQ2eVN3X1l5MjRsZWM4NVZOdmZzOEJUUUdjIiwiYW1yIjpbIjEiXSwiYXV0aF90aW1lIjoxNTgyODE1ODA2LCJpc3MiOiJodHRwczovL2dsdXUyLnRlZ2VybnNlZXIuY2JyNDZsYWIuZGUiLCJleHAiOjE1ODI4MTk0MDcsImlhdCI6MTU4MjgxNTgwNywibm9uY2UiOiJlaWxpaHVicTd1Z2h0MzIxcmw1cHJoMmZqMyIsIm94T3BlbklEQ29ubmVjdFZlcnNpb24iOiJvcGVuaWRjb25uZWN0LTEuMCJ9.W9UwpZpxzgNuXkxUH88nNiTnVxXXAwJcXK2JY_JUv5JkP70OoTX6TR7f0qMAEzjEBi2hpfFe6sBGkItoanPFMuonz0ADtIQu-CTzj4A9xxxWwx2Bil4NZwketWfl1lQsmx-R5nvkkUuLSm5M7o50R97zZOxz6vF79gai4CMLDHogpzBoH7Va2WCRnWC4DS1S49VaVhehbi09lMxhVoCLySemqkaylwDNUwHgI1a3WE8arFOqX2AXziS5_QEJtgUcQRjNGAgD04dM1TCwgUCgyotLDdkgCRtCmHYhBSOi8X5WU_VkRpgeUcEy15KkesEiD6NvJ54_puPwV2rhXSCLcA","refresh_token":"d0f86b3d-6831-4e00-823d-b1a287480235","id_token_claims":{"at_hash":"ftZKjs9RdRs6iPU7xFaOhQ","aud":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","acr":"casa","sub":"7xdPMJuo5lhxrHh3Id6ySw_Yy24lec85VNvfs8BTQGc","amr":["1"],"auth_time":1582815806,"iss":"https://gluu.local","exp":1582819407,"iat":1582815807,"nonce":"eilihubq7ught321rl5prh2fj3","oxOpenIDConnectVersion":"openidconnect-1.0"}} 27-02 16:03:27.590 DEBUG [qtp987405879-18] casa.core.navigation.HomeInitiator HomeInitiator.java:70- Authorization code=4cd42525-58e6-46ae-bf21-fa654647f698, Access token=3c010ba5-fd7f-4719-879e-3b978a372a57, Id token eyJraWQiOiJlYmI3N2JkNS1mNjUzLTRlMjItYjUyNy0wNTcwNTkyMTg2OGVfc2lnX3JzMjU2IiwidHlwIjoiSldUIiwiYWxnIjoiUlMyNTYifQ.eyJhdF9oYXNoIjoiZnRaS2pzOVJkUnM2aVBVN3hGYU9oUSIsImF1ZCI6IjE1MWJiMzc3LWM1ODctNGYxOC05ZjJmLTc4ODNkOGE0YTFjNCIsImFjciI6ImNhc2EiLCJzdWIiOiI3eGRQTUp1bzVsaHhySGgzSWQ2eVN3X1l5MjRsZWM4NVZOdmZzOEJUUUdjIiwiYW1yIjpbIjEiXSwiYXV0aF90aW1lIjoxNTgyODE1ODA2LCJpc3MiOiJodHRwczovL2dsdXUyLnRlZ2VybnNlZXIuY2JyNDZsYWIuZGUiLCJleHAiOjE1ODI4MTk0MDcsImlhdCI6MTU4MjgxNTgwNywibm9uY2UiOiJlaWxpaHVicTd1Z2h0MzIxcmw1cHJoMmZqMyIsIm94T3BlbklEQ29ubmVjdFZlcnNpb24iOiJvcGVuaWRjb25uZWN0LTEuMCJ9.W9UwpZpxzgNuXkxUH88nNiTnVxXXAwJcXK2JY_JUv5JkP70OoTX6TR7f0qMAEzjEBi2hpfFe6sBGkItoanPFMuonz0ADtIQu-CTzj4A9xxxWwx2Bil4NZwketWfl1lQsmx-R5nvkkUuLSm5M7o50R97zZOxz6vF79gai4CMLDHogpzBoH7Va2WCRnWC4DS1S49VaVhehbi09lMxhVoCLySemqkaylwDNUwHgI1a3WE8arFOqX2AXziS5_QEJtgUcQRjNGAgD04dM1TCwgUCgyotLDdkgCRtCmHYhBSOi8X5WU_VkRpgeUcEy15KkesEiD6NvJ54_puPwV2rhXSCLcA 27-02 16:03:27.592 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:315- Sending /get-client-token request to oxd-server with payload {"opDiscoveryPath":null,"keyId":null,"authenticationMethod":null,"clientId":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","clientSecret":"784e0c1f-e761-4234-8145-693ca8bf20ac","opHost":"https://gluu.local","client_id":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","client_secret":"784e0c1f-e761-4234-8145-693ca8bf20ac","op_host":"https://gluu.local","op_discovery_path":null,"scope":["openid","profile","user_name","clientinfo","oxd"],"authentication_method":null,"algorithm":null,"key_id":null} 27-02 16:03:27.691 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"c8074e65-82e0-4d7f-9127-80fb6b1b1db4","expires_in":299,"scope":["openid","user_name","clientinfo","profile","oxd"]} 27-02 16:03:27.692 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:306- getPAT. token=c8074e65-82e0-4d7f-9127-80fb6b1b1db4 27-02 16:03:27.692 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:315- Sending /get-user-info request to oxd-server with payload {"oxdId":"0b7be594-c7e6-46f0-aeb8-159039e0576a","accessToken":"3c010ba5-fd7f-4719-879e-3b978a372a57","oxd_id":"0b7be594-c7e6-46f0-aeb8-159039e0576a","access_token":"3c010ba5-fd7f-4719-879e-3b978a372a57","token":null} 27-02 16:03:27.879 TRACE [qtp987405879-18] gluu.casa.core.OxdService OxdService.java:323- Response received was {"sub":"7xdPMJuo5lhxrHh3Id6ySw_Yy24lec85VNvfs8BTQGc","user_name":"test","name":"test","inum":"0a2fb515-ad80-460e-836c-228342ef762f","given_name":"test","family_name":"test"} 27-02 16:03:27.880 TRACE [qtp987405879-18] gluu.casa.core.UserService UserService.java:59- Creating a user instance from claims. Username is test 27-02 16:03:27.890 DEBUG [qtp987405879-18] casa.core.navigation.HomeInitiator HomeInitiator.java:74- Adding user to session 27-02 16:03:28.132 TRACE [qtp987405879-17] casa.ui.vm.HomeViewModel HomeViewModel.java:56- Browser data is {"description":"Firefox 73.0 on Windows 10 64-bit","layout":"Gecko","manufacturer":null,"name":"Firefox","prerelease":null,"product":null,"ua":null,"version":"73.0","os":{"architecture":64,"family":"Windows","version":"10"},"offset":3600,"screenWidth":2560} 27-02 16:03:28.134 TRACE [qtp987405879-17] casa.ui.vm.HomeViewModel HomeViewModel.java:78- Time offset for session is +01:00 27-02 16:03:28.134 TRACE [qtp987405879-17] casa.ui.vm.HomeViewModel HomeViewModel.java:62- Detected browser is not mobile 27-02 16:03:28.252 DEBUG [qtp987405879-18] casa.core.navigation.HomeInitiator HomeInitiator.java:85- Taking user to homepage... 27-02 16:03:28.253 DEBUG [qtp987405879-18] gluu.casa.misc.WebUtils WebUtils.java:96- Redirecting to URL=user.zul 27-02 16:03:28.447 INFO [qtp987405879-17] ui.vm.user.UserPreferenceViewModel UserPreferenceViewModel.java:70- Number of credentials for user test: 1 ``` #### /opt/gluu/jetty/casa/logs/2020_02_27.jetty.log ``` 27-02 16:03:27.156 TRACE gluu.casa.core.OxdService OxdService.java:315- Sending /get-client-token request to oxd-server with payload {"opDiscoveryPath":null,"keyId":null,"authenticationMethod":null,"clientId":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","clientSecret":"784e0c1f-e761-4234-8145-693ca8bf20ac","opHost":"https://gluu.local","client_id":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","client_secret":"784e0c1f-e761-4234-8145-693ca8bf20ac","op_host":"https://gluu.local","op_discovery_path":null,"scope":["openid","profile","user_name","clientinfo","oxd"],"authentication_method":null,"algorithm":null,"key_id":null} 27-02 16:03:27.282 TRACE gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"d52a4b17-acdc-4fa4-bd4d-b2b565a97f0b","expires_in":299,"scope":["openid","user_name","clientinfo","profile","oxd"]} 27-02 16:03:27.284 TRACE gluu.casa.core.OxdService OxdService.java:306- getPAT. token=d52a4b17-acdc-4fa4-bd4d-b2b565a97f0b 27-02 16:03:27.284 TRACE gluu.casa.core.OxdService OxdService.java:315- Sending /get-tokens-by-code request to oxd-server with payload {"oxdId":"0b7be594-c7e6-46f0-aeb8-159039e0576a","oxd_id":"0b7be594-c7e6-46f0-aeb8-159039e0576a","code":"4cd42525-58e6-46ae-bf21-fa654647f698","state":"uc5vq0sqkevgfgc2f61aqsi670","token":null} 27-02 16:03:27.589 TRACE gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"3c010ba5-fd7f-4719-879e-3b978a372a57","expires_in":299,"id_token":"eyJraWQiOiJlYmI3N2JkNS1mNjUzLTRlMjItYjUyNy0wNTcwNTkyMTg2OGVfc2lnX3JzMjU2IiwidHlwIjoiSldUIiwiYWxnIjoiUlMyNTYifQ.eyJhdF9oYXNoIjoiZnRaS2pzOVJkUnM2aVBVN3hGYU9oUSIsImF1ZCI6IjE1MWJiMzc3LWM1ODctNGYxOC05ZjJmLTc4ODNkOGE0YTFjNCIsImFjciI6ImNhc2EiLCJzdWIiOiI3eGRQTUp1bzVsaHhySGgzSWQ2eVN3X1l5MjRsZWM4NVZOdmZzOEJUUUdjIiwiYW1yIjpbIjEiXSwiYXV0aF90aW1lIjoxNTgyODE1ODA2LCJpc3MiOiJodHRwczovL2dsdXUyLnRlZ2VybnNlZXIuY2JyNDZsYWIuZGUiLCJleHAiOjE1ODI4MTk0MDcsImlhdCI6MTU4MjgxNTgwNywibm9uY2UiOiJlaWxpaHVicTd1Z2h0MzIxcmw1cHJoMmZqMyIsIm94T3BlbklEQ29ubmVjdFZlcnNpb24iOiJvcGVuaWRjb25uZWN0LTEuMCJ9.W9UwpZpxzgNuXkxUH88nNiTnVxXXAwJcXK2JY_JUv5JkP70OoTX6TR7f0qMAEzjEBi2hpfFe6sBGkItoanPFMuonz0ADtIQu-CTzj4A9xxxWwx2Bil4NZwketWfl1lQsmx-R5nvkkUuLSm5M7o50R97zZOxz6vF79gai4CMLDHogpzBoH7Va2WCRnWC4DS1S49VaVhehbi09lMxhVoCLySemqkaylwDNUwHgI1a3WE8arFOqX2AXziS5_QEJtgUcQRjNGAgD04dM1TCwgUCgyotLDdkgCRtCmHYhBSOi8X5WU_VkRpgeUcEy15KkesEiD6NvJ54_puPwV2rhXSCLcA","refresh_token":"d0f86b3d-6831-4e00-823d-b1a287480235","id_token_claims":{"at_hash":"ftZKjs9RdRs6iPU7xFaOhQ","aud":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","acr":"casa","sub":"7xdPMJuo5lhxrHh3Id6ySw_Yy24lec85VNvfs8BTQGc","amr":["1"],"auth_time":1582815806,"iss":"https://gluu.local","exp":1582819407,"iat":1582815807,"nonce":"eilihubq7ught321rl5prh2fj3","oxOpenIDConnectVersion":"openidconnect-1.0"}} 27-02 16:03:27.590 DEBUG casa.core.navigation.HomeInitiator HomeInitiator.java:70- Authorization code=4cd42525-58e6-46ae-bf21-fa654647f698, Access token=3c010ba5-fd7f-4719-879e-3b978a372a57, Id token eyJraWQiOiJlYmI3N2JkNS1mNjUzLTRlMjItYjUyNy0wNTcwNTkyMTg2OGVfc2lnX3JzMjU2IiwidHlwIjoiSldUIiwiYWxnIjoiUlMyNTYifQ.eyJhdF9oYXNoIjoiZnRaS2pzOVJkUnM2aVBVN3hGYU9oUSIsImF1ZCI6IjE1MWJiMzc3LWM1ODctNGYxOC05ZjJmLTc4ODNkOGE0YTFjNCIsImFjciI6ImNhc2EiLCJzdWIiOiI3eGRQTUp1bzVsaHhySGgzSWQ2eVN3X1l5MjRsZWM4NVZOdmZzOEJUUUdjIiwiYW1yIjpbIjEiXSwiYXV0aF90aW1lIjoxNTgyODE1ODA2LCJpc3MiOiJodHRwczovL2dsdXUyLnRlZ2VybnNlZXIuY2JyNDZsYWIuZGUiLCJleHAiOjE1ODI4MTk0MDcsImlhdCI6MTU4MjgxNTgwNywibm9uY2UiOiJlaWxpaHVicTd1Z2h0MzIxcmw1cHJoMmZqMyIsIm94T3BlbklEQ29ubmVjdFZlcnNpb24iOiJvcGVuaWRjb25uZWN0LTEuMCJ9.W9UwpZpxzgNuXkxUH88nNiTnVxXXAwJcXK2JY_JUv5JkP70OoTX6TR7f0qMAEzjEBi2hpfFe6sBGkItoanPFMuonz0ADtIQu-CTzj4A9xxxWwx2Bil4NZwketWfl1lQsmx-R5nvkkUuLSm5M7o50R97zZOxz6vF79gai4CMLDHogpzBoH7Va2WCRnWC4DS1S49VaVhehbi09lMxhVoCLySemqkaylwDNUwHgI1a3WE8arFOqX2AXziS5_QEJtgUcQRjNGAgD04dM1TCwgUCgyotLDdkgCRtCmHYhBSOi8X5WU_VkRpgeUcEy15KkesEiD6NvJ54_puPwV2rhXSCLcA 27-02 16:03:27.592 TRACE gluu.casa.core.OxdService OxdService.java:315- Sending /get-client-token request to oxd-server with payload {"opDiscoveryPath":null,"keyId":null,"authenticationMethod":null,"clientId":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","clientSecret":"784e0c1f-e761-4234-8145-693ca8bf20ac","opHost":"https://gluu.local","client_id":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","client_secret":"784e0c1f-e761-4234-8145-693ca8bf20ac","op_host":"https://gluu.local","op_discovery_path":null,"scope":["openid","profile","user_name","clientinfo","oxd"],"authentication_method":null,"algorithm":null,"key_id":null} 27-02 16:03:27.691 TRACE gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"c8074e65-82e0-4d7f-9127-80fb6b1b1db4","expires_in":299,"scope":["openid","user_name","clientinfo","profile","oxd"]} 27-02 16:03:27.692 TRACE gluu.casa.core.OxdService OxdService.java:306- getPAT. token=c8074e65-82e0-4d7f-9127-80fb6b1b1db4 27-02 16:03:27.692 TRACE gluu.casa.core.OxdService OxdService.java:315- Sending /get-user-info request to oxd-server with payload {"oxdId":"0b7be594-c7e6-46f0-aeb8-159039e0576a","accessToken":"3c010ba5-fd7f-4719-879e-3b978a372a57","oxd_id":"0b7be594-c7e6-46f0-aeb8-159039e0576a","access_token":"3c010ba5-fd7f-4719-879e-3b978a372a57","token":null} 27-02 16:03:27.879 TRACE gluu.casa.core.OxdService OxdService.java:323- Response received was {"sub":"7xdPMJuo5lhxrHh3Id6ySw_Yy24lec85VNvfs8BTQGc","user_name":"test","name":"test","inum":"0a2fb515-ad80-460e-836c-228342ef762f","given_name":"test","family_name":"test"} 27-02 16:03:27.880 TRACE gluu.casa.core.UserService UserService.java:59- Creating a user instance from claims. Username is test 27-02 16:03:27.890 DEBUG casa.core.navigation.HomeInitiator HomeInitiator.java:74- Adding user to session 27-02 16:03:28.132 TRACE casa.ui.vm.HomeViewModel HomeViewModel.java:56- Browser data is {"description":"Firefox 73.0 on Windows 10 64-bit","layout":"Gecko","manufacturer":null,"name":"Firefox","prerelease":null,"product":null,"ua":null,"version":"73.0","os":{"architecture":64,"family":"Windows","version":"10"},"offset":3600,"screenWidth":2560} 27-02 16:03:28.134 TRACE casa.ui.vm.HomeViewModel HomeViewModel.java:78- Time offset for session is +01:00 27-02 16:03:28.134 TRACE casa.ui.vm.HomeViewModel HomeViewModel.java:62- Detected browser is not mobile 27-02 16:03:28.252 DEBUG casa.core.navigation.HomeInitiator HomeInitiator.java:85- Taking user to homepage... 27-02 16:03:28.253 DEBUG gluu.casa.misc.WebUtils WebUtils.java:96- Redirecting to URL=user.zul 27-02 16:03:28.447 INFO ui.vm.user.UserPreferenceViewModel UserPreferenceViewModel.java:70- Number of credentials for user test: 1 ``` #### /opt/gluu/jetty/oxauth/logs/oxauth.log ``` 2020-02-27 16:03:26,962 INFO [qtp1359044626-69] [org.gluu.oxauth.service.AuthenticationService] (AuthenticationService.java:589) - Attempting to redirect user: SessionUser: SessionState {dn='2531e549-eaf1-496b-9839-4a630db91521', id='2531e549-eaf1-496b-9839-4a630db91521', lastUsedAt=Thu Feb 27 16:03:26 CET 2020, userDn='inum=0a2fb515-ad80-460e-836c-228342ef762f,ou=people,o=gluu', authenticationTime=Thu Feb 27 16:03:26 CET 2020, state=authenticated, sessionState='9669fbae34a2985de984fe530dc9596011edd43530cad51215b27329959cbbb7.ffc8f8a1-ad07-4db6-9bf3-2bb34e317cea', permissionGranted=null, isJwt=false, jwt=null, permissionGrantedMap=org.gluu.oxauth.model.common.SessionIdAccessMap@4bbc280f, involvedClients=null, sessionAttributes={auth_external_attributes=[{"ACR":"java.lang.String"},{},{"otp_auth_method":"java.lang.String"}], opbs=cdf98cda-091b-4aba-acbe-79b4a12ad956, methods=null, otp_auth_method=authenticate, response_type=code, nonce=eilihubq7ught321rl5prh2fj3, client_id=151bb377-c587-4f18-9f2f-7883d8a4a1c4, auth_step_passed_1=true, auth_step=2, ACR=otp, acr=casa, remote_ip=10.2.0.152, auth_user=test, scope=openid profile user_name clientinfo oxd, acr_values=casa, redirect_uri=https://gluu.local/casa, state=uc5vq0sqkevgfgc2f61aqsi670}, persisted=true} 2020-02-27 16:03:26,963 INFO [qtp1359044626-69] [org.gluu.oxauth.service.AuthenticationService] (AuthenticationService.java:597) - Attempting to redirect user: User: org.gluu.oxauth.model.common.User@40ddf2b 2020-02-27 16:03:26,964 INFO [qtp1359044626-69] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:426) - Authentication success for User: 'null' 2020-02-27 16:03:27,255 INFO [qtp1359044626-18] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:276) - Authentication success for Client: '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-27 16:03:27,269 WARN [qtp1359044626-18] [org.gluu.oxauth.model.crypto.AbstractCryptoProvider] (AbstractCryptoProvider.java:236) - WARNING! Key with alias: ebb77bd5-f653-4e22-b527-05705921868e_sig_rs256 Expires In: 1 days Expires On: 2020-02-29 13:26:40 Today's Date: 2020-02-27 16:03:27 2020-02-27 16:03:27,473 INFO [qtp1359044626-18] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:276) - Authentication success for Client: '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-27 16:03:27,487 WARN [qtp1359044626-18] [org.gluu.oxauth.model.crypto.AbstractCryptoProvider] (AbstractCryptoProvider.java:236) - WARNING! Key with alias: ebb77bd5-f653-4e22-b527-05705921868e_sig_rs256 Expires In: 1 days Expires On: 2020-02-29 13:26:40 Today's Date: 2020-02-27 16:03:27 2020-02-27 16:03:27,666 INFO [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:276) - Authentication success for Client: '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-27 16:03:27,679 WARN [qtp1359044626-12] [org.gluu.oxauth.model.crypto.AbstractCryptoProvider] (AbstractCryptoProvider.java:236) - WARNING! Key with alias: ebb77bd5-f653-4e22-b527-05705921868e_sig_rs256 Expires In: 1 days Expires On: 2020-02-29 13:26:40 Today's Date: 2020-02-27 16:03:27 ``` ### Logs when using SuperGluu #### /opt/gluu/jetty/casa/logs/2020_02_27.jetty.log ``` 2020-02-27 16:13:01,201 ERROR [qtp1359044626-14] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:283) - Failed to get session attributes 2020-02-27 16:13:01,203 INFO [qtp1359044626-14] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:223) - Authentication failed for 'test' ``` #### /opt/gluu/jetty/casa/logs/casa.log ``` 2020-02-27 16:13:01,201 ERROR [qtp1359044626-14] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:283) - Failed to get session attributes 2020-02-27 16:13:01,203 INFO [qtp1359044626-14] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:223) - Authentication failed for 'test' ``` #### /opt/gluu/jetty/oxauth/logs/oxauth.log ``` 2020-02-27 16:10:32,900 INFO [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:223) - Authentication failed for 'test' ```

By Michael Schwartz staff 27 Feb 2020 at 11:27 a.m. CST

Michael Schwartz gravatar
The logs look beautiful, but I think you included the success for the OTP token in the `oxauth.log`, not the failure for the Super Gluu authentication. Are you getting the push notification on the Super Gluu device? There should be a clue in the oxAuth log about what's failing. Also, perhaps look at the oxauth_script.log, and add some more debugging in the Casa script to find out when it's failing.

By Not Ce user 28 Feb 2020 at 1:32 a.m. CST

Not Ce gravatar
Hi Michael, thank you very much for your fast reply. I run another test and set the debug level of oxAuth to DEBUG. Hopefully the logs do include the information you need. I don't get a notification on the Super Gluu device, the error message appears immediately. #### casa.log ``` 28-02 08:11:37.486 DEBUG [qtp987405879-96] casa.core.navigation.HomeInitiator HomeInitiator.java:103- Starting authorization flow 28-02 08:11:37.487 TRACE [qtp987405879-96] gluu.casa.core.OxdService OxdService.java:315- Sending /get-client-token request to oxd-server with payload {"opDiscoveryPath":null,"keyId":null,"authenticationMethod":null,"clientId":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","clientSecret":"784e0c1f-e761-4234-8145-693ca8bf20ac","opHost":"https://gluu.local","client_id":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","client_secret":"784e0c1f-e761-4234-8145-693ca8bf20ac","op_host":"https://gluu.local","op_discovery_path":null,"scope":["openid","profile","user_name","clientinfo","oxd"],"authentication_method":null,"algorithm":null,"key_id":null} 28-02 08:11:37.787 TRACE [qtp987405879-96] gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"b446e069-f808-456c-b22a-a319a1e208c5","expires_in":299,"scope":["openid","user_name","clientinfo","profile","oxd"]} 28-02 08:11:37.792 TRACE [qtp987405879-96] gluu.casa.core.OxdService OxdService.java:306- getPAT. token=b446e069-f808-456c-b22a-a319a1e208c5 28-02 08:11:37.793 TRACE [qtp987405879-96] gluu.casa.core.OxdService OxdService.java:315- Sending /get-authorization-url request to oxd-server with payload {"responseTypes":null,"customParameters":null,"hostedDomain":null,"oxdId":"0b7be594-c7e6-46f0-aeb8-159039e0576a","redirectUri":null,"acrValues":["casa"],"oxd_id":"0b7be594-c7e6-46f0-aeb8-159039e0576a","acr_values":["casa"],"prompt":null,"scope":null,"hd":null,"token":null,"state":null,"custom_parameters":null,"params":null,"redirect_uri":null,"response_types":null} 28-02 08:11:37.912 TRACE [qtp987405879-96] gluu.casa.core.OxdService OxdService.java:323- Response received was {"authorization_url":"https://gluu.local/oxauth/restv1/authorize?response_type=code&client_id=151bb377-c587-4f18-9f2f-7883d8a4a1c4&redirect_uri=https://gluu.local/casa&scope=openid+profile+user_name+clientinfo+oxd&state=60li76vp5hc49s50fq0uj2r1ld&nonce=ik8tisff6ghclbhbken2qo61k1&acr_values=casa"} 28-02 08:11:37.913 DEBUG [qtp987405879-96] gluu.casa.misc.WebUtils WebUtils.java:96- Redirecting to URL=https://gluu.local/oxauth/restv1/authorize?response_type=code&client_id=151bb377-c587-4f18-9f2f-7883d8a4a1c4&redirect_uri=https://gluu.local/casa&scope=openid+profile+user_name+clientinfo+oxd&state=60li76vp5hc49s50fq0uj2r1ld&nonce=ik8tisff6ghclbhbken2qo61k1&acr_values=casa 28-02 08:12:09.605 DEBUG [casaScheduler_Worker-5] gluu.casa.core.LogService LogService.java:62- LogService timer running... 28-02 08:12:46.776 INFO [qtp987405879-281] casa.core.filter.LocaleInterceptor LocaleInterceptor.java:54- Locale for this session will be 'en_US' 28-02 08:12:46.812 DEBUG [qtp987405879-281] casa.core.navigation.HomeInitiator HomeInitiator.java:103- Starting authorization flow 28-02 08:12:46.813 TRACE [qtp987405879-281] gluu.casa.core.OxdService OxdService.java:315- Sending /get-client-token request to oxd-server with payload {"opDiscoveryPath":null,"keyId":null,"authenticationMethod":null,"clientId":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","clientSecret":"784e0c1f-e761-4234-8145-693ca8bf20ac","opHost":"https://gluu.local","client_id":"151bb377-c587-4f18-9f2f-7883d8a4a1c4","client_secret":"784e0c1f-e761-4234-8145-693ca8bf20ac","op_host":"https://gluu.local","op_discovery_path":null,"scope":["openid","profile","user_name","clientinfo","oxd"],"authentication_method":null,"algorithm":null,"key_id":null} 28-02 08:12:47.131 TRACE [qtp987405879-281] gluu.casa.core.OxdService OxdService.java:323- Response received was {"access_token":"2e159a12-5ae6-4639-898b-359560434f3b","expires_in":299,"scope":["openid","user_name","clientinfo","profile","oxd"]} 28-02 08:12:47.133 TRACE [qtp987405879-281] gluu.casa.core.OxdService OxdService.java:306- getPAT. token=2e159a12-5ae6-4639-898b-359560434f3b 28-02 08:12:47.134 TRACE [qtp987405879-281] gluu.casa.core.OxdService OxdService.java:315- Sending /get-authorization-url request to oxd-server with payload {"responseTypes":null,"customParameters":null,"hostedDomain":null,"oxdId":"0b7be594-c7e6-46f0-aeb8-159039e0576a","redirectUri":null,"acrValues":["casa"],"oxd_id":"0b7be594-c7e6-46f0-aeb8-159039e0576a","acr_values":["casa"],"prompt":null,"scope":null,"hd":null,"token":null,"state":null,"custom_parameters":null,"params":null,"redirect_uri":null,"response_types":null} 28-02 08:12:47.478 TRACE [qtp987405879-281] gluu.casa.core.OxdService OxdService.java:323- Response received was {"authorization_url":"https://gluu.local/oxauth/restv1/authorize?response_type=code&client_id=151bb377-c587-4f18-9f2f-7883d8a4a1c4&redirect_uri=https://gluu.local/casa&scope=openid+profile+user_name+clientinfo+oxd&state=7ikr64ll8lmo6k19dif9p42u00&nonce=f9gd4ve0bq27bka0artljatcld&acr_values=casa"} 28-02 08:12:47.480 DEBUG [qtp987405879-281] gluu.casa.misc.WebUtils WebUtils.java:96- Redirecting to URL=https://gluu.local/oxauth/restv1/authorize?response_type=code&client_id=151bb377-c587-4f18-9f2f-7883d8a4a1c4&redirect_uri=https://gluu.local/casa&scope=openid+profile+user_name+clientinfo+oxd&state=7ikr64ll8lmo6k19dif9p42u00&nonce=f9gd4ve0bq27bka0artljatcld&acr_values=casa 28-02 08:13:09.606 DEBUG [casaScheduler_Worker-3] gluu.casa.core.LogService LogService.java:62- LogService timer running... ``` #### oxauth.log ``` 2020-02-28 08:12:00,584 TRACE [qtp1359044626-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:301) - Found session_id cookie: 'c1c47f19-7d9f-4031-8aab-a24f433b41cd' 2020-02-28 08:12:00,586 TRACE [qtp1359044626-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:766) - Try to get session by id: c1c47f19-7d9f-4031-8aab-a24f433b41cd ... 2020-02-28 08:12:00,587 TRACE [qtp1359044626-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:768) - Session dn: c1c47f19-7d9f-4031-8aab-a24f433b41cd 2020-02-28 08:12:00,587 TRACE [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:192) - Authenticating ... (interactive: true, skipPassword: false, credentials.username: test) 2020-02-28 08:12:00,588 TRACE [qtp1359044626-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:301) - Found session_id cookie: 'c1c47f19-7d9f-4031-8aab-a24f433b41cd' 2020-02-28 08:12:00,588 TRACE [qtp1359044626-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:766) - Try to get session by id: c1c47f19-7d9f-4031-8aab-a24f433b41cd ... 2020-02-28 08:12:00,588 TRACE [qtp1359044626-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:768) - Session dn: c1c47f19-7d9f-4031-8aab-a24f433b41cd 2020-02-28 08:12:00,596 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.UserService] (UserService.java:172) - Getting user information from LDAP: attributeName = 'uid', attributeValue = 'test' 2020-02-28 08:12:00,613 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.UserService] (UserService.java:187) - Found '1' entries 2020-02-28 08:12:00,623 TRACE [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:335) - ######################################################################### 2020-02-28 08:12:00,624 TRACE [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:336) - ++++++++++++++++++++++++++++++++++++++++++CURRENT ACR:casa 2020-02-28 08:12:00,624 TRACE [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:337) - ++++++++++++++++++++++++++++++++++++++++++CURRENT STEP:1 2020-02-28 08:12:00,625 TRACE [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:340) - According to API version script supports steps overriding 2020-02-28 08:12:00,626 DEBUG [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:343) - Get next step from script: '-1' 2020-02-28 08:12:00,626 INFO [qtp1359044626-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:223) - Authentication failed for 'test' 2020-02-28 08:12:46,985 TRACE [qtp1359044626-69] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:109) - Get request to: 'https://gluu.local/oxauth/restv1/token' 2020-02-28 08:12:46,987 DEBUG [qtp1359044626-69] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:121) - Starting token endpoint authentication 2020-02-28 08:12:46,987 DEBUG [qtp1359044626-69] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:134) - Starting Basic Auth token endpoint authentication 2020-02-28 08:12:47,003 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,004 TRACE [qtp1359044626-69] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:192) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: 151bb377-c587-4f18-9f2f-7883d8a4a1c4) 2020-02-28 08:12:47,004 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:88) - Authenticating Client with LDAP: clientId = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,005 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,005 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,006 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.AuthenticationService] (AuthenticationService.java:570) - ConfigureSessionClient: username: '151bb377-c587-4f18-9f2f-7883d8a4a1c4', credentials: '404498524' 2020-02-28 08:12:47,006 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,006 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,028 INFO [qtp1359044626-69] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:276) - Authentication success for Client: '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-28 08:12:47,029 TRACE [qtp1359044626-69] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:219) - Authentication successfully for '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-28 08:12:47,043 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,055 DEBUG [qtp1359044626-69] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:104) - Attempting to request access token: grantType = client_credentials, code = null, redirectUri = null, username = null, refreshToken = null, clientId = null, ExtraParams = {grant_type=[client_credentials], scope=[openid+user_name+clientinfo+profile+oxd]}, isSecure = true, codeVerifier = null, ticket = null 2020-02-28 08:12:47,056 DEBUG [qtp1359044626-69] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:126) - Starting to validate request parameters 2020-02-28 08:12:47,056 TRACE [qtp1359044626-69] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:132) - Request parameters are right 2020-02-28 08:12:47,057 DEBUG [qtp1359044626-69] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:134) - Grant type: 'client_credentials' 2020-02-28 08:12:47,057 DEBUG [qtp1359044626-69] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:140) - Get sessionClient: 'org.gluu.oxauth.model.session.SessionClient@572bead6' 2020-02-28 08:12:47,057 DEBUG [qtp1359044626-69] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:144) - Get client from session: '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-28 08:12:47,058 TRACE [qtp1359044626-69] [gluu.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2020-02-28 08:12:47,059 DEBUG [qtp1359044626-69] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:39) - Checking scopes policy for: openid user_name clientinfo profile oxd 2020-02-28 08:12:47,082 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,082 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,083 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,083 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,084 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,084 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,084 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,085 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,085 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,085 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,085 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,086 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,086 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,086 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,087 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,087 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,087 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,088 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,088 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,088 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,089 DEBUG [qtp1359044626-69] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:68) - Granted scopes: [openid, user_name, clientinfo, profile, oxd] 2020-02-28 08:12:47,112 WARN [qtp1359044626-69] [org.gluu.oxauth.model.crypto.AbstractCryptoProvider] (AbstractCryptoProvider.java:236) - WARNING! Key with alias: ebb77bd5-f653-4e22-b527-05705921868e_sig_rs256 Expires In: 1 days Expires On: 2020-02-29 13:26:40 Today's Date: 2020-02-28 08:12:47 2020-02-28 08:12:47,206 TRACE [qtp1359044626-11440] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:109) - Get request to: 'https://gluu.local/oxauth/restv1/token' 2020-02-28 08:12:47,206 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:121) - Starting token endpoint authentication 2020-02-28 08:12:47,206 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:134) - Starting Basic Auth token endpoint authentication 2020-02-28 08:12:47,207 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,207 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,208 TRACE [qtp1359044626-11440] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:192) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: 151bb377-c587-4f18-9f2f-7883d8a4a1c4) 2020-02-28 08:12:47,208 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.ClientService] (ClientService.java:88) - Authenticating Client with LDAP: clientId = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,208 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,208 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,209 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.AuthenticationService] (AuthenticationService.java:570) - ConfigureSessionClient: username: '151bb377-c587-4f18-9f2f-7883d8a4a1c4', credentials: '404498524' 2020-02-28 08:12:47,209 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,209 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,321 INFO [qtp1359044626-11440] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:276) - Authentication success for Client: '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-28 08:12:47,321 TRACE [qtp1359044626-11440] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:219) - Authentication successfully for '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-28 08:12:47,332 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,336 DEBUG [qtp1359044626-11440] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:104) - Attempting to request access token: grantType = client_credentials, code = null, redirectUri = null, username = null, refreshToken = null, clientId = null, ExtraParams = {grant_type=[client_credentials], scope=[openid]}, isSecure = true, codeVerifier = null, ticket = null 2020-02-28 08:12:47,336 DEBUG [qtp1359044626-11440] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:126) - Starting to validate request parameters 2020-02-28 08:12:47,337 TRACE [qtp1359044626-11440] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:132) - Request parameters are right 2020-02-28 08:12:47,337 DEBUG [qtp1359044626-11440] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:134) - Grant type: 'client_credentials' 2020-02-28 08:12:47,338 DEBUG [qtp1359044626-11440] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:140) - Get sessionClient: 'org.gluu.oxauth.model.session.SessionClient@752808c6' 2020-02-28 08:12:47,338 DEBUG [qtp1359044626-11440] [gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:144) - Get client from session: '151bb377-c587-4f18-9f2f-7883d8a4a1c4' 2020-02-28 08:12:47,339 TRACE [qtp1359044626-11440] [gluu.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2020-02-28 08:12:47,339 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:39) - Checking scopes policy for: openid 2020-02-28 08:12:47,340 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,340 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,340 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,341 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,341 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,341 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:68) - Granted scopes: [openid] 2020-02-28 08:12:47,355 WARN [qtp1359044626-11440] [org.gluu.oxauth.model.crypto.AbstractCryptoProvider] (AbstractCryptoProvider.java:236) - WARNING! Key with alias: ebb77bd5-f653-4e22-b527-05705921868e_sig_rs256 Expires In: 1 days Expires On: 2020-02-29 13:26:40 Today's Date: 2020-02-28 08:12:47 2020-02-28 08:12:47,445 TRACE [qtp1359044626-14] [gluu.oxauth.introspection.ws.rs.IntrospectionWebService] (IntrospectionWebService.java:109) - Introspect token, authorization: Bearer 1d556d12-a3d0-43de-a818-e88b257883fa, token to introsppect: 2e159a12-5ae6-4639-898b-359560434f3b, tokenTypeHint: 2020-02-28 08:12:47,454 DEBUG [qtp1359044626-14] [org.gluu.oxauth.service.UserService] (UserService.java:81) - Getting user information from LDAP: userId = null 2020-02-28 08:12:47,454 TRACE [qtp1359044626-14] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,454 DEBUG [qtp1359044626-14] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,460 DEBUG [qtp1359044626-14] [org.gluu.oxauth.service.UserService] (UserService.java:81) - Getting user information from LDAP: userId = null 2020-02-28 08:12:47,460 TRACE [qtp1359044626-14] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,460 DEBUG [qtp1359044626-14] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,461 TRACE [qtp1359044626-14] [org.gluu.oxauth.model.common.AuthorizationGrant] (AuthorizationGrant.java:358) - User is null for grant 8bc20384-4ad3-4cc6-8c4c-fbc837c1a399 2020-02-28 08:12:47,467 DEBUG [qtp1359044626-14] [org.gluu.oxauth.service.external.ExternalIntrospectionService] (ExternalIntrospectionService.java:35) - There is no any external interception scripts defined. 2020-02-28 08:12:47,468 TRACE [qtp1359044626-14] [gluu.oxauth.introspection.ws.rs.IntrospectionWebService] (IntrospectionWebService.java:171) - Canceled changes made by external introspection script since method returned `false`. 2020-02-28 08:12:47,522 TRACE [qtp1359044626-69] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:109) - Get request to: 'https://gluu.local/oxauth/restv1/authorize;jsessionid=node01b1zfi3elwbj4x2bzjm7dzhha30.node0' 2020-02-28 08:12:47,523 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,523 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,523 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,524 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,526 DEBUG [qtp1359044626-69] [gluu.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] (AuthorizeRestWebServiceImpl.java:170) - Attempting to request authorization: responseType = code, clientId = 151bb377-c587-4f18-9f2f-7883d8a4a1c4, scope = openid profile user_name clientinfo oxd, redirectUri = https://gluu.local/casa, nonce = f9gd4ve0bq27bka0artljatcld, state = 7ikr64ll8lmo6k19dif9p42u00, request = null, isSecure = true, requestSessionId = null, sessionId = null 2020-02-28 08:12:47,527 DEBUG [qtp1359044626-69] [gluu.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] (AuthorizeRestWebServiceImpl.java:176) - Attempting to request authorization: acrValues = casa, amrValues = null, originHeaders = null, codeChallenge = null, codeChallengeMethod = null, customRespHeaders = null, claims = null, tokenBindingHeader = null 2020-02-28 08:12:47,527 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,528 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,528 DEBUG [qtp1359044626-69] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:39) - Checking scopes policy for: openid profile user_name clientinfo oxd 2020-02-28 08:12:47,528 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,529 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,529 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,529 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,530 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,530 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,530 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,532 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,533 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,533 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,534 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,534 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,534 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,534 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,536 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,536 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,536 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,537 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,537 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,538 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,538 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,539 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,540 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,540 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,541 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,541 DEBUG [qtp1359044626-69] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:68) - Granted scopes: [openid, user_name, clientinfo, profile, oxd] 2020-02-28 08:12:47,542 TRACE [qtp1359044626-69] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,542 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,542 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.RedirectionUriService] (RedirectionUriService.java:77) - Validating redirection URI: clientIdentifier = 151bb377-c587-4f18-9f2f-7883d8a4a1c4, redirectionUri = https://gluu.local/casa, found = 1 2020-02-28 08:12:47,543 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.RedirectionUriService] (RedirectionUriService.java:83) - Comparing https://gluu.local/casa == https://gluu.local/casa 2020-02-28 08:12:47,602 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=151bb377-c587-4f18-9f2f-7883d8a4a1c4,ou=clients,o=gluu 2020-02-28 08:12:47,603 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 151bb377-c587-4f18-9f2f-7883d8a4a1c4 2020-02-28 08:12:47,603 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:39) - Checking scopes policy for: openid profile user_name clientinfo oxd 2020-02-28 08:12:47,603 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,603 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,603 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,604 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,604 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,604 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,604 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,605 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,605 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,605 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,605 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,605 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,606 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,606 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,606 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,606 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,607 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,607 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,607 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,608 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,608 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=6D90,ou=scopes,o=gluu 2020-02-28 08:12:47,608 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=F0C4,ou=scopes,o=gluu 2020-02-28 08:12:47,608 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=43F1,ou=scopes,o=gluu 2020-02-28 08:12:47,609 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=10B2,ou=scopes,o=gluu 2020-02-28 08:12:47,609 TRACE [qtp1359044626-11440] [org.gluu.service.CacheService] (CacheService.java:56) - Loaded from cache, key: inum=341A,ou=scopes,o=gluu 2020-02-28 08:12:47,609 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:68) - Granted scopes: [openid, user_name, clientinfo, profile, oxd] 2020-02-28 08:12:47,612 TRACE [qtp1359044626-11440] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:558) - Generated new session, id = '344e588f-e1db-4387-9297-8df9af48f7ab', state = 'unauthenticated', asJwt = 'false', persisted = 'false' 2020-02-28 08:12:47,613 TRACE [qtp1359044626-11440] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:631) - sessionIdAttributes: org.gluu.oxauth.model.common.SessionIdAccessMap@4e890bdc 2020-02-28 08:12:47,613 TRACE [qtp1359044626-11440] [gluu.oxauth.authorize.ws.rs.AuthorizeAction] (AuthorizeAction.java:287) - Session '344e588f-e1db-4387-9297-8df9af48f7ab' persisted to LDAP 2020-02-28 08:12:47,652 TRACE [qtp1359044626-11440] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:301) - Found session_id cookie: '344e588f-e1db-4387-9297-8df9af48f7ab' 2020-02-28 08:12:47,653 TRACE [qtp1359044626-11440] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:766) - Try to get session by id: 344e588f-e1db-4387-9297-8df9af48f7ab ... 2020-02-28 08:12:47,653 TRACE [qtp1359044626-11440] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:768) - Session dn: 344e588f-e1db-4387-9297-8df9af48f7ab 2020-02-28 08:12:47,657 TRACE [qtp1359044626-11440] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:553) - Storing sessionIdAttributes: {auth_step=1, acr=casa, remote_ip=10.2.0.152, auth_external_attributes=null, opbs=44cb13fc-7855-4615-b285-de67864747f5, scope=openid profile user_name clientinfo oxd, acr_values=casa, response_type=code, redirect_uri=https://gluu.local/casa, state=7ikr64ll8lmo6k19dif9p42u00, nonce=f9gd4ve0bq27bka0artljatcld, client_id=151bb377-c587-4f18-9f2f-7883d8a4a1c4} 2020-02-28 08:12:47,657 TRACE [qtp1359044626-11440] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:554) - Storing authExternalAttributes: {} 2020-02-28 08:13:01,624 TRACE [ForkJoinPool.commonPool-worker-0] [org.gluu.oxauth.service.AppInitializer] (AppInitializer.java:275) - Attempting to use persistenceEntryManager: org.gluu.persist.ldap.operation.impl.LdapOperationsServiceImpl@5c24a636 2020-02-28 08:13:02,882 TRACE [qtp1359044626-68] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:301) - Found session_id cookie: '344e588f-e1db-4387-9297-8df9af48f7ab' 2020-02-28 08:13:02,883 TRACE [qtp1359044626-68] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:766) - Try to get session by id: 344e588f-e1db-4387-9297-8df9af48f7ab ... 2020-02-28 08:13:02,883 TRACE [qtp1359044626-68] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:768) - Session dn: 344e588f-e1db-4387-9297-8df9af48f7ab 2020-02-28 08:13:02,883 TRACE [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:192) - Authenticating ... (interactive: true, skipPassword: false, credentials.username: test) 2020-02-28 08:13:02,883 TRACE [qtp1359044626-68] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:301) - Found session_id cookie: '344e588f-e1db-4387-9297-8df9af48f7ab' 2020-02-28 08:13:02,884 TRACE [qtp1359044626-68] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:766) - Try to get session by id: 344e588f-e1db-4387-9297-8df9af48f7ab ... 2020-02-28 08:13:02,884 TRACE [qtp1359044626-68] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:768) - Session dn: 344e588f-e1db-4387-9297-8df9af48f7ab 2020-02-28 08:13:02,889 DEBUG [qtp1359044626-68] [org.gluu.oxauth.service.UserService] (UserService.java:172) - Getting user information from LDAP: attributeName = 'uid', attributeValue = 'test' 2020-02-28 08:13:02,904 DEBUG [qtp1359044626-68] [org.gluu.oxauth.service.UserService] (UserService.java:187) - Found '1' entries 2020-02-28 08:13:02,915 TRACE [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:335) - ######################################################################### 2020-02-28 08:13:02,915 TRACE [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:336) - ++++++++++++++++++++++++++++++++++++++++++CURRENT ACR:casa 2020-02-28 08:13:02,915 TRACE [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:337) - ++++++++++++++++++++++++++++++++++++++++++CURRENT STEP:1 2020-02-28 08:13:02,916 TRACE [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:340) - According to API version script supports steps overriding 2020-02-28 08:13:02,917 DEBUG [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:343) - Get next step from script: '-1' 2020-02-28 08:13:02,918 INFO [qtp1359044626-68] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:223) - Authentication failed for 'test' ``` #### oxauth_script.log ``` 2020-02-28 08:11:09,015 TRACE [oxAuthScheduler_Worker-5] [org.gluu.service.custom.script.CustomScriptManager] (CustomScriptManager.java:126) - Last finished time '2020-02-28T08:11:09.015+0100' 2020-02-28 08:11:38,034 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:277) - Executing python 'getPageForStep' authenticator method 2020-02-28 08:11:38,036 INFO [qtp1359044626-11440] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getPageForStep called 1 2020-02-28 08:11:38,076 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:384) - Validating acr_values: 'casa' 2020-02-28 08:11:38,077 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:151) - Executing python 'isValidAuthenticationMethod' authenticator method 2020-02-28 08:11:38,078 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. isValidAuthenticationMethod called 2020-02-28 08:11:38,079 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:249) - Executing python 'prepareForStep' authenticator method 2020-02-28 08:11:38,080 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. prepareForStep 1 2020-02-28 08:11:38,080 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method 2020-02-28 08:11:38,080 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getExtraParametersForStep 1 2020-02-28 08:11:39,002 TRACE [oxAuthScheduler_Worker-1] [org.gluu.service.custom.script.CustomScriptManager] (CustomScriptManager.java:126) - Last finished time '2020-02-28T08:11:39.002+0100' 2020-02-28 08:11:40,497 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:193) - Executing python 'authenticate' authenticator method 2020-02-28 08:11:40,497 INFO [qtp1359044626-69] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. authenticate 1 2020-02-28 08:11:40,525 INFO [qtp1359044626-69] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getAvailMethodsUser. hasEnrollments call could not be issued for super_gluu module 2020-02-28 08:11:40,525 INFO [qtp1359044626-69] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getAvailMethodsUser [] 2020-02-28 08:11:40,527 INFO [qtp1359044626-69] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getSuitableAcr. On mobile = False 2020-02-28 08:11:40,527 INFO [qtp1359044626-69] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getSuitableAcr. None was selected for user test 2020-02-28 08:11:40,528 INFO [qtp1359044626-69] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. authenticate for step 1 was not successful 2020-02-28 08:11:40,529 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:291) - Executing python 'getApiVersion' authenticator method 2020-02-28 08:11:40,529 DEBUG [qtp1359044626-69] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:207) - Executing python 'getNextStep' authenticator method 2020-02-28 08:11:40,529 INFO [qtp1359044626-69] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getNextStep called 1 2020-02-28 08:12:00,589 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:193) - Executing python 'authenticate' authenticator method 2020-02-28 08:12:00,592 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. authenticate 1 2020-02-28 08:12:00,620 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getAvailMethodsUser. hasEnrollments call could not be issued for super_gluu module 2020-02-28 08:12:00,621 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getAvailMethodsUser [] 2020-02-28 08:12:00,622 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getSuitableAcr. On mobile = False 2020-02-28 08:12:00,623 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getSuitableAcr. None was selected for user test 2020-02-28 08:12:00,623 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. authenticate for step 1 was not successful 2020-02-28 08:12:00,624 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:291) - Executing python 'getApiVersion' authenticator method 2020-02-28 08:12:00,625 DEBUG [qtp1359044626-12] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:207) - Executing python 'getNextStep' authenticator method 2020-02-28 08:12:00,625 INFO [qtp1359044626-12] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getNextStep called 1 2020-02-28 08:12:09,027 TRACE [oxAuthScheduler_Worker-1] [org.gluu.service.custom.script.CustomScriptManager] (CustomScriptManager.java:126) - Last finished time '2020-02-28T08:12:09.027+0100' 2020-02-28 08:12:39,012 TRACE [oxAuthScheduler_Worker-4] [org.gluu.service.custom.script.CustomScriptManager] (CustomScriptManager.java:126) - Last finished time '2020-02-28T08:12:39.012+0100' 2020-02-28 08:12:47,610 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:277) - Executing python 'getPageForStep' authenticator method 2020-02-28 08:12:47,611 INFO [qtp1359044626-11440] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getPageForStep called 1 2020-02-28 08:12:47,654 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:384) - Validating acr_values: 'casa' 2020-02-28 08:12:47,654 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:151) - Executing python 'isValidAuthenticationMethod' authenticator method 2020-02-28 08:12:47,654 INFO [qtp1359044626-11440] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. isValidAuthenticationMethod called 2020-02-28 08:12:47,655 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:249) - Executing python 'prepareForStep' authenticator method 2020-02-28 08:12:47,655 INFO [qtp1359044626-11440] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. prepareForStep 1 2020-02-28 08:12:47,656 DEBUG [qtp1359044626-11440] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method 2020-02-28 08:12:47,656 INFO [qtp1359044626-11440] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getExtraParametersForStep 1 2020-02-28 08:13:02,885 DEBUG [qtp1359044626-68] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:193) - Executing python 'authenticate' authenticator method 2020-02-28 08:13:02,886 INFO [qtp1359044626-68] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. authenticate 1 2020-02-28 08:13:02,910 INFO [qtp1359044626-68] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getAvailMethodsUser. hasEnrollments call could not be issued for super_gluu module 2020-02-28 08:13:02,913 INFO [qtp1359044626-68] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getAvailMethodsUser [] 2020-02-28 08:13:02,913 INFO [qtp1359044626-68] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getSuitableAcr. On mobile = False 2020-02-28 08:13:02,914 INFO [qtp1359044626-68] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getSuitableAcr. None was selected for user test 2020-02-28 08:13:02,914 INFO [qtp1359044626-68] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. authenticate for step 1 was not successful 2020-02-28 08:13:02,916 DEBUG [qtp1359044626-68] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:291) - Executing python 'getApiVersion' authenticator method 2020-02-28 08:13:02,916 DEBUG [qtp1359044626-68] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:207) - Executing python 'getNextStep' authenticator method 2020-02-28 08:13:02,917 INFO [qtp1359044626-68] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Casa. getNextStep called 1 ```

By Mohib Zico staff 02 Mar 2020 at 8:13 a.m. CST

Mohib Zico gravatar
@Mohit.Mali: Can you please test this scenario?

By Mohit Mali staff 03 Mar 2020 at 12:14 a.m. CST

Mohit Mali gravatar
Yes sure , let me test this scenario.

By Not Ce user 26 Mar 2020 at 4:13 a.m. CDT

Not Ce gravatar
@Mohit.Mali Have you be able to test this issue by now? Thanks for your response.

By Mohib Zico staff 16 Apr 2020 at 10:46 a.m. CDT

Mohib Zico gravatar
Mohit has been busy. I am re-assigning ticket to me.