ci: make a CI failure legible - crash frames, budget overruns, shared memory, and a coverage job that fits its cap - #648
ci: make a CI failure legible - crash frames, budget overruns, shared memory, and a coverage job that fits its cap#648bburda wants to merge 8 commits into
Conversation
A test step killed by its cap is marked failed by the runner rather than cancelled, and the test that was in flight leaves no result file. `colcon test-result` then reports one erroring test named `<test>.xunit.missing_result` - a test that never failed - among thousands that never ran, while every package queued behind it disappears without trace. Read on its own that is indistinguishable from a single flake, so the budget gets re-run instead of raised. Measured over one month: 17 of 25 killed jobs died on a step cap, and every timeout in this file has been raised at least once. The step's own log is not readable from inside the job, so the overrun is detected by the clock: the start is recorded before the test step and compared against that step's cap afterwards. The same check warns at 80% of the cap, which is the number nobody had when the coverage job reached twelve seconds of margin. It deliberately does not count registered tests against result files - `test_dds_domain_allocation` is registered in every package and writes no xunit, so that comparison reports missing results on a run where everything passed. Container jobs now ask for 1 GB of /dev/shm instead of Docker's default 64 MB. Fast DDS puts a 512 KB segment plus port files there per participant, measured at about 0.65 MB, and a participant killed rather than shut down never gets them back: 15 live participants take 9.6 MB, and 125 killed ones fill 63 MB of 64. Locally, scripts/test.sh now reclaims that memory before a run through `fastdds shm clean`, the vendor's own tool, which decides a segment is stale by taking an exclusive non-blocking flock on its lock file - a lock the kernel drops when a process dies, SIGKILL included. Measured: eight killed participants stranded 5.24 MB across 66 files, all of it reclaimed.
The coverage job finished 89m48s against its 90 minute cap on 2026-08-27 - twelve seconds - and four of its last five runs on main sat between 86 and 90 minutes. Its test step grew from 19m13s to 51m07s in a month, 166%, while every other test-bearing job stayed flat. The cause is one line: build-and-test and jazzy-test both skip ros2_medkit_graph_watchdog, whose suite is 24 minutes on its own, and coverage skips only ros2_medkit_opcua. It alone kept running the suite the others carved out on 2026-08-24, which is the date its step time steps up. Measured test time per package on one run: integration_tests 1050s, graph_watchdog about 1440s, gateway plus fault_manager 389s, and everything else together 85s. The four shards follow those numbers, and their selections partition the workspace - checked against src/, 19 packages, none uncovered and no name that does not exist. Each shard builds the whole workspace because every package needs its dependencies, and tests only its own selection. Minutes are free on a public repository and wall clock is not, so paying for the build four times to quarter the wall clock is the trade worth making. fail-fast is off: with it, one failing shard cancels the others, and a cancelled job cannot be told apart from one killed by its cap. The completeness gate, the HTML report and the Codecov upload move to a merge job, because a shard's tracefile is legitimately partial and no single shard can answer whether the report still describes the whole workspace. lcov -a sums execution counts for matching files, so a line covered by only one shard is covered in the merged report - verified on two tracefiles where a line uncovered in one and covered in the other merges to covered, and the totals sum. The cap stays at 90 for now. The worst shard should land near 45, but the first run starts from a cold per-shard ccache, so the number to lower it by is one to read from the margin the test step now records, not one to guess.
Welcome to Codecov 🎉Once you merge this PR into your default branch, you're all set! Codecov will compare coverage reports and display results in all future pull requests. ℹ️ You can also turn on project coverage checks and project coverage reporting on Pull Request comment Thanks for integrating Codecov - We've got you covered ☂️ |
The codecov action's dependency check fails the step outright when curl is absent, rather than skipping the upload, so the merge job died at the last step with every tracefile already merged and the completeness gate already green.
…signal A node killed by SIGSEGV during startup left nothing to read: no output, and no core file, because a container cannot set the host's core_pattern. An exit status alone cannot separate a defect in this repository from one below it, in rclcpp, rmw or the DDS implementation. run_demo_node() now installs a handler for SIGSEGV, SIGBUS and SIGABRT that writes the frames to stderr behind a MEDKIT-CRASH marker and then lets the original signal terminate the process, so the exit status a test asserts on is unchanged. Sanitizer builds keep their own handler: this one stands down there, and the tests assert that case too rather than going quiet under it. The launch-domain probe child spun under a bare rclpy.spin, so CPython re-raised SIGINT and the process died from the signal with its participant never destroyed. A participant that is not destroyed strands its shared-memory segments, measured at roughly 0.5 MB each against the 64 MB a container gets for the whole job. The child now answers both SIGINT and SIGTERM through the same path and shuts down, and the test asserts an exit status of zero instead of accepting any non-crash. CI records /dev/shm and the installed rmw packages after the test step, because neither is recoverable once a run has finished.
**The overrun guard reported false overruns on short caps.** It treated "within a minute of the cap" as an overrun, so a one-minute cap flagged a two-second run, and at a five-minute cap the 80% warning and the overrun error collided on the same second. The runner kills a step AT its cap and this check runs afterwards, so the test is simply elapsed at or past the cap - no subtraction. Its inputs are now validated too: a zero cap divided by zero while still printing an overrun, and a start from another clock read as an enormous one. Verified across nine bands, from a two-second run to a cap reached exactly. **The cap was written in two places.** The step's timeout-minutes and the guard's argument could drift, and either direction is silent: raise the timeout and a long-but-legal run reports an overrun, lower it and a real one reports as an ordinary test failure. Both now read one job-level value. **A failing step cost the environment evidence.** If anything before the tests failed, the recorded start was missing, the guard died on its usage error, and the /dev/shm and middleware census below it never ran. The guard is now skipped with a notice when there is no start, and the census always runs. **A failed shard suppressed the whole merge.** With `needs: coverage` alone, one broken shard skipped the merged report, the completeness gate and the upload - losing the diagnostic exactly when a shard broke. The merge job now always runs, reports what it could merge, refuses to publish a partial report as the workspace figure, and fails on the shard's behalf. **Four ccache entries per commit.** Every shard builds the same workspace with the same flags, so per-shard keys quadrupled the cache against a 10 GB repository limit and would evict the entries keeping builds warm. One key for the matrix. **The crash handler could hang instead of reporting.** Unwinding from a signal handler is not async-signal-safe: backtrace() may need the loader or an allocator lock, and a fault that interrupts either deadlocks the handler - in exactly the startup paths this exists to diagnose, turning a crash into a test that hangs to its timeout with nothing to read. It now sets a five-second alarm first, so a wedged unwinder becomes a dead process with whatever was already written. The handler also blocks the other fatal signals while it runs, because SA_RESETHAND resets only the signal that fired and two threads taking different signals would interleave their reports through one static buffer. strlen is gone from the handler; the lengths come from the literals' types. **Two tests proved less than they claimed.** The frame assertion required a frame with no symbol name, so on a build that exports symbols it was satisfied only by libc's frames while ours went unchecked - measured: 2 matching lines instead of 7. And the repeated-install test installed twice in the parent, while the helper installs again inside the dying child, so it discriminated nothing. Both fixed, and the crash tests still pass on jazzy at -O2, with -rdynamic, under ASan, and in a lyrical container.
…ctors **The missing-result detector never fired.** `missing_result` is not a filename: ament writes it as the `name` attribute of a `<testcase>` inside the ordinary xunit file, and writes that file before running the command, so it is neither absent nor empty. `find -name '*.missing_result'` therefore returned zero always. Measured across five build trees: zero files named that, while one tree carried two genuine missing results in its XML. The guard now greps the XML, and on that tree reports both - the warning branch had been unreachable since it was written. **Four of the six crash cases never crashed under the sanitizer job.** That job builds `asan,ubsan`, and UBSan diagnoses a store through a null pointer before the store happens, so no signal was raised and the "no marker" assertions passed because nothing faulted rather than because the handler stood down. The crash now targets a non-null unmapped address, which UBSan has nothing to say about. **The sanitizer assertions took their oracle from the code under test.** Both the branch selector and the installer read one macro, so a regression in the detection flipped both and the test stayed green either way. The sanitizer branch now asserts the sanitizer's OWN report is present alongside our marker's absence, which does not depend on that macro. The SIGABRT case keeps the weaker assertion on purpose: a sanitizer does not take SIGABRT by default, so there is no report to require. **The frame assertion no longer proved anything about our frames.** Widening it for symbolised frames left it satisfiable by a single libc line. It is now anchored on this binary's own path, read from /proc/self/exe rather than written down. **The stated reason for the launch-test change was false.** Measured on jazzy, /dev/shm bytes before and after: a bare `rclpy.spin` killed by SIGINT returns to baseline exactly, because CPython finalises the interpreter before re-raising and the participant is destroyed on the way out. Only SIGKILL strands segments, which no handler in that child can affect. The tighter exit status still stands on its own - a fixture that dies from its shutdown signal reports the same status whether it shut down or was cut off - but the shared-memory rationale was wrong and is gone. **The sweep's refusal missed the two commands that run the suite.** `colcon test` and `launch_test` both went unmatched, so a sweep could run in the middle of another worktree's integration run. Verified per command line, with the patterns kept out of the checking harness's own argv - three earlier attempts reported every case as a hit because pgrep was matching the harness. Also: a corrupt tracefile no longer merges silently, the census no longer pipes through `head` under pipefail, shard artifacts live seven days rather than one, a shard whose package name rots now fails instead of testing nothing, and `ament_cmake_gmock` is declared where it is used.
**The workflow would not start.** `timeout-minutes: ${{ env.TEST_STEP_CAP_MINUTES }}`
fails validation before any step runs - an expression yields a string and that key
demands a number, so the run died with "The template is not valid ... Unexpected
value '45'". `fromJSON` returns a number and is the documented way to spend an
expression on a numeric key. The single source for the cap was worth having; the
form it was written in was not checkable locally, and it took a red run to find
out.
**The completeness guard died silently on every healthy run.** The missing-result
detector was changed to grep the XML - correct, since `missing_result` is a
testcase name and never a filename - but `grep` exits 1 when it matches nothing,
which is the healthy case, and under `set -e` with `pipefail` that killed the
script before it printed anything. Measured: on a tree with no missing results it
exited 1 with no output; on a tree with two it worked. So the guard failed exactly
the runs it had nothing to say about, which is the worst possible polarity for a
diagnostic. `|| true` now sits inside the braces, where the pipeline can see it.
The lyrical job that surfaced both ran 5382 tests with zero failures. Nothing in
the suite was broken; the job was red because of the two lines above.
4ba9ad3 to
205d952
Compare
| # the same installed code and put it back in the report. Name-aware, | ||
| # because a shard selecting two packages still produces results when | ||
| # only one of the names rotted. | ||
| for pkg in ${{ matrix.select }}; do |
There was a problem hiding this comment.
This loop walks every word of matrix.select, and for the rest shard that is --packages-skip ros2_medkit_opcua ros2_medkit_integration_tests .... First non-flag word is ros2_medkit_opcua, which this job never builds, so the find is empty and the step exits 1 (the four skipped packages fail the same way: built, not tested here). This landed in the second-pass commit after the green sharded run in the description, and PR CI never runs this job, so the first push to main after merge fails coverage (rest) and the merge job fails with it.
Run the loop only when the flag is --packages-select, or add a separate check: matrix key with the packages to verify.
| # handler that is merely installed proves nothing about what a crash leaves | ||
| # behind. ROS-free: it creates no node, only signals. | ||
| find_package(ament_cmake_gmock REQUIRED) | ||
| medkit_add_gmock(test_crash_backtrace test/test_crash_backtrace.cpp) |
There was a problem hiding this comment.
The sanitizer stand-down is never exercised by CI: sanitizers are opt-in per package via include(ROS2MedkitSanitizers) (seven packages do it), and this package includes only Compat/Linting/Warnings at lines 11-13. So -DSANITIZER=asan,ubsan/tsan in quality.yml is an unused variable here, __SANITIZE_ADDRESS__ is never defined, the handler stays active in the ASan/TSan jobs and every else branch of the new test is dead. Either include the module (and accept instrumented demo nodes) or drop the "tests assert that case too" claim.
| # report still covers every package the source tree says holds production | ||
| # C++. Sharding makes this stricter, not weaker: a shard that silently | ||
| # tested nothing now shows up as a package missing from the merge. | ||
| - name: Verify every C++ package reached the coverage report |
There was a problem hiding this comment.
No if: always() here. When a shard fails it uploads no tracefile, this gate exits 1 on the missing package, and both the HTML upload and "Fail if any shard did not succeed" below are skipped. The run then says "package X missing" instead of "shard Y failed" and the partial HTML is gone, which is the opposite of the comment at 644-647. if: always() on those two steps fixes it.
| # than shut down never gets its segments back. Measured: 15 live | ||
| # participants take 9.6 MB, and 125 killed ones fill 63 MB. 1g is tmpfs, so | ||
| # it costs only what is used, against 16 GB of runner memory. | ||
| options: --shm-size=1g |
There was a problem hiding this comment.
This job gets the 1g shm but not the census, and neither jazzy-test nor graph-watchdog (45 min step cap on a 24 min suite) gets the record/guard pair build-and-test got. A kill there still shows up as one missing_result test. Worth a small composite action (record + guard + census) used in all three.
| ::backtrace_symbols_fd(frames, depth, STDERR_FILENO); | ||
| write_literal(kCrashMarker); | ||
| write_literal(" end\n"); | ||
| } |
There was a problem hiding this comment.
Re-raise is implicit here: return and let the faulting instruction re-execute. That does not hold for a SIGSEGV/SIGBUS delivered by kill/raise/pthread_kill: the process resumes and the still-armed alarm(5) kills it 5 s later with SIGALRM (status 14, not 11), contrary to README line 96. Ending the handler with ::raise(signum) covers both cases and is async-signal-safe (default disposition is already back via SA_RESETHAND).
| struct sigaction action {}; | ||
| action.sa_handler = &detail::crash_handler; | ||
| // The handler writes into one static frame buffer, and SA_RESETHAND only | ||
| // resets the signal that fired. Without this, a second thread taking a |
There was a problem hiding this comment.
sa_mask only applies to the thread running the handler, so this does not prevent what the comment says. Thread A in SIGSEGV, thread B takes SIGBUS: B runs crash_handler concurrently, both write the same static frames[] and interleave stderr. A static std::atomic_flag (test_and_set is lock-free) with a one-line marker for the second entrant would actually do it.
| // would have without us. | ||
| // SA_ONSTACK puts the handler on the alternate stack above, which is what lets | ||
| // it run at all when the ordinary stack is the thing that overflowed. | ||
| action.sa_flags = SA_RESETHAND | SA_ONSTACK; |
There was a problem hiding this comment.
SA_RESETHAND | SA_ONSTACK is unsigned going into int sa_flags: -Wsign-conversion "changes value from 2281701376 to -2013265920", once per including TU (34 times in a build). Bits are right; static_cast<int>(SA_RESETHAND | SA_ONSTACK) silences it.
| char exe[PATH_MAX] = {}; | ||
| const ssize_t len = ::readlink("/proc/self/exe", exe, sizeof(exe) - 1); | ||
| const std::string self = len > 0 ? std::string(exe, static_cast<std::size_t>(len)) : std::string(); | ||
| return self + R"(\([^)]*\+0x[0-9a-fA-F]+\) ?\[0x[0-9a-fA-F]+\])"; |
There was a problem hiding this comment.
glibc prints the main executable as argv[0] (dl-addr.c uses _dl_argv[0] for the main map), not the realpath from /proc/self/exe. With a symlinked workspace path, or ./test_crash_backtrace run by hand, the frame line and this pattern differ and the test fails on a correct report. Anchoring on the basename test_crash_backtrace\( is enough.
|
|
||
| ### Crash reports | ||
|
|
||
| Every demo binary goes through `run_demo_node()` in |
There was a problem hiding this comment.
Not every one: demo_nodes/unresponsive_param_node.cpp:116 and demo_nodes/managed_lifecycle_node.cpp:64 have their own main and never call install_crash_backtrace(), so those two still die silently. Calling it first thing in both mains makes this sentence (and the CMake comment at 209) true.
| # demo_ covers the launch fixtures the documented demo workflow starts, which | ||
| # the earlier pattern missed entirely - a developer running only demo nodes got | ||
| # a sweep in the middle of live work. | ||
| if pgrep -f '[g]ateway_node|[f]ault_manager_node|[d]emo_|[c]test|[l]aunch_test|[c]olcon test' >/dev/null 2>&1; then |
There was a problem hiding this comment.
This pattern matches the caller: bash ./scripts/test.sh test_demo_lifecycle contains demo_, so the documented single-test presets always get "ROS processes are running" and never sweep (test.sh swallows the exit, so the only symptom is the misleading refusal). Filter $PPID/$$ out of the pgrep result, or match executable names with pgrep -x.
**The shard assertion would have failed main on the first push.** It walked every word of `matrix.select`, and the catch-all shard's is `--packages-skip ros2_medkit_opcua ...` - so the first name it checked was a package that job never builds. Coverage jobs do not run on pull requests, so this would have surfaced only after merge. The check now runs for `--packages-select` alone. **A failed shard hid its own cause.** The completeness gate and the HTML upload in the merge job had no `if: always()`, so a failing shard made the gate report a missing package and skipped both the report and the step that names the real reason. All three now run regardless. **The sanitizer stand-down is not tested, and the tests no longer claim it is.** Sanitizers are opt-in per package through `include(ROS2MedkitSanitizers)`; seven packages do it and this one does not, so `__SANITIZE_ADDRESS__` is never defined here and every `else` branch was unreachable. The stand-down stays in the header for the day this package opts in; the dead branches are gone. **`alarm(5)` changed the exit status it promised not to.** For a signal delivered by `raise`, `kill` or `pthread_kill` there is no faulting instruction to retry, so returning from the handler resumed the process and the armed alarm killed it five seconds later. Measured: `raise(SIGSEGV)` exited 142, not 139. The handler now ends with `::raise(signum)`, which covers both delivery paths, and the measurement is back to 139. **`sa_mask` cannot do what its comment claimed.** It blocks signals for the thread running the handler, so it does nothing about thread A in SIGSEGV while thread B takes SIGBUS - both would write one static frame buffer. An atomic flag now lets the first entrant report and the second say so in one line. **Two demo binaries died silently.** `unresponsive_param_node` and `managed_lifecycle_node` own their shutdown sequence and deliberately do not use `run_demo_node()`, so they never installed the handler. They install it themselves now, and the README sentence is true rather than nearly true. **`SA_RESETHAND | SA_ONSTACK` is unsigned going into an int field**, which `-Wsign-conversion` reports once per including translation unit. Cast. **The frame assertion was anchored on the wrong path.** glibc prints `argv[0]` for the main executable, not the realpath `/proc/self/exe` returns, so a symlinked workspace or a hand-run `./test_crash_backtrace` would have failed on a correct report. Anchored on the basename. **The sweep refused to run for its own caller.** `./scripts/test.sh test_demo_lifecycle` contains `demo_`, so every single-test preset got "ROS processes are running" and never swept, with `test.sh` swallowing the exit so the refusal was the only symptom. Our own process and our caller are excluded now. **The record-and-census pair lived in one job of three.** `jazzy-test` and `graph-watchdog` had the shm bump but no margin guard, so a kill there still showed up as a single `missing_result`. All three now share one composite action.
Pull Request
Summary
Everything here came out of one investigation: a lyrical job failed, and the failure was
unreadable. Four changes, each from a measurement.
A node that dies leaves no trace.
demo_brake_pressure_sensorwas killed by SIGSEGV1.155 s into a run, having printed nothing at all - no output, and no core file, because a
container cannot set the host's
core_pattern. The exit status alone cannot separate adefect here from one in rclcpp, rmw or the DDS implementation.
run_demo_node()nowinstalls a handler for SIGSEGV, SIGBUS and SIGABRT that writes the frames behind a
MEDKIT-CRASHmarker and then lets the original signal terminate the process, so the exitstatus a test asserts on is unchanged. Sanitizer builds keep their own handler: this one
stands down there, and the tests assert that case too rather than going quiet under it.
A step timeout reads as a test failure. A step killed by its cap is marked failed by the
runner, not cancelled, and the in-flight test leaves no result file;
colcon test-resultthen reports one erroring test named
<test>.xunit.missing_resultamong thousands thatnever ran. Over one month, 17 of 25 killed jobs died on a step cap, and every timeout in
this file has been raised at least once. A new step says so plainly and warns at 80% of the
cap. It detects the overrun by the clock, because a job cannot read its own step log.
Shared memory was unmeasured and stranded. Container jobs got Docker's default 64 MB of
/dev/shm. Fast DDS puts a 512 KB segment plus port files there per participant, measuredat ~0.65 MB, and a participant killed rather than shut down never gets them back: 15 live
participants take 9.6 MB, and 125 killed ones fill 63 MB of 64. Jobs now ask for 1 GB and
record what they used;
scripts/test.shreclaims stranded segments locally throughfastdds shm clean. The launch-domain probe child, which died from SIGINT with itsparticipant never destroyed, now shuts down on both SIGINT and SIGTERM, and its test
asserts an exit status of zero instead of accepting any non-crash.
The coverage job was twelve seconds from failing. 89m48s against a 90 minute cap on
2026-08-27, with four of its last five runs on main between 86 and 90 minutes, and a test
step that grew 166% in a month. The cause is one line:
build-and-testandjazzy-testboth skip
ros2_medkit_graph_watchdog, whose suite is 24 minutes, andcoverageskipsonly
ros2_medkit_opcua. It is now sharded four ways by measured test time per package,with a merge job carrying the completeness gate, the HTML report and the Codecov upload,
because a shard's tracefile is legitimately partial.
fail-fastis off deliberately: withit, one failing shard cancels the others, and a cancelled job cannot be told apart from one
killed by its cap.
Issue
No issue filed - this came out of investigating a CI failure rather than from a report.
Happy to open one if the history is worth having separately.
Type
Testing
The sharded coverage job only runs on push to main, so it could not execute before landing
there. Two temporary commits widened that condition, the job ran on this branch, and the
condition is restored - the net diff against main carries no temporary condition. Results
from run 33426859082, every job green:
--shm-sizeis accepted and takes effectshm 1.0G 2.1M 1022M 1% /dev/shm, 44 segments at the end of the suite - the first time this has been measured at allcoverage (integration/graph-watchdog/gateway/rest), including the folded-YAML catch-all shardmerging 4 tracefilesOK: all 15 checked C++ package(s) include ROS2MedkitCoverage and reached coverage.infotest step: 1573s elapsed of a 2700s cap (58%); results: 285 written, 0 empty, 0 missing_resultoutcome=successSharding loses no coverage. The last unsharded run on main measured 86.9% at 34537 of
39753 lines; the sharded run measures 86.9% at 34539 of 39753. Identical denominator, so
the same instrumented line universe.
Wall clock. Worst shard
graph-watchdog3046s, thenintegration2663s,gateway2041s,
rest1462s. Against 86-90 minutes serial and a 90 minute cap, the margin goes fromtwelve seconds to about 39 minutes. The cap stays at 90 here: those are cold-cache numbers,
and the figure to lower it by should come from a few runs of the margin line.
Verified outside CI:
-O2, 5/5 in a lyrical/resolutecontainer, and 5/5 under
-fsanitize=addresswhere the marker correctly never appears.rclpy.spinmakes it fail, so the assertion discriminates.lyrical container;
fastdds shm cleanreturned 5.23 MB of it.lcov -a: checked on two tracefiles where a line uncovered in one and covered in theother merges to covered, with counts summing.
Two of these tests were wrong first, which is worth recording. The crash test asserted a
frame format that only matches one glibc release - resolute writes
") [0x"where noblewrites
")[0x"- and it was written with avolatilequalifier on the wrong side of thepointer, so the compiler deleted the store at
-O2and the process did not crash at all.The completeness guard first compared registered tests against result files and reported
missing results on a run where everything passed, because
test_dds_domain_allocationisregistered in every package and writes no xunit. All three were caught by running the
tests, not by reading them.
Checklist