Observable Python Automation — the run and its witnesses

A run that leaves no record is indistinguishable from a run that never happened.

§ IFrame — The Fourth Rung

The Python-track Ops arc has climbed three rungs. The 07-24 lesson taught how a single step fails and what the program owes the operator: retry, degrade, or fail loud. The 07-27 lesson scaled that to two hundred hosts and made the partial-failure ledger the deliverable. The 07-30 lesson made the tool installable: a package with entry points, a library a fleet can share.

Today the installed tool runs at 06:30 with nobody watching. That sentence is the whole lesson. An ops tool graduates the moment it runs unattended, and at that moment every prior discipline turns invisible unless the run writes its own witness. The operator at the keyboard could see the traceback. Cron sees nothing.

This is not staged for teaching. This morning's Fajr cycle opened, per its own runbook, by probing two files: a failure flag and a heartbeat. The heartbeat was absent. Absence is a verdict with two readings that could hardly differ more: either the publisher never ran, or it ran and nothing recorded the running. Call the failure mode the silent success: the run that worked, told no one, and taught the operator to trust silence. Silence then means "healthy" right up until the day it means "dead," and no one can say which day that was.

The cure is a discipline of three artifacts, the three witnesses in the cards above: three witnesses, three readers.

§ IIFoundations — Why print() Is Not a Witness

Python's logging system rewards ten minutes of actual study, and Python for DevOps gives it exactly that (ch. 7, Deeper Configuration, pp. 290-293). Four objects, one pipeline: the logger is the named entry point the code calls; a handler routes a record to a destination; a formatter turns the record into bytes worth reading; a filter drops or annotates records in flight.

The names form a tree. hedronite.sync.fetch is a child of hedronite.sync, and records climb to every ancestor's handlers. This is why library code takes one line, logging.getLogger(__name__), and never touches handlers. The 07-30 lesson made __name__ the module's address on the import path; the logging tree reuses that address, so the package layout you shipped is the logging topology you query. Configuration belongs to the application, at the entry point, once. A library that installs its own handlers is a houseguest rearranging the kitchen.

Two habits follow. First, levels carry semantics (DEBUG 10 → CRITICAL 50), a volume knob turned at the entry point without touching call sites; the 07-24 taxonomy maps directly: retried transient logs WARNING, degraded enrichment logs WARNING with the degradation named, fail-loud logs ERROR with exc_info=True so the traceback travels inside the record. Second, lazy interpolation: logger.debug("parsed %s rows", n) formats only if a handler will emit it; an f-string formats always, and a hot loop pays that tax at production volume.

So why not print()? Print has one reader, one destination, no level, no timestamp, no source address, no off switch. A log record has all six. The difference is the difference between talking and testifying.

§ IIIMechanism — Records a Machine Can Read

The default formatter writes for a human tailing a terminal. The unattended run's first reader is more often a machine: a grep, a dashboard, a shipper feeding an index (the road that ends at Elasticsearch, pp. 303-305). The on-disk shape that makes this cheap is JSON Lines: one JSON object per line, append-only, no enclosing array; a writer can always append, a reader can always tail.

import json, logging, time

class JsonFormatter(logging.Formatter):
    def format(self, record):
        doc = {
            "ts": time.strftime("%Y-%m-%dT%H:%M:%S%z", time.localtime(record.created)),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
            "run_id": getattr(record, "run_id", None),
        }
        if record.exc_info:
            doc["exc"] = self.formatException(record.exc_info)
        return json.dumps(doc, ensure_ascii=False)

The field that earns its place is run_id. One invocation produces dozens of lines; the id is the thread that strings them back into one story when three nights of runs interleave in one file. Mint it at entry (uuid4().hex[:12]), attach it with a LoggerAdapter or filter so no call site has to remember it. This is the 07-27 partial-failure ledger grown up: the ledger now writes itself into the log stream and survives the process.

The heartbeat answers the question logs answer badly: is the thing alive? Store the timestamp as the artifact itself, written at the end of a successful run, replaced atomically:

import json, os, tempfile

def write_heartbeat(path, run_id, started, finished, outcome):
    doc = {"run_id": run_id, "started": started,
           "finished": finished, "outcome": outcome}
    fd, tmp = tempfile.mkstemp(dir=os.path.dirname(path))
    with os.fdopen(fd, "w") as f:
        f.write(json.dumps(doc))
    os.replace(tmp, path)

os.replace is the move that matters. Write a sibling temp file, rename over the target: POSIX rename is atomic within a filesystem, so every reader sees a complete heartbeat, old or new, never a torn one. The probe on the other side is arithmetic, and this morning's Fajr ran precisely it: read, parse the stamp, compare age against cadence, and treat file missing as its own verdict. Fresh proves liveness. Stale proves stoppage. Missing proves the recording leg was never installed, a finding about the instrument rather than the patient, and the distinction changes who gets paged.

The exit code is the third witness. Exit 0 means success; anything else means failure; every supervisor since the epoch agrees on nothing else so completely. Let the code be computed, not sprinkled: one sys.exit(main()), with main() returning 0 or the count of fatal failures. The 07-24 fail-loud rule lands with nowhere left to hide: a script that catches, logs, and wanders to the end of main returns 0 and has told its supervisor the opposite of the truth.

§ IVWorked Example — Instrumenting nightly-sync

Take nightly-sync as it ships in the 07-30 package (fetch, enrich, write) and give it witnesses. Library modules change by one line each: logger = logging.getLogger(__name__), plus level-true calls at each decision 07-24 already routed. The entry point gains configuration and verdict:

import logging, sys, time, uuid

from hedronite_ops import sync, witness

def main() -> int:
    run_id = uuid.uuid4().hex[:12]
    started = time.strftime("%Y-%m-%dT%H:%M:%S%z")
    root = logging.getLogger()
    handler = logging.StreamHandler()
    handler.setFormatter(witness.JsonFormatter())
    handler.addFilter(witness.RunId(run_id))
    root.addHandler(handler)
    root.setLevel(logging.INFO)
    log = logging.getLogger("hedronite.sync.cli")

    ledger = sync.run_all(deadline_s=30)
    finished = time.strftime("%Y-%m-%dT%H:%M:%S%z")
    fatal = [r for r in ledger if r.grade == "fatal"]
    outcome = "fail" if fatal else "ok"
    log.info("sync finished: %d ok, %d degraded, %d fatal",
             *ledger.counts())
    witness.write_heartbeat("state/sync-heartbeat.json",
                            run_id, started, finished, outcome)
    if fatal:
        witness.write_flag("state/sync-fail.flag", run_id, fatal)
        return 1
    return 0

if __name__ == "__main__":
    sys.exit(main())

Trace one bad night. Enrich degrades on two hosts; fetch dies on one essential host. The log stream carries the story as JSON Lines, every line stamped with the same run_id, the fatal one carrying its traceback. The heartbeat lands with "outcome": "fail", because the run completed; a heartbeat is a completion record, not a health certificate, and conflating the two rebuilds the silent success one layer up. The flag file lands beside it naming the fatal host. The process returns 1, and cron's mail, for once, is worth opening.

At fleet scale the probe costs two file reads, so a supervisor sweeps fifty tools' heartbeats in a millisecond without parsing a log. Logs answer what happened; the heartbeat answers are you alive; the exit code answers should someone come now. None substitutes for another.

§ VConnection to Prior Lessons

One sentence per rung. 07-24 decided what a failure is; here each grade testifies (WARNING, WARNING-with-name, ERROR-plus-flag-plus-nonzero). 07-27 built the partial-failure ledger inside one run; here the ledger's verdict survives the process and its rows carry a run_id thread. 07-30 drew the library/application boundary; logging respects it exactly, loggers in the library, handlers at the entry point, and the module addresses packaging fixed become the logging topology operations queries.

§ VIConnection to Today's Dev Lesson

The Dev lesson takes the witness module and asks what a sink, a formatter, a ledger row are to the type checker. The answer is a Protocol: a structural contract the file sink, the stdout sink, and the test's in-memory sink all satisfy without inheriting from anything. The pairing is deliberate: Ops built the witnesses, Dev makes their contracts checkable before the run nobody watches.

§ VIIClosing

The unattended run is the normal run. Three witnesses, always: the log line for the investigator, the heartbeat for the prober, the exit code for the supervisor. Write the heartbeat atomically. Compute the exit code, never assume it. When a probe finds silence, remember the two readings of absence: the cure for one is a fix, the cure for the other is an instrument.

Drill the JsonFormatter and the heartbeat writer until they are muscle. Then go look at one of your own cron jobs and ask it: who would know?