From 0a4aabec180d4d2d1f2d26f851e7f2ea3acf6a1d Mon Sep 17 00:00:00 2001 From: frostebite Date: Sun, 20 Sep 2026 20:13:00 +0100 Subject: [PATCH 1/4] fix: stop quoting docker's pull noise as the cause of a Unity abort When Unity aborts batchmode, Docker.run passes the reason from stdout and then appended `docker run`'s own stderr under an "Original error:" heading. That stderr opens with the benign pre-pull "Unable to find image ... locally" status line, so the message read as an editor failing to load a version and buried the actual cause two lines above it: Unity aborted before completing: Scripts have compiler errors. ... Original error: Unable to find image 'unityci/editor:...' locally Two Mirror maintainers read it exactly that way on Mirror#4128 - they went looking for a 6000.3.23f1 problem while "Scripts have compiler errors." sat in the same message. System.run already streams that stderr live, so repeating it loses nothing. describe() now takes originalMessage as optional and omits the section when the caller has nothing to add. HostRunner keeps passing it: on its --silent path the streamed copy does not exist, so the quoted text is the only one. Co-Authored-By: Claude Sonnet 5 --- src/model/docker.test.ts | 20 +++++++++--- src/model/docker.ts | 9 +++++- .../unity/unity-batchmode-failure.test.ts | 12 +++++++ src/model/unity/unity-batchmode-failure.ts | 31 +++++++++++++++---- 4 files changed, 61 insertions(+), 11 deletions(-) diff --git a/src/model/docker.test.ts b/src/model/docker.test.ts index 5d40792..429db85 100644 --- a/src/model/docker.test.ts +++ b/src/model/docker.test.ts @@ -105,8 +105,9 @@ describe("Docker", () => { }); System.run = mock(() => Promise.reject(dockerError)); - await expect( - Docker.run("game-ci/unity-editor-stub:latest", { + let rejection: Error | undefined; + try { + await Docker.run("game-ci/unity-editor-stub:latest", { hostOS: "linux", hostPlatform: "linux", currentWorkDir: "/home/runner/work/cli/cli", @@ -117,8 +118,19 @@ describe("Docker", () => { dockerWorkspacePath: "/github/workspace", engine: "unity", runTests: true, - } as any), - ).rejects.toThrow(/Scripts have compiler errors\./); + } as any); + } catch (error: any) { + rejection = error; + } + + expect(rejection?.message).toContain('Scripts have compiler errors.'); + + // And it must not be quoted back at the reader as the cause: System.run + // already streamed this stderr live, and leading with "Unable to find + // image ... locally" under an "Original error:" heading is exactly what + // made MirrorNetworking/Mirror#4128 read as an editor failing to load + // 6000.3.23f1 rather than scripts failing to compile. + expect(rejection?.message).not.toContain('Unable to find image'); }); it("still throws the original error when there is no Unity abort reason to extract", async () => { diff --git a/src/model/docker.ts b/src/model/docker.ts index 69163ef..b45f50c 100644 --- a/src/model/docker.ts +++ b/src/model/docker.ts @@ -157,7 +157,14 @@ class Docker { // failure this command hits, and error.message alone never contains // it - see UnityBatchmodeFailure's own comment for why. Checked first // since it's the highest-value case to get right. - const batchmodeFailure = UnityBatchmodeFailure.describe(error.stdout, error.message); + // No originalMessage: this command's error text is `docker run`'s own + // stderr - pull progress, led by its benign "Unable to find image ... + // locally" status line - which System.run has already streamed live + // above. Repeating it under an "Original error:" heading asserted it + // was the cause: MirrorNetworking/Mirror#4128 read as an editor failing + // to load 6000.3.23f1 when the real cause was scripts failing to + // compile, two lines up in the same message. + const batchmodeFailure = UnityBatchmodeFailure.describe(error.stdout); if (batchmodeFailure) { throw new Error(batchmodeFailure); } diff --git a/src/model/unity/unity-batchmode-failure.test.ts b/src/model/unity/unity-batchmode-failure.test.ts index ae19931..daed930 100644 --- a/src/model/unity/unity-batchmode-failure.test.ts +++ b/src/model/unity/unity-batchmode-failure.test.ts @@ -53,6 +53,18 @@ describe('UnityBatchmodeFailure', () => { expect(described).toContain('not a\ndocker/game-ci infrastructure problem'); }); + // Regression: Docker.run passes no originalMessage, because its error + // text is `docker run`'s stderr - pull progress it has already streamed + // live. Appending that under "Original error:" made + // MirrorNetworking/Mirror#4128 read as an editor failing to load a + // version when Unity had in fact aborted on script compiler errors. + it('omits the original-error section when the caller supplies nothing to add', () => { + const described = UnityBatchmodeFailure.describe(realWorldStdout); + + expect(described).toContain('Scripts have compiler errors.'); + expect(described).not.toContain('Original error:'); + }); + it('returns undefined when there is nothing to extract, leaving the caller to fall back to the original error', () => { expect(UnityBatchmodeFailure.describe('some unrelated stdout', 'Command exited with code 1')).toBeUndefined(); expect(UnityBatchmodeFailure.describe(undefined, 'Command exited with code 1')).toBeUndefined(); diff --git a/src/model/unity/unity-batchmode-failure.ts b/src/model/unity/unity-batchmode-failure.ts index be47e1a..651d967 100644 --- a/src/model/unity/unity-batchmode-failure.ts +++ b/src/model/unity/unity-batchmode-failure.ts @@ -13,6 +13,16 @@ * run failed with exit code 1" - the real reason, "Scripts have compiler * errors.", was sitting ~1400 log lines earlier and never reached the final * error message at all. + * + * Reported live once more, from the opposite direction: the same CI then + * appended that stderr under the "Original error:" heading below, burying + * the reason it was supposed to support. Docker leads its stderr with the + * benign pre-pull "Unable to find image '...' locally" line, so the message + * read as an editor failing to load 6000.3.23f1 - two maintainers went + * looking for a version problem while "Scripts have compiler errors." sat + * two lines above it. Hence `originalMessage` is optional, and the one + * caller whose error text is already in the log - Docker, via System.run's + * live stderr passthrough - omits it. */ class UnityBatchmodeFailure { static extractReason(stdout: string | undefined): string | undefined { @@ -25,21 +35,30 @@ class UnityBatchmodeFailure { return match?.[1]?.trim() || undefined; } - /** Returns a clearer error message when `stdout` contains Unity's own abort reason, or undefined otherwise. */ - static describe(stdout: string | undefined, originalMessage: string): string | undefined { + /** + * Returns a clearer error message when `stdout` contains Unity's own abort + * reason, or undefined otherwise. + * + * `originalMessage` is the caller's own error text, appended under an + * "Original error:" heading. Omit it when that text is already in the log + * above - the reason is the useful part, and repeating a stream the reader + * has already scrolled past only buries it. + */ + static describe(stdout: string | undefined, originalMessage?: string): string | undefined { const reason = UnityBatchmodeFailure.extractReason(stdout); if (!reason) return undefined; - return String.dedent` + const message = String.dedent` Unity aborted before completing: ${reason} This is a failure inside the Unity Editor itself (commonly script compiler errors, a missing package, or a crash during startup) - not a docker/game-ci infrastructure problem. The full Unity log is above. - - Original error: - ${originalMessage} `; + + if (!originalMessage) return message; + + return `${message}\n\nOriginal error:\n${originalMessage}`; } } From 5fdab58ee8aa7aecbce2fdfda5c5a92a54954c3b Mon Sep 17 00:00:00 2001 From: frostebite Date: Sun, 20 Sep 2026 20:22:11 +0100 Subject: [PATCH 2/4] ci: stop the install smoke tests failing for the wrong reason Two defects in the release-download smoke tests, both hit live on PR #293: The macOS job 403'd on api.github.com while the ubuntu job passed beside it, running the same install.sh against the same endpoint in the same minute. install.sh resolves "latest" through the API and authenticates only when handed a token - unauthenticated is 60 requests/hour per IP, and Actions runners share IPs across unrelated repos and orgs. The script was written to be given one, and says so in its own comment; the workflow never passed it. Both smoke steps, and the root-wrapper steps that default to "latest" and hit the same call, now pass GH_TOKEN - the pattern already used throughout orchestrator-integrity.yml. install.sh treats an empty token as no token, so a fork PR (no secrets, read-only github.token) degrades to today's behaviour rather than failing. The retry loop reported every failure the same way - "likely the latest release's binaries are still uploading". A 403 rate limit is not that, and re-running the identical unauthenticated request 30 seconds later cannot clear it, so it spent all five attempts and 2.5 minutes asserting a cause it had no way to know. That is the same misdiagnosis this branch's Unity abort message fix exists to remove: point at the error that actually occurred instead of substituting a guess for it. Verified end-to-end: GH_TOKEN=... bash scripts/install.sh latest resolves v0.1.69, downloads, and checksum-verifies. actionlint clean. Co-Authored-By: Claude Sonnet 5 --- .github/workflows/tests.yml | 30 ++++++++++++++++++++++++++---- 1 file changed, 26 insertions(+), 4 deletions(-) diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 047d5e3..6211476 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -190,6 +190,18 @@ jobs: # lands in that window - e.g. this repo's own version-bump commit, # created right after cutting the release it's for - hit exactly # this 404 in practice, failing Tests on main itself, not just a PR. + # + # GH_TOKEN because install.sh resolves "latest" through the GitHub + # API and only authenticates when handed one (see its own comment). + # Unauthenticated is 60 requests/hour *per IP*, and Actions runners + # share IPs across unrelated repos and orgs - so the macOS job below, + # running the same install.sh against the same endpoint seconds + # later, was 403ing on that limit while this job passed beside it. + # install.sh reads GITHUB_TOKEN or GH_TOKEN and treats an empty one + # as no token, so a fork PR (no secrets, read-only github.token) + # degrades to today's unauthenticated behaviour rather than failing. + env: + GH_TOKEN: ${{ secrets.GIT_PRIVATE_TOKEN || github.token }} run: | for attempt in 1 2 3 4 5; do # install.sh writes progress to stderr and only the final binary @@ -203,7 +215,7 @@ jobs: echo "FAIL: scripts/install.sh still failing after 5 attempts" exit 1 fi - echo "install.sh failed (attempt $attempt/5) - likely the latest release's binaries are still uploading - retrying in 30s..." + echo "install.sh failed (attempt $attempt/5) - see the error above; retrying in 30s..." sleep 30 done [ -x "$binary_path" ] || { echo "FAIL: $binary_path is not executable"; exit 1; } @@ -221,6 +233,10 @@ jobs: # above has already established that the latest release is fully # uploaded. - name: Smoke-test the root install.sh wrapper + # Same GH_TOKEN reason as the step above: the wrapper defaults to + # "latest" and resolves it through the same API call. + env: + GH_TOKEN: ${{ secrets.GIT_PRIVATE_TOKEN || github.token }} run: | export GAME_CI_INSTALL=/tmp/root-install-sh-smoke-test sh ./install.sh @@ -257,8 +273,10 @@ jobs: *) echo "FAIL: expected macOS's system bash to be 3.x, got $bash_version - this job no longer covers the bash-3.2 compatibility class it exists for"; exit 1 ;; esac - name: Smoke-test scripts/install.sh against the latest release - # Same retry rationale as the ubuntu job: "latest" can resolve to a - # release whose binaries are still uploading. + # Same retry rationale, and the same GH_TOKEN reason, as the ubuntu + # job above - this is the job the token exists to stop 403ing. + env: + GH_TOKEN: ${{ secrets.GIT_PRIVATE_TOKEN || github.token }} run: | for attempt in 1 2 3 4 5; do if binary_path="$(/bin/bash scripts/install.sh latest /tmp/install-sh-smoke-test)"; then @@ -268,13 +286,17 @@ jobs: echo "FAIL: scripts/install.sh still failing after 5 attempts" exit 1 fi - echo "install.sh failed (attempt $attempt/5) - likely the latest release's binaries are still uploading - retrying in 30s..." + echo "install.sh failed (attempt $attempt/5) - see the error above; retrying in 30s..." sleep 30 done [ -x "$binary_path" ] || { echo "FAIL: $binary_path is not executable"; exit 1; } [ -d "$(dirname "$binary_path")/dist" ] || { echo "FAIL: dist/ was not extracted next to $binary_path"; exit 1; } "$binary_path" --help - name: Smoke-test the root install.sh wrapper + # Same GH_TOKEN reason as the step above: the wrapper defaults to + # "latest" and resolves it through the same API call. + env: + GH_TOKEN: ${{ secrets.GIT_PRIVATE_TOKEN || github.token }} run: | export GAME_CI_INSTALL=/tmp/root-install-sh-smoke-test /bin/sh ./install.sh From 3e55c781ebcc629132aa91137075b0dc7cee1db8 Mon Sep 17 00:00:00 2001 From: frostebite Date: Sun, 20 Sep 2026 22:13:27 +0100 Subject: [PATCH 3/4] ci: reproduce the Mirror#4128 Unity abort message end to end A container aborts Unity, docker leads its own stderr with the benign "Unable to find image '...' locally" pre-pull notice, and the CLI's final error used to append that stderr under an "Original error:" heading. The message then read as an editor failing to load a Unity version, while Unity's real reason - a genuine script compile error - sat two lines above it (#288). #293 fixed the message and src/model/docker.test.ts asserts it, but that test hard-codes BOTH streams onto its fake error, so it stays green if Docker.run reads the wrong stream or System.run folds them together. That plumbing is precisely what broke, and nothing in CI ran a real `docker run` through it. This adds that, and grades what the user is actually shown. - New unity-abort-message job: an aborting-editor stub (no Unity, no licence, no multi-GB pull), driven through both CLI routes because they reach stdout differently - build.sh passes `-logfile /dev/stdout`, while test.sh writes the log to a file and cats it after capturing the exit code. Both graded by scripts/assert-unity-abort-message.sh. - Wired into smoke-gate.needs, so a failure there actually fails the gate. - scripts/test-assert-unity-abort-message.sh drives the grader in both directions against hand-written logs - including the pre-#293 message it exists to reject - because its two "must not contain" assertions can only ever pass vacuously on a run that died early. - A stream-split case in system.integration.test.ts, against a real child process rather than the mocked System.run. - A comment pinning the `silent` coupling Docker.run's catch block rests on ("System.run has already streamed it live above"), which holds only while options.silent stays falsy. No behaviour change. Co-Authored-By: Claude Sonnet 5 --- .github/workflows/engine-smoke-test.yml | 179 +++++++++++++++++++- .github/workflows/tests.yml | 9 + scripts/assert-unity-abort-message.sh | 122 +++++++++++++ scripts/test-assert-unity-abort-message.sh | 172 +++++++++++++++++++ src/model/docker.ts | 9 + src/model/system/system.integration.test.ts | 31 ++++ 6 files changed, 521 insertions(+), 1 deletion(-) create mode 100644 scripts/assert-unity-abort-message.sh create mode 100644 scripts/test-assert-unity-abort-message.sh diff --git a/.github/workflows/engine-smoke-test.yml b/.github/workflows/engine-smoke-test.yml index fcf7855..fae5098 100644 --- a/.github/workflows/engine-smoke-test.yml +++ b/.github/workflows/engine-smoke-test.yml @@ -247,6 +247,183 @@ jobs: echo "Shipped binary verified end to end against a real container" + # ─── Unity — the Mirror#4128 abort message, end to end ───────── + # The incident: a container aborted Unity, docker led its own stderr with the + # benign "Unable to find image '...' locally" pre-pull notice, and the CLI's + # final error appended that stderr under an "Original error:" heading. The + # message therefore read as an editor failing to load a Unity version, while + # Unity's real reason - a genuine script compile error - sat two lines above + # it. Two Mirror maintainers went hunting for a version problem (see #288). + # + # src/model/docker.test.ts already asserts the corrected message, but it + # hard-codes BOTH streams onto its fake error, so it stays green if Docker.run + # reads the wrong stream or System.run ever folds them together. That plumbing + # is precisely what broke. Nothing in CI ran a real `docker run` through it, so + # this job does, and grades what the user is actually shown + # (scripts/assert-unity-abort-message.sh, itself tested by its sibling in + # tests.yml). + # + # Both CLI routes are exercised, because they reach stdout differently: + # build.sh runs the editor with `-logfile /dev/stdout`, whereas test.sh writes + # the log to a file and cats it after capturing the exit code. The stub below + # honours whichever spelling it is handed. + unity-abort-message: + name: Unity abort message (Mirror#4128) + needs: changes + if: needs.changes.outputs.core == 'true' || needs.changes.outputs.unity == 'true' + runs-on: ubuntu-latest + timeout-minutes: 10 + steps: + - uses: actions/checkout@v4 + with: + persist-credentials: false + + - name: Set up Bun + uses: oven-sh/setup-bun@v2 + with: + bun-version: latest + + - name: Install dependencies + run: bun install --frozen-lockfile + + # Same stub shape as unity-build's above, with two differences: it fails + # the way the incident failed, and it puts each half on the stream reality + # puts it on. + # + # Docker cannot supply the stderr half itself here: this image is built + # locally a few lines up, so there is nothing for docker to pull and + # docker writes nothing. The container emits that text on the stream docker + # would have used, leading with the same benign "not cached locally" line. + - name: Build aborting-editor stub + run: | + mkdir -p /tmp/unity-abort-stub-ctx + cat > /tmp/unity-abort-stub-ctx/unity-editor <<'SCRIPT' + #!/bin/bash + set -euo pipefail + + # Activation has to succeed, or runsteps.sh exits before ever reaching + # the build/test step. Same licence line unity-build's stub prints, + # which activate.sh greps for. + if printf '%s\n' "$*" | grep -q -- '-manualLicenseFile'; then + echo "LICENSE SYSTEM [CI Stub] Next license update check is after 2099-01-01T00:00:00" + exit 0 + fi + + # Where Unity was told to write its log. build.sh passes + # `-logfile /dev/stdout`; test.sh passes `-logFile /x.log` + # and cats it afterwards. Honouring both keeps each route's abort + # reason on the stream that route really puts it on. + LOG_DEST="" + while [ "$#" -gt 0 ]; do + case "$1" in + -logFile|-logfile) + LOG_DEST="${2:-}" + shift 2 + ;; + *) + shift + ;; + esac + done + + # Docker's own stderr in the incident: harmless status output whose + # first line names an image it is about to pull. Quoted back under an + # "Original error:" heading, it read as an editor failing to load that + # version. + { + echo "Unable to find image 'game-ci/unity-abort-stub:latest' locally" + echo "latest: Pulling from game-ci/unity-abort-stub" + } >&2 + + # Unity's own reason, on Unity's own stream. The grader keys on this + # exact pairing - and on the two stderr lines above - to prove the + # incident was really reproduced rather than passing its absence + # checks vacuously. + print_abort() { + echo "Aborting batchmode due to failure:" + echo "Scripts have compiler errors." + } + + if [ -z "$LOG_DEST" ] || [ "$LOG_DEST" = "/dev/stdout" ]; then + print_abort + else + mkdir -p "$(dirname "$LOG_DEST")" + print_abort > "$LOG_DEST" + fi + exit 1 + SCRIPT + chmod +x /tmp/unity-abort-stub-ctx/unity-editor + + cat > /tmp/unity-abort-stub-ctx/Dockerfile <<'DOCKERFILE' + FROM alpine:3.19 + RUN apk add --no-cache bash coreutils git + COPY unity-editor /usr/local/bin/unity-editor + RUN chmod +x /usr/local/bin/unity-editor + WORKDIR /github/workspace + DOCKERFILE + + docker build -t game-ci/unity-abort-stub:latest -f /tmp/unity-abort-stub-ctx/Dockerfile /tmp/unity-abort-stub-ctx + + # No --allowDirtyBuild here, unlike unity-build's second run: versioning's + # dirty check is a yargs middleware registered inside + # VersioningOptions.configure, which only `game-ci build` calls - `test` + # never runs it. (It is also not an option there, and the CLI parses + # strictly, so passing it would fail the invocation outright.) + - name: Run the aborting build and grade the message + run: | + set -uo pipefail + LOG=/tmp/unity-abort-build.log + + UNITY_VERSION="${{ github.event.inputs.unity-version || '2019.4.40f1' }}" + + # Captured to a FILE, never piped through tee: writes to a pipe are + # asynchronous, so the CLI's process.exit(1) can truncate the very + # message under test. File writes are synchronous. + if bun run src/index.ts build test-project \ + --engineVersion "${UNITY_VERSION}" \ + --targetPlatform StandaloneLinux64 \ + --customImage game-ci/unity-abort-stub:latest \ + --unityLicense ci-stub-license \ + > "$LOG" 2>&1; then + echo "::error::the aborting stub build was expected to fail, but exited 0" + cat "$LOG" + exit 1 + fi + + cat "$LOG" + bash scripts/assert-unity-abort-message.sh "$LOG" + + # The incident was `game-ci test`, not `build`, and test.sh reaches stdout + # by cat-ing the log file rather than via -logfile /dev/stdout. Same + # Docker.run catch either way, but a future change to that cat's position + # relative to the exit-code capture could lose the reason while the build + # step above stayed green. + - name: Run the aborting test and grade the message + run: | + set -uo pipefail + LOG=/tmp/unity-abort-test.log + + UNITY_VERSION="${{ github.event.inputs.unity-version || '2019.4.40f1' }}" + + # --docker is what selects the container flow; without it this would + # run the experimental `unity test` CLI path instead. + if bun run src/index.ts test test-project \ + --docker \ + --engineVersion "${UNITY_VERSION}" \ + --targetPlatform StandaloneLinux64 \ + --testPlatforms editmode \ + --coverageEnabled false \ + --customImage game-ci/unity-abort-stub:latest \ + --unityLicense ci-stub-license \ + > "$LOG" 2>&1; then + echo "::error::the aborting stub test run was expected to fail, but exited 0" + cat "$LOG" + exit 1 + fi + + cat "$LOG" + bash scripts/assert-unity-abort-message.sh "$LOG" + # ─── Godot — detect + build using third-party image ──────────── godot-build: name: Godot build @@ -503,7 +680,7 @@ jobs: # blocks every path-scoped PR, which would defeat the filtering. smoke-gate: name: Engine smoke gate - needs: [unity-build, godot-build, unreal-build, protocol-tests] + needs: [unity-build, unity-abort-message, godot-build, unreal-build, protocol-tests] if: always() runs-on: ubuntu-latest timeout-minutes: 5 diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 6211476..e169998 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -165,6 +165,15 @@ jobs: # directions. - name: Licensing matrix gate tests run: bash scripts/test-licensing-matrix-gate.sh + # The grader engine-smoke-test.yml's unity-abort-message job runs against + # a real Docker run (the Mirror#4128 abort message). Its two "must not + # contain" assertions can only ever pass *vacuously* on a run that died + # early, so this drives it both directions against hand-written logs - + # including the pre-#293 message it exists to reject - to pin that a + # degraded stub or a reintroduced "Original error:" section still fails. + # No Docker, no Unity, no network. + - name: Unity abort message grader tests + run: bash scripts/test-assert-unity-abort-message.sh # scripts/install.sh is fetched and run directly by engine wrappers # (unity-builder and future ones) - see its own header comment - so a # syntax error here breaks every wrapper's CLI install step, not just diff --git a/scripts/assert-unity-abort-message.sh b/scripts/assert-unity-abort-message.sh new file mode 100644 index 0000000..58a2254 --- /dev/null +++ b/scripts/assert-unity-abort-message.sh @@ -0,0 +1,122 @@ +#!/usr/bin/env bash +# +# Grades one CLI run against the MirrorNetworking/Mirror#4128 incident: a +# container that aborts Unity, where docker's own stderr leads with its benign +# pre-pull "Unable to find image '...' locally" status line. +# +# Usage: assert-unity-abort-message.sh +# +# The log must be the combined stdout+stderr of a `game-ci build` or +# `game-ci test` run against the aborting-editor stub built by +# .github/workflows/engine-smoke-test.yml's unity-abort-message job - see that +# job for what the stub emits and why. +# +# What went wrong, so the assertions below make sense: the CLI used to append +# its own error text - docker's stderr, i.e. pull progress - under an +# "Original error:" heading. That made the message read as an editor failing to +# load a version, while Unity's actual reason sat two lines above it. Two +# maintainers went hunting for a version problem. Hence: the reason must be the +# last thing the user sees, and the noise must not be quoted as its cause. +# +# Why this lives in a script rather than inline in the workflow, and why it has +# a sibling test-assert-unity-abort-message.sh: same reasons as +# scripts/licensing-verdict.sh. It is shell, not YAML, and shell that only ever +# runs in CI is shell nobody has syntax-checked - tests.yml's `bash -n` sweep +# only proves it parses, not that it grades. + +set -uo pipefail + +LOG="${1:-}" +if [ -z "$LOG" ] || [ ! -f "$LOG" ]; then + echo "usage: $(basename "$0") " >&2 + exit 2 +fi + +# The stub's own stderr, and the proof that it actually ran. +# +# Both lines matter, and the second is the one doing the work: if the image +# were missing, docker would print the first line *itself* before failing to +# pull, which would make an "the stub ran" assertion pass on a run where it +# never did. Docker never prints "Pulling from" for an image it cannot pull - +# it prints "pull access denied" - so requiring the pair pins the stub. +NOISE_LEAD="Unable to find image 'game-ci/unity-abort-stub:latest' locally" +NOISE_PROOF="Pulling from game-ci/unity-abort-stub" + +REASON="Unity aborted before completing: Scripts have compiler errors." + +fail=0 + +require() { # + if ! grep -qF "$1" "$LOG"; then + echo "::error::$2 (missing from the log: $1)" + fail=1 + fi +} + +forbid() { # + if grep -qF "$1" "$LOG"; then + echo "::error::$2 (found in the log: $1)" + fail=1 + fi +} + +# --- Non-vacuous guards, on the raw log ------------------------------- +# Every "must not contain" below could pass on a run that died before reaching +# the editor, so prove the incident was actually reproduced first. The noise is +# legitimately in the raw log: System.run streams both streams live, and the +# fix deliberately did not stop that - it stopped the *message* repeating it. +require "$NOISE_LEAD" "the stub's stderr half never reached the log, so the incident was not reproduced" +require "$NOISE_PROOF" "the aborting stub never ran - docker's own missing-image notice is not the same thing" +require "Aborting batchmode due to failure:" "the stub's stdout half never reached the log" + +# --- The final message, and only it ----------------------------------- +# log.error emits one [ERROR]-prefixed console.error call per invocation, with +# the multi-line message body following on the same call's later lines, so +# "from the last [ERROR] marker to EOF" is exactly what the user is shown as +# the cause. Scoping matters: the noise is streamed live above this point, so +# asserting its absence over the whole log would fail on a correct run. +# +# Not anchored to ^: this job captures the CLI directly, where the marker does +# start the line, but the same log re-read from GitHub's viewer carries a +# "2026-09-19T12:37:25.89Z " prefix - and an anchored match would report the +# misleading "no [ERROR] line at all" rather than grading the message. The last +# match is the CLI's final error either way, so trailing output after it is +# harmless: every assertion below is a containment check. +start="$(grep -n '\[ERROR\]' "$LOG" | tail -1 | cut -d: -f1)" +start="${start:-}" + +if [ -z "$start" ]; then + echo "::error::the CLI printed no [ERROR] line at all - the run failed some other way" + fail=1 +else + FINAL="$(mktemp)" + tail -n "+$start" "$LOG" > "$FINAL" + + if ! grep -qF "$REASON" "$FINAL"; then + echo "::error::the final error does not name Unity's own reason (missing: $REASON)" + echo "--- final error block ---" + cat "$FINAL" + echo "-------------------------" + fail=1 + fi + + if grep -qF 'Unable to find image' "$FINAL"; then + echo "::error::the final error quotes docker's pull noise back as the cause - this is the Mirror#4128 regression" + fail=1 + fi + + rm -f "$FINAL" +fi + +# --- The heading, over the whole log ---------------------------------- +# Sound over the whole log because only two things can print it: the shm-size +# branch in Docker.run (unreachable on an abort path) and +# UnityBatchmodeFailure.describe, which emits it only when its caller passes an +# originalMessage - and Docker.run deliberately no longer does. +forbid 'Original error:' "the final error still carries an 'Original error:' section" + +if [ "$fail" -ne 0 ]; then + exit 1 +fi + +echo "Unity abort message verified: Unity's own reason in the final error, docker's pull noise left in the log above it" diff --git a/scripts/test-assert-unity-abort-message.sh b/scripts/test-assert-unity-abort-message.sh new file mode 100644 index 0000000..3ff7d72 --- /dev/null +++ b/scripts/test-assert-unity-abort-message.sh @@ -0,0 +1,172 @@ +#!/usr/bin/env bash +# +# Drives scripts/assert-unity-abort-message.sh against synthetic logs, in both +# directions. +# +# Why this exists: the grader is the only thing standing between a regression +# and a green build, and a grader that fails open is worse than no grader. Its +# two "must not contain" assertions can only ever pass *vacuously* on a run that +# died early, so the cases below pin that it still fails when the stub degrades, +# and that the pre-#293 message really is rejected. +# +# Every log here is hand-written, which is the point: these cases assert the +# grader's own logic, not whether Unity emits what we think it does. The +# fidelity question is the engine-smoke-test job's problem, and a real log from +# a real run is what answers it. +# +# No Docker, no Unity, no network. Runs in tests.yml alongside the other +# scripts/*.sh suites. + +set -uo pipefail + +REPO_ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" +GRADER="$REPO_ROOT/scripts/assert-unity-abort-message.sh" + +WORK="$(mktemp -d)" +trap 'rm -rf "$WORK"' EXIT + +pass=0 +fail=0 + +# A log shaped like a correct run: the noise is streamed live (System.run does +# that on purpose and the fix did not change it), the reason is the last thing +# printed, and nothing repeats the noise under a heading. +faithful_log() { + cat > "$1" <<'LOG' +Requesting activation (license file) +Successfully updated UnityEntitlementLicense.xml! +# Testing in editmode # +Unable to find image 'game-ci/unity-abort-stub:latest' locally +latest: Pulling from game-ci/unity-abort-stub +Aborting batchmode due to failure: +Scripts have compiler errors. +Build failed, with exit code 1 +[ERROR] Error: Unity aborted before completing: Scripts have compiler errors. + +This is a failure inside the Unity Editor itself (commonly script +compiler errors, a missing package, or a crash during startup) - not a +docker/game-ci infrastructure problem. The full Unity log is above. + at Docker.run (src/model/docker.ts:169:13) +LOG +} + +check() { # + local name="$1" expected="$2" log="$3" actual + bash "$GRADER" "$log" > "$WORK/out" 2>&1 + actual=$? + + if [ "$actual" -eq "$expected" ]; then + echo "ok - $name" + pass=$((pass + 1)) + else + echo "FAIL - $name (expected exit $expected, got $actual)" + sed 's/^/ /' "$WORK/out" + fail=$((fail + 1)) + fi +} + +echo "assert-unity-abort-message.sh" + +# --- The direction that must pass ------------------------------------- +faithful_log "$WORK/faithful.log" +check "accepts a correct run" 0 "$WORK/faithful.log" + +# The same log as GitHub's log viewer renders it, every line timestamp-prefixed. +# The job captures the CLI directly, so this is not the path under test - but a +# grader that misreports a pasted log as "no [ERROR] line at all" wastes exactly +# the debugging time this whole change exists to save. +sed 's/^/2026-09-19T12:37:25.8974485Z /' "$WORK/faithful.log" > "$WORK/timestamped.log" +check "accepts a log carrying GitHub's timestamp prefixes" 0 "$WORK/timestamped.log" + +# --- The regression itself -------------------------------------------- +# The exact pre-#293 shape: the reason is right there, and the noise is quoted +# underneath it as the cause. This is the message two Mirror maintainers read. +cat > "$WORK/regression.log" <<'LOG' +Unable to find image 'game-ci/unity-abort-stub:latest' locally +latest: Pulling from game-ci/unity-abort-stub +Aborting batchmode due to failure: +Scripts have compiler errors. +[ERROR] Error: Unity aborted before completing: Scripts have compiler errors. + +This is a failure inside the Unity Editor itself - not a docker/game-ci +infrastructure problem. The full Unity log is above. + +Original error: +Unable to find image 'game-ci/unity-abort-stub:latest' locally +latest: Pulling from game-ci/unity-abort-stub +LOG +check "rejects the pre-#293 message that quotes the noise" 1 "$WORK/regression.log" + +# The heading alone is enough to reject, even if the noise were stripped from +# it - a future edit could reintroduce the section with different contents. +cat > "$WORK/heading-only.log" <<'LOG' +Unable to find image 'game-ci/unity-abort-stub:latest' locally +latest: Pulling from game-ci/unity-abort-stub +Aborting batchmode due to failure: +Scripts have compiler errors. +[ERROR] Error: Unity aborted before completing: Scripts have compiler errors. + +Original error: +something else entirely +LOG +check "rejects an 'Original error:' heading with any contents" 1 "$WORK/heading-only.log" + +# --- The reason must survive to the end of the run --------------------- +# The original bug's shape: the reason was never in the message at all, so the +# user got a bare exit code. +cat > "$WORK/no-reason.log" <<'LOG' +Unable to find image 'game-ci/unity-abort-stub:latest' locally +latest: Pulling from game-ci/unity-abort-stub +Aborting batchmode due to failure: +Scripts have compiler errors. +[ERROR] Error: Test run failed with exit code 1 +LOG +check "rejects a final error that never names the reason" 1 "$WORK/no-reason.log" + +cat > "$WORK/no-error-line.log" <<'LOG' +Unable to find image 'game-ci/unity-abort-stub:latest' locally +latest: Pulling from game-ci/unity-abort-stub +Aborting batchmode due to failure: +Scripts have compiler errors. +LOG +check "rejects a log with no [ERROR] line at all" 1 "$WORK/no-error-line.log" + +# --- The guards must not fail open ------------------------------------ +# A degraded stub: it never wrote its stderr half, so every "must not contain" +# assertion would pass vacuously. This is the case that keeps the two above +# honest. +grep -vF 'Unable to find image' "$WORK/faithful.log" \ + | grep -vF 'Pulling from' > "$WORK/no-stderr-half.log" +check "rejects a run where the stub never emitted its stderr half" 1 "$WORK/no-stderr-half.log" + +# Docker's own missing-image notice, with the stub never having run - the case +# a naive "the noise is present, so the stub ran" guard would wave through. +cat > "$WORK/docker-own-notice.log" <<'LOG' +Unable to find image 'game-ci/unity-abort-stub:latest' locally +docker: Error response from daemon: pull access denied for game-ci/unity-abort-stub, repository does not exist or may require 'docker login'. +[ERROR] Error: Command exited with code 125 +LOG +check "rejects docker's own missing-image notice as proof the stub ran" 1 "$WORK/docker-own-notice.log" + +# --- Bad invocation --------------------------------------------------- +bash "$GRADER" > "$WORK/out" 2>&1 +if [ $? -eq 2 ]; then + echo "ok - exits 2 with no arguments" + pass=$((pass + 1)) +else + echo "FAIL - exits 2 with no arguments" + fail=$((fail + 1)) +fi + +bash "$GRADER" "$WORK/does-not-exist.log" > "$WORK/out" 2>&1 +if [ $? -eq 2 ]; then + echo "ok - exits 2 for a missing log file" + pass=$((pass + 1)) +else + echo "FAIL - exits 2 for a missing log file" + fail=$((fail + 1)) +fi + +echo +echo "$pass passed, $fail failed" +[ "$fail" -eq 0 ] diff --git a/src/model/docker.ts b/src/model/docker.ts index b45f50c..d9cc971 100644 --- a/src/model/docker.ts +++ b/src/model/docker.ts @@ -127,6 +127,15 @@ class Docker { // Multiline values (a .ulf's XML) are emitted as bare `--env NAME`, so // the docker client has to inherit them from its own environment - see // ImageEnvironmentFactory.getInheritedEnvVars. + // + // Deliberately no `silent` key, which leaves options.silent undefined - + // falsy, but not the `false` System.run's signature default was written + // to express, since a default object only applies when the argument is + // itself undefined. Two things below depend on that: System.run streams + // both streams live (so the catch block can drop docker's stderr as + // already-shown), and a non-silent run keeps `errorMessage` to stderr + // only rather than folding stdout into it. Passing silent: true here + // would silently lose docker's stderr from both the log and the message. const dockerRun = await System.run(command, undefined, { env: ImageEnvironmentFactory.getInheritedEnvVars(options, engineEnvVars(options)), }); diff --git a/src/model/system/system.integration.test.ts b/src/model/system/system.integration.test.ts index 894f02d..ba51972 100644 --- a/src/model/system/system.integration.test.ts +++ b/src/model/system/system.integration.test.ts @@ -29,6 +29,37 @@ describe('System', () => { test('throws when a command exits non-zero', async () => { await expect(System.run('exit 1')).rejects.toThrow(); }); + + // The contract Docker.run's Unity-abort handling rests on, asserted + // against a real child process rather than the mocked System.run in + // docker.test.ts - that mock hard-codes both streams, so it stays + // green if the streams are ever folded together here, which is one of + // the two ways the useful abort reason could go missing again + // (game-ci/cli#288, reported live from MirrorNetworking's CI). + // + // Specifically: Unity's "Aborting batchmode due to failure:" line has + // to arrive on stdout - build.sh runs the editor with `-logfile + // /dev/stdout` - while docker's own pull noise arrives on stderr. That + // split is the only reason the catch block can surface the reason and + // drop the noise. The windowsSpecificCommand exists only so this runs + // on a developer's Windows box too; System.run otherwise picks + // powershell there and sh everywhere else. + test('keeps stdout and stderr apart on a non-zero exit', async () => { + const rejection: any = await System + .run( + "printf 'unity-reason\\n'; printf 'docker-noise\\n' >&2; exit 3", + "Write-Output 'unity-reason'; [Console]::Error.WriteLine('docker-noise'); exit 3", + ) + .catch((error) => error); + + expect(rejection.stdout).toContain('unity-reason'); + expect(rejection.stderr).toContain('docker-noise'); + + // stderr is the whole of `message`; stdout must not be folded in, or + // Docker.run would quote docker's noise as the cause again. + expect(rejection.message).toContain('docker-noise'); + expect(rejection.message).not.toContain('unity-reason'); + }); } }); }); From ded6d672ee7c256c233bb82bb0ddfe28f97bfc97 Mon Sep 17 00:00:00 2001 From: frostebite Date: Sun, 20 Sep 2026 23:14:46 +0100 Subject: [PATCH 4/4] ci: address review on the abort-message reproduction Declare UNITY_VERSION through each step's env rather than interpolating the workflow_dispatch input into the script body, where ${{ }} expands into shell source before bash sees it. Clean the grader's temp file from an EXIT trap so an interrupt cannot leave it behind. Co-Authored-By: Claude Sonnet 5 --- .github/workflows/engine-smoke-test.yml | 12 ++++++++---- scripts/assert-unity-abort-message.sh | 6 ++++-- 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/.github/workflows/engine-smoke-test.yml b/.github/workflows/engine-smoke-test.yml index fae5098..670e338 100644 --- a/.github/workflows/engine-smoke-test.yml +++ b/.github/workflows/engine-smoke-test.yml @@ -370,12 +370,15 @@ jobs: # never runs it. (It is also not an option there, and the CLI parses # strictly, so passing it would fail the invocation outright.) - name: Run the aborting build and grade the message + # Declared as env rather than interpolated into the script body below: + # ${{ }} expands into the source before bash ever sees it, which makes a + # workflow_dispatch input shell code instead of data. + env: + UNITY_VERSION: ${{ github.event.inputs.unity-version || '2019.4.40f1' }} run: | set -uo pipefail LOG=/tmp/unity-abort-build.log - UNITY_VERSION="${{ github.event.inputs.unity-version || '2019.4.40f1' }}" - # Captured to a FILE, never piped through tee: writes to a pipe are # asynchronous, so the CLI's process.exit(1) can truncate the very # message under test. File writes are synchronous. @@ -399,12 +402,13 @@ jobs: # relative to the exit-code capture could lose the reason while the build # step above stayed green. - name: Run the aborting test and grade the message + # Same reason as the build step above. + env: + UNITY_VERSION: ${{ github.event.inputs.unity-version || '2019.4.40f1' }} run: | set -uo pipefail LOG=/tmp/unity-abort-test.log - UNITY_VERSION="${{ github.event.inputs.unity-version || '2019.4.40f1' }}" - # --docker is what selects the container flow; without it this would # run the experimental `unity test` CLI path instead. if bun run src/index.ts test test-project \ diff --git a/scripts/assert-unity-abort-message.sh b/scripts/assert-unity-abort-message.sh index 58a2254..1f46c96 100644 --- a/scripts/assert-unity-abort-message.sh +++ b/scripts/assert-unity-abort-message.sh @@ -90,6 +90,10 @@ if [ -z "$start" ]; then fail=1 else FINAL="$(mktemp)" + # On every exit path, not just the normal one: an interrupt between here and + # the end would otherwise leave the temp file behind. + trap 'rm -f "$FINAL"' EXIT + tail -n "+$start" "$LOG" > "$FINAL" if ! grep -qF "$REASON" "$FINAL"; then @@ -104,8 +108,6 @@ else echo "::error::the final error quotes docker's pull noise back as the cause - this is the Mirror#4128 regression" fail=1 fi - - rm -f "$FINAL" fi # --- The heading, over the whole log ----------------------------------