Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: 408 Timeout during initial import after 175 records #405

Open
babbitt opened this issue Feb 2, 2024 · 10 comments
Open

[Bug]: 408 Timeout during initial import after 175 records #405

babbitt opened this issue Feb 2, 2024 · 10 comments
Assignees
@AnalogJ
Labels
bug Something isn't working

Comments

@babbitt
Copy link

babbitt commented Feb 2, 2024

Contact Details

[email protected]

What happened?

During initial resource import after connection (Using eClinicalWorks in this case, can check with another type of connection and get back to you) The first 175 resources import fine then the logs start returning 408's and fasten keeps trying to generate a new access token.

Each resource then takes exactly 10s to fail, one after the other.

Based on the fact that 175 seems like to round of a number to be a coincidence; seems like maybe eClinicalWorks is rate limiting you (without knowing anything about either system). Maybe it's worth putting in a watchdog that pauses resource import for X minutes after Y fails (or worse yet hard-coding 175 resource loads per chunk).

Again, huge fan of what you're doing and happy hunt down bugs :)

Flavor

Docker

Version

main#f21ff8b

Relevant log output

time="2024-02-02T20:09:29Z" level=info msg="access token expired, must refresh" type=web
time="2024-02-02T20:09:29Z" level=info msg="using refresh token to generate access token..." type=web
time="2024-02-02T20:09:39Z" level=warning msg="skipping resource ([TYPE]/[RESOURCEID]), request failed: oauth2: cannot fetch token: 408 Request Time-out\nResponse: <html><body><h1>408 Request Time-out</h1>\nYour browser didn't send a complete request in time.\n</body></html>\n" type=web
@babbitt babbitt added the bug Something isn't working label Feb 2, 2024
@AnalogJ
Copy link
Member

AnalogJ commented Feb 2, 2024

just to make sure I understand the issue, when Fasten attempts to refresh the access token, the refresh fails?

@babbitt
Copy link
Author

babbitt commented Feb 2, 2024 •
edited
Loading

It appears that way based on the log output.

Here's a snippet of the logs surrounding where they start to fail:

...
time="2024-02-02T20:09:22Z" level=info msg="insert/update FHIRResource ([ResourceType]) [RESOURCE]" type=web
time="2024-02-02T20:09:22Z" level=info msg="Publishing message to room: `[MESSAGEID]`" type=web
time="2024-02-02T20:09:25Z" level=info msg="insert/update FHIRResource ([ResourceType]) [RESOURCE]" type=web
time="2024-02-02T20:09:26Z" level=info msg="Publishing message to room: `[MESSAGEID]`" type=web
time="2024-02-02T20:09:28Z" level=info msg="insert/update FHIRResource ([ResourceType]) [RESOURCE]" type=web
time="2024-02-02T20:09:29Z" level=info msg="Publishing message to room: `[MESSAGEID]`" type=web
time="2024-02-02T20:09:29Z" level=info msg="access token expired, must refresh" type=web
time="2024-02-02T20:09:29Z" level=info msg="using refresh token to generate access token..." type=web
time="2024-02-02T20:09:39Z" level=warning msg="skipping resource ([ResourceType]/[RESOURCE]), request failed: oauth2: cannot fetch token: 408 Request Time-out\nResponse: <html><body><h1>408 Request Time-out</h1>\nYour browser didn't send a complete request in time.\n</body></html>\n" type=web
time="2024-02-02T20:09:39Z" level=info msg="access token expired, must refresh" type=web
time="2024-02-02T20:09:39Z" level=info msg="using refresh token to generate access token..." type=web
time="2024-02-02T20:09:49Z" level=warning msg="skipping resource ([ResourceType]/[RESOURCE]), request failed: oauth2: cannot fetch token: 408 Request Time-out\nResponse: <html><body><h1>408 Request Time-out</h1>\nYour browser didn't send a complete request in time.\n</body></html>\n" type=web
time="2024-02-02T20:09:49Z" level=info msg="access token expired, must refresh" type=web
time="2024-02-02T20:09:50Z" level=info msg="using refresh token to generate access token..." type=web
time="2024-02-02T20:10:00Z" level=warning msg="skipping resource ([ResourceType]/[RESOURCE]), request failed: oauth2: cannot fetch token: 408 Request Time-out\nResponse: <html><body><h1>408 Request Time-out</h1>\nYour browser didn't send a complete request in time.\n</body></html>\n" type=web
...

All resources above and below of this point continued their respective patterns. In total the first 175 resources completed successfully while the next 167 (the rest) errored out as shown above.

At the end of the sync there is an error message that appears to be unrelated. Happy to break that out into it's own issue if it isn't. Putting it below in case it is:

time="2024-02-02T20:38:11Z" level=error msg="3 error(s) occurred during sync. \n map[CarePlan:An error occurred during request {URL} - 400 - 400  [{\n  \"resourceType\": \"OperationOutcome\",\n  \"text\": {\n    \"status\": \"generated\",\n    \"div\": \"<div xmlns=\\\"http:https://www.w3.org/1999/xhtml\\\"><h1>Operation Outcome</h1><table border=\\\"0\\\"><tr><td style=\\\"font-weight: bold;\\\">ERROR</td><td>[]</td><td><pre>Invalid request: Does not know how to handle get operation with parameter [patient]</pre></td>\\r\\n\\t\\t\\t\\t\\t\\r\\n\\t\\t\\t\\t\\r\\n\\t\\t\\t</tr>\\r\\n\\t\\t</table>\\r\\n\\t</div>\"\n  },\n  \"issue\": [ {\n    \"severity\": \"error\",\n    \"code\": \"processing\",\n    \"diagnostics\": \"Invalid request: Does not know how to handle get operation with parameter [patient]\"\n  } ]\n}] CareTeam:An error occurred during request {URL} - 400 - 400  [{\n  \"resourceType\": \"OperationOutcome\",\n  \"text\": {\n    \"status\": \"generated\",\n    \"div\": \"<div xmlns=\\\"http:https://www.w3.org/1999/xhtml\\\"><h1>Operation Outcome</h1><table border=\\\"0\\\"><tr><td style=\\\"font-weight: bold;\\\">ERROR</td><td>[]</td><td><pre>Invalid request: Does not know how to handle get operation with parameter [patient]</pre></td>\\r\\n\\t\\t\\t\\t\\t\\r\\n\\t\\t\\t\\t\\r\\n\\t\\t\\t</tr>\\r\\n\\t\\t</table>\\r\\n\\t</div>\"\n  },\n  \"issue\": [ {\n    \"severity\": \"error\",\n    \"code\": \"processing\",\n    \"diagnostics\": \"Invalid request: Does not know how to handle get operation with parameter [patient]\"\n  } ]\n}] Observation:An error occurred during request {URL} - 400 - 400  [{\n  \"resourceType\": \"OperationOutcome\",\n  \"text\": {\n    \"status\": \"generated\",\n    \"div\": \"<div xmlns=\\\"http:https://www.w3.org/1999/xhtml\\\"><h1>Operation Outcome</h1><table border=\\\"0\\\"><tr><td style=\\\"font-weight: bold;\\\">ERROR</td><td>[]</td><td><pre>Invalid request: Does not know how to handle get operation with parameter [patient]</pre></td>\\r\\n\\t\\t\\t\\t\\t\\r\\n\\t\\t\\t\\t\\r\\n\\t\\t\\t</tr>\\r\\n\\t\\t</table>\\r\\n\\t</div>\"\n  },\n  \"issue\": [ {\n    \"severity\": \"error\",\n    \"code\": \"processing\",\n    \"diagnostics\": \"Invalid request: Does not know how to handle get operation with parameter [patient]\"\n  } ]\n}]]" type=web

Note: {URL} is a replacement for privacy

@AnalogJ
Copy link
Member

AnalogJ commented Feb 2, 2024

Hmm, so every request after the first 175 fails while attempting to refresh the offline token.. that's definitely not how this should work.

Let me see if I can replicate this locally. I haven't seen any issues like this in the eClinicalWorks/Healow Sandbox, so I might have to find a way to create a real patient portal account with one of these practices :(

@babbitt
Copy link
Author

babbitt commented Feb 2, 2024

On the sync dashboard the following info is displayed:
image

{
  "source_id": "{VALUE}",
  "brand_id": "{VALUE}",
  "checkpoint_data": {
    "stage": "PendingResources",
    "summary": {
      "UpdatedResources": [
        ...
        {RESOURCES}
        ...
      ],
      "TotalResources": 343
    }
  },
  "error_data": {
    "errors": {
      "CarePlan": {},
      "CareTeam": {},
      "Observation": {}
    }
  }
}

@babbitt
Copy link
Author

babbitt commented Feb 2, 2024

Hmm, so every request after the first 175 fails while attempting to refresh the offline token.. that's definitely not how this should work.

Let me see if I can replicate this locally. I haven't seen any issues like this in the eClinicalWorks/Healow Sandbox, so I might have to find a way to create a real patient portal account with one of these practices :(

If you need a guinea pig to play around with some stuff I'm happy to help to the extent I can

@babbitt
Copy link
Author

babbitt commented Feb 21, 2024

@AnalogJ just wanted to ping this. Still looking for help with this?

@AnalogJ
Copy link
Member

AnalogJ commented Feb 21, 2024

Hey @babbitt Apologies, I've been a bit distracted working on the Patient Summary Export/PDF generation.

Can you throw a meeting on my calendar? We can do a live debugging session and maybe I can figure out how to replicate this issue locally.

https://calendly.com/jason-kulatunga/

@AnalogJ
Copy link
Member

AnalogJ commented Feb 28, 2024

hey @babbitt can you pull the latest docker image and see if theres any additional errors being logged during the token refresh?

Here's the change I made: fastenhealth/fasten-sources@ba30d17

The log message should be prefixed with An error occurred during token refresh:

@babbitt
Copy link
Author

babbitt commented Feb 28, 2024

@AnalogJ
Unfortunately I think this may not have helped all that much. Just a prettier version of the same message.

2024/02/28 04:18:01 An error occurred during token refresh: oauth2: cannot fetch token: 408 Request Time-out
Response: <html><body><h1>408 Request Time-out</h1>
Your browser didn't send a complete request in time.
</body></html>

@AnalogJ
Copy link
Member

AnalogJ commented Mar 1, 2024

ugh. well thats not very helpful, let me see if I can find some other logging I can add.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@AnalogJ AnalogJ

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@AnalogJ @babbitt