From ac2f310d102f1e424df23e7872c28faea27b8039 Mon Sep 17 00:00:00 2001 From: ducoterra Date: Fri, 30 Oct 2026 22:53:57 -0400 Subject: [PATCH] Say what an image build is doing, and keep saying it A build is the slow part of a first run and the thing --install triggers: apt, a Node tarball, an npm install. Every byte of podman's transcript used to go to a log file, so minutes of silence looked exactly like a wedge -- and a wedge is what people interrupt, leaving a half-built image. One line per build step, plus a notice every AISB_BUILD_QUIET_SECS (15) that a step has shown the terminal nothing, whether it is producing output the view drops or no output at all. AISB_BUILD_OUTPUT=progress|full|quiet picks how much the terminal sees; the complete transcript stays in $AISB_STATE_DIR/build-*.log in all three, because the progress view is a filter and a failed build has to be diagnosable from the raw apt output. The first line names the extra packages going in, which is what answers "why is this run building when the last one did not". podman build writes its transcript to *stdout* -- the same stdout the $(ensure_image ...) call reads back as the image ref -- so the transcript is routed onto stderr and the ref stays one clean line. A failed build now names the package apt could not find instead of pointing at a file to go read, and reports the time it took. Resolving a digest by pulling the base says so too: that is a download of the base image. tests/unit/11_build.sh stubs podman for both heartbeat paths and checks the ref, the failure text and that a canary credential appears nowhere. LLM-Generated: true --- AGENTS.md | 12 +++ README.md | 31 +++++++- bin/ai-sandbox | 147 ++++++++++++++++++++++++++++++++++-- docs/recipes.md | 7 +- tests/unit/11_build.sh | 166 +++++++++++++++++++++++++++++++++++++++++ 5 files changed, 353 insertions(+), 10 deletions(-) create mode 100755 tests/unit/11_build.sh diff --git a/AGENTS.md b/AGENTS.md index 352be2a..96f62f0 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -140,6 +140,18 @@ networking or the image, `make e2e` green too. * `split_target()` / `classify_allows()` — the mapping from what the user typed to what the firewall and the proxy enforce. * `build_argv()` — every isolation flag lives here. +* `build_in()` / `build_progress()` — a build is minutes of apt, a Node tarball and an + npm install, so it has to announce itself and keep announcing: silence is what a hang + looks like from the terminal, and an interrupted build is a half-built image. Note that + `podman build` writes its transcript to **stdout** — the same stdout that the + `$(ensure_image ...)` call reads back as the image ref — so the transcript is routed + onto stderr. Print it + to stdout and the build log comes back spliced into the ref. Whatever the terminal shows + (`AISB_BUILD_OUTPUT=progress|full|quiet`), the complete transcript belongs in + `$AISB_STATE_DIR/build-*.log`, because the progress view is a filter and a failed build + has to be diagnosable from the raw apt output. Tests: `tests/unit/11_build.sh` (a stub + podman, both heartbeat paths, the ref stays one clean line, a canary value appears + nowhere). * `resolve_workdir()` / `mirror_block_of()` — what the project is called inside the container. Mirroring the host path is the convenience; the deny list is the safety, because a bind hides whatever the image has at that destination and podman puts `--tmpfs /tmp` on diff --git a/README.md b/README.md index 22f46e8..0d88577 100644 --- a/README.md +++ b/README.md @@ -233,6 +233,34 @@ distinct policy and tagged by content hash: git, curl, jq, build tools, python3, PKG` adds packages and produces a different tag, so variants coexist, and `--base-image` swaps the base. +### A build is not a hang + +A run whose policy names an image that does not exist yet — a first run, a new +`--install`, a refreshed base, a new release of ai-sandbox itself — builds that image +before it starts anything: apt, a Node tarball, an `npm install`. Tens of seconds to a +few minutes, said out loud as it happens: + +```console +ai-sandbox: building the sandbox image with 2 extra package(s): rustc cmake -- one build per policy change, reused by every run after it +ai-sandbox: build: localhost/ai-sandbox:ubuntu-1a2b3c4d5e6f (transcript: ~/.local/state/ai-sandbox/build-sandbox-1a2b3c4d5e6f.log) +ai-sandbox: build: [4/21] RUN apt-get update && apt-get install -y --no-install-recomme +ai-sandbox: build: still on [4/21] RUN apt-get update && apt-get install -y --no-in (52s, 61s total) +ai-sandbox: built localhost/ai-sandbox:ubuntu-1a2b3c4d5e6f in 84s +``` + +One line per build step, plus a notice every `AISB_BUILD_QUIET_SECS` (15) that a step has +shown nothing — a step downloading a toolchain and a step wedged look identical from the +terminal, and only the clock tells them apart. The names go in the first line because +that is what answers "why is *this* run building when the last one did not". + +Whatever the terminal shows, the **complete** transcript of every build is written to +that file under `AISB_STATE_DIR`, and the last 25 lines of it are printed when a build +fails — with the package names called out, since a name apt has never heard of is what +`--install` usually gets wrong and it drowns in the package lists. +`AISB_BUILD_OUTPUT=full` streams podman's raw transcript instead; `=quiet` shows only the +announcements. None of it goes to stdout: `podman build` writes its progress there, and +this script's stdout is the image ref the run is then started with. + ### The base is pinned by digest A tag is a moving pointer: `FROM ubuntu:24.04` means "whatever Canonical points at @@ -274,7 +302,8 @@ ai-sandbox ps | clean [--all] [--volumes[=GLOB]] | inspect | gate up|status|logs ``` State lives under `~/.local/state/ai-sandbox` (session dirs, `log` of every run -with no secret values, build logs). Config in `~/.config/ai-sandbox`. +with no secret values, and `build-*.log` — the full transcript of each image build, +which is what to read when a build fails). Config in `~/.config/ai-sandbox`. `/home/sandbox` is a named volume (`aisb-home`) so npm and tool caches survive between runs. It outlives the image, so after changing the image you may be looking diff --git a/bin/ai-sandbox b/bin/ai-sandbox index 1f2a58a..e162642 100755 --- a/bin/ai-sandbox +++ b/bin/ai-sandbox @@ -34,6 +34,18 @@ AISB_IMAGE_REPO="${AISB_IMAGE_REPO:-localhost/ai-sandbox}" AISB_GATE_IMAGE_REPO="${AISB_GATE_IMAGE_REPO:-localhost/ai-sandbox-gate}" AISB_PI_PACKAGE="${AISB_PI_PACKAGE:-@earendil-works/pi-coding-agent}" +# How much of an image build to show while it runs. A build is the slow part of a first +# run and the thing --install triggers: apt, a Node tarball, an npm install. It has to +# look like work, because minutes of silence look like a wedge and a wedge is what +# people interrupt. progress = one line per step plus a notice while a step runs without +# showing anything worth reading; full = podman's whole transcript; quiet = neither. The +# complete transcript is written to $AISB_STATE_DIR/build-*.log in all three. +AISB_BUILD_OUTPUT="${AISB_BUILD_OUTPUT:-progress}" +# How long a build may go without showing the terminal anything (a step working quietly, +# or a step producing output the progress view drops) before it says it is still going. +# 0 turns the notice off, and a build that is genuinely stuck looks stuck again. +AISB_BUILD_QUIET_SECS="${AISB_BUILD_QUIET_SECS:-15}" + # The knobs below are deliberately NOT defaulted here. A value set in the # environment has to beat a config file, and a config file has to beat the # built-in default -- so the built-in defaults live in resolve_opts() and the @@ -226,7 +238,9 @@ IMAGE registry digest at build time; REF may itself already be a digest (name@sha256:...) to take that decision away. --install PKG Extra apt package in the image. Repeatable. - Each distinct set gets its own cached image tag. + Each distinct set gets its own cached image tag, so a new set + means a build: the run names the packages going in, says + which step it is on, and says so again if a step goes quiet. --harness NAME Default in-container command: pi | codex | claude | none. PI CONFIG @@ -300,6 +314,12 @@ CONFIG AISB_BASE_AUTO_UPDATE (0 keeps the recorded digest), AISB_BASE_PULL_FALLBACK (0 forbids the 'podman pull' used to learn a digest when skopeo is absent), AISB_SKOPEO. + Builds: AISB_BUILD_OUTPUT = progress (default: one line per build step, plus a notice + whenever the terminal has seen nothing for a while, so a slow step is not a hung one) + | full (podman's whole transcript) | quiet. AISB_BUILD_QUIET_SECS (15) is that + threshold, 0 to drop the notice. A build's complete transcript is written to + $AISB_STATE_DIR/build-*.log either way, and the last 25 lines of it are always shown, + with the offending package named, when a build fails. EXIT STATUS The exit code of the in-container command. 77/78: the sandbox refused to start @@ -1199,7 +1219,11 @@ base_digest_online() { # $1=ref -> digest from the registry, empty when unreacha # That is fine for an update and rude for an ordinary run, so it can be turned off # with AISB_BASE_PULL_FALLBACK=0 (the tests do exactly that, to stay offline). if [[ -z "$d" && "${AISB_BASE_PULL_FALLBACK:-1}" == 1 ]]; then - if podman pull -q "$ref" > /dev/null 2>&1; then + # The second thing that can sit silent for a minute: this is a download of the whole + # base image. podman's progress lines go to stderr and are left there; only the image + # id on stdout is dropped, since the digest is what this function is after. + log " no skopeo on the host: resolving the digest this way pulls $ref first" + if podman pull "$ref" > /dev/null; then d="$(podman image inspect "$ref" --format '{{.Digest}}' 2>/dev/null)" fi fi @@ -1407,6 +1431,14 @@ ensure_image() { # $1=sandbox|gate [[ "${OPT_IMAGE_EXISTS_OK:-0}" == 1 ]] && podman image exists "$ref" && { printf '%s\n' "$ref"; return 0; } if podman image exists "$ref"; then printf '%s\n' "$ref"; return 0; fi [[ "${OPT_NO_BUILD:-0}" == 1 ]] && die "image $ref is not built (and --no-build was given). Run: $PROG build" + # Named before the first thing that can take a minute (resolving the Node checksum is + # a network call of its own), and naming the extra packages says why this run builds + # and the last one did not. + local why="building the sandbox image" + if ((${#P_install[@]})); then + why+=" with ${#P_install[@]} extra package(s): ${P_install[*]}" + fi + log "$why -- one build per policy change, reused by every run after it" ctx="$AISB_CACHE_DIR/build/sandbox-$(image_hash)" rm -rf "$ctx"; mkdir -p "$ctx" containerfile > "$ctx/Containerfile" @@ -1421,6 +1453,7 @@ ensure_image() { # $1=sandbox|gate ref="$(gate_image_ref)" if podman image exists "$ref"; then printf '%s\n' "$ref"; return 0; fi [[ "${OPT_NO_BUILD:-0}" == 1 ]] && die "gate image is not built (and --no-build was given). Run: $PROG build --gate" + log "building the egress gate image (squid)" ctx="$AISB_CACHE_DIR/build/gate-$(sha12 "$ref")" rm -rf "$ctx"; mkdir -p "$ctx" gate_containerfile > "$ctx/Containerfile" @@ -1431,17 +1464,112 @@ ensure_image() { # $1=sandbox|gate printf '%s\n' "$ref" } +# One line of "still here": which step, how long that step has taken, how long the build +# has taken. Silence and a hang look identical from the terminal, and this is the only +# way to tell them apart while a step is doing something we are not printing. +build_beat() { # $1=step label (may be empty) $2=epoch the step began $3=epoch the build began + if [[ -n "$1" ]]; then + log "build: still on ${1:0:52} ($(( $(date +%s) - $2 ))s, $(( $(date +%s) - $3 ))s total)" + else + log "build: still working ($(( $(date +%s) - $3 ))s so far)" + fi +} + +# The live view of a build: podman's transcript in on stdin, one readable line per step +# out on stdout (the caller puts that on *our* stderr), and a notice every so often while +# a step is running -- whether it is producing output we choose not to print (an apt +# resolving 33 MB of package lists) or no output at all (a tarball downloading). Always +# exits 0: the pipeline's status is podman's business, not this one's. +build_progress() { # $1=epoch seconds at build start $2=seconds between notices + local t0="$1" quiet="$2" line rc pos instr step="" t_step t_last shown + local -a topt=() + if (( quiet > 0 )); then topt=(-t "$quiet"); fi + t_step="$(date +%s)"; t_last="$t_step" + while :; do + if IFS= read -r "${topt[@]}" line; then + shown=0 + case "$line" in + STEP\ *) + pos="${line#STEP }"; instr="${pos#*: }" + step="[${pos%%:*}] ${instr:0:64}" + t_step="$(date +%s)" + log "build: $step"; shown=1 + ;; + # The pull is the other half of "what is happening now": before the first STEP + # there is a download of the base image, and it is not a step. Layer results are + # not ("--> " says nothing a numbered STEP line does not, cache hit included). + "Trying to pull "*|"Getting image source"*|"Copying "*|"Writing manifest "*|COMMIT*) + log "build: ${line:0:88}"; shown=1 + ;; + # Anything that reads as a failure gets through even here. A build that dies + # quietly is worse than forty lines of apt. + "Error:"*|"error:"*|"E: "*|"Err: "*|"dpkg:"*|"npm error "*|"npm ERR!"*|*"exit status"*) + log "build: ${line:0:120}"; shown=1 + ;; + esac + if (( shown )); then + t_last="$(date +%s)" + elif (( quiet > 0 )) && (( $(date +%s) - t_last >= quiet )); then + build_beat "$step" "$t_step" "$t0"; t_last="$(date +%s)" + fi + else + rc=$? + if (( rc > 128 )); then # a read timeout, not the end of the output + build_beat "$step" "$t_step" "$t0"; t_last="$(date +%s)" + continue + fi + break # end of the transcript + fi + done + return 0 +} + build_in() { local ctx="$1" ref="$2"; shift 2 - local logf + local mode="${AISB_BUILD_OUTPUT:-progress}" logf rc=0 secs t0 t1 + case "$mode" in + progress|full|quiet) ;; + *) warn "AISB_BUILD_OUTPUT='$mode' is not progress, full or quiet; using progress" + mode=progress ;; + esac + secs="${AISB_BUILD_QUIET_SECS:-15}" + if [[ ! "$secs" =~ ^[0-9]+$ ]]; then + warn "AISB_BUILD_QUIET_SECS='$secs' is not a number; using 15"; secs=15 + fi mkdir -p "$AISB_STATE_DIR" logf="$AISB_STATE_DIR/build-$(basename "$ctx").log" - if podman build -t "$ref" "$@" "$ctx" > "$logf" 2>&1; then - log "built $ref" + # Opened before the build starts: a state directory that cannot hold a log should fail + # here rather than halfway through a five-minute build, with the transcript lost. + : > "$logf" || die "cannot write the build log at $logf -- nothing was built" + log "build: $ref (transcript: $logf)" + t0="$(date +%s)" + # podman build writes its transcript to *stdout*, and ensure_image()'s callers read + # stdout as the image ref -- so the transcript is routed onto stderr. tee keeps every + # byte in the log file whatever the terminal gets, and with pipefail rc is the worst of + # the stages: only podman and tee can fail here, and tee only if the log went away. + case "$mode" in + full) podman build -t "$ref" "$@" "$ctx" 2>&1 | tee "$logf" >&2 || rc=$? ;; + quiet) podman build -t "$ref" "$@" "$ctx" > "$logf" 2>&1 || rc=$? ;; + *) podman build -t "$ref" "$@" "$ctx" 2>&1 | tee "$logf" \ + | build_progress "$t0" "$secs" >&2 || rc=$? ;; + esac + t1="$(date +%s)" + if (( rc == 0 )); then + log "built $ref in $((t1 - t0))s" rm -rf "$ctx" else + # The reason, not just the fact: in progress mode the apt/dpkg output that explains a + # failure was deliberately not shown, and it is three hundred lines up in the log. tail -25 "$logf" >&2 - die "image build failed for $ref (full log: $logf)" + # The commonest failure by far is a name apt has never heard of, and it drowns in the + # package lists. Saying "a package could not be installed" is not feedback; naming it + # is, and that is the one thing --install gets wrong. + local -a miss=() + mapfile -t miss < <(sed -n 's/^E: Unable to locate package //p' "$logf") + if ((${#miss[@]})); then + die "image build failed for $ref: no such apt package: ${miss[*]} (check the name; full transcript: $logf)" + fi + die "image build failed for $ref after $((t1 - t0))s (full transcript: $logf)" fi } @@ -2324,9 +2452,12 @@ cmd_update() { printf 'gate image %s -> %s\n' "$old_gref" "$new_gref" fi fi + # No "built ..." here: a build that ran has already reported itself with the time it + # took, and a build that was not needed has nothing to say. These two lines name what + # to run against, whichever happened. local ref gref - ref="$(ensure_image sandbox)"; log "built $ref" - if (( want_gate )); then gref="$(ensure_image gate)"; log "built $gref"; fi + ref="$(ensure_image sandbox)"; log "sandbox image: $ref" + if (( want_gate )); then gref="$(ensure_image gate)"; log "gate image: $gref"; fi printf 'the previous image is kept for rollback; remove it with: podman rmi %s\n' "$old_ref" } diff --git a/docs/recipes.md b/docs/recipes.md index 03906b2..de779dc 100644 --- a/docs/recipes.md +++ b/docs/recipes.md @@ -332,9 +332,14 @@ A project whose tests need something the image lacks gets it from the launcher: sandbox-pi () { export AI_API_TOKEN=$(pass aipi/dev-token) ai-sandbox --allow aipi.reeseapps.com --allow pypi.org --allow files.pythonhosted.org \ - --install 'python3-pip ripgrep' --env AI_API_TOKEN "$@" + --install python3-pip --install ripgrep --env AI_API_TOKEN "$@" } ``` +A new `--install` set is a new image tag, so the first run after changing it builds: that +one run says which packages are going in and reports every step until the image exists +(`AISB_BUILD_OUTPUT=quiet` if you would rather it did not talk). Every later run starts +without a word about the image, because there is nothing left to do. + `doctor`, `inspect`, `clean` and the rest of ai-sandbox work unchanged underneath it — `--status` prints the policy the launcher will apply, without applying it. diff --git a/tests/unit/11_build.sh b/tests/unit/11_build.sh new file mode 100755 index 0000000..0544901 --- /dev/null +++ b/tests/unit/11_build.sh @@ -0,0 +1,166 @@ +#!/usr/bin/env bash +# tests/unit/11_build.sh -- feedback while an image is being built. +# +# The bug this file exists for: a build is the slow part of a first run and the thing +# --install triggers, and every byte of podman's transcript used to go to a log file. +# Minutes of silence reads as a hang. So these tests ask the running script what a user +# would see, with a stub for podman rather than a container. +# +# The stub stands in for the two behaviours of the real thing that this file is about: +# 'image exists' answers no, so a build is needed, and 'build' writes its transcript to +# *stdout* (measured on podman 5: that is where podman build writes) -- which is the one +# thing the script must never let reach its own stdout, because ensure_image()'s stdout +# is read back as the image ref. +source "$TESTS/lib.sh" + +PROJ="$WORK/proj"; mkdir -p "$PROJ"; cd "$PROJ" || exit 1 + +BIN="$WORK/bin"; mkdir -p "$BIN" +cat > "$BIN/podman" <<'EOS' +#!/usr/bin/env bash +case "${1:-} ${2:-}" in + "image exists") exit 1 ;; + "build -t") + # what the build was invoked with, so a credential smuggled into a --build-arg + # shows up in the transcript and the canary test below fails + printf 'STUB-BUILD-ARGS: %s\n' "$*" + # the packages the build was actually handed, read back out of --build-arg, so this + # transcript names what the policy under test asked for instead of a fixed guess + pkgs="" + for a in "$@"; do + case "$a" in AISB_EXTRA_PACKAGES=*) pkgs="${a#*=}" ;; esac + done + printf 'Trying to pull docker.io/library/ubuntu:24.04...\n' + printf 'Getting image source signatures\n' + printf 'STEP 1/3: FROM docker.io/library/ubuntu:24.04\n' + printf 'STEP 2/3: RUN apt-get update && apt-get install -y%s\n' "${pkgs:+ $pkgs}" + for ((i = 0; i < "${AISB_STUB_NOISE:-20}"; i++)); do + printf 'Get:%d http://archive.ubuntu.com/ubuntu noble/main amd64 curl amd64 8.5.0-1 [11 MB]\n' "$i" + sleep "${AISB_STUB_NOISE_DELAY:-0}" + done + sleep "${AISB_STUB_SLEEP:-0}" + if [[ "${AISB_STUB_RC:-0}" != 0 ]]; then + printf 'Reading package lists...\n' + for p in $pkgs; do printf 'E: Unable to locate package %s\n' "$p"; done + printf 'Error: building at STEP "RUN apt-get install": while running runtime: exit status 100\n' + exit "${AISB_STUB_RC}" + fi + printf '%s\n' '--> 1234567890ab' + printf 'STEP 3/3: CMD ["bash", "-li"]\n' + printf 'COMMIT localhost/ai-sandbox:stub\n' + printf 'Successfully tagged localhost/ai-sandbox:stub\n' + printf 'abc123def\n' + ;; + *) exit 0 ;; +esac +EOS +chmod +x "$BIN/podman" +export PATH="$BIN:$PATH" +# node_sha256() fetches from nodejs.org; a unit test never touches a registry. +export AISB_NODE_SHA256=0000000000000000000000000000000000000000000000000000000000000000 + +# The transcript path the last run announced, which is the only way a test is supposed +# to find it -- and naming it is itself part of the feedback under test. +last_transcript() { printf '%s' "$OUT" | sed -n 's/^ai-sandbox: build: [^ ]* (transcript: \(.*\))$/\1/p' | head -1; } +log_says() { # log_says