Tests asserting on logs fail intermittently with an empty capture
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
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- 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