OpenFn / OpenFn/lightning

Tests asserting on logs fail intermittently with an empty capture

Open
#5,082 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Elixir
Stars
296
Forks
86
Avg merge
1d 13h
Merged PRs (30d)
50

Description

Tests that assert on a log line fail intermittently in a full run and pass on their own. When they fail, the captured log is empty rather than wrong, so the assertion reads left: "".

This is not new and it is not caused by any one change. It happens on main too. Writing it down because it costs real time: it lands on whoever pushed next rather than on whoever caused it, and today it cost several CI re-runs on an unrelated stack.

It is worth more than it looks. Counting failures whose captured log came back empty, across four full-suite runs of near-identical trees:

run empty-capture failures total failures
main 10 25
branch 0 16
branch, later 2 22
branch, later still 13 29

So about half of a local full-suite run's failures are this one symptom, and it swings between none and thirteen with the code essentially unchanged. Fixing it would make the suite roughly twice as trustworthy locally, and stop the reruns in CI.

Tests seen doing this include AdaptorServiceTest, the InstallSchemasTest group, MetadataServiceTest, ObanManagerTest and Lightning.WorkflowsTest.

What has been ruled out: it is not the log level. The messages involved are all logged at warning and the primary level in test is warning, so they are not being filtered. It is also not simply that logs from concurrent tests bleed into each other, though that does happen in the other direction: a test asserting nothing was logged can catch a neighbour's warning, and there was one of those which has since been changed to assert on the specific message instead.

What has not been established is the mechanism. The obvious guess is that concurrent tests interfere with each other's capture, but ObanManagerTest is already async: false and still does it, and a sync module should be running on its own by the time it starts. There is also a global capture_log: true in test/test_helper.exs, so every test already has an outer capture and any inner one nests inside it, which is worth looking at. Erlang's logger drops messages when a handler's queue grows past a threshold, which would fit the symptom and the variability, but that has not been confirmed.

Whoever picks this up: the useful signal is the count of left: "" in a full run rather than the total failure count, which is too noisy on a busy machine to compare between runs.

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with test/test_helper.exs and reproduce the issue in a full test run, counting failures whose captured value is empty rather than comparing total failures. Then inspect the capture behavior in AdaptorServiceTest, InstallSchemasTest, MetadataServiceTest, ObanManagerTest, and Lightning.WorkflowsTest, including nested capture_log usage and logger queue behavior. Done means empty log captures no longer cause intermittent assertion failures.

Written by the indexing model from the issue text.

Assessment

Tech stack
elixir, erlang
Domain
observability, testing-qa
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Quiet
Clarity
Needs clarification
Newbie friendliness
38/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.