Python Part II · Module 33 · Testing and Debugging Automation

Logging: Levels, Timestamps and What to Record

A regression that fails at three in the morning is debugged from whatever the script happened to write down. `print` writes for someone watching; a log writes for someone reading tomorrow, who needs to know when each thing happened and which of several hundred runs it belonged to. Python's logging module does all of that, and the two-line idiom everybody copies has a surprise in each line — the first names your logger something other than what you expect, and the second, as written, prints nothing at all.

Intermediate22 min readPythonPart IIAutomationLoggingDebugging

Part II · Module 33 · Chapter 33.10 · Logging: Levels, Timestamps and What to Record

1. Two Different Jobs

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

JOBS = [
    ("print", "someone watching now", "stdout", "no", "no"),
    ("print", "a consumer parsing it", "stdout", "no", "no"),
    ("logging", "someone reading tomorrow", "stderr", "yes", "yes"),
]

print(f"{'tool':<10} {'audience':<26} {'stream':<8} {'timestamped':<12} filterable")
for tool, who, stream, ts, filt in JOBS:
    print(f"{tool:<10} {who:<26} {stream:<8} {ts:<12} {filt}")

print()
print("why the stream matters:", "33.8 §6 — stdout is the data channel")
print("so a log on stderr      :", "cannot corrupt `tool.py > results.csv`")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

tool       audience                   stream   timestamped  filterable
print      someone watching now       stdout   no           no
print      a consumer parsing it      stdout   no           no
logging    someone reading tomorrow   stderr   yes          yes

why the stream matters: 33.8 §6 — stdout is the data channel
so a log on stderr      : cannot corrupt `tool.py > results.csv`

The stream column is the practical reason to care, and it connects straight back to Chapter 33.8 Section 6. A tool whose progress messages go through print writes them to stdout, where the data goes; the same messages through logging go to stderr by default, so tool.py > results.csv produces a clean CSV with the commentary still visible on the terminal. Logging is not only a nicer print — it is on the correct stream.

2. The Annotation

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

log = logging.getLogger(__name__)
log.info("run %s seed=%d -> %s", test, seed, status)

That is the idiom to copy, and both of its lines behave in a way most people do not expect the first time. Take them in order.

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import logging

log = logging.getLogger(__name__)

print("__name__ in the entry script:", repr(__name__))
print("so the logger is named      :", repr(log.name))
print()
print("logger's own level          :", log.level,
      "(" + logging.getLevelName(log.level) + ")")
print("root logger's level         :",
      logging.getLevelName(logging.getLogger().level))
print("effective level             :",
      logging.getLevelName(log.getEffectiveLevel()))
print()
print("isEnabledFor(DEBUG)   :", log.isEnabledFor(logging.DEBUG))
print("isEnabledFor(INFO)    :", log.isEnabledFor(logging.INFO))
print("isEnabledFor(WARNING) :", log.isEnabledFor(logging.WARNING))

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

__name__ in the entry script: '__main__'
so the logger is named      : '__main__'

logger's own level          : 0 (NOTSET)
root logger's level         : WARNING
effective level             : WARNING

isEnabledFor(DEBUG)   : False
isEnabledFor(INFO)    : False
isEnabledFor(WARNING) : True

Two facts, both worth keeping.

getLogger(__name__) in the script you actually run names the logger __main__, not after a module. The idiom's point is that every imported module gets a logger named after itself — flow.parsers.uvm, flow.report — which is what makes filtering by subsystem possible. In the entry script, __name__ is "__main__" and always has been; that is Chapter 13.6's guard fact reappearing where nobody expects it.

The logger's own level is NOTSET, so it inherits, and what it inherits is the root logger's WARNING. Which brings us to the second line of the annotation.

3. The Annotation's Second Line Prints Nothing

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import contextlib
import io
import logging

log = logging.getLogger(__name__)

test, seed, status = "axi_burst", 4121, "FAIL"

out, err = io.StringIO(), io.StringIO()
with contextlib.redirect_stdout(out), contextlib.redirect_stderr(err):
    log.info("run %s seed=%d -> %s", test, seed, status)
    log.warning("retrying %s", test)

print("after log.info and log.warning, with NO configuration:")
print("  stdout:", repr(out.getvalue()))
print("  stderr:", repr(err.getvalue()))
print()
print("the info line was        :", "discarded")
print("the warning line was     :", "emitted, to stderr, unformatted")
print("lines the annotation adds:", 0)

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

after log.info and log.warning, with NO configuration:
  stdout: ''
  stderr: 'retrying axi_burst\n'

the info line was        : discarded
the warning line was     : emitted, to stderr, unformatted
lines the annotation adds: 0

The annotation, copied exactly and run, produces no output. log.info is below the effective level of WARNING, so the record is created and dropped. The log.warning on the next line does appear — via logging's last-resort handler, with no timestamp, no level and no logger name — which is why a half-configured script shows a few bare warnings and nothing else.

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import io
import logging

log = logging.getLogger("flow.run")
cap = io.StringIO()
handler = logging.StreamHandler(cap)
handler.setFormatter(logging.Formatter("%(levelname)-8s %(name)s | %(message)s"))
log.addHandler(handler)
log.propagate = False
log.setLevel(logging.INFO)          # <- the line that was missing

test, seed, status = "axi_burst", 4121, "FAIL"
log.debug("filelist = %s", "rtl/files.f")
log.info("run %s seed=%d -> %s", test, seed, status)
log.warning("retrying %s", test)
log.error("giving up on %s after %d attempts", test, 2)

print(cap.getvalue(), end="")
print()
print("calls made   :", 4)
print("lines emitted:", len(cap.getvalue().strip().splitlines()))
print("suppressed   :", "the debug line — INFO is the threshold")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

INFO     flow.run | run axi_burst seed=4121 -> FAIL
WARNING  flow.run | retrying axi_burst
ERROR    flow.run | giving up on axi_burst after 2 attempts

calls made   : 4
lines emitted: 3
suppressed   : the debug line — INFO is the threshold

Now the annotation's line appears, and the debug call above it does not. One number — the level — decides which of four calls become lines.

4. Which Level for What

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import logging

LEVELS = [
    ("DEBUG", logging.DEBUG, "the exact command line, env vars, each file read",
     "off in a normal run"),
    ("INFO", logging.INFO, "one line per run: test, seed, status, duration",
     "on in a normal run"),
    ("WARNING", logging.WARNING, "retried, fell back, a stale file was used",
     "always on"),
    ("ERROR", logging.ERROR, "this run did not produce a result",
     "always on"),
    ("CRITICAL", logging.CRITICAL, "the sweep cannot continue at all",
     "always on"),
]

print(f"{'level':<10} {'num':>4}  {'what belongs here in a flow':<48} default")
for name, num, what, default in LEVELS:
    print(f"{name:<10} {num:>4}  {what:<48} {default}")

print()
print("the gap between levels:", LEVELS[1][1] - LEVELS[0][1])
print("so a custom level is possible:", "logging.addLevelName(25, 'NOTICE')")
print()
print("the test for INFO vs DEBUG:")
print("  would you want this line for a run that SUCCEEDED?  -> INFO")
print("  only when you are chasing something?               -> DEBUG")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

level       num  what belongs here in a flow                      default
DEBUG        10  the exact command line, env vars, each file read off in a normal run
INFO         20  one line per run: test, seed, status, duration   on in a normal run
WARNING      30  retried, fell back, a stale file was used        always on
ERROR        40  this run did not produce a result                always on
CRITICAL     50  the sweep cannot continue at all                 always on

the gap between levels: 10
so a custom level is possible: logging.addLevelName(25, 'NOTICE')

the test for INFO vs DEBUG:
  would you want this line for a run that SUCCEEDED?  -> INFO
  only when you are chasing something?               -> DEBUG

The last two printed lines are the only level rule worth memorising. Would you want this line in the log of a run that succeeded? A per-run summary — test, seed, status — yes, always: that is INFO, and it is what the annotation logs. The resolved filelist, every environment variable, each file opened — only when something is wrong: that is DEBUG.

WARNING has a sharper definition that is easy to blur. It is not "something a bit bad"; it is the run continued but not the way you asked. A retry, a fallback, a stale file accepted. Chapter 30.3's new-versus-fixed distinction depends on those lines existing, because a run that silently retried and then passed looks identical in the results to one that passed first time.

5. Why the Annotation Uses `%s` and Not an f-String

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import io
import logging


class CountsFormatting:
    """Records how many times something asked for its string form."""

    def __init__(self):
        self.calls = 0

    def __str__(self):
        self.calls += 1
        return "rtl/files.f (resolved, 412 entries)"


log = logging.getLogger("fmt")
log.addHandler(logging.StreamHandler(io.StringIO()))
log.propagate = False
log.setLevel(logging.WARNING)          # DEBUG and INFO are suppressed

a = CountsFormatting()
log.info("filelist = %s", a)
print("%-args, suppressed      : __str__ called", a.calls, "times")

b = CountsFormatting()
log.info(f"filelist = {b}")
print("f-string, suppressed    : __str__ called", b.calls, "times")

c = CountsFormatting()
log.warning("filelist = %s", c)
print("%-args, emitted         : __str__ called", c.calls, "times")

print()
print("the difference:", "%-args defer formatting to emit time")
print("so a DEBUG line in a hot loop costs:", "a function call and a compare")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

%-args, suppressed      : __str__ called 0 times
f-string, suppressed    : __str__ called 1 times
%-args, emitted         : __str__ called 1 times

the difference: %-args defer formatting to emit time
so a DEBUG line in a hot loop costs: a function call and a compare

Zero against one. This is the measured reason the annotation is written log.info("run %s seed=%d -> %s", test, seed, status) rather than as an f-string: the message and its arguments are stored on the record and only combined if something is going to emit it. A suppressed call never builds the string.

For three short strings that difference is invisible. For a log.debug inside a loop over every line of a 2 GB log — the case Chapter 20.6 was about — it is the difference between a debug statement you can leave in the code and one you have to delete.

The f-string, by contrast, is evaluated before log.info is called. Python builds the whole string, passes it in, and logging then throws it away. There is no level check that can save you, because the work already happened at the call site.

6. Naming Loggers So Filtering Works

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import io
import logging

cap = io.StringIO()
h = logging.StreamHandler(cap)
h.setFormatter(logging.Formatter("%(name)-18s %(levelname)-7s %(message)s"))
root = logging.getLogger("flow")
root.addHandler(h)
root.propagate = False
root.setLevel(logging.DEBUG)

parser = logging.getLogger("flow.parsers.uvm")
report = logging.getLogger("flow.report")
runner = logging.getLogger("flow.runner")

parser.debug("matched %d severity lines", 3)
runner.info("run %s seed=%d -> %s", "axi_burst", 4121, "FAIL")
report.info("wrote %s", "summary.csv")

print(cap.getvalue(), end="")
print()
# now quiet ONE subsystem without touching the others
parser.setLevel(logging.WARNING)
cap.truncate(0), cap.seek(0)
parser.debug("matched %d severity lines", 3)
runner.info("run %s seed=%d -> %s", "axi_lite", 7, "PASS")
print("after parser.setLevel(WARNING):")
print(cap.getvalue(), end="")
print()
print("parser lines now:", 0, "| runner lines still:", 1)
print("the hierarchy is:", "dots — flow.parsers.uvm inherits from flow")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

flow.parsers.uvm   DEBUG   matched 3 severity lines
flow.runner        INFO    run axi_burst seed=4121 -> FAIL
flow.report        INFO    wrote summary.csv

after parser.setLevel(WARNING):
flow.runner        INFO    run axi_lite seed=7 -> PASS

parser lines now: 0 | runner lines still: 1
the hierarchy is: dots — flow.parsers.uvm inherits from flow

One subsystem silenced, the rest untouched. That is what the annotation's getLogger(__name__) buys: because every module's logger is named after its import path, the dotted hierarchy already exists and logging.getLogger("flow.parsers").setLevel(...) turns down a whole subtree.

A script that calls logging.info(...) at module level instead — on the root logger — gets none of this. Every line has the same origin, and the only available decision is all or nothing.

7. Timestamps, and Making Them Testable

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import io
import logging
import re

cap = io.StringIO()
h = logging.StreamHandler(cap)
h.setFormatter(logging.Formatter("%(asctime)s %(message)s"))
log = logging.getLogger("ts")
log.addHandler(h)
log.propagate = False
log.setLevel(logging.INFO)

log.info("run started")
stamp = cap.getvalue().split(" run started")[0]

print("default asctime, digits masked:", re.sub(r"\d", "N", stamp))
print("length                        :", len(stamp))
print("millisecond field present     :", "," in stamp)
print()
print("so two runs produce            :", "different bytes")
print("and a golden-file comparison   :", "fails every time — 33.4")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

default asctime, digits masked: NNNN-NN-NN NN:NN:NN,NNN
length                        : 23
millisecond field present     : True

so two runs produce            : different bytes
and a golden-file comparison   : fails every time — 33.4

The default timestamp is %Y-%m-%d %H:%M:%S followed by a comma and three milliseconds — 23 characters, and every one of the last 19 changes between runs. That is correct for a log and fatal for a test, which is the tension Chapter 33.4 set up: a golden fixture needs byte-stable output, and a timestamp is the definition of unstable.

The fix is to make the formatter's clock an input:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import io
import logging
import time

FIXED = time.struct_time((2026, 3, 14, 9, 26, 53, 5, 73, 0))


def fixed_clock_handler(stream):
    """A handler whose timestamps do not move — for tests only."""
    h = logging.StreamHandler(stream)
    fmt = logging.Formatter("%(asctime)s %(levelname)-8s %(name)s | %(message)s",
                            datefmt="%Y-%m-%d %H:%M:%S")
    fmt.converter = lambda secs: FIXED
    h.setFormatter(fmt)
    return h


cap = io.StringIO()
log = logging.getLogger("flow.run")
log.addHandler(fixed_clock_handler(cap))
log.propagate = False
log.setLevel(logging.INFO)

log.info("run %s seed=%d -> %s", "axi_burst", 4121, "FAIL")
log.warning("retrying %s", "axi_burst")

print(cap.getvalue(), end="")
print()
EXPECTED = (
    "2026-03-14 09:26:53 INFO     flow.run | "
    "run axi_burst seed=4121 -> FAIL\n"
    "2026-03-14 09:26:53 WARNING  flow.run | retrying axi_burst\n"
)
print("byte-identical to the golden text:", cap.getvalue() == EXPECTED)
print("what changed in the code under test:", "nothing")
print("what the test controls              :", "the clock and the stream")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

2026-03-14 09:26:53 INFO     flow.run | run axi_burst seed=4121 -> FAIL
2026-03-14 09:26:53 WARNING  flow.run | retrying axi_burst

byte-identical to the golden text: True
what changed in the code under test: nothing
what the test controls              : the clock and the stream

A log line is now comparable byte for byte. Two things were made inputs rather than ambient facts — the stream, by handing the handler a StringIO, and the clock, by replacing formatter.converter. That is Chapter 33.2's seam argument applied to the two least obvious dependencies a log line has.

Note what was not changed: the code that calls log.info is identical in the test and in production. The annotation's line is written once and the test configures the world around it, which is the only arrangement that tests what actually ships.

8. A Malformed Log Call Does Not Raise

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import contextlib
import io
import logging

cap = io.StringIO()
h = logging.StreamHandler(cap)
h.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
log = logging.getLogger("bad")
log.addHandler(h)
log.propagate = False
log.setLevel(logging.INFO)

err = io.StringIO()
raised = None
with contextlib.redirect_stderr(err):
    try:
        log.info("run %s seed=%d", "axi_burst")      # one argument short
    except Exception as exc:
        raised = type(exc).__name__

print("exception seen by the caller :", raised)
print("record reached the handler   :", repr(cap.getvalue()))
print("stderr lines produced        :", len(err.getvalue().splitlines()))
print("stderr first line            :", repr(err.getvalue().splitlines()[0]))
print("TypeError named in there     :", "TypeError" in err.getvalue())
print()
print("so the line is               :", "lost")
print("and the program              :", "continued")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

exception seen by the caller : None
record reached the handler   : ''
stderr lines produced        : 19
stderr first line            : '--- Logging error ---'
TypeError named in there     : True

so the line is               : lost
and the program              : continued

No exception, no log line, and nineteen lines of complaint on a stream nobody reads. The handler received nothing — the record was built, formatting raised a TypeError inside emit, and logging swallowed it deliberately, on the principle that a logging call must never take down the program it is observing.

That principle is defensible and it has a consequence worth naming: a logging statement is the one statement in your script that can fail without failing. The information you most wanted — the one line describing the run that went wrong — is exactly the line that disappears, and the only evidence is on stderr, mixed in with everything else, in a run nobody is watching.

It gets quieter still:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import contextlib
import io
import logging

log = logging.getLogger("quiet")
log.addHandler(logging.StreamHandler(io.StringIO()))
log.propagate = False
log.setLevel(logging.INFO)

for flag in (True, False):
    logging.raiseExceptions = flag
    err = io.StringIO()
    with contextlib.redirect_stderr(err):
        log.info("seed=%d status=%s", 4121)      # one short, again
    print(f"raiseExceptions={str(flag):<6} stderr lines: "
          f"{len(err.getvalue().splitlines()):>2}")

logging.raiseExceptions = True
print()
print("the usual production setting:", False)
print("what it costs               :", "the only evidence a line was lost")
print("the mitigation              :", "a test that asserts the log TEXT — §7")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

raiseExceptions=True   stderr lines: 19
raiseExceptions=False  stderr lines:  0

the usual production setting: False
what it costs               : the only evidence a line was lost
the mitigation              : a test that asserts the log TEXT — §7

Nineteen lines, then none. logging.raiseExceptions = False is widely recommended for production, and it is the setting under which a malformed log call becomes completely invisible: no exception, no record, no complaint.

Which is the argument for Section 7's fixed-clock test. A test that asserts the text of the log line is the only thing that catches a format string whose arguments do not match it — because nothing at runtime ever will.

9. `basicConfig` Is a No-Op the Second Time

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import io
import logging

first, second = io.StringIO(), io.StringIO()

logging.basicConfig(stream=first, level=logging.INFO,
                    format="%(levelname)s %(name)s | %(message)s")
print("root handlers after the 1st call:", len(logging.getLogger().handlers))
print("root level after the 1st call   :",
      logging.getLevelName(logging.getLogger().level))

logging.basicConfig(stream=second, level=logging.DEBUG, format="SECOND %(message)s")
print("root handlers after the 2nd call:", len(logging.getLogger().handlers))
print("root level after the 2nd call   :",
      logging.getLevelName(logging.getLogger().level))

log = logging.getLogger("flow.runner")
log.debug("a debug line")
log.info("run %s seed=%d -> %s", "axi_burst", 4121, "FAIL")

print()
print("first stream :", repr(first.getvalue()))
print("second stream:", repr(second.getvalue()))
print()
print("the 2nd call changed the level :", False)
print("the 2nd call changed the format:", False)
print("the 2nd call changed the stream:", False)
print("to actually reconfigure        :", "basicConfig(..., force=True)")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

root handlers after the 1st call: 1
root level after the 1st call   : INFO
root handlers after the 2nd call: 1
root level after the 2nd call   : INFO

first stream : 'INFO flow.runner | run axi_burst seed=4121 -> FAIL\n'
second stream: ''

the 2nd call changed the level : False
the 2nd call changed the format: False
the 2nd call changed the stream: False
to actually reconfigure        : basicConfig(..., force=True)

The second call did nothing at all — not the level, not the format, not the stream, and the debug line it asked for never appeared. basicConfig returns early if the root logger already has a handler, which is almost always what you want (an imported library must not be able to reconfigure your logging) and is baffling the first time you hit it in your own script.

Two shapes trigger it in practice. A library you imported called basicConfig at import time, so yours is the second call. Or your own main() is invoked twice in one process — in a test, which is how it usually surfaces. force=True replaces the existing handlers; configuring logging once, in the entry script, before anything else avoids needing it.

10. The Run Logger, Assembled

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import io
import logging
import time

FIXED = time.struct_time((2026, 3, 14, 9, 26, 53, 5, 73, 0))


def build_run_logger(console_stream, file_stream, verbose=False):
    """Console gets the summary; the run file gets everything.

    Returns a logger with two handlers at different levels — the shape a
    flow wants, because the terminal and the archive have different readers.
    """
    log = logging.getLogger("flow")
    log.handlers.clear()
    log.propagate = False
    log.setLevel(logging.DEBUG)          # the handlers do the filtering

    def fmt(pattern):
        f = logging.Formatter(pattern, datefmt="%Y-%m-%d %H:%M:%S")
        f.converter = lambda secs: FIXED
        return f

    console = logging.StreamHandler(console_stream)
    console.setLevel(logging.DEBUG if verbose else logging.INFO)
    console.setFormatter(fmt("%(levelname)-8s %(message)s"))

    runfile = logging.StreamHandler(file_stream)
    runfile.setLevel(logging.DEBUG)
    runfile.setFormatter(fmt("%(asctime)s %(levelname)-8s %(name)s | %(message)s"))

    log.addHandler(console)
    log.addHandler(runfile)
    return log


console, runfile = io.StringIO(), io.StringIO()
log = build_run_logger(console, runfile)

runner = logging.getLogger("flow.runner")
parser = logging.getLogger("flow.parsers.uvm")

runner.debug("cmd = %s", "vvp sim.vvp +seed=4121")
runner.info("run %s seed=%d started", "axi_burst", 4121)
parser.debug("scanned %d lines", 48213)
parser.warning("truncated log: no TEST DONE line")
runner.info("run %s seed=%d -> %s", "axi_burst", 4121, "FAIL")
runner.error("run %s produced no results file", "axi_burst")

print("--- console (what a person watching sees)")
print(console.getvalue(), end="")
print("--- run file (what you read tomorrow)")
print(runfile.getvalue(), end="")
print()
print("calls made        :", 6)
print("console lines     :", len(console.getvalue().strip().splitlines()))
print("run file lines    :", len(runfile.getvalue().strip().splitlines()))
print("debug lines kept  :", "only in the file")
print("the run file is   :", "the evidence 33.13 is about")

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

--- console (what a person watching sees)
INFO     run axi_burst seed=4121 started
WARNING  truncated log: no TEST DONE line
INFO     run axi_burst seed=4121 -> FAIL
ERROR    run axi_burst produced no results file
--- run file (what you read tomorrow)
2026-03-14 09:26:53 DEBUG    flow.runner | cmd = vvp sim.vvp +seed=4121
2026-03-14 09:26:53 INFO     flow.runner | run axi_burst seed=4121 started
2026-03-14 09:26:53 DEBUG    flow.parsers.uvm | scanned 48213 lines
2026-03-14 09:26:53 WARNING  flow.parsers.uvm | truncated log: no TEST DONE line
2026-03-14 09:26:53 INFO     flow.runner | run axi_burst seed=4121 -> FAIL
2026-03-14 09:26:53 ERROR    flow.runner | run axi_burst produced no results file

calls made        : 6
console lines     : 4
run file lines    : 6
debug lines kept  : only in the file
the run file is   : the evidence 33.13 is about

Six calls, four console lines, six file lines. The logger's own level is DEBUG and the handlers filter, which is the arrangement that lets one call feed two readers at two verbosities. Set the level on the logger instead and the file loses the debug lines permanently, with no way to get them back.

The first DEBUG line in the run file is the one that pays for all of this. cmd = vvp sim.vvp +seed=4121 is the exact command, recorded at the moment it ran, and Chapter 33.14 is almost entirely about wanting that line and not having it.

11. Predict, Run, Observe

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

import contextlib
import io
import logging

log = logging.getLogger("pro")
cap = io.StringIO()
log.addHandler(logging.StreamHandler(cap))
log.propagate = False

# A
print("A:", log.getEffectiveLevel(), log.isEnabledFor(logging.INFO))

# B
log.setLevel(logging.INFO)
log.info("seed=%d", 4121)
print("B:", repr(cap.getvalue()))

# C
cap.truncate(0), cap.seek(0)
err = io.StringIO()
with contextlib.redirect_stderr(err):
    log.info("seed=%d run=%s", 4121)
print("C:", repr(cap.getvalue()), len(err.getvalue().splitlines()) > 0)

# D
print("D:", logging.getLogger("pro") is log,
      logging.getLogger("pro.child").parent is log)

The verified output:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

A: 30 False
B: 'seed=4121\n'
C: '' True
D: True True

A — 30 is WARNING, inherited from the root, and INFO is therefore off. Sections 2 and 3 as two values.

B — one setLevel and the same call now emits. Note there is no timestamp or level in the output: a bare StreamHandler has no formatter, so the message is all you get.

C — the malformed call from Section 8: nothing in the handler, and something on stderr. The line is lost and the program ran on.

D — getLogger with the same name returns the same object, and the dotted name wires the hierarchy automatically. That is why Section 6's filtering works without any registration step, and why getLogger(__name__) at the top of every module is enough.

12. Exercises

Exercise 1 — two audiences. For one of your scripts, list which messages are for someone watching and which are for someone reading tomorrow.

Exercise 2 — the stream. Confirm that logging writes to stderr and explain why that matters for tool.py > out.csv.

Exercise 3 — the logger's name. Print getLogger(__name__).name in your entry script and in an imported module. Explain the difference.

Exercise 4 — the silent annotation. Copy the annotation's two lines into an empty script, run it, and record the output.

Exercise 5 — why nothing appeared. Print the effective level and isEnabledFor(INFO) to explain it.

Exercise 6 — the one missing line. Add the setLevel or basicConfig call and confirm the line appears.

Exercise 7 — the last-resort handler. Log a warning with no configuration and describe exactly what the output lacks.

Exercise 8 — succeeded or not. For ten messages in your flow, assign a level using the "would I want this for a successful run?" test.

Exercise 9 — what WARNING means. Find a place in your flow that retries or falls back silently, and add the warning.

Exercise 10 — lazy formatting. Reproduce the zero-versus-one measurement with your own counting object.

Exercise 11 — the cost in a loop. Put a log.debug inside a loop over a large log, once with %s and once as an f-string, and say which you would ship.

Exercise 12 — evaluated at the call site. Explain in two sentences why no level check can rescue an f-string.

Exercise 13 — name your subsystems. Pick dotted logger names for the parsing, running and reporting parts of your flow.

Exercise 14 — quiet one. Silence one subsystem with a single setLevel and confirm the others still log.

Exercise 15 — root-only logging. Explain what you lose by calling logging.info(...) directly.

Exercise 16 — mask the timestamp. Print a default asctime with its digits masked and count the characters.

Exercise 17 — the golden-file problem. Say in one sentence why a timestamped log cannot be compared to a fixture.

Exercise 18 — a fixed clock. Write fixed_clock_handler and assert a log line byte for byte.

Exercise 19 — nothing in the code changed. Explain why that matters for what the test proves.

Exercise 20 — timezone. Switch a formatter to time.gmtime and say who benefits.

Exercise 21 — one argument short. Make a malformed log call and record what the caller sees, what the handler gets, and what reaches stderr.

Exercise 22 — fails without failing. Explain in two sentences why logging swallows the error, and what that costs.

Exercise 23 — raiseExceptions. Set it to False, repeat Exercise 21, and say what evidence remains.

Exercise 24 — the only defence. Write the test that would have caught the malformed format string.

Exercise 25 — basicConfig twice. Call it twice with different levels and confirm which one won.

Exercise 26 — why it returns early. Explain why a library must not be able to reconfigure your logging.

Exercise 27 — two handlers, two levels. Build the Section 10 logger for your own flow.

Exercise 28 — level on the handlers. Explain what breaks if you set the level on the logger instead.

Exercise 29 — the line that pays. Add the DEBUG line recording the exact command, and keep it.

Exercise 30 — read it back. Take a run file from your own flow and list three questions it cannot answer. Add the lines that would.

13. Summary

print is for someone watching; a log is for someone reading tomorrow — and logging defaults to stderr, so it cannot corrupt the data on stdout.
getLogger(__name__) in the entry script names the logger __main__. The idiom pays off in imported modules, where __name__ is the import path.
A logger's own level is NOTSET, so it inherits the root's WARNING.
The annotation's log.info line, run as written, prints nothing. It is the most common way a carefully-logged script writes nothing down, and nothing warns you.
A bare warning with no configuration still appears, via the last-resort handler, with no timestamp, level or logger name.
The level test is one question: would you want this line for a run that succeeded? Yes is INFO, only-when-chasing is DEBUG.
WARNING means the run continued but not the way you asked — a retry, a fallback, a stale file.
%-args defer formatting to emit time. A suppressed call formats its argument zero times; the f-string version formats it once, before logging is even entered.
Dotted logger names build the hierarchy for free, so one setLevel silences a subsystem and leaves the rest.
The default timestamp carries comma-milliseconds — 23 characters, unstable, and fatal to a golden-file comparison.
Replace formatter.converter to pin the clock, hand the handler a StringIO to pin the stream, and a log line becomes byte-comparable with no change to the code under test.
A malformed log call does not raise. The caller sees nothing, the handler receives nothing, and the complaint goes to stderr — or nowhere at all with raiseExceptions = False.
So a logging statement can fail without failing, and a test on the log text is the only thing that catches it.
basicConfig is a no-op once the root has a handler — not the level, format or stream. Use force=True, or configure once in the entry script.
Set the level on the handlers, not the logger, so one call can feed a quiet console and a complete run file.

The next chapter moves from recording what happened to refusing to start when the inputs are wrong.

Where this fits

Part of the Python curriculum.

1. Two Different Jobs

2. The Annotation

3. The Annotation's Second Line Prints Nothing

4. Which Level for What

5. Why the Annotation Uses %s and Not an f-String

6. Naming Loggers So Filtering Works

7. Timestamps, and Making Them Testable

8. A Malformed Log Call Does Not Raise

9. basicConfig Is a No-Op the Second Time

10. The Run Logger, Assembled

11. Predict, Run, Observe

12. Exercises

13. Summary

Where this fits

5. Why the Annotation Uses `%s` and Not an f-String

9. `basicConfig` Is a No-Op the Second Time