diff --git a/.github/workflows/notify-main-failure.yml b/.github/workflows/notify-main-failure.yml index 08467ae..9e58fed 100644 --- a/.github/workflows/notify-main-failure.yml +++ b/.github/workflows/notify-main-failure.yml @@ -96,6 +96,10 @@ on: description: "Post a 'recovered' message with no prior failure to recover from. Only the smoke-test dispatch sets this; a real pipeline leaves it off, or every green run reports a recovery." type: boolean default: false + repeat-alert-after-minutes: + description: "How long a still-failing pipeline stays quiet before it reports the failure again. Repeats are collapsed so a standing breakage does not page every run, but never indefinitely: a conclusion says that a run failed, not what failed, so a suppressed repeat can hide an outage that grew." + type: number + default: 60 runs-on: description: "Runner label for the notify job" type: string @@ -177,5 +181,6 @@ jobs: freeze-token: ${{ steps.freeze-token.outputs.token }} github-token: ${{ github.token }} force-post: ${{ inputs.force-post }} + repeat-alert-after-minutes: ${{ inputs.repeat-alert-after-minutes || 60 }} slack-channel-id: ${{ secrets.SLACK_ENG_CHANNEL_ID }} slack-bot-token: ${{ secrets.GH_ACTIONS_SLACK_BOT_TOKEN }} diff --git a/README.md b/README.md index 24479c6..00183e0 100644 --- a/README.md +++ b/README.md @@ -40,8 +40,21 @@ sends no failure alert. An endpoint that fails twice makes the run red and passe failure to `notify-main-failure.yml`, which posts to the engineering Slack channel. That message names each failing environment, route, and observed result. A `200` response without the configured marker is reported as either `status 200 missing SPA marker` or -`status 200 missing website marker`. The next successful run uses that reusable workflow's -existing recovery lookup, so routine green runs stay silent. +`status 200 missing website marker`. A redirect names its destination, as in +`production /cowork status 301 to /cowork/`, because the status alone says a route moved but not +where to, and the destination is usually the diagnosis. + +**One breakage pages once, then hourly.** A failing endpoint alerts on the run that breaks it, then +goes quiet, then repeats itself once an hour for as long as it lasts, because `notify-pipeline-status` +collapses a failure whose predecessor also failed. At this cadence the alternative is roughly 220 +messages a day for a single unfixed route, which is how a real page gets scrolled past. Routine green +runs stay silent through the same lookup. + +The hourly repeat is not a formality. A run's conclusion records **that** it failed, never **what** +failed, so two dead routes and a total console outage are both `failure`. Suppressing every repeat +would let the second grow behind an alert already sent for the first. The repeat bounds how long a +change in the failing set can go unmentioned; raise `repeat-alert-after-minutes` for a known noisy +breakage, but do not try to disable it. The reviewable source of truth is [`config/console-route-probe.json`](config/console-route-probe.json). The Console matrix crosses these environments: @@ -188,11 +201,36 @@ single job runs unless the workflow was cancelled and derives the outcome from `recovered` is not the same as green: the reusable looks up the previous conclusive run of the same workflow on the same branch and stays silent unless it -failed, so a routine green merge posts nothing. That lookup needs `actions: read` -on this job, because the default workflow token carries contents + packages read -only and a called workflow can never hold more than its caller grants. Without -it the lookup is refused and the job stays silent (it never fails the run), so a -missing recovery message is the symptom to look for. +failed, so a routine green merge posts nothing. + +**The same lookup collapses repeated failures.** A red run whose predecessor was +also red posts nothing, so a standing breakage pages once rather than on every +run. The two directions fail open in opposite ways on purpose: with no evidence, +an alert posts and a recovery does not, because an unreported failure costs more +than a duplicate one. + +**Collapsed is not muted.** A conclusion says that a run failed, not what failed, +so a suppressed repeat could hide an outage that grew behind an alert already +sent. A still-failing pipeline therefore reports itself again every +`repeat-alert-after-minutes` (default 60), measured from the oldest failure in +the current streak so the repeat lands once per window at any cadence. An +unreadable or missing streak clock posts rather than staying quiet, and setting +the interval to zero or a non-number falls back to the default instead of +muting the channel. + +That lookup needs `actions: read` on this job, because the default workflow token +carries contents + packages read only and a called workflow can never hold more +than its caller grants. Without it the lookup is refused and the job stays silent +(it never fails the run), so a missing recovery message is the symptom to look +for — and, since the deduplication reads the same evidence, a caller missing the +grant also re-pages every run of a standing failure. + +The lookup asks the per-workflow runs endpoint rather than paging the branch's +recent runs, so one frequent cron cannot crowd another workflow out of its own +history. It used to read fifty branch-wide runs and filter afterwards, which the +five-minute public web probe compressed to about four hours of coverage; any +workflow whose previous run was older than that found no evidence and silently +dropped its recovery message. ### Scoping staging alerts to the freeze window @@ -241,8 +279,8 @@ Requires two org secrets, reaching the workflow via `secrets: inherit`: must be a member of that channel. `workflow_dispatch` on the reusable itself is a smoke test: it posts a sample -message in either style, skipping the prior-run lookup so `recovered` always -posts. +message in either style, skipping the prior-run lookup so both `recovered` and a +repeated `failed` always post. ### The one failure it cannot see: a run that never started diff --git a/notify-pipeline-status/action.yml b/notify-pipeline-status/action.yml index bb123f8..41ec851 100644 --- a/notify-pipeline-status/action.yml +++ b/notify-pipeline-status/action.yml @@ -63,13 +63,17 @@ inputs: required: false default: "" github-token: - description: "Token for the prior-run lookup behind the recovery message. Needs actions:read." + description: "Token for the prior-run lookup that both suppresses a duplicate alert and licenses a recovery. Needs actions:read. Without it every run of a standing failure re-pages." required: false default: "" force-post: - description: "'true' to post a recovery with no prior failure to recover from. The smoke test, and nothing else: a release-train wrapper must leave this alone or every manual run reports a recovery that did not happen." + description: "'true' to post with no prior run to compare against, in either direction. The smoke test, and nothing else: a release-train wrapper must leave this alone or every manual run reports a recovery that did not happen." required: false default: "false" + repeat-alert-after-minutes: + description: "How long a still-failing pipeline stays quiet before it reports the failure again. Repeats are collapsed so a standing breakage does not page every run, but never indefinitely: a run's conclusion says that it failed, not what failed, so a suppressed repeat can hide an outage that grew. Raise it for a noisy known breakage; do not disable it." + required: false + default: "60" branch: description: "Branch to name in the message. Defaults to the running ref, which is wrong for a `workflow_run` caller, where GITHUB_REF is the default branch rather than the branch whose pipeline finished." required: false @@ -123,15 +127,23 @@ runs: python3 "${SHARED}/scripts/freeze_state.py" read \ --repo "${REPO}" --ruleset-name "${RULESET_NAME}" --on-error escalate - # For the recovery message, find out how the PREVIOUS conclusive run of this - # same workflow on this same branch ended. This step only gathers evidence; - # `notify_decision.py` below decides what it means. + # Find out how the PREVIOUS conclusive run of this same workflow on this same + # branch ended. This step only gathers evidence; `notify_decision.py` below + # decides what it means. + # + # BOTH directions need that evidence. A failure used to post unconditionally + # and skip this lookup, so a standing breakage re-paged on every run: + # ENG-2324's five-minute probe turned one unfixed production route into about + # 220 Slack messages a day. The conclusion that suppresses a duplicate alert + # is the same conclusion that licenses a recovery, so one lookup serves both + # and the two directions fail open opposite ways — no evidence pages, and no + # evidence withholds a recovery. # - # Skipped when nothing it could find would change the outcome: a failure posts - # regardless, `force-post` posts regardless, and a freeze-scoped caller outside - # the window posts nothing either way. `steps.freeze.outputs.frozen` is empty - # when the freeze step did not run, which is not 'false', so an unscoped caller - # still reaches this. + # Still skipped when nothing it could find would change the outcome: + # `force-post` posts regardless, and a freeze-scoped caller outside the window + # posts nothing either way. `steps.freeze.outputs.frozen` is empty when the + # freeze step did not run, which is not 'false', so an unscoped caller still + # reaches this. # # BRANCH is deliberately the running ref rather than `inputs.branch`. For a # `workflow_run` caller those differ: the run is attributed to the default @@ -139,7 +151,7 @@ runs: # branch whose pipeline finished. - name: Check how the previous run ended id: prev - if: inputs.status == 'recovered' && inputs.force-post != 'true' && steps.freeze.outputs.frozen != 'false' + if: inputs.force-post != 'true' && steps.freeze.outputs.frozen != 'false' shell: bash env: GH_TOKEN: ${{ inputs.github-token }} @@ -174,24 +186,69 @@ runs: WF_PATH="${WORKFLOW_REF%%@*}" export WF_PATH="${WF_PATH#"${REPO}/"}" - # Most recent CONCLUSIVE run on this branch, excluding the current one: - # cancelled and skipped runs are not evidence either way. - if ! PREV=$(gh api "repos/${REPO}/actions/runs?branch=${BRANCH}&status=completed&per_page=50" \ - --jq '[ .workflow_runs[] - | select(.path == env.WF_PATH or .name == env.WORKFLOW) - | select((.id|tostring) != env.RUN_ID) - | select(.conclusion == "success" or .conclusion == "failure" - or .conclusion == "timed_out" or .conclusion == "startup_failure") - ][0].conclusion // ""' 2>&1); then + # Ask for THIS workflow's history rather than the branch's most recent + # fifty runs. A frequent cron on the same branch crowds every other + # workflow out of a branch-wide page: at ENG-2324's five-minute cadence + # fifty slots span about four hours, so an hourly workflow found no + # evidence of itself and silently dropped its recovery message. The + # per-workflow endpoint takes the file name and cannot be crowded out. + # + # A caller whose `workflow_ref` points outside this repo has no such + # endpoint here, so that case keeps the branch scan and its name filter. + ENDPOINT="repos/${REPO}/actions/runs?branch=${BRANCH}&status=completed&per_page=50" + CALLER='select(.path == env.WF_PATH or .name == env.WORKFLOW)' + case "$WF_PATH" in + .github/workflows/*) + ENDPOINT="repos/${REPO}/actions/workflows/${WF_PATH##*/}/runs?branch=${BRANCH}&status=completed&per_page=10" + CALLER='.' + ;; + esac + + # Most recent CONCLUSIVE run of this workflow on this branch, excluding + # the current one: cancelled and skipped runs are not evidence either way. + # + # Also measure the CURRENT FAILURE STREAK and when it started, which is + # what lets a repeated failure be quiet without being silent. The streak + # is the leading run of failures in this history; its oldest member dates + # the breakage. A page that truncates the streak understates its age, + # which makes the reminder fire sooner rather than later. + read -r -d '' RUNS_JQ <<'JQ' || true + [ .workflow_runs[] + | CALLER_FILTER + | select((.id|tostring) != env.RUN_ID) + | select(.conclusion == "success" or .conclusion == "failure" + or .conclusion == "timed_out" or .conclusion == "startup_failure") + ] + | map({conclusion, created_at}) + | (map(.conclusion == "failure" or .conclusion == "timed_out" + or .conclusion == "startup_failure") | index(false)) as $break + | (if $break == null then length else $break end) as $streak + | [ (.[0].conclusion // ""), + (.[0].created_at // ""), + ($streak | tostring), + (if $streak > 0 then .[$streak - 1].created_at else "" end) + ] + | @tsv + JQ + RUNS_JQ="${RUNS_JQ//CALLER_FILTER/${CALLER}}" + + if ! ROW=$(gh api "$ENDPOINT" --jq "$RUNS_JQ" 2>&1); then # Almost always a missing `actions: read` grant on the caller job. Report # no evidence rather than failing: an unreadable history has to read as # "not a recovery", because a notify step must never redden a green run. - echo "Could not read run history, so there is no evidence either way: ${PREV}" + # It also has to read as "not a duplicate", so the alert still pages. + echo "Could not read run history, so there is no evidence either way: ${ROW}" exit 0 fi - echo "prev_conclusion=${PREV}" >> "$GITHUB_OUTPUT" + IFS=$'\t' read -r PREV PREV_STARTED STREAK STREAK_STARTED <<<"${ROW}" + { + echo "prev_conclusion=${PREV}" + echo "prev_started_at=${PREV_STARTED}" + echo "streak_started_at=${STREAK_STARTED}" + } >> "$GITHUB_OUTPUT" echo "Previous conclusive run on ${BRANCH} concluded '${PREV:-none}'." + echo "Consecutive failures before this run: ${STREAK:-0}, oldest at ${STREAK_STARTED:-n/a}." # One decision, one place, with tests. See scripts/notify_decision.py for the # three outcomes and why `force-post` is an input rather than an event check. @@ -205,9 +262,15 @@ runs: FROZEN: ${{ steps.freeze.outputs.frozen }} FORCE_POST: ${{ inputs.force-post }} PREV_CONCLUSION: ${{ steps.prev.outputs.prev_conclusion }} + PREV_STARTED_AT: ${{ steps.prev.outputs.prev_started_at }} + STREAK_STARTED_AT: ${{ steps.prev.outputs.streak_started_at }} + REPEAT_AFTER_MINUTES: ${{ inputs.repeat-alert-after-minutes }} run: | set -euo pipefail python3 "${SHARED}/scripts/notify_decision.py" \ + --streak-started-at "${STREAK_STARTED_AT}" \ + --prev-started-at "${PREV_STARTED_AT}" \ + --repeat-alert-after-minutes "${REPEAT_AFTER_MINUTES}" \ --status "${STATUS}" \ --freeze-scoped "${FREEZE_SCOPED}" \ --frozen "${FROZEN}" \ diff --git a/scripts/notify_decision.py b/scripts/notify_decision.py index 55619ab..c09dd8b 100644 --- a/scripts/notify_decision.py +++ b/scripts/notify_decision.py @@ -24,20 +24,37 @@ half of a story the channel was never told is worse than posting neither. ``alert`` - A failure. Always posts, because the freeze veto above is the only thing that - may suppress one. + A failure. It posts when the breakage is new, and again once per + ``--repeat-alert-after-minutes`` for as long as it lasts. The freeze veto + above is the only thing that suppresses one outright. + + Repeats are collapsed because a standing breakage that re-pages on every run + is how a real alert gets missed: ENG-2324's public web probe runs every five + minutes, so one unfixed route was worth about 220 Slack messages a day. + + They are collapsed but never silenced, because the run's conclusion says only + THAT it failed, not WHAT failed. Two endpoints down and twenty-one endpoints + down are both ``failure``, so suppressing every repeat would let an outage + grow behind an alert that had already been sent. The reminder bounds how long + a change in the failure can go unmentioned, and it is why this is a digest + rather than a mute. ``recovered`` A success whose predecessor failed. Posts only on that evidence, or when ``--force-post`` says this is the smoke test. A green run after a green run posts nothing, which is what keeps the channel worth reading. +Both directions therefore turn on the same evidence, and they fail open in +opposite directions on purpose. No evidence posts an alert and withholds a +recovery, because an unreported failure is the expensive mistake and a duplicate +alert is the cheap one. + ``--prev-conclusion`` is the conclusion of the previous conclusive run, or of the previous attempt of this run. Empty means "no evidence": either the lookup was never made because nothing was going to post anyway, or it was refused. Refused -is the common one — the recovery lookup needs ``actions: read`` on the calling -job — and it has to read as "not a recovery" rather than as an error, because a -notify step must never turn a green pipeline red. +is the common one — the lookup needs ``actions: read`` on the calling job — and +it has to read as "not a recovery" rather than as an error, because a notify step +must never turn a green pipeline red. """ from __future__ import annotations @@ -45,11 +62,15 @@ import argparse import os import sys +from datetime import datetime, timezone # Conclusions a `success` can be a recovery FROM. `cancelled` and `skipped` are # not evidence that anything was broken, so recovering from them is not news. FAILED_CONCLUSIONS = frozenset({"failure", "timed_out", "startup_failure"}) +# How long a repeated failure may stay quiet before it says so again. +DEFAULT_REPEAT_ALERT_AFTER_MINUTES = 60 + STYLES: dict[str, dict[str, str]] = { "silenced": {"color": "", "icon": "", "verb": "", "prefix": ""}, "recovered": {"color": "#00C851", "icon": ":white_check_mark:", "verb": "recovered", "prefix": "Recovered"}, @@ -57,6 +78,61 @@ } +def _parse_minutes(value: str) -> float: + """The reminder interval, falling back rather than rejecting the argument.""" + + try: + minutes = float(value) + except (TypeError, ValueError): + return DEFAULT_REPEAT_ALERT_AFTER_MINUTES + return minutes if minutes > 0 else DEFAULT_REPEAT_ALERT_AFTER_MINUTES + + +def _parse_time(value: str) -> datetime | None: + """A GitHub timestamp, or None when there is nothing usable to read.""" + + if not value: + return None + try: + parsed = datetime.fromisoformat(value.replace("Z", "+00:00")) + except ValueError: + return None + return parsed if parsed.tzinfo else parsed.replace(tzinfo=timezone.utc) + + +def repeat_alert_is_due( + *, + streak_started_at: str, + prev_started_at: str, + now: str, + repeat_after_minutes: float, +) -> bool: + """Whether a still-failing pipeline has crossed into a new reminder window. + + Windows are counted from the oldest failure in the streak rather than from + the last message, because nothing records when a message was sent. Both this + run and its predecessor are placed in a window and a reminder is due when + they land in different ones, which posts exactly once per window at any + cadence. + + Anything unreadable returns True. A reminder that fires early costs one + message; one that never fires hides a growing outage. + """ + + started = _parse_time(streak_started_at) + previous = _parse_time(prev_started_at) + current = _parse_time(now) + if started is None or previous is None or current is None: + return True + if repeat_after_minutes <= 0: + return True + + window = repeat_after_minutes * 60 + elapsed_now = (current - started).total_seconds() + elapsed_prev = (previous - started).total_seconds() + return int(elapsed_now // window) != int(elapsed_prev // window) + + def decide( *, status: str, @@ -64,6 +140,10 @@ def decide( frozen: str, force_post: str, prev_conclusion: str, + streak_started_at: str = "", + prev_started_at: str = "", + now: str = "", + repeat_after_minutes: float = DEFAULT_REPEAT_ALERT_AFTER_MINUTES, ) -> dict[str, str]: """The full decision, as the flat strings the Slack payload interpolates. @@ -80,7 +160,20 @@ def decide( level = "recovered" post = force_post == "true" or prev_conclusion in FAILED_CONCLUSIONS else: - level, post = "alert", True + level = "alert" + # Only evidence of an already-failing predecessor collapses an alert, and + # only until the next reminder is due. An empty conclusion is absence of + # evidence, so it still pages. + post = ( + force_post == "true" + or prev_conclusion not in FAILED_CONCLUSIONS + or repeat_alert_is_due( + streak_started_at=streak_started_at, + prev_started_at=prev_started_at, + now=now, + repeat_after_minutes=repeat_after_minutes, + ) + ) return {"post": "true" if post else "false", "level": level, **STYLES[level]} @@ -90,7 +183,12 @@ def why(decision: dict[str, str], *, status: str, force_post: str, prev_conclusi if decision["level"] == "silenced": return "Freeze-scoped and the window is closed, so nothing posts in either direction." if decision["level"] == "alert": - return "Posting a failure." + if decision["post"] == "true": + return "Posting a failure." + return ( + f"Previous run also concluded '{prev_conclusion}', so this breakage has already " + "been reported. Staying quiet until it recovers or the next reminder is due." + ) if force_post == "true": return "Posting a recovery unconditionally (--force-post: this is the smoke test)." if decision["post"] == "true": @@ -121,9 +219,36 @@ def main(argv: list[str] | None = None) -> int: parser.add_argument( "--force-post", default="false", - help="post a recovery without evidence; set only by the notify workflow's own smoke-test dispatch", + help="post without evidence in either direction; set only by the notify workflow's own smoke-test dispatch", + ) + parser.add_argument( + "--prev-conclusion", + default="", + help="empty means no evidence either way, which posts an alert and withholds a recovery", + ) + parser.add_argument( + "--streak-started-at", + default="", + help="when the current run of consecutive failures began; empty means the reminder is due", + ) + parser.add_argument( + "--prev-started-at", + default="", + help="when the previous conclusive run began; empty means the reminder is due", + ) + parser.add_argument( + "--now", + default="", + help="override the current time, for tests", + ) + # Deliberately a string, parsed leniently below. A composite action's input is + # "" when the caller does not set it, and a notify step must never fail the + # run it is reporting on — least of all by rejecting its own argument. + parser.add_argument( + "--repeat-alert-after-minutes", + default="", + help="how long a still-failing pipeline stays quiet before it says so again", ) - parser.add_argument("--prev-conclusion", default="", help="empty means no evidence either way") args = parser.parse_args(argv) decision = decide( @@ -132,6 +257,10 @@ def main(argv: list[str] | None = None) -> int: frozen=args.frozen, force_post=args.force_post, prev_conclusion=args.prev_conclusion, + streak_started_at=args.streak_started_at, + prev_started_at=args.prev_started_at, + now=args.now or datetime.now(timezone.utc).isoformat(), + repeat_after_minutes=_parse_minutes(args.repeat_alert_after_minutes), ) emit(decision) print(why(decision, status=args.status, force_post=args.force_post, prev_conclusion=args.prev_conclusion)) diff --git a/scripts/probe_console_routes.py b/scripts/probe_console_routes.py index e115fab..23d4fe7 100644 --- a/scripts/probe_console_routes.py +++ b/scripts/probe_console_routes.py @@ -28,6 +28,7 @@ DEFAULT_ALERT_LABEL = "public web probe" MAX_BODY_BYTES = 64 * 1024 MAX_NETWORK_ERROR_CHARS = 64 +MAX_REDIRECT_TARGET_CHARS = 64 MAX_ALERT_LABEL_CHARS = 2_000 @@ -89,6 +90,11 @@ class FetchResult: status: int | None body: str = "" error: str | None = None + # Where a redirect points. A bare "status 301" tells the on-call that a route + # moved but not where to, and the destination is usually the whole diagnosis: + # production /cowork reported 301 for a week while the answer, that it lands + # on /cowork/ and 403s there, was only ever visible by hand. + location: str | None = None @dataclass(frozen=True) @@ -258,9 +264,12 @@ def fetch_endpoint(endpoint: Endpoint, timeout_seconds: float) -> FetchResult: body=_decode_body(response.read(MAX_BODY_BYTES)), ) except urllib.error.HTTPError as error: + # NoRedirectHandler declines every 3xx, which urllib then raises here, so + # this is the branch that sees a redirect's Location. return FetchResult( status=int(error.code), body=_decode_body(error.read(MAX_BODY_BYTES)), + location=error.headers.get("Location"), ) except (urllib.error.URLError, TimeoutError, OSError) as error: return FetchResult(status=None, error=_compact(str(error))) @@ -282,6 +291,9 @@ def evaluate(endpoint: Endpoint, result: FetchResult) -> Failure | None: ) if result.status != 200: status = "unknown" if result.status is None else str(result.status) + if result.location: + target = _compact(result.location, limit=MAX_REDIRECT_TARGET_CHARS) + return Failure(endpoint, f"status {status} to {target}") return Failure(endpoint, f"status {status}") if endpoint.body_marker not in result.body: return Failure(endpoint, f"status 200 missing {endpoint.marker_label} marker") @@ -368,16 +380,27 @@ def format_alert_label(failures: Sequence[Failure]) -> str: for failure in failures ) compact_label = label_prefix + compact_summaries - if len(compact_label) > MAX_ALERT_LABEL_CHARS: - raise ValueError("failure identities exceed the alert-label size limit") - return compact_label + if len(compact_label) <= MAX_ALERT_LABEL_CHARS: + return compact_label + + # Last resort, reached only if the endpoint list outgrows the label. Report + # the count and leave the identities to the run log. Raising here instead + # would crash the one step whose job is to say that something is down, and it + # would do so precisely when the outage is at its widest. + return _compact( + f"{label_prefix}{len(failures)} endpoints failed, see the run log", + limit=MAX_ALERT_LABEL_CHARS, + ) def _compact_alert_reason(reason: str) -> str: + """The endpoint's result category, minus the detail that varies in length.""" + network_prefix = "network error" if reason.startswith(f"{network_prefix}: "): return network_prefix - return reason + status, redirected, _ = reason.partition(" to ") + return status if redirected else reason def write_github_output(path: str | None, *, alert_label: str) -> None: diff --git a/tests/test_notify_decision.py b/tests/test_notify_decision.py index e58f72c..f9785b1 100644 --- a/tests/test_notify_decision.py +++ b/tests/test_notify_decision.py @@ -12,8 +12,8 @@ - staging outside the freeze window is silent in BOTH directions - a green run whose predecessor was also green posts nothing -- a failure always posts, and the freeze veto is the only thing that may stop it -- an unreadable run history reads as "not a recovery", never as an error +- a red run whose predecessor was also red posts nothing +- an unreadable run history posts an alert and withholds a recovery, never errors """ import importlib.util @@ -28,7 +28,13 @@ def decide(**kwargs): - """`decide` with the defaults a caller that passes nothing would get.""" + """`decide` with the defaults a caller that passes nothing would get. + + The streak clock defaults to the middle of a reminder window: a failing + streak that began at 12:00, a previous run at 12:30 and now 12:40, all inside + the first 60-minute window. Deduplication tests therefore read as + deduplication, and a test that cares about the reminder sets its own clock. + """ return notify.decide( **{ "status": "failed", @@ -36,6 +42,9 @@ def decide(**kwargs): "frozen": "", "force_post": "false", "prev_conclusion": "", + "streak_started_at": "2026-09-04T12:00:00Z", + "prev_started_at": "2026-09-04T12:30:00Z", + "now": "2026-09-04T12:40:00Z", **kwargs, } ) @@ -85,16 +94,134 @@ def test_an_unreadable_history_is_not_a_recovery_and_not_an_error(self): assert decide(status="recovered", prev_conclusion="")["post"] == "false" -class TestFailuresAlwaysPost: - def test_a_failure_posts_with_no_history_lookup_at_all(self): - assert decide(status="failed")["post"] == "true" +class TestTheFirstFailurePosts: + def test_a_failure_after_a_green_run_posts(self): + assert decide(status="failed", prev_conclusion="success")["post"] == "true" def test_a_failure_posts_while_the_freeze_window_is_open(self): assert decide(status="failed", freeze_scoped="true", frozen="true")["post"] == "true" - def test_the_freeze_veto_is_the_only_thing_that_silences_a_failure(self): + def test_the_freeze_veto_silences_a_failure(self): assert decide(status="failed", freeze_scoped="true", frozen="false")["post"] == "false" + @pytest.mark.parametrize("conclusion", ["success", "cancelled", "skipped"]) + def test_anything_that_is_not_a_prior_failure_lets_the_alert_through(self, conclusion): + """`cancelled` and `skipped` are not evidence the channel was already told, + for the same reason they are not evidence anything was broken.""" + assert decide(status="failed", prev_conclusion=conclusion)["post"] == "true" + + +class TestRepeatFailuresStayQuiet: + """The ENG-2324 regression: one standing breakage paged every five minutes. + + The public web probe runs on a `*/5` cron. Production `/cowork` and `/assets/` + had been returning 301 and 403 since before the probe existed, so every run + re-reported the same two routes: about 220 Slack messages a day into the + channel that also carries the paging Cloudflare checks. Nothing suppressed a + failure except the freeze veto, and a cron probe is never freeze-scoped. + """ + + @pytest.mark.parametrize("conclusion", ["failure", "timed_out", "startup_failure"]) + def test_a_failure_whose_predecessor_also_failed_posts_nothing(self, conclusion): + assert decide(status="failed", prev_conclusion=conclusion)["post"] == "false" + + def test_the_suppressed_alert_still_reads_as_an_alert(self): + """Only `post` changes. A deduped failure is not a recovery and not a + silenced freeze, and the log line has to be able to say which it was.""" + assert decide(status="failed", prev_conclusion="failure")["level"] == "alert" + + def test_no_evidence_still_pages(self): + """Absence of evidence is not evidence the channel was already told. The + lookup needs `actions: read`, and a caller that forgot the grant must + still get its first alert rather than silence.""" + assert decide(status="failed", prev_conclusion="")["post"] == "true" + + def test_the_smoke_test_overrides_the_dedupe(self): + assert decide(status="failed", force_post="true", prev_conclusion="failure")["post"] == "true" + + def test_the_log_line_says_why_it_stayed_quiet(self): + d = decide(status="failed", prev_conclusion="failure") + reason = notify.why(d, status="failed", force_post="false", prev_conclusion="failure") + assert "already been reported" in reason + + def test_a_repeat_still_reports_itself_once_the_reminder_is_due(self): + """The reason this is a digest and not a mute. + + A conclusion says THAT a run failed, never WHAT failed. Two endpoints + down and twenty-one endpoints down are both `failure`, so suppressing + every repeat would let an outage grow behind an alert already sent. The + reminder bounds how long that can go unmentioned. + """ + quiet = decide( + status="failed", + prev_conclusion="failure", + streak_started_at="2026-09-04T12:00:00Z", + prev_started_at="2026-09-04T12:40:00Z", + now="2026-09-04T12:50:00Z", + repeat_after_minutes=60, + ) + due = decide( + status="failed", + prev_conclusion="failure", + streak_started_at="2026-09-04T12:00:00Z", + prev_started_at="2026-09-04T12:55:00Z", + now="2026-09-04T13:05:00Z", + repeat_after_minutes=60, + ) + assert (quiet["post"], due["post"]) == ("false", "true") + + def test_the_reminder_fires_once_per_window_not_every_run_after_it(self): + """A five-minute cron crossing the hour must not start paging again.""" + assert decide( + status="failed", + prev_conclusion="failure", + streak_started_at="2026-09-04T12:00:00Z", + prev_started_at="2026-09-04T13:05:00Z", + now="2026-09-04T13:10:00Z", + repeat_after_minutes=60, + )["post"] == "false" + + @pytest.mark.parametrize( + "streak_started_at,prev_started_at", + [("", "2026-09-04T12:40:00Z"), ("2026-09-04T12:00:00Z", ""), ("nonsense", "nonsense")], + ) + def test_unreadable_streak_timestamps_page_rather_than_stay_quiet( + self, streak_started_at, prev_started_at + ): + """A reminder that fires early costs one message. One that never fires + hides a growing outage.""" + assert decide( + status="failed", + prev_conclusion="failure", + streak_started_at=streak_started_at, + prev_started_at=prev_started_at, + now="2026-09-04T12:50:00Z", + )["post"] == "true" + + def test_a_nonpositive_interval_cannot_be_used_to_mute_the_channel(self): + """`repeat-alert-after-minutes: 0` must not mean 'never remind'.""" + assert decide( + status="failed", + prev_conclusion="failure", + streak_started_at="2026-09-04T12:00:00Z", + prev_started_at="2026-09-04T12:40:00Z", + now="2026-09-04T12:50:00Z", + repeat_after_minutes=0, + )["post"] == "true" + + def test_a_standing_breakage_pages_once_then_recovers_once(self): + """The whole point, as the sequence the channel actually sees: one red on + the run that breaks, silence while it stays broken, one green when it is + fixed. Three messages for a three-day outage, not eight hundred.""" + posts = [ + decide(status="failed", prev_conclusion="success")["post"], + decide(status="failed", prev_conclusion="failure")["post"], + decide(status="failed", prev_conclusion="failure")["post"], + decide(status="recovered", prev_conclusion="failure")["post"], + decide(status="recovered", prev_conclusion="success")["post"], + ] + assert posts == ["true", "false", "false", "true", "false"] + class TestFreezeScoping: def test_silent_in_both_directions_while_thawed(self): diff --git a/tests/test_notify_pipeline_status.py b/tests/test_notify_pipeline_status.py new file mode 100644 index 0000000..9ee18f3 --- /dev/null +++ b/tests/test_notify_pipeline_status.py @@ -0,0 +1,125 @@ +"""Contract tests for `notify-pipeline-status/action.yml`. + +`scripts/notify_decision.py` decides whether an alert posts, and +`tests/test_notify_decision.py` pins that decision. This file pins the wiring +that feeds it, because the decision is only as good as the evidence it is handed +and two ENG-2324 defects lived entirely in the wiring: + +- the prior-run lookup was gated on `inputs.status == 'recovered'`, so a failure + never had a predecessor to be compared against and the dedupe below it could + never fire +- the lookup read the branch's most recent fifty runs and then filtered by + workflow, so a frequent cron on the same branch crowded every other workflow + out of its own history and their recovery messages were silently dropped + +Neither is reachable from Python, so they are asserted against the YAML. +""" + +import yaml +from pathlib import Path + +ACTION_PATH = Path(__file__).resolve().parents[1] / "notify-pipeline-status" / "action.yml" +ACTION = yaml.safe_load(ACTION_PATH.read_text(encoding="utf-8")) +STEPS = ACTION["runs"]["steps"] + + +def step(step_id: str) -> dict: + matches = [candidate for candidate in STEPS if candidate.get("id") == step_id] + assert len(matches) == 1, f"expected exactly one step with id '{step_id}'" + return matches[0] + + +class TestThePriorRunLookupRunsForBothDirections: + """A failure needs a predecessor too, or the dedupe cannot fire.""" + + def test_the_lookup_is_not_gated_on_the_recovered_status(self): + assert "inputs.status" not in step("prev")["if"] + + def test_the_smoke_test_still_skips_the_lookup(self): + """`force-post` posts without evidence in either direction, so reading the + history would only cost an API call.""" + assert "inputs.force-post != 'true'" in step("prev")["if"] + + def test_a_thawed_freeze_scoped_caller_still_skips_the_lookup(self): + assert "steps.freeze.outputs.frozen != 'false'" in step("prev")["if"] + + def test_the_lookup_result_reaches_the_decision(self): + decide = step("msg") + assert decide["env"]["PREV_CONCLUSION"] == "${{ steps.prev.outputs.prev_conclusion }}" + assert "--prev-conclusion" in decide["run"] + + +class TestTheRepeatReminderIsWiredEndToEnd: + """Collapsing repeats is only safe because the reminder bounds the silence. + + A conclusion says THAT a run failed, not WHAT failed, so a suppressed repeat + can hide an outage that grew behind an alert already sent. If any link in + this chain breaks, deduplication silently becomes a mute. + """ + + def test_the_streak_clock_is_measured(self): + run = step("prev")["run"] + assert "streak_started_at=" in run + assert "prev_started_at=" in run + + def test_the_streak_clock_reaches_the_decision(self): + decide = step("msg") + assert decide["env"]["STREAK_STARTED_AT"] == "${{ steps.prev.outputs.streak_started_at }}" + assert decide["env"]["PREV_STARTED_AT"] == "${{ steps.prev.outputs.prev_started_at }}" + assert "--streak-started-at" in decide["run"] + assert "--prev-started-at" in decide["run"] + + def test_the_interval_is_an_input_with_a_bounded_default(self): + interval = ACTION["inputs"]["repeat-alert-after-minutes"] + assert float(interval["default"]) > 0 + assert "--repeat-alert-after-minutes" in step("msg")["run"] + + def test_the_streak_counts_only_leading_failures(self): + """A success in the history ends the streak, which is what dates the + breakage to when it actually started rather than to the oldest run.""" + run = step("prev")["run"] + assert "index(false)" in run + + +class TestTheLookupAsksForOneWorkflowsOwnHistory: + """The branch-wide page is what a five-minute cron crowds out.""" + + def test_it_calls_the_per_workflow_runs_endpoint(self): + assert "actions/workflows/${WF_PATH##*/}/runs" in step("prev")["run"] + + def test_the_per_workflow_call_is_scoped_to_the_branch_and_conclusive_runs(self): + run = step("prev")["run"] + assert "branch=${BRANCH}&status=completed" in run + + def test_a_caller_outside_this_repo_keeps_the_branch_scan(self): + """`workflow_ref` can name another repo's workflow, which has no endpoint + here. That case still has to resolve to something rather than crash.""" + run = step("prev")["run"] + assert "repos/${REPO}/actions/runs?branch=" in run + assert "select(.path == env.WF_PATH or .name == env.WORKFLOW)" in run + + def test_the_current_run_is_still_excluded(self): + assert "select((.id|tostring) != env.RUN_ID)" in step("prev")["run"] + + def test_cancelled_and_skipped_runs_are_still_not_evidence(self): + run = step("prev")["run"] + assert '.conclusion == "success"' in run + assert '.conclusion == "cancelled"' not in run + assert '.conclusion == "skipped"' not in run + + def test_an_unreadable_history_degrades_instead_of_failing_the_job(self): + """A notify step must never turn a green pipeline red, so a refused lookup + reports no evidence and exits 0.""" + run = step("prev")["run"] + assert "no evidence either way" in run + assert "exit 0" in run + + def test_a_rerun_still_checks_the_previous_attempt_first(self): + """Attempts share a run id, so the failing attempt is the very run the + history lookup excludes as 'the current one'.""" + assert "attempts/${PREV_ATTEMPT}" in step("prev")["run"] + + +class TestTheCallerGrantsTheLookupItsPermission: + def test_the_action_documents_the_actions_read_requirement(self): + assert "actions: read" in ACTION_PATH.read_text(encoding="utf-8") diff --git a/tests/test_probe_console_routes.py b/tests/test_probe_console_routes.py index 2d7b6cf..51826d3 100644 --- a/tests/test_probe_console_routes.py +++ b/tests/test_probe_console_routes.py @@ -171,6 +171,30 @@ def test_301_fails_instead_of_counting_as_the_destination(self): failure = probe.evaluate(endpoint(), response(301, "Moved")) assert failure.summary == "staging /home status 301" + def test_a_redirect_names_where_it_went(self): + """The ENG-2324 diagnosis was in the destination, not the status. + + Production `/cowork` paged as a bare "status 301" for every run. The fact + that it lands on `/cowork/` and 403s there, which is what identifies the + shadowed-docroot bug, was only ever visible by hand. + """ + failure = probe.evaluate( + endpoint("/cowork"), + probe.FetchResult(status=301, body="Moved", location="/cowork/"), + ) + assert failure.summary == "staging /cowork status 301 to /cowork/" + + def test_a_redirect_destination_cannot_blow_the_label_budget(self): + """The origin controls this header, so its length cannot be trusted.""" + failure = probe.evaluate( + endpoint(), + probe.FetchResult(status=302, location="/" + "x" * 500), + ) + assert len(failure.reason) <= len("status 302 to ") + probe.MAX_REDIRECT_TARGET_CHARS + + def test_a_non_redirect_failure_gains_no_destination_clause(self): + assert probe.evaluate(endpoint(), response(403, "Forbidden")).reason == "status 403" + def test_200_nginx_page_fails_without_the_spa_marker(self): failure = probe.evaluate(endpoint(), response(200, NGINX_PAGE)) assert failure.summary == "staging /home status 200 missing SPA marker" @@ -210,6 +234,35 @@ def open(self, request, timeout): result = probe.fetch_endpoint(endpoint(), 4) assert (result.status, result.body) == (301, "Moved") + def test_fetch_captures_the_redirect_destination(self, monkeypatch): + class RedirectingOpener: + def open(self, request, timeout): + raise HTTPError( + request.full_url, + 301, + "Moved", + {"Location": "/cowork/"}, + BytesIO(b"Moved"), + ) + + monkeypatch.setattr( + probe.urllib.request, "build_opener", lambda *handlers: RedirectingOpener() + ) + assert probe.fetch_endpoint(endpoint("/cowork"), 4).location == "/cowork/" + + def test_an_error_response_without_a_location_header_reports_none(self, monkeypatch): + """A 403 carries no Location, and reading one must not raise.""" + + class ForbiddenOpener: + def open(self, request, timeout): + raise HTTPError(request.full_url, 403, "Forbidden", {}, BytesIO(b"nginx")) + + monkeypatch.setattr( + probe.urllib.request, "build_opener", lambda *handlers: ForbiddenOpener() + ) + result = probe.fetch_endpoint(endpoint("/assets/"), 4) + assert (result.status, result.location) == (403, None) + class TestRetryDebounce: def test_a_clean_first_attempt_does_not_sleep_or_retry(self): @@ -399,6 +452,60 @@ def test_output_is_one_json_safe_line_for_the_slack_payload(self, tmp_path): ) +class TestTheAlertLabelSurvivesEveryOutageShape: + """The label is the outage report, so it may never be the thing that breaks. + + `format_alert_label` used to raise once failure identities outgrew the cap, + and `main` did not catch it. That turned the widest possible outage into a + crash in the step whose only job is to say something is down. + """ + + def test_a_full_redirect_outage_keeps_every_endpoint_and_drops_the_targets(self): + failures = tuple( + probe.evaluate(target, probe.FetchResult(status=301, location="/" + "x" * 300)) + for target in probe.load_config().endpoints + ) + label = probe.format_alert_label(failures) + + assert len(label) <= probe.MAX_ALERT_LABEL_CHARS + assert label.count("status 301") == EXPECTED_ENDPOINT_COUNT + assert "xxx" not in label + for failure in failures: + identity = f"{failure.endpoint.environment} {failure.endpoint.route} status 301" + assert identity in label + + def test_identities_too_large_to_fit_degrade_to_a_count(self): + oversized = probe.Endpoint( + "e" * 200, + "https://oversized.example", + "/" + "r" * 200, + CONSOLE_MARKER, + "SPA", + ) + failures = tuple(probe.Failure(oversized, "status 503") for _ in range(50)) + + label = probe.format_alert_label(failures) + + assert len(label) <= probe.MAX_ALERT_LABEL_CHARS + assert "50 endpoints failed" in label + + def test_the_degraded_label_still_fits_the_step_output(self, tmp_path): + """Whatever the label degrades to still has to survive `write_github_output`, + which is what the notifier reads.""" + oversized = probe.Endpoint( + "e" * 200, "https://oversized.example", "/" + "r" * 200, CONSOLE_MARKER, "SPA" + ) + label = probe.format_alert_label( + tuple(probe.Failure(oversized, "status 503") for _ in range(50)) + ) + output = tmp_path / "github-output" + probe.write_github_output(str(output), alert_label=label) + + written = output.read_text(encoding="utf-8") + assert written == f"alert_label={label}\n" + assert written.count("\n") == 1 + + class TestConfigurationAndDocumentation: def test_config_is_the_exact_console_matrix_plus_standalone_roots(self): config = probe.load_config()