Streaming a Tool's Output While It Runs

Part II · Module 23 · Chapter 23.6 · Streaming a Tool's Output While It Runs

1. run Waits

import sys

for index in range(5):
    print(f"UVM_INFO step {index}")
print("TEST DONE")

import subprocess
import sys

print("before the call")
cp = subprocess.run([sys.executable, "steps.py"], capture_output=True, text=True)
print("after the call — and only now is there anything to show:")
for line in cp.stdout.strip().splitlines():
    print("   " + line)

before the call
after the call — and only now is there anything to show:
   UVM_INFO step 0
   UVM_INFO step 1
   UVM_INFO step 2
   UVM_INFO step 3
   UVM_INFO step 4
   TEST DONE

Every line arrived at once, after the tool had finished — Chapter 23.1 Section 2's starts the program, waits for it to finish, returns.

For a tool that takes a second that is invisible. For an elaboration that takes forty minutes it means a terminal showing nothing, and the two states a user most wants to tell apart — working and hung — look exactly the same.

2. Popen and the Line Loop

import sys

for index in range(5):
    print(f"UVM_INFO step {index}")
print("TEST DONE")

import subprocess
import sys

with subprocess.Popen([sys.executable, "steps.py"],
                      stdout=subprocess.PIPE, text=True) as proc:
    for line in proc.stdout:
        print("   saw:", line.rstrip())

print("returncode:", proc.returncode)

   saw: UVM_INFO step 0
   saw: UVM_INFO step 1
   saw: UVM_INFO step 2
   saw: UVM_INFO step 3
   saw: UVM_INFO step 4
   saw: TEST DONE
returncode: 0

That is the canonical annotation:

with subprocess.Popen(cmd, stdout=subprocess.PIPE, text=True) as p:
    for line in p.stdout:
        handle(line)

subprocess.Popen starts the program and returns immediately. The child runs alongside your script, and proc.stdout is a file-like object connected to its output — so for line in proc.stdout is Chapter 15.4's loop over a file, reading lines as the child produces them rather than from disk.

Three details that are not optional.

stdout=subprocess.PIPE is what creates the connection. Without it the child inherits the parent's stdout and there is nothing to read.

text=True gives strings instead of bytes, exactly as in Chapter 23.5 — and the same encoding caution applies, with errors="replace" available for the same reason.

The with waits for the child and closes the pipe when the block ends. Without it, leaving the block early leaves a running child and an open pipe — and the returncode never gets filled in.

3. returncode Is None Until It Is Not

import sys

for index in range(5):
    print(f"UVM_INFO step {index}")
sys.exit(1)

import subprocess
import sys

with subprocess.Popen([sys.executable, "steps.py"],
                      stdout=subprocess.PIPE, text=True) as proc:
    first = proc.stdout.readline().rstrip()
    print("first line        :", first)
    print("rc inside the block:", proc.returncode)
    print("`rc != 0` is       :", proc.returncode != 0)
    for _ in proc.stdout:
        pass

print("rc after the block :", proc.returncode)

first line        : UVM_INFO step 0
rc inside the block: None
`rc != 0` is       : True
rc after the block : 1

Inside the block proc.returncode is None, because the child has not exited — there is no status yet to report.

That is the commonest Popen bug, and the third line of output is why: None != 0 is True, so a classification written inside the loop treats every run as a failure, including the ones that go on to succeed. It is a quiet bug because the code reads correctly and the structure is the mistake.

Two ways to get the status, and either is fine:

Let the with block end and read proc.returncode afterwards, as above. The block calls wait() on the way out.

Call proc.wait() explicitly when you need the status before the block ends — it blocks until the child exits and returns the code.

proc.poll() is the non-blocking version: it returns None if the child is still running and the status if it has finished. It is for a loop doing something else while it waits, which is Chapter 26.x's territory rather than this one.

4. Show and Save at Once

A streaming loop is also where a log gets written, which is the shell | tee that Chapter 22.4 Section 6 warned destroys the exit status:

import sys

for index in range(5):
    print(f"UVM_INFO step {index}")
print("tool: a warning", file=sys.stderr)
print("TEST DONE")
sys.exit(1)

import subprocess
import sys
from pathlib import Path

shown = 0
with open("sim.log", "w", encoding="utf-8") as log, \
     subprocess.Popen([sys.executable, "steps.py"],
                      stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
                      text=True) as proc:
    for line in proc.stdout:
        log.write(line)
        if line.startswith("UVM_ERROR") or "TEST DONE" in line:
            print("   >>", line.rstrip())
        shown += 1

print("lines teed  :", shown)
print("log on disk :", len(Path("sim.log").read_text(encoding="utf-8").splitlines()))
print("returncode  :", proc.returncode)

   >> TEST DONE
lines teed  : 7
log on disk : 7
returncode  : 1

Every line went to the log; only the interesting ones went to the screen. And proc.returncode is 1 — the tool's own status, which a shell | tee would have replaced with tee's.

That is the real advantage of doing this in Python rather than in a shell, and it is worth being explicit: the shell pipeline shows progress and loses the status; this shows progress, saves the log, filters what a human sees, and keeps the status.

The filtering is the part a shell cannot do at all. Chapter 20.7's pattern could go in that if, so the screen shows errors and the log keeps everything — which on a forty-minute elaboration is the difference between watching and reading.

5. A Streaming Reader Does Not Make a Buffering Tool Stream

Here is the disappointment that follows writing the loop:

import subprocess
import sys
import time

CHILD = ("import sys, time\n"
         "for i in range(3):\n"
         "    print('UVM_INFO step', i)\n"
         "time.sleep(30)\n")

for flags, label in (([], "default   "), (["-u"], "python3 -u")):
    with subprocess.Popen([sys.executable] + flags + ["-c", CHILD],
                          stdout=subprocess.PIPE, text=True) as proc:
        time.sleep(0.6)
        proc.kill()
        received = proc.stdout.read()
    print(f"{label} -> lines received before the kill: {len(received.splitlines())}"
          f"  {received.splitlines()}")

default    -> lines received before the kill: 0  []
python3 -u -> lines received before the kill: 3  ['UVM_INFO step 0', 'UVM_INFO step 1', 'UVM_INFO step 2']

Both children printed three lines and then slept. The reader was identical. The default child delivered none of them.

The cause is Chapter 22.5 Section 5's, now on the other side of the boundary: the child's stdout is a pipe, so the child block-buffers it, holding the lines until a few kilobytes accumulate or the process exits. Three short lines is nowhere near a few kilobytes, so they sat in the child's buffer — and when the child was killed, they went with it.

python3 -u makes the child unbuffered and all three arrive immediately.

This is the single most important thing in the chapter, because of how it presents in practice: you write the loop, run it against a real tool, see nothing for ten minutes, and conclude the loop is broken. It is not. The tool is buffering, your reader is correct, and nothing you write in the parent can change it — the buffering decision is made inside the child, by code you did not write.

6. What Actually Helps

The parent cannot unbuffer the child, so the options are all about asking the child nicely:

The tool's own flag. Most EDA tools have one — a line-buffered or unbuffered output mode, often spelled -unbuffered, -linedebug or similar, and sometimes an environment variable. This is the first thing to look for and the only one that is both reliable and supported.

PYTHONUNBUFFERED=1 or -u, for a Python child. Which matters more than it sounds: half the things a flow runs are other Python scripts, and Chapter 22.6's composed tools are all Python.

import os
import subprocess
import sys

CHILD = "import sys, time\nfor i in range(2):\n    print('step', i)\ntime.sleep(30)\n"

for env, label in ((None, "no env     "), ({**os.environ, "PYTHONUNBUFFERED": "1"}, "UNBUFFERED")):
    import time
    with subprocess.Popen([sys.executable, "-c", CHILD], stdout=subprocess.PIPE,
                          text=True, env=env) as proc:
        time.sleep(0.6)
        proc.kill()
        received = proc.stdout.read()
    print(f"{label} -> {len(received.splitlines())} line(s)")

no env      -> 0 line(s)
UNBUFFERED -> 2 line(s)

A pseudo-terminal, which makes the child believe its output is a terminal and line-buffer accordingly. It works, it is a real technique, and it brings its own complications — Python's pty module is Unix-only and the output then contains whatever control sequences the tool emits for a terminal. Worth knowing it exists; not worth reaching for first.

Accept it and write the log instead. If the tool will not stream, Chapter 23.5's file handle is better than a streaming loop that shows nothing — the log is on disk as the tool flushes, and tail -f on it gives the user the progress view directly, with no Python in the middle.

That last option is the honest default for a tool you do not control. A streaming loop is worth writing when the tool cooperates, and a liability when it does not, because it adds a pipe, a loop and a buffering question in exchange for a blank screen.

7. The Deadlock Not to Write

One shape must be avoided, and it is easy to arrive at:

# DO NOT WRITE THIS
with subprocess.Popen(cmd, stdout=subprocess.PIPE,
                      stderr=subprocess.PIPE, text=True) as proc:
    for line in proc.stdout:       # reads stdout only
        handle(line)

Two pipes, and the loop reads one of them. A pipe holds a limited amount; once the child has written that much to stderr and nobody has read it, the child blocks waiting for space — and it therefore stops writing to stdout, so the loop blocks waiting for a line that will never come. Neither side can proceed.

That is not demonstrated in this chapter, deliberately: a correct demonstration hangs forever, and it would hang the process verifying these examples.

Two safe shapes:

Merge the streams, which is what Section 4 did — stderr=subprocess.STDOUT means there is one pipe and reading it drains everything.

Send stderr somewhere that cannot fill, a file or DEVNULL:

import sys

for index in range(3):
    print(f"UVM_INFO step {index}")
    print(f"tool: note {index}", file=sys.stderr)

import subprocess
import sys
from pathlib import Path

with open("sim.err", "w", encoding="utf-8") as errlog, \
     subprocess.Popen([sys.executable, "steps.py"], stdout=subprocess.PIPE,
                      stderr=errlog, text=True) as proc:
    lines = [line.rstrip() for line in proc.stdout]

print("stdout streamed :", lines)
print("stderr on disk  :", len(Path("sim.err").read_text(encoding="utf-8").splitlines()))
print("returncode      :", proc.returncode)

stdout streamed : ['UVM_INFO step 0', 'UVM_INFO step 1', 'UVM_INFO step 2']
stderr on disk  : 3
returncode      : 0

One pipe, one file, no way to deadlock — and stderr is still kept.

proc.communicate() is the third safe option: it reads both pipes concurrently and returns them. It also waits for the child and returns everything at once, so it is subprocess.run with extra steps — useful when you need two separate captures and not when you want to stream.

8. When run Is Still Right

Popen costs a pipe, a loop, a buffering question and a deadlock to avoid. subprocess.run costs none of those, and Chapters 23.2 to 23.5 used it throughout for good reason.

Use Popen with a streaming loop when all three hold:

• the tool runs long enough that silence is a problem,
• the tool's output actually streams — Section 5,
• and somebody is watching, or something downstream needs lines as they arrive.

Use run with a file handle otherwise, which is most of a flow: a sweep running four hundred tests in a scheduler has nobody watching any individual one, and the log on disk is what gets read afterwards.

The intermediate case is worth naming because it is common: a long tool that nobody is watching, which you still want a progress line from. A streaming loop writing one line per thousand to stderr — Chapter 22.5's channel for commentary — gives a nightly log you can tell apart from a hang, at a cost of a few lines.

9. Predict, Run, Observe

import sys

print("a")
print("b")
print("to stderr", file=sys.stderr)
sys.exit(2)

import subprocess
import sys

# A
with subprocess.Popen([sys.executable, "steps.py"], stdout=subprocess.PIPE,
                      stderr=subprocess.STDOUT, text=True) as proc:
    inside = proc.returncode
    lines = [line.rstrip() for line in proc.stdout]
print("A:", inside)

# B
print("B:", proc.returncode)

# C
print("C:", sorted(lines))

# D
print("D:", inside != 0, proc.returncode != 0)

# E
with subprocess.Popen([sys.executable, "steps.py"], stdout=subprocess.PIPE,
                      stderr=subprocess.DEVNULL, text=True) as p2:
    n = sum(1 for _ in p2.stdout)
print("E:", n)

# F
p3 = subprocess.Popen([sys.executable, "steps.py"], stdout=subprocess.DEVNULL,
                      stderr=subprocess.DEVNULL)
print("F:", p3.returncode, p3.wait(), p3.returncode)

The verified output:

A: None
B: 2
C: ['a', 'b', 'to stderr']
D: True True
E: 2
F: None 2 2

A — inside the block there is no status yet.

B — after the block there is.

C — merged streams, so all three lines came through the one pipe.

D — both are True, and the first one is the bug: None != 0 passes a test meant to detect failure.

E — with stderr discarded, only the two stdout lines arrive.

F — returncode is None before wait(), wait() returns the status, and afterwards the attribute holds it too.

10. Exercises

Exercise 1 — the silence. Run a multi-line tool with subprocess.run and confirm nothing appears until it finishes.

Exercise 2 — the loop. Rewrite it with Popen and a line loop. Confirm lines appear as they arrive.

Exercise 3 — three requirements. Remove stdout=subprocess.PIPE, then text=True, then the with. Record what breaks in each case.

Exercise 4 — None is not zero. Read proc.returncode inside the block and evaluate != 0. Say what a classification written there would report.

Exercise 5 — get it properly. Obtain the status both by leaving the block and by calling wait(). Confirm they agree.

Exercise 6 — tee with the status. Stream to the screen and a log at once, and confirm proc.returncode is still the tool's.

Exercise 7 — filter. Show only lines matching a Module 19 pattern while logging everything. Say what a shell pipeline could not do here.

Exercise 8 — the buffering. Run a child that prints and then sleeps, kill it, and count the lines received with and without -u.

Exercise 9 — not your bug. Explain in two sentences why the parent cannot fix the child's buffering.

Exercise 10 — what helps. For one real tool in your flow, find out whether it has an unbuffered or line-buffered output option. Record what you found.

Exercise 11 — the missing tail. Say why a tool killed at a timeout may have a log whose last lines are not the last thing it did.

Exercise 12 — the deadlock shape. Write down the two-pipe shape and say in one sentence why it hangs. Then write both safe versions.

Exercise 13 — which function. For three tool calls in your flow, choose run or Popen and give the reason from Section 8's three conditions.

11. Summary

• subprocess.run does not return until the tool finishes, so a forty-minute elaboration is forty minutes of blank terminal and working looks like hung.
• subprocess.Popen starts the program and returns immediately, and proc.stdout is a file-like object you can loop over as the child produces lines.
• Three parts are required: stdout=subprocess.PIPE to create the connection, text=True for strings, and the with to wait and close.
• proc.returncode is None inside the block, and None != 0 is True — so a classification written there reports every run as a failure.
• Get the status by leaving the with block or calling wait(); poll() is the non-blocking version.
• A streaming loop can tee and filter: everything to the log, only the interesting lines to the screen, and the tool's own exit status kept — which a shell | tee destroys.
• A streaming reader does not make a buffering tool stream. A child printing three lines to a pipe and then being killed delivered none of them; the same child under -u delivered all three.
• The buffering happens inside the child and the parent cannot change it. The loop is not the bug.
• So a tool killed at its timeout may lose whatever was still buffered, and the log's last line is the last thing flushed rather than the last thing done.
• What helps: the tool's own unbuffered flag, PYTHONUNBUFFERED=1 for a Python child, a pseudo-terminal, or accepting it and writing a log that tail -f can follow.
• Never read one pipe while the other fills. Two PIPEs and a single-stream loop deadlock, because the child blocks writing to the pipe nobody is draining.
• Safe shapes: merge with stderr=subprocess.STDOUT, or send stderr to a file or DEVNULL. communicate() reads both but waits.
• Use Popen only when the tool is long, its output streams, and somebody needs the lines — otherwise run with a file handle, which is most of a flow.

The next chapter is about where all of this happens, because a tool writes its artefacts wherever it is standing.