Flaky api integration tests: transitions

[dianabarsan]

Describe the issue
Example run: https://github.com/medic/cht-core/actions/runs/24440636603/job/71406458766#step:16:3866

  4) Transitions public_form
       when false, reports from unknwon sources should not be accepted:

      AssertionError: expected [ …(2) ] to have a length of 1 but got 2
      + expected - actual

      -2
      +1
      
      at Context.<anonymous> (/home/runner/work/cht-core/cht-core/tests/integration/transitions/public-form-transitions.spec.js:315:31)
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  5) transitions
       should run all sync transitions and all async transitions:

      AssertionError: expected 11 to equal 10
      + expected - actual

      -11
      +10
      
      at /home/runner/work/cht-core/cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:502:50
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  6) transitions
       should not crash services when transitions are misconfigured:

      AssertionError: expected 1 to equal +0
      + expected - actual

      -1
      +0
      
      at /home/runner/work/cht-core/cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:702:50
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

Multiple tests have failed during this run, so I am suspecting something was up with the machine.

[rsmihir389]

Hey — I've been seeing this exact pattern a lot. Flaky tests like this usually cost teams $30-40 per rerun in CI time + developer context-switching.

I built a tool that detects flaky tests and shows the dollar cost: kleore.com. Here's what a report looks like on a real repo: sample report.

60-second install as a GitHub App, free tier shows the cost. Might help here.

[witash]

I think these are detecting a race condition in the code, not just the tests.

after transitions are applied to a document, the list of transitions that have run is added to the infodoc.

cht-core/shared-libs/transitions/src/transitions/index.js

Line 260 in 8c0cefb

saveDoc(change, (err, result) => {

the modified document is saved, and if successful, the infodoc with the updated list of transitions is saved.

Subsequent changes to the document don't run the same transitions, because all transitions have a hasRun filter that checks the infoDoc to see if it has already run.
e.g.

cht-core/shared-libs/transitions/src/transitions/death_reporting.js

Line 58 in 8c0cefb

!transitionUtils.hasRun(info, NAME) &&

. this is specific to death_reporting, but there are similar checks in all transitions.

cht-core/shared-libs/transitions/src/transitions/utils.js

Line 72 in 8c0cefb

hasRun: (doc, transition) => {

The api runs some transitions synchronously, before documents are saved, without triggering sentinel.
This leads to a race condition where

1. api saves the document after applying transitions.
2. sentinel gets the changed document from the changes feed
3. sentinel gets the infodoc for the change; but the transitions list hasn't been updated yet
4. sentinel runs the same transitions as api (duplicates) because it doesn't know they were already run
5. api saves the infodoc with the updated transitions, but sentinel has already run.

I didn't come up with a way to reproduce this reliably without changing the code, but adding a delay at

cht-core/shared-libs/transitions/src/transitions/index.js

Line 269 in 8c0cefb

infodoc.saveTransitions(change)

to allow sentinel to run before the infodoc is saved causes these tests to fail reliably

  1) message duplicates
       should mark as duplicate after 5 retries by default:

      AssertionError: expected 2 to equal 1
      + expected - actual

      -2
      +1

      at cht-core/tests/integration/transitions/message-duplicates.spec.js:119:44
      at Array.forEach (<anonymous>)
      at cht-core/tests/integration/transitions/message-duplicates.spec.js:118:14
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  2) message duplicates
       should mark as duplicate using configured limit:

      AssertionError: expected 2 to equal 1
      + expected - actual

      -2
      +1

      at cht-core/tests/integration/transitions/message-duplicates.spec.js:165:44
      at Array.forEach (<anonymous>)
      at cht-core/tests/integration/transitions/message-duplicates.spec.js:160:14
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  3) Transitions public_form
       when false, reports from unknwon sources should not be accepted:

      AssertionError: expected [ 'registration', …(2) ] to have a length of 4 but got 3
      + expected - actual

      -3
      +4

      at expectTransitions (cht-core/tests/integration/transitions/public-form-transitions.spec.js:246:52)
      at Context.<anonymous> (cht-core/tests/integration/transitions/public-form-transitions.spec.js:300:5)
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  4) Transitions public_form
       when true, reports from unknwon sources should be accepted:

      AssertionError: expected [ 'registration', …(2) ] to have a length of 4 but got 3
      + expected - actual

      -3
      +4

      at expectTransitions (cht-core/tests/integration/transitions/public-form-transitions.spec.js:246:52)
      at Context.<anonymous> (cht-core/tests/integration/transitions/public-form-transitions.spec.js:372:5)
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  5) Transitions public_form
       should default to false:

      AssertionError: expected [ 'registration', …(2) ] to have a length of 4 but got 3
      + expected - actual

      -3
      +4

      at expectTransitions (cht-core/tests/integration/transitions/public-form-transitions.spec.js:246:52)
      at Context.<anonymous> (cht-core/tests/integration/transitions/public-form-transitions.spec.js:448:5)
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  6) transitions
       should run async and sync transitions over the same doc successfully:

      expected exactly 2 tasks (patient_reports + multi_report_alerts); more means a sync transition was re-run by sentinel after API already produced the task
      + expected - actual

      -3
      +2

      at cht-core/tests/integration/transitions/race-condition.spec.js:427:15
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  7) transitions
       should run all sync transitions and all async transitions:

      AssertionError: expected 19 to equal 10
      + expected - actual

      -19
      +10

      at cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:502:50
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  8) transitions
       should run transitions and save documents in series:

      AssertionError: expected 4 to equal 2
      + expected - actual

      -4
      +2

      at cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:829:54
      at Array.forEach (<anonymous>)
      at cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:827:21
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  9) transitions
       should run async and sync transitions over the same doc successfully:

      AssertionError: expected 3 to equal 2
      + expected - actual

      -3
      +2

      at cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:924:42
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

  10) transitions
       should creating a patient that is already dead:

      AssertionError: expected 2 to equal 3
      + expected - actual

      -2
      +3

      at expectTransitions (cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:308:59)
      at cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js:992:9
      at process.processTicksAndRejections (node:internal/process/task_queues:105:5)

With some additional debug logging, can see the exact timing

1   api-1       | [RACE 1776847141628] api.messaging.createDocs: starting processDocs for 1 doc(s): [{"gateway_ref":"imm1"}]
2   api-1       | [RACE 1776847141651] api.processDocs: PRE-SAVE infodoc.bulkUpdate: [{"_id":"f9b9accb-4121-4272-a893-88602c0f038e-info"}]
3   sentinel-1  | [RACE 1776847142032] sentinel.processChange: read infodoc for settings, doc._rev=3-86c97dc23894b6d12f9cb80dec2beb4c, info.transitions={}
4   api-1       | [RACE 1776847142111] api.applyTransition RUN: key=update_clinics docId=f9b9accb-4121-4272-a893-88602c0f038e
5   api-1       | [RACE 1776847142131] api.applyTransition CHANGED: key=update_clinics docId=f9b9accb-4121-4272-a893-88602c0f038e
6   api-1       | [RACE 1776847142131] api.applyTransition RUN: key=accept_patient_reports docId=f9b9accb-4121-4272-a893-88602c0f038e
7   api-1       | [RACE 1776847142140] api.applyTransition CHANGED: key=accept_patient_reports docId=f9b9accb-4121-4272-a893-88602c0f038e
8   api-1       | [RACE 1776847142163] api.finalize MEDIC DOC SAVED (feed fires): docId=f9b9accb-4121-4272-a893-88602c0f038e newRev=1-2f1080a48eaa587e6a80fd524385c5ec
9   sentinel-1  | [RACE 1776847142272] sentinel.processChange: read infodoc for f9b9accb-4121-4272-a893-88602c0f038e, doc._rev=1-2f1080a48eaa587e6a80fd524385c5ec, info.transitions=undefined
10  sentinel-1  | [RACE 1776847142276] sentinel.applyTransition RUN: key=accept_patient_reports docId=f9b9accb-4121-4272-a893-88602c0f038e
11  sentinel-1  | [RACE 1776847142295] sentinel.applyTransition CHANGED: key=accept_patient_reports docId=f9b9accb-4121-4272-a893-88602c0f038e
12  sentinel-1  | [RACE 1776847142295] sentinel.applyTransition RUN: key=multi_report_alerts docId=f9b9accb-4121-4272-a893-88602c0f038e
13  sentinel-1  | [RACE 1776847142303] sentinel.applyTransition CHANGED: key=multi_report_alerts docId=f9b9accb-4121-4272-a893-88602c0f038e
14  sentinel-1  | [RACE 1776847142347] sentinel.finalize MEDIC DOC SAVED (feed fires): docId=f9b9accb-4121-4272-a893-88602c0f038e newRev=2-42ab2bfedc14378d50ffc66b2eacbb71
15  api-1       | [RACE 1776847143163] api.finalize POST-DELAY, about to saveTransitions: docId=f9b9accb-4121-4272-a893-88602c0f038e transitions=["update_clinics","accept_patient_reports"]
16  api-1       | [RACE 1776847143192] api.finalize saveTransitions DONE: docId=f9b9accb-4121-4272-a893-88602c0f038e
17  sentinel-1  | [RACE 1776847143348] sentinel.finalize POST-DELAY, about to saveTransitions: docId=f9b9accb-4121-4272-a893-88602c0f038e transitions=["accept_patient_reports","multi_report_alerts"]
18  sentinel-1  | [RACE 1776847143368] sentinel.finalize saveTransitions DONE: docId=f9b9accb-4121-4272-a893-88602c0f038e

line 9 shows sentinel reading the info before transitions have been saved to it, and then running the duplicate transitions
before api saves the transitions on line 15

[dianabarsan]

I think that the only reliable way to resolve this is to save the infodoc before the medic doc.
But that's with a big caveat, because in case the medic doc save fails we would need to revert the infodoc, and that can lead to all manner of weird timing inconsistencies (maybe we'd just be creating MORE race conditions).

Or, we somehow "lock" the infodoc, this means that there are two writes happening to the infodoc.
Off the top of my head, I would "lock" the infodoc, writing the _rev of the medic doc that we are running transitions over, and then "unlock" it when done. Sentinel would not process a doc that is infodoc locked.
A bit more involved, but it would save us from further race conditions.

What do you think?

[witash]

So I tried a couple of things.
Just saving the transitions before the medic documents, for both processDocs and processChanges, does lead to more race conditions which can be reliably reproduced in tests. Specifically, when saving messages, api tries to update a message while sentinel is running transitions, and sentinel gets a conflict when it also tries to save the message. Then the transitions don't ever re-run on the next change because infodoc says they already ran. Currently, there's no explict retry, but transitions do get rerun on the next change. Which may not be intentional (this comment suggests its not) but tests, and maybe even production code, rely on it.

I also tried saving the infodoc first, and if saving the medic document fails, rolling it back. There is still a possibility for inconsistent infodocs if the sentinel process stops after saving the infodoc but before saving the medic doc, or if the rollback itself fails. Maybe still a possibility but seems too complicated for not any real guarantees.

What I came up with is saving the infodocs first in processDocs only, and for processChanges, keeping the current behavior of saving the transitions after saving the medic doc.
This sidesteps the race condition for transitions run by api by not triggering sentinel until after transitions are saved. It doesn't solve the other race condition where sentinel gets a conflict, but keeps the current behavior where transitions are rerun on the the next change.
Which gets the tests to pass, but is mediocre in several ways, and still allows the possibility for the infodoc to be inconsistent and show that transitions have run when the haven't. Maybe that doesn't really matter? if it did can detect this with last_rev; if transitions.last_rev is the same as the current rev of the medic document, the the medic document wasn't saved.

Locking the infodoc would be less janky, but by itself wouldn't solve this particular issue, unless we can change sentinel's behavior, or have sentinel wait for the lock somehow, instead of just not processing the change at all.
Sentinel still needs to run async transitions even if api ran 'sync' transitions. "should run async and sync transitions over the same doc successfully" tests this directly

cht-core/tests/integration/transitions/sentinel-api-transitions.spec.js

Line 852 in 58547e4

it('should run async and sync transitions over the same doc successfully', () => {

So locking the infodoc, and having sentinel not process the doc at all if its infodoc was locked wouldn't allow that; it would need to wait until the lock was "released".
Or not allow sync and async transitions to run on the same document at all, which doesn't seem like it would be possible.

[dianabarsan]

Locking the infodoc would be less janky, but by itself wouldn't solve this particular issue, unless we can change sentinel's behavior, or have sentinel wait for the lock somehow, instead of just not processing the change at all.

That was the idea. To change Sentinel to check for the lock and wait for the unlock.

[witash]

wait for the unlock.

sentinel would need to not process other changes while its waiting, since it only has its saved sequence to tell which changes its processed.
And would need a way to handle stale locks if saving the infodoc succeeded the first time, but then either the medic document or the second infodoc update failed.
It would allow sentinel to handle the race condition, but doesn't really solve it; the changes feed would still be triggered before the lock is released; the thing about saving the infodoc first is that nothing even appears in the changes feed until both the infodoc and the medic document are consistent.

All of which is fine, maybe, but it feels like lot of complexity to add for what is still a workaround...I would prefer going for the simpler workaround in the short term

[dianabarsan]

That's the thing. that I don't believe it's a workaround, i think it's just the final solution to having both system process documents in parallel.

[witash]

having both system process documents in parallel.

ideally both systems shouldn't need to process documents in parallel; api would run the sync transitions, then sentinel runs the async transitions afterwards. There's no reason for them to be processing the same document at the same time, except it being difficult to prevent for other reasons.

so locking is conceptually cleaner, but more complex and solves a concurrency problem that ideally wouldn't exist at all
reordering saves is simpler and solves the ordering issue directly, but is messier

the question is which we prefer