Investigate several failed searches in AN WMDA UAT environment

[daria-sorokina-da]

Several searches failed in AN WMDA UAT environment according to the teams channel.

Need to investigate what happened.

Failures on Monday 7 Aug Search ID: 441e824d-58fc-40a6-890a-8c45663f4dc1 Search ID: 5d7ea224-3a3d-4d5a-b945-eb7044aa06da Search ID: 3d0e3c65-4553-422c-85b2-875fecf7e529 Search ID: 72b5c3ee-49f5-468a-8838-171ff382b1c4 Search ID: ad629ac1-4ae3-4e8e-80f1-a3ca72a5c61a

Failures on Tuesday 8 Aug Search ID: e88331ba-b9a8-4ed2-995c-4dc2fcf36ffe

All failures have the following details: Repeat ID (if relevant): Stage Reached: Matching Algorithm ValidationError (if relevant):

[zabeen]

Investigations

Failures caused by *NEW allele in the patient

441e824d-58fc-40a6-890a-8c45663f4dc1 e88331ba-b9a8-4ed2-995c-4dc2fcf36ffe db1bb854-59f5-46c1-a68d-d3cfed62e0a9 38dfe9cf-073e-4192-b5ef-2f631261a5fb

The validation error was reported in the search notification but logic app wasn't grabbing the value to display it in the teams message, that's been fixed now.

Logs show only matching traces, but no exceptions

3d0e3c65-4553-422c-85b2-875fecf7e529 - 07/08/2023 09:30 5d7ea224-3a3d-4d5a-b945-eb7044aa06da - 07/08/2023 09:30 72b5c3ee-49f5-468a-8838-171ff382b1c4 - 07/08/2023 09:37 ad629ac1-4ae3-4e8e-80f1-a3ca72a5c61a - 07/08/2023 09:40 5bad2ac4-ea2d-4872-aef5-14c28010393c - 09/08/2023 14:18 d6a71944-a4e2-4243-b731-cd6db2711bfd - 11/08/2023 07:00 9432ab74-4d94-4001-8e98-69ae45ef02a2 - 11/08/2023 07:02

• Possible thread pool starvation and high CPU usage reported by UAT-WMDA-ATLAS-FUNCTIONS.
• I looked up the first few searches in matching-algorithm-results and they actually had results uploaded!
  • But clearly something went wrong for the matching request message to be replayed and eventually dead-letter (and the permanent failure notification to be sent out).
  • No log file was written for these searches, despite that step being wrapped in a finally block, and no "failure to write log" message was observed in AI logs.
  • The first few searches had very similar patient HLA, re-submitting 3d0e3... to see if it fails when there is no other searches running (as is the case right now): new id 0bd27755-d639-4ed8-820a-45ba18005abd.
  • the re-submitted search succeeded, but no matching phase 2 traces were logged - raised #1035
  • There were about 25 searches submitted at the same time, with similar HLA but varying mismatch criteria.
• I suspect the failures were due to intermittent CPU/memory issues, caused by multiple searches running at the same time.
• If we observe this same problem in live, then we may want to reduce parallelisation by lowering values for this matching setting and/or this matching prediction setting.

[zabeen]

Investigations - Part 2

Attempt 1

• MATCHING_MAX_CONCURRENT_PROCESSES_PER_INSTANCE reduced from 3 to 2
• MAX_CONCURRENT_ACTIVITY_FUNCTIONS reduced from 5 to 3
• Re-ran 25 searches from 7th August 2023 08:00-09:00 UTC in one batch
• Early matching algorithm logs show only 2 matching requests being processed in parallel, as expected
• This time only one matching request from the batch failed due to dead-lettering: 85866829-9ea7-4cc6-84ba-54c361181dfa - this request previously completed successfully.
  • Note: the searches that had previously failed only succeeded after several attempts, so there is still some issue that is causing the replays, even if everything eventually succeeds.

[zabeen]

Dev

• Add search request id to metadata of matching request
• Add WillRetry to metadata of search result notification
• Add search request and attempt number to log (for both successful and failed searches)

Testing

• Add search request id to metadata of matching request - passed
• Add WillRetry to metadata of search result notification - passed
• Add search request and attempt number to log (for both successful and failed searches) - passed
  • successful and failed matching requests had search request and attempt number stored
  • successful and failed atlas-search had search request

[zabeen]

@seanmobrien increased the number of vCores on the active matching db from 8 to 20, and that has reduced the number of failed searches at the matching stage, but not completely eliminated them. The same issue has not yet been observed in live-wmda-atlas, so there is a still a question of whether any action needs to be taken beyond tweaking resource configurations and reducing search parallelisation on UAT as much as possible.

[zabeen]

Searches are still occasionally failing on UAT, but thankfully not on Live.

I am closing this ticket for now, as it is not a live issue - it can be reopened or new ticket raised if required.