Fix foreground stdio deadlock when the internal logging process stops consuming - #5151
Fix foreground stdio deadlock when the internal logging process stops consuming#5151gsaddict91 wants to merge 1 commit into
Conversation
… consuming `nerdctl run` in the foreground tees container stdout/stderr through a 64 KiB pipe to a forked logging process (`nerdctl _NERDCTL_INTERNAL_LOGGING`) on the same goroutine that drains the container's stdio FIFOs. If that logging process ever stopped consuming (killed, crashed, OOM), the tee write blocked forever: nerdctl kept its own copies of the logger pipe read ends open, so the kernel never delivered EPIPE. The blocked goroutine stopped draining the stdout FIFO, the container's writer blocked behind the full pipe at exactly pipe-capacity-plus-one-chunk bytes, the container never exited, `nerdctl run` never returned, and `nerdctl rm -f` on the wedged container hung as well. Four changes, from the analysis in containerd#5137: - Close the parent's copies of the logger pipe read ends once the logging process has started (the equivalent of containerd's binaryIO.CloseAfterStart), so that logger death turns into EPIPE on the tee instead of an eternal pipe-buffer block. - Make the logger leg of the stdio tee best-effort: on the first failed write, warn and stop writing to the logger, but keep streaming to the attached stdout/stderr. Closing the read ends alone is not enough: the EPIPE would error the io.MultiWriter, abort the io.CopyBuffer that drains the container's stdio FIFO, and the container would still wedge on the undrained FIFO chain behind it. With both changes the attach and the container survive logger death; the log file is what goes incomplete (with a warning on nerdctl's stderr). - In the logging process, do not treat an errored delivery on the task wait channel as a container exit. containerd's client sends Wait RPC failures through the same channel as a synthetic ExitStatus; cancelling the stdio readers on such a delivery silently stopped all logging while the container was still running - and, before the changes above, wedged the foreground attach permanently. Re-arm the wait instead, and close each containerd client once its wait delivers so re-arming does not accumulate open clients. - Fail IO setup when a binary-v2 logging binary exits before signalling readiness (mirroring containerd's n == 0 check); plain binary:// keeps EOF-as-ready for backward compatibility with third-party logging binaries. Fixes containerd#5137 Signed-off-by: An Lu <an.lu.91@googlemail.com>
925e996 to
6bf8252
Compare
|
Tested this on the same box/setup as my earlier repro (nerdctl 2.3.5 base, containerd 2.3.3, runc 1.5.1, rootless). Built from this branch and reran my exact reproduction (8 KiB chunks with a 20ms delay, killing
Also ran Nice diagnosis catching that closing the read ends alone wasn't sufficient, that's a subtle second-order effect (EPIPE killing the MultiWriter and aborting the FIFO drain) that's easy to miss. This one's solid from where I'm standing. |
|
A note on CI for reviewers: the initial The three remaining red jobs appear to be pre-existing flakes unrelated to this change:
I can't re-run the failed jobs from an outside fork — happy to rebase/re-push if a maintainer prefers a fresh run. |
Fixes #5137.
nerdctl runin the foreground tees container stdout/stderr through a 64 KiB pipe to the forked_NERDCTL_INTERNAL_LOGGINGprocess, on the same goroutine that drains the container's stdio FIFOs. If the logging process stops consuming for any reason, the tee write blocks forever — nerdctl keeps its own copies of the logger pipe read ends open, so the kernel never raises EPIPE — and the whole chain deadlocks: output freezes at pipe-capacity + one writer chunk, the container blocks on a full pipe and never exits,nerdctl runnever returns, andnerdctl rm -fon the wedged container hangs too. Full analysis in #5137 (comment).Changes
Close the parent's copies of the logger pipe read ends after the logging process starts (
pkg/cioutil/container_io.go) — the equivalent of containerd'sbinaryIO.CloseAfterStart. Logger death now surfaces as EPIPE instead of an eternal block. The pipe ends are wrapped in idempotent closers so the success path and the error-path cleanup can both close them safely.Make the logger leg of the stdio tee best-effort (
bestEffortWriterinpkg/cioutil/container_io.go). While implementing (1) I found it is necessary but not sufficient: with the read ends closed, killing the logger indeed produced EPIPE —/procshowed the read ends gone and the stdout copy goroutine exited — but the run still wedged, because the EPIPE errored theio.MultiWriter, which aborted theio.CopyBufferdraining the container's stdout FIFO, and the container then blocked on the undrained FIFO chain. So the tee now warns once and stops writing to the logger on the first failed write, while continuing to stream to the attached stdout/stderr. The attach and the container survive logger death; the log file is what goes incomplete. (This is the "attach shouldn't be gated on a best-effort logging process" point from the issue — it turned out to be required, not optional.)Don't treat an errored wait-channel delivery as a container exit (
pkg/logging/logging.go). containerd's client sends Wait RPC failures through the exit channel as a syntheticExitStatus; the logger's bare<-exitChtreated that as an exit, cancelled its readers, and silently stopped all logging while the container was still running — the suspected initiator of the original Kata-environment wedge. The logger now checksstatus.Error()and re-arms the wait (1s delay, aborting on SIGTERM).getContainerWaitalso closes each containerd client once its wait delivers, so re-arming doesn't accumulate open clients.Fail IO setup when a
binary-v2logging binary exits before signalling readiness, mirroring containerd'sn == 0check. Plainbinary://keeps EOF-as-ready for backward compatibility with third-party logging binaries (nerdctl's own internal logger URI isbinary://, and with (1)+(2) a logger that dies beforeready()now degrades gracefully instead of wedging).Verification
Unit tests (new, both fail on
main, pass with this PR):TestLoggingProcessAdapterWaitError— feeds the adapter an erroredExitStatusfollowed by a real exit; asserts output produced after the errored delivery is still logged, the wait is re-armed, and the real exit still terminates the logger. Onmainit fails at "logger did not re-arm the container wait".TestBestEffortWriter/TestBestEffortWriterClosedPipe— the tee leg reports full writes and abandons the underlying writer after the first failure, including real EPIPE on a closedos.Pipe.End-to-end A/B (privileged Linux container: containerd v2.3.3, runc 1.4.3, linux/arm64, busybox; the no-Kata reproducer from the issue — container writes 8 MiB in 8 KiB chunks with a 20 ms sleep,
killthe_NERDCTL_INTERNAL_LOGGINGprocess mid-stream):mainnerdctl runnerdctl rm -f--rmcompleted)Same result for SIGTERM and SIGKILL of the logger. Healthy-path controls on the patched build: untouched logger streams the full 8 MiB with exit 0 and no warning;
nerdctl logsshows the expected output afterwards.The runtime-side half of the original report (kata runtime-rs holding its own FIFO read end and gating exit reporting on the stdio copy tasks) is independent and tracked in kata-containers/kata-containers#13676.