diff --git a/.github/workflows/engine-smoke-test.yml b/.github/workflows/engine-smoke-test.yml index fcf7855..670e338 100644 --- a/.github/workflows/engine-smoke-test.yml +++ b/.github/workflows/engine-smoke-test.yml @@ -247,6 +247,187 @@ 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 + # 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 + + # 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 + # 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 + + # --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 +684,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 047d5e3..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 @@ -190,6 +199,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 +224,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 +242,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 +282,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 +295,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 diff --git a/scripts/assert-unity-abort-message.sh b/scripts/assert-unity-abort-message.sh new file mode 100644 index 0000000..1f46c96 --- /dev/null +++ b/scripts/assert-unity-abort-message.sh @@ -0,0 +1,124 @@ +#!/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)" + # 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 + 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 +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.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..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)), }); @@ -157,7 +166,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/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'); + }); } }); }); 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}`; } }