From 53e5be4056cdb39d2694ce74baf1d8407ee768fe Mon Sep 17 00:00:00 2001 From: makseq Date: Mon, 10 Aug 2026 18:49:18 +0300 Subject: [PATCH] Follow a run while it happens: logs.sh MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The output of a step is hard to read for a reason nobody guesses on their first attempt: the agent removes a job's container when the job ends. `docker logs` on the container you wanted therefore finds nothing, and the runs most worth reading are exactly the short ones that went wrong. logs.sh attaches at the moment a container STARTS, by watching the daemon's event stream and filtering on the lspo.agent label the agent puts on every job container — so on a machine running several agents it follows only this one's work. It can also tail the agent itself, which is the journal that explains a run that never started at all: a refused image pull, a credentials directory it could not write, an environment variable outside the allowlist. None of those ever reach a container, so none of them appears in a node's log. ./logs.sh agent | node | both (both is the default) Verified against a container carrying the agent's own labels: the watcher caught it at start and streamed its lines through to exit. docs/OPERATIONS.md gains a section saying why it is needed and which of the two journals to trust — the platform keeps a tail of the last 1000 lines and the durable copy is built from that same trimmed buffer, so the copy on the machine is the complete one. The troubleshooting table gains the row that sends people there, because "the output was gone before I could read it" is the symptom, and its cause is not a bug to hunt. It reads and never writes, nothing in the contract mentions it, and a node that never runs it is in no way worse off. The inventory rows say so. Co-Authored-By: Claude Opus 5 --- CLAUDE.md | 1 + README.md | 1 + docs/OPERATIONS.md | 41 ++++++++++++++++++++++ logs.sh | 85 ++++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 128 insertions(+) create mode 100755 logs.sh diff --git a/CLAUDE.md b/CLAUDE.md index 2c0eab6..9c34b01 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -17,6 +17,7 @@ below exists to serve both without lying to either. |---|---| | `node.py` | A complete, correct example step. Copy it and edit | | `Dockerfile` | The smallest image that is a real external step | +| `logs.sh` | Follows the agent and the job containers it starts, live. An operator's convenience, not part of the contract | | `docs/` | **The documentation. Start here** | | `conformance/` | A black-box harness: it builds this image, runs it, judges it from the outside only | | `tests/` | The tests that harness runs | diff --git a/README.md b/README.md index 72dfb59..06a903d 100644 --- a/README.md +++ b/README.md @@ -55,6 +55,7 @@ digest, hand it over. |---|---| | `node.py` | A complete, correct example step. Copy it and edit | | `Dockerfile` | The smallest image that is a real external step | +| `logs.sh` | Follows the agent and the job containers it starts, live. An operator's convenience, not part of the contract | | `docs/` | **The documentation. Start here** | | `conformance/` | A black-box harness: it builds this image, runs it, and judges it only from the outside | | `tests/` | The tests that harness runs, and `pytest.ini` names the label on each one | diff --git a/docs/OPERATIONS.md b/docs/OPERATIONS.md index f890fd3..ec622c2 100644 --- a/docs/OPERATIONS.md +++ b/docs/OPERATIONS.md @@ -500,6 +500,46 @@ which you cannot change from a node. --- +## Watching a run, live + +**BEHAVIOUR, and it is why `docker logs` on its own is not the answer.** The agent removes +a job's container when the job ends. So the container whose output you want is gone by the +time you go looking for it, and the runs worth reading are exactly the short ones that went +wrong. To see a step's own output on the machine that ran it you have to attach at the +moment the container **starts**. + +`logs.sh` in this repository does that, by watching the docker daemon's event stream: + +```bash +./logs.sh agent # the agent: claims, heartbeats, container lifecycle +./logs.sh node # every job container the agent starts, from its first line +./logs.sh both # the two interleaved and tagged (the default) +``` + +**BEHAVIOUR.** Job containers are named `lspo--g` and carry the +labels the agent puts on them, including `lspo.agent` with the agent's own name — which is +what lets the script follow only the work this agent started on a machine running several. + +**RECOMMENDATION.** Start it before you start the run rather than after. The interesting +part of a failing step is usually its first three lines, and those are the ones a container +that has already exited can no longer show you. + +**BEHAVIOUR, and it decides which of the two journals to trust.** The same node output is +shipped to the orchestrator and appears live in the run view, which is the only option when +the agent is on somebody else's machine. It is not the same document: the platform keeps a +tail of the last **1000 lines** and drops the oldest when a run is chattier than that, and +the durable copy stored with the execution is built from that same trimmed buffer (see +[PROTOCOL.md](PROTOCOL.md#33-logging), which is also why a step should say the +important things once, at the end, in few lines). The copy on the machine is the whole of +it, for as long as the container lives. + +**BEHAVIOUR.** The agent's own journal is an ordinary `docker logs -f lspo-agent`, and it +is the one that explains a run which never started at all: a refused image pull, a +credentials directory it could not write, an environment variable outside the allowlist. +None of those ever reach a container of yours, so none of them appears in a node's log. + +--- + ## Troubleshooting **The table below is labelled row by row, in its Kind column**, rather than by one label @@ -535,6 +575,7 @@ two rows where that distinction bites are marked inline. | A cancelled run's partial output does not reach anything downstream | nothing was collected, because cancelling a step whose container is **still running** does not read its marker | BEHAVIOUR — by design, on both branches of the cancellation race. One exception, and it is not about a running container: a cancellation arriving while collection is **already under way** lets that collection finish, and what it verified is attached to the cancelled run as diagnostics under no output port — visible in the artifact browser, readable by nobody downstream ([PROTOCOL.md](PROTOCOL.md#7-cancellation)) | nothing to fix in the node. If partial output matters, let the step finish or fail on its own rather than cancelling it | | Logs stop partway through | you exceeded the shipping rate, or a single line exceeded 64 KiB and its tail was discarded | BEHAVIOUR — the excess is dropped silently | fewer, shorter lines | | Logs never appear at all | a logging library that defaults to WARNING and to stderr only, or a buffered stdout | Unchecked | configure the logger explicitly and set `PYTHONUNBUFFERED=1` | +| A container's output is gone before you could read it | the agent removes a job's container when the job ends | BEHAVIOUR — nothing is retained locally afterwards | attach at the start instead: [Watching a run, live](#watching-a-run-live) | | Log lines arrive mangled, with stray `[31m` in them | you printed ANSI colour; the escape byte is stripped as a control character and the rest survives | BEHAVIOUR | print plain text | | The node runs but downstream steps see nothing | the objects were inventoried but claimed under no output port | BEHAVIOUR — an unclaimed object is verified and kept, but not offered downstream | claim them under a port; `produced_ports` is what becomes downstream artifacts | | A configuration key on the node seems to do nothing | unknown keys are accepted and ignored | BEHAVIOUR — validation ignores what it does not recognise | check the spelling against the configuration table above | diff --git a/logs.sh b/logs.sh new file mode 100755 index 0000000..5fedf96 --- /dev/null +++ b/logs.sh @@ -0,0 +1,85 @@ +#!/usr/bin/env bash +# Follow, in real time, what this machine is doing for the orchestrator. +# +# ./logs.sh agent the runner agent: claims, heartbeats, container lifecycle +# ./logs.sh node every job container the agent starts, from its first line +# ./logs.sh both the two interleaved and tagged (the default) +# +# WHY THIS EXISTS, rather than `docker logs `. The agent removes a +# job's container when the job ends, so by the time anybody thinks to look there is +# nothing left to look at — and the runs worth reading are exactly the short ones that +# went wrong. This attaches at the moment a container STARTS, by watching the daemon's +# event stream, so it catches the first line. +# +# The same node output also appears live in the orchestrator's run view, which is the +# only option when the agent runs on somebody else's machine. The two differ in +# completeness and it matters: the platform keeps a tail of the last 1000 lines and +# drops the oldest when a run is chattier than that (docs/PROTOCOL.md section 3.3). +# What this shows is the whole of it. +# +# Nothing here is part of the contract. It is an operator's convenience, it reads and +# never writes, and a node that never runs it is in no way worse off. +set -uo pipefail + +AGENT_CONTAINER="${LSPO_AGENT_CONTAINER:-lspo-agent}" +MODE="${1:-both}" + +case "$MODE" in + agent|node|both) ;; + -h|--help) sed -n '2,20p' "$0" | sed 's/^# \{0,1\}//'; exit 0 ;; + *) echo "usage: $0 [agent|node|both]" >&2; exit 2 ;; +esac + +if ! command -v docker >/dev/null 2>&1; then + echo "docker is not on PATH; this script talks to the daemon the agent talks to." >&2 + exit 1 +fi + +if ! docker inspect "$AGENT_CONTAINER" >/dev/null 2>&1; then + echo "no container called '$AGENT_CONTAINER' on this machine." >&2 + echo "the agent is started by the docker run line the Connect reply prints; see" >&2 + echo "docs/OPERATIONS.md. If yours is named differently, set LSPO_AGENT_CONTAINER." >&2 + exit 1 +fi + +if [ "$(docker inspect -f '{{.State.Running}}' "$AGENT_CONTAINER")" != "true" ]; then + echo "WARNING: '$AGENT_CONTAINER' is not running, so no job will ever start." >&2 + echo " start it with: docker start $AGENT_CONTAINER" >&2 + echo >&2 +fi + +# The name the agent enrolled under. The agent puts it on every job container as the +# lspo.agent label (agent/executors/docker_exec.py, labels_for), so filtering on it +# follows only the work THIS agent started, on a machine that runs more than one. +AGENT_NAME="$(docker inspect -f \ + '{{range .Config.Env}}{{if eq (index (split . "=") 0) "LSPO_AGENT_NAME"}}{{index (split . "=") 1}}{{end}}{{end}}' \ + "$AGENT_CONTAINER" 2>/dev/null)" +AGENT_NAME="${AGENT_NAME:-$(hostname)}" + +CHILDREN=() +cleanup() { for pid in "${CHILDREN[@]:-}"; do kill "$pid" 2>/dev/null; done; } +trap cleanup EXIT INT TERM + +if [ "$MODE" != "node" ]; then + ( docker logs -f --tail 20 "$AGENT_CONTAINER" 2>&1 | sed -u 's/^/[agent] /' ) & + CHILDREN+=($!) +fi + +if [ "$MODE" != "agent" ]; then + echo "[watch] following job containers started by agent '$AGENT_NAME'" + echo "[watch] they are named lspo--g; nothing appears until a run starts" + ( + docker events --filter 'type=container' --filter 'event=start' \ + --filter "label=lspo.agent=$AGENT_NAME" \ + --format '{{.Actor.Attributes.name}}' 2>/dev/null | + while read -r container; do + [ -n "$container" ] || continue + echo "[watch] job container started: $container" + ( docker logs -f "$container" 2>&1 | sed -u "s|^|[$container] |" + echo "[watch] $container finished" ) & + done + ) & + CHILDREN+=($!) +fi + +wait