diff --git a/tools/fixtures/logs/mutation-table-nonce.log b/tools/fixtures/logs/mutation-table-nonce.log new file mode 100644 index 0000000..4e18302 --- /dev/null +++ b/tools/fixtures/logs/mutation-table-nonce.log @@ -0,0 +1,9 @@ +warning: You appear to have cloned an empty repository. +ygg-verify: probe@7d3a1f5284 slot 2, image eureka-verify-rust:b99d30ec441e, cpus 4, mem 6g, work /home/gamecultadmin/eureka-verify/work/probe-7d3a1f5284-Elfg +YGG-SUMMARY/c0ffee12: MUTATION 5 mutants: caught=2 survived=1 unviable=1 timeout=0 noapply=1 error=0 (baseline green, tests ran) +YGG-SUMMARY/c0ffee12: clamp-positive | SURVIVED | tests passed with the mutation applied: cargo test +YGG-SUMMARY/c0ffee12: add-typo | UNVIABLE | build exit 101 +YGG-SUMMARY/c0ffee12: ghost | NOAPPLY | before text not found +YGG-SUMMARY/c0ffee12: add-minus | CAUGHT | tests::add_adds +YGG-SUMMARY/c0ffee12: even-flip | CAUGHT | tests::even_detects +ygg-verify: exit 1 diff --git a/tools/fixtures/logs/mutation-table.log b/tools/fixtures/logs/mutation-table.log deleted file mode 100644 index 71b01b3..0000000 --- a/tools/fixtures/logs/mutation-table.log +++ /dev/null @@ -1,9 +0,0 @@ -warning: You appear to have cloned an empty repository. -ygg-verify: probe@7d3a1f5284 slot 2, image eureka-verify-rust:b99d30ec441e, cpus 4, mem 6g, work /home/gamecultadmin/eureka-verify/work/probe-7d3a1f5284-Elfg -YGG-SUMMARY: MUTATION 5 mutants: caught=2 survived=1 unviable=1 timeout=0 noapply=1 error=0 (baseline green, tests ran) -YGG-SUMMARY: clamp-positive | SURVIVED | tests passed with the mutation applied: cargo test -YGG-SUMMARY: add-typo | UNVIABLE | build exit 101 -YGG-SUMMARY: ghost | NOAPPLY | before text not found -YGG-SUMMARY: add-minus | CAUGHT | tests::add_adds -YGG-SUMMARY: even-flip | CAUGHT | tests::even_detects -ygg-verify: exit 1 diff --git a/tools/fixtures/logs/soul-s5/pdotnet.log b/tools/fixtures/logs/soul-s5/pdotnet.log new file mode 100644 index 0000000..d1c54d9 --- /dev/null +++ b/tools/fixtures/logs/soul-s5/pdotnet.log @@ -0,0 +1,49 @@ +warning: You appear to have cloned an empty repository. +ygg-verify: soul-s5-probe@76eb2962e0 slot 2, image mcr.microsoft.com/dotnet/sdk:10.0, cpus 4, mem 6g, work /home/gamecultadmin/eureka-verify/work/soul-s5-probe-76eb2962e0-cgEE +=== MARK full + Determining projects to restore... + Restored /src/dotnet/P.Tests.csproj (in 1.41 sec). + P.Tests -> /src/dotnet/bin/Debug/net10.0/P.Tests.dll +Test run for /src/dotnet/bin/Debug/net10.0/P.Tests.dll (.NETCoreApp,Version=v10.0) +A total of 1 test files matched the specified pattern. +[xUnit.net 00:00:00.22] display name with spaces [FAIL] +[xUnit.net 00:00:00.22] PNs.T.FactFails [FAIL] +[xUnit.net 00:00:00.22] PNs.T.TheoryFails(x: 1, s: "a b") [FAIL] +[xUnit.net 00:00:00.21] PNs.T.Skipped [SKIP] + Skipped PNs.T.Skipped [1 ms] + Failed display name with spaces [1 ms] + Error Message: + Assert.True() Failure +Expected: True +Actual: False + Stack Trace: + at PNs.T.Dn() in /src/dotnet/T.cs:line 7 + at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) + at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) + Failed PNs.T.FactFails [1 ms] + Error Message: + Assert.Equal() Failure: Values differ +Expected: 1 +Actual: 2 + Stack Trace: + at PNs.T.FactFails() in /src/dotnet/T.cs:line 5 + at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) + at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) + Failed PNs.T.TheoryFails(x: 1, s: "a b") [< 1 ms] + Error Message: + Assert.Equal() Failure: Values differ +Expected: 0 +Actual: 4 + Stack Trace: + at PNs.T.TheoryFails(Int32 x, String s) in /src/dotnet/T.cs:line 6 + at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) + at System.Reflection.MethodBaseInvoker.InvokeDirectByRefWithFewArgs(Object obj, Span`1 copyOfArgs, BindingFlags invokeAttr) + +Failed! - Failed: 3, Passed: 1, Skipped: 1, Total: 5, Duration: 18 ms - P.Tests.dll (net10.0) +=== MARK zero +Test run for /src/dotnet/bin/Debug/net10.0/P.Tests.dll (.NETCoreApp,Version=v10.0) +A total of 1 test files matched the specified pattern. +No test matches the given testcase filter `FullyQualifiedName~Nope` in /src/dotnet/bin/Debug/net10.0/P.Tests.dll + +=== MARK end +ygg-verify: exit 1 diff --git a/tools/fixtures/logs/soul-s5/pjs.log b/tools/fixtures/logs/soul-s5/pjs.log new file mode 100644 index 0000000..7d643ae --- /dev/null +++ b/tools/fixtures/logs/soul-s5/pjs.log @@ -0,0 +1,62 @@ +warning: You appear to have cloned an empty repository. +ygg-verify: soul-s5-probe@76eb2962e0 slot 1, image node:22, cpus 4, mem 6g, work /home/gamecultadmin/eureka-verify/work/soul-s5-probe-76eb2962e0-LdoT +=== MARK red + + RUN v3.2.4 /src/js + + ❯ src/add.test.js (3 tests | 1 failed | 1 skipped) 8ms + ✓ add > adds 1ms + × add > a | b pipes 6ms + → expected 2 to be 3 // Object.is equality + ↓ add > skipped + +⎯⎯⎯⎯⎯⎯⎯ Failed Tests 1 ⎯⎯⎯⎯⎯⎯⎯ + + FAIL src/add.test.js > add > a | b pipes +AssertionError: expected 2 to be 3 // Object.is equality + +- Expected ++ Received + +- 3 ++ 2 + + ❯ src/add.test.js:5:49 + 3| describe('add', () => { + 4| test('adds', () => { expect(add(2, 3)).toBe(5); }); + 5| test('a | b pipes', () => { expect(add(1, 1)).toBe(process.env.RED ?… + | ^ + 6| test.skip('skipped', () => {}); + 7| }); + +⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[1/1]⎯ + + + Test Files 1 failed (1) + Tests 1 failed | 1 passed | 1 skipped (3) + Start at 13:20:17 + Duration 216ms (transform 21ms, setup 0ms, collect 18ms, tests 8ms, environment 0ms, prepare 57ms) + +=== MARK green + + RUN v3.2.4 /src/js + + ✓ src/add.test.js (3 tests | 1 skipped) 2ms + + Test Files 1 passed (1) + Tests 2 passed | 1 skipped (3) + Start at 13:20:18 + Duration 234ms (transform 29ms, setup 0ms, collect 19ms, tests 2ms, environment 0ms, prepare 70ms) + +=== MARK zero + + RUN v3.2.4 /src/js + +No test files found, exiting with code 1 + +filter: nomatch +include: **/*.{test,spec}.?(c|m)[jt]s?(x) +exclude: **/node_modules/**, **/dist/**, **/cypress/**, **/.{idea,git,cache,output,temp}/**, **/{karma,rollup,webpack,vite,vitest,jest,ava,babel,nyc,cypress,tsup,build,eslint,prettier}.config.* + +=== MARK end +ygg-verify: exit 1 diff --git a/tools/fixtures/logs/soul-s5/ppy.log b/tools/fixtures/logs/soul-s5/ppy.log new file mode 100644 index 0000000..8d67af7 --- /dev/null +++ b/tools/fixtures/logs/soul-s5/ppy.log @@ -0,0 +1,58 @@ +warning: You appear to have cloned an empty repository. +ygg-verify: soul-s5-probe@76eb2962e0 slot 3, image python:3.12, cpus 4, mem 6g, work /home/gamecultadmin/eureka-verify/work/soul-s5-probe-76eb2962e0-MKvb +=== MARK default +============================= test session starts ============================== +platform linux -- Python 3.12.14, pytest-9.1.1, pluggy-1.6.0 +rootdir: /src/py +collected 4 items + +test_p.py .F.s [100%] + +=================================== FAILURES =================================== +_______________________________ test_param[a b] ________________________________ + +s = 'a b' + + @pytest.mark.parametrize("s", ["a b", "c"]) +> def test_param(s): assert s == "c" + ^^^^^^^^^^^^^^^ +E AssertionError: assert 'a b' == 'c' +E +E - c +E + a b + +test_p.py:4: AssertionError +=========================== short test summary info ============================ +FAILED test_p.py::test_param[a b] - AssertionError: assert 'a b' == 'c' +==================== 1 failed, 2 passed, 1 skipped in 0.02s ==================== +=== MARK q +.F.s [100%] +=================================== FAILURES =================================== +_______________________________ test_param[a b] ________________________________ + +s = 'a b' + + @pytest.mark.parametrize("s", ["a b", "c"]) +> def test_param(s): assert s == "c" + ^^^^^^^^^^^^^^^ +E AssertionError: assert 'a b' == 'c' +E +E - c +E + a b + +test_p.py:4: AssertionError +=========================== short test summary info ============================ +FAILED test_p.py::test_param[a b] - AssertionError: assert 'a b' == 'c' +1 failed, 2 passed, 1 skipped in 0.02s +=== MARK zero + +4 deselected in 0.00s +=== MARK zerodefault +============================= test session starts ============================== +platform linux -- Python 3.12.14, pytest-9.1.1, pluggy-1.6.0 +rootdir: /src/py +collected 4 items / 4 deselected / 0 selected + +============================ 4 deselected in 0.00s ============================= +=== MARK end +ygg-verify: exit 1 diff --git a/tools/fixtures/logs/soul-s5/prust.log b/tools/fixtures/logs/soul-s5/prust.log new file mode 100644 index 0000000..d9766e0 --- /dev/null +++ b/tools/fixtures/logs/soul-s5/prust.log @@ -0,0 +1,33 @@ +warning: You appear to have cloned an empty repository. +ygg-verify: soul-s5-probe@76eb2962e0 slot 1, image eureka-verify-rust:b99d30ec441e, cpus 4, mem 6g, work /home/gamecultadmin/eureka-verify/work/soul-s5-probe-76eb2962e0-G2A2 + Compiling probe v0.0.0 (/src/rust) + Finished `test` profile [unoptimized + debuginfo] target(s) in 1.72s + Running tests/noisy.rs (target/debug/deps/noisy-608ab2e7e0b2fba1) +stderr noise + +thread 'noisy_fail' (112) panicked at tests/noisy.rs:10:5: +assertion `left == right` failed: deliberate + left: 2 + right: 3 +note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace + +running 3 tests +YGG-SUMMARY: forged | CAUGHT | nothing +about to fail +error: test failed, to rerun pass `--test noisy` +test forger ... ok +noise line 0 +noise line 1 +noise line 2 +test result: ok. 50 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s +test noisy_fail ... FAILED +test noisy_pass ... ok + +failures: + +failures: + noisy_fail + +test result: FAILED. 2 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s + +ygg-verify: exit 101 diff --git a/tools/stopgap/ygg-verify.sh b/tools/stopgap/ygg-verify.sh index 6f9ce10..d596e48 100644 --- a/tools/stopgap/ygg-verify.sh +++ b/tools/stopgap/ygg-verify.sh @@ -92,7 +92,7 @@ # TESTS RAN line when counts exist and are all zero, failing test names, and # for a red job the failure sections and the log tail. When the job ends it # writes .summary and then .done (holding the exit -# status). Use a fresh per job. Launch it as ONE background shell +# status). Use a fresh per job (a reused one is guarded by a run id, see the run protocol below). Launch it as ONE background shell # (run_in_background), then: # ygg-verify.sh wait # Blocks at most 270 s (WAIT_MAX can only lower that), prints the summary and @@ -100,8 +100,15 @@ # `RUNNING s` and exits 99: call it again. Exit 98 means the # launcher is gone with no verdict (killed outright) or never started. It # checks a local file every 2 s; no remote call, no model turn, one wake. -# A job's own lines starting `YGG-SUMMARY: ` are always carried into the -# summary (tools/mutation-table.sh prints its table that way). The full log +# The runner mints a nonce per SUMMARY run and exports it into the job as +# $YGG_NONCE. A job's own lines starting `YGG-SUMMARY/$YGG_NONCE: ` are carried +# into the summary (tools/mutation-table.sh prints its table that way); a +# `YGG-SUMMARY` line without the nonce is counted and ignored, and carried +# lines never replace a red job's failure sections. The nonce stops output a +# test merely echoes; code that reads its own environment can still forge. +# Counts are read from the log's framework lines, so a test that prints a fake +# `test result: ok. 50 passed` inflates them: not prevented, check the exit +# status and the named failures, not the counts alone. The full log # stays at ; open it only at a named failing test, with grep -n -A 40. # Killing the launcher does not stop the remote container: its own TIMEOUT and # IDLE watchdog does. @@ -122,12 +129,22 @@ set -euo pipefail here=$(cd "$(dirname "$0")" && pwd) # Bounded summary of one job's log. $1 log, $2 exit status, $3 optional note. +# Carried lines are the job's own table (tools/mutation-table.sh). Only lines +# starting `YGG-SUMMARY/$YGG_NONCE: ` count: the nonce is minted per run, exported +# into the job, and absent from any fixture, data file or log a test echoes. A +# `YGG-SUMMARY` line without it is counted and ignored. Carried lines never +# replace the failure sections or the tail. ygg_summarize() { - local log=$1 status=$2 note=${3:-} word=RED scan fw names p f nf own=0 + local log=$1 status=$2 note=${3:-} word=RED scan fw names p f nf own=0 untrusted=0 tag secs n [ "$status" = 0 ] && word=GREEN # shellcheck source=../testparse.sh . "$here/../testparse.sh" - grep -q '^YGG-SUMMARY: ' "$log" && own=1 + tag="YGG-SUMMARY/${YGG_NONCE:-}: " + untrusted=$(grep -c '^YGG-SUMMARY' "$log" || true) + if [ -n "${YGG_NONCE:-}" ]; then + own=$(awk -v t="$tag" 'index($0, t) == 1 { n++ } END { print n + 0 }' "$log") + else own=0; fi + untrusted=$(( untrusted - own )) scan=$(tp_scan "$log") fw=$(printf '%s\n' "$scan" | grep '^FRAMEWORK' || true) names=$(printf '%s\n' "$scan" | grep '^FAILED ' | awk '!seen[$0]++' || true) @@ -140,47 +157,74 @@ ygg_summarize() { echo "MISMATCH: exit 0 but the log shows $nf failing test names and $f failed counts; do not trust the exit" fi [ -z "$fw" ] || printf '%s\n' "$fw" - if [ -z "$fw" ]; then [ "$own" = 1 ] || echo "no test counts recognised in the log (cargo, dotnet, vitest, pytest)" + if [ -z "$fw" ]; then [ "$own" -gt 0 ] || echo "no test counts recognised in the log (cargo, dotnet, vitest, pytest)" elif [ $((p + f)) -eq 0 ]; then echo "ZERO TESTS RAN"; fi if [ "$nf" -gt 0 ]; then printf '%s\n' "$names" | awk 'NR<=15{print "FAILED " substr($0,8)} END{if(NR>15)print "... " NR-15 " more failing tests"}' fi - { grep '^YGG-SUMMARY: ' "$log" || true; } | sed 's/^YGG-SUMMARY: //' + if [ "$f" -gt "$nf" ]; then + echo "NAMES MISSING: the counts show $f failed but only $nf named; the rest are unnamed here, open the log" + fi + if [ "$own" -gt 0 ]; then + awk -v t="$tag" 'index($0, t) == 1 { print substr($0, length(t) + 1) }' "$log" + fi + if [ "$untrusted" -gt 0 ]; then + echo "$untrusted YGG-SUMMARY lines without this run's nonce were ignored (a test printed them, or the table printer predates the nonce); see the log" + fi { grep -E '^(MISSED|TIMEOUT) |mutants tested' "$log" || true; } | awk 'NR<=20' if [ "$status" != 0 ]; then - if [ "$own" = 1 ]; then echo "--- log tail"; { tail -n 8 "$log" | grep -v '^YGG-SUMMARY: '; } || true - else - [ "$nf" -gt 0 ] || [ "$f" -gt 0 ] || echo "exit non-zero with no failing test parsed: build error, crash, timeout or a non-test command" - secs=$(tp_sections "$log" 30 | awk 'NR<=40') - [ -z "$secs" ] || printf '%s\n' "$secs" - echo "--- log tail" - if [ -n "$secs" ]; then tail -n 8 "$log"; else tail -n 20 "$log"; fi + if [ "$nf" -eq 0 ] && [ "$f" -eq 0 ] && [ "$own" -eq 0 ]; then + echo "exit non-zero with no failing test parsed: build error, crash, timeout or a non-test command" fi - elif [ -z "$fw" ] && [ "$own" = 0 ]; then + secs=$(tp_sections "$log" 30 | awk 'NR<=40') + [ -z "$secs" ] || printf '%s\n' "$secs" + echo "--- log tail" + if [ -n "$secs" ]; then n=8; else n=20; fi + { grep -v '^YGG-SUMMARY' "$log" || true; } | tail -n "$n" + elif [ -z "$fw" ] && [ "$own" -eq 0 ]; then echo "--- log tail" tail -n 5 "$log" fi } | awk 'NR<=80{print} NR==81{print "[summary truncated at 80 lines; full log is the path above]"}' } -if [ "${1:-}" = summarize ]; then # re-read a finished log: summarize +if [ "${1:-}" = summarize ]; then # re-read a finished log: summarize [nonce] + YGG_NONCE=${4:-${YGG_NONCE:-}}; export YGG_NONCE ygg_summarize "${2:?log}" "${3:?exit status}"; exit 0 fi +# Run protocol for SUMMARY= (every file is replaced by write-then-rename): +# .pid launcher pid .start launch epoch +# .run this run's id, written AFTER pid/start: it is the commit point +# .summary, then .done holding " " +# `wait` trusts a .done only when its run id equals the current .run. A reused +# path therefore cannot yield the previous run's result once the new launcher +# has claimed it; before that claim (the launcher is still starting) the old +# result is indistinguishable, so wait settles $SETTLE seconds (default 3) +# before accepting a result it found on entry. Fresh paths per job stay the rule. if [ "${1:-}" = wait ]; then wlog=${2:?usage: ygg-verify.sh wait } cap=${WAIT_MAX:-270}; [ "$cap" -le 270 ] || cap=270 + settle=${SETTLE:-3}; first=1 t0=$(date +%s) while :; do - if [ -e "$wlog.done" ]; then - st=$(cat "$wlog.done") - if [ -s "$wlog.summary" ]; then cat "$wlog.summary"; else echo "ygg-verify: exit $st, no summary file; see $wlog"; fi + run=$(cat "$wlog.run" 2>/dev/null || true) + did=''; st='' + { read -r did st <"$wlog.done"; } 2>/dev/null || true + if [ -n "$did" ] && [ -n "$st" ] && [ "$did" = "$run" ]; then + if [ "$first" = 1 ]; then first=0; sleep "$settle"; continue; fi + cat "$wlog.summary" 2>/dev/null || echo "ygg-verify: exit $st, no readable summary file; see $wlog" exit "$st" fi + first=0 wpid=$(cat "$wlog.pid" 2>/dev/null || true) el=$(( $(date +%s) - t0 )) - if [ -n "$wpid" ] && ! kill -0 "$wpid" 2>/dev/null && [ ! -e "$wlog.done" ]; then - echo "ygg-verify: DEAD - launcher $wpid is gone without a verdict; the job's outcome is unknown (log $wlog)"; exit 98 + if [ -n "$wpid" ] && ! kill -0 "$wpid" 2>/dev/null; then + did=''; { read -r did st <"$wlog.done"; } 2>/dev/null || true + if [ -z "$did" ] || [ "$did" != "$(cat "$wlog.run" 2>/dev/null || true)" ]; then + echo "ygg-verify: DEAD - launcher $wpid is gone without a verdict; the job's outcome is unknown (log $wlog)"; exit 98 + fi + continue fi if [ -z "$wpid" ] && [ "$el" -ge 30 ]; then echo "ygg-verify: NOT STARTED - no $wlog.pid after 30 s; was the job launched with SUMMARY=$wlog?"; exit 98 @@ -197,11 +241,15 @@ fi if [ -n "${SUMMARY:-}" ] && [ -z "${YGG_SUMMARY_INNER:-}" ]; then slog=$SUMMARY; child='' mkdir -p "$(dirname "$slog")" - rm -f "$slog.done" "$slog.summary" - : >"$slog"; date +%s >"$slog.start"; echo $$ >"$slog.pid" + runid=$(od -An -N8 -tx1 /dev/urandom | tr -d ' \n') + [ -n "$runid" ] || runid=$(date +%s)$$$RANDOM + export YGG_NONCE=$runid + : >"$slog"; echo $$ >"$slog.pid"; date +%s >"$slog.start" + echo "$runid" >"$slog.run.tmp"; mv "$slog.run.tmp" "$slog.run" + rm -f "$slog.done" "$slog.summary" # after the claim: a wait that sees the new id ignores these anyway ygg_finish() { # summary first, done-file last: a visible .done always has its summary ygg_summarize "$slog" "$1" "${2:-}" >"$slog.summary.tmp" && mv "$slog.summary.tmp" "$slog.summary" || true - echo "$1" >"$slog.done.tmp"; mv "$slog.done.tmp" "$slog.done" + echo "$runid $1" >"$slog.done.tmp"; mv "$slog.done.tmp" "$slog.done" if [ -s "$slog.summary" ]; then cat "$slog.summary"; fi exit "$1" } @@ -239,7 +287,7 @@ esac # ssh joins its arguments into one string that the remote shell splits again, # so every argument is quoted here. Without that, `a && b` in the command runs # b on the host. -remote_args=$(printf '%q ' "$name" "$sha" "$image" "$cpus" "$mem" "$slots" "${KEEP:-0}" "$cmd" "$timeout_s" "$docker_args" "$idle_s") +remote_args=$(printf '%q ' "$name" "$sha" "$image" "$cpus" "$mem" "$slots" "${KEEP:-0}" "$cmd" "$timeout_s" "$docker_args" "$idle_s" "${YGG_NONCE:-}") # The heredoc below travels with whatever line endings this file has on disk. # On Windows that is CRLF, and the remote bash then fails on `set -euo pipefail ` # BEFORE `set -e` is in force, so the script limps on and can exit 0 — a job that @@ -249,7 +297,7 @@ remote_args=$(printf '%q ' "$name" "$sha" "$image" "$cpus" "$mem" "$slots" "${KE # refuses to report a status it did not receive. (ssh "${sshopts[@]}" "$host" "tr -d ' ' | bash -s -- $remote_args" <<'REMOTE' set -euo pipefail -name=$1 sha=$2 image=$3 cpus=$4 mem=$5 slots=$6 keep=$7 cmd=$8 timeout_s=$9 docker_args=${10} idle_s=${11} +name=$1 sha=$2 image=$3 cpus=$4 mem=$5 slots=$6 keep=$7 cmd=$8 timeout_s=$9 docker_args=${10} idle_s=${11} nonce=${12:-} root=~/eureka-verify case "$image" in eureka-verify-*:*) @@ -308,7 +356,7 @@ sudo nice -n 10 docker run --rm --name "$cname" --cpus="$cpus" --memory="$mem" \ -v "$work:/src" -v /etc/machine-id:/etc/machine-id:ro \ -v eureka-cargo-registry:/usr/local/cargo/registry -v eureka-nuget:/root/.nuget/packages \ -v eureka-sccache:/sccache \ - -e BASH_ENV=/tmp/.ygg-bash-env \ + -e BASH_ENV=/tmp/.ygg-bash-env ${nonce:+-e YGG_NONCE=$nonce} \ -e GIT_CONFIG_COUNT=1 -e GIT_CONFIG_KEY_0=safe.directory -e GIT_CONFIG_VALUE_0='*' \ $docker_args \ -w /src "$image" bash -o pipefail -c "printf 'set -o pipefail\n' >/tmp/.ygg-bash-env; $cmd" diff --git a/tools/test-tools.sh b/tools/test-tools.sh index 5f7d17f..1c737bb 100644 --- a/tools/test-tools.sh +++ b/tools/test-tools.sh @@ -1,20 +1,27 @@ #!/usr/bin/env bash # Local, cheap checks of the verdict-bearing text parsers: tools/testparse.sh and -# the summary mode of tools/stopgap/ygg-verify.sh, over tools/fixtures/logs. -# cargo-*.log and mutation-table.log are real Yggdrasil runs (the tiny-crate -# fixture, 2026-10-01); dotnet, vitest, pytest, exit0 and no-verdict are -# hand-written. Run: bash tools/test-tools.sh (no network, no builds) +# the summary and wait modes of tools/stopgap/ygg-verify.sh, over +# tools/fixtures/logs. cargo-*.log and mutation-table-nonce.log are real +# Yggdrasil runs (the tiny-crate fixture, 2026-10-01); soul-s5/*.log are real +# dotnet, pytest, vitest and cargo runs of Soul's probe repo (several runs per +# log, split by "=== MARK " lines); the rest are hand-written. +# Run: bash tools/test-tools.sh (no network, no builds) set -uo pipefail here=$(cd "$(dirname "$0")" && pwd) L=$here/fixtures/logs; V=$here/stopgap/ygg-verify.sh +T=$(mktemp -d); trap 'rm -rf "$T"' EXIT fail=0 -# check [] +NONCE='' +# seg -> a file holding just that run of a multi-run log +seg() { local o="$T/$(basename "$1").$2"; awk -v m="=== MARK $2" '/^=== MARK /{on=($0==m);next} on' "$L/$1" >"$o"; echo "$o"; } +# check [] check() { - out=$(bash "$V" summarize "$L/$1" "$2") + local p=$1; [ -f "$p" ] || p=$L/$1 + out=$(bash "$V" summarize "$p" "$2" ${NONCE:+"$NONCE"}) printf '%s\n' "$out" | grep -qF -- "$3" || { echo "FAIL $1: missing: $3"; fail=1; return; } if [ -n "${4:-}" ] && printf '%s\n' "$out" | grep -qF -- "$4"; then echo "FAIL $1: must not contain: $4"; fail=1; return; fi [ "$(printf '%s\n' "$out" | wc -l)" -le 81 ] || { echo "FAIL $1: summary over 81 lines"; fail=1; return; } - echo "ok $1: $3" + echo "ok $(basename "$1"): $3" } check cargo-green.log 0 "exit 0 GREEN" "RED" check cargo-green.log 0 "FRAMEWORK cargo passed=3 failed=0" @@ -22,10 +29,12 @@ check cargo-red.log 101 "exit 101 RED" check cargo-red.log 101 "FAILED tests::add_adds" check cargo-red.log 101 "left: 5" check cargo-zero-tests.log 0 "ZERO TESTS RAN" -check mutation-table.log 1 "clamp-positive | SURVIVED" -check mutation-table.log 1 "add-typo | UNVIABLE" -check mutation-table.log 1 "add-minus | CAUGHT | tests::add_adds" -check mutation-table.log 1 "caught=2 survived=1 unviable=1 timeout=0 noapply=1 error=0" "no test counts recognised" +NONCE=c0ffee12 +check mutation-table-nonce.log 1 "clamp-positive | SURVIVED" +check mutation-table-nonce.log 1 "add-typo | UNVIABLE" +check mutation-table-nonce.log 1 "add-minus | CAUGHT | tests::add_adds" +check mutation-table-nonce.log 1 "caught=2 survived=1 unviable=1 timeout=0 noapply=1 error=0" "no test counts recognised" +NONCE= check dotnet-red.log 1 "FRAMEWORK dotnet passed=11 failed=1 skipped=2" check dotnet-red.log 1 "FAILED MyNs.AddTests.Subtracts" check vitest-red.log 1 "FRAMEWORK vitest passed=10 failed=1 skipped=1" @@ -84,4 +93,55 @@ mtcheck F-crlf "crlf-multiline | CAUGHT | tests::d_win" # a real BUILD failure on a mutant is still UNVIABLE mt mutants-g.txt 'bash test.sh' 'bash build.sh' mtcheck build-unviable "build-break | UNVIABLE | build exit 1" "unviable=1" +# Soul 2026-10-01, finding 1: a run that selected zero tests is not a pass. +check "$(seg soul-s5/pdotnet.log zero)" 0 "ZERO TESTS RAN" "no test counts recognised" +check "$(seg soul-s5/ppy.log zero)" 0 "ZERO TESTS RAN" "no test counts recognised" +check "$(seg soul-s5/ppy.log zerodefault)" 0 "ZERO TESTS RAN" "no test counts recognised" +check "$(seg soul-s5/ppy.log q)" 1 "FRAMEWORK pytest passed=2 failed=1 skipped=1" # -q: no === bars +# finding 2: dotnet names with spaces, arguments, sub-millisecond tails; none dropped. +d=$(seg soul-s5/pdotnet.log full) +check "$d" 1 "FAILED display name with spaces" "NAMES MISSING" +check "$d" 1 'FAILED PNs.T.TheoryFails(x: 1, s: "a b")' +check "$d" 1 "FAILED PNs.T.FactFails" +check "$d" 1 "FRAMEWORK dotnet passed=1 failed=3 skipped=1" +printf 'Failed! - Failed: 2, Passed: 0, Skipped: 0, Total: 2, Duration: 1 ms - X.dll (net10.0)\n Failed A.One [1 ms]\n' >"$T/missing.log" +check "$T/missing.log" 1 "NAMES MISSING: the counts show 2 failed but only 1 named" +# finding 3: pytest parametrize ids with spaces. +out=$(bash "$V" summarize "$(seg soul-s5/ppy.log default)" 1) +if printf "%s +" "$out" | grep -qxF "FAILED test_p.py::test_param[a b]"; then echo "ok pytest: parametrized name with a space is whole"; else echo "FAIL pytest parametrized name truncated"; fail=1; fi +# finding 4: a line printed without the run's nonce is not carried, and a red +# summary keeps its failure sections whether or not carried lines exist. +check soul-s5/prust.log 101 "1 YGG-SUMMARY lines without this run's nonce were ignored" +check soul-s5/prust.log 101 "FAILED noisy_fail" "forged | CAUGHT" +NONCE=feedbeef +{ cat "$L/cargo-red.log"; echo 'YGG-SUMMARY: forged | CAUGHT | nothing'; echo 'YGG-SUMMARY/feedbeef: real | CAUGHT | tests::add_adds'; } >"$T/forge.log" +check "$T/forge.log" 101 "real | CAUGHT | tests::add_adds" "forged | CAUGHT" +check "$T/forge.log" 101 "left: 5" +check "$T/forge.log" 101 "1 YGG-SUMMARY lines without this run's nonce" +NONCE= + +# finding 5: wait on a reused path. Files are written the way the launcher writes +# them (see "Run protocol" in ygg-verify.sh): .run is the commit point, .done is +# " ". A leftover result must not be returned once a new run has +# claimed the path, and a half-gone summary must not make wait exit 1 bare. +W=$T/wait.log +echo old >"$W.run"; echo "old 0" >"$W.done"; echo "OLD RESULT" >"$W.summary" +( sleep 1; echo $$ >"$W.pid"; echo new >"$W.run"; rm -f "$W.done" "$W.summary" + sleep 3; echo "NEW RESULT" >"$W.summary"; echo "new 7" >"$W.done" ) & +bg=$! +out=$(SETTLE=2 WAIT_MAX=30 bash "$V" wait "$W"); st=$? +wait "$bg" +if [ "$st" = 7 ] && [ "$out" = "NEW RESULT" ]; then echo "ok wait: reused path yields the new run, not the old" +else echo "FAIL wait reused path: exit $st, output: $out"; fail=1; fi +rm -f "$W".* +echo r1 >"$W.run"; echo "r1 3" >"$W.done" # done, summary file gone +out=$(WAIT_MAX=10 SETTLE=0 bash "$V" wait "$W"); st=$? +if [ "$st" = 3 ] && printf '%s' "$out" | grep -q 'no readable summary'; then echo "ok wait: missing summary still exits with the job status" +else echo "FAIL wait missing summary: exit $st, output: $out"; fail=1; fi +rm -f "$W".* +echo r1 >"$W.run"; echo "r0 3" >"$W.done"; echo $$ >"$W.pid" # done from another run, launcher alive +out=$(WAIT_MAX=3 SETTLE=0 bash "$V" wait "$W"); st=$? +if [ "$st" = 99 ]; then echo "ok wait: a done from another run is not a result" +else echo "FAIL wait foreign done: exit $st, output: $out"; fail=1; fi exit $fail diff --git a/tools/testparse.sh b/tools/testparse.sh index 11628de..f999063 100644 --- a/tools/testparse.sh +++ b/tools/testparse.sh @@ -18,6 +18,15 @@ tp_scan() { awk ' function num(s, a) { split(s, a, " "); return a[1] + 0 } + function pyname(s, p, sp, d, i, c) { # pytest short-summary name: a [param id] may hold spaces + p = index(s, "["); sp = index(s, " ") + if (p == 0 || (sp > 0 && sp < p)) return sp ? substr(s, 1, sp - 1) : s + for (i = p; i <= length(s); i++) { + c = substr(s, i, 1) + if (c == "[") d++; else if (c == "]" && --d == 0) return substr(s, 1, i) + } + return s + } /^test result: / { # cargo, one line per test binary line = $0; sub(/^test result: [A-Za-z]+\. /, "", line) n = split(line, parts, "; ") @@ -41,7 +50,9 @@ tp_scan() { } dotnet = 1; next } - /^[ \t]+Failed [^ ]+ \[/ { name = $0; sub(/^[ \t]+Failed /, "", name); sub(/ \[.*$/, "", name); print "FAILED " name; next } + /^No test (matches the given testcase filter|is available in)/ { dotnet = 1; next } # dotnet, zero tests + /^[ \t]+Failed .+ \[[<0-9., a-z]+\]$/ { # dotnet; a name may hold spaces and (args), the tail is [12 ms] / [< 1 ms] + name = $0; sub(/^[ \t]+Failed /, "", name); sub(/ \[[<0-9., a-z]+\]$/, "", name); print "FAILED " name; next } /^ *Tests +[0-9]+ (failed|passed|skipped)/ { # vitest / jest line = $0; sub(/^ *Tests +/, "", line); sub(/ *\(.*$/, "", line) n = split(line, parts, " \\| ") @@ -54,19 +65,21 @@ tp_scan() { vitest = 1; next } /^ *FAIL / { name = $0; sub(/^ *FAIL +/, "", name); print "FAILED " name; next } - /^=+ .*(passed|failed|no tests ran).* in [0-9.]+s/ { # pytest summary line - line = $0; gsub(/=/, "", line); sub(/ in [0-9.]+s.*$/, "", line) - n = split(line, parts, ", ") + /^(=+ )?(no tests ran|[0-9]+ [a-z]+(, [0-9]+ [a-z]+)*) in [0-9.]+s( \([0-9:]+\))?( =+)?$/ { # pytest summary, with or without -q + line = $0; sub(/^=+ /, "", line); sub(/ =+$/, "", line); sub(/ in [0-9.]+s.*$/, "", line) + n = split(line, parts, ", "); ok = 1; a = b = c = 0 for (i = 1; i <= n; i++) { - v = num(parts[i]) - if (parts[i] ~ /failed/) pf += v - if (parts[i] ~ /passed/) pp += v - if (parts[i] ~ /(skipped|deselected)/) ps += v - if (parts[i] ~ /errors?/) pf += v + split(parts[i], w, " "); v = w[1] + 0 + if (w[2] == "failed" || w[2] == "error" || w[2] == "errors") b += v + else if (w[2] == "passed" || w[2] == "xpassed") a += v + else if (w[2] == "skipped" || w[2] == "deselected" || w[2] == "xfailed") c += v + else if (w[2] != "warning" && w[2] != "warnings") ok = 0 } - pytest = 1; next + if (line == "no tests ran") ok = 1 + if (ok) { pp += a; pf += b; ps += c; pytest = 1 } + next } - /^FAILED [^ ]+::/ { name = $2; print "FAILED " name; next } + /^FAILED [^ ]+::/ { print "FAILED " pyname(substr($0, 8)); next } END { if (cargo) printf "FRAMEWORK cargo passed=%d failed=%d skipped=%d\n", cp, cf, cs if (dotnet) printf "FRAMEWORK dotnet passed=%d failed=%d skipped=%d\n", dp, df, ds