400/Bad Request while trying to get an Access Token

Hi @adunsulag

I was able to work with my DevOps colleague to get PHP error logs. We used another thread: Docker PHP Error Logs - #5 by brady.miller as a guideline (thank you for posting it).

Here’s what we see when we try to complete the authorization grant noted above:

[Fri Mar 18 17:27:59.276514 2022] [php7:notice] [pid 92] [client 10.0.0.2:25588] [2022-03-18T17:27:59.275807+00:00] OpenEMR.DEBUG: oauth2 request received {“endpoint”:"/default/provider/login"} [], referer: http://localhost:8181/
[Fri Mar 18 17:27:59.279501 2022] [php7:notice] [pid 92] [client 10.0.0.2:25588] [2022-03-18T17:27:59.279470+00:00] OpenEMR.DEBUG: AuthorizationController->userLogin() presenting blank login form [] [], referer: http://localhost:8181/
[Fri Mar 18 17:28:12.987002 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:12.986172+00:00] OpenEMR.DEBUG: oauth2 request received {“endpoint”:"/default/login"} [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:12.990470 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:12.990438+00:00] OpenEMR.DEBUG: AuthorizationController->userLogin() verifying login information [] [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:13.064999 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:13.064958+00:00] OpenEMR.DEBUG: AuthorizationController->verifyLogin() user login {“pid”:“95d27c2e-5647-4043-89c2-9ead520b49e6”} [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:13.065051 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:13.065031+00:00] OpenEMR.DEBUG: AuthorizationController->userLogin() verifyLogin result {“continueLogin”:“1”} [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:13.065076 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:13.065061+00:00] OpenEMR.DEBUG: AuthorizationController->userLogin() login valid, continuing oauth process [] [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:13.066171 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:13.066138+00:00] OpenEMR.DEBUG: fhirUser claim is {“role”:“users”,“fhirUser”:“https://emr-test.mphise.us/apis/default/fhir/Practitioner/95d27c2e-5647-4043-89c2-9ead520b49e6”} [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:15.260930 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:15.260221+00:00] OpenEMR.DEBUG: oauth2 request received {“endpoint”:"/default/device/code"} [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:15.263938 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:15.263905+00:00] OpenEMR.DEBUG: AuthorizationController->authorizeUser() starting authorization [] [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:15.265378 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:15.265350+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() creating server [] [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:15.267067 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:15.267039+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() grantType is authorization_code [] [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:15.268708 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:15.268681+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() authServer created [] [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:15.447090 2022] [php7:notice] [pid 84] [client 10.0.0.2:25624] [2022-03-18T17:28:15.447047+00:00] OpenEMR.DEBUG: AuthorizationController->authorizeUser() sending server response [] [], referer: OpenEMR Authorization
[Fri Mar 18 17:28:19.505881 2022] [php7:warn] [pid 463] [client 10.0.0.2:25640] PHP Warning: mysqli_real_connect(): MySQL server has gone away in /var/www/localhost/htdocs/openemr/library/ADODB_mysqli_log.php on line 191, referer: https://emr-test.mphise.us/interface/main/tabs/main.php?token_main=yz38cawgL3tXXNvHg5aq0C4eqPNsDUq62kXkgCXs
[Fri Mar 18 17:28:29.407171 2022] [php7:notice] [pid 85] [client 10.0.0.2:41442] [2022-03-18T17:28:29.406374+00:00] OpenEMR.DEBUG: oauth2 request received {“endpoint”:"/default/token"} []
[Fri Mar 18 17:28:29.410475 2022] [php7:notice] [pid 85] [client 10.0.0.2:41442] [2022-03-18T17:28:29.410445+00:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() starting request [] []
[Fri Mar 18 17:28:29.413425 2022] [php7:notice] [pid 85] [client 10.0.0.2:41442] [2022-03-18T17:28:29.413394+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() creating server [] []
[Fri Mar 18 17:28:29.415219 2022] [php7:notice] [pid 85] [client 10.0.0.2:41442] [2022-03-18T17:28:29.415175+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() grantType is authorization_code [] []
[Fri Mar 18 17:28:29.416904 2022] [php7:notice] [pid 85] [client 10.0.0.2:41442] [2022-03-18T17:28:29.416876+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() authServer created [] []
[Fri Mar 18 17:28:29.417233 2022] [php7:notice] [pid 85] [client 10.0.0.2:41442] [2022-03-18T17:28:29.417205+00:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() OAuthServerException occurred {“message”:“Bad request”,“stack”:"#0 /var/www/localhost/htdocs/openemr/oauth2/authorize.php(73): OpenEMR\\RestControllers\\AuthorizationController->oauthAuthorizeToken()\n#1 {main}"} []