Follow a run while it happens: logs.sh

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 |

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 |

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-<execution>-g<generation>` 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 |

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 job's container>`. 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-<execution>-g<generation>; 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