[test/DNM] ci: try to reproduce the conmon job hang - #677
Closed
kolyshkin wants to merge 18 commits into
Closed
Conversation
$CONMON_PID_FILE is a single path per test, but a test may start more than one conmon (one for the container and one for an --exec), in which case the second one overwrites the first one's pidfile, and there is no way to tell what the first conmon's pid was. Have start_conmon_with_default_args use a pidfile of its own for every conmon it starts, and expose the pid of the one just started as $CONMON_PID, so that tests do not have to deal with the path at all. $CONMON_PID_FILE stays for the tests that run conmon directly. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
The test waits for the container to reach the "stopped" state and then
reads the container log, expecting the container output to be there.
This is racy: the container being stopped does not mean conmon is done
writing the log, and the test can (and in CI does) read an empty log:
not ok 92 attach: container finishes immediately without --stdin
# (from function `bail-now' in file conmon/test/test_helper.bash, line 519,
# from function `assert' in file conmon/test/test_helper.bash, line 635,
# in test file conmon/test/07-attach.bats, line 37)
# `assert "${output}" =~ "Container stopped!" "'Container stopped!' found in the log"' failed
#| FAIL: 'Container stopped!' found in the log
#| expected: =~ Container stopped\!
#| actual: ''
conmon having exited does mean the log is complete, so add a helper
waiting for that, and use it in the affected test.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
The same pattern as fixed by the previous commit -- wait for the
container to be stopped, then read a conmon log -- is used in a few more
places. These have not been seen to fail, but the race is the same, so
convert them, too.
Where a test starts more than one conmon, $CONMON_PID is saved right
after the start, and only the conmon(s) owning the log(s) actually read
are waited for.
The most common instance of the pattern is run_conmon_with_default_args
itself, so the barrier goes right into it, covering all of its callers.
This one has been seen to fail:
not ok 45 ctr logs: k8s partial message
# `assert "${output}" =~ "stdout P"' failed
#| expected: =~ stdout P
#| actual: ''
in the coverage job, where conmon is built with --coverage and is thus
slow enough to lose the race more often.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The intent was to wait for conmon to exit, but the argument is the name of the pidfile rather than the pid it contains, so bash rightfully complains wait: `/tmp/.../conmon-pidfile': not a pid or valid job spec which the test then discards along with the rest of the errors. In other words, this waits for nothing at all. Use wait_for_conmon_exit instead. The sleep above it is left as is: it is what gives the sync pipe reader time to write out what conmon sent it. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
The GitHub Actions default job timeout is 6 hours, so a job that hangs squats a runner for the rest of the day instead of failing. This is not hypothetical: today both the setup step (apt, five git clones, wget) and the test step (which starts with a podman pull) have been seen hanging on what looks like stalled network I/O, and one such job was still sitting there 2.5 hours later. Give the jobs timeouts a few times their normal runtime, so a hang fails in minutes rather than hours: the conmon job normally takes about 4 minutes and the cri-o one about 40. Note static.yml already sets one (360, the default), left alone here. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This script clones five repositories, downloads a tarball and a repo key, and runs apt, and not one of those has a usable timeout by default: - git has none at all; - curl has no total timeout and no retries, only a 300 second connect timeout, so a connection that stalls mid-transfer hangs forever; - wget does have a 900 second read timeout, but also 20 tries by default, which adds up to hours; - apt retries nothing by default. This is not theoretical: this step has been seen hanging for 49 minutes, and was still going when the job was cancelled. Give each of them a bound. The git ones get GIT_HTTP_LOW_SPEED_LIMIT and GIT_HTTP_LOW_SPEED_TIME, which abort a connection that transfers less than 1 KiB/s for a minute, and cover all five clones at once. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
setup_suite pulls the image the test rootfs is made of. It is the only network access in the whole suite, podman has no timeout of its own, and a hang there stops the suite before a single test runs -- with no output at all, since bats shows setup_suite's output only once it completes. The test step has been seen hanging for 35 minutes with exactly that signature. Bound the pull, and say in the failure message that a timeout is a possibility. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Five seconds for a container to change state is not much when the CI runner is loaded, and it has been observed to be too little: not ok 51 runtime: container execution with multiple log drivers not ok 101 ctrl: resize the terminal, negative width and height #| FAIL: timed out waiting for 'stopped' from conmon-test-... The helper polls, so a longer limit costs nothing when things are well -- it returns as soon as the state is reached -- and only comes into play where the alternative is a spurious failure. Make it 30 seconds. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
"integration: exec exit codes work correctly" runs six podman commands, of which exactly one -- the initial probe -- has a timeout. The rest can hang forever, and one of them did: ok 67 exec requires proper arguments <17 minutes of nothing> The job has exceeded the maximum execution time of 20m0s Test 68 is this one. Nothing is printed while it hangs, because bats shows a test's output only once the test ends, so the suite just goes quiet -- and before the job timeout added earlier in this series, quiet for up to six hours. The container creation is the likeliest culprit: container_id=$(podman --conmon $conmon_path run -dt ... sleep 30) a command substitution waits for stdout to be closed, and conmon is started by podman with that very stdout -- this test runs the freshly built conmon on purpose, so it is exactly the thing that may hold it open. Wrap every podman invocation here in a timeout. A hang now fails the test in a minute, with the rest of the suite still running. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
kolyshkin
force-pushed
the
test-conmon-hang-repro
branch
from
August 19, 2026 06:20
83b4add to
0f04698
Compare
The Acquire::*::Timeout options added in the previous commit turned out not to be enough. They apply to individual requests of the acquisition method, while the frontend will happily wait for that method forever, which is exactly what happened: 04:56:18 + sudo apt -o Acquire::Retries=3 ... update 04:57:27 Get:5 https://archive.ubuntu.com/ubuntu noble-security InRelease [126 kB] <19 minutes of nothing> 05:16:30 The job has exceeded the maximum execution time of 20m0s Five of ten parallel jobs died that way in one experiment, all of them after apt gave up on the azure.archive.ubuntu.com mirror (a screenful of "Ign:") and fell back to archive.ubuntu.com. Bound the whole command instead, and retry it a couple of times, since a stalled mirror is a transient thing. Also stop waiting on the dpkg lock, which a previous timed out run may well have left behind, and switch to apt-get, whose CLI is the one meant for scripts. Three minutes per attempt: the mirror has since stalled again, and three attempts have to fit in the job timeout with the tests still to run -- at five minutes each they took a quarter of an hour to reach a verdict, which is most of the twenty minutes the job gets. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
start_conmon_with_default_args swallowed a failing conmon:
run timeout 10s "$CONMON_BINARY" ... "${extra_args[@]}"
if [ "$status" -ne 0 ]; then
return
fi
so a test whose conmon died, or was killed by that 10 second timeout,
carried on regardless and failed thirty seconds later in
wait_for_runtime_status, reporting that the container never reached the
expected state -- while the actual error, sitting right there in $output,
was thrown away. Debugging that from a CI log is guesswork.
Die instead, with the status and the output. The behaviour was load
bearing for eight tests which use the helper to check that conmon
rejects what it should reject, so give them a helper that says as much:
run_conmon_expecting_failure, which runs conmon and leaves $status and
$output alone.
While at it, factor the conmon invocation the two share into _run_conmon,
rather than having the argument list twice.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Every conmon a test starts was told to write the container's pid to the same $PID_FILE, so the runtimes of a container and of an exec into it were handed the same --pid-file. runc writes that file by creating ".<name>" with O_EXCL and renaming it afterwards, which makes a shared path a race waiting to happen -- and it happens: <ntrace>: calling runtime args: /usr/bin/runc create --pid-file /tmp/conmon-test-oXpcPe/pidfile <ctr> <ntrace>: calling runtime args: /usr/bin/runc exec --pid-file /tmp/conmon-test-oXpcPe/pidfile --process ... --detach <ctr> <nwarn>: runtime stderr: level=error msg="exec failed: open /tmp/conmon-test-oXpcPe/.pidfile: file exists" <nwarn>: Failed to read pidfile: Failed to open file ".../pidfile": No such file or directory The exec then never runs, the container waits for it forever, and the test fails thirty seconds later saying the container did not stop -- a symptom bearing no resemblance to the cause. This accounted for a dozen failures across the parallel runs used to chase it, in every job that hit it. The window is between runc saving the container state, which is what "runc state" starts reporting as "created", and runc writing the pid file a moment later: the test sees "created" and starts the exec while the create's temporary file is still there. Give each conmon its own, exposed as $CONTAINER_PIDFILE, the way $CONMON_PIDFILE already is. Both tests that read the pid want the last conmon started -- the only one in 04-runtime, the exec one in 08-exec -- which is exactly what they now get, rather than relying on the exec's runtime having clobbered the container's file. $PID_FILE stays for the tests that run conmon directly, where there is only ever one conmon and nothing to collide with. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Trying to reproduce the hang seen twice today, where the test suite goes quiet after "ok 67" and stays that way until the job times out. It does not reproduce locally at all, and in CI it happens perhaps one run in several, so: ten parallel attempts of the conmon job, fail-fast off, and nothing else running to compete for runners (the cri-o job is dropped here, coverage and validate are switched to workflow_dispatch). Note the previous commit bounds every podman call in the test that is the prime suspect, so a recurrence should now show up as not ok 68 integration: exec exit codes work correctly rather than as a wedged job. Either outcome is informative: the former confirms the suspect, the latter means the hang is somewhere else. The test also dumps the surviving conmon/podman processes on the way out. Not for merge. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The first round of this experiment reproduced the hang in 2 of 10 attempts, and moved the suspect: ok 67 exec requires proper arguments not ok 68 integration: exec exit codes work correctly # (in test file test/06-exec-exit-status.bats, line 83) # FAIL: true command should succeed with 62.4 and 61.7 seconds between the two lines, i.e. exactly the "timeout 60" firing. So it is not the container creation that hangs, as guessed, but the very first podman --conmon $conmon_path exec "$container_id" true The container is created fine, and everything after the hung exec runs normally. Collect what a hang leaves behind, before tearing the container down: the process list with wchan and elapsed time, each conmon's State, its kernel stack and its open fds, podman ps, and conmon's journal. Then retry the exec with podman debug logs, to see whether the container is wedged for good or only that one exec was. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Two attempts reproduced the hang with identical process trees: 31832 PPID=1 S do_wait 60s bin/conmon --api-version 1 -c d2ebb658... -u d2ebb658... 31836 PPID=31832 Sl futex_do_wait 60s /usr/local/bin/podman ... --exit-command-arg container --exit-command-arg cleanup conmon is in wait4() on its child, which is the "podman container cleanup" exit command podman itself asked conmon to run, and that child is deadlocked in a futex. conmon holds nothing -- its fds are the three standard ones, all on /dev/null -- so the bug is inside podman. Get the Go side of it. SIGQUIT is not an option: the cleanup process inherits conmon's fds, so its stderr is /dev/null and the goroutine dump would go nowhere. Attach gdb instead, and take the kernel stack of every thread while at it. Also dump /proc/locks, a cleanup deadlock being a plausible candidate for a database or storage lock. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The hang is a deadlock inside "podman container cleanup", and there are two podman builds on the runner: the image's own static bundle in /usr/local/bin (5.8.4, built without the systemd tag -- see actions/runner-images#14569, which reports health checks silently not working for the same reason) and Ubuntu's package in /usr/bin (4.9.3), which our install_packages pulls in. /usr/local/bin comes first in PATH, including sudo's secure_path, so the bundle is what runs today. Add a second matrix dimension that removes the bundle, leaving Ubuntu's podman. Twenty jobs, ten of each. If the hang only ever shows up with the bundle, that is the answer, and the fix is to drop it in remove_runtimes along with the bundled runc and crun. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The second failure mode -- "class B" -- is a container that never reaches the stopped state: not ok 94 exec: simple --exec --exec-process-spec from function `wait_for_runtime_status' in test/test_helper.bash `wait_for_runtime_status "$CTR_ID" stopped' failed It hits both podman arms of the matrix, it is always an exec test (both 08-exec.bats and the exec that 10-ctrl.bats does), and thirty seconds of patience does not help, so it is a wedge rather than slowness. In the last run it also came in a batch of eleven, in the two jobs that also hit the podman cleanup deadlock -- and never in the tests running before it. We know nothing else about it, because that path just says "timed out". Move dump_hang_state to the shared helper and call it there, with the container id, so the dump also shows the runtime's view of the container and its init process. What this should settle: whether a wedged podman from test 68 is still sitting there when this happens (making it a knock-on effect of the cleanup deadlock), or whether it is only conmon and the runtime (making it a bug of its own, and one reproducible without podman in the picture). The dump is capped at three per suite: a wedged run fails a dozen tests in a row, gdb alone is allowed a minute, and the first dumps are the interesting ones anyway. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The "class B" failures come down to this sequence, from the journal of an exec conmon in CI: <ntrace>: calling runtime args: /usr/bin/runc exec --pid-file .../pidfile --process .../process.json --detach <ctr> <nwarn>: Failed to read pidfile: Failed to open file ".../pidfile": No such file or directory runc exec failed, so no pidfile was written, and conmon warned and exited 1 -- from the daemonized child, long after the parent returned 0, so the caller sees nothing wrong. The container then waits forever for what the exec was supposed to do, and the test fails half a minute later saying the container never stopped, with the actual error nowhere to be seen. Why runc exec failed we do not know, and cannot know from here: for exec, the branch that reads the runtime's stderr is skipped, since a non-zero runtime exit there is normally the exec'd command's own exit status. A missing pidfile, though, means the process was never started at all, so at that point the runtime's stderr is exactly what we want. Read it (with the pipe made non-blocking, so that nothing hangs when there is nothing to say) and log it, along with the runtime's exit status. This is for the investigation. The real bug -- conmon exiting silently without reporting the failure on the sync pipe -- wants a separate fix. Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
kolyshkin
force-pushed
the
test-conmon-hang-repro
branch
from
August 19, 2026 07:13
fda7abc to
90bd3df
Compare
Collaborator
Author
|
Enough statistics collected: five runs of the 10x2 matrix, ~14 hangs of the podman cleanup deadlock with the bundled podman against 0 without it, and the exec pidfile race identified and fixed in #673 (0 occurrences in the last 20 jobs). The findings live in #673 (test fixes and CI containment) and #679 (removing the bundled podman); the deadlock itself is written up for whoever takes it upstream. The branch stays around in case the experiment needs re-running. |
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
1 participant
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.
Do not merge. This is #673 plus one throwaway commit on top, to hunt a hang.
What we are chasing
Twice today the
conmonjob went quiet mid-suite and stayed that way until it was killed:Test 68 is
integration: exec exit codes work correctlyintest/06-exec-exit-status.bats. It runs six podman commands, and until #673 exactly one of them -- the initial probe -- had a timeout. The prime suspect is the container creation:container_id=$(podman --conmon $conmon_path run -dt "$UBI10_MICRO_IMAGE" sleep 30)A command substitution waits for stdout to be closed, and conmon is started by podman with that very stdout. This test deliberately runs the freshly built conmon, so it is exactly the thing that might hold it open.
Nothing is printed while it hangs, because bats shows a test's output only once the test ends -- so from the outside the suite simply goes silent.
What this branch does
conmonjob ten times in parallel (matrix.attempt,fail-fast: false), since it does not reproduce locally at all and in CI hits maybe one run in several;cri-ojob and switchescoverageandvalidatetoworkflow_dispatch, so nothing else competes for runners;timeout-minutes: 20from test: fix some conmon test flakes/races #673, so a wedged attempt dies in 20 minutes rather than 6 hours;conmon/podman/runc/crunprocesses andpodman ps -aif the container creation times out.Reading the results
Both outcomes are useful:
not ok 68 integration: exec exit codes work correctlyin some attempts -> the suspect is confirmed, and the process dump says who was still alive;🤖 Generated with Claude Code