conn_sock.c: 'Failed to write container stdin' is logged on every EAGAIN, flooding the journal for slow stdin consumers

[petek]

Summary

sock_try_write_to_local_sock() logs Failed to write container stdin on every EAGAIN from the container's non-blocking stdin fd. For any container whose stdin consumer is slower than the writer, this floods the journal at a rate proportional to the bytes fed, while being entirely benign: the same code path retries the unwritten bytes, so nothing is lost.

Measured on a log-analysis pipeline (podman run --rm -i ... goaccess ... -, one normalized stream on stdin): ~11,000 journal lines a day from this one message, all of it inside the systemd unit's own journal. It made journalctl -u <unit> unusable exactly when the pipeline needed diagnosing, and the warnings read as input loss on a live rebuild until byte accounting ruled that out.

Mechanism

Container stdin is set non-blocking (conmon.c, g_unix_set_fd_nonblocking(mainfd_stdin, TRUE, NULL); also conn_sock.c for the destination fd). In conn_sock.c, v2.1.12:

if (local_sock->is_stream) {
        w = write(*(local_sock->fd), sock->buf + sock->off, sock->remaining);
} else {
        w = sendto(...);
}
if (w < 0) {
        nwarnf("Failed to write %s", local_sock->label);
} else {
        sock->off += w;
        sock->remaining -= w;
}

Two things follow:

1. errno is never examined, so EAGAIN (the pipe is simply full because the consumer is busy) logs identically to a real failure.
2. off/remaining are left untouched on error, so write_to_local_sock() sets has_data, local_sock_write_cb() returns G_SOURCE_CONTINUE, and the same bytes are written when the fd is next writable. The warning therefore reports a successful retry loop, one line per retry.

main still warns unconditionally; it only changed the message to pwarnf("Failed to write to fd %s", ...), which usefully appends strerror(errno) but does not make the warning conditional.

Reproduction

Two arms, identical except podman's log level, feeding ~40 MB of 200-byte lines into a container whose reader is a shell read loop (slow, line-oriented, so the pipe stays at capacity):

yes "$(head -c 200 /dev/zero | tr '\0' 'x')" | head -n 200000 \
  | podman [--log-level=error] run --rm -i --network none \
      --name arm --entrypoint sh <image> -c 'while IFS= read -r l; do :; done'

Warnings attributed by container id from journalctl -t conmon:

conmon --log-level	Failed to write container stdin
warning (podman default)	2,323
error	0

Versions: podman 5.4.2, conmon 2.1.12, crun 1.21, Debian packages.

Suggested fix

Skip the warning when the write failed only because the fd was not ready:

if (w < 0 && errno != EAGAIN && errno != EWOULDBLOCK)
        pwarnf("Failed to write to fd %s", local_sock->label);

EAGAIN on a non-blocking fd whose bytes are retried is a normal event in this loop, not a warning. Demoting it to ndebugf would work equally well for anyone who wants to see it.

Workaround

Lowering podman's log level for the affected invocation (podman --log-level=error run ...) propagates to conmon and silences the class, at the cost of every other podman/conmon warning for that run. That is what we shipped, but it is a mitigation rather than a fix.

Related: #576 notes conn_sock.c could use an overhaul generally; this is one specific, self-contained symptom.

[petek]

Two corrections to my own report, and the lineage I missed before filing.

Prior art: discussion #540 is the same symptom (conn_sock.c, same message, podman exec piping into another container's stdin), and it is what produced #554, the pwarnf change now on main. --log-level error was suggested there as the suppression, which is what we shipped. Apologies for the near-duplicate: GitHub issue search does not index discussions, so a phrase search across this repo's issues returns nothing for it.

What #540 left open is the thing my report can close: the reporter could not rebuild with #554 applied, so the actual errno was never observed. That is still the open question, and it decides whether the warning is benign.

Correction to what I stated as fact. I wrote that the warning fires on EAGAIN. What is actually verified here is:

• container stdin is non-blocking (conmon.c, g_unix_set_fd_nonblocking(mainfd_stdin, TRUE, NULL));
• the failed-write branch never reads errno, and leaves off/remaining unadvanced, so the same bytes are rewritten when the fd is next writable;
• the warning count scales with the volume fed on stdin, and the containers fed least never produce one;
• the data arrives intact end to end (byte accounting across ~45M parsed records reconciled against the source logs).

EAGAIN is the inference that fits all four, and a persistent hard error would not survive the retry loop, but I have not read errno. We run 2.1.12, which predates #554, so the message carries no strerror output. Treat the mechanism as inferred rather than measured until someone runs a pwarnf-carrying build against a slow stdin consumer.

The reproduction in the original report is deliberately shaped to make that easy: a shell read loop as the consumer keeps the pipe at capacity, and it produced 2,323 warnings in one ~40MB run, so any build printing errno will answer this in seconds rather than needing a production workload.

[petek]

The errno is EAGAIN, measured. This is the datum #540 could not get, so posting it here rather than leaving the mechanism inferred.

Reproduced in a container matching the affected host's distribution exactly: Debian 13, podman 5.4.2+ds1-2+b2, conmon 2.1.12-4, strace 6.13+ds-1. Since 2.1.12 predates #554 and prints no errno, strace -f -y -e trace=write -e status=failed was attached to the conmon that podman spawned.

Feed: 200,000 lines of 200 bytes on stdin. Consumer: sh -c 'while IFS= read -r l; do :; done', which is slow and line-oriented, so the pipe sits at capacity.

2192  write() calls returned -1, and every one of them was EAGAIN
   0  failures of any other errno

3547  write(9<pipe:[5048736]>, "xxxx..."..., 32768) = -1 EAGAIN (Resource temporarily unavailable)
3547  write(9<pipe:[5048736]>, "xxxx..."..., 8192)  = -1 EAGAIN (Resource temporarily unavailable)
3547  write(9<pipe:[5048736]>, "xxxx..."..., 24576) = -1 EAGAIN (Resource temporarily unavailable)

conmon's own warnings in the same run: 2,247, against 2,192 traced failing writes. The 55-line difference is the attach delay - strace attached a couple of seconds after the container started, so the earliest warnings precede the trace. Within that gap the relationship is one warning per failed write().

conmon: conmon 25f7b00db915842da325 <nwarn>: Failed to write container stdin

So the message reports a non-blocking pipe that was momentarily full, on a code path that then rewrites the same bytes successfully. errno != EAGAIN && errno != EWOULDBLOCK on the warning would remove the entire class without hiding anything real. With #554 the message now carries strerror(errno), which means anyone reproducing this on a current build will see Resource temporarily unavailable in their logs and can confirm it in one line.

Method note, in case it saves someone the detour: --cidfile is removed along with the container under --rm, so per-container attribution of these journal lines has to come from conmon's own argv while it runs. And a cat > /dev/null consumer drains at memory speed and produces almost no warnings; the consumer has to be slow for the pipe to stay full.