By: Jeff E Mandel user 05 Jun 2019 at 9:01 a.m. CDT

9 Responses

I have Casa installed and it has been running successfully until a few days ago. Now, all users are locked out if they have any 2FA method enabled. If I reset to password only, they can login. I have restarted casa, restarted all of the services, and restarted the entire VM without any change. This is the second time this has happened; the last time I brought it back by removing and reinstalling casa. Before I do this again, I thought I'd try to figure out the root cause. I've looked at the casa.log (at DEBUG level); no obvious error messages. I looked at oxauth.log and oxtrust.log. There are no errors. If I authenticate with password only, I get: ``` 2019-06-05 13:28:11,064 INFO [qtp804611486-10] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:409) - Authentication success for User: 'jeffemandel' ``` With my Yubikey enabled, I get: ``` 2019-06-05 13:29:58,541 INFO [qtp804611486-11] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:209) - Authentication failed for 'jeffemandel' 2019-06-05 13:30:29,940 INFO [qtp804611486-11] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:533) - Attempting to redirect user: SessionUser: SessionState {dn='oxAuthSessionId=134818d3-649d-4fb5-933a-4c575848b1ff,ou=session,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', id='134818d3-649d-4fb5-933a-4c575848b1ff', lastUsedAt=Wed Jun 05 13:30:29 UTC 2019, userDn='inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0000!BDA7.FC0A.928D.3B5A,ou=people,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', authenticationTime=Wed Jun 05 13:30:29 UTC 2019, state=authenticated, sessionState='redacted', permissionGranted=null, isJwt=false, jwt=null, permissionGrantedMap=org.xdi.oxauth.model.common.SessionIdAccessMap@5b08e7af, involvedClients=null, sessionAttributes={auth_external_attributes=null, opbs=1ecf979b-86ff-424d-b3a3-5ccc6031b6b6, response_type=code, nonce=redacted, client_id=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A, auth_step=1, acr=casa, remote_ip=192.168.1.29, auth_user=jeffemandel, scope=openid profile user_name clientinfo, acr_values=casa, redirect_uri=https://gluu.example.org/casa, state=redacted}, persisted=true} ``` The only other thing I've noticed is that the administrative dashboard isn't showing any logins, successful or failed.

Ubuntu 16.04 Gluu Casa 3.1.6 Ubuntu 16.04

closed

By Jose Gonzalez staff 05 Jun 2019 at 10:31 a.m. CDT

Copy

Hi Jeff, We're glad to hear you are intested in Casa. > all users are locked out if they have any 2FA method enabled What is the end-user facing actually? are they able to enter user+pwd and then an error comes out? are they requested for the second factor and then validation of it fails? Please give as much details as possible > There are no errors. To diagnose we are going to need in trace level (for a failed login attempt) the following: oxauth.log, oxauth_Script.log, casa.log. Also, have you checked casa_async_jobs.log? > The only other thing I've noticed is that the administrative dashboard isn't showing any logins, successful or failed. it's very suspicious indeed

By Jeff E Mandel user 05 Jun 2019 at 11:19 a.m. CDT

Copy

The failure comes immediately after enetering username/password, it doesn't get to the point of asking for the 2FA. I've tried this for both u2f and supergluu. The oxauth_script.log contains: ``` 2019-06-05 02:10:02,054 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 02:10:02,062 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 02:10:02,062 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 02:10:02,063 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 02:10:15,427 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 02:10:15,437 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 02:10:15,437 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 02:10:15,438 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 02:10:15,438 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 02:10:15,580 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Permission dynamic scope scope. Update method 2019-06-05 02:24:44,730 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 02:24:44,739 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 02:24:44,740 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 02:24:44,740 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:06:25,780 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:06:25,791 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:06:25,792 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:06:25,793 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:06:42,702 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:06:42,722 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:06:42,724 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:06:42,725 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:06:42,725 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:06:42,868 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Permission dynamic scope scope. Update method 2019-06-05 12:15:33,684 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:15:33,685 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:15:33,685 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:16:06,836 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:16:06,844 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:16:06,845 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:16:06,845 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:16:08,338 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:16:08,346 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:16:08,347 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:16:08,347 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:16:08,348 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:17:38,892 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa client registration. UpdateClient method 2019-06-05 12:17:38,901 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa client registration. Adding scope 'profile' 2019-06-05 12:17:38,902 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa client registration. Adding scope 'user_name' 2019-06-05 12:17:38,903 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa client registration. Adding scope 'clientinfo' 2019-06-05 12:17:38,905 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa client registration. Result scopes are: array(java.lang.String, [u'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0009!6D90,ou=scopes,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', u'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0009!F0C4,ou=scopes,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', u'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0009!C4F5.F66C,ou=scopes,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', u'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0009!6D99,ou=scopes,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', u'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0009!43F1,ou=scopes,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', u'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0009!10B2,ou=scopes,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu', u'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0009!341A,ou=scopes,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu']) 2019-06-05 12:18:36,689 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:18:36,697 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:18:36,698 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:18:36,698 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:18:43,127 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:18:43,131 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate for step 1 was not successful 2019-06-05 12:18:43,132 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:30:37,147 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. Destroyed called 2019-06-05 12:30:37,667 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init called 2019-06-05 12:30:37,668 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. uid attribute is 'uid' 2019-06-05 12:30:37,687 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Loading scripts for dynamic modules: [u'u2f', u'otp', u'super_gluu'] 2019-06-05 12:30:37,696 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_u2f 2019-06-05 12:30:37,696 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 12:30:37,696 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_u2f 2019-06-05 12:30:37,706 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_otp 2019-06-05 12:30:37,706 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 12:30:37,706 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_otp 2019-06-05 12:30:37,715 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_super_gluu 2019-06-05 12:30:37,715 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 12:30:37,715 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_super_gluu 2019-06-05 12:30:37,716 INFO [oxAuthScheduler_Worker-3] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Initialized successfully 2019-06-05 12:31:19,265 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:31:19,272 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:31:19,273 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:31:19,273 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:31:22,901 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:31:22,905 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate for step 1 was not successful 2019-06-05 12:31:22,906 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:31:52,132 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:31:52,148 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:31:52,149 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:31:52,150 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:31:52,150 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:32:21,710 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:32:21,716 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:32:21,716 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:32:21,717 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:32:25,967 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:32:25,969 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate for step 1 was not successful 2019-06-05 12:32:25,970 INFO [qtp804611486-18] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:33:58,711 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:33:58,730 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:33:58,731 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:33:58,734 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:33:58,734 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:36:16,280 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:36:16,286 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:36:16,286 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:36:16,286 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:36:20,163 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:36:20,172 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:36:20,172 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:36:20,172 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:36:20,173 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:36:46,126 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:36:46,133 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:36:46,134 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:36:46,134 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:36:48,437 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:36:48,440 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate for step 1 was not successful 2019-06-05 12:36:48,440 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:37:07,497 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:37:07,505 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:37:07,506 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:37:07,506 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:37:07,507 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:37:26,695 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:37:26,704 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:37:26,705 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:37:26,705 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:37:32,073 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:37:32,081 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:37:32,081 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:37:32,083 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:37:32,083 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:37:56,340 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:37:56,347 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:37:56,347 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:37:56,347 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 12:37:58,005 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:37:58,008 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate for step 1 was not successful 2019-06-05 12:37:58,008 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:38:07,949 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 12:38:07,957 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 12:38:07,958 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 12:38:07,958 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 12:38:07,958 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 12:44:37,146 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. Destroyed called 2019-06-05 12:44:37,523 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init called 2019-06-05 12:44:37,524 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. uid attribute is 'uid' 2019-06-05 12:44:37,542 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Loading scripts for dynamic modules: [u'u2f', u'otp', u'super_gluu'] 2019-06-05 12:44:37,550 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_u2f 2019-06-05 12:44:37,550 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 12:44:37,550 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_u2f 2019-06-05 12:44:37,558 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_otp 2019-06-05 12:44:37,559 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 12:44:37,559 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_otp 2019-06-05 12:44:37,573 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_super_gluu 2019-06-05 12:44:37,573 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 12:44:37,574 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_super_gluu 2019-06-05 12:44:37,574 INFO [oxAuthScheduler_Worker-5] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Initialized successfully 2019-06-05 12:52:56,968 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 12:52:56,975 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 12:52:56,976 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 12:52:56,978 INFO [qtp804611486-16] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 13:26:40,186 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init called 2019-06-05 13:26:40,222 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. uid attribute is 'uid' 2019-06-05 13:26:40,430 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Loading scripts for dynamic modules: [u'u2f', u'otp', u'super_gluu'] 2019-06-05 13:26:40,453 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_u2f 2019-06-05 13:26:40,453 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 13:26:40,453 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_u2f 2019-06-05 13:26:40,468 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_otp 2019-06-05 13:26:40,468 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 13:26:40,476 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_otp 2019-06-05 13:26:40,492 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_super_gluu 2019-06-05 13:26:40,493 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 13:26:40,493 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_super_gluu 2019-06-05 13:26:40,493 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Initialized successfully 2019-06-05 13:26:40,927 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Load. Failed to load licensing API 2019-06-05 13:26:43,676 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialization 2019-06-05 13:26:43,677 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialize Native/SNS/Gluu notification services 2019-06-05 13:26:43,677 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialize Gluu notification services 2019-06-05 13:26:43,678 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialize notification services 2019-06-05 13:26:44,025 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialize Gluu notification services. Assuming that 'gluu_secret_access_key' in not encrypted 2019-06-05 13:26:44,025 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialize Gluu notification services. Created Android notification service 2019-06-05 13:26:44,026 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialize Gluu notification services. Assuming that 'gluu_secret_access_key' in not encrypted 2019-06-05 13:26:44,026 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialize Gluu notification services. Created iOS notification service 2019-06-05 13:26:44,034 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Super-Gluu. Initialized successfully. oneStep: 'False', twoStep: 'True', pushNotifications: 'True', customLabel: 'Super Gluu' 2019-06-05 13:26:44,100 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Permission dynamic scope. Initialization 2019-06-05 13:26:44,100 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Permission dynamic scope. Initialized successfully 2019-06-05 13:26:44,645 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Fido2. Initialization 2019-06-05 13:26:44,645 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Fido2. Initialized successfully 2019-06-05 13:26:44,662 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Introspection script. Initializing ... 2019-06-05 13:26:44,662 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Introspection script. Initialized successfully 2019-06-05 13:26:44,713 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa client registration. Initialization 2019-06-05 13:26:44,713 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa client registration. Initialized successfully 2019-06-05 13:26:45,182 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - OTP. Initialization 2019-06-05 13:26:45,183 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - OTP. Load OTP configuration 2019-06-05 13:26:45,209 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - OTP. Initialized successfully 2019-06-05 13:26:45,235 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - U2F. Initialization 2019-06-05 13:26:45,236 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - U2F. Initialization. Downloading U2F metadata 2019-06-05 13:26:45,495 INFO [Thread-23] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - U2F. Initialized successfully 2019-06-05 13:27:15,569 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. Destroyed called 2019-06-05 13:27:16,382 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init called 2019-06-05 13:27:16,383 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. uid attribute is 'uid' 2019-06-05 13:27:16,469 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Loading scripts for dynamic modules: [u'u2f', u'otp', u'super_gluu'] 2019-06-05 13:27:16,491 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_u2f 2019-06-05 13:27:16,492 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 13:27:16,492 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_u2f 2019-06-05 13:27:16,520 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_otp 2019-06-05 13:27:16,520 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 13:27:16,520 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_otp 2019-06-05 13:27:16,537 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Failed to load module casa-external_super_gluu 2019-06-05 13:27:16,537 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Exception: 2019-06-05 13:27:16,537 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - No module named casa-external_super_gluu 2019-06-05 13:27:16,537 INFO [oxAuthScheduler_Worker-4] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. init. Initialized successfully 2019-06-05 13:27:50,277 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 13:27:50,285 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 13:27:50,286 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 13:27:50,286 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 13:27:54,332 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 13:27:54,362 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 13:27:54,363 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 13:27:54,364 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 13:27:54,364 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 13:28:07,520 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 13:28:07,530 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 13:28:07,530 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 13:28:07,531 INFO [qtp804611486-9] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 13:28:11,026 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 13:28:11,050 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 13:28:11,051 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 13:28:11,052 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 13:28:11,052 INFO [qtp804611486-10] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 13:29:56,695 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 13:29:56,706 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 13:29:56,707 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 13:29:56,707 INFO [qtp804611486-12] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 13:29:58,533 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 13:29:58,539 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate for step 1 was not successful 2019-06-05 13:29:58,540 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 13:30:06,436 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 13:30:06,459 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 13:30:06,459 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 13:30:06,460 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 13:30:06,461 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called 2019-06-05 13:30:27,125 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getPageForStep called 1 2019-06-05 13:30:27,133 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. isValidAuthenticationMethod called 2019-06-05 13:30:27,134 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. prepareForStep 1 2019-06-05 13:30:27,134 INFO [qtp804611486-17] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 1 2019-06-05 13:30:29,905 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. authenticate 1 2019-06-05 13:30:29,932 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getNextStep called 1 2019-06-05 13:30:29,933 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getExtraParametersForStep 2 2019-06-05 13:30:29,934 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - extras are [ACR, methods, trustedDevicesInfo] 2019-06-05 13:30:29,934 INFO [qtp804611486-11] [org.xdi.service.PythonService$PythonLoggerOutputStream] (PythonService.java:239) - Casa. getCountAuthenticationSteps called ``` The only error I see in casa_async_jobs.log is: ``` 05-06 00:21:50.325 ERROR [casaScheduler_Worker-4] timer.StatisticsTimer StatisticsTimer.java:165- null java.lang.NullPointerException: null at org.gluu.casa.timer.StatisticsTimer.getPluginInfo(StatisticsTimer.java:219) ~[classes/:?] at org.gluu.casa.timer.StatisticsTimer.jobToBeExecuted(StatisticsTimer.java:161) [classes/:?] at org.quartz.core.QuartzScheduler.notifyJobListenersToBeExecuted(QuartzScheduler.java:1945) [quartz-2.2.3.jar:?] at org.quartz.core.JobRunShell.notifyListenersBeginning(JobRunShell.java:324) [quartz-2.2.3.jar:?] at org.quartz.core.JobRunShell.run(JobRunShell.java:173) [quartz-2.2.3.jar:?] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [quartz-2.2.3.jar:?] ``` Here is oxauth.log with TRACE level for a failed login: ``` 2019-06-05 16:12:17,454 INFO [main] [org.jboss.weld.environment.servlet.EnhancedListener] (EnhancedListener.java:58) - WELD-ENV-001008: Initialize Weld using ServletContainerInitializer 2019-06-05 16:12:17,480 INFO [main] [org.jboss.weld.bootstrap.WeldStartup] (WeldStartup.java:148) - WELD-000900: 3.0.5 (Final) 2019-06-05 16:12:17,752 INFO [main] [jboss.weld.environment.deployment.discovery.ReflectionDiscoveryStrategy] (ReflectionDiscoveryStrategy.java:49) - WELD-ENV-000014: Falling back to Java Reflection for bean-discovery-mode="annotated" discovery. Add org.jboss:jandex to the classpath to speed-up startup. 2019-06-05 16:12:17,915 INFO [main] [org.jboss.weld.bootstrap.WeldStartup] (WeldStartup.java:225) - WELD-000101: Transactional services not available. Injection of @Inject UserTransaction not available. Transactional observers will be invoked synchronously. 2019-06-05 16:12:18,103 INFO [main] [org.jboss.weld.event.ExtensionObserverMethodImpl] (ExtensionObserverMethodImpl.java:86) - WELD-000411: Observer method [BackedAnnotatedMethod] public org.xdi.service.exception.ExceptionHandlerExtension.processAnnotatedType(@Observes ProcessAnnotatedType<X>) receives events for all annotated types. Consider restricting events using @WithAnnotations or a generic type with bounds. 2019-06-05 16:12:18,115 INFO [main] [org.jboss.weld.event.ExtensionObserverMethodImpl] (ExtensionObserverMethodImpl.java:86) - WELD-000411: Observer method [BackedAnnotatedMethod] public org.xdi.service.security.SecurityExtension.processAnnotatedType(@Observes ProcessAnnotatedType<X>) receives events for all annotated types. Consider restricting events using @WithAnnotations or a generic type with bounds. 2019-06-05 16:12:18,152 WARN [main] [org.jboss.weld.bootstrap.events.BeforeBeanDiscoveryImpl] (BeforeBeanDiscoveryImpl.java:118) - WELD-000146: BeforeBeanDiscovery.addAnnotatedType(AnnotatedType) used for class org.hibernate.validator.internal.cdi.interceptor.ValidationInterceptor is deprecated from CDI 1.1! 2019-06-05 16:12:18,165 WARN [main] [org.jboss.weld.bootstrap.events.BeforeBeanDiscoveryImpl] (BeforeBeanDiscoveryImpl.java:118) - WELD-000146: BeforeBeanDiscovery.addAnnotatedType(AnnotatedType) used for class com.sun.faces.flow.FlowDiscoveryCDIHelper is deprecated from CDI 1.1! 2019-06-05 16:12:18,182 INFO [weld-worker-1] [org.jboss.weld.bootstrap.MissingDependenciesRegistry] (MissingDependenciesRegistry.java:46) - WELD-000119: Not generating any bean definitions from org.gluu.jsf2.customization.AccessRewriteConfiguration because of underlying class loading error: Type org.ocpsoft.rewrite.servlet.config.HttpConfigurationProvider not found. If this is unexpected, enable DEBUG logging to see the full error. 2019-06-05 16:12:20,085 INFO [main] [org.jboss.weld.environment.jetty.JettyContainer] (JettyContainer.java:77) - WELD-ENV-001200: Jetty 7.2+ detected, CDI injection will be available in Servlets and Filters. Injection into Listeners should work on Jetty 9.1.1 and newer. 2019-06-05 16:12:21,340 INFO [main] [org.xdi.oxauth.model.util.SecurityProviderUtility] (SecurityProviderUtility.java:24) - Adding Bouncy Castle Provider 2019-06-05 16:12:22,020 INFO [main] [org.xdi.oxauth.model.config.ConfigurationFactory] (ConfigurationFactory.java:337) - Loading configuration from LDAP... 2019-06-05 16:12:22,092 INFO [main] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:330) - Created ldapEntryManager:org.gluu.site.ldap.persistence.LdapEntryManager@4e260e04 with provider org.xdi.service.ldap.LdapConnectionService@3c199e06 2019-06-05 16:12:22,300 INFO [main] [org.xdi.service.logger.LoggerService] (LoggerService.java:175) - External log configuration: 2019-06-05 16:12:22,300 INFO [main] [org.xdi.service.logger.LoggerService] (LoggerService.java:118) - Setting loggers level to: 'TRACE' 2019-06-05 16:12:22,301 INFO [main] [org.xdi.service.logger.LoggerService] (LoggerService.java:145) - Uppdated log level of '19' loggers to TRACE 2019-06-05 16:12:22,302 INFO [main] [org.xdi.oxauth.model.config.ConfigurationFactory] (ConfigurationFactory.java:170) - Configuration loaded successfully. 2019-06-05 16:12:23,155 INFO [main] [org.quartz.impl.StdSchedulerFactory] (StdSchedulerFactory.java:1172) - Using default implementation for ThreadExecutor 2019-06-05 16:12:23,213 INFO [main] [org.quartz.core.SchedulerSignalerImpl] (SchedulerSignalerImpl.java:61) - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl 2019-06-05 16:12:23,214 INFO [main] [org.quartz.core.QuartzScheduler] (QuartzScheduler.java:240) - Quartz Scheduler v.2.2.3 created. 2019-06-05 16:12:23,215 INFO [main] [org.quartz.simpl.RAMJobStore] (RAMJobStore.java:155) - RAMJobStore initialized. 2019-06-05 16:12:23,216 INFO [main] [org.quartz.core.QuartzScheduler] (QuartzScheduler.java:305) - Scheduler meta-data: Quartz Scheduler (v2.2.3) 'oxAuthScheduler' with instanceId 'NON_CLUSTERED' Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally. NOT STARTED. Currently in standby mode. Number of jobs executed: 0 Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 5 threads. Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered. 2019-06-05 16:12:23,216 INFO [main] [org.quartz.impl.StdSchedulerFactory] (StdSchedulerFactory.java:1327) - Quartz scheduler 'oxAuthScheduler' initialized from the specified file : 'quartz.properties' from the class resource path. 2019-06-05 16:12:23,216 INFO [main] [org.quartz.impl.StdSchedulerFactory] (StdSchedulerFactory.java:1331) - Quartz scheduler version: 2.2.3 2019-06-05 16:12:23,217 INFO [main] [org.quartz.core.QuartzScheduler] (QuartzScheduler.java:2311) - JobFactory set to: org.xdi.service.timer.JobExecutionFactory@3349d202 2019-06-05 16:12:23,219 INFO [main] [org.xdi.service.timer.QuartzSchedulerManager] (QuartzSchedulerManager.java:62) - Quartz scheduler manager initialized 2019-06-05 16:12:23,219 INFO [main] [org.quartz.core.QuartzScheduler] (QuartzScheduler.java:575) - Scheduler oxAuthScheduler_$_NON_CLUSTERED started. 2019-06-05 16:12:23,219 INFO [main] [org.xdi.service.timer.QuartzSchedulerManager] (QuartzSchedulerManager.java:116) - Quartz scheduler started 2019-06-05 16:12:23,231 DEBUG [main] [org.xdi.oxauth.model.config.ConfigurationFactory] (ConfigurationFactory.java:175) - Initializing Configuration Timer 2019-06-05 16:12:23,239 INFO [main] [org.xdi.service.logger.LoggerService] (LoggerService.java:47) - Initializing Logger Update Timer 2019-06-05 16:12:23,810 INFO [main] [org.gluu.oxauth.fido2.certification.DirectoryBasedMetadataLoader] (DirectoryBasedMetadataLoader.java:68) - Populating metadata from /etc/gluu/conf/fido2/server_metadata 2019-06-05 16:12:23,813 INFO [main] [gluu.oxauth.fido2.service.mds.MdsTocService] (MdsTocService.java:111) - Populating TOC entries from /etc/gluu/conf/fido2/mds/toc 2019-06-05 16:12:23,937 INFO [main] [org.jboss.weld.environment.servlet.Listener] (Listener.java:112) - WELD-ENV-001006: org.jboss.weld.environment.servlet.EnhancedListener used to initialize Weld 2019-06-05 16:12:25,314 INFO [main] [org.jboss.weld.environment.servlet.EnhancedListener] (EnhancedListener.java:75) - WELD-ENV-001009: org.jboss.weld.environment.servlet.Listener used for ServletRequest and HttpSession notifications 2019-06-05 16:12:25,660 INFO [main] [org.jboss.resteasy.spi.ResteasyDeployment] (ResteasyDeployment.java:518) - RESTEASY002225: Deploying javax.ws.rs.core.Application: class org.xdi.oxauth.service.ResteasyInitializer$Proxy$_$$_WeldClientProxy 2019-06-05 16:12:25,661 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jaxb.JAXBXmlRootElementProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,662 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jaxb.XmlJAXBContextFinder is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,662 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.JaxrsFormProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,689 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.SourceProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,694 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.DefaultNumberWriter is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,695 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.ReaderProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,699 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.DefaultTextPlain is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,699 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.FileProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,699 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.IIOImageProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,700 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jaxb.MapProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,701 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.InputStreamProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,701 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.FormUrlEncodedProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,704 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jaxb.JAXBXmlTypeProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,705 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.StringTextStar is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,706 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jaxb.CollectionProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,712 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.DocumentProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,713 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jackson.ResteasyJacksonProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,713 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.interceptors.encoding.MessageSanitizerContainerResponseFilter is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,713 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.DataSourceProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,713 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jaxb.JAXBXmlSeeAlsoProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,713 WARN [main] [org.jboss.resteasy.spi.ResteasyProviderFactory] (ResteasyProviderFactory.java:1413) - RESTEASY002155: Provider class org.jboss.resteasy.plugins.providers.jaxb.JAXBElementProvider is already registered. 2nd registration is being ignored. 2019-06-05 16:12:25,837 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType text/plain on requestEndSession() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:25,898 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType text/plain on requestEndSession() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:26,137 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType text/plain on requestAuthorizationGet() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:26,303 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType text/plain on requestAuthorizationPost() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:26,522 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType text/plain on requestAuthorizationGet() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:26,693 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType text/plain on requestAuthorizationPost() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:26,863 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType application/xml on get() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:26,863 WARN [main] [org.jboss.resteasy.spi.metadata.ResourceBuilder$ResourceMethodBuilder] (ResourceBuilder.java:581) - RESTEASY002141: MediaType application/xml on get() lacks charset. Consider setting charset or turning on context parameter resteasy.add.charset 2019-06-05 16:12:38,263 INFO [Thread-25] [org.xdi.service.logger.LoggerService] (LoggerService.java:145) - Uppdated log level of '43' loggers to TRACE 2019-06-05 16:12:38,731 INFO [qtp804611486-17] [org.xdi.oxauth.service.ApplicationFactory] (ApplicationFactory.java:63) - Cache configuration: CacheConfiguration{cacheProviderType=IN_MEMORY, memcachedConfiguration=MemcachedConfiguration{servers='localhost:11211', maxOperationQueueLength=100000, bufferSize=32768, defaultPutExpiration=60, connectionFactoryType=DEFAULT}, redisConfiguration=RedisConfiguration{servers='localhost:6379', defaultPutExpiration=60, redisProviderType=STANDALONE, useSSL=false, sslTrustStoreFilePath=}, inMemoryConfiguration=InMemoryConfiguration{defaultPutExpiration=60}, nativePersistenceConfiguration=NativePersistenceConfiguration [defaultPutExpiration=60, defaultCleanupBatchSize=25, baseDn=o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu]} 2019-06-05 16:12:38,737 ERROR [qtp804611486-17] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:608) - Failed to get attributes from session 2019-06-05 16:12:44,669 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/token' 2019-06-05 16:12:44,670 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:98) - Starting token endpoint authentication 2019-06-05 16:12:44,673 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:111) - Starting Basic Auth token endpoint authentication 2019-06-05 16:12:44,705 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:12:44,706 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:101) - Authenticating Client with LDAP: clientId = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:12:44,707 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:44,707 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:12:44,707 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:515) - ConfigureSessionClient: username: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286', credentials: '646376683' 2019-06-05 16:12:44,707 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:44,708 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:12:44,732 INFO [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:12:44,752 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:12:45,179 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:70) - Looking for the error with id: invalid_grant 2019-06-05 16:12:45,180 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:75) - Found error, id: invalid_grant 2019-06-05 16:12:46,700 TRACE [qtp804611486-17] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/authorize' 2019-06-05 16:12:46,715 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:46,743 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:46,743 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:46,789 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:46,789 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:46,882 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:46,882 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,159 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,160 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,165 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,165 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,166 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,167 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,168 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,168 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,172 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,174 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,177 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,177 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,178 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,179 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,179 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,180 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,206 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,207 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:47,207 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:47,208 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,362 INFO [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:209) - Authentication failed for 'jeffemandel' 2019-06-05 16:12:49,375 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,376 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,376 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,376 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,377 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,378 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,378 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,379 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,381 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,381 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,382 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,382 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,383 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,384 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,384 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,384 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,392 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,393 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:49,393 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:12:49,394 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!CB68.7AA3.B1F5.DC9A 2019-06-05 16:12:53,241 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:12:53,242 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:12:53,243 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.ConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:12:53,245 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:12:53,245 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:12:53,246 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:12:53,248 INFO [Thread-31] [org.xdi.service.logger.LoggerService] (LoggerService.java:145) - Uppdated log level of '31' loggers to TRACE 2019-06-05 16:13:01,125 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:01,126 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:01,166 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:08,247 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:08,248 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:08,249 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:14,718 TRACE [qtp804611486-17] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/token' 2019-06-05 16:13:14,718 DEBUG [qtp804611486-17] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:98) - Starting token endpoint authentication 2019-06-05 16:13:14,719 DEBUG [qtp804611486-17] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:111) - Starting Basic Auth token endpoint authentication 2019-06-05 16:13:14,719 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:13:14,719 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:14,722 TRACE [qtp804611486-17] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:181) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286) 2019-06-05 16:13:14,722 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:101) - Authenticating Client with LDAP: clientId = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:14,722 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:13:14,722 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:14,723 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:515) - ConfigureSessionClient: username: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286', credentials: '646376683' 2019-06-05 16:13:14,723 TRACE [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:13:14,723 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:14,737 INFO [qtp804611486-17] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:13:14,737 TRACE [qtp804611486-17] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:205) - Authentication successfully for '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:13:14,743 DEBUG [qtp804611486-17] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:14,750 DEBUG [qtp804611486-17] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:107) - Attempting to request access token: grantType = refresh_token, code = null, redirectUri = null, username = null, refreshToken = da96a135-c27f-4c0c-a10b-75cdfe3a2908, clientId = null, ExtraParams = {refresh_token=[da96a135-c27f-4c0c-a10b-75cdfe3a2908], grant_type=[refresh_token], scope=[openid profile user_name email permission]}, isSecure = true, codeVerifier = null, ticket = null 2019-06-05 16:13:14,751 DEBUG [qtp804611486-17] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:129) - Starting to validate request parameters 2019-06-05 16:13:14,751 TRACE [qtp804611486-17] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:135) - Request parameters are right 2019-06-05 16:13:14,751 DEBUG [qtp804611486-17] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:137) - Grant type: 'refresh_token' 2019-06-05 16:13:14,751 DEBUG [qtp804611486-17] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:143) - Get sessionClient: 'org.xdi.oxauth.model.session.SessionClient@7b493918' 2019-06-05 16:13:14,751 DEBUG [qtp804611486-17] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:147) - Get client from session: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:13:14,752 TRACE [qtp804611486-17] [xdi.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2019-06-05 16:13:14,758 DEBUG [qtp804611486-17] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:70) - Looking for the error with id: invalid_grant 2019-06-05 16:13:14,758 DEBUG [qtp804611486-17] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:75) - Found error, id: invalid_grant 2019-06-05 16:13:23,240 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:23,240 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:23,242 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.ConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:23,242 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:23,242 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:23,246 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:23,259 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:23,259 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LdapStatusEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:23,260 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:23,262 DEBUG [Thread-36] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:319) - Created ldapAuthEntryManager#0: org.gluu.site.ldap.persistence.LdapEntryManager@3cde21bd 2019-06-05 16:13:23,335 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:23,336 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:23,338 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:23,338 TRACE [Thread-37] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:282) - Attempting to use ldapEntryManager: org.gluu.site.ldap.OperationsFacade@2a213c36 2019-06-05 16:13:31,103 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:31,104 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:31,145 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:38,249 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:38,250 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:38,252 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:44,676 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/token' 2019-06-05 16:13:44,676 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:98) - Starting token endpoint authentication 2019-06-05 16:13:44,676 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:111) - Starting Basic Auth token endpoint authentication 2019-06-05 16:13:44,677 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:13:44,677 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:44,678 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:181) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286) 2019-06-05 16:13:44,678 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:101) - Authenticating Client with LDAP: clientId = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:44,679 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:13:44,679 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:44,679 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:515) - ConfigureSessionClient: username: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286', credentials: '646376683' 2019-06-05 16:13:44,680 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:13:44,680 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:44,692 INFO [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:13:44,693 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:205) - Authentication successfully for '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:13:44,703 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:13:44,715 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:107) - Attempting to request access token: grantType = refresh_token, code = null, redirectUri = null, username = null, refreshToken = da96a135-c27f-4c0c-a10b-75cdfe3a2908, clientId = null, ExtraParams = {refresh_token=[da96a135-c27f-4c0c-a10b-75cdfe3a2908], grant_type=[refresh_token], scope=[openid profile user_name email permission]}, isSecure = true, codeVerifier = null, ticket = null 2019-06-05 16:13:44,715 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:129) - Starting to validate request parameters 2019-06-05 16:13:44,715 TRACE [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:135) - Request parameters are right 2019-06-05 16:13:44,716 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:137) - Grant type: 'refresh_token' 2019-06-05 16:13:44,716 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:143) - Get sessionClient: 'org.xdi.oxauth.model.session.SessionClient@e3d58ef' 2019-06-05 16:13:44,716 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:147) - Get client from session: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:13:44,716 TRACE [qtp804611486-12] [xdi.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2019-06-05 16:13:44,718 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:70) - Looking for the error with id: invalid_grant 2019-06-05 16:13:44,718 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:75) - Found error, id: invalid_grant 2019-06-05 16:13:53,240 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:53,241 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:53,241 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:53,243 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.ConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:53,244 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:53,245 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:53,330 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:13:53,331 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:13:53,332 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:13:53,332 TRACE [Thread-42] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:282) - Attempting to use ldapEntryManager: org.gluu.site.ldap.OperationsFacade@2a213c36 2019-06-05 16:14:01,105 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:01,106 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:01,139 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:08,241 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:08,243 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:08,244 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:14,665 TRACE [qtp804611486-10] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/token' 2019-06-05 16:14:14,666 DEBUG [qtp804611486-10] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:98) - Starting token endpoint authentication 2019-06-05 16:14:14,666 DEBUG [qtp804611486-10] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:111) - Starting Basic Auth token endpoint authentication 2019-06-05 16:14:14,666 TRACE [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:14:14,667 DEBUG [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:14,667 TRACE [qtp804611486-10] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:181) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286) 2019-06-05 16:14:14,667 DEBUG [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:101) - Authenticating Client with LDAP: clientId = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:14,667 TRACE [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:14:14,668 DEBUG [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:14,668 DEBUG [qtp804611486-10] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:515) - ConfigureSessionClient: username: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286', credentials: '646376683' 2019-06-05 16:14:14,668 TRACE [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:14:14,668 DEBUG [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:14,695 INFO [qtp804611486-10] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:14:14,696 TRACE [qtp804611486-10] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:205) - Authentication successfully for '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:14:14,701 DEBUG [qtp804611486-10] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:14,705 DEBUG [qtp804611486-10] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:107) - Attempting to request access token: grantType = refresh_token, code = null, redirectUri = null, username = null, refreshToken = da96a135-c27f-4c0c-a10b-75cdfe3a2908, clientId = null, ExtraParams = {refresh_token=[da96a135-c27f-4c0c-a10b-75cdfe3a2908], grant_type=[refresh_token], scope=[openid profile user_name email permission]}, isSecure = true, codeVerifier = null, ticket = null 2019-06-05 16:14:14,705 DEBUG [qtp804611486-10] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:129) - Starting to validate request parameters 2019-06-05 16:14:14,705 TRACE [qtp804611486-10] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:135) - Request parameters are right 2019-06-05 16:14:14,706 DEBUG [qtp804611486-10] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:137) - Grant type: 'refresh_token' 2019-06-05 16:14:14,706 DEBUG [qtp804611486-10] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:143) - Get sessionClient: 'org.xdi.oxauth.model.session.SessionClient@4e5f74ab' 2019-06-05 16:14:14,706 DEBUG [qtp804611486-10] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:147) - Get client from session: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:14:14,706 TRACE [qtp804611486-10] [xdi.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2019-06-05 16:14:14,708 DEBUG [qtp804611486-10] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:70) - Looking for the error with id: invalid_grant 2019-06-05 16:14:14,708 DEBUG [qtp804611486-10] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:75) - Found error, id: invalid_grant 2019-06-05 16:14:23,240 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:23,241 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:23,242 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:23,242 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.ConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:23,243 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:23,244 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:23,259 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:23,260 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LdapStatusEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:23,261 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:23,330 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:23,331 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:23,333 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:23,333 TRACE [Thread-48] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:282) - Attempting to use ldapEntryManager: org.gluu.site.ldap.OperationsFacade@2a213c36 2019-06-05 16:14:31,110 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:31,111 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:31,136 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:38,242 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:38,243 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:38,244 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:44,691 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/token' 2019-06-05 16:14:44,691 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:98) - Starting token endpoint authentication 2019-06-05 16:14:44,691 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:111) - Starting Basic Auth token endpoint authentication 2019-06-05 16:14:44,692 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:14:44,692 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:44,692 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:181) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286) 2019-06-05 16:14:44,693 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:101) - Authenticating Client with LDAP: clientId = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:44,693 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:14:44,693 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:44,693 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:515) - ConfigureSessionClient: username: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286', credentials: '646376683' 2019-06-05 16:14:44,693 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:14:44,693 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:44,705 INFO [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:14:44,705 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:205) - Authentication successfully for '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:14:44,711 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:14:44,716 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:107) - Attempting to request access token: grantType = refresh_token, code = null, redirectUri = null, username = null, refreshToken = da96a135-c27f-4c0c-a10b-75cdfe3a2908, clientId = null, ExtraParams = {refresh_token=[da96a135-c27f-4c0c-a10b-75cdfe3a2908], grant_type=[refresh_token], scope=[openid profile user_name email permission]}, isSecure = true, codeVerifier = null, ticket = null 2019-06-05 16:14:44,716 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:129) - Starting to validate request parameters 2019-06-05 16:14:44,716 TRACE [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:135) - Request parameters are right 2019-06-05 16:14:44,717 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:137) - Grant type: 'refresh_token' 2019-06-05 16:14:44,717 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:143) - Get sessionClient: 'org.xdi.oxauth.model.session.SessionClient@5bcc56ff' 2019-06-05 16:14:44,717 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:147) - Get client from session: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:14:44,717 TRACE [qtp804611486-12] [xdi.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2019-06-05 16:14:44,719 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:70) - Looking for the error with id: invalid_grant 2019-06-05 16:14:44,719 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:75) - Found error, id: invalid_grant 2019-06-05 16:14:53,237 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:53,238 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.ConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:53,240 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:53,242 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:53,243 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:53,243 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:53,325 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:14:53,326 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:14:53,327 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:14:53,327 TRACE [Thread-53] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:282) - Attempting to use ldapEntryManager: org.gluu.site.ldap.OperationsFacade@2a213c36 2019-06-05 16:15:01,106 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:01,107 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:01,168 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:08,241 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:08,241 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:08,244 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:14,736 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/token' 2019-06-05 16:15:14,736 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:98) - Starting token endpoint authentication 2019-06-05 16:15:14,736 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:111) - Starting Basic Auth token endpoint authentication 2019-06-05 16:15:14,737 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:15:14,737 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:14,737 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:181) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286) 2019-06-05 16:15:14,738 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:101) - Authenticating Client with LDAP: clientId = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:14,738 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:15:14,738 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:14,738 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:515) - ConfigureSessionClient: username: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286', credentials: '646376683' 2019-06-05 16:15:14,738 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:15:14,738 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:14,748 INFO [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:15:14,748 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:205) - Authentication successfully for '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:15:14,761 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:14,764 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:107) - Attempting to request access token: grantType = refresh_token, code = null, redirectUri = null, username = null, refreshToken = da96a135-c27f-4c0c-a10b-75cdfe3a2908, clientId = null, ExtraParams = {refresh_token=[da96a135-c27f-4c0c-a10b-75cdfe3a2908], grant_type=[refresh_token], scope=[openid profile user_name email permission]}, isSecure = true, codeVerifier = null, ticket = null 2019-06-05 16:15:14,764 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:129) - Starting to validate request parameters 2019-06-05 16:15:14,764 TRACE [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:135) - Request parameters are right 2019-06-05 16:15:14,764 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:137) - Grant type: 'refresh_token' 2019-06-05 16:15:14,764 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:143) - Get sessionClient: 'org.xdi.oxauth.model.session.SessionClient@94fc18' 2019-06-05 16:15:14,764 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:147) - Get client from session: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:15:14,765 TRACE [qtp804611486-12] [xdi.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2019-06-05 16:15:14,766 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:70) - Looking for the error with id: invalid_grant 2019-06-05 16:15:14,766 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:75) - Found error, id: invalid_grant 2019-06-05 16:15:23,241 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:23,243 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.ConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:23,243 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:23,245 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:23,245 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:23,246 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:23,255 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:23,256 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LdapStatusEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:23,257 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:23,325 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:23,326 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:23,327 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:23,329 TRACE [Thread-61] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:282) - Attempting to use ldapEntryManager: org.gluu.site.ldap.OperationsFacade@2a213c36 2019-06-05 16:15:31,103 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:31,104 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:31,138 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:38,241 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:38,242 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:38,243 DEBUG [oxAuthScheduler_Worker-3] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:44,648 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:91) - Get request to: 'https://gluu.jeffmandel.org/oxauth/restv1/token' 2019-06-05 16:15:44,648 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:98) - Starting token endpoint authentication 2019-06-05 16:15:44,649 DEBUG [qtp804611486-12] [org.xdi.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:111) - Starting Basic Auth token endpoint authentication 2019-06-05 16:15:44,649 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:15:44,650 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:44,650 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:181) - Authenticating ... (interactive: false, skipPassword: false, credentials.username: @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286) 2019-06-05 16:15:44,650 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:101) - Authenticating Client with LDAP: clientId = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:44,650 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:15:44,651 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:44,651 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.AuthenticationService] (AuthenticationService.java:515) - ConfigureSessionClient: username: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286', credentials: '646376683' 2019-06-05 16:15:44,651 TRACE [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:199) - Get client from cache by Dn 'inum=@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286,ou=clients,o=@!0F72.46D1.7AF3.7752!0001!2C6D.E329,o=gluu' 2019-06-05 16:15:44,651 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:44,661 INFO [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:15:44,661 TRACE [qtp804611486-12] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:205) - Authentication successfully for '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:15:44,668 DEBUG [qtp804611486-12] [org.xdi.oxauth.service.ClientService] (ClientService.java:141) - Found 1 entries for client id = @!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286 2019-06-05 16:15:44,670 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:107) - Attempting to request access token: grantType = refresh_token, code = null, redirectUri = null, username = null, refreshToken = da96a135-c27f-4c0c-a10b-75cdfe3a2908, clientId = null, ExtraParams = {refresh_token=[da96a135-c27f-4c0c-a10b-75cdfe3a2908], grant_type=[refresh_token], scope=[openid profile user_name email permission]}, isSecure = true, codeVerifier = null, ticket = null 2019-06-05 16:15:44,671 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:129) - Starting to validate request parameters 2019-06-05 16:15:44,671 TRACE [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:135) - Request parameters are right 2019-06-05 16:15:44,671 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:137) - Grant type: 'refresh_token' 2019-06-05 16:15:44,672 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:143) - Get sessionClient: 'org.xdi.oxauth.model.session.SessionClient@34b56834' 2019-06-05 16:15:44,672 DEBUG [qtp804611486-12] [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] (TokenRestWebServiceImpl.java:147) - Get client from session: '@!0F72.46D1.7AF3.7752!0001!2C6D.E329!0008!FA3F.7BEB.3B3E.3286' 2019-06-05 16:15:44,672 TRACE [qtp804611486-12] [xdi.oxauth.model.crypto.binding.TokenBindingMessage] (TokenBindingMessage.java:57) - TokenBindingMessage present: false, rpCnfKey: null 2019-06-05 16:15:44,674 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:70) - Looking for the error with id: invalid_grant 2019-06-05 16:15:44,674 DEBUG [qtp804611486-12] [org.xdi.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:75) - Found error, id: invalid_grant 2019-06-05 16:15:53,247 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:53,248 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:53,248 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.ConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:53,249 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:53,249 DEBUG [oxAuthScheduler_Worker-4] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:53,251 DEBUG [oxAuthScheduler_Worker-5] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:53,325 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:15:53,326 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:15:53,327 DEBUG [oxAuthScheduler_Worker-1] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended 2019-06-05 16:15:53,327 TRACE [Thread-66] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:282) - Attempting to use ldapEntryManager: org.gluu.site.ldap.OperationsFacade@2a213c36 2019-06-05 16:16:01,104 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:52) - Bound request started 2019-06-05 16:16:01,105 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.TimerJob] (TimerJob.java:34) - Fire timer event [org.xdi.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.xdi.service.cdi.event.Scheduled()] 2019-06-05 16:16:01,133 DEBUG [oxAuthScheduler_Worker-2] [org.xdi.service.timer.RequestJobListener] (RequestJobListener.java:62) - Bound request ended ```

By Jose Gonzalez staff 05 Jun 2019 at 1:53 p.m. CDT

Copy

There are several problems there. I don't imagine what the cause can be (specially being xenial the distro we tested the most). To start, the 2FA blocking occurs due to > No module named casa-external_u2f > No module named casa-external_otp > No module named casa-external_super_gluu Upon installation, four `py` files are copied to `/opt/gluu/python/libs`. The above means they have somehow disappeared or are not readable (by `jetty` user) anymore, can you do `ls -l` in that directory and show the output?

By Jeff E Mandel user 05 Jun 2019 at 2:02 p.m. CDT

Copy

You are right: ``` ls -l /opt/gluu/python/libs total 8 -rw-r--r-- 1 root gluu 3018 Apr 21 16:37 duo_web.py -rw-r--r-- 1 root gluu 61 Apr 21 16:35 python.txt ``` So how do I restore these, and what made them go away? The second is more a rhetorical question.

By Jose Gonzalez staff 06 Jun 2019 at 8:35 a.m. CDT

Copy

``` cd /opt/gluu/python/libs wget https://github.com/GluuFederation/casa/raw/version_3.1.6/extras/scripts/casa-external_twilio_sms.py wget https://github.com/GluuFederation/casa/raw/version_3.1.6/extras/scripts/casa-external_super_gluu.py wget https://github.com/GluuFederation/casa/raw/version_3.1.6/extras/scripts/casa-external_twilio_sms.py wget https://github.com/GluuFederation/casa/raw/version_3.1.6/extras/scripts/casa-external_u2f.py ``` > what made them go away? Casa code never does removals in that directory. Actually ownership of those is root:root and flags `rwxr-xr-x` ...

By Jeff E Mandel user 06 Jun 2019 at 9:10 a.m. CDT

Copy

OK, that fixed it. BTW, you have casa-external_twilio_sms.py in there twice, shouldn't one of these be casa-external_otp.py? I still don't understand what caused them to disappear in the first place. I'm pretty sure this was what happened the last time Casa failed. Perhaps it would be useful to have auditd watch those files: ```` -a always,exit -F dir=/opt/gluu-server-3.1.6/opt/gluu/python/libs -S unlink -S unlinkat -S rename -S renameat -S rmdir -k delete_pythonlibs ```` This presumes running auditd on the server, not the chroot.

By Jose Gonzalez staff 06 Jun 2019 at 1:38 p.m. CDT

Copy

> BTW, you have casa-external_twilio_sms.py in there twice, shouldn't one of these be casa-external_otp.py? right! big typo..

By Jeff E Mandel user 06 Jun 2019 at 1:41 p.m. CDT

Copy

OK, and I have my traps set for any mice that try to nibble on my python/libs. Yes, they are gluu traps ;-)

By William Lowe user 07 Jun 2019 at 9:51 a.m. CDT

Copy

> Yes, they are gluu traps ;-) haha good idea! Why waste good cheese..?!

You need to Login in order to post an answer

Login via casa fails with any 2FA enabled

By: Jeff E Mandel user 05 Jun 2019 at 9:01 a.m. CDT

Answers

By Jose Gonzalez staff 05 Jun 2019 at 10:31 a.m. CDT

By Jeff E Mandel user 05 Jun 2019 at 11:19 a.m. CDT

By Jose Gonzalez staff 05 Jun 2019 at 1:53 p.m. CDT

By Jeff E Mandel user 05 Jun 2019 at 2:02 p.m. CDT

By Jose Gonzalez staff 06 Jun 2019 at 8:35 a.m. CDT

By Jeff E Mandel user 06 Jun 2019 at 9:10 a.m. CDT

By Jose Gonzalez staff 06 Jun 2019 at 1:38 p.m. CDT

By Jeff E Mandel user 06 Jun 2019 at 1:41 p.m. CDT

By William Lowe user 07 Jun 2019 at 9:51 a.m. CDT

Post an answer