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