400/Bad Request while trying to get an Access Token

OpenEMR Development
#1

Hello,

I’m struggling a bit with an Oauth2 implementation. I’ve been trying to follow the example laid out here:

What works:
I can pop open the Oauth2 dialogue with the required parameters and I can click the Authorize button. A request with an authorization code is then sent to my server per the specified redirect_uri parameter.

Screen Shot 2022-03-14 at 8.44.33 PM
Screen Shot 2022-03-14 at 8.44.33 PM2144×1782 359 KB

Where I’m stuck:
Once my server gets the authorization code, it tries to make the following request to get access and refresh tokens. However, it’s failing with a 400.

Here’s log output which shows request/response headers, parameters and bodies etc.

POST https://emr-test.mphise.us/oauth2/default/token
Content-Type application/x-www-form-urlencoded
Accept application/json
{grant_type=[authorization_code], client_id=[kF478EdEQo-IFv0vze_zPWtZ6Qfb6sW9ZeGq9o4l19g], client_secret=[LITal0M7Y5iwEIinB_75hL776ITeF8o7P41TF0fEZurYs_**** omitted ****], code=[def502000951abacd87f202bc469c3420b22d9a5c2e8683946c989bc8367901200155b18c492284637b42d6eb8453a777b8eb869d3693257193c5afba9358aa6a23573d1a6f0536b8aac43d4fde20b3a37d67eeb245c4b77a3db5c73b5d7c194c3b5407f60f24278f39edd9662f37fdbd3f02f60b6ddc84154e623e399ee41de0aa7aee210f6901e5c1f33211a3c6666e2d77ac192cbf7e062d3f0d6ea2945dd221b4733fb4b83e99cf58db5aba318355861d54c761e10e27605c5cc13dd96ad071053f9a70fa22303b1008207d93153209784545962e5b5b102694386b439d1a6068296588beeeeed6e0a4251b7e0b2753b2de60b6a0dcb3237feedcd70eb64c7c0f639e54d1c94c9d6d815dc2fbd3e5cfe443ddf6853ab3bb97d03772c2704a9031ad471a536cc2ad363ff54c8c5d476ea3021284fd8a9de44396704b74bd8aebe5eff9a45a8cfb0ba3fae151415091b65ce309b817d85018685f47c8a21d8e6291f553218c40e895e924c700654327dc6e2bcbe633794dc3525d2673916bbd86834d7c2966369c3be27d782dd7ca1aa1f9e018df0fa086589b3d417f7173384dd5e361e9419a07f13ebe8bffe0b397354573891da83f0520bb8684d718e78f22209bfe14d23217f9480b6d68d79a71d7ac3a3879485da3fa93aa40f07774c4c82eed26ade29ffabac6ebdf0cfd7d360c114b30cf7db0f0f17be9a92be9cd573ea01d79a2872dc293f26311bdbce0ea23e11cbbe7bd1c069376911a1997f5881ef0d4aaff1f6c028a7b3fa8dd4fce737abb4a086194c9c09b7946489e8249f6f640bcd4cf693c94c3c88a1b279f89feb7616fd61f067993bf93fbbf03bc50a0e443524f58057a9639170534b884104a4e0ca8fa7831ffdae3757032987e7b3013309d194849864184336ebf9b3e102f0ad7afe82f804d9f19d02e333c824d257d549aebaaf5ea0398142b497f8d26769e203afcfd0412b7931abfbd4a1b6511d5ecdabc1ee6a934af6d03eaad5392843e58495cd5c8c879a785d576ee0b48eedc095a29656c29153a7cf7ff0e00b5ab48a30c51f74298b89622b27cbdfe3c1523c469287dcc270e7a62e796595ef5d3d57b9574281c52716fc42101f5911d3870422c581da361be3de03169bc241d638ef824dcd178c2198122e10af90b6585347b15d0e7c04f8d7862506e7e319253824521a0933bc24532364cfbc1f7d3a40c0571c8affd0ffdb49523fe827e4b1d78e750371b6a3f13b2d9a2c47f5362d7e8083f9f80d040d2ad537785c270ccc3ccb8d43e5783525181e73d528fb2bf1930b823937c510b4d116f6cbf543ae2eb2efa04a2433882722c4545c292bb0c2ba640fb82162ff8d73fc5b2dd554f001980de6dce3401e36a2b83a4b3fea87315af9e7789d92f6281807bebf4d639c05581fa443750af2636cc34bfdc7e140ed3c3e04430e3c84f5bee296419a2f446475288be8ce9896c6a40a356110512aa2f409ba3c815e9af0b3f5e7cc80ac60b2d69f222ad29b23b1d9f5c806721109e1c3651dbf70e5be24d8ad1df5bcc6cfa0ca5aa58a9df21323ee566bc3c8fa7799caab6c6db90a4a09ec77a23dbef9a271e1636887bd2ca02a19e2d60ccabd54fae632dd7e3fbdefd1f8f382f4feaa86006ce9d79905fb861d96e16f594572f01412c38b605faa1dd46cb53c19b1ae0e124cc3bab1bec9f20a527b94e4798a1568653df572a2baf0d9fb91bd10fd9f62587aa305cf9c7652b9a6feba59306d7047eb5309f641453b7ee70c4228ca7b1a80af3f7c2ea896b189afbec0463742c12de4aba15f7ba427c6a000b6b35f2c6f116a77f6d9f128cdb76c3e6cc7e0341f1d6b79b07a9a5d7cdbd47998fab1880421aa1e4bc4373cd5fdb6f4f828244bd8cc6298ef70c01541ed210e83b74d5c20ff7a5337c5dae58374dcded33bdf1756ca6c1a7cae60746c2f0f552d7d8030ae8185427679935af8456bc68afac53b667fd6782409e8b2b0975cbec2835bb691fe277f7658257175c4248f9f96a3160466c7c81283543c0c2fc4d66a906c2a175b361832c3997a80]}

400/Bad Request
Date: Tue, 15 Mar 2022 03:43:38 GMT
Content-Type: application/json
Content-Length: 85
Connection: keep-alive
Server: Apache
Set-Cookie: authserverOpenEMR=WwPfhCZRZa8m%2CCyDps2nfV2E6Gu%2CU44de-ce5dcQmVq9RrWq; expires=Tue, 15-Mar-2022 11:30:18 GMT; Max-Age=28000; path=/oauth2/; secure; HttpOnly; SameSite=None,authserverOpenEMR=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/oauth2/; secure; HttpOnly; SameSite=None
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate
Pragma: no-cache
Access-Control-Allow-Credentials: true
Access-Control-Allow-Headers: origin, authorization, accept, content-type, x-requested-with
Access-Control-Allow-Methods: GET, HEAD, POST, PUT, DELETE, TRACE, OPTIONS
Access-Control-Allow-Origin: *
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
X-XSS-Protection: 1; mode=block
{“error”:“invalid_request”,“error_description”:“Bad request”,“message”:“Bad request”}

I’m unfortunately stumped. Is there something wrong with my POST request to /oauth2/default/token?

Thank you,

Chris

#2

Have you turned on the Debug Logging in Admin->Globals->Logging->System Error Logging Options?

Also it doesn’t look like you are passing the redirect_uri in your POST request to https://emr-test.mphise.us/oauth2/default/token

It needs to be the same redirect_uri that you passed in your authorize request as the server will match the encrypted redirect_uri inside the code parameter with what you send in your token request.

I noticed our Authorization Code grant instructions could have a bit more detail so I updated the documentation which can be found here: openemr/API_README.md at master · openemr/openemr · GitHub

1 Like
#3

Hi @adunsulag

Thank you so much for your reply. I’ve updated my POST request to /oauth2/default/token to have the redirect_uri as you noted. I actually had this before, but I removed it as a troubleshooting step since I thought maybe the 400 was coming from unwanted parameters.

I’m currently going over the documentation here:

I see that the example cUrl request /oauth2/default/token is cut off and is perhaps missing some parameters. Do you know by any chance what the full list of parameters is? I assume it needs the client_id and client_secret, does it also need the scopes or the state variable?

After configuring verbose logging and reproducing the 400, I don’t see anything in our logs unfortunately.

Thanks again for your help,

Chris

#4

@cw.efiia You need to use Basic HTTP authorization to send your client_id as the username and client_secret as the password.

What version of OpenEMR are you using? master has a lot more debugging information than 6.0.0.
If you’re not familiar with this header you concatenate your credentials like so base64_encode(client_id . ‘:’ . client_secret); Here is a sample POST request in insomnia which I use for my test client. I removed the hostname, ip address, and cookie information as its a private server.

* Preparing request to https://*************/oauth2/default/token
* Current time is 2021-10-18T20:44:24.386Z
* Using libcurl/7.73.0 OpenSSL/1.1.1g zlib/1.2.11 brotli/1.0.7 zstd/1.4.9 libidn2/2.2.0 libssh2/1.9.0 nghttp2/1.41.0
* Using default HTTP version
* Disable timeout
* Enable automatic URL encoding
* Disable SSL validation
* Enable cookie sending with jar of 29 cookies
* Found bundle for host *************: ************* [can multiplex]
* Re-using existing connection! (#2) with host *************
* Connected to ************* (*************) port 443 (#2)
* Using Stream ID: 9 (easy handle *************)

> POST /oauth2/default/token HTTP/2
> Host: *************
> user-agent: insomnia/2021.2.2
> cookie: authserverOpenEMR=*************
> content-type: application/x-www-form-urlencoded
> authorization: Basic eWk0bW5tVmFkcG5xbkppT2lna2NHc2h1Ry1LYXlpcTZrbUxxQ0pzWXJrNDpvVHdhQ2k4Q2xib0x3XzdpTjd0SVpyd0diRnprbDNPSHFuUlhuclRJQXZxM0g2RDZJNjR3TTd6WlFuWlZlZHVLcnB3NWs4VlVmSGJIc0F3YUpkVW1Hdw==
> accept: */*
> content-length: 2120

| grant_type=authorization_code&redirect_uri=https%3A%2F%2Fclient.example.org%2Fcallback&code=def5020003c455bd5727e9f6caf8563acebe4cc09adb3c5b7e7ff4d147920ed39b28cc881329c5d9ad07042fb738b874a2108a94c5abdd86e4821b54b0b9f22bbd699332ca97b0e4d6b3cef77cd8d9c11a036dae83414f6aa841a4894f2cfafff73dcb7be5076b7417dce148f84f5c362875a8f56f782c3c80ec68e594503b477c5477274c4f63d8ced9af869511a5c35e6c75ef05dec6375ab4548f3a0ca44362c98f465aefac9712b3baaf215f4cc3bf998e489dbeb9e2eed04541e1a8c8b2a81ab621e610eee21da8b118ac2a4e50802033f9961c438a9680555f6b6df566775e05042699b608afa8c9f30227c37398eb6d24fb7904ec0c3fb2e5bf77eee4bed877c364efae1ea333059888eb36d9ca15ce7a53f02800bd95998ff91c292ca9dd3c12394545832a0c2807fee524114eb7a4e1f41b9407073aa8e8825ee18f62d36ec7a123cb708a76842c92a574bffba7f0dd247ff6a645268e661754665df75fe2af99a4a94faa8e51fa16c1a693855d747e017faac32d98bd21e99a3136f635041924719dda2ad61b427b70d93c6ef909537293029c3ee36f3a31cd943e2ab95c892a1383b44d23793a4b9d3d443d50d9f8713f5eb05c4be1bdb025d1b44fb9e2897a5182280693092774a175cce54bc356b081cabae12aff449e7b72a46cff895216344021f6681ed5cf5f0100fd5a04dce7c4efee4e683024befb5d25c17d7106109b24e3168bc64d9fc250a4e483114fe2da4d5755b8d73cdd15ace2c290ceff25c8609723777cdd36918a3d005b66d7b3d7ce3c77292743c3bb08693152f91d9ffdcc731d99179fc0cba8bd6fee53e03576692817db99027bbd5be7dd23b1ad3e65ef73e90e1a01d156e9d264dcbfc7d26d6357d16f4a79fdcb3878680d6c23937502359d24187caa32eb466a5e26cbe8833da410916e6518f85a5a3f064a7c0cbe66ba7a09bab62164d5ae6e88d172cc353156a0773339e1514d20c47d0a698c19b309e2595103ad2abfa84b7adc2d7e022bee91c19bacc34d15332a279c8166c5a4049b7183114ed0bb90acd5371020a86fe54afe12f8a82f6b3df86028121a08a32b001d33a379fc186998043ab4572daecfa657672506a4978000565da7dd6ec49b864c6d3025d739e0289a5e7fd861c79d5c5533b49a6397c4142d25b61bbbad38a0207fb4ea983f5752aad81edcb4aaee63647c155a3b77528955b872236b2c4c9be785114f86af675842d8b066c236806d92dab2daaf69d0a124fa20ce1a163ed8f1984b4646a55ad2e3baf77dfe6202bef8bc8e49b5e9733b4e31b76e95f2bf8757b95106158042f647683e54c9f48d1a37d571950f5227e8103baf6c059b23afe55fc4f8ca22de83d326c32c87a85d59ec032fd7a38456e4bbde711188e002da0476d3c43ce726fdf456b7351b

You don’t need scopes as they are encrypted in the code parameter. State doesn’t apply here either.

#5

Hi @adunsulag,

I’ve moved the clientId and clientSecret to a Base64 ecoded Authorization header as you noted.

2022-03-17 17:54:12 DEBUG BaseOpenEmrClient:72 - Processing:https://emr-test.mphise.us/oauth2/default/token

2022-03-17 17:54:12 INFO BaseOpenEmrClient:165 - ** Executing HTTP Request **
POST https://***************/oauth2/default/token
Content-Type application/x-www-form-urlencoded
Accept application/json
Authorization Basic omitted
{grant_type=[authorization_code], redirect_uri=[http://localhost:8181/emr-oauth2-callback], code=[def502003f6441989f56916c7006c5256dcebc05ed5a0a2c905622872a9b06fed8ce1aab02d7b58c566226afba6e057dbdaf265203cf7f38aa2847e700fb7828523f90084acd55221eeff5f0d43098cf3a243376c9db7c5f412d1dd6d3f22a38a70a7dc7eacf21ee470e1cd1a544cb0aff1b132381d76872b4af796b9fec9071a923fa0c27b4da57ec92b5a52f43373fcafff74a0406d4545ee14243983bd54e833f124567bea318d0a9e92525fbee447851f0688405deb483d876a7d74621cf5a2753544dcb3d8645f093e0277954df6bb75f35506eaf8338a1936a3e311e45fabbf7f1783d995ea90a82ed235eb705f793da96f250a79b34223d4b94b132992c54bc9b6aa2a69aadc650e2f2f4c46c4060c12316418e2f86b6be9eb7d40b4df363434e4fa5ca462ef6e9a3478c72351abc352442f56eeb72731e8da67c2a7ede7ad93895e4deb006378177cde5b6804f15d07fd3297e05c60a4300f822e9e17353bd81a0da5d91541da8d5a179e989fbc050b5ddf84873fdd1a192f765570e6bfe5d54f1c012b8f111471f92ee72056303c07939721473a821f2cd9c1e94000037e6a183288adef5566cabbfaabf1d422fabbf1a2576c3b8b37e110689618784a97ad67866fada82a58f0910de1f42cc652a0deab5f15ecb0f8742865224e167a6aab33da12b23466ce76b9298fa09ba7f2fb4df72018cd4e0a96b8f41f7aff685c076b75a4c239004df2f32294be0a9e0e8ab51a4c7b924d31b8ed5ae0e1969137b422ef654abdf7f5b1ffb8bbcdf4382f560f1a5db3870c70d2eff9d7d99e382da86e0506d93c9ae45e1485e13cac752ae6e40f32a4b3ae0157bbee7f667d19f81c1d43d2deb8301e56615351c507e1c8aada8f687cfb1c73794971af1051893b11499da6c7ca2a7a8915ebf4a80eb4c0c92e65d948e903b6bd7a761a29e78559cf101d582488354f6184deff6a517bf858f00d48302360a1375549e3f85837c14cb12e9ab910efb81a696f11c4d569ead7fff333455e813fc410a65e8378426209ef07d82cae7c8e49d33d70af7a187ffbb28fceb691f1920f3500a94370706cc1e0496f6ddd422a9cb19a3cbbd6f5474b8d278a89978f9da055c2647263cc66e83019a88469f81b37928d56837614b04db84c0ed3f981066240debada828d7136c977a41325f075b01aaa63d0b3f547ca5861cb76dfa5591737e2afaa56956a789b9b1b37f0d0aac9f45bb4e06abdd28c08da635406c336a258727d88d071b728ca9bee43f413b6dcc65c311078b59e770f4f8e57b5e38f4414e24d3c5ec6049a14c0341ba238e3f3e5a8e0c74703ba96b79f6aab9f8cc5699de886ebbdf632c8fe029b30a5e48d37b1af1270533550c53ffc7604b54aad7310de0152c185c7bbe56c362e565949cf3fb077098ab0dde8779cf2a036ab4e9fb6b13d141723f5b928a26965d1c638fbb3eb8b0c675274309f22c434d722733721d768e586adb36712264ad463a10886feb92955da8c8f770b4dcf305985843af016f4eb5d5b9a627ba00e48c828c50614b773af87728c58c9f62e4e684d01abca22a6eab2d1a2f276e5789f6f1e9defea3d6f66275af4c816635071b9fdafea02263eda11c529cfa7942c55bc9fca8b2c13449bdf94362904d163d8505d45d1d901e4655b9866bdf73e67f47f2c534b43aed3c38eb968eb0b30b3d1548bde1d26b731ef570f4c4ce9d2cf30ccb648799e444a49d2619f9e7300f7708ba1f8259ff83dbd0706b0c507de5b1a9233b33d22e49cb3161434979a5ecf373c949b2d7a621908cfc87cfa81f45adb0eadc3ebec31c87d1fd30ae36d51057c7fa0eae28042a8c69a4356f7e08cadb6082a078630b9e9aa8c9124ca9ef6b0433c6648597a964fb4f18b6817d62d0c28b354e0f24fd9a46b40c6384fe7eefc5650f2845d6a0f95a43fb96656b596766b6e9634068c6af7a4837ba4bc36e1fb76c50e9fdc5c3f9995a607b95f9810adf5ce6b63a0fd7a3d61bfefa761f6c4aa2de096205dfcdfb7ba01c295cc784e67911e7b0c2f23a534e557aaa64acc6f8e3]}

2022-03-17 17:54:13 INFO BaseOpenEmrClient:145 - ** HTTP Response **

400/Bad Request
Date: Fri, 18 Mar 2022 00:54:13 GMT
Content-Type: application/json
Content-Length: 85
Connection: keep-alive
Server: Apache
Set-Cookie: authserverOpenEMR=6O-NB6pY0QHrXfCRCGO2vknFwKQ7q0uEq20bmMiyC3Y0cfQO; expires=Fri, 18-Mar-2022 08:40:53 GMT; Max-Age=28000; path=/oauth2/; secure; HttpOnly; SameSite=None,authserverOpenEMR=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/oauth2/; secure; HttpOnly; SameSite=None
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate
Pragma: no-cache
Access-Control-Allow-Credentials: true
Access-Control-Allow-Headers: origin, authorization, accept, content-type, x-requested-with
Access-Control-Allow-Methods: GET, HEAD, POST, PUT, DELETE, TRACE, OPTIONS
Access-Control-Allow-Origin: *
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
X-XSS-Protection: 1; mode=block
{“error”:“invalid_request”,“error_description”:“Bad request”,“message”:“Bad request”}

Is there anything obvious that I’ve missed? Is there working version of a Java client that I can reference?

Thank you,

Chris

#6

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}"} []

#7

What version of OpenEMR are you on? Are you running against master or the latest 6.0.0 patch 4 version?

You can see here is where that Bad Request is being generated in master as your code is used to pull the user session information (scopes authorized, user id, etc) and then we attempt to do a security check for the CSRF property. If we can’t get the CSRF property we fail the request.

You can see from the debug log in master that it is failing because it can’t grab your oauth2 session details from the code you provided. I would double check that the code you are sending is the same one stored in the oauth_trusted_user table in the code column. Since you are using a java client I would double check that there isn’t some kind of url encoding mismatch with the code stored in the database and what you are sending.

#8

I’ll take a look at my CSRF token, this should be present but maybe I’ve missed something. To be clear though, the CSRF token needs to be included in the request to /oauth2/default/authorize, once the code is sent back to my redirect_uri endpoint, the request to /oauth2/default/token happens server to server and would not have a CSRF token … correct?

For reference, we’re using v6.0.0

Screen Shot 2022-03-18 at 11.47.56 AM
Screen Shot 2022-03-18 at 11.47.56 AM976×1326 63 KB

#9

The CSRF is on the server inside the session and is created during your login and scope authorization flow in the browser. Your browser application should take care of everything when you re in the /oauth2/default/authorize endpoint. You’re correct in that the token endpoint does not receive a CSRF token fro your application as everything happens on the server using the code as an identifier.

There’s a number of changes in master since 6.0.0 but here is the the relevant code sections for 6.0.0 patch 4.

You can see on line 886 we grab the session using the code you send to the server (which is what the server sends to your application during the OAUTH2 flow redirect. The session is then deserialized from the session cache. We check the session for the CSRF variable in line 895. If for your code was invalid you’ll hit that line in 897 which is what is happening to you.

#10

My DevOps team is asking which docker image you recommend:
https://hub.docker.com/r/openemr/openemr/tags

To quote him,

they don’t have a tag for 6.0.0 patch 4. They have one for 6.1.0 that was updated 2 days ago, and one labeled. 7.0.0 that was pushed yesterday

Do you know which tag we should use?

Chris

#11

Are you attempting production use? If you are doing proof of concept right I’d use the flex dockers that will run off the master release branches as you are testing your apps. You or your devops guy can use the docker readme here: openemr/DOCKER_README.md at master · openemr/openemr · GitHub

Neither 6.1.0 nor 7.0.0 are considered production ready. I believe 6.1.0 will be released in the next week or two and will be more stable than the 7.0.0 release which is slated to come out once we are ONC certified sometime in April.

#12

My DevOps team upgraded our instance to 7.0.0-dev, here’s the About page:

Screen Shot 2022-03-18 at 3.54.46 PM
Screen Shot 2022-03-18 at 3.54.46 PM2282×1074 224 KB

The OAuth2 handshake is still giving me a 400/Bad request when I try to get a token. The error logs are different though. Is this still because of a missing CSRF token? I’m still trying to figure out how that’s even possible given the Authorization page is hosted on OpenEMR. In any case, this is what we see in the logs now:

[Fri Mar 18 22:48:10.932020 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:10.931275-04:00] OpenEMR.DEBUG: oauth2 request received {“endpoint”:"/default/scope-authorize-confirm"} [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.885888 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.885147-04:00] OpenEMR.DEBUG: oauth2 request received {“endpoint”:"/default/device/code"} [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.889712 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.889678-04:00] OpenEMR.DEBUG: AuthorizationController->authorizeUser() starting authorization [] [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.890316 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.890263-04:00] OpenEMR.DEBUG: AuthorizationController->updateAuthRequestWithUserApprovedScopes() attempting to update auth request with user approved scopes {“userApprovedScopes”:{“openid”:“openid”,“api:oemr”:“api:oemr”,“api:fhir”:“api:fhir”,“api:port”:“api:port”,“user/allergy.read”:“user/allergy.read”,“user/allergy.write”:“user/allergy.write”,“user/appointment.read”:“user/appointment.read”,“user/appointment.write”:“user/appointment.write”,“user/dental_issue.read”:“user/dental_issue.read”,“user/dental_issue.write”:“user/dental_issue.write”,“user/document.read”:“user/document.read”,“user/document.write”:“user/document.write”,“user/drug.read”:“user/drug.read”,“user/encounter.read”:“user/encounter.read”,“user/encounter.write”:“user/encounter.write”,“user/facility.read”:“user/facility.read”,“user/facility.write”:“user/facility.write”,“user/immunization.read”:“user/immunization.read”,“user/insurance.read”:“user/insurance.read”,“user/insurance.write”:“user/insurance.write”,“user/insurance_company.read”:“user/insurance_company.read”,“user/insurance_company.write”:“user/insurance_company.write”,“user/insurance_type.read”:“user/insurance_type.read”,“user/list.read”:“user/list.read”,“user/medical_problem.read”:“user/medical_problem.read”,“user/medical_problem.write”:“user/medical_problem.write”,“user/medication.read”:“user/medication.read”,“user/medication.write”:“user/medication.write”,“user/message.write”:“user/message.write”,“user/patient.read”:“user/patient.read”,“user/patient.write”:“user/patient.write”,“user/practitioner.read”:“user/practitioner.read”,“user/practitioner.write”:“user/practitioner.write”,“user/prescription.read”:“user/prescription.read”,“user/procedure.read”:“user/procedure.read”,“user/soap_note.read”:“user/soap_note.read”,“user/soap_note.write”:“user/soap_note.write”,“user/surgery.read”:“user/surgery.read”,“user/surgery.write”:“user/surgery.write”,“user/vital.read”:“user/vital.read”,“user/vital.write”:“user/vital.write”,“user/AllergyIntolerance.read”:“user/AllergyIntolerance.read”,“user/CareTeam.read”:“user/CareTeam.read”,“user/Condition.read”:“user/Condition.read”,“offline_access”:“offline_access”}} [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.890469 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.890428-04:00] OpenEMR.DEBUG: AuthorizationController->updateAuthRequestWithUserApprovedScopes() replaced request scopes with user approved scopes {“updatedScopes”:["“openid”","“offline_access”","“api:oemr”","“api:fhir”","“api:port”","“user\\/allergy.read”","“user\\/allergy.write”","“user\\/appointment.read”","“user\\/appointment.write”","“user\\/dental_issue.read”","“user\\/dental_issue.write”","“user\\/document.read”","“user\\/document.write”","“user\\/drug.read”","“user\\/encounter.read”","“user\\/encounter.write”","“user\\/facility.read”","“user\\/facility.write”","“user\\/immunization.read”","“user\\/insurance.read”","“user\\/insurance.write”","“user\\/insurance_company.read”","“user\\/insurance_company.write”","“user\\/insurance_type.read”","“user\\/list.read”","“user\\/medical_problem.read”","“user\\/medical_problem.write”","“user\\/medication.read”","“user\\/medication.write”","“user\\/message.write”","“user\\/patient.read”","“user\\/patient.write”","“user\\/practitioner.read”","“user\\/practitioner.write”","“user\\/prescription.read”","“user\\/procedure.read”","“user\\/soap_note.read”","“user\\/soap_note.write”","“user\\/surgery.read”","“user\\/surgery.write”","“user\\/vital.read”","“user\\/vital.write”","“user\\/AllergyIntolerance.read”","“user\\/CareTeam.read”","“user\\/Condition.read”"]} [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.891345 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.891319-04:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() creating server [] [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.894576 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.894548-04:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() grantType is authorization_code [] [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.894616 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.894596-04:00] OpenEMR.DEBUG: logging global params {“site_addr_oath”:“https://emr-test.mphise.us”,“web_root”:"",“site_id”:“default”} [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:13.896463 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:13.896437-04:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() authServer created [] [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:14.072059 2022] [php:notice] [pid 656] [client 10.99.9.237:6846] [2022-03-18T18:48:14.072018-04:00] OpenEMR.DEBUG: AuthorizationController->authorizeUser() sending server response [] [], referer: OpenEMR Authorization
[Fri Mar 18 22:48:27.574905 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.574040-04:00] OpenEMR.DEBUG: oauth2 request received {“endpoint”:"/default/token"} []
[Fri Mar 18 22:48:27.579177 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.579144-04:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() starting request [] []
[Fri Mar 18 22:48:27.580952 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.580923-04:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() grant type received {“grant_type”:“authorization_code”} []
[Fri Mar 18 22:48:27.581258 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.581221-04:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() restored session user from code {“session”:{“site_id”:“default”,“enable_database_connection_pooling”:“1”,“csrf”:"",“scopes”:“openid offline_access api:oemr api:fhir api:port user/allergy.read user/allergy.write user/appointment.read user/appointment.write user/dental_issue.read user/dental_issue.write user/document.read user/document.write user/drug.read user/encounter.read user/encounter.write user/facility.read user/facility.write user/immunization.read user/insurance.read user/insurance.write user/insurance_company.read user/insurance_company.write user/insurance_type.read user/list.read user/medical_problem.read user/medical_problem.write user/medication.read user/medication.write user/message.write user/patient.read user/patient.write user/practitioner.read user/practitioner.write user/prescription.read user/procedure.read user/soap_note.read user/soap_note.write user/surgery.read user/surgery.write user/vital.read user/vital.write user/AllergyIntolerance.read user/CareTeam.read user/Condition.read”,“client_id”:“biLM_8HljD6l8F2nQDJjqOgTcfK4MphiMe9IvotoVpo”,“client_role”:“user”,“launch”:"",“user_id”:“95da1f1f-96a6-4f6d-960a-99a284e68c84”,“persist_login”:“0”}} []
[Fri Mar 18 22:48:27.582246 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.582219-04:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() creating server [] []
[Fri Mar 18 22:48:27.585599 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.585572-04:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() grantType is authorization_code [] []
[Fri Mar 18 22:48:27.585639 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.585619-04:00] OpenEMR.DEBUG: logging global params {“site_addr_oath”:“https://emr-test.mphise.us”,“web_root”:"",“site_id”:“default”} []
[Fri Mar 18 22:48:27.587627 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.587600-04:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() authServer created [] []
[Fri Mar 18 22:48:27.587963 2022] [php:notice] [pid 721] [client 10.99.11.189:22606] [2022-03-18T18:48:27.587933-04:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() OAuthServerException occurred {“hint”:"",“message”:“Bad request”,“stack”:"#0 /var/www/localhost/htdocs/openemr/oauth2/authorize.php(73): OpenEMR\\RestControllers\\AuthorizationController->oauthAuthorizeToken()\n#1 {main}"} []

#13

Very strange, you can see in the log that when the session is restored, the CSRF is an empty string.
@sjpadgett Do you have any thoughts on why the authorization server would have an empty CSRF in the session?

I can look into this more, but it seems strange on why that would be the case.

#14

How are you calling your /oauth2/default/authorize endpoint? Are you passing the state parameter? After looking at how the CSRF token is built it leverages the state parameter in the authorize endpoint. I’m guessing that is your problem.

We’ve been talking about the token endpoint all this time but I assumed you had everything setup correctly for the authorize endpoint. I should have caught that with your earlier question.

It looks like we should add to the codebase to reject the authorize flow if the state parameter is missing. Can you check and see if that is the problem?

#15

Hi @adunsulag

I was not using the state parameter in my GET request to /oauth2/default/authorize. After adding the state parameter, I can complete the Oauth2 handshake and get both access and refresh tokens. Thank you for troubleshooting with me. I hope this is helpful to others also.

From what I understand, the state parameter is optional for most OAuth2 providers. If it’s a required field, the docs/examples should probably say as much. Also, validating CSRF doesn’t make a whole lot of sense on the /oauth2/default/token request since it’s not guaranteed to be a browser facing request. In either case, we’re thankful for this platform and the support that our team has been provided with.

Thank you,

Chris

#16

The documentation I updated 4 days ago and mentioned in this post actually mentioned the state parameter as being required. It is there in the example GET request as well. I’ll look to see if we can make that more clear. Perhaps having a table that lists the required fields in the Authorization server. Here is the instructions I wrote for people coming to this post:

You will need to pass the scopes you are requesting, the redirect_uri (must be one that was registered at the time of your client registration), and a state parameter which can be any value. Once authorization has finished the browser will be redirected to the URL specified in redirect_uri with an encrypted code value and the state value sent in the initial authorize request.

While some OAUTH2 providers skip the state parameter, it is recommended that it be used for mitigating CSRF requests with the authorize parameter. I’m not completely following why we check the CSRF on the token endoint and the original developer (@sjpadgett) could perhaps shed some light on that. That said we do only check it for the authorization_grant . Since we are treating it as a required field, my thoughts are we need to change the authorization flow to do a hard fail on the authorize endpoint if the state parameter is missing. This would have helped both of us identify this problem much quicker.

I won’t be able to make this change for a while as we’re in the middle of ONC work, nor will the original developer (@sjpadgett) but if you and your team wanted to give us a pull request making the change, we’d be happy to review it.