ci(backend): make backend-test hangs diagnosable - #7154
Draft
corneliusroemer-agent wants to merge 18 commits into
Draft
ci(backend): make backend-test hangs diagnosable#7154corneliusroemer-agent wants to merge 18 commits into
corneliusroemer-agent wants to merge 18 commits into
Conversation
`testLogging` only reported FAILED and STANDARD_ERROR, so the `:test` phase printed nothing between the first class's byte-buddy warning and BUILD SUCCESSFUL. A run that hangs and gets killed by the 15-minute timeout produced a log byte-for-byte the same shape as a green one, with no indication of where it stopped -- four such timeouts since June were undiagnosable for this reason. With STARTED and PASSED, the last STARTED without a matching PASSED is the test that hung. Costs ~1160 extra log lines for ~580 tests. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The job archived nothing, so `backend/build/test-results/test/*.xml` -- which carries per-class start times and the captured stdout that `testLogging` discards -- died with the runner on every failure. An `if: always()` upload alone would not have fixed that: `timeout-minutes` sat at *job* level, and a job timeout cancels the job, skipping all remaining steps. So move the 15-minute limit onto the `Run tests` step and give the job a larger cap; a step timeout fails only that step and lets the upload run. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Knowing *which* test hung (previous commits) still leaves the question of where inside it. A step timeout kills the JVM without a stack, so run a watchdog that `jcmd Thread.print`s every live JVM at 11 and 13 minutes -- before the 15-minute deadline -- and ship the dumps with the test-results artifact. Two dumps a couple of minutes apart distinguish a genuinely stuck thread from a slow one. The watchdog is killed as soon as Gradle returns, so it costs nothing on the ~99.3% of runs that finish normally. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-authored-by: Cornelius Roemer <cornelius.roemer@gmail.com>
The earlier `**/*.xml` glob uploads nothing in the case it was written for. Gradle converts the binary results to JUnit XML and HTML only when the `test` task completes, so a killed run leaves neither. Measured by SIGKILLing a local run: 0 XML files and no HTML report even though all 580 tests had executed -- only build/test-results/test/binary survived. So upload that directory too, and add a `recoverTestReport` task that rebuilds a report from it, run on failure. Its limits are measured rather than assumed: recovery is complete when the tests finished and the kill hit report generation, but yields an empty report when the run is killed genuinely mid-flight -- 73 tests had passed across ~10 classes and none appeared, because the binary store is not committed incrementally. For a hang the STARTED/PASSED log and the thread dumps stay the usable evidence. Also drop `retention-days: 14`, an arbitrary number that inherited the very problem it was meant to solve; the repo default applies instead. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Inspecting the artifact from a green run showed 60 MB carrying the same information three times: the JUnit XML (18 MB, and the only part that pays -- per-class timings plus the stdout logging Gradle discards from the console), `binary/output-events.bin` (19 MB, that same stdout in Gradle's internal format), and the HTML report (23 MB, a rendering of the XML). Nobody debugs a passing run, so upload on failure only. Drop the HTML, which is regenerable from the XML and absent on a kill anyway. Keep the binary results only when Gradle produced no XML, which is exactly when it was killed and they are the sole survivor; otherwise they duplicate the XML. Reverses the `always()` upload added earlier: the "green baseline to diff a hang against" it was justified by does not hold up -- that would want per-class timings, not 60 MB of HTML. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Its 100k inserts were logged individually by Exposed at debug, so the JUnit XML for that one class was 127 MB of the main-path artifact's 146 MB -- 123 MB of it from Slf4jSqlDebugLogger. Compressed that is only ~6 MB, but it makes the artifact unpleasant to download and expand. Set the level through `logging.level.Exposed=WARN` on the test's Spring context rather than manipulating the logger directly: a @BeforeAll that set the logback level was measured to have no effect, because Spring Boot re-applies logging configuration when the context starts, after @BeforeAll has run. Batch test XML 127.37 MB -> 1.28 MB, whole test-results directory 146 MB -> 41 MB. Checked that the level does not leak: logback levels are JVM-global, so this could have silenced SQL logging for every later class. It doesn't -- the DB-touching classes that run after this one still log Exposed at debug (the ones that don't are unit tests that never touch the database). Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
corneliusroemer
marked this pull request as ready for review
August 25, 2026 14:45
corneliusroemer
requested review from
anna-parker,
maverbiest,
theosanderson and
tombch
and
a lite review from Copilot
August 25, 2026 14:45
Contributor
|
Claude finished @corneliusroemer's task in 3m 29s —— View job ReviewGood change overall — the job/step timeout split is the right shape (a job timeout would skip the upload steps), the Two inline comments; only the first is worth acting on before merge:
Checked and fine:
One general note: every new step is Also: |
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
Pull request overview
This PR improves diagnosability of intermittent backend-tests CI hangs by increasing runtime test progress visibility and ensuring actionable artifacts (thread dumps + recovered reports where possible) are collected on failures/timeouts.
Changes:
- Expand Gradle
testtask logging to include STARTED/PASSED events for progress visibility during hangs. - Add a
recoverTestReportGradle task and update the GitHub Actions workflow to collect binary test results, attempt report recovery, and upload diagnostics artifacts (including thread dumps) on failure. - Reduce overly-verbose Exposed logging for the 100k-row batch submission endpoint test to avoid excessively large test result outputs.
Reviewed changes
Copilot reviewed 3 out of 3 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
backend/src/test/kotlin/org/loculus/backend/controller/submission/SubmitLargeBatchTest.kt |
Overrides Exposed log level for this heavy test to prevent massive test result output. |
backend/build.gradle |
Adds richer test logging and registers a report-recovery task for binary test results. |
.github/workflows/backend-tests.yml |
Adds watchdog thread dumps, extends job timeout to allow artifact collection, and uploads diagnostics on failure. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
The Gradle daemon survives the runner killing the test step's process tree, so recoverTestReport can block on the project lock instead of failing, and `|| true` does not help against a block. With a 15-minute test step inside a 20-minute job there is only about three minutes left, so a block there would hit the job timeout, which cancels the job and skips the upload - losing the thread dumps this workflow exists to capture.
added 2 commits
August 25, 2026 15:29
Streaming STARTED/PASSED to the console made every run's log unreadable for the sake of the rare hang that needs it. The progress is still what identifies a hung test, so it now goes to build/diagnostics/test-progress.log, which the existing artifact upload already picks up. Each line is appended and flushed as it happens, so a killed run keeps everything up to the moment it died. The lines are timestamped, which the console version could not be, so the log also gives per-test durations and shows exactly when progress stopped. Uses addTestListener rather than the beforeTest/afterTest closures: Gradle 9.7 deprecates those and removes them in 10, and they would have made the build report as Gradle 10 incompatible. On failure the diagnostics step prints just the tests that started and never finished, so the one line worth having in the job log is still there without the other 1159.
Anything logged from a plan-level hook has no test to be attributed to, so Gradle files it as root output of the whole test run, which exists only in build/reports/tests/test/index.html. That is where a failure to start the test environment reports its real cause. Measured on a forced startup failure: 74 per-class XMLs were written and the underlying pg_ctl error appeared in none of them and in no console line, only in that one file. This restores something earlier in this branch. 16bd0ce dropped reports/tests/** as a duplicate of the XML, which is true for a green or ordinarily-failing run and false for a startup failure, where the root page is the only durable copy of the cause. Rather than putting the whole report back, this takes just the root page: 57 KB against 9.4 MB, so the deduplication still holds for the per-class pages it was aimed at. The general lesson, since the same reasoning will come up again: when pruning archived diagnostics, judge each copy by what it holds on the worst run, not the typical one.
This was referenced Aug 25, 2026
corneliusroemer
marked this pull request as draft
August 25, 2026 16:04
The listener exists to make a hang name the test it was stuck in, without putting per-test output in the log of every normal run. Say that, and say why it is a TestListener rather than the shorter deprecated closures. Also say where the 127 MB came from, since the level alone doesn't show it. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Three simplifications and one reversal, all of which shrink the workflow: `jcmd <substring>` matches every JVM whose main class contains the substring, so `jcmd Gradle Thread.print` dumps the daemon and the test executor in one call, replacing the pid loop. It no longer covers the Kotlin compile daemon, but a wedge there shows up as the Gradle daemon waiting on it. The suite runs one test at a time (no maxParallelForks, no forkEvery, no junit-platform.properties), so the last line of the progress log is the test a hang was stuck in and a tail replaces the started-but-never-finished set. recoverTestReport is gone, along with the binary result store it read from. Recovery is empty when a run is killed while tests are still running, which is every hang we have, so it only paid off in the narrow window of a kill during the report write. Exposed logging stays at debug for the large-batch test: the 127 MB XML only appears when that main-only test fails, and there is no level that keeps a shorter trail, since Exposed inlines every parameter value into the statement it logs. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-authored-by: Cornelius Roemer <cornelius.roemer@gmail.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Why
backend-testsdies at the 15-minute cap every so often, and no occurrence was diagnosable — the job recorded nothing about where it stopped. Six occurrences in 3390 runs (~0.18%) going back to 2025-07-09: 19969091729, 24840664509, 31117640303, 31121527329, 32712103886 att 1, 32748302946 att 1. Two of those only show up if you ask for earlier attempts explicitly, because a run that hung and was then re-run green reports as a fast success.This PR improves logging and log collection and also adds a thread dump collection to be able to inspect exactly where the tests hang.
This has already proved useful, I'll make an issue or fix PRs for the reasons hangs happened (I did ~150 test runs of backend tests to find hangs to investigate).
Worth knowing (according to Claude)
Gradle writes the JUnit XML and HTML only when the
testtask completes. So an artifact glob oftest-results/**/*.xmluploads nothing on a timeout, which is the only case it would be written for. Measured by killing local runs at different points:test-results/test/binary/output-events.binHence keeping the binary store when there's no XML, plus
recoverTestReportto rebuild from it. That recovery has a limit worth knowing before relying on it: complete when all the tests had finished and the kill landed while the report was being written, but empty when the run is killed while tests are still running — 73 tests had passed across ~10 classes and none appeared, because Gradle only finalises that store at the end, rather than as each test finishes. So for a hang the useful evidence is the per-test progress log and the thread dumps; the recovery step only helps when a run is killed after the tests are done.Per-test progress goes to a file rather than the console. Printing every test's start and finish to the job log made ordinary runs unreadable, so it now goes to
build/diagnostics/test-progress.log, which the artifact already collects. Each line is written as it happens, so a killed run keeps everything up to the moment it died — checked by killing a run mid-suite, which left 509 lines with the last one naming the test still running. On a failure the job log gets only the tests that started and never finished, which is the part worth having there.The report's root page is the only place output from outside a test survives. Anything logged before the first test class starts has no test to be attributed to, so Gradle files it as output of the run as a whole, and that appears only in
build/reports/tests/test/index.html. It is where a failure to start the test database reports its real cause: on a deliberately broken startup, 74 per-class XML files were written and not one of them contained it. An earlier commit here dropped the HTML report as a duplicate of the XML, which holds for a normal run and not for that one, so the root page alone is back — 57 KB, against 9.4 MB for the whole report.🚀 Preview: Add
previewlabel to enable