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