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
This commit is contained in:
+139
-8
@@ -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 ("--> <hash>" 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"
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user