From ba113f84b20cefde378b5e8b2d4c4f9fa8d30c79 Mon Sep 17 00:00:00 2001 From: Umang Date: Thu, 30 Jul 2026 21:48:42 -0500 Subject: [PATCH] =?UTF-8?q?PR=2011=20=E2=80=94=20Advanced=20failure=20and?= =?UTF-8?q?=20concurrency=20validation?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds the validation tier IMPLEMENTATION_PLAN.md §13 assigns to PR 11. No product behavior changes; app/ is touched only to correct one stale forward reference. The work splits on one line: CI proves every claim that is a property of a file or of the application's own logic, and a dated reviewer transcript proves every claim that is a property of the Docker runtime. Nothing straddles, because CI runs `bundle exec rspec` with no tag exclusion against a bare postgres service and has no Compose stack. §15 step 8's own command does not do what the plan assumes, and that is the headline finding. `docker kill` is an API stop, so the daemon records the container as manually stopped and `restart: unless-stopped` is defined to skip exactly that case: measured against Docker 28.3.0, every killed service stayed down with RestartCount at 0. A reviewer following the plan literally would conclude §16's durability gate is unmet. The policy is sound — it is the kill that does not exercise it. A SIGKILL delivered to the container's main process from outside its PID namespace, which the daemon does not attribute to an operator, brought db, web and worker back on their own. script/verify_recovery.sh performs both kills and asserts both outcomes. The script records a verdict per check and exits non-zero if any fails, so a committed transcript and a green exit code cannot disagree. Two measurements needed that discipline to be correct rather than merely reported. Test isolation now stops the worker for the duration: continuous polling is the worker's whole job, so a fixture poll landing mid-suite moves push_events and solid_queue_jobs whether or not the suite touches them, and an earlier revision recorded 263 -> 353 while printing that the gate held. The redirect scenarios now force selection onto the corpus repository first, because §10 picks the newest eligible candidate and on a database that has polled live GitHub that is a real repository the corpus has never heard of — so an earlier revision watched both scenarios die on a corpus gap while `|| true` swallowed the exit code. ADR 0008 asked PR 11 to measure whether Solid Queue concurrency limits keyed by source id close a gap the source lock leaves. They do not, and the verdict is now recorded with four observations: five contended ticks produce no run row, request, debit or schedule movement; a contended tick issues no INSERT, UPDATE or DELETE at all, so a semaphore would spend writes to prevent writes that never happen; a killed session's lock frees in milliseconds where a fixed duration cannot; and key agreement comes from SourceProvisioner rather than from any concurrency primitive. An example asserts no job declares limits_concurrency, so reversing the decision fails a test. Two new examples pin behavior nothing pinned before, verified by breaking the code and watching only them fail. Removing IngestionRunner's in-lock `event_source.reload` fails four multi-poller examples and nothing else — that reload is what stops two pollers who both read a stale cadence from polling back to back, which ADR 0006 rejected an alternative to protect. Swapping PageWriter's actor-before-repository upsert order fails exactly one, asserted on statement order because both upserts share a transaction and the positional observable is identical either way. Fairness is measured over a whole window rather than one choice: against a 60:3 repository flood the three actors all enrich, borrowing begins only after the last actor choice, and forty real denials write nothing global. Crash windows are expressed as the durable state a kill leaves — an abandoned `running` run row that nothing resurrects, a page committed one envelope deep and replayed, and all three crash signatures composed into one restart. spec/recovery/concurrent_write_spec.rb turns transactional fixtures off, because what it tests is what one session can see of another's commit. The two redirect corpus scenarios are consumed at last, through the enrichment claim path: a rename completes and is debited for both hops, a hostile Location reaches permanent_failure with the second hop never sent and the event source still in service. The compose test-service assertion is structural rather than an equality against a frozen command string, so a later step appended to that pipeline — as PR 9 appended `bundle exec rspec spec/stress` — cannot turn a green branch red on merge. Closes #21 Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 63 +- app/jobs/poll_event_source_job.rb | 4 +- ...nqueue-and-entity-scoped-reconciliation.md | 26 + .../2026-07-31-container-kill-recovery.md | 523 +++++++++++ fixtures/github/README.md | 8 +- script/verify_recovery.sh | 848 ++++++++++++++++++ spec/docker_compose_spec.rb | 234 +++++ spec/recovery/concurrent_write_spec.rb | 238 +++++ spec/recovery/crash_window_spec.rb | 312 +++++++ spec/recovery/multi_poller_spec.rb | 334 +++++++ .../github/enrichment/fairness_stress_spec.rb | 248 +++++ .../enrichment/redirect_boundary_spec.rb | 126 +++ .../github/fixture_mode_fail_closed_spec.rb | 165 ++++ 13 files changed, 3123 insertions(+), 6 deletions(-) create mode 100644 docs/evidence/2026-07-31-container-kill-recovery.md create mode 100755 script/verify_recovery.sh create mode 100644 spec/recovery/concurrent_write_spec.rb create mode 100644 spec/recovery/crash_window_spec.rb create mode 100644 spec/recovery/multi_poller_spec.rb create mode 100644 spec/services/github/enrichment/fairness_stress_spec.rb create mode 100644 spec/services/github/enrichment/redirect_boundary_spec.rb create mode 100644 spec/services/github/fixture_mode_fail_closed_spec.rb diff --git a/README.md b/README.md index 2cf70e4..8cbc262 100644 --- a/README.md +++ b/README.md @@ -752,9 +752,7 @@ effectively-once persisted outcomes — never exactly-once execution. | Section | Lands with | |---|---| | Data model reference | PR 12 (design brief) | -| Full fixture scenario matrix (retries, rate limits, redirects) | PR 11 | | API and database inspection examples | PR 10, 12 | -| Crash-recovery verification (container kills) | PR 11, 12 | | Known limitations (sampling-based enrichment, no complete-capture guarantee, shared-IP budget) | PR 12 | ## Reviewer commands @@ -769,6 +767,7 @@ docker compose run --rm enrich --limit 6 # available now — up to GITHUB_MODE=fixture docker compose up --build # available now — the whole system, no network GITHUB_MODE=fixture docker compose run --rm ingest # available now — deterministic, no network GITHUB_MODE=fixture docker compose run --rm enrich --limit 6 +script/verify_recovery.sh --confirm # §15 step 8's container kills; nothing in CI runs it ``` The queue is a database, so it is inspectable with the same tool as everything else: @@ -793,8 +792,64 @@ docker compose start worker docker compose logs -f worker # enrichment.dispatched, then enrichment.completed ``` -Container-kill verification against the restart policies is `IMPLEMENTATION_PLAN.md` -§15's reviewer step and lands with PR 11; nothing above claims it. +## Crash recovery, verified + +`IMPLEMENTATION_PLAN.md` §15 step 8 asks a reviewer to kill containers and watch them come +back. Run it with one command, against a stack started in fixture mode: + +```bash +GITHUB_MODE=fixture docker compose up --build -d +script/verify_recovery.sh --confirm +``` + +A dated transcript of that run is committed at +[`docs/evidence/2026-07-31-container-kill-recovery.md`](docs/evidence/2026-07-31-container-kill-recovery.md). +Nothing in CI runs the script — it kills containers and writes to the development databases, +and `spec/docker_compose_spec.rb` asserts that no workflow references it. + +**Read §15's command knowing what it does.** `docker kill` is an API stop: the daemon records +the container as manually stopped, and `restart: unless-stopped` is defined to skip exactly +that case. So the documented command leaves the container down, and + +```bash +docker kill github-push-ingestor-worker-1 +docker compose ps # Exited (137) — and it stays that way +docker compose up -d worker +``` + +is the honest sequence. The restart policy is sound; it is the *kill* that does not exercise +it. A crash — the container's main process dying rather than being stopped through the API — +does, and every service recovered on its own with no operator step. The script performs both +and reports both. + +One reading tip for §15 step 8's `docker compose ps` output: `web`'s container healthcheck +curls `/health/live`, which never touches the database, so `web` stays green throughout a `db` +kill. `/health/ready` is the observable that flips. + +### Fixture scenario matrix + +Every scenario resolves inside [`fixtures/github/`](fixtures/github/) with no network at all. +Each poll obeys GitHub's `X-Poll-Interval` floor of 60s, which `--force` deliberately does not +bypass, so allow a minute between successive ingestion scenarios. + +| Scenario | Command | What it shows | Cleanup | +|---|---|---|---| +| `default` | `GITHUB_MODE=fixture docker compose run --rm ingest` | 4 push events, 3 actors, 3 repositories, 3 quarantined | none | +| `default` (replay) | `… run --rm ingest --force` after 60s | `duplicates_skipped > 0`, occurrence counts climb, no skipped entity reactivated | none | +| `default` (enrich) | `… run --rm enrich --limit 6` | both classes enrich within their fairness shares | none | +| `paginated` | `GITHUB_FIXTURE_SCENARIO=paginated MAX_PAGES_PER_POLL=3 … ingest` | `Link`-driven walk over 3 pages | none | +| `paginated_final_page` | `GITHUB_FIXTURE_SCENARIO=paginated_final_page … ingest` | the walk stops when no `next` link exists | none | +| `transient_failure` | `GITHUB_FIXTURE_SCENARIO=transient_failure … ingest` | one `500`, then success on retry | none | +| `transient_failure_exhausted` | `GITHUB_FIXTURE_SCENARIO=transient_failure_exhausted … ingest` | retries exhausted; the source backs off | source backoff | +| `redirecting_repository` | `GITHUB_FIXTURE_SCENARIO=redirecting_repository … enrich --class repository` | a renamed repository followed across one validated hop, debited twice | none | +| `hostile_redirect` | `GITHUB_FIXTURE_SCENARIO=hostile_redirect … enrich --class repository` | an off-host `Location` refused by the URL policy; the second hop is never sent and the event source stays in service | none | +| `secondary_rate_limited` | `GITHUB_FIXTURE_SCENARIO=secondary_rate_limited … ingest` | a secondary limit blocks globally | global block | +| `rate_limited` | `GITHUB_FIXTURE_SCENARIO=rate_limited … ingest` | primary exhaustion → `global_blocked_until` | **a real one-hour global block** | + +The last two leave durable state behind on purpose — that is the behaviour being demonstrated. +`script/verify_recovery.sh --phase=cleanup` runs the SQL under +[Recovering from a fixture rate-limit run](#recovering-from-a-fixture-rate-limit-run), and +`--phase=rate-limit` plays the rate-limit scenario and cleans up immediately after. ## Development diff --git a/app/jobs/poll_event_source_job.rb b/app/jobs/poll_event_source_job.rb index b1a838d..a8e989f 100644 --- a/app/jobs/poll_event_source_job.rb +++ b/app/jobs/poll_event_source_job.rb @@ -18,7 +18,9 @@ # fixed duration, so a container killed mid-poll would suppress that source until it expired, # where the session advisory lock is released by PostgreSQL the moment the backend dies. PR 8 # is the PR about surviving container kills; a weaker duplicate of a lock we already hold -# would be a regression. Revisit in PR 11, where multi-poller tests could justify one. +# would be a regression. PR 11 measured the question rather than leaving it open — a contended +# tick writes nothing at all, and the lock frees a killed session in milliseconds where a +# semaphore's fixed duration cannot. See spec/recovery/multi_poller_spec.rb and ADR 0008. class PollEventSourceJob < ApplicationJob # Facts about the process rather than about one source: continuing to the next source # would only repeat them, and a tick that "completed" after boot-level breakage would be a diff --git a/docs/adr/0008-post-commit-enqueue-and-entity-scoped-reconciliation.md b/docs/adr/0008-post-commit-enqueue-and-entity-scoped-reconciliation.md index 7139fbf..f57df04 100644 --- a/docs/adr/0008-post-commit-enqueue-and-entity-scoped-reconciliation.md +++ b/docs/adr/0008-post-commit-enqueue-and-entity-scoped-reconciliation.md @@ -98,6 +98,32 @@ existing lock — in the PR whose subject is surviving container kills — would regression. The source lock, the global request gate and the unique event constraint are the protections in force; revisit when PR 11's multi-poller tests can measure a gap. +**PR 11 measured it. Verdict: no gap, and the rejection stands.** +`spec/recovery/multi_poller_spec.rb`'s "the gap ADR 0008 asked PR 11 to measure" takes four +observations, on the definition that a gap exists iff sustained contention leaves some +observable cost or incorrectness a source-keyed semaphore would have prevented. + +1. Five contended ticks against a held source lock produce no run row, no request, no debit, + no schedule movement and no event — the four things the semaphore would exist to prevent + are already zero across a window, not merely across one tick. +2. A contended tick issues **no INSERT, UPDATE or DELETE at all**. A semaphore costs an insert + and a delete in `solid_queue_semaphores` per acquire, so it would spend writes to prevent + writes that never happen. +3. The lock frees a killed session in milliseconds, measured against `CLOCK_MONOTONIC`, + where a fixed-`duration` semaphore must by construction outlast the longest legitimate + poll. This is the crash-safety argument above, measured rather than asserted. +4. Agreement on the key comes from `Github::Ingestion::SourceProvisioner`, not from any + concurrency primitive — two first-time processes that each created a row would hold + semaphores on two different keys and both poll. + +The verdict is executable rather than prose: an example asserts that no job under `app/jobs/` +declares `limits_concurrency`, so reversing this decision fails a test and sends the author +back to this section. + +Bounded honestly: that measurement covers correctness and local cost. Whether a +`solid_queue_semaphores` round trip is material under N real worker containers is a load +question, and nothing here answers it. + **A dedicated outbox table.** A row per pending enrichment would be a second representation of a fact the entity row already carries, with its own drift and its own cleanup. §2A calls this design outbox-*style* precisely because there is no such record. diff --git a/docs/evidence/2026-07-31-container-kill-recovery.md b/docs/evidence/2026-07-31-container-kill-recovery.md new file mode 100644 index 0000000..20c4c9f --- /dev/null +++ b/docs/evidence/2026-07-31-container-kill-recovery.md @@ -0,0 +1,523 @@ +# Container-kill recovery verification + +Date: 2026-07-31 + +Status: First-party observation + +## Why this verification exists + +`IMPLEMENTATION_PLAN.md` §2A declares `restart: unless-stopped` on `db`, `web` and `worker`, +and §16 turns that declaration into a durability gate whose wording is deliberately strong: +"Docker restart policies recover crashed `db`/`web`/`worker` containers automatically +**(verified by container kills)**". §15 step 8 gives the reviewer the commands. + +Until something kills a container, all of that is a line of YAML. +`spec/docker_compose_spec.rb` asserts the *declarations* — that `db` keeps a named volume, +that `web` runs puma directly so no pid file can survive an ungraceful kill, that no service +leaves `restart` implicit — and `spec/recovery/` asserts the crash-window *state machine*. +Neither can observe Docker's restart policy, because no RSpec example can kill the process it +is running inside. This is the observation that closes that gap. + +## The finding + +**§15 step 8's own command does not exercise the restart policy, and never could.** + +`docker kill` is an API stop. The daemon records the container as manually stopped, and +`restart: unless-stopped` is defined to skip exactly that case — that is what "unless stopped" +means. Measured below, each of the three services stayed down after `docker kill` with +`RestartCount` unchanged at 0. A reviewer following the plan literally would watch three +containers die, see none of them come back, and conclude the durability gate is unmet. + +The policy itself is sound. When the container's main process is killed the way a real crash +kills it — SIGKILL delivered from outside the container's PID namespace, which the daemon does +not attribute to an operator — every service came back on its own, with `RestartCount` +incrementing and no operator step. + +So the two facts are separate and both belong in the record: + +| Service | `docker kill` (§15 step 8) | process crash | +|---|---|---| +| `worker` | stays down, `RestartCount` 0 → 0 | restarts itself, 0 → 1 | +| `db` | stays down, `RestartCount` 0 → 0 | restarts itself, 0 → 1 | +| `web` | stays down, `RestartCount` 0 → 0 | restarts itself, 0 → 1 | + +`script/verify_recovery.sh` therefore kills each service twice and reports both, rather than +quietly substituting the kill that works. A reviewer typing §15's command should be told what +they are about to see. + +Note that an in-container kill is not an alternative: the kernel refuses to deliver SIGKILL to +a PID namespace's own init from inside that namespace, so `docker exec … kill -9 1` is a no-op. +The helper runs `--pid=host --privileged --user 0`; the `--user 0` is load-bearing, because the +application image declares a non-root user which cannot signal postgres. + +## What else was measured + +- **Records survived.** `push_events` read 9,293 before the worker kill and 9,293 after every + kill, restart and recovery in this run. PostgreSQL replayed its WAL onto the same volume. +- **The volume is the same volume.** `github-push-ingestor_pgdata`'s `CreatedAt` is identical at + preflight and at the end, so the counts above are survival rather than recreation. +- **§16's test-isolation gate holds at runtime.** `docker compose run --rm test` left both + development databases byte-identical (`push_events` 9,293 and `solid_queue_jobs` 1,703 on + both sides) and did not trigger the development `setup` service. The worker is stopped for + the duration of that measurement and restarted after: it is the only other writer to those + tables, and a fixture poll landing mid-suite would otherwise move both counters and make the + comparison meaningless. An earlier revision of this script did not stop it, recorded + `push_events` climbing 263 → 353, and still printed that the gate held — the check now fails + the run instead. +- **Fixture mode failed closed in the running stack.** This development database holds entities + from earlier live polls, whose `api_url`s are absent from the corpus. The fixture-mode + enrichment cycle refused with a corpus gap and exit 2 rather than reaching `api.github.com`. + That is §6's rule observed in a container, which no unit test can show. +- **Both redirect corpus scenarios ran end to end, with a verdict.** `redirecting_repository` + left the corpus repository `complete` across a validated hop; `hostile_redirect` left it + `permanent_failure` with the second hop never sent. Selection is forced first — §10 picks the + newest eligible candidate, and on a database that has polled live GitHub that is a real + repository the corpus has never heard of, so an earlier revision of this script watched both + scenarios die on a corpus gap while `|| true` swallowed the exit code. + +## What this does not show + +- One host, one operating system, one Docker version, one date. Docker's treatment of + `docker kill` is a daemon behaviour and could differ on another version; the commands to + re-measure it are below. +- `unless-stopped` is **not** exercised here across a Docker daemon restart or a host reboot, + which is the other half of what the policy promises. +- A SIGKILL to postgres exercises WAL crash recovery, not disk corruption, not a failing + volume, and not a full disk. +- The worker ran in fixture mode, whose sticky-tail `304` is what makes "the count is + unchanged" a stable expectation. A live stack's count would legitimately grow between the two + measurements, and this transcript says nothing about that case. +- **No kill here was deliberately timed inside an in-flight `push_events` insert.** That + guarantee is not observable from outside the process and is asserted instead by + `spec/recovery/crash_window_spec.rb`, which composes a held source lock, an abandoned + enrichment lease and a lost enqueue into one restart. +- `docker kill` is not an OOM kill, not a power loss, and not a kernel panic. +- The counts are read as deltas, not against the README's documented absolutes (4 / 3 / 3 / 3), + because this database was not started from an empty volume. `script/verify_recovery.sh` + detects that and says which mode it used. +- The redirect scenarios are exercised against one seeded row, so what they show is the + outcome for *that* repository rather than a property of the selection policy. The policy + itself is asserted in `spec/services/github/enrichment/redirect_boundary_spec.rb`. + +## Every check in this run + +The script records a verdict per check and exits non-zero if any failed, so a committed +transcript and a green exit code cannot disagree. This run: **19 checks, all passing.** The +per-check list is in the transcript below, under each phase. + +## Reproducing it + +```bash +GITHUB_MODE=fixture docker compose up --build -d +script/verify_recovery.sh --confirm +``` + +The script refuses to run under `CI`, without `--confirm`, against a stack whose worker is not +in fixture mode, with `RAILS_ENV` set to anything but `development`, or when the container +names do not match the literals §15 uses. It never runs `docker compose down`, never drops a +database, and never issues psql against a `_test` database. + +Nothing in the suite, in `config/ci.rb`, in `bin/ci` or in the workflows executes it — +`spec/docker_compose_spec.rb` asserts that, so "CI never runs the verification" is a red test +rather than a promise. + +## Raw transcript + +Captured by `script/verify_recovery.sh` on the date above. `login`, `display_login`, +`full_name`, `api_url`, `avatar_url` and the corpus-miss payload are redacted in place — names +kept, values removed — because a development database that has polled live GitHub holds real +third-party account and repository names that no finding here needs. + + + +```text +Verification date: 2026-07-31 +Compose project: github-push-ingestor +Git revision: ac5cf989393e28dc5e85058647816c3aa00927e6 +Docker version: 28.3.0 +Compose version: 2.38.1-desktop.1 +Host: Darwin 25.5.0 arm64 +Worker mode: fixture (enforced by preflight) +Count mode: delta +Captured by: script/verify_recovery.sh +Redaction: login, display_login, full_name, api_url, avatar_url and the corpus-miss + payload are replaced in place; names kept, values removed +``` + +## Baseline + +``` + Container github-push-ingestor-db-1 Running + Container github-push-ingestor-db-1 Waiting + Container github-push-ingestor-db-1 Healthy + Container github-push-ingestor-setup-1 Starting + Container github-push-ingestor-setup-1 Started +{"timestamp":"2026-07-31T11:58:11.177Z","level":"info","service":"github-push-ingestor","environment":"development","event":"config.budget_resolved","mode":"fixture","poll_interval_seconds":300,"max_pages_per_poll":1,"enabled_live_source_count":1,"worst_case_reservations_per_poll":9,"limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20} +{"timestamp":"2026-07-31T11:58:11.373Z","level":"info","service":"github-push-ingestor","environment":"development","event":"ingestion.not_due","event_source_id":1,"forced":false,"deferral_reason":"cadence_due_at","next_poll_at":"2026-07-31T12:03:00Z","cadence_due_at":"2026-07-31T12:03:00Z","poll_floor_until":"2026-07-31T11:59:00Z"} +Ingestion deferred until 2026-07-31T12:03:00Z — cadence_due_at + +Latest successful run: 2026-07-31T11:58:00Z (run_id 01c3ca5b-2af6-4e89-9db9-3daed35148e4) +Persisted push events: 9,293 +Pending actor enrichments: 1,313 +Pending repository enrichments: 1,375 +Next poll due: 2026-07-31T12:03:00Z +Budget remaining (core): 59 (window resets 2026-07-31T12:58:00Z) +Global block: none +``` + +``` + Container github-push-ingestor-db-1 Running + Container github-push-ingestor-db-1 Waiting + Container github-push-ingestor-db-1 Healthy + Container github-push-ingestor-setup-1 Starting + Container github-push-ingestor-setup-1 Started +{"timestamp":"2026-07-31T11:58:13.633Z","level":"info","service":"github-push-ingestor","environment":"development","event":"config.budget_resolved","mode":"fixture","poll_interval_seconds":300,"max_pages_per_poll":1,"enabled_live_source_count":1,"worst_case_reservations_per_poll":9,"limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20} +{"timestamp":"2026-07-31T11:58:13.814Z","level":"info","service":"github-push-ingestor","environment":"development","event":"enrichment.aged_out","entity_type":"actor","skipped_count":467,"batch_size":1000,"eligible_since":"2026-07-31T10:58:13Z"} +{"timestamp":"2026-07-31T11:58:13.822Z","level":"info","service":"github-push-ingestor","environment":"development","event":"enrichment.aged_out","entity_type":"repository","skipped_count":493,"batch_size":1000,"eligible_since":"2026-07-31T10:58:13Z"} +Fixture corpus error: the corpus defines no response for "" +Actors pending/complete/skipped: 846 / 271 / 5,528 +Repos pending/complete/skipped: 882 / 267 / 5,844 +Actor requests used: 1 of 20 +Repository requests used: 0 of 20 +Enrichment requests used: 1 of 40 +Next enrichment due: due now + +Latest successful run: 2026-07-31T11:58:00Z (run_id 01c3ca5b-2af6-4e89-9db9-3daed35148e4) +Persisted push events: 9,293 +Pending actor enrichments: 846 +Pending repository enrichments: 882 +Next poll due: 2026-07-31T12:03:00Z +Budget remaining (core): 58 (window resets 2026-07-31T12:58:00Z) +Global block: none + +``` + +A corpus gap above is not a fault. It means this development database holds entities +from an earlier live run, and fixture mode refused to fetch them rather than falling +back to the network — exit 2, "refused to run", per §9's exit-code contract. + +The development database already held 9293 push events at the start of this +run, so the counts below are read as deltas. The README's documented absolutes +(4 / 3 / 3 / 3 / 3) apply only to a stack started from an empty volume. + +| measurement | push_events | actors | repositories | quarantined | occurrences | +| ------------------------ | --- | --- | --- | --- | --- | +| baseline | 9293 | 6646 | 6994 | 3 | 24 | + +## Worker kill (§15 step 8) + +Count before the kill: push_events = 9293 + +### Part 1 — the command §15 documents + +$ docker kill github-push-ingestor-worker-1 + +$ docker compose ps +``` +NAME IMAGE COMMAND SERVICE CREATED STATUS PORTS +github-push-ingestor-db-1 postgres:16 "docker-entrypoint.s…" db 22 hours ago Up 9 hours (healthy) 5432/tcp +github-push-ingestor-web-1 github-push-ingestor-app "bundle exec puma -C…" web 55 seconds ago Up 52 seconds (healthy) 0.0.0.0:3000->3000/tcp, [::]:3000->3000/tcp +``` + +| after `docker kill` | value | +| --- | --- | +| Running | false | +| ExitCode | 137 | +| RestartCount | 0 -> 0 | + +- PASS — docker kill leaves worker down, because an API stop skips the restart policy +- PASS — docker kill does not increment worker's RestartCount + +`docker kill` is an API stop, so the daemon records the container as manually stopped +and `restart: unless-stopped` does not apply. The container stays down and an operator +step is required to bring it back — which is what the next command is. + +$ docker compose up -d worker + +### Part 2 — a process crash, which is what the policy is for + +$ docker run --rm --pid=host --privileged --user 0 github-push-ingestor-app sh -c 'kill -9 71866' + +| after a process crash | value | +| --- | --- | +| Running | true | +| RestartCount | 0 -> 1 | +| StartedAt | 2026-07-31T11:58:27.985033422Z -> 2026-07-31T11:58:28.817818464Z | + +- PASS — worker was restarted by its policy after a process crash +- PASS — worker's RestartCount incremented + +Docker restarted `worker` on its own. No operator step. + +$ docker compose logs worker --since 2m +``` +{"timestamp":"2026-07-31T11:58:29.241Z","level":"info","service":"github-push-ingestor","environment":"development","event":"config.budget_resolved","mode":"live","poll_interval_seconds":300,"max_pages_per_poll":1,"enabled_live_source_count":1,"worst_case_reservations_per_poll":9,"limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20} +{"timestamp":"2026-07-31T11:58:29.524Z","level":"info","service":"github-push-ingestor","environment":"development","message":"SolidQueue-1.5.1 Started Supervisor(fork) (27.1ms) pid: 1, hostname: \"07576a1f31d4\", process_id: 255, name: \"supervisor(fork)-a08de2f018029095efd5\""} +{"timestamp":"2026-07-31T11:58:29.552Z","level":"info","service":"github-push-ingestor","environment":"development","message":"SolidQueue-1.5.1 Started Dispatcher (25.1ms) pid: 11, hostname: \"07576a1f31d4\", process_id: 256, name: \"dispatcher-b0a6d73b6ac91683b3d1\", polling_interval: 1, batch_size: 500, concurrency_maintenance_interval: 600"} +{"timestamp":"2026-07-31T11:58:29.552Z","level":"info","service":"github-push-ingestor","environment":"development","message":"SolidQueue-1.5.1 Started Worker (23.3ms) pid: 15, hostname: \"07576a1f31d4\", process_id: 257, name: \"worker-34a3ed5d4550b3bab3ab\", polling_interval: 1, queues: \"*\", thread_pool_size: 2"} +{"timestamp":"2026-07-31T11:58:29.563Z","level":"info","service":"github-push-ingestor","environment":"development","message":"SolidQueue-1.5.1 Started Scheduler (31.8ms) pid: 19, hostname: \"07576a1f31d4\", process_id: 258, name: \"scheduler-01c7cc9291d0c3c23e7f\", recurring_schedule: [\"poll_event_sources\", \"reconcile_pending_enrichments\", \"clear_solid_queue_finished_jobs\"]"} +``` + +Count after recovery: push_events = 9293 + +## Database kill (§15 step 8) + +Count before the kill: push_events = 9293 + +### Part 1 — the command §15 documents + +$ docker kill github-push-ingestor-db-1 + +$ docker compose ps +``` +NAME IMAGE COMMAND SERVICE CREATED STATUS PORTS +github-push-ingestor-web-1 github-push-ingestor-app "bundle exec puma -C…" web About a minute ago Up About a minute (healthy) 0.0.0.0:3000->3000/tcp, [::]:3000->3000/tcp +github-push-ingestor-worker-1 github-push-ingestor-app "bin/jobs" worker 14 seconds ago Restarting (1) 2 seconds ago +``` + +| after `docker kill` | value | +| --- | --- | +| Running | false | +| ExitCode | 137 | +| RestartCount | 0 -> 0 | + +- PASS — docker kill leaves db down, because an API stop skips the restart policy +- PASS — docker kill does not increment db's RestartCount + +`docker kill` is an API stop, so the daemon records the container as manually stopped +and `restart: unless-stopped` does not apply. The container stays down and an operator +step is required to bring it back — which is what the next command is. + +$ docker compose up -d db + +### Part 2 — a process crash, which is what the policy is for + +$ docker run --rm --pid=host --privileged --user 0 github-push-ingestor-app sh -c 'kill -9 72842' + +| after a process crash | value | +| --- | --- | +| Running | true | +| RestartCount | 0 -> 1 | +| StartedAt | 2026-07-31T11:58:41.025798345Z -> 2026-07-31T11:58:47.519682667Z | + +- PASS — db was restarted by its policy after a process crash +- PASS — db's RestartCount incremented + +Docker restarted `db` on its own. No operator step. + +Count after recovery: push_events = 9293 + +- PASS — push_events is unchanged across two SIGKILLs of the database + +PostgreSQL replayed its WAL onto the same named volume, which is §15 step 8's actual +question. + +## Web kill (beyond §15's list — verifies the Dockerfile's pid-file claim) + +§16's durability gate names db, web and worker; §15 step 8 kills only two. The +Dockerfile runs puma directly rather than `bin/rails server` so that a stale +tmp/pids/server.pid left by an ungraceful kill cannot block the restart +`unless-stopped` promises — and a crash is the only thing that exercises it. + +### Part 1 — the command §15 documents + +$ docker kill github-push-ingestor-web-1 + +$ docker compose ps +``` +NAME IMAGE COMMAND SERVICE CREATED STATUS PORTS +github-push-ingestor-db-1 postgres:16 "docker-entrypoint.s…" db 22 hours ago Up 16 seconds (healthy) 5432/tcp +github-push-ingestor-worker-1 github-push-ingestor-app "bin/jobs" worker 38 seconds ago Up 17 seconds 3000/tcp +``` + +| after `docker kill` | value | +| --- | --- | +| Running | false | +| ExitCode | 137 | +| RestartCount | 0 -> 0 | + +- PASS — docker kill leaves web down, because an API stop skips the restart policy +- PASS — docker kill does not increment web's RestartCount + +`docker kill` is an API stop, so the daemon records the container as manually stopped +and `restart: unless-stopped` does not apply. The container stays down and an operator +step is required to bring it back — which is what the next command is. + +$ docker compose up -d web + +### Part 2 — a process crash, which is what the policy is for + +$ docker run --rm --pid=host --privileged --user 0 github-push-ingestor-app sh -c 'kill -9 73745' + +| after a process crash | value | +| --- | --- | +| Running | true | +| RestartCount | 0 -> 1 | +| StartedAt | 2026-07-31T11:59:06.570479551Z -> 2026-07-31T11:59:08.565763093Z | + +- PASS — web was restarted by its policy after a process crash +- PASS — web's RestartCount incremented + +Docker restarted `web` on its own. No operator step. + +`/health/live` and `/health/ready` both answer again after an uncooperative kill, so no +pid file survived to block the restart. + +## Normal restart (§15 step 9) + +$ docker compose restart +``` +``` + +Took 1s. The worker's `stop_grace_period: 30s` is a ceiling, not a duration: +Solid Queue's supervisor acknowledges SIGTERM and exits well inside it whenever no +GitHub request is in flight, and in fixture mode none ever is for long. + +push_events before: 9293, after: 9293 + +## Test isolation (§16's reviewer-experience gate) + +§16 requires that `docker compose run --rm test` never touches the development +databases (app or queue) and never triggers the development `setup` service. +spec/docker_compose_spec.rb asserts the declarations; this measures the behaviour. + +$ docker compose stop worker # the only other writer to these databases + +``` + the reserve + stops every class at the reserve, however many callers are in flight + +Finished in 0.92454 seconds (files took 0.41603 seconds to load) +10 examples, 0 failures + +Randomized with seed 18641 + +``` + +$ docker compose start worker + +| observable | before | after | +| --- | --- | --- | +| development push_events | 9293 | 9293 | +| development solid_queue_jobs | 1703 | 1703 | +| setup container FinishedAt | 2026-07-31T11:59:11.267659511Z | 2026-07-31T11:59:11.267659511Z | + +- PASS — the suite left development push_events untouched +- PASS — the suite left the development queue untouched +- PASS — the suite did not trigger the development setup service + +## Deterministic fixture scenarios (§15 step 10) + +The full nine-scenario matrix is documented in the README; this phase runs the two +the transcript can prove without waiting. Every ingestion obeys GitHub's +`X-Poll-Interval` floor of 60s, which `--force` deliberately does not bypass, so +back-to-back poll scenarios are a README exercise rather than a script phase. The +redirect scenarios go through `bin/enrich`, which has no cadence. + +$ docker compose stop worker # so nothing re-orders the candidate set mid-scenario + +### redirecting_repository — a validated redirect is followed and the entity completes + +``` + Container github-push-ingestor-db-1 Running + Container github-push-ingestor-setup-1 Recreate + Container github-push-ingestor-setup-1 Recreated + Container github-push-ingestor-db-1 Waiting + Container github-push-ingestor-db-1 Healthy + Container github-push-ingestor-setup-1 Starting + Container github-push-ingestor-setup-1 Started +{"timestamp":"2026-07-31T11:59:46.289Z","level":"info","service":"github-push-ingestor","environment":"development","event":"config.budget_resolved","mode":"fixture","poll_interval_seconds":300,"max_pages_per_poll":1,"enabled_live_source_count":1,"worst_case_reservations_per_poll":9,"limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20} +{"timestamp":"2026-07-31T11:59:46.497Z","level":"info","service":"github-push-ingestor","environment":"development","event":"budget.window_rolled","carried_forward":"repository","limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20} +{"timestamp":"2026-07-31T11:59:46.498Z","level":"info","service":"github-push-ingestor","environment":"development","event":"budget.window_initialized","limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20,"rate_limit_resource":"core","rate_limit_limit":60,"rate_limit_remaining":54,"rate_limit_used":6,"rate_limit_reset_at":"2026-07-31T12:59:46Z","poll_used":0} +{"timestamp":"2026-07-31T11:59:46.505Z","level":"info","service":"github-push-ingestor","environment":"development","enrichment_outcome":"enriched","entity_type":"repository","github_id":1296269,"pool":"pending","classification":"ok","entity_status":"complete","enrichment_attempt":1,"duration_ms":71.8,"event":"enrichment.completed"} +Enriched repository 1296269 — complete + +Enrichment cycles: 1 +Entities enriched: 1 +Entities failed: 0 +Cycles deferred: 0 +Cycles with nothing eligible: 0 +Candidates skipped (budget): 0 + +Actors pending/complete/skipped: 845 / 272 / 5,528 +Repos pending/complete/skipped: 881 / 269 / 5,843 +Actor requests used: 0 of 20 +Repository requests used: 2 of 20 +Enrichment requests used: 2 of 40 +Next enrichment due: due now + +Latest successful run: 2026-07-31T11:58:00Z (run_id 01c3ca5b-2af6-4e89-9db9-3daed35148e4) +Persisted push events: 9,293 +Pending actor enrichments: 845 +Pending repository enrichments: 881 +Next poll due: 2026-07-31T12:03:00Z +Budget remaining (core): 53 (window resets 2026-07-31T12:59:46Z) +Global block: none +``` + +- PASS — redirecting_repository left the corpus repository complete + +### hostile_redirect — an off-host redirect is refused by the URL policy + +``` + Container github-push-ingestor-db-1 Running + Container github-push-ingestor-setup-1 Recreate + Container github-push-ingestor-setup-1 Recreated + Container github-push-ingestor-db-1 Waiting + Container github-push-ingestor-db-1 Healthy + Container github-push-ingestor-setup-1 Starting + Container github-push-ingestor-setup-1 Started +{"timestamp":"2026-07-31T11:59:49.923Z","level":"info","service":"github-push-ingestor","environment":"development","event":"config.budget_resolved","mode":"fixture","poll_interval_seconds":300,"max_pages_per_poll":1,"enabled_live_source_count":1,"worst_case_reservations_per_poll":9,"limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20} +{"timestamp":"2026-07-31T11:59:50.120Z","level":"info","service":"github-push-ingestor","environment":"development","event":"budget.window_rolled","carried_forward":"repository","limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20} +{"timestamp":"2026-07-31T11:59:50.121Z","level":"info","service":"github-push-ingestor","environment":"development","event":"budget.window_initialized","limit":60,"reserve":8,"poll_allowance":12,"enrichment_allowance":40,"actor_guarantee":20,"repository_guarantee":20,"rate_limit_resource":"core","rate_limit_limit":60,"rate_limit_remaining":54,"rate_limit_used":6,"rate_limit_reset_at":"2026-07-31T12:59:50Z","poll_used":0} +{"timestamp":"2026-07-31T11:59:50.122Z","level":"warn","service":"github-push-ingestor","environment":"development","event":"github.request","request_class":"repository","http_method":"get","url":"https://evil.example.com/repos/octocat/Hello-World","origin":"payload","entity_type":"repository","github_repository_id":1296269,"pool":"pending","entity_status":"pending","enrichment_attempt":1,"classification":"permanent_error","attempt":0,"duration_ms":0.0,"error_class":"Github::Errors::UrlPolicyViolation","error_message":"refused \"https://evil.example.com/repos/octocat/Hello-World\": host_not_allowed"} +{"timestamp":"2026-07-31T11:59:50.124Z","level":"info","service":"github-push-ingestor","environment":"development","enrichment_outcome":"failed","entity_type":"repository","github_id":1296269,"pool":"pending","classification":"permanent_error","entity_status":"permanent_failure","enrichment_attempt":1,"error_message":"refused \"https://evil.example.com/repos/octocat/Hello-World\": host_not_allowed","duration_ms":50.8,"event":"enrichment.failed"} +Repository 1296269 permanent_failure: refused "https://evil.example.com/repos/octocat/Hello-World": host_not_allowed + +Enrichment cycles: 1 +Entities enriched: 0 +Entities failed: 1 +Cycles deferred: 0 +Cycles with nothing eligible: 0 +Candidates skipped (budget): 0 + +Actors pending/complete/skipped: 845 / 272 / 5,528 +Repos pending/complete/skipped: 881 / 268 / 5,843 +Actor requests used: 0 of 20 +Repository requests used: 1 of 20 +Enrichment requests used: 1 of 40 +Next enrichment due: due now + +Latest successful run: 2026-07-31T11:58:00Z (run_id 01c3ca5b-2af6-4e89-9db9-3daed35148e4) +Persisted push events: 9,293 +Pending actor enrichments: 845 +Pending repository enrichments: 881 +Next poll due: 2026-07-31T12:03:00Z +Budget remaining (core): 54 (window resets 2026-07-31T12:59:50Z) +Global block: none +``` + +- PASS — hostile_redirect left the corpus repository permanent_failure + +$ docker compose start worker + +| measurement | push_events | actors | repositories | quarantined | occurrences | +| ------------------------ | --- | --- | --- | --- | --- | +| after scenarios | 9293 | 6646 | 6994 | 3 | 24 | + +## Volume identity + +`github-push-ingestor_pgdata` CreatedAt at preflight: 2026-07-30T13:38:59Z +`github-push-ingestor_pgdata` CreatedAt now: 2026-07-30T13:38:59Z + +- PASS — the pgdata volume is the same volume it was at preflight + +Identical means the records above *survived* the kills rather than being recreated +into a fresh volume, which is what makes the counts evidence rather than coincidence. + +## Verdict + +Every check above passed. + +Paste the above into docs/evidence/$(date -u +%Y-%m-%d)-container-kill-recovery.md and +write the finding and the "What this does not show" section by hand. diff --git a/fixtures/github/README.md b/fixtures/github/README.md index fa012b6..4fff4d1 100644 --- a/fixtures/github/README.md +++ b/fixtures/github/README.md @@ -99,7 +99,13 @@ readable in one place. Scenarios beyond `default` exist because §12 names them as corpus contents. The pagination and rate-limit ones are consumed by `Github::Ingestion::PageLoop` and -`Github::RateLimitPolicy`; the redirect ones wait for PR 11. +`Github::RateLimitPolicy`. The redirect ones are consumed by +`spec/services/github/enrichment/redirect_boundary_spec.rb`, which drives them through the +enrichment claim path rather than through the executor alone — so what is asserted is the +consequence for an *entity*: a rename reaches `complete` and is debited for both hops, while a +hostile `Location` reaches `permanent_failure` with the second hop never sent and the event +source still in service. Both also appear in the README's fixture scenario matrix as reviewer +commands. ## What is in `bodies/events/page-1.json` diff --git a/script/verify_recovery.sh b/script/verify_recovery.sh new file mode 100755 index 0000000..a507b84 --- /dev/null +++ b/script/verify_recovery.sh @@ -0,0 +1,848 @@ +#!/usr/bin/env bash +# +# Runs IMPLEMENTATION_PLAN.md §15 step 8's container-kill verification and prints a +# paste-ready transcript body for docs/evidence/. +# +# WHY THIS EXISTS +# +# §2A declares `restart: unless-stopped` on db, web and worker, and §16 turns that into a +# durability gate whose wording is "verified by container kills". Until something actually +# kills a container, the policy is a line of YAML. spec/docker_compose_spec.rb asserts the +# declarations — that db keeps a *named* volume, that web runs puma directly so no pid file +# can survive a kill, that no service leaves `restart` implicit — but a declaration is not +# an observation, and no RSpec example can kill the process it is running inside. +# +# The crash-window guarantees themselves are unit-tested: spec/recovery/ covers work +# committed but never enqueued, a job delivered twice, a lease left by a crashed worker, +# contention between pollers, advisory-lock release on session death, and the convergence of +# all three after a restart. What none of them can reach is Docker's restart policy, the +# named volume surviving a database kill, and the fact that `docker compose run --rm test` +# leaves the development databases untouched. That is what this script measures. +# +# WHY EACH SERVICE IS KILLED TWICE +# +# §15 step 8 prescribes `docker kill `, and that command does not do what the +# surrounding text assumes. `docker kill` is an API stop: the daemon records the container +# as manually stopped, and `restart: unless-stopped` is defined to skip exactly that case. +# Measured on 2026-07-31 against Docker 28.3.0, the killed worker stayed down with +# RestartCount at 0 — so the plan's own procedure demonstrates the opposite of §16's +# durability gate, and a reviewer following it would conclude the policy is broken. +# +# So each service is killed twice. First with §15's literal command, reporting honestly that +# the container stays down and needs `docker compose up -d` — because that is what a reviewer +# typing the documented command will see. Then with a SIGKILL delivered to the container's +# main process from outside its PID namespace, which the daemon does not treat as a manual +# stop and which is the crash the policy exists for. That second kill is the one that +# verifies §16's gate. +# +# WHY IT IS A SHELL SCRIPT AND NOT A RAKE TASK +# +# A rake task loads Rails, which would put `docker kill` one autoload away from +# Github.executor and the development github_api_budget row — the very state the transcript +# is about. This process knows nothing about the application. It is also not in bin/, which +# holds what the product runs: bin/ingest is what `docker compose run --rm ingest` resolves +# to, and a container-killing tool there invites someone to wire it into compose or CI. +# +# COST: kills and restarts the running db, web and worker containers, and writes to the +# *development* databases. It never touches the test databases, never removes a volume, and +# never runs db:drop or db:reset. Do not run it against a stack someone else is using. +# +# Nothing in the repository executes this file. spec/docker_compose_spec.rb asserts that, so +# "CI never runs the verification" is a red test rather than a promise. + +set -euo pipefail + +readonly PROJECT="github-push-ingestor" +readonly APP_IMAGE="github-push-ingestor-app" +readonly DEV_DB="github_push_ingestor_development" +readonly DEV_QUEUE_DB="github_push_ingestor_queue_development" +readonly LONG_RUNNING="db web worker" +readonly READY_URL="http://localhost:3000/health/ready" +readonly LIVE_URL="http://localhost:3000/health/live" +# octocat/Hello-World — the repository both redirect scenarios in fixtures/github/manifest.json +# are authored against, and the id inside bodies/repos/octocat_hello-world.json. +readonly CORPUS_REPOSITORY_ID=1296269 + +if [ -n "${CI:-}" ]; then + echo "refusing: this verification kills containers and writes to the development databases" >&2 + exit 2 +fi + +PHASE="all" +CONFIRMED="" + +for argument in "$@"; do + case "$argument" in + --confirm) CONFIRMED="yes" ;; + --phase=*) PHASE="${argument#--phase=}" ;; + *) + echo "unknown option: ${argument}" >&2 + CONFIRMED="" + break + ;; + esac +done + +if [ -z "$CONFIRMED" ]; then + cat >&2 <<'USAGE' +usage: script/verify_recovery.sh --confirm [--phase=NAME] + +Runs IMPLEMENTATION_PLAN.md §15 step 8 against the running Compose stack and prints a +transcript body for docs/evidence/. + +WHAT IT MUTATES + + - Kills the db, web and worker containers twice each, one service at a time: once with + §15's `docker kill` (an API stop, which does NOT trigger the restart policy — the + container is brought back with `docker compose up -d`), and once with a SIGKILL to the + container's main process from outside its PID namespace, which does. + - Runs one privileged --pid=host container per crash kill, using the image this project + already builds. Nothing is pulled. + - Runs `docker compose restart` (§15 step 9). + - Runs one fixture-mode ingestion and up to six enrichment cycles, which write to + github_push_ingestor_development: push events, actors, repositories, quarantine rows, + ingestion runs, and the github_api_budget counters. + - Runs `docker compose run --rm test`, which touches only the isolated test databases. + +WHAT IT NEVER DOES + + - No `docker compose down`, with or without -v. No db:drop, no db:reset. + - No psql against any _test database. + - No live GitHub request: fixture mode is a preflight requirement, not a suggestion. + +PHASES (--phase=NAME runs one; the default runs them in this order) + + preflight guards; always runs + baseline one fixture ingestion + enrichment, then record counts + kill-worker §15 step 8's worker kill + kill-db §15 step 8's database kill + kill-web SIGKILL web and wait for /health/ready (beyond §15's list — see below) + restart §15 step 9's `docker compose restart` + test-isolation §16's gate: the suite leaves the development databases untouched + scenarios §15 step 10's deterministic fixture scenario, plus both redirect scenarios + volume-check the pgdata volume is the same volume it was at the start + + rate-limit OPT-IN, never part of the default run. Plays the rate_limited scenario, + which leaves a real one-hour global block, then clears it. + cleanup clears a global block and restores a failed source; the escape hatch if + you interrupt a run + +WHY kill-web IS HERE AND NOT IN §15 + + §16's durability gate names db, web and worker; §15 step 8 kills only two. The Dockerfile + runs puma directly rather than `bin/rails server` specifically so a stale + tmp/pids/server.pid cannot block a restart after an ungraceful kill. That claim is + otherwise unverified. + +PREREQUISITE + + GITHUB_MODE=fixture docker compose up --build -d +USAGE + exit 2 +fi + +# --------------------------------------------------------------------------------------- +# Plumbing +# --------------------------------------------------------------------------------------- + +# Every psql call in this file goes through one of these two functions, and both hard-code a +# _development database name. There is deliberately no helper that takes a database +# argument: §16 gates that the test databases are never touched by anything but the suite, +# and the cheapest way to keep that true is to make the wrong database unspellable here. +psql_dev() { + docker compose exec -T db psql -U postgres -d "$DEV_DB" -tAc "$1" | tr -d '[:space:]' +} + +psql_queue_dev() { + docker compose exec -T db psql -U postgres -d "$DEV_QUEUE_DB" -tAc "$1" | tr -d '[:space:]' +} + +# Exactly one id, always. `docker compose ps -q` lists running containers only, and every +# measurement here is taken across a stop — but `--all` can return a recreated container +# alongside the one it replaced, and two ids would make every `docker inspect` below fail. So: +# prefer the running container, fall back to the most recent stopped one. +container_id() { + local id + id="$(docker compose ps -q "$1" 2>/dev/null | head -1)" + [ -n "$id" ] || id="$(docker compose ps -aq "$1" 2>/dev/null | head -1)" + + printf '%s' "$id" +} + +container_name() { + docker inspect -f '{{.Name}}' "$(container_id "$1")" | sed 's|^/||' +} + +started_at() { + docker inspect -f '{{.State.StartedAt}}' "$(container_id "$1")" +} + +restart_count() { + docker inspect -f '{{.RestartCount}}' "$(container_id "$1")" +} + +running() { + [ "$(docker inspect -f '{{.State.Running}}' "$(container_id "$1")")" = "true" ] +} + +health_status() { + docker inspect -f '{{if .State.Health}}{{.State.Health.Status}}{{else}}none{{end}}' "$(container_id "$1")" +} + +# Bounded, and never a bare sleep: if a container stops coming back, the verification has to +# fail with the thing it was waiting for rather than hang until someone notices. +wait_for() { + local description="$1" timeout="$2" + shift 2 + local deadline + deadline=$(( $(date +%s) + timeout )) + + until "$@" >/dev/null 2>&1; do + if [ "$(date +%s)" -ge "$deadline" ]; then + echo "timed out after ${timeout}s waiting for: ${description}" >&2 + return 1 + fi + sleep 1 + done +} + +restarted_since() { + running "$1" && [ "$(started_at "$1")" != "$2" ] +} + +db_healthy() { + [ "$(health_status db)" = "healthy" ] +} + +ready() { + curl --silent --show-error --fail -o /dev/null "$READY_URL" +} + +live() { + curl --silent --show-error --fail -o /dev/null "$LIVE_URL" +} + +push_events() { psql_dev "SELECT COUNT(*) FROM push_events;"; } +actors() { psql_dev "SELECT COUNT(*) FROM github_actors;"; } +repositories() { psql_dev "SELECT COUNT(*) FROM github_repositories;"; } +quarantined() { psql_dev "SELECT COUNT(*) FROM quarantined_events;"; } +occurrences() { psql_dev "SELECT COALESCE(SUM(occurrence_count), 0) FROM quarantined_events;"; } +runs() { psql_dev "SELECT COUNT(*) FROM ingestion_runs;"; } +queue_jobs() { psql_queue_dev "SELECT COUNT(*) FROM solid_queue_jobs;"; } + +count_row() { + printf '| %-24s | %s | %s | %s | %s | %s |\n' "$1" "$(push_events)" "$(actors)" \ + "$(repositories)" "$(quarantined)" "$(occurrences)" +} + +count_header() { + printf '| %-24s | push_events | actors | repositories | quarantined | occurrences |\n' "measurement" + printf '| %-24s | --- | --- | --- | --- | --- |\n' "------------------------" +} + +heading() { + echo + echo "## $1" + echo +} + +# A verification that prints "MISMATCH" and exits 0 is a verification nobody will notice +# failing. Every check below records its verdict here, the transcript carries a summary, and +# the process exits non-zero if anything failed — so a committed transcript and a green exit +# code cannot disagree about what happened. +FAILURES=0 + +check() { + local description="$1" expected="$2" actual="$3" + + if [ "$expected" = "$actual" ]; then + echo "- PASS — ${description}" + else + FAILURES=$((FAILURES + 1)) + echo "- **FAIL** — ${description}: expected \`${expected}\`, got \`${actual}\`" + fi +} + +# Mechanical, for the reason script/probe_304.sh states about its own transcript: this one is +# committed, and a development database that has ever polled live GitHub holds real third-party +# logins, repository names and avatar URLs embedding numeric user ids. None of that is needed +# by any finding here. +# +# The corpus-miss message is redacted in its payload only. "the corpus defines no response for +# " still proves fixture mode failed closed, which is the whole point of quoting it, +# while the account name it names is somebody's. +redact() { + sed -E \ + -e 's#(defines no response for )".*"#\1""#g' \ + -e 's#("login":")[^"]*#\1#g' \ + -e 's#("display_login":")[^"]*#\1#g' \ + -e 's#("full_name":")[^"]*#\1#g' \ + -e 's#("avatar_url":")[^"]*#\1#g' \ + -e 's#("api_url":")[^"]*#\1#g' +} + +# --------------------------------------------------------------------------------------- +# preflight +# --------------------------------------------------------------------------------------- + +preflight() { + local service + + for service in $LONG_RUNNING; do + if [ -z "$(container_id "$service")" ] || ! running "$service"; then + echo "refusing: the ${service} container is not running." >&2 + echo " start the stack first: GITHUB_MODE=fixture docker compose up --build -d" >&2 + exit 2 + fi + done + + # The single most important guard. A live worker polls api.github.com every 60 seconds, + # so rows appear between the two measurements §15 compares and "the count is unchanged" + # becomes flaky rather than false. It also spends this IP's unauthenticated quota, and it + # puts third-party logins, avatar URLs embedding numeric user ids, and repository names + # into `docker compose logs worker` — which this script then prints into a transcript + # somebody commits. + local mode + mode="$(docker compose exec -T worker printenv GITHUB_MODE | tr -d '[:space:]')" + + if [ "$mode" != "fixture" ]; then + echo "refusing: the worker is running in GITHUB_MODE=${mode:-unset}, not fixture." >&2 + echo " restart the stack offline: GITHUB_MODE=fixture docker compose up --build -d" >&2 + exit 2 + fi + + # The shared compose anchor reads RAILS_ENV: ${RAILS_ENV:-development}, so a reviewer with + # RAILS_ENV=test exported gets `docker compose run --rm ingest` writing into the *test* + # databases — every documented count wrong, and the §16 isolation gate broken by the very + # script that checks it. + if [ -n "${RAILS_ENV:-}" ] && [ "${RAILS_ENV}" != "development" ]; then + echo "refusing: RAILS_ENV=${RAILS_ENV} is exported in this shell." >&2 + echo " the compose anchor would forward it, and the one-shots would write to the wrong databases." >&2 + exit 2 + fi + + # §15 step 8's commands are copy-pasteable literals. If `name:` ever changes, they stop + # working and the plan silently documents something that does not exist. + for service in $LONG_RUNNING; do + local actual expected + actual="$(container_name "$service")" + expected="${PROJECT}-${service}-1" + + if [ "$actual" != "$expected" ]; then + echo "refusing: ${service} is named ${actual}, not ${expected}." >&2 + echo " IMPLEMENTATION_PLAN.md §15 step 8 names containers literally; COMPOSE_PROJECT_NAME breaks it." >&2 + exit 2 + fi + done + + VOLUME_CREATED_AT="$(docker volume inspect -f '{{.CreatedAt}}' "${PROJECT}_pgdata")" + BASELINE_PUSH_EVENTS="$(push_events)" + + if [ "$BASELINE_PUSH_EVENTS" = "0" ]; then + MODE="absolute" + else + MODE="delta" + fi +} + +# --------------------------------------------------------------------------------------- +# phases +# --------------------------------------------------------------------------------------- + +phase_baseline() { + heading "Baseline" + + echo '```' + GITHUB_MODE=fixture docker compose run --rm ingest 2>&1 | redact || true + echo '```' + echo + + echo '```' + GITHUB_MODE=fixture docker compose run --rm enrich --limit 6 2>&1 | redact || true + echo '```' + echo + + # Expected, and worth keeping in the transcript rather than engineering around: a + # development database that has previously polled live GitHub holds actors and repositories + # whose api_urls are real. Fixture mode has no entry for them, so the cycle refuses with a + # corpus gap and exit 2 instead of quietly reaching api.github.com. That is §6's fail-closed + # rule holding in the running stack, which no unit test can show. + echo "A corpus gap above is not a fault. It means this development database holds entities" + echo "from an earlier live run, and fixture mode refused to fetch them rather than falling" + echo "back to the network — exit 2, \"refused to run\", per §9's exit-code contract." + echo + + if [ "$MODE" = "absolute" ]; then + echo "The development database was empty at the start of this run, so the counts below are" + echo "the README's documented absolutes." + else + echo "The development database already held ${BASELINE_PUSH_EVENTS} push events at the start of this" + echo "run, so the counts below are read as deltas. The README's documented absolutes" + echo "(4 / 3 / 3 / 3 / 3) apply only to a stack started from an empty volume." + fi + echo + + count_header + count_row "baseline" +} + +# §15 step 8's literal command, and what it actually does. +# +# `docker kill` is an API stop: the daemon marks the container manually stopped, so +# `unless-stopped` deliberately does NOT bring it back. It is still worth running, because it +# is the command the plan documents and a reviewer will type — but on its own it demonstrates +# the opposite of §16's durability gate. Reported honestly rather than quietly replaced. +api_kill_observation() { + local service="$1" + local before_restarts + before_restarts="$(restart_count "$service")" + + echo "\$ docker kill ${PROJECT}-${service}-1" + docker kill "${PROJECT}-${service}-1" >/dev/null + sleep 10 + echo + + echo "\$ docker compose ps" + echo '```' + docker compose ps + echo '```' + echo + + local running after_restarts + running="$(docker inspect -f '{{.State.Running}}' "$(container_id "$service")")" + after_restarts="$(restart_count "$service")" + + echo "| after \`docker kill\` | value |" + echo "| --- | --- |" + echo "| Running | ${running} |" + echo "| ExitCode | $(docker inspect -f '{{.State.ExitCode}}' "$(container_id "$service")") |" + echo "| RestartCount | ${before_restarts} -> ${after_restarts} |" + echo + + # The finding, asserted rather than narrated. If a future Docker version starts restarting + # after `docker kill`, this fails and the evidence document needs rewriting — which is + # exactly when somebody should be told. + check "docker kill leaves ${service} down, because an API stop skips the restart policy" \ + "false" "$running" + check "docker kill does not increment ${service}'s RestartCount" \ + "$before_restarts" "$after_restarts" + echo + echo "\`docker kill\` is an API stop, so the daemon records the container as manually stopped" + echo "and \`restart: unless-stopped\` does not apply. The container stays down and an operator" + echo "step is required to bring it back — which is what the next command is." + echo + + echo "\$ docker compose up -d ${service}" + docker compose up -d "$service" >/dev/null 2>&1 + echo +} + +# The crash the restart policy actually exists for: SIGKILL delivered to the container's main +# process from *outside* its PID namespace, which the daemon does not treat as a manual stop. +# +# It cannot be done from inside the container: the kernel refuses to deliver SIGKILL to a PID +# namespace's own init from within that namespace, so `docker exec … kill -9 1` is a no-op. +# A privileged --pid=host container is the smallest thing that reaches the process, and it +# runs the image this project already built rather than pulling a new one. +crash_recovery_observation() { + local service="$1" wait_description="$2" wait_timeout="$3" + shift 3 + + local pid before_started before_restarts + pid="$(docker inspect -f '{{.State.Pid}}' "$(container_id "$service")")" + before_started="$(started_at "$service")" + before_restarts="$(restart_count "$service")" + + echo "\$ docker run --rm --pid=host --privileged --user 0 ${APP_IMAGE} sh -c 'kill -9 ${pid}'" + + # --user 0 is load-bearing, not belt and braces. The app image declares a non-root USER, and + # a helper running as that user can signal the worker and web processes (same uid) but not + # postgres, which runs as its own user inside the db container — `kill` answers "Operation + # not permitted" and only the database phase fails, which is a confusing way to find out. + if ! docker run --rm --pid=host --privileged --user 0 "$APP_IMAGE" sh -c "kill -9 ${pid}" >/dev/null 2>&1; then + echo + echo "The crash-kill helper exited non-zero. The observation below is still taken, but" + echo "treat it as inconclusive rather than as evidence the policy worked." + fi + echo + + wait_for "${service} to be restarted by its policy" 120 restarted_since "$service" "$before_started" + wait_for "$wait_description" "$wait_timeout" "$@" + + local running after_restarts + running="$(docker inspect -f '{{.State.Running}}' "$(container_id "$service")")" + after_restarts="$(restart_count "$service")" + + echo "| after a process crash | value |" + echo "| --- | --- |" + echo "| Running | ${running} |" + echo "| RestartCount | ${before_restarts} -> ${after_restarts} |" + echo "| StartedAt | ${before_started} -> $(started_at "$service") |" + echo + + check "${service} was restarted by its policy after a process crash" "true" "$running" + check "${service}'s RestartCount incremented" \ + "$((before_restarts + 1))" "$after_restarts" + echo + echo "Docker restarted \`${service}\` on its own. No operator step." + echo +} + +phase_kill_worker() { + heading "Worker kill (§15 step 8)" + + local before + before="$(push_events)" + echo "Count before the kill: push_events = ${before}" + echo + + echo "### Part 1 — the command §15 documents" + echo + api_kill_observation worker + wait_for "the worker container to be running again" 60 running worker + + echo "### Part 2 — a process crash, which is what the policy is for" + echo + crash_recovery_observation worker "the worker container to be running again" 60 running worker + + echo "\$ docker compose logs worker --since 2m" + echo '```' + docker compose logs worker --since 2m --no-log-prefix 2>/dev/null | tail -20 | redact + echo '```' + echo + + echo "Count after recovery: push_events = $(push_events)" +} + +phase_kill_db() { + heading "Database kill (§15 step 8)" + + local before + before="$(push_events)" + echo "Count before the kill: push_events = ${before}" + echo + + echo "### Part 1 — the command §15 documents" + echo + api_kill_observation db + wait_for "the database to report healthy again" 180 db_healthy + wait_for "/health/ready to return 200 once the database is back" 180 ready + + echo "### Part 2 — a process crash, which is what the policy is for" + echo + crash_recovery_observation db "the database to report healthy again" 180 db_healthy + wait_for "/health/ready to return 200 once the database is back" 180 ready + + local after + after="$(push_events)" + echo "Count after recovery: push_events = ${after}" + echo + + check "push_events is unchanged across two SIGKILLs of the database" "$before" "$after" + echo + echo "PostgreSQL replayed its WAL onto the same named volume, which is §15 step 8's actual" + echo "question." +} + +phase_kill_web() { + heading "Web kill (beyond §15's list — verifies the Dockerfile's pid-file claim)" + + echo "§16's durability gate names db, web and worker; §15 step 8 kills only two. The" + echo "Dockerfile runs puma directly rather than \`bin/rails server\` so that a stale" + echo "tmp/pids/server.pid left by an ungraceful kill cannot block the restart" + echo "\`unless-stopped\` promises — and a crash is the only thing that exercises it." + echo + + echo "### Part 1 — the command §15 documents" + echo + api_kill_observation web + wait_for "/health/ready to return 200 again" 180 ready + + echo "### Part 2 — a process crash, which is what the policy is for" + echo + crash_recovery_observation web "/health/ready to return 200 from the restarted container" 180 ready + + echo "\`/health/live\` and \`/health/ready\` both answer again after an uncooperative kill, so no" + echo "pid file survived to block the restart." +} + +phase_restart() { + heading "Normal restart (§15 step 9)" + + local before started elapsed + before="$(push_events)" + + echo "\$ docker compose restart" + started="$(date +%s)" + echo '```' + docker compose restart + echo '```' + elapsed=$(( $(date +%s) - started )) + echo + echo "Took ${elapsed}s. The worker's \`stop_grace_period: 30s\` is a ceiling, not a duration:" + echo "Solid Queue's supervisor acknowledges SIGTERM and exits well inside it whenever no" + echo "GitHub request is in flight, and in fixture mode none ever is for long." + echo + + wait_for "/health/ready to return 200 after the restart" 120 ready + + echo "push_events before: ${before}, after: $(push_events)" +} + +phase_test_isolation() { + heading "Test isolation (§16's reviewer-experience gate)" + + echo "§16 requires that \`docker compose run --rm test\` never touches the development" + echo "databases (app or queue) and never triggers the development \`setup\` service." + echo "spec/docker_compose_spec.rb asserts the declarations; this measures the behaviour." + echo + + # The worker has to be stopped for the duration, and the first version of this phase did not + # do that — which made the measurement meaningless and the transcript wrong. Continuous + # polling is the whole point of the worker: it ingests a fixture page every cadence and + # enqueues from it, so `push_events` and `solid_queue_jobs` both climb *while the suite + # runs* whether or not the suite touches them. The earlier run recorded 263 -> 353 and + # 56 -> 62 and still printed that the gate held. Stopping the worker removes the only other + # writer, so a difference here can mean nothing except the suite. + echo "\$ docker compose stop worker # the only other writer to these databases" + docker compose stop worker >/dev/null 2>&1 + sleep 3 + echo + + local before_primary before_queue before_setup + before_primary="$(push_events)" + before_queue="$(queue_jobs)" + before_setup="$(docker inspect -f '{{.State.FinishedAt}}' "$(container_id setup)" 2>/dev/null || echo "absent")" + + echo '```' + docker compose run --rm test 2>&1 | tail -8 + echo '```' + echo + + local after_primary after_queue after_setup + after_primary="$(push_events)" + after_queue="$(queue_jobs)" + after_setup="$(docker inspect -f '{{.State.FinishedAt}}' "$(container_id setup)" 2>/dev/null || echo "absent")" + + echo "\$ docker compose start worker" + docker compose start worker >/dev/null 2>&1 + echo + + echo "| observable | before | after |" + echo "| --- | --- | --- |" + echo "| development push_events | ${before_primary} | ${after_primary} |" + echo "| development solid_queue_jobs | ${before_queue} | ${after_queue} |" + echo "| setup container FinishedAt | ${before_setup} | ${after_setup} |" + echo + + check "the suite left development push_events untouched" "$before_primary" "$after_primary" + check "the suite left the development queue untouched" "$before_queue" "$after_queue" + check "the suite did not trigger the development setup service" "$before_setup" "$after_setup" +} + +phase_scenarios() { + heading "Deterministic fixture scenarios (§15 step 10)" + + echo "The full nine-scenario matrix is documented in the README; this phase runs the two" + echo "the transcript can prove without waiting. Every ingestion obeys GitHub's" + echo "\`X-Poll-Interval\` floor of 60s, which \`--force\` deliberately does not bypass, so" + echo "back-to-back poll scenarios are a README exercise rather than a script phase. The" + echo "redirect scenarios go through \`bin/enrich\`, which has no cadence." + echo + + # Selection has to be forced, and the first version of this phase did not force it — so both + # scenarios died on a corpus gap while `|| true` swallowed the exit code and the transcript + # claimed they had run. §10 picks the newest eligible candidate, and on a development + # database that has ever polled live GitHub the newest repository is a real one whose + # api_url the corpus has never heard of. + # + # So the corpus's own repository is made the unambiguous newest candidate first. It is the + # row both scenarios are authored against (bodies/repos/octocat_hello-world.json carries the + # matching id, which RepositoryDocument.parse checks), and the worker is stopped for the + # duration so nothing else can move last_seen_at underneath the selection. + echo "\$ docker compose stop worker # so nothing re-orders the candidate set mid-scenario" + docker compose stop worker >/dev/null 2>&1 + sleep 3 + echo + + redirect_scenario "redirecting_repository" "complete" \ + "a validated redirect is followed and the entity completes" + redirect_scenario "hostile_redirect" "permanent_failure" \ + "an off-host redirect is refused by the URL policy" + + echo "\$ docker compose start worker" + docker compose start worker >/dev/null 2>&1 + echo + + count_header + count_row "after scenarios" +} + +# One redirect scenario, end to end, with a verdict rather than a hope. +redirect_scenario() { + local scenario="$1" expected_status="$2" description="$3" + + echo "### ${scenario} — ${description}" + echo + + # Pending, unleased, never fetched, and newer than every other candidate. now() + 1s rather + # than now() because the corpus repository may already carry this instant from a fixture + # poll, and a tie is broken by id, which is not ours to choose. + psql_dev "UPDATE github_repositories + SET enrichment_status = 'pending', next_retry_at = NULL, fetched_at = NULL, + last_error = NULL, enrichment_attempts = 0, + last_seen_at = now() + interval '1 second' + WHERE github_id = ${CORPUS_REPOSITORY_ID};" >/dev/null + + local seeded + seeded="$(psql_dev "SELECT count(*) FROM github_repositories WHERE github_id = ${CORPUS_REPOSITORY_ID};")" + if [ "$seeded" != "1" ]; then + FAILURES=$((FAILURES + 1)) + echo "- **FAIL** — the corpus repository ${CORPUS_REPOSITORY_ID} is not in this database, so" + echo " ${scenario} cannot be exercised. Run \`docker compose run --rm ingest\` in fixture" + echo " mode first." + echo + return + fi + + echo '```' + GITHUB_MODE=fixture GITHUB_FIXTURE_SCENARIO="$scenario" \ + docker compose run --rm enrich --limit 1 --class repository 2>&1 | redact || true + echo '```' + echo + + local actual + actual="$(psql_dev "SELECT enrichment_status FROM github_repositories WHERE github_id = ${CORPUS_REPOSITORY_ID};")" + + check "${scenario} left the corpus repository ${expected_status}" "$expected_status" "$actual" + echo +} + +phase_rate_limit() { + heading "Rate-limit scenario (opt-in)" + + echo "\`rate_limited\` writes a real one-hour \`global_blocked_until\`. It is never part of the" + echo "default run, because every later phase would report a deferral. Cleanup runs immediately." + echo + + echo '```' + GITHUB_MODE=fixture GITHUB_FIXTURE_SCENARIO=rate_limited docker compose run --rm ingest || true + echo '```' + echo + + echo "Budget row after the scenario:" + echo '```' + psql_dev "SELECT window_status || ' blocked_until=' || COALESCE(global_blocked_until::text, 'none') FROM github_api_budget;" + echo '```' + echo + + phase_cleanup +} + +phase_cleanup() { + heading "Cleanup" + + echo "The same SQL the README publishes, so a reviewer who interrupts a run has one place" + echo "to look (\`--phase=cleanup\`)." + echo + + echo '```sql' + echo "UPDATE github_api_budget SET global_blocked_until = NULL, window_status = 'active';" + echo "UPDATE event_sources SET status = 'idle', consecutive_failures = 0," + echo " retry_not_before_at = NULL WHERE status = 'failed';" + echo '```' + echo + + psql_dev "UPDATE github_api_budget SET global_blocked_until = NULL, window_status = 'active' WHERE window_status = 'globally_blocked' OR global_blocked_until IS NOT NULL;" >/dev/null || true + psql_dev "UPDATE event_sources SET status = 'idle', consecutive_failures = 0, retry_not_before_at = NULL WHERE status = 'failed';" >/dev/null || true + + echo "Budget and source state after cleanup:" + echo '```' + psql_dev "SELECT 'budget: ' || window_status || ' blocked_until=' || COALESCE(global_blocked_until::text, 'none') FROM github_api_budget;" + psql_dev "SELECT 'source: ' || source_type || ' status=' || status || ' enabled=' || enabled FROM event_sources;" + echo '```' +} + +phase_volume_check() { + heading "Volume identity" + + local now + now="$(docker volume inspect -f '{{.CreatedAt}}' "${PROJECT}_pgdata")" + + echo "\`${PROJECT}_pgdata\` CreatedAt at preflight: ${VOLUME_CREATED_AT}" + echo "\`${PROJECT}_pgdata\` CreatedAt now: ${now}" + echo + + check "the pgdata volume is the same volume it was at preflight" "$VOLUME_CREATED_AT" "$now" + echo + echo "Identical means the records above *survived* the kills rather than being recreated" + echo "into a fresh volume, which is what makes the counts evidence rather than coincidence." +} + +# --------------------------------------------------------------------------------------- +# Run +# --------------------------------------------------------------------------------------- + +preflight + +cat <
+ +\`\`\`text +Verification date: $(date -u +%Y-%m-%d) +Compose project: ${PROJECT} +Git revision: $(git rev-parse HEAD 2>/dev/null || echo "unknown") +Docker version: $(docker version -f '{{.Server.Version}}') +Compose version: $(docker compose version --short) +Host: $(uname -srm) +Worker mode: fixture (enforced by preflight) +Count mode: ${MODE} +Captured by: script/verify_recovery.sh +Redaction: login, display_login, full_name, api_url, avatar_url and the corpus-miss + payload are replaced in place; names kept, values removed +\`\`\` +HEADER + +case "$PHASE" in + all) + phase_baseline + phase_kill_worker + phase_kill_db + phase_kill_web + phase_restart + phase_test_isolation + phase_scenarios + phase_volume_check + ;; + baseline) phase_baseline ;; + kill-worker) phase_kill_worker ;; + kill-db) phase_kill_db ;; + kill-web) phase_kill_web ;; + restart) phase_restart ;; + test-isolation) phase_test_isolation ;; + scenarios) phase_scenarios ;; + rate-limit) phase_rate_limit ;; + cleanup) phase_cleanup ;; + volume-check) phase_volume_check ;; + *) + echo "unknown phase: ${PHASE}" >&2 + exit 2 + ;; +esac + +heading "Verdict" + +if [ "$FAILURES" -eq 0 ]; then + echo "Every check above passed." +else + echo "**${FAILURES} check(s) failed.** This transcript records a failed verification and must" + echo "not be committed as evidence that the gate holds." +fi + +echo +echo "Paste the above into docs/evidence/\$(date -u +%Y-%m-%d)-container-kill-recovery.md and" +echo "write the finding and the \"What this does not show\" section by hand." + +# The exit code and the transcript have to agree. A verification that prints FAIL and exits 0 +# is one somebody will paste into docs/evidence/ without reading. +exit $(( FAILURES > 0 ? 1 : 0 )) diff --git a/spec/docker_compose_spec.rb b/spec/docker_compose_spec.rb index 4666ff2..3cf2afd 100644 --- a/spec/docker_compose_spec.rb +++ b/spec/docker_compose_spec.rb @@ -167,4 +167,238 @@ def unprofiled expect(enrich.fetch("environment")).to eq(services.fetch("ingest").fetch("environment")) end end + + # Everything below is what §16's durability gate — "Docker restart policies recover crashed + # db/web/worker containers automatically (verified by container kills)" — actually rests on. + # script/verify_recovery.sh proves the runtime behaviour once, on one host, on one date. + # These examples prove the declarations that behaviour comes from, on every push, and they + # are the reason a compose edit cannot silently invalidate the committed transcript. + describe "the db service" do + let(:db) { services.fetch("db") } + + it "pins the PostgreSQL major version the schema was written against" do + expect(db.fetch("image")).to eq("postgres:16") + end + + it "restarts after a crash, because the transcript's db kill depends on it" do + expect(db.fetch("restart")).to eq("unless-stopped") + end + + # §8's "PostgreSQL will use a named Docker volume", and the distinction is the whole + # point: an anonymous volume or a bind mount also survives `docker kill` and `docker + # compose restart`, so a count check after either would pass. It is `docker compose down` + # and recreation that tells them apart, and only a *named* volume survives that. + it "keeps its data in a named volume, not an anonymous one or a bind mount" do + expect(db.fetch("volumes")).to eq([ "pgdata:/var/lib/postgresql/data" ]) + expect(compose.fetch("volumes").keys).to eq([ "pgdata" ]) + end + + # -h 127.0.0.1 is load-bearing and easy to "simplify" away. postgres's first-boot initdb + # runs a temporary server that answers pg_isready on the unix socket only, so a socket + # check reports healthy before the real server accepts TCP — and every + # `service_healthy` gate in this file would then release too early. + it "probes over TCP, so first-boot initdb cannot report healthy early" do + expect(db.dig("healthcheck", "test")).to eq([ "CMD-SHELL", "pg_isready -U postgres -h 127.0.0.1" ]) + end + + # Pinned because `setup`, `web` and `worker` all gate on this probe: the timings decide + # how long a recovering stack waits before it gives up on the database. + it "declares the timings every service_healthy gate derives from" do + expect(db.fetch("healthcheck")).to include( + "interval" => "5s", "timeout" => "3s", "retries" => 10, "start_period" => "10s" + ) + end + end + + describe "the web service" do + let(:web) { services.fetch("web") } + + # The sharpest assertion in this file. `bin/rails server` writes tmp/pids/server.pid, and + # as PID 1 in a container a stale pid file left by an ungraceful kill blocks every + # subsequent boot — which defeats `unless-stopped` precisely in the case it exists for. + # The Dockerfile carries the same note against its CMD. A future "simplification" back to + # `bin/rails server` has to fail here, because the symptom otherwise appears only after a + # crash, in a container that will not come back. + it "runs puma directly, so no pid file can survive a kill and block the restart" do + expect(web.fetch("command")).to eq([ "bundle", "exec", "puma", "-C", "config/puma.rb" ]) + expect(web).not_to have_key("entrypoint") + expect(web.fetch("command")).not_to include("rails", "server") + end + + it "restarts after a crash" do + expect(web.fetch("restart")).to eq("unless-stopped") + end + + it "publishes the port the README's health checks use" do + expect(web.fetch("ports")).to eq([ "3000:3000" ]) + end + + # Liveness, never readiness. A readiness-based container healthcheck would mark web + # unhealthy for as long as a killed db took to come back — so Docker would report the + # symptom of the db kill on the wrong service, and §15 step 8's `docker compose ps` + # would read as though web had also failed. /health/ready is the observable that flips; + # the container probe deliberately is not. + it "probes liveness, so a db kill is not misreported as a web failure" do + expect(web.dig("healthcheck", "test")).to eq( + [ "CMD", "curl", "-fsS", "http://localhost:3000/health/live" ] + ) + end + + it "waits for the schema both databases need" do + expect(web.dig("depends_on", "db", "condition")).to eq("service_healthy") + expect(web.dig("depends_on", "setup", "condition")).to eq("service_completed_successfully") + end + end + + describe "the setup service" do + let(:setup) { services.fetch("setup") } + + it "prepares both databases declared in config/database.yml" do + expect(setup.fetch("command")).to eq([ "bin/rails", "db:prepare" ]) + end + + # A `setup` that restarted would run db:prepare again every time the stack recovered, + # racing the web and worker containers it exists to unblock. + it "never restarts, so recovery cannot re-run a migration step" do + expect(setup.fetch("restart")).to eq("no") + end + + it "runs on a plain up, unlike the tools-profiled one-shots" do + expect(setup).not_to have_key("profiles") + end + end + + # §16's reviewer-experience gate: "docker compose run --rm test never touches the + # development databases (app or queue) and never triggers the development setup service." + # Nothing asserted it before this PR, in a file or at runtime. + describe "the test service" do + let(:test) { services.fetch("test") } + + # Literal, never the anchor's ${RAILS_ENV:-development}. The suite would probably still + # land on the test databases through spec/rails_helper.rb's RAILS_ENV default — but a + # §16 gate must not depend on that reasoning holding somewhere else. + it "pins the test environment rather than inheriting the development default" do + expect(test.fetch("environment").fetch("RAILS_ENV")).to eq("test") + end + + # Pinned so `GITHUB_MODE=fixture docker compose run --rm test` cannot quietly run a + # different suite than CI does. + it "pins live mode, so a reviewer's fixture-mode shell cannot change what CI ran" do + expect(test.fetch("environment").fetch("GITHUB_MODE")).to eq("live") + end + + # The gate, as one assertion: adding `setup` here would run db:prepare against the + # *development* databases as a side effect of running the test suite. + it "depends on db alone, never on the development setup service" do + expect(test.fetch("depends_on").keys).to eq([ "db" ]) + expect(test.dig("depends_on", "db", "condition")).to eq("service_healthy") + end + + # Asserted structurally rather than as an exact command. What §16's gate needs is that the + # *test* databases are prepared before anything runs and that the development preparer is + # never invoked — not that the command has a particular number of steps. Freezing the + # literal string makes every later addition to the pipeline a false failure, which is how + # this example broke once already: PR 9 appended `bundle exec rspec spec/stress`, and an + # equality assertion written before it turned a green branch red on merge. + it "prepares its own isolated databases before running anything" do + command = test.fetch("command") + script = command.last + + expect(command.first(2)).to eq([ "bash", "-c" ]) + expect(script).to start_with("bin/rails db:test:prepare") + expect(script).to include("bundle exec rspec") + end + + # `db:prepare` is the development preparer; `db:test:prepare` does not contain it as a + # substring, so this is an exact statement of "the test service never prepares the + # development databases". + it "never invokes the development database preparer" do + expect(test.fetch("command").last).not_to include("db:prepare") + end + + it "never restarts" do + expect(test.fetch("restart")).to eq("no") + end + + # Catches both drift directions in one line: a variable added to the shared anchor that + # `test` should have inherited, and a third override slipped in beside the two intended + # ones. + it "differs from the one-shots by exactly the two overrides it declares" do + expect(test.fetch("environment")).to eq( + services.fetch("ingest").fetch("environment") + .merge("RAILS_ENV" => "test", "GITHUB_MODE" => "live") + ) + end + end + + describe "restart policies, as a set" do + # Stated as a partition rather than service by service, so a service added later cannot + # land in neither list unnoticed. + it "declares unless-stopped on exactly the long-running services" do + always_on = services.select { |_name, service| service["restart"] == "unless-stopped" }.keys + + expect(always_on).to match_array(%w[db web worker]) + end + + it "declares no on every one-shot" do + one_shots = services.select { |_name, service| service["restart"] == "no" }.keys + + expect(one_shots).to match_array(%w[setup ingest enrich test]) + end + + # The real guard. Docker's default policy is `no`, so an *omitted* restart key on a + # long-running service loses crash recovery silently — there is no error, no warning, + # and the container simply stays dead the first time it is killed. + it "leaves the policy implicit nowhere, because Docker's default would lose recovery" do + missing = services.reject { |_name, service| service.key?("restart") }.keys + + expect(missing).to be_empty + end + end + + # A killed worker restarts on whatever `github-push-ingestor-app` currently is. If one + # service built a different tag, the container that came back would not be the one the + # recovery transcript was produced against. + describe "the shared application image" do + let(:app_services) { %w[setup web worker ingest enrich test] } + + it "builds one image and runs every application service from it" do + app_services.each do |name| + expect(services.fetch(name).fetch("build")).to eq(".") + expect(services.fetch(name).fetch("image")).to eq("github-push-ingestor-app") + end + end + end + + # The same rule spec/network_boundary_spec.rb applies to the live rate-limit probe under + # script/, for the same reason: script/verify_recovery.sh kills containers and writes to the + # *development* databases, so "CI never runs it" has to be a red test rather than a promise. + # + # That spec greps every file under spec/ for the probe's name, so this comment names it + # obliquely on purpose — spelling it out here would turn its guard red. + # + # It lives here rather than beside the probe guard because that spec's subject is the + # network boundary, and this script makes no network calls at all — fixture mode is one of + # its preflight requirements. + describe "script/verify_recovery.sh" do + it "exists and is executable, because the README tells a reviewer to run it" do + script = Rails.root.join("script/verify_recovery.sh") + + expect(script).to exist + expect(script).to be_executable + end + + it "is referenced by no workflow, no compose service, and no CI entry point" do + reachable = Dir[Rails.root.join(".github/workflows/*.yml")] + + [ Rails.root.join("config/ci.rb").to_s, + Rails.root.join("bin/ci").to_s, + Rails.root.join("docker-compose.yml").to_s ] + + referencing = reachable.select do |path| + File.file?(path) && File.read(path).include?("verify_recovery") + end + + expect(referencing).to be_empty + end + end end diff --git a/spec/recovery/concurrent_write_spec.rb b/spec/recovery/concurrent_write_spec.rb new file mode 100644 index 0000000..34552e7 --- /dev/null +++ b/spec/recovery/concurrent_write_spec.rb @@ -0,0 +1,238 @@ +require "rails_helper" + +# §9's fourth multi-poller protection — "unique event constraints as final duplicate +# protection" — under genuine concurrency. +# +# Every existing duplicate test (page_writer_spec.rb, ingestion_runner_spec.rb) replays a page +# sequentially in one session, which exercises the transaction's own snapshot rather than the +# unique index. The interesting case is the one the index exists for: another poller committed +# the row microseconds ago, from a session this one has never seen, and the write has to absorb +# it under READ COMMITTED. +# +# This is the second file in the suite to turn transactional fixtures off, and the reason is +# the same one spec/services/github/budget_ledger_durability_spec.rb gives: the property under +# test is *what one session can see of another's commit*, and a fixture transaction hides +# exactly that. It also cannot be worked around with an `around` hook — an `around`'s ensure +# still runs inside the fixture transaction, so its cleanup would be rolled back with +# everything else and the committed rows would survive into the next example. +# +# The price is that this file owns its own cleanup, and under config.order = :random that +# cleanup is load-bearing: a leftover row would break unrelated files' create_actor with a +# uniqueness violation, and a stranded lock_timeout would give every later example on this +# connection a 250ms deadline it never asked for. Hence around + ensure rather than an after +# hook — it has to run even when the example raises — and deletion in reverse insertion order, +# which the schema requires: push_events carries real foreign keys to github_actors.github_id +# and github_repositories.github_id. +RSpec.describe "a page racing another poller's commit", type: :integration do + self.use_transactional_tests = false + + ACTOR_ID = IngestionHelpers::ACTOR_GITHUB_ID + REPOSITORY_ID = IngestionHelpers::REPOSITORY_GITHUB_ID + OTHER_ACTOR_ID = 9_100_001 + OTHER_REPOSITORY_ID = 9_200_001 + EVENT_ID = "58000000001".freeze + OTHER_EVENT_ID = "58000009001".freeze + + let(:writer) { Github::Ingestion::PageWriter.new(clock: -> { frozen_time }) } + let(:stamp) { frozen_time.iso8601 } + + around do |example| + example.run + ensure + # The second session may still be inside its FOR UPDATE transaction if an example failed + # before its own rollback ran, and nothing can delete the row it holds until it is out. + begin + second_session.exec("ROLLBACK") + rescue StandardError + nil + end + close_second_session + + connection = ActiveRecord::Base.connection + # Session-level, not SET LOCAL: the only transaction it could have been local to belongs + # to PageWriter. With no fixture transaction to revert it, this RESET is the only thing + # that stops a 250ms lock timeout riding the pooled connection into the rest of the run. + connection.execute("RESET lock_timeout") + connection.execute( + "DELETE FROM push_events WHERE github_event_id IN ('#{EVENT_ID}', '#{OTHER_EVENT_ID}')" + ) + connection.execute("DELETE FROM github_actors WHERE github_id IN (#{ACTOR_ID}, #{OTHER_ACTOR_ID})") + connection.execute( + "DELETE FROM github_repositories WHERE github_id IN (#{REPOSITORY_ID}, #{OTHER_REPOSITORY_ID})" + ) + end + + # The other poller: a genuinely separate PostgreSQL session, committing before this one + # looks. Raw SQL rather than Active Record, because the pooled connection is inside the + # example's fixture transaction and anything written through it would be invisible to the + # index this file is about. + def commit_actor!(status: "pending", skipped_at: nil) + second_session.exec_params(<<~SQL, [ ACTOR_ID, "octocat", status, stamp, skipped_at ]) + INSERT INTO github_actors + (github_id, login, display_login, api_url, enrichment_status, enrichment_attempts, + last_seen_at, first_seen_at, created_at, updated_at, skipped_at) + VALUES ($1, $2, $2, 'https://api.github.com/users/octocat', $3, 0, $4, $4, $4, $4, $5) + SQL + end + + def commit_repository! + second_session.exec_params(<<~SQL, [ REPOSITORY_ID, "octocat/Hello-World", "Hello-World", stamp ]) + INSERT INTO github_repositories + (github_id, full_name, name, api_url, enrichment_status, enrichment_attempts, + last_seen_at, first_seen_at, created_at, updated_at) + VALUES ($1, $2, $3, 'https://api.github.com/repos/octocat/Hello-World', 'pending', 0, $4, $4, $4, $4) + SQL + end + + def commit_push_event! + second_session.exec_params(<<~SQL, [ EVENT_ID, REPOSITORY_ID, ACTOR_ID, sha_40, sha_64, stamp ]) + INSERT INTO push_events + (github_event_id, github_push_id, github_repository_id, github_actor_id, + ref, head_sha, before_sha, occurred_at, raw_payload, created_at, updated_at) + VALUES ($1, 27500000001, $2, $3, 'refs/heads/main', $4, $5, $6, '{"type":"PushEvent"}', $6, $6) + SQL + end + + describe "an event the other poller committed first" do + before do + commit_actor! + commit_repository! + commit_push_event! + end + + # ON CONFLICT (github_event_id) DO NOTHING RETURNING id, against a row this session never + # inserted and cannot roll back. §9's last line of defence, doing its job. + it "absorbs it as a duplicate rather than raising or double-writing" do + tally = writer.write([ well_formed_envelope ], run_id: SecureRandom.uuid) + + expect(tally.duplicates_skipped).to eq(1) + expect(tally.events_created).to eq(0) + expect(PushEvent.where(github_event_id: EVENT_ID).count).to eq(1) + end + + # The RETURNING gate holding under concurrency. Without it two pollers racing the same + # page would each register activity for the same event, and last_seen_at would report + # traffic that never happened. + it "registers no activity for the loser" do + writer.write([ well_formed_envelope ], run_id: SecureRandom.uuid) + + expect(GithubActor.find_by(github_id: ACTOR_ID).last_seen_at).to eq(frozen_time) + expect(GithubActor.find_by(github_id: ACTOR_ID).latest_event_at).to be_nil + end + end + + # §7's rule 4 — "duplicate replays may refresh identity fields but must never reactivate a + # skipped_budget entity" — where the duplicate is another session's commit rather than this + # session's own earlier write. + describe "a skipped entity whose event another poller committed first" do + before do + commit_actor!(status: "skipped_budget", skipped_at: stamp) + commit_repository! + commit_push_event! + end + + it "cannot be reactivated by losing the race" do + writer.write([ well_formed_envelope ], run_id: SecureRandom.uuid) + + expect(GithubActor.find_by(github_id: ACTOR_ID)) + .to have_attributes(enrichment_status: "skipped_budget", skipped_at: frozen_time) + end + end + + # PageWriter#persist upserts the actor before the repository, always, with the comment "so + # two concurrent pages touching the same pair cannot deadlock on the two entity rows". + # Nothing asserted it. Two pages taking the rows in the same order cannot form a cycle; two + # taking them in opposite orders can, and the symptom would be an intermittent + # ActiveRecord::Deadlocked in production and nowhere else. + # + # Asserted on the statements actually issued, and deliberately not by holding one row and + # watching the other fail to appear: both upserts share one per-envelope transaction, so a + # blocked second upsert rolls the first one back too and the observable is identical + # whichever order they run in. Statement order is the only thing that distinguishes them — + # verified by swapping the two lines in PageWriter#persist, which fails this example and + # nothing else in the suite. + describe "the order the two entity rows are taken in" do + def capture_sql + statements = [] + subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*, payload| + next if payload[:name] == "SCHEMA" || payload[:cached] + + statements << payload[:sql] + end + + yield + statements + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) + end + + it "upserts the actor before the repository, always" do + statements = capture_sql { writer.write([ well_formed_envelope ], run_id: SecureRandom.uuid) } + + actor_at = statements.index { |sql| sql.match?(/INSERT INTO "github_actors"/i) } + repository_at = statements.index { |sql| sql.match?(/INSERT INTO "github_repositories"/i) } + + expect(actor_at).not_to be_nil + expect(repository_at).not_to be_nil + expect(actor_at).to be < repository_at + end + end + + # What a contended entity row actually costs, which is a different question from the order + # the rows are taken in. + describe "when another session holds the actor row" do + before do + commit_actor! + second_session.exec("BEGIN") + second_session.exec_params("SELECT 1 FROM github_actors WHERE github_id = $1 FOR UPDATE", [ ACTOR_ID ]) + + # Converts "would block forever" into a typed, bounded failure. Without it this example + # hangs the container rather than failing, because PostgreSQL reads the default + # lock_timeout of 0 as "no timeout". + ActiveRecord::Base.connection.execute("SET lock_timeout = '250ms'") + end + + # The lock wait surfaces as an ActiveRecord::LockWaitTimeout, which is not one of + # PageWriter::FATAL_ERRORS — so it is classified as a failed envelope rather than + # terminating the batch, and §16's "malformed data does not terminate the batch" extends + # to a contended one. + it "fails that envelope rather than raising out of the page" do + tally = nil + + expect { tally = writer.write([ well_formed_envelope ], run_id: SecureRandom.uuid) } + .not_to raise_error + expect(tally.events_failed).to eq(1) + expect(tally.events_created).to eq(0) + end + + # ADR 0005's per-envelope transaction, seen from the failure side: the envelope leaves no + # half-written entity pair behind, because the repository upsert was inside the same + # transaction the timeout rolled back. + it "leaves no partial pair behind" do + writer.write([ well_formed_envelope ], run_id: SecureRandom.uuid) + + expect(GithubRepository.where(github_id: REPOSITORY_ID)).to be_empty + expect(PushEvent.where(github_event_id: EVENT_ID)).to be_empty + end + + # ADR 0005's per-envelope transaction, against a real contended row rather than the + # synthetic bad value page_writer_spec.rb uses: one envelope's failure does not discard + # the envelope beside it. + it "still persists the envelopes that do not touch the held row" do + other = well_formed_envelope( + "id" => "58000009001", + "actor" => { "id" => 9_100_001, "login" => "other", "display_login" => "other", + "url" => "https://api.github.com/users/other" }, + "repo" => { "id" => 9_200_001, "name" => "other/repo", + "url" => "https://api.github.com/repos/other/repo" }, + "payload" => { "repository_id" => 9_200_001 } + ) + + tally = writer.write([ well_formed_envelope, other ], run_id: SecureRandom.uuid) + + expect(tally.events_failed).to eq(1) + expect(tally.events_created).to eq(1) + expect(PushEvent.where(github_event_id: "58000009001")).to exist + end + end +end diff --git a/spec/recovery/crash_window_spec.rb b/spec/recovery/crash_window_spec.rb new file mode 100644 index 0000000..8dfde96 --- /dev/null +++ b/spec/recovery/crash_window_spec.rb @@ -0,0 +1,312 @@ +require "rails_helper" + +# Extension B's ninth child issue — "add Docker restart policies; test crash-window scenarios +# including container kills" — is half policy and half test. The policy shipped in PR 2 and is +# asserted as a declaration in spec/docker_compose_spec.rb; the kills themselves are +# script/verify_recovery.sh's, because nothing inside `bundle exec rspec` can kill the process +# it is running in. This file is the rest of it. +# +# A SIGKILL runs no ensure block, no rescue and no after_commit. So a crash window cannot be +# simulated by stubbing something to raise — that would exercise the very recovery path the +# crash skipped. It is expressed instead as *the durable state a kill leaves behind*, and each +# example asserts what the next process does with that state. +# +# §8 enumerates the windows this design actually has. PR 8 covered three of them +# (pending_enrichment_recovery_spec.rb, worker_crash_lease_spec.rb, +# duplicate_job_execution_spec.rb). The two below are the ones nothing reaches yet, and the +# last group composes all of them into the single restart a container kill really produces. +RSpec.describe "crash windows", type: :integration do + let(:transport) { fixture_transport } + + before { active_budget_window(now: frozen_time) } + + # --------------------------------------------------------------------------------------- + # §8: "a SIGKILL still leaves one, and that is the intended crash signal" + # --------------------------------------------------------------------------------------- + # + # IngestionRunner rescues everything it can see and finalizes the run row before re-raising, + # so `running` with a NULL completed_at is unreachable from any error the process survives — + # spec/services/github/ingestion_runner_spec.rb covers that path. It is reachable only from a + # kill, which is why it is the signal, and why nothing tested it. + describe "a run row abandoned in running" do + let!(:event_source) { fixture_event_source } + + # The crash: a run opened, and then nothing at all. + let!(:abandoned) do + Github::Ingestion::RunRecorder.new(event_source: event_source, clock: -> { frozen_time }).start! + end + + it "is exactly what a kill leaves: running, with no completion and no counters" do + expect(abandoned.reload).to have_attributes(status: "running", completed_at: nil) + expect(IngestionRun::COUNTERS.map { |counter| abandoned.public_send(counter) }).to all(eq(0)) + end + + # The source's scheduling components are written by PollState at the *end* of a run, so a + # kill costs the source no backoff and the next tick is immediately due. That is the + # intended behaviour — a crash is not evidence the source is unhealthy. + it "leaves the source's schedule untouched, so the next tick is immediately due" do + expect(event_source.reload).to have_attributes( + cadence_due_at: nil, next_poll_at: nil, last_polled_at: nil, consecutive_failures: 0 + ) + end + + it "never blocks the next poll, because nothing reads it as a claim" do + result = fixture_runner(transport: transport).call(event_source: event_source) + + expect(result).to be_completed + expect(PushEvent.count).to eq(4) + expect(IngestionRun.count).to eq(2) + end + + # There is no sweeper, and this states plainly that there should not be one: finalizing a + # row nobody observed completing would fabricate an outcome. The honest posture is to + # leave the evidence of the crash exactly as the crash left it. + it "is never resurrected or finalized by anything, which is the honest posture" do + allow(Github).to receive(:configuration).and_return(configuration_with("GITHUB_MODE" => "fixture")) + allow(Github::IngestionRunner).to receive(:new).and_call_original + allow(Github::IngestionRunner).to receive(:new).and_return(fixture_runner(transport: transport)) + + before_attributes = abandoned.reload.attributes + + PollEventSourceJob.new.perform_now + ReconcilePendingEnrichmentsJob.new.perform_now + + expect(abandoned.reload.attributes).to eq(before_attributes) + end + + # §7's "failures stay spent", across a crash. The killed process may have spent its + # reservation before dying, and there is no refund path — so the window is charged and the + # recovery poll spends a second attempt. Conservative in the safe direction: the + # alternative would be crediting a request GitHub has already counted. + it "charges the window for the request the dead process may have spent, and never refunds it" do + Github::BudgetLedger.new.reserve!(:poll, now: frozen_time) + + fixture_runner(transport: transport).call(event_source: event_source) + + expect(current_budget.poll_used).to eq(2) + end + end + + # --------------------------------------------------------------------------------------- + # The window §8's per-envelope transaction exists for + # --------------------------------------------------------------------------------------- + # + # ADR 0005: "Transactions are per envelope, not per page. PostgreSQL aborts an entire + # transaction on any failed statement, so a page-wide transaction would let one malformed + # envelope discard the events already reported as persisted beside it." + # + # Every existing duplicate test replays a *complete* page, which exercises the snapshot + # rather than the boundary. A prefix is the shape a kill actually produces, and it is the + # only thing that can tell a per-envelope transaction from a per-page one. + describe "a page interrupted between two envelopes" do + let(:page) { corpus_page("page-1.json") } + let(:writer) { Github::Ingestion::PageWriter.new(clock: -> { frozen_time }) } + + # Envelopes 0..2 are the three well-formed push events at the head of the page. The kill + # lands after them and before everything else. + def write_prefix(count = 3) + writer.write(page.first(count), run_id: SecureRandom.uuid) + end + + def replay_whole_page + Github::Ingestion::PageWriter.new(clock: -> { frozen_time + 60 }) + .write(page, run_id: SecureRandom.uuid) + end + + it "commits a prefix of the page rather than all of it or none of it" do + write_prefix + + expect(PushEvent.count).to eq(3) + expect(GithubActor.count).to eq(2) + expect(GithubRepository.count).to eq(2) + expect(QuarantinedEvent.count).to eq(0) + end + + it "persists exactly the remainder on replay, with the prefix absorbed as duplicates" do + write_prefix + tally = replay_whole_page + + expect(tally.events_created).to eq(1) + expect(tally.duplicates_skipped).to eq(3) + expect(PushEvent.count).to eq(4) + expect(GithubActor.count).to eq(3) + expect(GithubRepository.count).to eq(3) + end + + # ADR 0005's fourth mechanism, holding across a crash boundary rather than across a plain + # replay: the duplicated envelopes produce no RETURNING row, so the reactivation they + # would otherwise trigger never runs. + it "reactivates nothing the prefix already recorded" do + write_prefix + GithubActor.where(github_id: IngestionHelpers::ACTOR_GITHUB_ID) + .update_all(enrichment_status: "skipped_budget", skipped_at: frozen_time) + + replay_whole_page + + expect(GithubActor.find_by(github_id: IngestionHelpers::ACTOR_GITHUB_ID)) + .to have_attributes(enrichment_status: "skipped_budget", skipped_at: frozen_time) + end + + # The other half of the same rule, so the first is not passing merely because nothing + # reactivates anything: a genuinely new event for the same entity does. + it "still reactivates that entity for an event the crash had not yet seen" do + write_prefix + GithubActor.where(github_id: IngestionHelpers::ACTOR_GITHUB_ID) + .update_all(enrichment_status: "skipped_budget", skipped_at: frozen_time) + + writer.write([ well_formed_envelope("id" => "58000009999") ], run_id: SecureRandom.uuid) + + expect(GithubActor.find_by(github_id: IngestionHelpers::ACTOR_GITHUB_ID)) + .to have_attributes(enrichment_status: "pending", skipped_at: nil) + end + + # PageWriter#quarantine is deliberately one statement outside every transaction. A crash + # mid-page must therefore keep the quarantine rows it had already written, and the replay + # must count the second observation rather than create a second row. + it "keeps quarantine rows written before the crash, and counts the replay as a recurrence" do + writer.write(page.first(5), run_id: SecureRandom.uuid) + + expect(QuarantinedEvent.count).to eq(1) + expect(QuarantinedEvent.sole.occurrence_count).to eq(1) + + replay_whole_page + + expect(QuarantinedEvent.count).to eq(3) + expect(QuarantinedEvent.order(:id).first.occurrence_count).to eq(2) + end + end + + # --------------------------------------------------------------------------------------- + # The order a crash can interrupt finish() in + # --------------------------------------------------------------------------------------- + # + # IngestionRunner#finish writes poll state before finalizing the run row. The ordering is + # commented in the source as being about the completion *log line*, but it also decides + # which of two states a kill between the two writes can leave — and only one of them is + # safe. Observed through the statements actually issued, so nothing is stubbed and the + # assertion is about the real sequence. + describe "the order a crash can interrupt a run's completion in" do + it "writes the source's backoff before finalizing the run, never the reverse" do + statements = [] + + subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*, payload| + next if payload[:name] == "SCHEMA" || payload[:cached] + + statements << payload[:sql] + end + + begin + fixture_runner(transport: transport).call(event_source: fixture_event_source) + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) + end + + source_update = statements.index { |sql| sql.match?(/\AUPDATE\s+"event_sources"/i) } + run_update = statements.index { |sql| sql.match?(/\AUPDATE\s+"ingestion_runs"/i) } + + expect(source_update).not_to be_nil + expect(run_update).not_to be_nil + expect(source_update).to be < run_update + end + + # Why the order above is the safe one. A crash in that window leaves a source that has + # backed off and a run row still marked running — which is a visible, self-correcting + # state. The reverse would leave a finalized run and a source with no cadence written, so + # the next tick would be immediately due and would spend another request into the same + # crash: a hot loop, and §10's "do not crash-loop the poller" forbids exactly that. + it "means a crash in that window can never leave the source immediately due again" do + result = fixture_runner(transport: transport).call(event_source: fixture_event_source) + + expect(result).to be_completed + expect(EventSource.sole.cadence_due_at).to be_present + expect(EventSource.sole.next_poll_at).to be_present + end + end + + # --------------------------------------------------------------------------------------- + # The whole thing at once + # --------------------------------------------------------------------------------------- + # + # Each crash signature is covered on its own: a held source lock whose session dies + # (advisory_lock_session_death_spec.rb), an abandoned entity lease (worker_crash_lease_spec.rb), + # a lost enqueue (pending_enrichment_recovery_spec.rb). A container kill produces all three + # in one instant, and nothing composes them — which matters, because the interesting + # question is not whether each recovers but whether they recover *together*, with no + # operator step and no ordering between them. + # + # This is as close as RSpec gets to §15 step 8. The transcript in docs/evidence/ is the rest. + describe "the whole container-kill cycle, without the container" do + let(:source_namespace) { Github::AdvisoryLock::SOURCE_LOCK_NAMESPACE } + let(:claim) { Github::Enrichment::Claim.new(configuration: Github.configuration) } + let(:actor_type) { Github::Enrichment::EntityType.fetch(:actor) } + let!(:event_source) { fixture_event_source } + + # Ingested at Time.current rather than at frozen_time, for the reason + # pending_enrichment_recovery_spec.rb states: Solid Queue constructs + # ReconcilePendingEnrichmentsJob, so there is no clock to inject into it and its sweep + # measures §10's eligibility window against the wall clock. Entities stamped in 2026-07-29 + # would be outside that window today, and the reconciler would correctly find nothing — + # which would make this example pass for a reason that has nothing to do with recovery. + let(:crashed_at) { Time.current } + + before { active_budget_window(now: crashed_at) } + + # Everything a worker container was holding at the instant it was killed. + def crash! + fixture_runner(transport: transport, now: crashed_at).call(event_source: event_source) + + claim.acquire(actor_type, pool: :pending, now: crashed_at) # a lease with no worker + clear_enqueued_jobs # the lost enqueue + acquire_in_other_session(source_namespace, # the dead poller's lock + Github::AdvisoryLock.key_for(event_source.id)) + terminate_second_session! # the kill + wait_for_advisory_lock_release(source_namespace, Github::AdvisoryLock.key_for(event_source.id)) + end + + # The restart, running only the two recurring tasks a real worker runs, at a clock past + # the abandoned lease's expiry — so the entity the dead worker was holding is reachable + # again by arithmetic alone, with no cleanup step. + def restart! + allow(Github).to receive(:configuration).and_return(configuration_with("GITHUB_MODE" => "fixture")) + allow(Github::EnrichmentRunner).to receive(:new).and_call_original + allow(Github::EnrichmentRunner).to receive(:new) + .and_return(fixture_enrichment_runner(transport: transport, + now: crashed_at + claim.lease_seconds + 1)) + + 6.times do + ReconcilePendingEnrichmentsJob.perform_now + perform_enqueued_jobs + end + end + + it "converges on the state the uncrashed run would have reached" do + crash! + restart! + + expect(PushEvent.count).to eq(4) + expect(GithubActor.find_by(github_id: IngestionHelpers::ACTOR_GITHUB_ID)) + .to have_attributes(enrichment_status: "complete", name: "The Octocat") + expect(GithubRepository.find_by(github_id: IngestionHelpers::REPOSITORY_GITHUB_ID).enrichment_status) + .to eq("complete") + end + + it "needs no operator step, no cleanup job and no sweeper to get there" do + crash! + restart! + + expect(advisory_lock_holders(source_namespace, Github::AdvisoryLock.key_for(event_source.id))) + .to be_empty + expect(Github::LockOrder.held_keys).to be_empty + end + + # The crash itself is not evidence of a fault, so nothing that survived it should carry a + # penalty for it. + it "charges the crashed entity no attempt and the source no failure" do + crash! + restart! + + expect(GithubActor.find_by(github_id: IngestionHelpers::ACTOR_GITHUB_ID).enrichment_attempts).to eq(0) + expect(event_source.reload.consecutive_failures).to eq(0) + end + end +end diff --git a/spec/recovery/multi_poller_spec.rb b/spec/recovery/multi_poller_spec.rb new file mode 100644 index 0000000..b46852b --- /dev/null +++ b/spec/recovery/multi_poller_spec.rb @@ -0,0 +1,334 @@ +require "rails_helper" + +# §9's "Multiple poller containers", at the depth PR 11 owes it. PR 8 established the +# baseline — spec/recovery/source_contention_spec.rb covers a tick against a source another +# process holds *for the whole tick*, where the loser never gets in at all. +# +# The scenario that decides whether the design is correct is the other one: both pollers +# read the row before mutual exclusion existed, both concluded a poll was due, and the +# loser acquires the lock *after* the winner has finished and committed. ADR 0006 rejected +# checking the cadence before taking the lock for exactly this reason — "two processes would +# both read a stale cadence_due_at, both decide they were due, serialize on the lock, and +# poll back to back" — and the defence is one `event_source.reload` inside +# IngestionRunner#call. Nothing tested it. +# +# Every "second poller" here is either a genuinely separate PostgreSQL session +# (spec/support/advisory_lock_helpers.rb) or a second Ruby object over one committed row. +# Never a thread: session advisory locks are re-entrant within a session and the pinned pool +# connection is shared, so a thread-based version of any example below would pass even +# against an empty Github::RequestGate.hold. +RSpec.describe "multiple pollers", type: :integration do + let(:source_namespace) { Github::AdvisoryLock::SOURCE_LOCK_NAMESPACE } + let(:gate_namespace) { Github::AdvisoryLock::REQUEST_GATE_NAMESPACE } + let(:gate_key) { Github::AdvisoryLock::REQUEST_GATE_KEY } + + before { active_budget_window(now: frozen_time) } + + # --------------------------------------------------------------------------------------- + # §9, bullet 1 — the session advisory lock per source + # --------------------------------------------------------------------------------------- + describe "two pollers that both decided the source was due" do + # Two transports, because Github::Transports::Fixture keeps its scripted-response cursor + # on the instance — one per simulated process is what makes them independent. + let(:transport_a) { fixture_transport } + let(:transport_b) { fixture_transport } + + # Poller B's read of the row, taken before poller A ran and therefore before any mutual + # exclusion existed. This is the whole scenario in one line. + let!(:stale) { fixture_event_source } + + def poll_a(force: false) + fixture_runner(transport: transport_a).call(event_source: fixture_event_source, force: force) + end + + def poll_b(force: false, wait_seconds: 5) + fixture_runner(transport: transport_b) + .call(event_source: stale, force: force, wait_seconds: wait_seconds) + end + + it "lets exactly one of them reach GitHub" do + poll_a + poll_b + + expect(transport_a.requests.size).to eq(1) + expect(transport_b.requests).to be_empty + expect(PushEvent.count).to eq(4) + end + + # The regression test for the reload. Remove `event_source.reload` from + # IngestionRunner#call and this example fails while the rest of the suite stays green, + # because every other poll spec hands the runner a freshly loaded row. + it "makes the loser re-read the row under the lock and find it not due" do + poll_a + + expect(poll_b).to be_deferred + expect(poll_b.deferral_reason).to eq("cadence_due_at") + end + + # Distinguishes "the row was re-read" from "the object happened to be current". reload + # mutates in place, so the stale object carries the proof. + it "proves the reload happened, rather than the cadence merely binding" do + expect(stale.cadence_due_at).to be_nil + + poll_a + poll_b + + expect(stale.cadence_due_at).to eq(EventSource.sole.cadence_due_at) + expect(stale.cadence_due_at).not_to be_nil + end + + it "opens one run row, not two" do + poll_a + poll_b + + expect(IngestionRun.count).to eq(1) + end + + # §10's ledger is global, so a back-to-back double poll would spend two of the twelve + # attempts this hour has for a page it already holds. + it "spends one poll attempt, not two" do + poll_a + poll_b + + expect(current_budget.poll_used).to eq(1) + end + + it "advances the schedule once, to the instant the winner wrote" do + poll_a + winner_scheduled = EventSource.sole.next_poll_at + + poll_b + + expect(EventSource.sole.next_poll_at).to eq(winner_scheduled) + end + + # The line between the two mechanisms, drawn explicitly. §9 licenses --force against the + # cadence; it licenses nothing against the lock, and SourceLock.acquire wraps the call + # before `force` is read at all. + it "still refuses a forced loser while the winner holds the lock" do + other_session_holding(source_namespace, Github::AdvisoryLock.key_for(stale.id)) do + expect { poll_b(force: true, wait_seconds: 0) } + .to raise_error(Github::Errors::SourceBusy) + end + end + + it "leaves no lock and no lock-order tracking behind either poller" do + poll_a + poll_b + + expect(advisory_lock_holders(source_namespace, Github::AdvisoryLock.key_for(stale.id))).to be_empty + expect(Github::LockOrder.held_keys).to be_empty + end + end + + # --------------------------------------------------------------------------------------- + # §9, bullet 2 — the global request gate + # --------------------------------------------------------------------------------------- + # + # §2A: "at most one in-flight live request across poller, worker, and one-shot". The poll + # side of that is covered (spec/services/github/request_executor_spec.rb, + # ingestion_runner_spec.rb). The enrichment side is not, and it is the side with a lease + # to put back. + describe "the global request gate, across both request paths" do + let(:transport) { fixture_transport } + let!(:actor) do + create_actor(github_id: IngestionHelpers::ACTOR_GITHUB_ID, last_seen_at: frozen_time, + enrichment_status: "pending") + end + + # 0.1s, never 0: PostgreSQL reads lock_timeout = 0 as "no timeout", so a zero wait would + # block forever rather than defer. + def enrichment_cycle + fixture_enrichment_runner( + executor: fixture_executor(transport: transport, request_gate_wait: 0.1) + ).call + end + + def poll_cycle + fixture_runner(transport: transport, request_gate_wait: 0.1) + .call(event_source: fixture_event_source) + end + + it "defers an enrichment cycle rather than failing it" do + result = other_session_holding(gate_namespace, gate_key) { enrichment_cycle } + + expect(result).to be_deferred + expect(result.deferral_reason).to eq("gate_unavailable") + end + + it "spends nothing and issues no request while the gate is held" do + other_session_holding(gate_namespace, gate_key) { enrichment_cycle } + + expect(current_budget.enrichment_used).to eq(0) + expect(current_budget.actor_share_used).to eq(0) + expect(transport.requests).to be_empty + end + + # The assertion this file exists for. A deferred cycle still *claimed* the row — it + # wrote next_retry_at as a lease before discovering the gate was busy — so proving the + # entity is untouched proves Github::Enrichment::Claim#release! restored the exact prior + # instant rather than clearing it or leaving the lease stranded for its full 594s. + it "gives the lease back exactly, leaving the entity byte-identical" do + before = actor.reload.attributes + + other_session_holding(gate_namespace, gate_key) { enrichment_cycle } + + expect(actor.reload.attributes).to eq(before) + end + + # One gate, application-wide — asserted as a single fact rather than as two separate + # claims about two subsystems. + it "stops the poller and the enrichment worker alike" do + poll_result = nil + enrichment_result = nil + + other_session_holding(gate_namespace, gate_key) do + poll_result = poll_cycle + enrichment_result = enrichment_cycle + end + + expect(poll_result).to be_deferred + expect(enrichment_result).to be_deferred + expect(current_budget.poll_used).to eq(0) + expect(current_budget.enrichment_used).to eq(0) + expect(transport.requests).to be_empty + end + + it "leaves the gate free and the lock order clean after both deferrals" do + other_session_holding(gate_namespace, gate_key) do + poll_cycle + enrichment_cycle + end + + expect(advisory_lock_holders(gate_namespace, gate_key)).to be_empty + expect(Github::LockOrder.held_keys).to be_empty + end + end + + # --------------------------------------------------------------------------------------- + # The measurement ADR 0008 deferred to this PR + # --------------------------------------------------------------------------------------- + # + # ADR 0008 rejected Solid Queue's limits_concurrency keyed by event_source_id and said so + # with a condition attached: "The source lock, the global request gate and the unique event + # constraint are the protections in force; revisit when PR 11's multi-poller tests can + # measure a gap." app/jobs/poll_event_source_job.rb repeats it. + # + # A gap exists iff, under sustained contention, some observable cost or incorrectness + # survives that a semaphore keyed by source id would have prevented. Four observables are + # measured below. + # + # VERDICT: no gap. The three protections §9 names are sufficient, and the semaphore is + # strictly weaker on two of the four axes — it writes to prevent writes that never happen + # (G2), and its fixed duration outlives a killed container where an advisory lock dies with + # the session (G3). + # + # What this measurement does NOT cover, stated rather than glossed: whether a + # solid_queue_semaphores round trip is material under N real worker containers is a load + # question, not a unit one. The verdict is bounded to correctness and local cost. + describe "the gap ADR 0008 asked PR 11 to measure" do + let(:transport) { fixture_transport } + let!(:event_source) { fixture_event_source } + let(:key) { Github::AdvisoryLock.key_for(event_source.id) } + + before do + allow(Github).to receive(:configuration).and_return(configuration_with("GITHUB_MODE" => "fixture")) + + allow(Github::IngestionRunner).to receive(:new).and_call_original + runner = fixture_runner(transport: transport) + allow(Github::IngestionRunner).to receive(:new).and_return(runner) + end + + def contended_ticks(count) + other_session_holding(source_namespace, key) do + count.times { PollEventSourceJob.new.perform_now } + end + end + + # G1 — the four things a semaphore would exist to prevent, measured across a window of + # ticks rather than a single one. + it "G1 — sustained contention produces no duplicate request, row, debit or schedule move" do + before_source = event_source.attributes + + contended_ticks(5) + + expect(IngestionRun.count).to eq(0) + expect(transport.requests).to be_empty + expect(current_budget.poll_used).to eq(0) + expect(PushEvent.count).to eq(0) + expect(event_source.reload.attributes).to eq(before_source) + end + + # G2 — the cost comparison. A contended tick writes nothing at all, so a semaphore would + # spend an INSERT and a DELETE in solid_queue_semaphores to prevent zero writes. + # + # The statement *classes* are the load-bearing claim. The count is a smoke bound, not a + # specification of the query plan: cached and SCHEMA statements are filtered because + # whether the schema cache is already warm depends on file order under + # config.order = :random. + it "G2 — a contended tick costs no write at all, so a semaphore would save nothing" do + statements = [] + + subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*, payload| + next if payload[:name] == "SCHEMA" || payload[:cached] + + statements << payload[:sql] + end + + begin + contended_ticks(1) + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) + end + + expect(statements.grep(/\A\s*(INSERT|UPDATE|DELETE)/i)).to be_empty + expect(statements.size).to be < 10 + end + + # G3 — ADR 0008's stated rejection reason, measured rather than argued: "a container + # killed mid-poll would suppress that source until the semaphore expired. The session + # advisory lock this system already holds is released by PostgreSQL the instant the + # backend dies." + # + # A limits_concurrency semaphore must declare a fixed `duration` at least as long as the + # longest legitimate poll, so its floor is tens of seconds. The lock's recovery is + # measured below and asserted an order of magnitude under one second. + it "G3 — a killed session frees the source immediately, where a semaphore would not" do + acquire_in_other_session(source_namespace, key) + + started = Process.clock_gettime(Process::CLOCK_MONOTONIC) + terminate_second_session! + wait_for_advisory_lock_release(source_namespace, key) + elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - started + + expect(elapsed).to be < 1 + expect(Github::SourceLock.acquire(event_source.id, wait_seconds: 5) { :polled }).to eq(:polled) + end + + # G4 — a semaphore keyed by source id is only as good as the agreement on that id, and + # nothing about the semaphore provides it. Github::Ingestion::SourceProvisioner does, + # by converging every process on the lowest id for the type; the mechanism itself is + # covered by source_provisioner_spec.rb, and what is asserted here is the consequence + # for the key. + it "G4 — key agreement comes from the provisioner, not from any concurrency primitive" do + create_event_source(source_type: "github_fixture_events") + + first = Github::Ingestion::SourceProvisioner.ensure!(mode: :fixture, now: frozen_time) + second = Github::Ingestion::SourceProvisioner.ensure!(mode: :fixture, now: frozen_time) + + expect(Github::AdvisoryLock.key_for(first.id)).to eq(Github::AdvisoryLock.key_for(second.id)) + end + + # The verdict, made executable. Written in the idiom of spec/job_boundary_spec.rb's and + # spec/network_boundary_spec.rb's grep guards: if someone later adds a source-keyed + # concurrency limit, this fails and sends them back to ADR 0008's condition rather than + # letting the decision be reversed silently. + it "records the verdict: no job declares a source-keyed concurrency limit" do + declaring = Dir[Rails.root.join("app/jobs/**/*.rb")].select do |path| + File.read(path).include?("limits_concurrency") + end + + expect(declaring).to be_empty + end + end +end diff --git a/spec/services/github/enrichment/fairness_stress_spec.rb b/spec/services/github/enrichment/fairness_stress_spec.rb new file mode 100644 index 0000000..999ffb3 --- /dev/null +++ b/spec/services/github/enrichment/fairness_stress_spec.rb @@ -0,0 +1,248 @@ +require "rails_helper" + +# Story 3's ninth child issue asks for "starved-class enrichment" to be tested, and §10 says +# what starvation would look like: one observed live page held ~89 distinct actors and ~92 +# distinct repositories, so "repository candidates alone exceed the whole hourly allowance, +# and a repo-first policy — or any policy ordering purely by recency across a mixed pool — +# starves actor enrichment to zero indefinitely". +# +# That is a claim about how a *whole window* is distributed, and no single-choice example can +# express it. spec/services/github/enrichment/fairness_spec.rb asks for one choice at a time, +# and budget_ledger_spec.rb and enrichment/end_to_end_spec.rb check the boundaries against +# counters set with update_all. None of them ever spends a window, so none of them can +# observe the property Story 3 actually asks for: that after forty real reservations against +# a twenty-to-one flood, the starved class still got every request it had a candidate for. +# +# The drain drives Fairness, Claim and BudgetLedger directly rather than through +# Github::EnrichmentRunner, and deliberately not through the transport. The corpus resolves +# six entity URLs and its sticky tail would hand every flood row octocat's body, which +# RepositoryDocument.parse then rejects on identity — fifty-seven permanent failures with +# nothing to do with fairness, obscuring the sequence that is the whole point. The three +# objects below are the ones the property lives in, and they are the real ones. +RSpec.describe "enrichment fairness under a flood", type: :integration do + let(:configuration) { Github.configuration } + let(:selector) { Github::Enrichment::CandidateSelector.new(configuration: configuration) } + let(:fairness) { Github::Enrichment::Fairness.new(configuration: configuration, selector: selector) } + let(:claim) { Github::Enrichment::Claim.new(configuration: configuration, selector: selector) } + let(:ledger) { Github::BudgetLedger.new(configuration: configuration) } + + # [entity_type_key, borrowed] per granted request, in the order the window granted them. + let(:sequence) { [] } + + before { active_budget_window(now: frozen_time) } + + # One granted request: choose, lease so the row stops being eligible, debit. Returns the + # Choice so a caller can assert on a refusal. + def spend! + choice = fairness.choose(now: frozen_time) + return choice unless choice.chosen? + + claim.acquire(choice.entity_type, pool: choice.pool, now: frozen_time) + ledger.reserve!(choice.entity_type.request_class, now: frozen_time, borrow: choice.borrow) + sequence << [ choice.entity_type.key, choice.borrow ] + + choice + end + + def drain!(limit = 60) + limit.times { break unless spend!.chosen? } + end + + def flood_repositories(count) + count.times do |index| + create_repository(github_id: 300_000 + index, full_name: "flood/repo-#{index}", + name: "repo-#{index}", last_seen_at: frozen_time, + enrichment_status: "pending") + end + end + + def flood_actors(count) + count.times do |index| + create_actor(github_id: 400_000 + index, login: "flood-user-#{index}", + display_login: "flood-user-#{index}", last_seen_at: frozen_time, + enrichment_status: "pending") + end + end + + # At the pinned defaults the window is 40 requests split 20/20, so sixty repositories + # against three actors is §10's ratio with room to spare on one side and none on the other. + describe "a repository flood, twenty to one" do + before do + flood_repositories(60) + flood_actors(3) + drain! + end + + # Story 3's requirement, measured over a window rather than asserted about one choice. + it "enriches every actor candidate, which is what §10 says a repo-first policy would not" do + expect(sequence.count { |(key, _)| key == :actor }).to eq(3) + end + + it "leases every actor it chose, so none of the three was chosen twice" do + leased = GithubActor.where.not(next_retry_at: nil).count + + expect(leased).to eq(3) + end + + # A sequence-level property: no per-choice example can state "only after", because the + # borrow condition is evaluated fresh each time and is legitimately true at the end. + it "borrows only after the other class has genuinely run dry" do + first_borrow = sequence.index { |(_, borrow)| borrow } + last_actor = sequence.rindex { |(key, _)| key == :actor } + + expect(first_borrow).to be > last_actor + end + + it "spends the window exactly once, with the two shares summing to the class counter" do + budget = current_budget + + expect(budget.enrichment_used).to eq(40) + expect(budget.actor_share_used).to eq(3) + expect(budget.repository_share_used).to eq(37) + expect(budget.actor_share_used + budget.repository_share_used).to eq(budget.enrichment_used) + end + + it "never lets either share exceed the class allowance" do + budget = current_budget + + expect(budget.actor_share_used).to be <= budget.enrichment_allowance + expect(budget.repository_share_used).to be <= budget.enrichment_allowance + end + + it "stops at the allowance rather than one request past it" do + expect(spend!.reason).to eq("class_exhausted") + expect(current_budget.enrichment_used).to eq(40) + end + + # A starved backlog must be *waiting*, not damaged: nothing was charged an attempt and + # nothing recorded an error, so the rows are exactly as eligible next window as they were + # this one. + it "leaves the unenriched backlog intact rather than corrupted" do + untouched = GithubRepository.where(next_retry_at: nil) + + expect(untouched.count).to eq(60 - 37) + expect(untouched.pluck(:enrichment_status).uniq).to eq([ "pending" ]) + expect(untouched.pluck(:enrichment_attempts).uniq).to eq([ 0 ]) + expect(untouched.pluck(:last_error).uniq).to eq([ nil ]) + end + end + + # §10 says "and vice versa", and a floor/remainder split is exactly the kind of arithmetic + # that works in one direction and is off by one in the other. + describe "an actor flood, twenty to one" do + before do + flood_actors(60) + flood_repositories(3) + drain! + end + + it "still enriches every repository candidate" do + expect(sequence.count { |(key, _)| key == :repository }).to eq(3) + end + + it "holds the flooding class to its guarantee until the other class is quiet" do + within_guarantee = sequence.count { |(key, borrow)| key == :actor && !borrow } + + expect(within_guarantee).to eq(20) + end + + # The arithmetic of the drain, not a single boundary: the flooding class takes its + # twenty, the starved class takes the three it has candidates for, and the remainder is + # borrowed. + it "lets the flooding class borrow exactly the remainder" do + borrowed = sequence.count { |(_, borrow)| borrow } + + expect(borrowed).to eq(40 - 20 - 3) + end + + it "spends the window exactly once, mirrored" do + budget = current_budget + + expect(budget.enrichment_used).to eq(40) + expect(budget.actor_share_used).to eq(37) + expect(budget.repository_share_used).to eq(3) + end + end + + describe "class isolation under a real drain" do + let(:transport) { fixture_transport } + + before do + flood_repositories(60) + flood_actors(3) + drain! + end + + # The stress direction of Github::RateLimitPolicy's rule that only :reserve_reached, a + # primary limit and a secondary limit are global. Forty consecutive class-and-share + # denials wrote nothing global — which is unreachable from any spec that sets the + # counters with update_all, because there were no denials to write anything. + it "never writes a global block while denying a whole window of enrichment" do + spend! + spend! + + expect(current_budget.global_blocked_until).to be_nil + expect(current_budget.window_status).to eq("active") + end + + # The derived-not-stored isolation mechanism, observed after real spending. + it "blocks the enrichment class and leaves the poll class alone" do + budget = current_budget + + expect(budget.poll_used).to eq(0) + expect(budget.poll_class_blocked_until(now: frozen_time)).to be_nil + expect(budget.enrichment_class_blocked_until(now: frozen_time)).to eq(budget.reset_at) + end + + it "still polls after enrichment has spent its entire allowance" do + result = fixture_runner(transport: transport).call(event_source: fixture_event_source) + + expect(result).to be_completed + expect(current_budget.poll_used).to eq(1) + expect(PushEvent.count).to eq(4) + end + end + + # Extension B's eighth bullet — "bound the enrichment backlog via the eligibility window and + # skipped_budget (no unbounded growth)" — at flood scale. spec/services/github/enrichment/ + # age_out_spec.rb tests the predicate and the batch bound on a handful of rows; the fact + # asserted here is the interaction: a class starved by *budget* is still bounded by *time*, + # so the two mechanisms compose rather than each assuming the other is doing the work. + describe "the backlog stays bounded under a flood" do + let(:age_out) { Github::Enrichment::AgeOut.new(configuration: configuration, selector: selector) } + let(:past_window) { frozen_time + configuration.enrichment_eligibility_window_seconds + 1 } + + before do + flood_repositories(60) + flood_actors(3) + drain! + end + + # Sixty-three rows, comfortably under AgeOut's batch of 1,000, so this measures the + # eligibility window and not the batch bound. + it "ages the surviving flood into skipped_budget rather than letting it grow" do + age_out.call(now: past_window) + + expect(GithubRepository.where(enrichment_status: "pending")).to be_empty + expect(GithubRepository.where(enrichment_status: "skipped_budget").count).to eq(60) + end + + it "charges the skipped rows no attempt, because nothing was ever tried on them" do + age_out.call(now: past_window) + + skipped = GithubRepository.where(enrichment_status: "skipped_budget") + + expect(skipped.pluck(:enrichment_attempts).uniq).to eq([ 0 ]) + expect(skipped.pluck(:skipped_at).compact.size).to eq(60) + end + + it "leaves nothing eligible once the window has passed" do + age_out.call(now: past_window) + + expect(selector.pending_available?(Github::Enrichment::EntityType.fetch(:repository), now: past_window)) + .to be(false) + expect(selector.pending_available?(Github::Enrichment::EntityType.fetch(:actor), now: past_window)) + .to be(false) + end + end +end diff --git a/spec/services/github/enrichment/redirect_boundary_spec.rb b/spec/services/github/enrichment/redirect_boundary_spec.rb new file mode 100644 index 0000000..9adbc8b --- /dev/null +++ b/spec/services/github/enrichment/redirect_boundary_spec.rb @@ -0,0 +1,126 @@ +require "rails_helper" + +# The corpus has carried `redirecting_repository` and `hostile_redirect` since PR 4, and +# until now nothing consumed them: fixtures/github/README.md said "the redirect ones wait for +# PR 11", and the only reference anywhere was a spec asserting the scenario *names* exist. +# §16's final-review gate forbids dead infrastructure, and corpus that exists only to be +# enumerated is exactly that. +# +# spec/services/github/request_executor_spec.rb already covers the redirect machinery at the +# executor level — following a validated target, debiting each hop, refusing an off-host +# Location, stopping at MAX_REDIRECTS. What it cannot show is the consequence for an +# *entity*, because the executor has no entity: whether a rename lands as `complete`, whether +# a hostile hop costs the entity its record, and — the one §10 cares about most — whether +# either of them can take the event source out of service. That is this file. +# +# Both scenarios are single-hop, so MAX_REDIRECTS stays at its default of 2 and nothing is +# added to the compose anchor to run them. +RSpec.describe "enrichment across a redirect", type: :integration do + # The corpus body for this id is repos/octocat_hello-world.json, whose own `id` is + # 1296269 — RepositoryDocument.parse checks identity, so the row and the body have to + # agree or a rename would be indistinguishable from a mis-served body. + let!(:repository) do + create_repository(github_id: IngestionHelpers::REPOSITORY_GITHUB_ID, + full_name: "octocat/Hello-World", name: "Hello-World", + api_url: "https://api.github.com/repos/octocat/Hello-World", + last_seen_at: frozen_time, enrichment_status: "pending") + end + + let!(:event_source) { fixture_event_source } + + before { active_budget_window(now: frozen_time) } + + # --class repository, because fairness picks actor before repository as its tie-break and + # an unscoped cycle would not reliably reach this row. Narrowing the class bypasses no + # budget rule — the allowance, the share, the reserve and every global block still bind. + def enrich(scenario) + transport = fixture_transport(scenario: scenario) + result = fixture_enrichment_runner(transport: transport).call(entity_class: GithubRepository) + + [ result, transport ] + end + + describe "redirecting_repository — a rename the URL policy accepts" do + it "follows the hop and completes the entity" do + result, = enrich("redirecting_repository") + + expect(result).to be_enriched + expect(repository.reload.enrichment_status).to eq("complete") + end + + it "stores the document the second hop returned" do + enrich("redirecting_repository") + + expect(repository.reload.full_name).to eq("octocat/Hello-World") + expect(repository.reload.fetched_at).to be_present + end + + # §7's "failures stay spent" generalizes to hops: each one is a real outbound request + # and the ledger debits every attempt. Two requests for one entity is the honest cost of + # a rename, and an operator reading the per-class counter should see it. + it "charges the repository share for both hops, not one" do + _, transport = enrich("redirecting_repository") + + expect(transport.requests.size).to eq(2) + expect(current_budget.repository_share_used).to eq(2) + expect(current_budget.enrichment_used).to eq(2) + end + + it "leaves no lease behind on the completed entity" do + enrich("redirecting_repository") + + expect(repository.reload.next_retry_at).to be_nil + end + end + + describe "hostile_redirect — a Location pointing off-host" do + it "refuses the entity rather than following it" do + result, = enrich("hostile_redirect") + + expect(result).to be_failed + expect(repository.reload.enrichment_status).to eq("permanent_failure") + end + + # The assertion that makes this an SSRF test rather than an error-handling test: the + # second hop was never sent. The URL policy runs *before* the request gate, so the + # refusal happens outside any reservation and the socket is never opened. + it "never sends the second request" do + _, transport = enrich("hostile_redirect") + + expect(transport.requests.size).to eq(1) + expect(transport.requests.map(&:to_s)).to all(include("api.github.com")) + end + + it "spends one debit — the hop that did happen — and no more" do + enrich("hostile_redirect") + + expect(current_budget.repository_share_used).to eq(1) + expect(current_budget.enrichment_used).to eq(1) + end + + it "records the policy violation on the entity so an operator sees the reason" do + enrich("hostile_redirect") + + expect(repository.reload.last_error).to be_present + end + + # §10's rule, and the one a hostile payload would otherwise be able to exploit: a + # redirect target this application refuses is a fact about one entity, never about the + # feed. Taking the source out of service on it would let one crafted repository URL stop + # ingestion for everything. + it "never takes the event source out of service" do + enrich("hostile_redirect") + + expect(event_source.reload.status).to eq("idle") + expect(event_source.reload.enabled).to be(true) + expect(event_source.reload.consecutive_failures).to eq(0) + end + + it "writes no global block, because one bad target is not a rate limit" do + enrich("hostile_redirect") + + expect(current_budget.global_blocked_until).to be_nil + expect(current_budget.window_status).to eq("active") + end + end +end diff --git a/spec/services/github/fixture_mode_fail_closed_spec.rb b/spec/services/github/fixture_mode_fail_closed_spec.rb new file mode 100644 index 0000000..9d222bc --- /dev/null +++ b/spec/services/github/fixture_mode_fail_closed_spec.rb @@ -0,0 +1,165 @@ +require "rails_helper" +require "tmpdir" + +# Extension D's twelfth child issue asks for fixture-mode end-to-end verification and states +# the property it has to demonstrate: "fixture mode fails closed, never a live fallback". +# +# The container half of that — that the web, worker and ingest services make no egress with +# GITHUB_MODE=fixture — is script/verify_recovery.sh's, because nothing inside +# `bundle exec rspec` can observe a process it did not start. This file is the half that +# needs no Docker at all, because failing closed is a property of the application's own +# wiring: Github.transport, EventSources::Base.for_mode, UrlPolicy::MODES, +# Transports::Fixture#get, and RequestExecutor's deliberate decision not to rescue a miss. +# +# Each of those is asserted individually elsewhere. What is asserted here is that they move +# *together* — a mode is not one switch but three coupled decisions, and the failure this +# file exists to catch is one of them being changed without the others. +RSpec.describe "fixture mode fails closed" do + describe "the three decisions GITHUB_MODE makes at once" do + it "selects the offline transport and the offline event source from the same value" do + expect(Github::EventSources::Base.for_mode(:fixture)).to eq(Github::EventSources::FixtureEvents) + expect(Github::EventSources::Base.for_mode(:live)).to eq(Github::EventSources::PublicEvents) + expect(Github::UrlPolicy::MODES.keys).to match_array(%i[ live fixture ]) + end + + # The offline address cannot leak into a live deployment: it is not merely unusual + # under the live policy, it is refused by it. + it "refuses the fixture source's own page-one URL under the live policy" do + result = Github::UrlPolicy.validate(Github::EventSources::FixtureEvents::FIRST_PAGE_URL, mode: :live) + + expect(result.violations).to include(:scheme_not_allowed) + end + + it "refuses a live api.github.com URL under the fixture policy" do + result = Github::UrlPolicy.validate("https://api.github.com/events?per_page=100", mode: :fixture) + + expect(result.violations).to include(:scheme_not_allowed) + end + + # Asserted as a pair on purpose. Either transport accepting the other mode's URL would + # turn a mode mismatch into a request, and the symmetry is the guarantee. + it "makes each transport refuse the other mode's validated URL at its door" do + expect { Github::Transports::Faraday.new.get(fixture_url("/events?per_page=100")) } + .to raise_error(ArgumentError, /live transport accepts only a live/) + + expect { fixture_transport.get(live_url("/events?per_page=100")) } + .to raise_error(ArgumentError, /fixture transport accepts only a fixture/) + end + + # §10 puts the allowed host in code rather than in the environment, "because an env var + # here would turn the SSRF boundary into a deployment setting". Asserted against the + # configuration's own key list so adding one would fail here rather than in review. + it "keeps the allowed host out of the configuration entirely" do + expect(Github::Configuration::DEFAULTS.values).not_to include(Github::UrlPolicy::ALLOWED_HOST) + expect(Github::Configuration::DEFAULTS.keys.grep(/HOST|BASE_URL|ENDPOINT/)).to be_empty + expect(Github::UrlPolicy::ALLOWED_HOST).to eq("api.github.com") + end + end + + # A corpus that resolves nothing the run needs. §6 says an unknown URL "raises a fixture + # error, never a live fallback", and RequestExecutor states why it must not be converted + # into a FetchResult: "a corpus gap is an authoring bug, not a runtime outcome, and + # laundering it into a failed fetch would let a fixture-mode demo report a plausible-looking + # failure instead of naming the missing entry." + # + # Proved through the real chain rather than by stubbing something to raise — which is what + # separates this from spec/services/github/ingestion/one_shot_spec.rb's exit-code example. + describe "a corpus with no entry for the request" do + around do |example| + Dir.mktmpdir do |directory| + @gapped_root = Pathname.new(directory) + @gapped_root.join("manifest.json").write( + JSON.generate( + version: 1, + default_headers: {}, + # Deliberately not /events: the poll's own URL is the one that must miss. + scenarios: { default: { responses: { "/users/nobody" => [ { status: 404 } ] } } } + ) + ) + example.run + end + end + + let(:gapped_transport) do + Github::Transports::Fixture.new( + corpus: Github::FixtureCorpus.new(root: @gapped_root, scenario: "default"), + clock: -> { frozen_time } + ) + end + + before { active_budget_window(now: frozen_time) } + + it "raises rather than reaching GitHub" do + expect { fixture_runner(transport: gapped_transport).call(event_source: fixture_event_source) } + .to raise_error(Github::Errors::FixtureMiss, /defines no response for/) + end + + it "names the missing key, so the corpus can be fixed without guessing" do + fixture_runner(transport: gapped_transport).call(event_source: fixture_event_source) + rescue Github::Errors::FixtureMiss => error + expect(error.message).to include("/events?per_page=100") + end + + # The miss reaches the caller as an exception, so it can never be reported as a poll + # that happened and failed. + it "records no successful run and persists nothing" do + begin + fixture_runner(transport: gapped_transport).call(event_source: fixture_event_source) + rescue Github::Errors::FixtureMiss + nil + end + + expect(PushEvent.count).to eq(0) + expect(IngestionRun.where(status: "completed")).to be_empty + end + + # §9's exit-code contract: 2 is "refused to run — bad option, bad configuration, or a + # corpus gap", and a corpus gap must never be reported as 0. + it "makes the one-shot refuse with exit 2 rather than report a deferral" do + one_shot = Github::Ingestion::OneShot.new( + argv: [], output: StringIO.new, error_output: StringIO.new, + runner: fixture_runner(transport: gapped_transport), + provisioner: double(ensure!: fixture_event_source) + ) + + result = one_shot.call + + expect(result.exit_code).to eq(Github::Ingestion::OneShot::REFUSED) + expect(result.outcome).to eq(:refused) + end + + it "lists the corpus errors among the ones that refuse rather than defer" do + expect(Github::Ingestion::OneShot::REFUSING_ERRORS).to include( + Github::Errors::FixtureMiss, Github::Errors::FixtureCorpusError + ) + end + end + + # §12's end-to-end claim, in its executable form: "known corpus in, exact expected counts + # out … zero live quota consumed". The suite already refuses net connect globally + # (spec/network_boundary_spec.rb), so what this adds is the stronger statement that a full + # fixture run does not even *attempt* one. + describe "a complete fixture ingestion" do + let(:transport) { fixture_transport } + + before { active_budget_window(now: frozen_time) } + + it "produces the documented counts with no HTTP request of any kind" do + result = fixture_runner(transport: transport).call(event_source: fixture_event_source) + + expect(result).to be_completed + expect(PushEvent.count).to eq(4) + expect(GithubActor.count).to eq(3) + expect(GithubRepository.count).to eq(3) + expect(QuarantinedEvent.count).to eq(3) + expect(a_request(:any, /.*/)).not_to have_been_made + end + + it "spends the poll class of the local ledger and nothing else" do + fixture_runner(transport: transport).call(event_source: fixture_event_source) + + expect(current_budget.poll_used).to eq(1) + expect(current_budget.enrichment_used).to eq(0) + end + end +end