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
```