diff --git a/.github/workflows/dotnet.yml b/.github/workflows/dotnet.yml index f185915ca..d872aaf92 100644 --- a/.github/workflows/dotnet.yml +++ b/.github/workflows/dotnet.yml @@ -36,6 +36,9 @@ jobs: echo "### Version: $version" >> $GITHUB_STEP_SUMMARY - name: Test + # Names this run in the retry ledger written to the job summary (build/RetryLedger.cs). + env: + CI_JOB_NAME: dotnet-ci run: ./build.sh ci # The CI target now also runs MessageRoutingTests, which boots a real diff --git a/.github/workflows/http.yml b/.github/workflows/http.yml index 23934b34e..206face22 100644 --- a/.github/workflows/http.yml +++ b/.github/workflows/http.yml @@ -35,11 +35,17 @@ jobs: - name: Exercise the openapi command run: ./build.sh OpenApiCommand --framework net9.0 + # CI_JOB_NAME names each run in the retry ledger written to the job summary + # (build/RetryLedger.cs). - name: Run HTTP Tests + env: + CI_JOB_NAME: CIHttp run: ./build.sh CIHttp --framework net9.0 # Asp.Versioning tests are pinned to net10.0 - name: Run HTTP Asp.Versioning Tests + env: + CI_JOB_NAME: CIHttpAspVersioning run: ./build.sh CIHttpAspVersioning - name: Stop containers diff --git a/.github/workflows/slow-tests.yml b/.github/workflows/slow-tests.yml index 249bdac79..702fdfbee 100644 --- a/.github/workflows/slow-tests.yml +++ b/.github/workflows/slow-tests.yml @@ -45,6 +45,9 @@ jobs: dotnet-version: 10.0.x - name: Run Tests + # Names this run in the retry ledger written to the job summary (build/RetryLedger.cs). + env: + CI_JOB_NAME: CISlowTests run: ./build.sh CISlowTests --framework net9.0 - name: Stop containers diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index f6ac3ef36..c3c51bac3 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -91,6 +91,9 @@ jobs: - name: Run Tests env: MEMORY_TELEMETRY: ${{ matrix.memory_telemetry }} + # Names this job in the retry ledger (build/RetryLedger.cs). GITHUB_JOB is the matrix's + # job id -- the same string, "test", for all thirty of these -- so it cannot be used. + CI_JOB_NAME: ${{ matrix.target }} run: | # The sampler has to live inside this step: when the runner is killed, later steps are # skipped, so only what has already been streamed to this step's log survives. See #3771. @@ -111,6 +114,65 @@ jobs: echo "::endgroup::" free -m + # The per-job half of GH-3787. `if: always()` because a job that FAILED is exactly the one + # whose retry count is worth having -- and a job killed by the 20-minute cap uploads nothing + # at all, which the roll-up below reports as unmeasured rather than as clean. + - name: Upload retry ledger + if: always() + uses: actions/upload-artifact@v7 + with: + name: test-ledger-${{ matrix.target }} + path: artifacts/test-ledger/ + if-no-files-found: ignore + retention-days: 30 + - name: Stop containers if: always() run: docker compose down + + # The run-level half of GH-3787. Aggregates every job's ledger into one table on the run summary + # and diffs it against the last `main` run that published one. + # + # This exists because the absolute retry count was never the signal: CIAzureServiceBus sat at 22 of + # 25 retries for four consecutive GREEN main runs, and the step from 1 to 22 between two adjacent + # runs was the thing worth seeing. Nowhere had that number ever been written down to compare + # against. Informational only -- it never fails the run. + flakiness: + name: Flakiness roll-up + needs: test + if: always() + runs-on: ubuntu-latest + permissions: + actions: read + contents: read + steps: + - name: Checkout + uses: actions/checkout@v6 + with: + fetch-depth: 1 + + # Fails when nothing matches, which is a legitimate state: every test job can have died before + # it wrote a ledger. The roll-up reports that as unmeasured, so it must survive to run. + - name: Download retry ledgers + continue-on-error: true + uses: actions/download-artifact@v8 + with: + pattern: test-ledger-* + path: ledgers + merge-multiple: false + + - name: Roll up + env: + GH_TOKEN: ${{ github.token }} + run: ./build/flakiness-report.sh ledgers rollup + + # This run's aggregate becomes the next run's baseline. Only from `main`: a PR's numbers are + # measured against main, never the other way round, or one noisy branch would move the bar. + - name: Publish this run's baseline + if: github.ref == 'refs/heads/main' + uses: actions/upload-artifact@v7 + with: + name: test-ledger-run + path: rollup/aggregate.json + if-no-files-found: warn + retention-days: 90 diff --git a/build/RetryLedger.cs b/build/RetryLedger.cs new file mode 100644 index 000000000..63a444b9c --- /dev/null +++ b/build/RetryLedger.cs @@ -0,0 +1,198 @@ +using System; +using System.IO; +using System.Linq; +using System.Text; +using System.Text.Json; +using Bobcat.Supervisor; +using Nuke.Common.IO; +using Serilog; + +// The retry ledger: what every supervised run reports about its OWN flakiness, where somebody will +// actually see it. See GH-3787. +// +// The problem this exists for: CIAzureServiceBus was green for four consecutive main runs while +// spending 22 of its 25-retry budget on every one of them — the same 22 tests failing on the first +// attempt and passing alone in a fresh process, because the emulator wasn't warm yet. That was 85% +// of all flakiness in the repository, and nothing in the GitHub UI distinguishes a job at 22/25 +// retries from one at 0/25. Both render as a green tick. +// +// Bobcat already logged all of it. Serilog warnings are not GitHub annotations, though — the +// annotations endpoint for that job returns an empty list — so reading them meant opening the log +// of a job that PASSED, which nobody has a reason to do. It was found by accident. +// +// Three outputs, deliberately: +// +// - `$GITHUB_STEP_SUMMARY` markdown, so the numbers are on the run page without opening a log. +// - a `::warning` workflow command when the count is nonzero, so it reaches the Annotations panel. +// - a JSON ledger under artifacts/test-ledger/, uploaded per job and aggregated by the +// `flakiness` roll-up job in tests.yml, which diffs the run against the last completed main run. +// +// The third is the one that matters most. The absolute count mattered less than the CHANGE in it: +// the step from 1 to 22 between two adjacent main runs was the real signal, and no baseline existed +// anywhere to notice it against. +// +// Deliberately NOT here: failing the build past a retry threshold. A suite legitimately sitting at +// 3 today would be one bad day away from a red main, and the value is in visibility, not a cliff. +partial class Build +{ + /// + /// Per-project ledger files, one per project+framework, uploaded as a CI artifact. Under + /// artifacts/ because empties it at the start of every run, so a ledger can + /// never be a stale leftover from a previous invocation. + /// + static AbsolutePath LedgerDirectory => RootDirectory / "artifacts" / "test-ledger"; + + /// + /// The CI job this run belongs to (e.g. CIAzureServiceBus). Set by tests.yml from the matrix + /// target; the Nuke target name isn't reachable from here and GITHUB_JOB reports the matrix's + /// job id ("test"), which is the same string for all thirty jobs. + /// + static string ledgerJobName => Environment.GetEnvironmentVariable("CI_JOB_NAME") is { Length: > 0 } name + ? name + : "local"; + + void recordLedger(string projectName, string framework, SupervisorResults results) + { + var entry = new LedgerEntry + { + Job = ledgerJobName, + Project = projectName, + Framework = framework, + Tests = results.Tests.Count, + CleanPasses = results.CleanPasses.Count, + PassedOnRetry = results.PassedOnRetry.Count, + RetriesPerformed = results.RetriesPerformed, + Failed = results.Failed.Count, + Indeterminate = results.Indeterminate.Count, + WorkerFaults = results.WorkerFaults.Count, + AbortReason = results.AbortReason, + // Bounded by the budget itself: the point of the list is to name the suspects, not to + // reproduce the log. + FlakyTests = results.PassedOnRetry.Select(x => x.DisplayName).Take(MaxRetriesPerRun).ToArray() + }; + + writeLedgerFile(entry); + appendStepSummary(entry); + annotate(entry); + } + + static void writeLedgerFile(LedgerEntry entry) + { + try + { + LedgerDirectory.CreateDirectory(); + + // One file per project+framework: a target can run several projects, and a project can + // run under several TFMs, so neither alone is a unique key. + var fileName = $"{entry.Job}.{entry.Project}.{entry.Framework}.json"; + var path = LedgerDirectory / fileName; + + File.WriteAllText(path, JsonSerializer.Serialize(entry, LedgerJson)); + } + catch (Exception e) + { + // Reporting about the tests must never be what fails the tests. + Log.Warning(e, "Could not write the retry ledger for {Project}", entry.Project); + } + } + + /// + /// Appends this project's row to the job summary. Every supervised project in the job appends + /// to the same file, so the header is written once, on the first append. + /// + static void appendStepSummary(LedgerEntry entry) + { + var summaryFile = Environment.GetEnvironmentVariable("GITHUB_STEP_SUMMARY"); + if (string.IsNullOrEmpty(summaryFile)) return; + + try + { + var builder = new StringBuilder(); + + if (new FileInfo(summaryFile) is { Exists: false } or { Length: 0 }) + { + builder.AppendLine($"### Retry ledger — {entry.Job}"); + builder.AppendLine(); + builder.AppendLine("| project | tests | clean | passed on retry | retries | failed | indeterminate |"); + builder.AppendLine("|---|--:|--:|--:|--:|--:|--:|"); + } + + builder.AppendLine( + $"| {entry.Project} ({entry.Framework}) | {entry.Tests} | {entry.CleanPasses} | " + + $"{mark(entry.PassedOnRetry)} | {mark(entry.RetriesPerformed)} | {mark(entry.Failed)} | " + + $"{mark(entry.Indeterminate)} |"); + + if (entry.AbortReason is not null) + { + builder.AppendLine(); + builder.AppendLine($"> **ABORTED** — {entry.AbortReason}"); + } + + if (entry.FlakyTests.Length > 0) + { + builder.AppendLine(); + builder.AppendLine("
Tests that only passed on a retry"); + builder.AppendLine(); + foreach (var test in entry.FlakyTests) builder.AppendLine($"- `{test}`"); + builder.AppendLine(); + builder.AppendLine("
"); + } + + builder.AppendLine(); + + File.AppendAllText(summaryFile, builder.ToString()); + } + catch (Exception e) + { + Log.Warning(e, "Could not append to $GITHUB_STEP_SUMMARY for {Project}", entry.Project); + } + + // Zero reads as zero; anything else is bolded, because the eye is meant to stop on it. + static string mark(int count) => count == 0 ? "0" : $"**{count}**"; + } + + /// + /// Emits the retry count as a GitHub annotation. Serilog's warnings are not annotations — the + /// annotations endpoint came back empty for the run that was burning 22 retries — so this has + /// to be the literal workflow command on stdout. + /// + static void annotate(LedgerEntry entry) + { + if (Environment.GetEnvironmentVariable("GITHUB_ACTIONS") != "true") return; + if (entry.RetriesPerformed == 0) return; + + var suspects = entry.FlakyTests.Length > 0 + ? $" First flaky test: {entry.FlakyTests[0]}." + : ""; + + // Workflow commands are newline-delimited, so the message has to be a single line. + Console.WriteLine( + $"::warning title={entry.Job}: {entry.RetriesPerformed} retries::" + + $"{entry.Project} ({entry.Framework}) spent {entry.RetriesPerformed} of its " + + $"{MaxRetriesPerRun}-retry budget; " + + $"{entry.PassedOnRetry} test(s) passed only on a retry.{suspects}"); + } + + static readonly JsonSerializerOptions LedgerJson = new() { WriteIndented = true }; + + /// + /// One supervised project run, as the roll-up job consumes it. Property names are the contract + /// with build/flakiness-report.sh — rename one and the jq there goes silently null, which is why + /// that script asserts on the fields it reads. + /// + class LedgerEntry + { + public string Job { get; init; } + public string Project { get; init; } + public string Framework { get; init; } + public int Tests { get; init; } + public int CleanPasses { get; init; } + public int PassedOnRetry { get; init; } + public int RetriesPerformed { get; init; } + public int Failed { get; init; } + public int Indeterminate { get; init; } + public int WorkerFaults { get; init; } + public string AbortReason { get; init; } + public string[] FlakyTests { get; init; } = []; + } +} diff --git a/build/SupervisedTests.cs b/build/SupervisedTests.cs index 598dc0290..1505a8252 100644 --- a/build/SupervisedTests.cs +++ b/build/SupervisedTests.cs @@ -43,6 +43,13 @@ partial class Build /// [Parameter] readonly bool DisableTestRetry; + /// + /// Retries a whole project run may spend before every remaining failure is reported as failed + /// WITHOUT being retried at all. Read the retry ledger (see RetryLedger.cs) against this number: + /// a run at the cap is not "N flaky tests", it is N flaky tests plus an unknown tail. + /// + const int MaxRetriesPerRun = 25; + /// /// The standing exclusion every CI target applies: tests tagged [Trait("Category", "Flaky")] /// do not run. Same semantics as the old vstest `Category!=Flaky` filter. @@ -139,7 +146,7 @@ bool runSupervised(string projectPath, string framework, Func TestFilter = shardFilter is null ? NotFlaky : t => NotFlaky(t) && shardFilter(t), RetryBudget = DisableTestRetry ? RetryBudget.None - : new RetryBudget { MaxAttemptsPerTest = 3, MaxRetriesPerRun = 25 }, + : new RetryBudget { MaxAttemptsPerTest = 3, MaxRetriesPerRun = MaxRetriesPerRun }, // The policy below only ever asks for fresh-process retries, so idle lanes are // released before they run: without this, workers+1 test hosts sit resident at once, // which OOM-killed 16GB GitHub runners twice — both times during a retry. @@ -151,7 +158,7 @@ bool runSupervised(string projectPath, string framework, Func var results = supervisor.Run().GetAwaiter().GetResult(); - return report(projectName, results, shardFilter is not null); + return report(projectName, framework, results, shardFilter is not null); } /// @@ -175,8 +182,10 @@ public Disposition Decide(AttemptContext attempt) } } - bool report(string projectName, SupervisorResults results, bool hadShardFilter) + bool report(string projectName, string framework, SupervisorResults results, bool hadShardFilter) { + recordLedger(projectName, framework, results); + if (results.AbortReason is not null) { Log.Error("=== {Project}: run ABORTED — {Reason} ===", projectName, results.AbortReason); diff --git a/build/flakiness-report.sh b/build/flakiness-report.sh new file mode 100755 index 000000000..aa973a55f --- /dev/null +++ b/build/flakiness-report.sh @@ -0,0 +1,208 @@ +#!/usr/bin/env bash +# +# The run-level half of the retry ledger (GH-3787). Each test job writes its own ledger JSON (see +# build/RetryLedger.cs) and uploads it; this aggregates all of them into one table on the run +# summary and — the part that actually matters — diffs the run against the last `main` run that +# published a ledger. +# +# The ASB story this exists for: 22 of 25 retries burned on four consecutive green main runs. The +# absolute 22 was not the signal. The step from 1 to 22 between two adjacent runs was, and there was +# nowhere that number had ever been written down to compare against. +# +# Informational by design: this script never fails the run. A retry count is something a human +# explains, not a gate — a suite legitimately sitting at 3 would otherwise be one bad day from a red +# main. +# +# Usage: flakiness-report.sh +# ledger-dir contains the downloaded per-job artifacts (searched recursively for *.json) +# output-dir receives aggregate.json, uploaded as this run's baseline for the next one +# +# Expects in the environment: GH_TOKEN, GITHUB_REPOSITORY, GITHUB_RUN_ID, GITHUB_STEP_SUMMARY. + +set -uo pipefail + +ledger_dir="${1:?usage: flakiness-report.sh }" +output_dir="${2:?usage: flakiness-report.sh }" + +repo="${GITHUB_REPOSITORY:-JasperFx/wolverine}" +summary="${GITHUB_STEP_SUMMARY:-/dev/stdout}" + +mkdir -p "${output_dir}" + +# ── This run ──────────────────────────────────────────────────────────────── + +# One object per project run. Several projects can report under one job (CIAWS, CIMQTT), so the job +# rows are a group-by rather than a rename. +ledger_files=$(find "${ledger_dir}" -name '*.json' -type f 2>/dev/null | sort) +if [ -n "${ledger_files}" ]; then + # Ledger file names are composed from job/project/framework — no spaces to quote around. + # shellcheck disable=SC2086 + jq -s '.' ${ledger_files} > "${output_dir}/entries.json" || echo '[]' > "${output_dir}/entries.json" +else + echo '[]' > "${output_dir}/entries.json" +fi + +# The field names here are the contract with LedgerEntry in build/RetryLedger.cs. Assert rather than +# let jq quietly resolve a renamed field to null and report a comforting zero. +if [ "$(jq 'length' "${output_dir}/entries.json")" != "0" ]; then + if [ "$(jq '[.[] | select(.Job == null or .RetriesPerformed == null)] | length' "${output_dir}/entries.json")" != "0" ]; then + echo "::error::Ledger entries are missing Job/RetriesPerformed — build/RetryLedger.cs and this script have drifted." + jq '.[0]' "${output_dir}/entries.json" + exit 0 + fi +fi + +jq '[group_by(.Job)[] | { + job: .[0].Job, + tests: (map(.Tests) | add), + retries: (map(.RetriesPerformed) | add), + passedOnRetry: (map(.PassedOnRetry) | add), + failed: (map(.Failed) | add), + indeterminate: (map(.Indeterminate) | add), + flakyTests: (map(.FlakyTests[]) | unique) + }] | sort_by(-.retries, .job)' \ + "${output_dir}/entries.json" > "${output_dir}/aggregate.json" + +total_retries=$(jq '[.[] | .retries] | add // 0' "${output_dir}/aggregate.json") +total_tests=$(jq '[.[] | .tests] | add // 0' "${output_dir}/aggregate.json") +reporting_jobs=$(jq 'length' "${output_dir}/aggregate.json") + +# ── The baseline ──────────────────────────────────────────────────────────── +# +# The newest completed main run that actually published an aggregate. Walking a few back rather than +# taking the immediately previous one: a cancelled or infrastructure-failed run publishes nothing, +# and "no baseline" is a worse answer than "a slightly older baseline". + +baseline_file="" +baseline_run="" + +# An explicit baseline, for exercising the diff path outside of CI. +if [ -n "${FLAKINESS_BASELINE_FILE:-}" ] && [ -f "${FLAKINESS_BASELINE_FILE}" ]; then + baseline_file="${FLAKINESS_BASELINE_FILE}" + baseline_run="local" +else + candidates=$(gh api "repos/${repo}/actions/workflows/tests.yml/runs?branch=main&status=completed&per_page=10" \ + --jq '.workflow_runs[].id' 2>/dev/null | grep -v "^${GITHUB_RUN_ID:-none}$" | head -n 6) + + for candidate in ${candidates}; do + if gh run download "${candidate}" --repo "${repo}" -n test-ledger-run -D "${output_dir}/baseline" >/dev/null 2>&1 \ + && [ -f "${output_dir}/baseline/aggregate.json" ]; then + baseline_file="${output_dir}/baseline/aggregate.json" + baseline_run="${candidate}" + break + fi + rm -rf "${output_dir}/baseline" + done +fi + +baseline_retries="" +if [ -n "${baseline_file}" ]; then + baseline_retries=$(jq '[.[] | .retries] | add // 0' "${baseline_file}") +fi + +# ── Jobs that reported nothing ────────────────────────────────────────────── +# +# A job killed by the 20-minute cap produces no ledger at all — Bobcat prints its summary only at the +# end, so a cap-killed job reports not even a partial count. That silence is itself a finding, and +# without this it would read as "no flakiness". + +# +# Jobs that legitimately produce nothing are listed here rather than reported every run: a section +# that cries wolf on every single run is how a signal channel gets ignored, which is the failure +# this whole report exists to undo. CIAotSmoke builds and RUNS two AOT smoke apps -- it invokes no +# test project at all, so it has no retry budget to spend. +NO_LEDGER_EXPECTED="CIAotSmoke" + +missing="" +# gh api prints the error BODY to stdout on a failed request, so the exit code has to gate this — +# otherwise a 404 lands in the report as the name of a job that "reported no ledger". +if gh api "repos/${repo}/actions/runs/${GITHUB_RUN_ID:-0}/jobs?per_page=100" --paginate \ + --jq '.jobs[] | select(.conclusion != "skipped" and .conclusion != null) | select(.name | startswith("CI")) | .name' \ + > "${output_dir}/jobs.txt" 2>/dev/null +then + missing=$(sort -u "${output_dir}/jobs.txt" | while read -r job; do + # [[ ]] rather than case: bash 3.2 (what macOS ships) mis-parses a case pattern's ")" as the + # end of the enclosing $( ) substitution. + if [[ " ${NO_LEDGER_EXPECTED} " == *" ${job} "* ]]; then continue; fi + if [ "$(jq --arg j "${job}" '[.[] | select(.job == $j)] | length' "${output_dir}/aggregate.json")" = "0" ]; then + echo "${job}" + fi + done) +fi + +# ── The report ────────────────────────────────────────────────────────────── + +delta_for() { + local current="$1" previous="$2" + if [ -z "${previous}" ]; then echo "—"; return; fi + local d=$((current - previous)) + if [ "${d}" -gt 0 ]; then echo "**+${d}**" + elif [ "${d}" -lt 0 ]; then echo "${d}" + else echo "·"; fi +} + +{ + echo "## Flakiness roll-up" + echo + + if [ -n "${baseline_retries}" ]; then + if [ "${baseline_run}" = "local" ]; then + described="a locally supplied baseline" + else + described="last \`main\` run [#${baseline_run}](https://github.com/${repo}/actions/runs/${baseline_run})" + fi + echo "**${total_retries} retries** across ${reporting_jobs} reporting job(s), ${total_tests} tests." + echo "Baseline — ${described}: **${baseline_retries}**, $(delta_for "${total_retries}" "${baseline_retries}")." + else + echo "**${total_retries} retries** across ${reporting_jobs} reporting job(s), ${total_tests} tests." + echo "No baseline found in the last few completed \`main\` runs — reporting absolute numbers only." + fi + echo + + echo "A retry means a test failed and then passed alone in a fresh process. Zero is the only number" + echo "that needs no explanation; a count that *moved* is the one worth chasing." + echo + + if [ -n "${missing}" ]; then + # `paste -sd', '` would cycle the two delimiters and yield "a,b c,d" -- one delimiter, then sed. + echo "> **Reported no ledger at all:** $(echo "${missing}" | paste -sd, - | sed 's/,/, /g')" + echo ">" + echo "> Bobcat prints its summary only at the end, so a job killed by the 20-minute cap reports" + echo "> nothing — not even a partial count. Treat this as unmeasured, not as clean." + echo + fi + + if [ "${total_retries}" = "0" ] && [ "$(jq '[.[] | select(.failed > 0 or .indeterminate > 0)] | length' "${output_dir}/aggregate.json")" = "0" ]; then + echo "No job spent a retry." + else + echo "| job | retries | baseline | Δ | passed on retry | failed | indeterminate |" + echo "|---|--:|--:|:--|--:|--:|--:|" + + jq -r '.[] | select(.retries > 0 or .failed > 0 or .indeterminate > 0) + | [.job, .retries, .passedOnRetry, .failed, .indeterminate] | @tsv' \ + "${output_dir}/aggregate.json" \ + | while IFS=$'\t' read -r job retries passed_on_retry failed indeterminate; do + was="" + if [ -n "${baseline_file}" ]; then + was=$(jq -r --arg j "${job}" '[.[] | select(.job == $j) | .retries] | first // ""' "${baseline_file}") + fi + echo "| ${job} | ${retries} | ${was:-—} | $(delta_for "${retries}" "${was}") | ${passed_on_retry} | ${failed} | ${indeterminate} |" + done + fi + echo + + if [ "${total_retries}" != "0" ]; then + echo "
Tests that only passed on a retry" + echo + jq -r '.[] | select(.retries > 0) | "- **\(.job)**", (.flakyTests[] | " - `\(.)`")' \ + "${output_dir}/aggregate.json" + echo + echo "
" + echo + fi +} >> "${summary}" + +# Also on stdout, so the roll-up is greppable from `gh run view --log` the way the per-job lines are. +echo "=== flakiness roll-up: ${total_retries} retries, baseline ${baseline_retries:-none} (run ${baseline_run:-none}) ===" + +exit 0