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