stdout, stderr and What Belongs on Each

Part II · Module 22 · Chapter 22.5 · stdout, stderr and What Belongs on Each

1. Two Streams That Look Like One

import sys

print("out 1")
print("err 1", file=sys.stderr)
print("out 2")
print("err 2", file=sys.stderr)

import subprocess
import sys

done = subprocess.run([sys.executable, "streams.py"], capture_output=True, text=True)
print("stdout only:", done.stdout.strip().replace("\n", " | "))
print("stderr only:", done.stderr.strip().replace("\n", " | "))

stdout only: out 1 | out 2
stderr only: err 1 | err 2

Four print calls, two destinations. On a terminal all four lines appear together and nothing suggests there are two channels at all; the moment anything captures or redirects one of them, the split becomes the most important thing about the output.

print(..., file=sys.stderr) is the whole mechanism. Everything else in this chapter is about which lines get it.

2. The Result and the Commentary

import json
import sys

print("reading sim.log", file=sys.stderr)
print("note: waves were disabled for this run", file=sys.stderr)

summary = {"test": "axi_smoke", "seed": 1839274, "status": "FAIL", "errors": 2}
print(json.dumps(summary))

print("done in 143.2s", file=sys.stderr)

import subprocess
import sys

done = subprocess.run([sys.executable, "report.py"], capture_output=True, text=True)
print("stdout:")
print("   " + done.stdout.strip())
print("stderr:")
for line in done.stderr.strip().splitlines():
    print("   " + line)

stdout:
   {"test": "axi_smoke", "seed": 1839274, "status": "FAIL", "errors": 2}
stderr:
   reading sim.log
   note: waves were disabled for this run
   done in 143.2s

That is the canonical annotation:

print(json.dumps(summary))                        # stdout: the result
print("warning: waves disabled", file=sys.stderr)  # stderr: the commentary

Stdout contains exactly one thing: the answer. Everything a person might want to know about how the answer was arrived at is on the other stream.

Notice what that buys even before anything is piped. done.stdout is parseable JSON with no filtering, no skipping of preamble, no "ignore lines starting with note:". The consumer needs no knowledge of this tool beyond the shape of its result.

3. One Line in the Wrong Stream

import json
import sys

print("note: waves disabled for this run", file=sys.stderr)
print(json.dumps({"test": "axi_smoke", "status": "FAIL", "errors": 2}))

import json

print("note: waves disabled for this run")
print(json.dumps({"test": "axi_smoke", "status": "FAIL", "errors": 2}))

import json
import sys

text = sys.stdin.read()
try:
    record = json.loads(text)
    print("consumer ok:", record["status"], record["errors"])
except json.JSONDecodeError as exc:
    print(f"consumer failed: {exc.msg} (line {exc.lineno})")

import subprocess
import sys

PY = sys.executable
for script in ["good.py", "bad.py"]:
    done = subprocess.run(
        ["/bin/sh", "-c", f"{PY} {script} 2>/dev/null | {PY} consume.py"],
        capture_output=True, text=True)
    print(f"$ {script} | consume.py")
    print("   " + done.stdout.strip())

$ good.py | consume.py
   consumer ok: FAIL 2
$ bad.py | consume.py
   consumer failed: Expecting value (line 1)

The two scripts differ by four characters — , file=sys.stderr on one line — and one of them can be piped into another program while the other cannot.

The failure is also unhelpfully worded from the consumer's point of view. Expecting value (line 1) describes the note, not the JSON, and a person debugging the consumer will spend a while before suspecting the producer's first line of chatter.

This is the shape of the problem in a real flow: a tool works perfectly for months while everybody runs it on a terminal, and breaks the first time somebody tries to compose it with something. Chapter 21.4 made JSON the machine-readable default; a machine-readable format on a stream mixed with prose is not machine-readable.

4. The Test

The question that decides every case:

Could this line be the input to another program?

If yes, it is a result and goes to stdout. If no, it is commentary and goes to stderr.

Two rows are worth dwelling on because they are the ones people get wrong in opposite directions.

PASS / FAIL goes on stdout. It looks like a message for a person, and it is also the tool's entire result — a wrapper doing verdict=$(check.py sim.log) needs it there. Chapter 22.4's exit status says the same thing to a machine; the printed verdict is for a caller that wants it as text.

A usage message goes on stderr, even though it is the only thing the run produced. The script produced no result, so stdout must stay empty — which is what Chapter 22.3 Section 3 observed parser.error doing, and why a pipeline reading a misused tool gets nothing rather than a usage message where a result should be.

The limiting case is the one the table makes obvious: if a tool has no machine-readable result at all, its stdout should be empty. A script whose only job is to print a human-readable summary is a reasonable thing to write, and it should still put that summary on stdout — because that summary is its result, and summary.py > report.txt is how somebody will capture it.

5. Capturing Both: the Order Is Not What You Think

The second thing the canonical purpose says must keep working is capturing a log. That is usually written 2>&1 — merge stderr into stdout — and it has a consequence nobody expects:

import sys

print("out 1")
print("err 1", file=sys.stderr)
print("out 2")
print("err 2", file=sys.stderr)

import subprocess
import sys

merged = subprocess.run([sys.executable, "streams.py"],
                        stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True)
print("merged, buffered :", merged.stdout.strip().replace("\n", " | "))

unbuffered = subprocess.run([sys.executable, "-u", "streams.py"],
                            stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True)
print("merged, -u       :", unbuffered.stdout.strip().replace("\n", " | "))

merged, buffered : err 1 | err 2 | out 1 | out 2
merged, -u       : out 1 | err 1 | out 2 | err 2

The first line is every diagnostic, then every result. The program printed them alternately and the captured log says otherwise.

The cause is buffering. When stdout is a terminal it is line-buffered, so each line appears as it is printed. When stdout is a pipe or a file it switches to block buffering and holds output until a few kilobytes accumulate or the process exits. Stderr is never block-buffered. So in a captured run, the diagnostics go straight through and the results arrive in one lump at the end.

The practical damage is to reading. A captured log of a long run shows all the progress messages, then all the results — so a reader cannot tell which diagnostic belongs to which result, and a run that failed halfway looks like a run that did everything and then complained.

Three fixes, and the choice depends on who controls the invocation:

import sys

print("out 1")
print("err 1", file=sys.stderr)
print("out 2")
print("err 2", file=sys.stderr)

import sys

print("out 1", flush=True)
print("err 1", file=sys.stderr)
print("out 2", flush=True)
print("err 2", file=sys.stderr)

import subprocess
import sys


def merged(args):
    done = subprocess.run(args, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True)
    return done.stdout.strip().replace("\n", " | ")


print("default            :", merged([sys.executable, "streams.py"]))
print("python3 -u         :", merged([sys.executable, "-u", "streams.py"]))
print("flush=True in code :", merged([sys.executable, "flushed.py"]))

default            : err 1 | err 2 | out 1 | out 2
python3 -u         : out 1 | err 1 | out 2 | err 2
flush=True in code : out 1 | err 1 | out 2 | err 2

python3 -u is the caller's fix, and the one to reach for in a wrapper script or a CI step: it makes both streams unbuffered without touching the tool. The environment variable PYTHONUNBUFFERED=1 does the same thing.

flush=True is the tool's fix, applied per call. It costs a little throughput on a tool that prints a great deal, and it is the right choice for the handful of lines whose ordering matters — a progress line a user is watching, for instance.

Not merging at all is the third option and often the best: tool > out.log 2> err.log keeps each stream in its own file, in order, with no buffering question. It is worse only when you genuinely need to see the interleaving — which is the case -u exists for.

6. Redirecting Them Separately

import json
import sys

print("reading sim.log", file=sys.stderr)
print(json.dumps({"test": "axi_smoke", "status": "FAIL", "errors": 2}))
print("done", file=sys.stderr)

import subprocess
import sys
from pathlib import Path

PY = sys.executable
subprocess.run(["/bin/sh", "-c", f"{PY} report.py > result.json 2> run.err"], check=True)

print("result.json:")
print("   " + Path("result.json").read_text(encoding="utf-8").strip())
print("run.err:")
for line in Path("run.err").read_text(encoding="utf-8").strip().splitlines():
    print("   " + line)

import json
record = json.loads(Path("result.json").read_text(encoding="utf-8"))
print("parsed     :", record["status"], record["errors"])

result.json:
   {"test": "axi_smoke", "status": "FAIL", "errors": 2}
run.err:
   reading sim.log
   done
parsed     : FAIL 2

> result.json 2> run.err sends each stream to its own file, and result.json is a valid JSON document with nothing to strip. That is the payoff for the discipline: the tool's result is a file, not a file that needs filtering first.

Three redirections worth knowing, all POSIX:

The last one is how a caller that only wants the result gets it, and it only works on a tool that put the result in the right place. Section 3's bad.py cannot be rescued by any redirection, because the two kinds of line are already mixed.

7. A Tool That Composes

Putting the chapter together with Chapter 22.4's exit status:

import argparse
import json
import sys

parser = argparse.ArgumentParser(prog="check.py")
parser.add_argument("--log", required=True)
parser.add_argument("--quiet", action="store_true")
args = parser.parse_args()

LOGS = {
    "smoke.log": {"test": "axi_smoke", "status": "FAIL", "errors": 2},
    "reset.log": {"test": "axi_reset", "status": "PASS", "errors": 0},
}

if args.log not in LOGS:
    print(f"check.py: error: cannot read {args.log!r}", file=sys.stderr)
    sys.exit(2)

if not args.quiet:
    print(f"reading {args.log}", file=sys.stderr)

record = LOGS[args.log]
print(json.dumps(record))

sys.exit(0 if record["status"] == "PASS" else 1)

import subprocess
import sys

PY = sys.executable
for args in (["--log", "reset.log"], ["--log", "smoke.log"], ["--log", "nope.log"]):
    done = subprocess.run([PY, "check.py"] + args, capture_output=True, text=True)
    print(f"$ check.py {' '.join(args)}")
    print(f"   rc     = {done.returncode}")
    print(f"   stdout = {done.stdout.strip()!r}")
    print(f"   stderr = {done.stderr.strip()!r}")

$ check.py --log reset.log
   rc     = 0
   stdout = '{"test": "axi_reset", "status": "PASS", "errors": 0}'
   stderr = 'reading reset.log'
$ check.py --log smoke.log
   rc     = 1
   stdout = '{"test": "axi_smoke", "status": "FAIL", "errors": 2}'
   stderr = 'reading smoke.log'
$ check.py --log nope.log
   rc     = 2
   stdout = ''
   stderr = "check.py: error: cannot read 'nope.log'"

Three invocations and three consistent stories. A caller can rely on four promises at once:

rc == 0 means passed, 1 means failed, 2 means could not run — Chapter 22.4's contract.

stdout is a JSON record whenever rc is 0 or 1, and empty when rc is 2. So a caller knows from the number whether parsing stdout is worth attempting, without trying and catching.

stderr is always safe to ignore — nothing on it is needed to understand the result.

--quiet suppresses the commentary and not the result, which is the only thing a --quiet flag should ever do. A --quiet that silences stdout is silencing the answer.

That set of promises is what makes a tool composable, and Chapter 22.6 turns it into an agreement every tool in a flow keeps.

8. Predict, Run, Observe

import sys

print("A")
print("B", file=sys.stderr)
sys.stdout.write("C\n")
sys.stderr.write("D\n")
print("E", file=sys.stdout)

import subprocess
import sys

done = subprocess.run([sys.executable, "po5.py"], capture_output=True, text=True)
print("out:", done.stdout.strip().replace("\n", ""))
print("err:", done.stderr.strip().replace("\n", ""))

merged = subprocess.run([sys.executable, "po5.py"],
                        stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True)
print("mrg:", merged.stdout.strip().replace("\n", ""))

flushed = subprocess.run([sys.executable, "-u", "po5.py"],
                         stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True)
print("-u :", flushed.stdout.strip().replace("\n", ""))

empty = subprocess.run([sys.executable, "-c", "import sys; print('x', file=sys.stderr)"],
                       capture_output=True, text=True)
print("stdout empty:", empty.stdout == "", "| rc:", empty.returncode)

The verified output:

out: ACE
err: BD
mrg: BDACE
-u : ABCDE
stdout empty: True | rc: 0

out is ACE — print and sys.stdout.write go to the same place, and file=sys.stdout is the default spelled out.

err is BD — same for the other stream.

mrg is BDACE — stderr first, then stdout, because stdout was a pipe and therefore block-buffered. Section 5.

-u is ABCDE — the real order, which only unbuffering reveals.

The last line — a program writing only to stderr leaves stdout genuinely empty and still exits 0. An empty stdout is not an error, which is why a caller needs the exit status to interpret it.

9. Exercises

Exercise 1 — two streams. Write a script printing to both and capture them separately. Confirm each line went where you expected.

Exercise 2 — the canonical pair. Emit a JSON result on stdout and three diagnostics on stderr. Confirm stdout parses with no filtering.

Exercise 3 — four characters. Take a working tool and move one diagnostic from stderr to stdout. Pipe it into a JSON consumer and record the error.

Exercise 4 — read the error. Say why the consumer's message describes the note rather than the JSON, and who would be debugged first.

Exercise 5 — apply the test. For ten lines your own tool prints, answer "could this be the input to another program?" and assign a stream to each.

Exercise 6 — the two arguable ones. Justify putting PASS/FAIL on stdout and a usage message on stderr, in one sentence each.

Exercise 7 — the reordering. Capture a program printing out/err/out/err with 2>&1 and record the order. Explain it in terms of buffering.

Exercise 8 — three fixes. Restore the true order with -u, with flush=True, and by not merging. Say which your flow can apply without editing the tool.

Exercise 9 — the hung tool. Print progress to stdout, pipe it to tee, and describe what a user sees. Then move it to stderr.

Exercise 10 — separate files. Redirect each stream to its own file and parse the result file with no preprocessing.

Exercise 11 — discard the noise. Run a tool with 2>/dev/null and confirm the result survives. Then try it on a tool that mixes the streams.

Exercise 12 — four promises. Write a tool keeping all four from Section 7. Confirm that rc tells a caller whether stdout is worth parsing.

Exercise 13 — what --quiet means. Add a --quiet flag and confirm it silences only the commentary.

10. Summary

• Every process has two output streams and on a terminal they look like one, which is why the split is learned the hard way.
• print(..., file=sys.stderr) is the whole mechanism.
• Stdout carries the result; stderr carries everything about how the result was reached.
• One line in the wrong stream stops a tool being piped — four characters' difference turns a parseable record into a parse error.
• The consumer's error describes the chatter, not the data, so the wrong program gets debugged first.
• The test is one question: could this line be the input to another program?
• A PASS/FAIL verdict is a result and goes on stdout, even though a human reads it.
• A usage message is a diagnostic and goes on stderr, leaving stdout empty because there was no result.
• If a tool has no machine-readable result, stdout should be empty — but a human-readable summary is a result.
• Piped stdout is block-buffered and stderr is not, so a 2>&1 capture shows every diagnostic before every result.
• The captured log is then in an order the run never happened in, and a run that died halfway looks like one that finished and complained.
• Three fixes: python3 -u or PYTHONUNBUFFERED=1 from the caller, flush=True in the tool, or redirecting to two files and not merging at all.
• Progress on stdout through a pipe looks like a hung tool. Progress belongs on stderr.
• > out.log 2> err.log gives a result file that needs no filtering; 2>/dev/null works only on a tool that got the split right.
• Four promises make a tool composable: a meaningful exit status, a machine-readable stdout, an ignorable stderr, and a --quiet that silences only the commentary.

The last chapter of this module makes those promises an agreement that every tool in a flow keeps, so they compose with each other and not just with a careful caller.