Job sheet 004 · Worked example Verified

Observe CI commands

Hooks, structured events, and the opt-in GitHub Actions sink that folds each run into a log group.

Verified 2026-10-19 · Cuprum 0.2.0b2 · Python 3.12 · Linux

ObservabilityCI

01 — Problem

The job

A CI job runs commands nobody is watching. When one fails, the log should say which, with its output grouped where a reader can find it, and the job's own telemetry should record every run without anyone parsing output.

Cuprum reports a run through three channels at once here: structured lifecycle events to an observe hook, start and exit records through the standard logging module with logging_hook, and the echoed output framed for GitHub Actions by GitHubActionsSink.

02 — Before you start

Before you start

Level: Intermediate
Needs: Python 3.12 or later, which stands in for a test runner; the flags run also needs python3 on PATH
Install: Cuprum 0.2.0b2 from PyPI; see Getting started
Tested: 2026-10-19 against Cuprum 0.2.0b2 on Linux, Python 3.12; every run repeated eight times, identical apart from the random stop-commands token; the flags run with GITHUB_ACTIONS=true and python3 on PATH
Uses: sh.observe, ExecEvent, logging_hook, cuprum.sinks.GitHubActionsSink, RunOutputOptions(group=..., annotate_failure=...)

03 — Code

The code

ci_step.py Complete

import io
import logging
import sys

from cuprum import (
    Program,
    ProgramCatalogue,
    RunOutputOptions,
    logging_hook,
    scoped,
    sh,
)
from cuprum.sinks import GitHubActionsSink

PYTHON = Program(sys.executable)
CATALOGUE = ProgramCatalogue.from_programs(PYTHON, name="ci")
python = sh.make(PYTHON, catalogue=CATALOGUE)

events = []


def collect(event):
    events.append((event.phase, event.exit_code))


logging.basicConfig(level=logging.INFO, format="%(name)s %(levelname)s %(message)s")
workflow_log = io.StringIO()
sink = GitHubActionsSink(workflow_log, title="Unit tests", force=True)

with (
    scoped(catalogue=CATALOGUE),
    sh.observe(collect),
    logging_hook(logger=logging.getLogger("ci.commands")),
):
    result = python("-c", "print('42 passed')").run_sync(
        output=RunOutputOptions(echo=True, sink=sink),
    )

print("result:", result.ok, repr(result.stdout))
print("phases:", [phase for phase, _ in events])
print("workflow log:")
print(workflow_log.getvalue(), end="")

Verified 2026-10-19 · Cuprum 0.2.0b2 · Python 3.12 · Linux

04 — Output

Expected output

Expected outputstdout

result: True '42 passed\n'
phases: ['plan', 'start', 'stdout', 'exit', 'settled']
workflow log:
::group::Unit tests
::stop-commands::949162b00dd838c9
42 passed
::949162b00dd838c9::
::endgroup::

The hook saw five ExecEvent phases: the plan, the start, the output, the exit, and settled, which closes every observed execution exactly once with a bounded terminal_outcome (here exit_zero), even when no child ever started. Each event also carries the program, the argument vector, and an exec_id that ties one run's events together, plus the process ID and timings where the phase has them: the plan has no process yet, and a spawn failure settles without one.

The workflow log is what GitHub Actions reads: the output inside a collapsible group titled Unit tests. The ::stop-commands:: pair around it, with a token that is random on every run, stops the child's own output being read as workflow commands. The cuprum.start and cuprum.exit records went to the ci.commands logger on stderr.

05 — Failure path

When it fails

The same step, failing. The sink adds one error annotation, titled after the group, which GitHub shows on the job summary.

ci_step_fails.py Failure path

import io
import sys

from cuprum import Program, ProgramCatalogue, RunOutputOptions, scoped, sh
from cuprum.sinks import GitHubActionsSink

PYTHON = Program(sys.executable)
CATALOGUE = ProgramCatalogue.from_programs(PYTHON, name="ci")
python = sh.make(PYTHON, catalogue=CATALOGUE)

FAIL = "import sys; print('1 failed, 41 passed'); sys.exit(1)"

workflow_log = io.StringIO()
sink = GitHubActionsSink(workflow_log, title="Unit tests", force=True)

with scoped(catalogue=CATALOGUE):
    result = python("-c", FAIL).run_sync(
        output=RunOutputOptions(echo=True, sink=sink),
    )

print("result:", result.ok, result.exit_code)
print(workflow_log.getvalue(), end="")

Verified 2026-10-19 · Cuprum 0.2.0b2 · Python 3.12 · Linux

Observed outputstdout

result: False 1
::group::Unit tests
::stop-commands::6bcf93e9497b517e
1 failed, 41 passed
::6bcf93e9497b517e::
::endgroup::
::error title=Unit tests::exit_nonzero

The run's result is unchanged by the framing: ok is False and the exit code is 1, and capture still holds the output. The sink activates by itself when GITHUB_ACTIONS is true; force=True reproduces the framing elsewhere, as here.

On the runner: two flags, no sink

A job that only wants the group and the annotation can skip the sink. group=True and annotate_failure=True on RunOutputOptions build a GitHubActionsSink for the run, so one options object can be shared by every step. The flags carry no force: they act only when GITHUB_ACTIONS is true, and write to the parent's stderr. This step calls python3 from PATH, so the group's default title is the command line itself.

ci_step_flags.py On the runner

from cuprum import Program, ProgramCatalogue, RunOutputOptions, scoped, sh

PYTHON = Program("python3")
CATALOGUE = ProgramCatalogue.from_programs(PYTHON, name="ci")
python = sh.make(PYTHON, catalogue=CATALOGUE)

# One options object for every step; inert off GitHub Actions.
CI_OUTPUT = RunOutputOptions(echo=True, group=True, annotate_failure=True)

FAIL = "import sys; print('1 failed, 41 passed'); sys.exit(1)"

with scoped(catalogue=CATALOGUE):
    result = python("-c", FAIL).run_sync(output=CI_OUTPUT)

print("result:", result.ok, result.exit_code, repr(result.stdout))

Verified 2026-10-19 · Cuprum 0.2.0b2 · Python 3.12 · Linux

Observed outputGITHUB_ACTIONS=true, stdout and stderr

::group::python3 -c import sys; print('1 failed, 41 passed'); sys.exit(1)
::stop-commands::977dbae16495e769
1 failed, 41 passed
::977dbae16495e769::
::endgroup::
::error title=ci%3A python3::exit_nonzero
result: False 1 '1 failed, 41 passed\n'

Observed outputGITHUB_ACTIONS unset

1 failed, 41 passed
result: False 1 '1 failed, 41 passed\n'

The group is titled with the whole command line, arguments included, so it appears in the step's log. The annotation, which GitHub also shows on the job summary, carries only the run's bounded label, ci: python3 (escaped as ci%3A in the workflow command), and never an argument. Off the runner the flags do nothing: the output is echoed as usual and the result is the same. An explicit sink= always wins over the flags, so a step that needs its own title passes a sink as the first two runs do.

06 — Why it is allowed

Why the policy permits it

The catalogue lists only this interpreter, and scoped(catalogue=...) makes it the block's allowlist. The observe hook and the logging hook are registrations local to the block: leaving it removes them, so a library that runs commands elsewhere in the process is not observed by accident.

The logging hook records argv in full. Pass secrets through a file rather than as arguments, or give the hook a RedactionPolicy as Keep secrets out of telemetry shows, and never turn untrusted arguments into metric labels.