Skip to content

Fix foreground stdio deadlock when the internal logging process stops consuming - #5151

Open
gsaddict91 wants to merge 1 commit into
containerd:mainfrom
gsaddict91:fix-logger-pipe-deadlock
Open

Fix foreground stdio deadlock when the internal logging process stops consuming#5151
gsaddict91 wants to merge 1 commit into
containerd:mainfrom
gsaddict91:fix-logger-pipe-deadlock

Conversation

@gsaddict91

Copy link
Copy Markdown

Fixes #5137.

nerdctl run in the foreground tees container stdout/stderr through a 64 KiB pipe to the forked _NERDCTL_INTERNAL_LOGGING process, 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 run never returns, and nerdctl rm -f on the wedged container hangs too. Full analysis in #5137 (comment).

Changes

  1. 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's binaryIO.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.

  2. Make the logger leg of the stdio tee best-effort (bestEffortWriter in pkg/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 — /proc showed the read ends gone and the stdout copy goroutine exited — but the run still wedged, because the EPIPE errored the io.MultiWriter, which aborted the io.CopyBuffer draining 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.)

  3. 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 synthetic ExitStatus; the logger's bare <-exitCh treated 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 checks status.Error() and re-arms the wait (1s delay, aborting on SIGTERM). getContainerWait also closes each containerd client once its wait delivers, so re-arming doesn't accumulate open clients.

  4. 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 (nerdctl's own internal logger URI is binary://, and with (1)+(2) a logger that dies before ready() now degrades gracefully instead of wedging).

Verification

Unit tests (new, both fail on main, pass with this PR):

  • TestLoggingProcessAdapterWaitError — feeds the adapter an errored ExitStatus followed 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. On main it 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 closed os.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, kill the _NERDCTL_INTERNAL_LOGGING process mid-stream):

unpatched main this PR
output delivered frozen mid-stream, never advances 8,388,608 / 8,388,608 bytes
nerdctl run never returns (>45 s, killed manually) returns, exit 0
nerdctl rm -f hangs (10 s timeout) n/a (--rm completed)
leaked containers 1 0

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 logs shows 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.

… 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>
@ogulcanaydogan

Copy link
Copy Markdown
Contributor

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 _NERDCTL_INTERNAL_LOGGING mid-stream):

  • SIGTERM on the logger: full 8 MiB delivered, nerdctl run exits cleanly, no leftover container.
  • SIGKILL on the logger: same result, full 8 MiB, clean exit.

Also ran go vet and go test -v on both pkg/cioutil and pkg/logging, all green, including your new TestLoggingProcessAdapterWaitError and the best-effort-writer tests. gofmt -l clean too.

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.

@gsaddict91

Copy link
Copy Markdown
Author

A note on CI for reviewers: the initial unit / windows-2025 failure was real — my new TestLoggingProcessAdapterWaitError relied on cancelreader.Cancel() for teardown, which cannot cancel a blocked pipe read on Windows. Fixed (the test now ends its streams via EOF) and that job is green.

The three remaining red jobs appear to be pre-existing flakes unrelated to this change:

  • in-host / nerdctl.gomodjail rootless linuxTestRunRmTime (12.6s vs 3s deadline): the identical failure (13.79s, same assertion) occurred on run 32358304695 for a PR that only adds a DCT flag and doesn't touch logging. I also verified locally that run --rm <img> true completes in ~0.1s with this branch, same as main.
  • in-host / windowsTestNetworkInspectWithContainers: the exact same test failed on a main-branch push, run 32338807591. This PR's logger-tee code is behind a runtime.GOOS != "windows" guard and doesn't touch network inspect.
  • in-host / rootful linux (old ubuntu) (ctd: v1.7.34)TestIPFSCompNoBuild: listed as a known recurring failure in the CI tracking issue [CI]: Tracking status #3577 (suspected snapshotter issue).

I can't re-run the failed jobs from an outside fork — happy to rebase/re-push if a maintainer prefers a fresh run.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

nerdctl run with attached stdio stops draining container stdout at ~72 KiB, deadlocking the container (nerdctl 2.3.5, containerd 2.3.3, Kata runtime-rs)

3 participants