Logs
The logs don’t even register anything is being done.
Situation
I’m running a dev docker compose instance of OpenEMR directly from the git repo.
I’m trying to test calling the FHIR APIs from Postman. I have registered a private client, and created an Oauth2.0 config in postman with the authorize url, token url, client id and secret, etc, which were returned from the /register call.
When I click ‘Get New Access Token’ in Postman, it calls the /authorize endpoint which seems to work
I get the login dialog, it then redirects back to postman and postman automatically attempts to call the /token endpoint with the access code, but it immediately fails with a 400:
{“error”:“invalid_request”,“error_description”:“Bad request”,“message”:“Bad request”}
Anything I’m obviously doing wrong? I know the client id, secret, callback sent to /authorize and /token are identical because postman automates the code exchange.
Have you tried turning on the debug api logs in Logging → System Error Logging Options?
From what I see of your request you’ve posted it seems like it should be working. I did just fix a CORS bug in the master branch about two weeks ago dealing with the /token endpoint, but I don’t think that would have impacted you, plus you’re working on the latest dev branch anyways.
Was not aware of how to turn the logs on/up. Thanks! Though that didn’t immediately have any affect. I think I might know what the problem is though. Postman allows two options for Client Authentication 1) Send as Basic Auth Header or 2) Send client credentials in body.
I can’t seem to have it both send the client_id in the body and the auth header.
I’m not an OAuth expert, but this might be a too-onerous requirement on the OpenEMR side to require both, if indeed it does.
Are you looking at the apache error logs? You should see a number of log entries when you hit the token endpoint.
Your right the example does show the client_id in the body which isn’t required and I’m pretty sure its ignored as my test scripts work fine with just the Basic header authentication.
I didn’t see anywhere that you enabled your confidential client app inside OpenEMR. Confidential apps are disabled by default and must be enabled by an OpenEMR administrator to make requests.
Thanks for the help Stephen. I did make sure to go in and enable the client. Perhaps I’m looking in the wrong place for the logs. When I run docker compose 4 containers start up. I’m tailing the console log for “openemr/openemr:flex” - which is the container exposing the 8300/9300 ports. Are the logs in a file or something? Nothing is coming up on the console after it starts. This is the last thing printed:
Starting apache!
AH00558: httpd: Could not reliably determine the server’s fully qualified domain name, using 172.23.0.6. Set the ‘ServerName’ directive globally to suppress this message
That’s the way I do it. There might be a way to configure the docker containers to output the php error logs to the docker stdout but you’d need someone like @jesdynf or @brady.miller to chime in as I don’t know of any.
I’m on the main branch, not dev FYI. So now the question is, how to correct this (unless you think it’s related to the CORS bug you mentioned?).
I’ve used Postman to connect to several other OAuth providers (Keycloak, Auth0, etc.). So it should be compliant/safe/etc…
It does supply a standard redirect URI which I’m not 100% certain how it works, but that may be what is triggered the CSFR, perhaps? Because the /token request doesn’t originate from the redirect domain.
I just barely hit a CSRF bug on the database upgrade script just a few minutes ago. Could be related to something internally in OpenEMR. You shouldn’t be triggering any kind of CSRF on the api as only our internal api which uses a session cookie deals with the CSRF.
You could try hitting our demo instances and see if you get the same behavior on one of the stable releases, either that or check out an earlier release locally while we investigate the issue.
So postman will auto-save cookies. We do issue a cookie as part of the authorization flow, can you try clearing the cookies in the postman request and see if that clears your CSRF issue?
I’m interested to know if we have introduced a bug in how we setup the session cookies.
I cleared the cookies in Postman, restarted OpenEMR, and restarted Chrome. (I did not explicitly delete cookies in chrome).
Same error, here are the logs from the point where I authorized the requested scopes in the post-login dialog, at which point Postman then tries to get the access token.
I do see a line “restored session user from code” - which may be relevant? (really I’m not sure, just speculating)
Wed Jun 21 18:47:23.205922 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.205383+00:00] OpenEMR.DEBUG: oauth2 request received {"endpoint":"/default/device/code"} [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.210196 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.209823+00:00] OpenEMR.DEBUG: AuthorizationController->authorizeUser() starting authorization [] [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.211026 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.210988+00:00] OpenEMR.DEBUG: AuthorizationController->updateAuthRequestWithUserApprovedScopes() attempting to update auth request with user approved scopes {"userApprovedScopes":{"user/Patient.read":"user/Patient.read","openid":"openid"}} [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.211099 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.211069+00:00] OpenEMR.DEBUG: AuthorizationController->updateAuthRequestWithUserApprovedScopes() replaced request scopes with user approved scopes {"updatedScopes":[""openid"",""user\\\\/Patient.read""]} [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.211886 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.211854+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() creating server [] [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.215243 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.215205+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() grantType is authorization_code [] [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.215337 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.215280+00:00] OpenEMR.DEBUG: logging global params {"site_addr_oath":"https://localhost:9300","web_root":"","site_id":"default"} [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.216573 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.216544+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() authServer created [] [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:23.316935 2023] [php:notice] [pid 39] [client 172.28.0.1:36190] [2023-06-21T18:47:23.316882+00:00] OpenEMR.DEBUG: AuthorizationController->authorizeUser() sending server response [] [], referer: https://localhost:9300/oauth2/default/scope-authorize-confirm
[Wed Jun 21 18:47:24.661571 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.660796+00:00] OpenEMR.DEBUG: oauth2 request received {"endpoint":"/default/token"} []
[Wed Jun 21 18:47:24.666133 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.666085+00:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() starting request [] []
[Wed Jun 21 18:47:24.667759 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.667705+00:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() grant type received {"grant_type":"authorization_code"} []
[Wed Jun 21 18:47:24.668421 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.668376+00:00] OpenEMR.DEBUG: AuthorizationController->oauthAuthorizeToken() restored session user from code {"session":{"site_id":"default","enable_database_connection_pooling":"1","csrf":"","scopes":"openid user/Patient.read","client_id":"4IQi7FNnVrieMqIJNQ4By4913qYK_Tvhaqef9965G-k","client_role":"user","launch":"","redirect_uri":"https://oauth.pstmn.io/v1/callback","user_id":"996d5012-381a-4c2a-a884-ec935438daa2","persist_login":"0"}} []
[Wed Jun 21 18:47:24.669400 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.669364+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() creating server [] []
[Wed Jun 21 18:47:24.673563 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.673514+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() grantType is authorization_code [] []
[Wed Jun 21 18:47:24.673654 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.673617+00:00] OpenEMR.DEBUG: logging global params {"site_addr_oath":"https://localhost:9300","web_root":"","site_id":"default"} []
[Wed Jun 21 18:47:24.675578 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.675537+00:00] OpenEMR.DEBUG: AuthorizationController->getAuthorizationServer() authServer created [] []
[Wed Jun 21 18:47:24.675662 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.675619+00:00] OpenEMR.ERROR: AuthorizationController->oauthAuthorizeToken() CSRF check failed [] []
[Wed Jun 21 18:47:24.675992 2023] [php:notice] [pid 47] [client 172.28.0.1:33120] [2023-06-21T18:47:24.675954+00: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}"} []
$this->grantType = $request->getParsedBody()['grant_type'];
$this->logger->debug("AuthorizationController->oauthAuthorizeToken() grant type received", ['grant_type' => $this->grantType]);
if ($this->grantType === 'authorization_code') {
// re-populate from saved session cache populated in authorizeUser().
$ssbc = $this->sessionUserByCode($code);
$_SESSION = json_decode($ssbc['session_cache'], true);
$this->logger->debug("AuthorizationController->oauthAuthorizeToken() restored session user from code ", ['session' => $_SESSION]);
}
// TODO: explore why we create the request again...
if ($this->grantType === 'refresh_token') {
$request = $this->createServerRequest();
}
// Finally time to init the server.
$server = $this->getAuthorizationServer();
try {
if (($this->grantType === 'authorization_code') && empty($_SESSION['csrf'])) {
// the saved session was not populated as expected
$this->logger->error("AuthorizationController->oauthAuthorizeToken() CSRF check failed");
throw new OAuthServerException('Bad request', 0, 'invalid_request', 400);
}
I’m in the middle of something else but you can take a look at your oauth_trusted_users table at the session_cache table and see if you are getting a csrf saved in the session. If you’re not then something is going wrong in the authorization form flow. If a value is saved, then there’s something wrong with the session cookies being sent.
I’m scratching my head though why you’re running into this as I’ve seen something similar when crossing from HTTP to HTTPS but it doesn’t look like you are doing that. Have you tested this against any of the OpenEMR demo servers OpenEMR Demo and reproduced the problem?
You may need to walk me through this… I’m a fairly experienced backend developer, but brand new to OpenEMR. Do I need to connect to the mariadb container to query this, or is there someplace in the UI to extract this?
