Python Observability

Standard Output vs File Logging in Containers

The choice between writing log records to standard output and writing them to a file looks like a preference and is actually a decision about which failures lose data. This page works through what the container runtime does to each byte a Python process writes, the line-length limit that destroys whole records, and the narrow set of cases where a file sink is still correct. It is a task article under log shipping and collection, part of the Python telemetry pipelines and delivery section, and it pairs with best practices for log rotation in Python for the cases where a file is the answer.

Two sinks, two sets of failure The upper path shows a write to standard output. The bytes enter a pipe with a small kernel buffer, the container runtime reads the other end, wraps each line in an envelope containing a timestamp and a stream name, and appends it to a file on the node which the runtime itself rotates. Two hazards are marked: if the runtime stops reading, the pipe buffer fills and the writing thread blocks, and if a line exceeds the runtime's limit it is split into fragments. The lower path shows a direct file write from the application. The bytes go to the page cache and then to the node's disk, with no reader to block on and no line limit, but the application now owns rotation, and an unrotated file fills the disk, which stops the runtime path as well. The conclusion drawn is that the two paths share a disk and therefore share their worst failure. where the bytes go, and what stops them handler pipe · 64 KiB runtime envelope node file · rotated reader stops → the write blocks line > limit → split into fragments handler page cache application's own file — you own rotation no reader to block on, no line limit, no rotation either both paths land on the same disk — an unrotated file takes the runtime path down with it
The two sinks fail differently but share a disk, which is why an unrotated application file is a platform-wide incident rather than a local one.

Prerequisites

Nothing beyond a formatter that produces one line per record. The relevant configuration is environmental:

# in the container image
ENV PYTHONUNBUFFERED=1

pip install "python-json-logger>=2.0.7,<4.0.0"

Implementation

Step 1 — Write to standard output, unbuffered. Python decides its buffering strategy from whether the stream is a terminal. In a container it is a pipe, so the default is block buffering: output accumulates until a buffer fills, which means the records immediately preceding a crash are frequently the ones that never appear. PYTHONUNBUFFERED removes the buffer entirely; reconfiguring the stream for line buffering keeps a little of the efficiency and still flushes at every newline.

import sys
import logging
from pythonjsonlogger import jsonlogger

# 1. Line buffering: one flush per record, not one per 8 KiB of output.
sys.stdout.reconfigure(line_buffering=True)

handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(jsonlogger.JsonFormatter("%(asctime)s %(levelname)s %(name)s %(message)s"))
logging.basicConfig(level=logging.INFO, handlers=[handler], force=True)

Step 2 — Cap the record size before the runtime does. This is the failure that costs the most and is noticed the least. A runtime that splits a line above its limit emits two entries, each carrying a partial flag that most collectors handle by concatenating — if they are configured to. When they are not, both halves are invalid JSON and the entire record is dropped by the store. The records that hit the limit are exactly the ones with large context: a serialised request body, a long traceback, a database row. Capping in the formatter turns a silent total loss into a visible truncation.

MAX_CHARS = 8_000            # well under a 16 KiB runtime limit, after escaping


class BoundedJsonFormatter(jsonlogger.JsonFormatter):
    def add_fields(self, target, record, message_dict):
        super().add_fields(target, record, message_dict)
        for key, value in list(target.items()):
            if isinstance(value, str) and len(value) > MAX_CHARS:
                dropped = len(value) - MAX_CHARS
                target[key] = value[:MAX_CHARS] + f"…[{dropped} chars truncated]"
                target["truncated"] = True     # queryable, so the cap's effect is visible

Expected Output: an oversized field arrives complete enough to use, and says so.

{"asctime": "2026-09-18T09:31:44.117Z", "level": "ERROR", "message": "upstream rejected payload", "body": "{\"items\":[…]}…[41208 chars truncated]", "truncated": true}

Step 3 — Keep the write off the request path when the sink can stall. A blocked pipe blocks the writing thread, and under a prefork server that is one worker; under asyncio it is the entire process. A queue between the application and the stream handler converts a collector stall into a bounded queue and a counted drop, which is a far better outcome than latency. The mechanics are in non-blocking logging with QueueHandler.

Step 4 — Add a file sink only where the record must outlive the path. Audit records, security events and anything with a retention obligation should exist on disk independently of whether a collector is running. That is an additional handler, not a replacement, and it needs its own rotation policy because nothing else will rotate it.

from logging.handlers import RotatingFileHandler

audit = logging.getLogger("audit")
audit.propagate = False                      # audit records do not also go to stdout
audit_handler = RotatingFileHandler(
    "/var/log/app/audit.jsonl",
    maxBytes=64 * 1024 * 1024,               # 64 MiB per file
    backupCount=5,                           # 320 MiB ceiling, bounded and predictable
)
audit_handler.setFormatter(jsonlogger.JsonFormatter("%(asctime)s %(message)s"))
audit.addHandler(audit_handler)

Step 5 — Bound every file you create. The ceiling above is deliberate and arithmetic: five backups of sixty-four megabytes is a number you can put in a pod's ephemeral storage request. An unrotated file has no such number, and the failure it produces — a node with a full disk — stops the runtime's own log files too, so a single service's unbounded audit log takes out collection for everything on that node.

The records a buffer eats Two timelines of the same process approaching a crash. In the upper timeline standard output is block buffered because it is a pipe. Records accumulate in an eight kilobyte buffer and are written only when it fills, so at the moment the process is killed the last several seconds of records are still in user space memory and are lost with the process. Those are precisely the records describing what went wrong. In the lower timeline the stream is line buffered, so each record is written as it is produced. The crash loses nothing, at the cost of one write syscall per record instead of one per eight kilobytes. A note underneath observes that the cost difference is measurable only when the log volume is high enough that the service has a different problem. the last seconds before a crash, twice block buffered — the container default written in the buffer, never flushed SIGKILL the lost records are the ones that describe the failure line buffered every record written as produced SIGKILL cost: one syscall per record — visible only at volumes that are already a separate problem
Buffering trades the records nearest a crash for syscalls. In a container that is almost never the right trade.

What the runtime adds, and why it matters

Reading a container's logs with a runtime command shows the lines the application wrote. What is stored on the node is not those lines: it is an envelope per line, containing a timestamp assigned by the runtime at read time, the stream name — stdout or stderr — and a flag indicating whether this entry is a complete line or a fragment of a longer one.

Three consequences follow and each one surprises somebody eventually.

The timestamp in the envelope is not the application's timestamp. It is when the runtime read the bytes, which under a blocked pipe or a busy node can be measurably later. Any ordering or duration reasoning must use the application's own timestamp field, which is one more reason for structured records with an explicit time field rather than relying on collection time.

The stream name is preserved, which means stderr is distinguishable from stdout all the way to the store. That is useful — uncaught tracebacks and interpreter warnings arrive on stderr whether you asked for them or not — and it argues for deliberately routing application records to stdout so that anything appearing on stderr is by definition something unhandled. That signal is worth having, and it pairs with capturing unhandled exceptions and warnings.

The partial flag is the mechanism behind split lines, and it is also the mechanism for recovering from them: a collector that honours it will rejoin fragments. Whether yours does is worth verifying explicitly rather than assuming, because the failure only appears for the largest records and looks like an application bug.

A fourth consequence concerns ordering between the two streams. Records written to stdout and stderr travel through separate pipes and are read independently, so their relative order is not preserved. A traceback printed to stderr by the interpreter and a log record written to stdout by the handler that caught the same failure can arrive in either order, occasionally separated by hundreds of milliseconds under load. Any investigation that reasons from the order of two entries on different streams is reasoning from an artefact of the collection path. The practical remedy is to route everything the application produces deliberately to one stream, so that cross-stream ordering never has to be interpreted at all.

stdout or a file, property by property A table comparing logging to stdout and logging to a file inside a container on five properties. Collection: stdout is collected by the runtime and any node agent automatically; a file needs a sidecar or shared volume. Rotation: the runtime rotates stdout logs; a file needs rotation in the application or a tool. Survival of a crash: stdout lines already written are kept by the runtime; buffered file writes may be lost. Disk usage: runtime limits cap stdout logs; a file can fill the container's writable layer. Separate streams: a file can separate audit from application logs easily; stdout needs a field to distinguish them. The note says stdout wins on everything except stream separation, which a field solves. property stdout file in the container collection automatic sidecar or shared volume rotation by the runtime app or tool must do it crash survival written lines kept buffered writes lost disk usage capped by runtime can fill the layer separate streams needs a field easy stdout wins on everything except stream separation — and a field solves that
In a container, the runtime already does collection, rotation and limits for stdout. A file makes the application do all three.

Configuration options

Concern Standard output Application file
Who collects it the platform's agent an agent you configure
Survives a collector outage yes, buffered on the node yes
Survives a full node disk no no
Line length limit runtime limit applies none
Rotation the runtime's yours to configure
Blocks the writer when the reader stalls rarely, page cache absorbs it
Right for everything, by default records that must outlive the path

Verification

Confirm the two properties that actually break: buffering and line length.

# 1. Is output flushed per record? Should print immediately, not in bursts.
kubectl exec deploy/checkout -- python -c "
import sys, time
for i in range(3):
    print({'seq': i}, flush=False); time.sleep(1)
"

# 2. What happens to a record near the limit?
kubectl exec deploy/checkout -- python -c "
print('{\"msg\": \"' + 'x' * 20000 + '\"}')
" && kubectl logs deploy/checkout --tail=3 | wc -l

Expected Output: three lines arriving one per second, and a single oversized record arriving as more than one line — which is the limit, demonstrated.

{'seq': 0}
{'seq': 1}
{'seq': 2}
2

A wc -l of two for one printed record is the split, reproduced in ten seconds. That is the evidence to bring to a decision about the cap in step 2.

Common mistakes

The last log lines before a crash are always missing. Error signature: a pod restarts and its final records describe normal operation. Root cause: block buffering on a pipe. Remediation: set PYTHONUNBUFFERED in the image, or reconfigure the stream at startup as in step 1.

Large records disappear entirely rather than arriving truncated. Error signature: records with big payloads present in the application's own reasoning but absent from the store. Root cause: a runtime line split producing two invalid JSON fragments. Remediation: cap field sizes in the formatter and confirm the collector honours the partial flag.

A node runs out of disk and collection stops for every pod on it. Error signature: every service on one node goes quiet at the same moment. Root cause: an application file sink with no rotation. Remediation: bound every file handler with maxBytes and backupCount, and set an ephemeral storage limit on the pod so the failure is contained to the offender.

Logs arrive with timestamps that disagree with the traces. Error signature: a log record timestamped after the span that produced it. Root cause: reading the runtime's collection timestamp rather than the application's. Remediation: index the application's own time field and use it as the time axis.

Frequently Asked Questions

Is logging to standard output slower than logging to a file?

Slightly, and only when the reader is slow. A write to a pipe is a syscall like a write to a file; the difference is that a pipe has a small buffer and a blocked reader makes the write block, whereas a file write goes to the page cache. Under a healthy collector the difference is not measurable.

Why do some long log lines arrive split in two?

Several container runtimes cap the length of a single log line, typically around sixteen kilobytes, and split anything longer across multiple entries with a partial flag. If the payload was JSON, both fragments are invalid and the record is lost entirely rather than truncated.

Should I disable Python's output buffering in containers?

Yes. When standard output is a pipe rather than a terminal, Python block-buffers it, so records can sit unwritten for kilobytes at a time and are lost if the process is killed. Set PYTHONUNBUFFERED, or reconfigure the stream with line buffering at startup.

When is a file sink still the right choice?

For records that must survive the collection path failing — audit trails, security events, anything with a compliance obligation — and on long-lived hosts where an agent already tails a directory. In both cases the file is in addition to standard output, not instead of it.

Related Guides