Flaky integration test: run:complete triggers before step:complete

[josephjclark]

here's the output of a flaky test with debug logging on

It looks like the run:complete triggers before the step:complete, for some reason. This then closes down the run in the lightning mock and so the step:complete never fires. Which, in this case, kills the test.

joe@jc-mint:~/.../worker$ pnpm exec ava test/integration.test.ts 
--import=@swc-node/register/esm-register

[LTG] ℹ Listening on  2318
[worker] ✔ Worker dirty-jars-matter listening on 2994
[worker] ⚠ WARNING: no collections URL provided. Collections service will not be enabled.
[worker] ⚠ Pass --collections-url or set WORKER_COLLECTIONS_URL to set the url
[worker] ❯ Connecting to Lightning at ws://localhost:2318/worker
[worker] ℹ Closing server...
[worker] ❯ No active runs detected, closing immediately
[worker] ✔ Server closed
[worker] ❯ Connected to worker queue socket
[worker] ✔ Worker fancy-rings-fall listening on 2146
[worker] ⚠ WARNING: no collections URL provided. Collections service will not be enabled.
[worker] ⚠ Pass --collections-url or set WORKER_COLLECTIONS_URL to set the url
[worker] ❯ Connecting to Lightning at ws://localhost:2318/worker
[worker] ❯ Connected to worker queue socket
[worker] ✔ Connected to Lightning at ws://localhost:2318/worker
[worker] ℹ Starting workloop for manual>*:5
[worker] ❯ Claiming runs [manual>*:5] :: demand 1 | capacity 0/5 | memory 3% (109/4144mb)
[LTG] ℹ joining channel run:7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[LTG] ℹ Claiming 1 runs
[worker] ❯ claimed 1 runs in 4ms (7c6e0fd8-d50c-45ff-ae96-355326e4dbdf)
[worker] ❯ skipping run token validation for 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[worker] ❯  starting run 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[worker] ℹ JOINING run:7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[worker] ❯ connecting to run:7c6e0fd8-d50c-45ff-ae96-355326e4dbdf with timeout 0.01s
[worker] ✔ connected to run:7c6e0fd8-d50c-45ff-ae96-355326e4dbdf ok
[worker] ℹ executing  7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Memory limit: 500mb
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Timeout: 600s
[worker] ℹ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: sent run:log (2):: OK :: 1ms
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Payload limit: 100mb
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Versions:
    ▸ node.js                 22.12.0
    ▸ worker                  1.23.2
    ▸ @openfn/test-adaptor    1.0.0
[worker] ℹ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: sent run:start :: OK :: 5ms
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Compiling all workflow steps...
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Finished in 0.002s
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Compilation complete in 0.013s
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Workflow compilation complete in 0.022s
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Executing 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Starting execution from step,fd6799bb-0209-46f0-8527-84e2fb1f8c8b
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Starting step fd6799bb-0209-46f0-8527-84e2fb1f8c8b
[worker] ℹ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: sent run:log (7):: OK :: 1ms
[worker] ℹ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: sent step:start :: OK :: 1ms
[worker] ℹ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: sent step:start :: OK :: 1ms
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] [linker] loading module @openfn/test-adaptor
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] [linker] Loading module @openfn/test-adaptor from /home/joe/repo/openfn/kit/integration-tests/worker/dummy-repo/node_modules/@openfn/test-adaptor_1.0.0/index.js
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Executing expression (1 operations)
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Starting operation 1
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Operation 1 complete in 0ms
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Expression complete!
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] fd6799bb-0209-46f0-8527-84e2fb1f8c8b completed in 2ms
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Step memory usage: [step 42mb] [system 180mb]
[LTG] ℹ LOG [7c6e0fd8-d50c-45ff-ae96-355326e4dbdf] Run complete with status: success
[worker] ℹ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: sent run:log (8):: OK :: 2ms
[LTG] ℹ Completed run  7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[LTG] ❯ {
  "data": "aaaa"
}
[worker] ✘ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: step:complete :: ERR: [step:complete] There are no listeners on channel run:7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[worker] ❯ workflow 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf complete in 0.302s: releasing worker
[worker] ❯ Leaving run:7c6e0fd8-d50c-45ff-ae96-355326e4dbdf
[worker] ℹ cancelling workloop: restarting
[worker] ℹ Starting workloop for manual>*:5
[worker] ❯ Claiming runs [manual>*:5] :: demand 1 | capacity 0/5 | memory 3% (111/4144mb)
[worker] ℹ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: sent run:complete :: OK :: 4ms
[LTG] ❯ No claims (queue empty)
[worker] ❯ claimed 0 runs in 2ms (-)
[worker] ✘ 7c6e0fd8-d50c-45ff-ae96-355326e4dbdf :: job-start :: timeout (fallback)
[worker] ❯ Claiming runs [manual>*:5] :: demand 1 | capacity 0/5 | memory 3% (111/4144mb)

[josephjclark]

This is a bug deep in the engine.

I can see from logs that events are received from the engine by the worker in the right order - but the worker is actually emitting those events in the wrong order. Just very very occasionally.

I'm looking at the central event processor queue, which is responsible for handling this stuff and ensuring the sequence stays the same. And I can see that it's pulling and event before another one has finished.

This is likely to be the cause of some lost runs