From 45145cb7c0198a0efb525243e9a44a510971a6f5 Mon Sep 17 00:00:00 2001 From: Tomasz Mazur Date: Mon, 31 Aug 2026 12:18:16 +0200 Subject: [PATCH] feat: report progress while provisioning, and -v to stream the log First boot spends minutes in `mise install` -- Ruby, Node, and since #13 the tools the mounted project pins -- while orbx sits in wait_ready polling /etc/sandbox-status and printing nothing. The machine is created and running by then, so from the outside a provision and a hang look identical. The only way to see anything was `orbx logs` from a second terminal, which you have to know about and cannot reach for once orbx has your prompt. The template already logs every step with a timestamp, so nothing new has to be produced -- orbx just never surfaced it. wait_ready now reports: - a spinner + elapsed time, redrawn in place, on a TTY; - one plain line naming the machine, plus `ready in Xm YYs`, when stderr is redirected (CI, an agent driving `orbx run`) -- escape codes there would be noise, and this is what closes the hang ambiguity for an agent; - with -v/--verbose, the guest's provisioning log inline instead. The stream is incremental polling, not a background `tail -f`: orbx::stream_log asks for everything past the line count it was handed and echoes the new count back, so there is no child process to supervise and kill, and a log that does not exist yet simply comes back empty. Latency is one poll interval. A machine that answers `ready` on the very first poll was already provisioned: nothing is being waited on, so wait_ready returns silently and does not replay a log of work that finished days ago. The everyday path -- `orbx` in a project whose sandbox exists -- prints exactly what it printed before, which is nothing. Every exit from the wait funnels through orbx::wait_done (clear the line, drop the trap), the INT trap included: Ctrl-C wipes the spinner's last frame and re-raises with `kill -INT "$BASHPID"`, so an interrupted orbx dies of the signal (130) rather than returning as if the wait had finished. $BASHPID rather than $$ because the script gets sourced into other shells, where the signal must stay with the subshell running the wait. No test can deliver a real Ctrl-C -- a backgrounded job inherits SIGINT ignored, and bash cannot trap what was ignored on entry -- so the tests assert the arm/disarm and the handler's re-raise separately, and AGENTS.md records why, so it is not "fixed" into a flaky signal test later. Verified with 97 bats tests (7 new) and shellcheck clean, plus an end-to-end run of `orbx up` against the suite's fake orb: the spinner redraws in place and clears, -v prints each log line exactly once across polls (tail -n +1 then +7), an already-ready machine prints nothing, and a redirected stderr carries no escape codes. --- AGENTS.md | 19 ++++++++ README.md | 6 +++ bin/orbx | 104 +++++++++++++++++++++++++++++++++++++++--- test/helpers/orb-stub | 14 ++++++ test/lifecycle.bats | 71 ++++++++++++++++++++++++++++ 5 files changed, 208 insertions(+), 6 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 9f560cf..8f72336 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -60,6 +60,25 @@ machine, then `wait_ready` polls `orb -m -u root cat /etc/sandbox-status` until it reads `ready` (or `failed`/timeout). Readiness is driven by the template writing that file — the CLI and the template share this contract. +**Provisioning feedback.** That poll can run for minutes on first boot (mise +installs Ruby/Node plus the project's pinned tools), so `wait_ready` reports +progress: a spinner + elapsed time, redrawn on stderr only when stderr is a TTY +(`orbx::spinner_on`), or — with `-v`/`--verbose` — the guest's +`/var/log/sandbox-provision.log` streamed inline. The stream is *incremental +polling*, not a background `tail -f`: `orbx::stream_log` asks for everything +past the line count it was handed and echoes the new count back, so there is no +child process to supervise and a log that doesn't exist yet is simply empty. A +machine that answers `ready` on the very first poll was already provisioned, so +it returns silently — the common path prints nothing. + +Every exit from the wait funnels through `orbx::wait_done` (clear the line, drop +the trap), including the `INT` trap: Ctrl-C wipes the spinner's last frame and +then re-raises with `kill -INT "$BASHPID"`, so an interrupted `orbx` dies of the +signal (130) instead of returning as if the wait had finished. Tests cannot +deliver a real Ctrl-C — a backgrounded job inherits SIGINT *ignored*, and bash +cannot trap what was ignored on entry — so they assert the arm/disarm and the +handler's re-raise separately. + **Terminfo prelude.** `ORBX_TERM_PRELUDE` is a guest-side bash snippet prepended to every `shell`/`run` invocation. The host's `infocmp -x $TERM` (`orbx::host_terminfo`) is passed as a positional arg; the guest seeds its own diff --git a/README.md b/README.md index ae94cc3..3dcdf90 100644 --- a/README.md +++ b/README.md @@ -40,6 +40,11 @@ orbx # creates (or starts) myapp's sandbox, waits for it to be Run it again later and it just starts the existing machine and shells in — provisioning only happens once. +That first run takes a few minutes: it installs the toolchain, including the +tools your project pins in `mise.toml`/`.tool-versions`. A spinner shows how +long it has been going; `orbx -v` streams the provisioning log inline instead, +and `orbx logs` tails the same log from another terminal. + ## Commands The output of `orbx --help`: @@ -74,6 +79,7 @@ FLAGS --arch amd64 | arm64 (default: native) --dry-run Print the orb command that would run, then exit --yes, -y Assume yes for confirmations + --verbose, -v Stream the provisioning log while waiting (instead of a spinner) --force Overwrite when scaffolding (orbx init) -h, --help Show this help --version Show version diff --git a/bin/orbx b/bin/orbx index e16e83b..fdb98ed 100755 --- a/bin/orbx +++ b/bin/orbx @@ -139,7 +139,7 @@ orbx::resolve_template() { } # Resolved run state (populated by orbx::resolve_context). -declare -g ORBX_NAME ORBX_IMAGE ORBX_ARCH ORBX_TEMPLATE ORBX_TEMPLATE_PATH ORBX_MOUNT_ON ORBX_DRYRUN ORBX_YES +declare -g ORBX_NAME ORBX_IMAGE ORBX_ARCH ORBX_TEMPLATE ORBX_TEMPLATE_PATH ORBX_MOUNT_ON ORBX_DRYRUN ORBX_YES ORBX_VERBOSE declare -ga ORBX_MOUNTS ORBX_CREATE_CMD orbx::resolve_context() { @@ -192,7 +192,7 @@ orbx::die() { printf 'orbx: %s\n' "$*" >&2; exit 1; } orbx::parse_flags() { ORBX_FLAG_MOUNTS=() - ORBX_DRYRUN=0; ORBX_YES=0; ORBX_FORCE=0 + ORBX_DRYRUN=0; ORBX_YES=0; ORBX_FORCE=0; ORBX_VERBOSE=0 ORBX_ARGS=() while (( $# )); do case "$1" in @@ -204,6 +204,7 @@ orbx::parse_flags() { --no-mount) ORBX_FLAG_NO_MOUNT=1; shift ;; --dry-run) ORBX_DRYRUN=1; shift ;; --yes|-y) ORBX_YES=1; shift ;; + --verbose|-v) ORBX_VERBOSE=1; shift ;; --force) ORBX_FORCE=1; shift ;; --) shift; while (( $# )); do ORBX_ARGS+=("$1"); shift; done ;; -*) orbx::die "unknown flag: $1" ;; @@ -249,6 +250,7 @@ FLAGS --arch amd64 | arm64 (default: native) --dry-run Print the orb command that would run, then exit --yes, -y Assume yes for confirmations + --verbose, -v Stream the provisioning log while waiting (instead of a spinner) --force Overwrite when scaffolding (orbx init) -h, --help Show this help --version Show version @@ -301,22 +303,112 @@ orbx::cmd_up() { orbx::machine_exists() { orb list -q | grep -Fxq -- "$1"; } orbx::machine_running() { orb list -r -q | grep -Fxq -- "$1"; } +# --- Progress while provisioning runs -------------------------------------- +# First boot spends minutes in `mise install` (Ruby, Node, and the mounted +# project's own pinned tools) with the machine already created and running, so +# a silent poll loop is indistinguishable from a hang. Default: a spinner with +# elapsed time. --verbose: stream the guest's provisioning log instead. +ORBX_PROVISION_LOG=/var/log/sandbox-provision.log +ORBX_SPIN_FRAMES=(⠋ ⠙ ⠹ ⠸ ⠼ ⠴ ⠦ ⠧ ⠇ ⠏) +ORBX_SPIN_I=0 + +# Spinner only when it has a terminal to redraw in and isn't competing with the +# log stream. With stderr redirected (CI, an agent driving `orbx run`) the +# escape codes would be noise, so we stay silent exactly as before. +orbx::spinner_on() { [[ "${ORBX_VERBOSE:-0}" != "1" && -t 2 ]]; } + +orbx::spinner_draw() { + orbx::spinner_on || return 0 + local e=$SECONDS + printf '\r\033[K%s provisioning… %dm%02ds' \ + "${ORBX_SPIN_FRAMES[ORBX_SPIN_I]}" $(( e / 60 )) $(( e % 60 )) >&2 + ORBX_SPIN_I=$(( (ORBX_SPIN_I + 1) % ${#ORBX_SPIN_FRAMES[@]} )) +} + +orbx::spinner_clear() { + orbx::spinner_on || return 0 + printf '\r\033[K' >&2 +} + +# Every exit from the wait -- ready, failed, timeout, Ctrl-C -- goes through +# here, so the spinner's last frame is never left on the line and the interrupt +# trap does not outlive the wait it belongs to. +orbx::wait_done() { trap - INT; orbx::spinner_clear; } + +# Ctrl-C during a multi-minute provision must not leave a stray spinner frame +# where the shell is about to draw its prompt. Wipe the line, restore the +# default disposition, then re-raise so we die of the signal we were sent +# (exit 130) instead of returning as if the wait had finished. $BASHPID, not +# $$: sourced into another shell (the test suite does this), the signal must +# stay with the subshell running the wait. +orbx::on_interrupt() { + orbx::wait_done + kill -INT "$BASHPID" +} + +# Sleep $1 seconds, animating the spinner ~5x a second so the wait never looks +# frozen. With no spinner to draw it is a plain sleep, so poll timing (and the +# zeroed timers the tests rely on) is unchanged. +orbx::wait_tick() { + local secs="$1" i + (( secs > 0 )) || return 0 + orbx::spinner_on || { sleep "$secs"; return 0; } + for (( i = 0; i < secs * 5; i++ )); do + orbx::spinner_draw + sleep 0.2 + done +} + +# Verbose mode: print whatever the provisioning log has grown by since the last +# poll. Asking for everything past the lines already shown keeps this inside the +# existing poll loop -- no background `tail -f` to supervise and kill, and a log +# that does not exist yet simply comes back empty. Echoes the new line count on +# stdout for the caller to carry into the next poll; log lines go to stderr. +orbx::stream_log() { + local name="$1" shown="$2" line new=0 + if [[ "${ORBX_VERBOSE:-0}" != "1" ]]; then printf '%s' "$shown"; return 0; fi + while IFS= read -r line; do + printf '%s\n' "$line" >&2 + new=$(( new + 1 )) + done < <(orb -m "$name" -u root tail -n "+$(( shown + 1 ))" "$ORBX_PROVISION_LOG" 2>/dev/null) + printf '%s' "$(( shown + new ))" +} + orbx::wait_ready() { local name="$1" local timeout="${ORBX_READY_TIMEOUT:-1200}" local interval="${ORBX_POLL_INTERVAL:-5}" local delay="${ORBX_POLL_DELAY:-2}" waited=0 status + local shown=0 first=1 + SECONDS=0 + trap orbx::on_interrupt INT (( delay > 0 )) && sleep "$delay" while :; do status="$(orb -m "$name" -u root cat /etc/sandbox-status 2>/dev/null || true)" + # An already-provisioned machine answers `ready` on the very first poll: + # nothing is being waited on, so there is no progress to report and no + # point replaying a log of work that finished days ago. + [[ "$status" == "ready" && "$first" == "1" ]] && { orbx::wait_done; return 0; } + first=0 + # Say once that something is being waited on. The spinner covers a + # terminal; this line is what a redirected stderr (CI, an agent driving + # `orbx run`) gets, and it points at the two ways to see more. + (( waited == 0 )) && [[ "${ORBX_VERBOSE:-0}" != "1" ]] && \ + printf 'orbx: provisioning %s — first run installs the toolchain (-v streams the log, or: orbx logs)\n' \ + "$name" >&2 + shown="$(orbx::stream_log "$name" "$shown")" case "$status" in - ready) return 0 ;; - failed) printf 'orbx: provisioning failed. See: orbx logs\n' >&2; return 1 ;; + ready) orbx::wait_done + printf 'orbx: ready in %dm%02ds\n' $(( SECONDS / 60 )) $(( SECONDS % 60 )) >&2 + return 0 ;; + failed) orbx::wait_done + printf 'orbx: provisioning failed. See: orbx logs\n' >&2; return 1 ;; esac (( waited >= timeout )) && break - (( interval > 0 )) && sleep "$interval" + orbx::wait_tick "$interval" waited=$(( waited + (interval > 0 ? interval : 1) )) done + orbx::wait_done printf 'orbx: timed out after %ss waiting for ready. See: orbx logs\n' "$timeout" >&2 return 1 } @@ -395,7 +487,7 @@ orbx::cmd_run() { orbx::cmd_stop() { orbx::resolve_context; orb stop "$ORBX_NAME"; } orbx::cmd_list() { orb list; } -orbx::cmd_logs() { orbx::resolve_context; orb -m "$ORBX_NAME" tail -f /var/log/sandbox-provision.log; } +orbx::cmd_logs() { orbx::resolve_context; orb -m "$ORBX_NAME" tail -f "$ORBX_PROVISION_LOG"; } orbx::cmd_down() { orbx::resolve_context diff --git a/test/helpers/orb-stub b/test/helpers/orb-stub index e027b55..cc5a2a0 100755 --- a/test/helpers/orb-stub +++ b/test/helpers/orb-stub @@ -26,6 +26,20 @@ if [[ "$*" == *"cat /etc/sandbox-status"* ]]; then exit 0 fi +# Provisioning log reads: `orb -m NAME -u root tail -n +N /var/log/...`. +# Emits $ORB_STUB_PROVISION_LOG_FIXTURE from line N on, so incremental polling +# sees each line exactly once, the way the real log does as it grows. +if [[ "$*" == *"/var/log/sandbox-provision.log"* ]]; then + fixture="${ORB_STUB_PROVISION_LOG_FIXTURE:-}" + [[ -n "$fixture" && -f "$fixture" ]] || exit 0 + start=1 + for arg in "$@"; do + case "$arg" in +[0-9]*) start="${arg#+}" ;; esac + done + tail -n "+$start" "$fixture" + exit 0 +fi + # `orb info NAME -f json` -> fixture JSON. if [[ "${1:-}" == "info" ]]; then cat "${ORB_STUB_INFO_FIXTURE:-/dev/null}" diff --git a/test/lifecycle.bats b/test/lifecycle.bats index bb10ea6..965b890 100644 --- a/test/lifecycle.bats +++ b/test/lifecycle.bats @@ -68,3 +68,74 @@ load helpers/test_helper [ "$status" -ne 0 ] [[ "$output" == *"orbx logs"* ]] } + +@test "wait_ready says nothing when the machine is already provisioned" { + orbx_source + printf '%s ' ready > "$ORBX_TMP/seq" + export ORB_STUB_STATUS_SEQ="$ORBX_TMP/seq" + run orbx::wait_ready korelo + [ "$status" -eq 0 ] + [ -z "$output" ] +} + +@test "wait_ready reports that it is waiting, then how long it took" { + orbx_source + printf '%s ' provisioning ready > "$ORBX_TMP/seq" + export ORB_STUB_STATUS_SEQ="$ORBX_TMP/seq" + run orbx::wait_ready korelo + [ "$status" -eq 0 ] + [[ "$output" == *"provisioning korelo"* ]] + [[ "$output" == *"ready in"* ]] + # No spinner escape codes when stderr is not a terminal. + [[ "$output" != *$'\033'* ]] +} + +@test "verbose streams each provisioning log line exactly once" { + orbx_source + printf '%s ' provisioning provisioning ready > "$ORBX_TMP/seq" + export ORB_STUB_STATUS_SEQ="$ORBX_TMP/seq" + printf '%s\n' "Installing mise..." "Installing Ruby (latest)..." > "$ORBX_TMP/prov.log" + export ORB_STUB_PROVISION_LOG_FIXTURE="$ORBX_TMP/prov.log" + ORBX_VERBOSE=1 run orbx::wait_ready korelo + [ "$status" -eq 0 ] + [ "$(grep -c 'Installing mise' <<< "$output")" -eq 1 ] + [ "$(grep -c 'Installing Ruby' <<< "$output")" -eq 1 ] +} + +@test "without verbose the provisioning log is not streamed" { + orbx_source + printf '%s ' provisioning ready > "$ORBX_TMP/seq" + export ORB_STUB_STATUS_SEQ="$ORBX_TMP/seq" + printf '%s\n' "Installing mise..." > "$ORBX_TMP/prov.log" + export ORB_STUB_PROVISION_LOG_FIXTURE="$ORBX_TMP/prov.log" + run orbx::wait_ready korelo + [ "$status" -eq 0 ] + [[ "$output" != *"Installing mise"* ]] +} + +@test "-v is accepted as a global flag" { + orbx_source + orbx::parse_flags -v up + [ "$ORBX_VERBOSE" -eq 1 ] + [ "${ORBX_ARGS[0]}" = "up" ] +} + +# A backgrounded job inherits SIGINT *ignored*, and bash cannot trap a signal +# that was ignored on entry -- so no test here can deliver a real Ctrl-C. These +# two cover the halves that are testable: the trap is armed for exactly as long +# as the wait, and the handler ends the run the way a signal should. +@test "wait_ready arms the interrupt trap while waiting and disarms it after" { + orbx_source + printf '%s ' provisioning ready > "$ORBX_TMP/seq" + export ORB_STUB_STATUS_SEQ="$ORBX_TMP/seq" + orbx::wait_tick() { trap -p INT > "$ORBX_TMP/armed"; } # runs inside the loop + orbx::wait_ready korelo 2>/dev/null + grep -q "orbx::on_interrupt" "$ORBX_TMP/armed" + trap -p INT > "$ORBX_TMP/after" # back in the test shell + [ ! -s "$ORBX_TMP/after" ] +} + +@test "the interrupt handler re-raises, so the run dies of the signal (130)" { + run bash -c "source '$ORBX_BIN'; orbx::on_interrupt" + [ "$status" -eq 130 ] +}