Capturing Output, or Redirecting It to a Log

Part II · Module 23 · Chapter 23.5 · Capturing Output, or Redirecting It to a Log

1. Four Destinations

import sys

count = int(sys.argv[1])
for index in range(count):
    print(f"UVM_INFO line {index}")
print("tool: a warning", file=sys.stderr)

import subprocess
import sys
from pathlib import Path

PY = sys.executable

captured = subprocess.run([PY, "noisy.py", "3"], capture_output=True, text=True)
print("capture_output -> stdout is", type(captured.stdout).__name__,
      "of", len(captured.stdout), "chars")

with open("tool.log", "w", encoding="utf-8") as handle:
    to_file = subprocess.run([PY, "noisy.py", "3"], stdout=handle,
                             stderr=subprocess.STDOUT)
print("stdout=handle  -> stdout is", to_file.stdout,
      "| file has", len(Path("tool.log").read_text(encoding="utf-8").splitlines()), "lines")

discarded = subprocess.run([PY, "noisy.py", "3"],
                           stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
print("DEVNULL        -> stdout is", discarded.stdout, "| rc", discarded.returncode)

capture_output -> stdout is str of 48 chars
stdout=handle  -> stdout is None | file has 4 lines
DEVNULL        -> stdout is None | rc 0

Three of the four, plus the default from Chapter 23.1 Section 6 — inheriting the parent's streams, which is what happens when you pass nothing at all.

The whole chapter is choosing between rows two and three.

2. Capture Holds All of It

import sys

count = int(sys.argv[1])
for index in range(count):
    print(f"UVM_INFO line {index}")

import subprocess
import sys

cp = subprocess.run([sys.executable, "noisy.py", "5000"],
                    capture_output=True, text=True)

print("lines     :", cp.stdout.count("\n"))
print("characters:", len(cp.stdout))
print("per line  :", round(len(cp.stdout) / cp.stdout.count("\n"), 1))
print("type      :", type(cp.stdout).__name__)

lines     : 5000
characters: 93890
per line  : 18.8
type      : str

Five thousand short lines are ninety-four thousand characters, and all of them exist as one string before the next line of your program runs. subprocess.run does not return until the child has finished and everything it printed has been assembled.

Those numbers are a property of the text, not of this machine, so the arithmetic carries. A UVM log line is nearer 80 characters than 19, and a gate-level regression log runs to tens of millions of lines — the string capture_output would build for one of those is the whole file, in memory, in one object, in addition to whatever your parser then does with it.

Chapter 15.7 made this exact argument about reading a log with .read() instead of iterating it. This is the same mistake one step earlier: the file is not even on disk yet, and you have already decided to hold it.

capture_output=True is right when the output is small and you want it immediately. A -version query, a which-style check, a tool that prints one JSON record — Chapter 22.6's composed tools are exactly this case, and capture is the correct choice there.

3. A File Handle Holds Nothing

import sys

count = int(sys.argv[1])
for index in range(count):
    print(f"UVM_INFO line {index}")
print("tool: a warning", file=sys.stderr)

import subprocess
import sys
from pathlib import Path

log_path = Path("sim.log")

with open(log_path, "w", encoding="utf-8") as handle:
    cp = subprocess.run([sys.executable, "noisy.py", "5000"],
                        stdout=handle, stderr=subprocess.STDOUT)

print("cp.stdout      :", cp.stdout)
print("cp.returncode  :", cp.returncode)
print("lines on disk  :", len(log_path.read_text(encoding="utf-8").splitlines()))
print("first line     :", log_path.read_text(encoding="utf-8").splitlines()[0])

cp.stdout      : None
cp.returncode  : 0
lines on disk  : 5001
first line     : UVM_INFO line 0

That is the canonical annotation:

with open(log_path, "w") as f:
    subprocess.run(cmd, stdout=f, stderr=subprocess.STDOUT)

cp.stdout is None and the log is on disk. Python never held the output — the operating system connected the child's stdout directly to the file, and the bytes went from one to the other without passing through your process at all.

That is the right default for any tool whose output you are not going to parse in the next few lines, which for a simulator is always. The log is where it needs to be anyway (Chapter 21.1's log_path field), the parser from Module 20 streams it when it is ready, and nothing was held.

stderr=subprocess.STDOUT merges the two streams into the one file — 5001 lines, the extra one being the warning. Section 8 is about whether you want that.

4. Confusing the Two

import sys

count = int(sys.argv[1])
for index in range(count):
    print(f"UVM_INFO line {index}")

import subprocess
import sys
from pathlib import Path

LINES = 5000


def capture_then_write(path):
    """Hold the whole log, then write it. Two copies exist at once."""
    cp = subprocess.run([sys.executable, "noisy.py", str(LINES)],
                        capture_output=True, text=True)
    Path(path).write_text(cp.stdout, encoding="utf-8")
    return len(cp.stdout)


def write_directly(path):
    """The child writes the file. Nothing is held."""
    with open(path, "w", encoding="utf-8") as handle:
        subprocess.run([sys.executable, "noisy.py", str(LINES)], stdout=handle)
    return 0


held_a = capture_then_write("via_memory.log")
held_b = write_directly("direct.log")

same = (Path("via_memory.log").read_text(encoding="utf-8")
        == Path("direct.log").read_text(encoding="utf-8"))

print("characters held, capture-then-write:", held_a)
print("characters held, direct            :", held_b)
print("files identical                    :", same)

characters held, capture-then-write: 93890
characters held, direct            : 0
files identical                    : True

Identical files; one route held ninety-four thousand characters and the other held none.

This is the confusion the canonical purpose names, and it is common because it looks thorough: capture the output so you have it, then also write it to a log. The result is the same file by a route that cannot scale, and the failure mode on a real log is not slowness — it is the job being killed, which Chapter 23.4 Section 5 showed arriving as SIGKILL and a negative return code.

The reverse confusion is quieter. A tool whose output you do need immediately, sent to a file and then read straight back, works perfectly and does two extra filesystem operations for no reason:

import subprocess
import sys
from pathlib import Path

with open("version.txt", "w", encoding="utf-8") as handle:
    subprocess.run([sys.executable, "-c", "print('FakeSim 2024.09')"], stdout=handle)
version_via_file = Path("version.txt").read_text(encoding="utf-8").strip()

cp = subprocess.run([sys.executable, "-c", "print('FakeSim 2024.09')"],
                    capture_output=True, text=True)
version_direct = cp.stdout.strip()

print("via a file:", version_via_file)
print("captured  :", version_direct)
print("same      :", version_via_file == version_direct)

via a file: FakeSim 2024.09
captured  : FakeSim 2024.09
same      : True

The rule is a question about what happens next: are you going to use this output in the next few lines, or is it evidence for later? Immediately means capture; later means a file.

5. Discarding It

import subprocess
import sys

cp = subprocess.run([sys.executable, "-c",
                     "import sys; print('chatter'); print('warning', file=sys.stderr); sys.exit(0)"],
                    stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)

print("rc     :", cp.returncode)
print("stdout :", cp.stdout)
print("nothing was held, written or shown")

rc     : 0
stdout : None
nothing was held, written or shown

DEVNULL is for a tool whose output genuinely does not matter and whose exit status does — a mkdir, a licence ping, a cleanup step that chatters.

Use it deliberately and rarely. A discarded log is a run that cannot be debugged, and the usual reason somebody reaches for it is that the tool is noisy on a terminal — which Chapter 23.3 Section 4's file handle solves without throwing the evidence away.

6. One Byte Can Destroy a Capture

import sys

sys.stdout.buffer.write(b"UVM_INFO line 1\n")
sys.stdout.buffer.write(b"UVM_INFO path: /proj/caf\xe9/rtl\n")
sys.stdout.buffer.write(b"UVM_INFO line 3\n")

import subprocess
import sys

print("text=True, default errors:")
try:
    cp = subprocess.run([sys.executable, "binary.py"], capture_output=True, text=True)
    print("   got:", repr(cp.stdout))
except UnicodeDecodeError as exc:
    print("   UnicodeDecodeError:", exc.reason)
    print("   and the whole capture is gone — including the good lines")

print()
print("text=True, errors='replace':")
cp = subprocess.run([sys.executable, "binary.py"], capture_output=True,
                    text=True, errors="replace")
print("   lines kept:", len(cp.stdout.splitlines()))
print("   the bad one:", repr(cp.stdout.splitlines()[1]))

print()
print("no text= at all (bytes):")
cp = subprocess.run([sys.executable, "binary.py"], capture_output=True)
print("   type:", type(cp.stdout).__name__)
print("   the bad one:", cp.stdout.splitlines()[1])

text=True, default errors:
   UnicodeDecodeError: invalid continuation byte
   and the whole capture is gone — including the good lines

text=True, errors='replace':
   lines kept: 3
   the bad one: 'UVM_INFO path: /proj/caf�/rtl'

no text= at all (bytes):
   type: bytes
   the bad one: b'UVM_INFO path: /proj/caf\xe9/rtl'

One byte, and capture_output=True, text=True raised — losing not just that line but the entire output, because the decode happens on the whole thing at once after the child exits.

This is not exotic. A simulator prints paths, and a path can contain a byte that is not valid UTF-8: a directory created on a system with a different locale, a filename copied from a Windows share, a vendor banner with a legacy-encoded copyright symbol. The line above is a é written in Latin-1, which is one of the commonest ways it happens.

Three ways out, in order of how much they keep:

errors="replace" keeps every line, with the undecodable bytes shown as the replacement character. Right when you are going to parse the text and the broken bytes are not the part you care about — Chapter 20.12 Section 3 used the same argument for a truncated tail.

No text=, giving bytes, which keeps the data exactly. Right when the output is not really text, or when you intend to write it somewhere byte-for-byte.

A file handle, which is the one this chapter recommends anyway. With stdout=handle there is no decoding step in Python at all — the bytes go from the child to the file untouched, and the encoding question moves to whoever reads the log later, where Chapter 15.3's errors= on the read handles it one line at a time instead of all at once.

7. Merged or Separate

import sys

print("tool: compiling")
print("tool: warning on line 88", file=sys.stderr)
print("tool: done")

import subprocess
import sys
from pathlib import Path

with open("merged.log", "w", encoding="utf-8") as handle:
    subprocess.run([sys.executable, "noisy.py"], stdout=handle, stderr=subprocess.STDOUT)

with open("out.log", "w", encoding="utf-8") as out, \
     open("err.log", "w", encoding="utf-8") as err:
    subprocess.run([sys.executable, "noisy.py"], stdout=out, stderr=err)

for name in ["merged.log", "out.log", "err.log"]:
    lines = Path(name).read_text(encoding="utf-8").strip().splitlines()
    print(f"{name:<12} {len(lines)} line(s): {lines}")

merged.log   3 line(s): ['tool: warning on line 88', 'tool: compiling', 'tool: done']
out.log      2 line(s): ['tool: compiling', 'tool: done']
err.log      1 line(s): ['tool: warning on line 88']

Look at merged.log. The warning was printed second and is in the file first — Chapter 22.5 Section 5's buffering, now across a process boundary: the child's stdout is a file and therefore block-buffered, its stderr is not, so the diagnostics land ahead of the output.

That decides the choice more than taste does.

Merge when a human will read one log and the interleaving does not have to be exact — which is most tool logs, and is what the canonical annotation does. The ordering will be wrong in the way shown above, and for a simulator whose stderr carries a handful of warnings that is tolerable.

Separate when the ordering matters, when stdout is machine-readable and must not be polluted (Chapter 22.5 Section 3), or when you want to know whether the tool said anything on stderr at all without scanning the whole log — err.log being empty is a one-line check.

A flow running many tools usually merges, because one log per run is what an engineer wants to open. A flow where one tool's stdout feeds another captures stdout and lets stderr go to a file, which is the two mechanisms combined.

8. The Pattern

import sys

print("FakeSim: elaborating")
for i in range(20):
    print(f"UVM_INFO scb.sv(120) @ {i * 1000}: compared {i * 8} transactions")
print("UVM_ERROR drv.sv(88) @ 141900: bad handshake")
print("FakeSim: warning: waves disabled", file=sys.stderr)
print("TEST DONE")
sys.exit(1)

import subprocess
import sys
from pathlib import Path


def run_and_log(cmd, log_path):
    """Run a tool, send everything to a log, return the status and the path."""
    log_path = Path(log_path)
    log_path.parent.mkdir(parents=True, exist_ok=True)
    with open(log_path, "w", encoding="utf-8") as handle:
        cp = subprocess.run(cmd, stdout=handle, stderr=subprocess.STDOUT)
    return {"rc": cp.returncode, "log": str(log_path)}


def count_errors(log_path):
    """Stream the log the parser's way — Chapter 20.3."""
    errors = 0
    with open(log_path, encoding="utf-8", errors="replace") as handle:
        for line in handle:
            if line.startswith("UVM_ERROR"):
                errors += 1
    return errors


result = run_and_log([sys.executable, "fake_sim.py"], "runs/axi_smoke/sim.log")
result["errors"] = count_errors(result["log"])

print("rc     :", result["rc"])
print("log    :", result["log"])
print("errors :", result["errors"])
print("held   : nothing")

rc     : 1
log    : runs/axi_smoke/sim.log
errors : 1
held   : nothing

Write it, then read it. The tool's output goes to disk as it is produced, and the parser streams it afterwards one line at a time — Chapter 20.3's loop, which never holds more than a line.

Four properties worth naming.

Nothing is ever fully in memory, at either stage. That is the property that makes this work on a log of any size.

The log exists even if the parse fails. A UnicodeDecodeError, a pattern bug, a crash in the summariser — all of them leave the evidence on disk, where capture_output would have taken it with them.

errors="replace" is on the read, where it costs one line rather than the whole capture. Section 6's third way out.

The log path goes in the record, which is Chapter 21.1's log_path field and the reason a report can link to the evidence.

9. Predict, Run, Observe

import sys

print("line one")
print("to stderr", file=sys.stderr)
print("line two")

import subprocess
import sys
from pathlib import Path

PY = sys.executable

# A
a = subprocess.run([PY, "small.py"], capture_output=True, text=True)
print("A:", repr(a.stdout), repr(a.stderr))

# B
b = subprocess.run([PY, "small.py"], capture_output=True)
print("B:", type(b.stdout).__name__)

# C
with open("c.log", "w", encoding="utf-8") as handle:
    c = subprocess.run([PY, "small.py"], stdout=handle)
print("C:", c.stdout, len(Path("c.log").read_text(encoding="utf-8").splitlines()))

# D
with open("d.log", "w", encoding="utf-8") as handle:
    subprocess.run([PY, "small.py"], stdout=handle, stderr=subprocess.STDOUT)
print("D:", len(Path("d.log").read_text(encoding="utf-8").splitlines()))

# E
e = subprocess.run([PY, "small.py"], stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
print("E:", e.stdout, e.returncode)

# F
f = subprocess.run([PY, "small.py"], capture_output=True, text=True)
print("F:", len(f.stdout), "chars held")

The verified output:

A: 'line one\nline two\n' 'to stderr\n'
B: bytes
to stderr
C: None 2
D: 3
E: None 0
F: 18 chars held

A — capture gives both streams as strings, separately.

B — without text=True, they are bytes.

C — stdout=handle leaves cp.stdout as None, and only stdout's two lines reach the file. The stderr line went to the parent's stderr.

D — merging adds the third line, and it is first in the file for Section 7's reason.

E — DEVNULL discards both and keeps the status.

F — the whole output exists as a string, which is the thing that does not scale.

10. Exercises

Exercise 1 — four destinations. Run the same tool four ways and record cp.stdout for each.

Exercise 2 — measure the text. Capture 5,000 lines and print the character count and the average line length. Extrapolate to a twenty-million-line log.

Exercise 3 — nothing held. Run the same tool with stdout=handle and confirm cp.stdout is None while the file has every line.

Exercise 4 — the confusion. Write the capture-then-write version and the direct version. Confirm identical files and say what the first one held.

Exercise 5 — the other confusion. Send a one-line version query to a file and read it back. Say what you gained.

Exercise 6 — the question. For three tool calls in your own flow, answer "immediately or later" and assign a destination.

Exercise 7 — the bad byte. Make a stand-in tool emit a non-UTF-8 byte and capture it with text=True. Record the exception and how many good lines you lost.

Exercise 8 — three ways out. Repeat it with errors="replace", as bytes, and to a file handle. Say which one your flow should use by default.

Exercise 9 — when it raises. Say at what point in a one-hour simulation the UnicodeDecodeError appears, and what you have left.

Exercise 10 — merged order. Merge stdout and stderr into one log from a tool that alternates them. Record the order and explain it.

Exercise 11 — separate. Write them to two files and say what the empty err.log tells you in one check.

Exercise 12 — write then read. Implement run_and_log plus a streaming parser. Confirm nothing is fully in memory at either stage, and that the log survives a deliberate parser crash.

11. Summary

• Four destinations, one argument each: inherit the parent's streams, capture to memory, redirect to a file, or discard with DEVNULL.
• capture_output=True assembles the entire output as one string before your next line runs — 5,000 short lines is nearly 94,000 characters, and a real UVM line is four times longer.
• It is right when the output is small and wanted immediately — a version query, a tool that prints one JSON record.
• stdout=handle holds nothing. The operating system connects the child to the file and cp.stdout is None.
• Capture-then-write produces the same file by a route that cannot scale, and it looks thorough, which is why it gets written.
• The question is "immediately, or evidence for later?" Immediately means capture; later means a file.
• DEVNULL is for a tool whose output does not matter and whose status does — and a discarded log is a run that cannot be debugged.
• One non-UTF-8 byte makes text=True raise and destroys the whole capture, including every good line before it.
• It raises after the tool has finished, so an hour of compute is spent and there is no log, because you were holding it.
• Three ways out: errors="replace", capture as bytes, or a file handle — which has no decoding step in Python at all.
• Merging stdout and stderr puts the diagnostics first, because the child's stdout is block-buffered to a file and its stderr is not.
• Merge for a human reading one log; separate when ordering matters, when stdout is machine-readable, or to check whether stderr said anything at all.
• Write it, then read it. The tool streams to disk and the parser streams from disk, so nothing is ever fully in memory and the log survives a parser crash.
• Put errors="replace" on the read, where a bad byte costs one line instead of everything.

The next chapter keeps the file-handle approach and adds the thing it cannot do: showing a human what the tool is doing while it is still doing it.