diff --git a/.env.example b/.env.example index f084a0d..93bde21 100644 --- a/.env.example +++ b/.env.example @@ -126,6 +126,25 @@ GITHUB_MODE=live # ACTOR_REFRESH_TTL_SECONDS=86400 # REPOSITORY_REFRESH_TTL_SECONDS=86400 +# How far back GET /status looks when it computes §11's three coverage +# percentages. Unlike every other knob in this file it changes only what the +# system *reports* — nothing schedules, reserves, defers or skips on it, so two +# processes reading different values is a cosmetic disagreement rather than a +# policy split. +# +# The window is measured on push_events.created_at, the instant this application +# persisted the row, not on GitHub's occurred_at. Coverage grades this +# application's enrichment pipeline, and that pipeline's own eligibility rule is +# already COALESCE(last_seen_at, created_at) — one clock, not two. It also keeps +# the offline reviewer path meaningful: the fixture corpus pins its event +# timestamps to a fixed date, so an occurred_at basis would report null coverage +# to anyone running the walkthrough after that date. +# +# Must be greater than zero: the window is the sole denominator of all three +# percentages, so zero reports null for every one of them, permanently. Widen it +# when reviewing a corpus that has aged. +# ENRICHMENT_COVERAGE_WINDOW_SECONDS=86400 + # Deliberately absent, and not oversights: # # GITHUB_API_BASE_URL / GITHUB_API_HOST - the allowed host is a constant in @@ -142,7 +161,3 @@ GITHUB_MODE=live # Github::Events::ProcessorRegistry.for refuses an unimplemented type with a # configuration error naming what is implemented. The day a second processor # lands, this becomes one DEFAULTS entry and one validate! line. -# ENRICHMENT_COVERAGE_WINDOW_SECONDS - §10 prints it alongside the three timings -# above, but it is an input to §11's coverage percentages, which land with the -# rich /status in PR 10. Nothing reads it yet, and a knob with no consumer is -# what §16 calls speculative infrastructure. diff --git a/README.md b/README.md index 8ca7d31..b2020c8 100644 --- a/README.md +++ b/README.md @@ -83,7 +83,74 @@ curl http://localhost:3000/health/live # {"status":"ok"} — process is up curl http://localhost:3000/health/ready # {"status":"ok"} — database reachable, schema current ``` -Neither health endpoint ever calls GitHub or consumes request budget. +See what it has actually done, and inspect what it captured: + +```bash +curl -s http://localhost:3000/status | jq +curl -s 'http://localhost:3000/api/push_events?limit=5' | jq +curl -s http://localhost:3000/api/push_events/ | jq .data.raw_payload +``` + +**No endpoint on this surface ever calls GitHub or consumes request budget** (plan +§11). That is structural rather than a promise: none of these controllers holds an +executor or a transport, and `Github::BudgetLedger` is absent from all of them — +every one of its public methods writes, and `#bootstrap!` would create from a read +path the very ledger row a reservation owns. Four specs pin it, including one that +subscribes to every SQL statement a request issues and fails on any `INSERT`, +`UPDATE` or `DELETE`. + +#### `GET /status` + +Reports persisted state only: the poll schedule per event source (all five of §9's +components, plus which one is binding), the per-class ledger state, §11's three +enrichment coverage percentages, and the per-status entity counts. + +Three conventions in the response body are worth knowing before reading one: + +- **`null` is never a zero.** A counted zero prints `0`; a number that does not + exist prints `null`. Where `null` would be ambiguous the disambiguating fact gets + its own field — `ledger.present` separates "no ledger row yet" from "remaining is + genuinely 0", `due_now` separates "no constraint applies" from "unknown", and + `claimable_now` separates "work is claimable this second" from "nothing is + waiting". An empty coverage window reports `null` percentages, not `0.0`: the + ratio is undefined, not zero, and every denominator is published beside its ratio + so you can check it. +- **The coverage window is measured on `created_at`** — when *this application* + persisted the event, not GitHub's `occurred_at`. Coverage grades this + application's enrichment pipeline, and that pipeline's own eligibility and + freshness rules already run on this clock. The basis is published as + `coverage.basis` so the choice is visible rather than assumed. Widen + `ENRICHMENT_COVERAGE_WINDOW_SECONDS` when reviewing a fixture corpus that has aged. +- **`actor_requests.available` is a floor, not a ceiling.** §10 lets one class + borrow the other's unspent capacity when the other has no eligible candidate, so a + class does not stop at zero available. The real ceiling is the `enrichment` pair + beside it. + +`pending` in the entity counts means `enrichment_status = 'pending'` exactly. The +`candidates` figure beside it is pending **plus** `retryable_failure` — the "how much +work is left" number `bin/ingest` prints. Two questions, two names, deliberately. + +#### `GET /api/push_events` and `GET /api/push_events/:id` + +`:id` is the **GitHub event id**, not the surrogate primary key — the identifier §11 +puts on every log line, so a log line is a URL you can type. The surrogate key +appears in no response. + +Paging is keyset on `(occurred_at, id)` with an opaque cursor, not `offset`: the +poller writes continuously and this list is newest-first, so an offset page 2 would +re-serve rows from page 1 and skip others whenever a poll landed in between. Follow +`pagination.next_cursor`, or the RFC-8288 `Link: …; rel="next"` header. `limit` +defaults to 25 and is capped at 100 — a value outside that range is a `400`, never a +silent clamp, because a client that asked for 500 and received 100 cannot tell +whether it received everything. `actor_id` and `repository_id` filter; an unknown +parameter is a `400` rather than a silently unfiltered answer. + +The list omits `raw_payload` — it is a multi-kilobyte TOASTed `jsonb` column nobody +scans a list for. `GET /api/push_events/:id` returns it, which is how §16's "raw +payload is retained" gate is checkable without a psql session. Every row nests its +actor and repository with their `enrichment_status`, so §16's enrichment gate is +visible in a browser as statuses flip from `pending` to `complete` while the worker +runs. Run the test suite (isolated `*_test` databases; never touches the development databases): @@ -386,13 +453,35 @@ the request that reached its fairness guarantee — `budget.global_block_set` an `budget.global_block_cleared`. Enrichment adds `enrichment.completed` and `enrichment.failed`, each carrying the -entity type, its GitHub id, the response classification and the resulting entity -status; `enrichment.aged_out`, one summary line per class per sweep rather than one -per row; `enrichment.reactivated` when a genuinely new push event brings a -`skipped_budget` entity back; and `enrichment.lease_lost` at warning level when an -outcome arrived after another worker had claimed the row. - -`LOG_LEVEL=debug` adds `github.request`, `ingestion.page_fetched` and +entity type, its GitHub id, the response classification, the resulting entity status +and the attempt number; `enrichment.aged_out`, one summary line per class per sweep +rather than one per row; `enrichment.reactivated` when a genuinely new push event +brings a `skipped_budget` entity back; `enrichment.lease_lost` at warning level when +an outcome arrived after another worker had claimed the row; and +`enrichment.cycle_failed` at error level when an exception escapes a cycle entirely, +carrying the lease it released and the error class. + +**Every failure and every retry reaches the default level.** `github.request` is +raised to warning when the request failed — a 5xx, a network timeout, a 404 on an +entity URL, a permanent 4xx, or a URL the SSRF boundary refused — carrying the +classification, status, URL and attempt number. `github.retry_scheduled` is emitted +at info for each of the `MAX_HTTP_RETRIES` backoffs, reporting the delay actually +slept rather than a freshly jittered one. `github.retry_exhausted` is emitted at +warning when the attempts ran out, which is what distinguishes "retried and gave up" +from "failed once, permanently". Each carries the `run_id` of the poll or the entity +id of the enrichment that issued it, so a whole retry ladder greps as one trace. + +On the source side, `ingestion.source_backoff` names a failed poll's own retry +instant and the delay behind it — `next_poll_at` is the maximum of §9's five +independent components and so cannot say which one is binding — and +`ingestion.source_failed` at error level reports the one transition nothing in this +application reverses: a permanent 4xx on `/events` takes the source out of service +until an operator clears it (plan §10). It shares its token with the +`deferral_reason` of every poll subsequently refused, so one grep returns the +transition and its consequences together. + +`LOG_LEVEL=debug` adds the `github.request` line for requests that **succeeded** (the +failing ones are already at warning), `ingestion.page_fetched` and `ingestion.page_processed` per page, `ingestion.pagination_stopped` with its reason, `ingestion.not_modified` — which carries the `x-ratelimit-used` and `x-ratelimit-remaining` that make the `304` accounting visible in the running @@ -425,7 +514,7 @@ is [`.env.example`](.env.example). | Variable | Default | Purpose | |---|---|---| -| `LOG_LEVEL` | `info` | JSON log verbosity: `debug` adds per-request/per-page lines (plan §11) | +| `LOG_LEVEL` | `info` | JSON log verbosity. `info` carries the run summaries, the budget transitions and **every failure, retry and backoff**; `debug` adds the per-request and per-page lines for requests that succeeded (plan §11) | | `RAILS_ENV` | `development` | Environment for the compose app services | | `RAILS_MAX_THREADS` | `5` | Connection pool / Puma thread size | | `GITHUB_MODE` | `live` | `live` reaches api.github.com; `fixture` resolves everything inside [`fixtures/github/`](fixtures/github/) with no network and fails closed on an unknown URL (plan §6, §12) | @@ -443,6 +532,7 @@ is [`.env.example`](.env.example). | `ENRICHMENT_ELIGIBILITY_WINDOW_SECONDS` | `3600` | How long a candidate stays worth enriching. Past it, the entity transitions to `skipped_budget` — which is what bounds the backlog — until a genuinely new push event reactivates it (plan §10, B8) | | `ACTOR_REFRESH_TTL_SECONDS` | `86400` | How long an enriched actor is reused before it is re-fetched. Never-enriched candidates always take priority over refreshes (plan §10) | | `REPOSITORY_REFRESH_TTL_SECONDS` | `86400` | The same, for repositories | +| `ENRICHMENT_COVERAGE_WINDOW_SECONDS` | `86400` | How far back `GET /status` looks when computing §11's three coverage percentages, measured on `push_events.created_at`. The only knob here that changes what the system *reports* rather than what it *does* | `POLL_INTERVAL_SECONDS`, `MAX_PAGES_PER_POLL`, `ENABLED_LIVE_SOURCE_COUNT` and `RATE_LIMIT_RESERVE` feed the one authoritative allowance formula (plan §10): diff --git a/app/controllers/api/push_events_controller.rb b/app/controllers/api/push_events_controller.rb new file mode 100644 index 0000000..99d187b --- /dev/null +++ b/app/controllers/api/push_events_controller.rb @@ -0,0 +1,61 @@ +module Api + # IMPLEMENTATION_PLAN.md §11's event inspection endpoints. + # + # **Never initiates a GitHub request and never consumes budget** — the guarantee §11 + # places on the whole health-and-inspection surface. Structural rather than a promise: + # this controller holds no executor and no transport, and its only collaborators are + # Inspection:: value objects over Active Record. The same specs that pin + # Github::Ingestion::StateSummary pin it — a recording transport that must see no request, + # and row counts that must not change. + # + # Api, not API: config/initializers/inflections.rb registers no acronym, so `namespace + # :api` camelizes to Api and Zeitwerk expects this path. + class PushEventsController < ApplicationController + def index + page = Inspection::PushEventPage.for(params) + + set_next_link(page) + render json: Inspection::PushEventView.page(page) + end + + # :id is github_event_id, not the surrogate primary key, and the two are genuinely + # ambiguous — real GitHub event ids are numeric strings, so only one reading can be + # right. §7 keeps the surrogate key out of this application's identity vocabulary + # entirely (even the foreign keys target github_id), github_event_id is the unique index + # the whole idempotency story rests on, and it is the identifier §11 puts on every log + # line — which is what makes "log line -> record" a URL a reviewer can type. + # + # find_by! rather than find_by plus an explicit render: ApplicationController maps + # ActiveRecord::RecordNotFound to the one 404 body, so the miss and the hit share a + # single code path. + def show + event = PushEvent.preload(:github_actor, :github_repository) + .find_by!(github_event_id: params[:id]) + + render json: { data: Inspection::PushEventView.detail(event) } + end + + private + + # RFC 8288 — the same relation Github::LinkHeader reads off GitHub's own /events + # response, emitted here on ours. Deliberately *not* added to that module: its contract + # is that it only reads, and one header line is not worth inverting it. + # + # The body carries next_cursor too. The header is for clients that already speak Link + # (this application among them); the cursor is what a JSON-only client asserts on. + def set_next_link(page) + return if page.next_cursor.nil? + + response.set_header("Link", %(<#{next_page_url(page)}>; rel="next")) + end + + def next_page_url(page) + api_push_events_url( + { limit: page.limit, + cursor: page.next_cursor.encode, + actor_id: page.actor_id, + repository_id: page.repository_id }.compact + ) + end + end +end diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 4ac8823..82bb84f 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -1,2 +1,30 @@ class ApplicationController < ActionController::API + # One error body for every failure this application returns, and never a framework + # default. + # + # This is not tidiness. config.consider_all_requests_local is true in development *and* + # test, and this is an api_only application, so config.debug_exception_response_format + # defaults to :api — meaning an unrescued exception is rendered by + # ActionDispatch::DebugExceptions as JSON carrying the exception class **and its full + # backtrace**. HealthController already refuses to leak that way, reporting only + # e.class.name; these two handlers hold the same line for IMPLEMENTATION_PLAN.md §11's + # inspection endpoints, and give clients one error shape instead of two. + # + # The 404 message is fixed rather than read off the exception, for the same reason. + + rescue_from ActiveRecord::RecordNotFound do + render_error(:not_found, "not_found", "no record matches that identifier") + end + + # The message is safe to echo: Inspection::Errors::InvalidParameter builds it from the + # parameter *name* and a fixed phrase, never from the value the client sent. + rescue_from Inspection::Errors::InvalidParameter do |error| + render_error(:bad_request, "invalid_parameter", error.message, parameter: error.parameter) + end + + private + + def render_error(status, code, message, **details) + render json: { error: { code: code, message: message, **details } }, status: status + end end diff --git a/app/controllers/status_controller.rb b/app/controllers/status_controller.rb new file mode 100644 index 0000000..b7afc1a --- /dev/null +++ b/app/controllers/status_controller.rb @@ -0,0 +1,38 @@ +# IMPLEMENTATION_PLAN.md §11's GET /status: "reports persisted state only; **never +# initiates a GitHub request**." +# +# Structural rather than a promise, the way Github::Ingestion::StateSummary states it: this +# controller holds no executor and no transport, and Github::Status::Snapshot's only +# collaborators are Active Record models and pure values. Github::BudgetLedger is absent by +# construction — all four of its public methods write, and a read path must never create +# the row a reservation owns. +class StatusController < ApplicationController + # Narrowed to ActiveRecordError rather than StandardError, which is where this departs + # from HealthController#ready. That action's entire body is one SELECT 1, so every error + # it can raise really is a database error. Here a bug in the snapshot must surface as a + # 500 with its backtrace in the JSON log stream, not be laundered into a 503 that tells + # an operator the database is down. ConnectionNotEstablished, StatementInvalid and + # NoDatabaseError all descend from this, so the genuine cases are covered. + # + # Only the class name crosses the boundary — the same no-internals rule HealthController + # already holds. + rescue_from ActiveRecord::ActiveRecordError do |error| + render json: { status: "unavailable", reason: error.class.name }, + status: :service_unavailable + end + + # Always 200 while the database answers. A globally blocked ledger, a source out of + # service and an empty coverage window are the states this endpoint exists to report, + # not failures of the endpoint — answering 503 for an exhausted rate limit would pull the + # container out of a load balancer for something /health/live and /health/ready both + # correctly call healthy. + # + # no-store rather than no-cache: a snapshot is true for the instant it was taken, and an + # intermediary serving a stale ledger to an operator diagnosing a live rate limit is the + # one failure mode worth spending a header on. + def show + response.headers["Cache-Control"] = "no-store" + + render json: Github::Status::Snapshot.capture.payload + end +end diff --git a/app/services/github/configuration.rb b/app/services/github/configuration.rb index 4739a9a..f542865 100644 --- a/app/services/github/configuration.rb +++ b/app/services/github/configuration.rb @@ -38,7 +38,8 @@ class Configuration "ACTOR_ENRICHMENT_SHARE" => "0.50", "ENRICHMENT_ELIGIBILITY_WINDOW_SECONDS" => "3600", "ACTOR_REFRESH_TTL_SECONDS" => "86400", - "REPOSITORY_REFRESH_TTL_SECONDS" => "86400" + "REPOSITORY_REFRESH_TTL_SECONDS" => "86400", + "ENRICHMENT_COVERAGE_WINDOW_SECONDS" => "86400" }.freeze # A zero here is a broken configuration, not a conservative one: a zero interval @@ -50,6 +51,14 @@ class Configuration # so the sweep skips the entire backlog and enrichment can never run; a zero refresh # TTL makes every enriched entity instantly stale, turning off the freshness cache # §13 lists as a PR 7 capability. "Never refresh" is a large number, not zero. + # + # The coverage window is the fourth, and it fails the same way from the other end. It + # is the sole denominator of §11's three percentages, so a zero window puts every + # denominator at zero and Github::Enrichment::Coverage reports null for all three, + # permanently — §11's headline metric disabled by a number rather than by a decision. + # A negative value is worse than useless rather than merely useless: `now - (-N)` is a + # floor in the *future*, which empties the window just as completely while reading + # like a wider one. POSITIVE_INTEGERS = { poll_interval_seconds: "POLL_INTERVAL_SECONDS", max_pages_per_poll: "MAX_PAGES_PER_POLL", @@ -59,7 +68,8 @@ class Configuration source_lock_wait_seconds: "SOURCE_LOCK_WAIT_SECONDS", enrichment_eligibility_window_seconds: "ENRICHMENT_ELIGIBILITY_WINDOW_SECONDS", actor_refresh_ttl_seconds: "ACTOR_REFRESH_TTL_SECONDS", - repository_refresh_ttl_seconds: "REPOSITORY_REFRESH_TTL_SECONDS" + repository_refresh_ttl_seconds: "REPOSITORY_REFRESH_TTL_SECONDS", + enrichment_coverage_window_seconds: "ENRICHMENT_COVERAGE_WINDOW_SECONDS" }.freeze # Zero is meaningful for all three: no reserve, no retries, no redirects. @@ -76,15 +86,16 @@ class Configuration actor_enrichment_share: "ACTOR_ENRICHMENT_SHARE" }.freeze - # ENRICHMENT_COVERAGE_WINDOW_SECONDS is deliberately absent. §10 prints it in the - # same block as the three above, but it is an input to §11's coverage percentages, - # which §13 assigns to PR 10 — and §16 forbids speculative infrastructure. + # enrichment_coverage_window_seconds is the odd one out and worth naming as such: every + # other knob here changes what the system *does*, and this one changes only what + # Github::Enrichment::Coverage *reports*. Nothing schedules, reserves, or defers on it. attr_reader :mode, :fixture_scenario, :poll_interval_seconds, :max_pages_per_poll, :enabled_live_source_count, :rate_limit_reserve, :http_open_timeout_seconds, :http_read_timeout_seconds, :max_http_retries, :max_redirects, :source_lock_wait_seconds, :actor_enrichment_share, :enrichment_eligibility_window_seconds, - :actor_refresh_ttl_seconds, :repository_refresh_ttl_seconds + :actor_refresh_ttl_seconds, :repository_refresh_ttl_seconds, + :enrichment_coverage_window_seconds def initialize(env = ENV) @mode = read(env, "GITHUB_MODE").downcase diff --git a/app/services/github/enrichment/coverage.rb b/app/services/github/enrichment/coverage.rb new file mode 100644 index 0000000..7a29955 --- /dev/null +++ b/app/services/github/enrichment/coverage.rb @@ -0,0 +1,163 @@ +module Github + module Enrichment + # IMPLEMENTATION_PLAN.md §11's three enrichment coverage percentages, computed over + # ENRICHMENT_COVERAGE_WINDOW_SECONDS. + # + # The piece Github::Enrichment::Summary names and defers — "deliberately not the + # percentages, which need ENRICHMENT_COVERAGE_WINDOW_SECONDS and a join against + # push_events". Both arrive with PR 10, and this is where they land. + # + # **It never initiates a GitHub request**, structurally and for the reason + # Github::Ingestion::StateSummary gives: no executor, no transport, no ledger. It does + # not read github_api_budget at all — one SELECT, and nothing that writes. + # + # ## The window is measured on created_at, not occurred_at + # + # Coverage grades *this application's* enrichment pipeline, and that pipeline runs on + # this application's clock throughout: eligibility is + # COALESCE(last_seen_at, created_at) > floor (Github::Enrichment::CandidateSelector), + # staleness is fetched_at + TTL, and the budget refills on a wall-clock rate-limit + # window. A denominator defined by GitHub's event clock would mix two clocks inside one + # ratio. §11's own wording — "distinct **persisted** push events in the coverage + # window" — reads the same way, and after downtime created_at is the basis that answers + # the question an operator is actually asking. + # + # It also keeps the offline reviewer path honest. §12 makes the fixture corpus the + # deterministic path and §16 makes these percentages an Operability gate, but the + # corpus pins its envelope timestamps to a fixed date — so an occurred_at basis reports + # three nulls to anyone running the walkthrough after that date, on a database that + # demonstrably holds enriched events. + # + # Rejected alternative, recorded because it is a real one: occurred_at is the indexed + # column (index_push_events_on_occurred_at) and reads as "GitHub activity in the last N + # seconds". The cost of not using it is a sequential scan, accepted deliberately — at + # the pinned defaults the feed yields on the order of 3,000 rows a day, so a month is + # under 100k rows, and spec/db/schema_spec.rb already states this repository's posture + # on raw_payload: no index until a query demands one. Note also that created_at is + # always >= occurred_at, so the occurred_at window is a strict *subset* of this one — + # the rows it drops are exactly the high-latency catch-up events, and removing them + # from the denominator alone would inflate the reported percentage. + # + # The basis is published in #payload rather than left implicit, so the choice is + # reviewable from the response instead of only from this comment. + class Coverage < Data.define(:window_seconds, :window_start, :event_count, + :actor_count, :complete_actor_count, + :repository_count, :complete_repository_count, + :both_complete_event_count) + # One of Enrichable::ENRICHMENT_STATUSES, interpolated rather than bound: it is a code + # constant that a CHECK constraint enforces and that db/schema.rb already inlines into + # two partial-index predicates, so there is no caller input here to bind. A spec pins + # it against the enum, so a renamed status cannot leave this filtering on a value that + # no longer exists. + COMPLETE = "complete".freeze + + ACTOR_COMPLETE = "github_actors.enrichment_status = '#{COMPLETE}'".freeze + REPOSITORY_COMPLETE = "github_repositories.enrichment_status = '#{COMPLETE}'".freeze + + # `>` rather than `>=`, matching CandidateSelector's eligibility floor — one window + # convention in this codebase, not two. The table qualifier is mandatory rather than + # tidy: all three joined tables carry created_at, so an unqualified column is + # ambiguous and PostgreSQL rejects the statement. + # + # No upper bound. A future-dated row is clock skew, and excluding it would remove the + # same row from the numerator and the denominator together — the eligibility window + # has none either, for the same reason. + WINDOW_CLAUSE = "push_events.created_at > :floor".freeze + + # §11's three formulas, as six counts taken in one pass. + # + # COUNT(DISTINCT …) is what keeps the entity ratios honest: an actor referenced by two + # hundred events in the window is one actor on *both* sides of its own ratio, while + # the event ratio counts rows. The event denominator needs no DISTINCT of its own — + # the unique index on github_event_id plus PushEvent.insert_if_new's ON CONFLICT DO + # NOTHING mean a re-polled window never produces a second row for one event. + # + # FILTER rather than SUM(CASE …) because it is the same plan and states the intent. + COUNTS = { + event_count: "COUNT(*)", + actor_count: "COUNT(DISTINCT push_events.github_actor_id)", + complete_actor_count: + "COUNT(DISTINCT push_events.github_actor_id) FILTER (WHERE #{ACTOR_COMPLETE})", + repository_count: "COUNT(DISTINCT push_events.github_repository_id)", + complete_repository_count: + "COUNT(DISTINCT push_events.github_repository_id) FILTER (WHERE #{REPOSITORY_COMPLETE})", + both_complete_event_count: + "COUNT(*) FILTER (WHERE #{ACTOR_COMPLETE} AND #{REPOSITORY_COMPLETE})" + }.freeze + + # Two decimals. §10 sizes the honest steady state at a low single-digit percentage, so + # the second decimal is the one that moves; a fourth would read as precision the + # sampling rate does not have. + PRECISION = 2 + + # The basis, published so a consumer never has to guess which clock bounds the window. + BASIS = "created_at".freeze + + # joins(:github_actor, :github_repository) rather than hand-written ON clauses, so the + # join keys come from the associations PushEvent already declares with + # primary_key: :github_id and a schema change cannot silently desynchronise them. + # + # INNER is correct rather than merely convenient: both foreign key columns are NOT + # NULL and both carry real foreign keys to a UNIQUE github_id, so each join matches + # exactly one row. It can neither drop a push event from the denominator nor duplicate + # one into it — which is the property that lets all six counts share one pass and + # still agree with six separate queries. + def self.capture(now: Time.current, configuration: Github.configuration) + window_seconds = configuration.enrichment_coverage_window_seconds + window_start = now - window_seconds + + values = PushEvent.joins(:github_actor, :github_repository) + .where(WINDOW_CLAUSE, floor: window_start) + .pick(*COUNTS.each_value.map { |expression| Arel.sql(expression) }) + + new(window_seconds: window_seconds, window_start: window_start, + **COUNTS.keys.zip(Array(values).map(&:to_i)).to_h) + end + + def actor_coverage_pct = percentage(complete_actor_count, actor_count) + def repository_coverage_pct = percentage(complete_repository_count, repository_count) + + def events_with_both_entities_enriched_pct + percentage(both_complete_event_count, event_count) + end + + # Every count and every denominator, not only the three percentages. A ratio whose + # denominator is hidden cannot be checked, and "100.0% actor coverage" printed alone + # over a single actor is exactly the misleading guarantee §16 forbids. + def payload + { window_seconds: window_seconds, + window_start: Ingestion::Report.timestamp(window_start), + basis: BASIS, + event_count: event_count, + actor_count: actor_count, + complete_actor_count: complete_actor_count, + actor_coverage_pct: actor_coverage_pct, + repository_count: repository_count, + complete_repository_count: complete_repository_count, + repository_coverage_pct: repository_coverage_pct, + both_complete_event_count: both_complete_event_count, + events_with_both_entities_enriched_pct: events_with_both_entities_enriched_pct } + end + + def to_log + { coverage_window_seconds: window_seconds, coverage_event_count: event_count, + actor_coverage_pct: actor_coverage_pct, + repository_coverage_pct: repository_coverage_pct, + events_with_both_entities_enriched_pct: events_with_both_entities_enriched_pct } + end + + private + + # nil, never 0.0. An empty window has no coverage percentage — the ratio is undefined + # rather than zero — and 0.0 there reads as "nothing is enriched" when the truth is + # "there is nothing in the window to enrich". §16 forbids exactly that fabricated + # zero, and #payload publishes the denominator beside every ratio, so nil is + # self-explanatory rather than a gap. + def percentage(numerator, denominator) + return nil if denominator.zero? + + (100.0 * numerator / denominator).round(PRECISION) + end + end + end +end diff --git a/app/services/github/enrichment/summary.rb b/app/services/github/enrichment/summary.rb index 0ac57b0..1969fd1 100644 --- a/app/services/github/enrichment/summary.rb +++ b/app/services/github/enrichment/summary.rb @@ -7,9 +7,10 @@ module Enrichment # different questions and §13 splits them across two PRs: StateSummary is §9's # proof-of-state for the *polling* command, and §11 assigns the coverage percentages to # PR 10's /status. What lands here is the part PR 7's own outcome would otherwise be - # invisible without — the per-status counts and the per-class share usage §10 defines — - # and deliberately not the percentages, which need ENRICHMENT_COVERAGE_WINDOW_SECONDS - # and a join against push_events. + # invisible without — the per-status counts and the per-class share usage §10 defines. + # The percentages themselves are Github::Enrichment::Coverage, which needs + # ENRICHMENT_COVERAGE_WINDOW_SECONDS and a join against push_events; both arrived with + # PR 10, and /status renders the two objects side by side. # # **It never initiates a GitHub request**, structurally and for StateSummary's reason: # no executor, no transport, no ledger — three read statements over Active Record @@ -19,10 +20,20 @@ module Enrichment class Summary < Data.define(:actor_counts, :repository_counts, :actor_share_used, :repository_share_used, :actor_guarantee, :repository_guarantee, :enrichment_used, - :enrichment_allowance, :window_status, :next_enrichment_at) + :enrichment_allowance, :window_status, :claimable_now, + :next_enrichment_at) NO_LEDGER = "not yet initialized".freeze DUE_NOW = "due now".freeze + # next_enrichment_at is nil in two states that are not the same fact: something is + # claimable *right now*, and nothing will ever become claimable without new ingest + # activity. Printing "due now" for both was wrong on an empty backlog — bin/enrich + # would say work was due in the same breath it reported nothing to enrich — and + # publishing the same nil as JSON would hand /status's consumers the identical + # ambiguity. claimable_now is the member that separates them; this is the label for + # the other side. + NOTHING_WAITING = "nothing waiting".freeze + # The three statuses an operator acts on. permanent_failure and retryable_failure are # rolled into the pending/complete/skipped triple's remainder rather than printed # separately: §11's line is "pending/skipped counts", and a five-column row would @@ -30,10 +41,18 @@ class Summary < Data.define(:actor_counts, :repository_counts, :actor_share_used REPORTED_STATUSES = %w[ pending complete skipped_budget ].freeze class << self + # @param budget [GithubApiBudget, nil] the ledger row, when the caller already holds + # it. Github::Status::Snapshot passes one so /status reads the singleton exactly + # once: three independent find_by calls could straddle a committing reservation + # and produce one response whose poll block contradicts its ledger block. The + # default keeps every existing caller reading it here, and keeps reading it with + # find_by rather than through Github::BudgetLedger, because a read path must not + # create the row. def capture(now: Time.current, configuration: Github.configuration, - selector: CandidateSelector.new(configuration: configuration)) - budget = GithubApiBudget.find_by(id: GithubApiBudget::SINGLETON_ID) + selector: CandidateSelector.new(configuration: configuration), + budget: GithubApiBudget.find_by(id: GithubApiBudget::SINGLETON_ID)) guarantees = guarantees_for(budget, configuration) + claimable = claimable_now?(budget, selector, now: now) new( actor_counts: counts(GithubActor), @@ -44,7 +63,8 @@ def capture(now: Time.current, configuration: Github.configuration, enrichment_used: budget&.enrichment_used, enrichment_allowance: budget&.enrichment_allowance, window_status: budget&.window_status, - next_enrichment_at: next_enrichment_at(budget, selector, now: now) + claimable_now: claimable, + next_enrichment_at: next_enrichment_at(budget, selector, claimable, now: now) ) end @@ -72,15 +92,33 @@ def guarantees_for(budget, configuration) # complete row deferred by a failed refresh was invisible for the same reason; and # one candidate due now beside one deferred printed the deferred instant while work # was in fact claimable. - def next_enrichment_at(budget, selector, now:) - # A global block or a spent class outranks every per-entity instant, and is the - # one case where an answer exists without reading a single entity row. - global = [ budget&.global_blocked_until, budget&.enrichment_class_blocked_until(now: now) ].compact.max - return global if global&.>(now) - return nil if EntityType.all.any? { |type| selector.claimable?(type, now: now) } + def next_enrichment_at(budget, selector, claimable, now:) + blocked = blocked_until(budget, now: now) + return blocked if blocked + return nil if claimable EntityType.all.filter_map { |type| selector.earliest_claimable_at(type, now: now) }.min end + + # "A request would be issued if the runner ran right now." Both pools, and the + # ledger asked first: a global block or a spent class outranks every per-entity + # instant, and is the one case where the answer exists without reading an entity + # row at all. + def claimable_now?(budget, selector, now:) + return false if blocked_until(budget, now: now) + + EntityType.all.any? { |type| selector.claimable?(type, now: now) } + end + + # nil unless the instant is genuinely still ahead: BudgetLedger derives blocking + # from the timestamp rather than from the label precisely so an expired one cannot + # strand the row, and this reader has to agree with it. + def blocked_until(budget, now:) + blocked = [ budget&.global_blocked_until, + budget&.enrichment_class_blocked_until(now: now) ].compact.max + + blocked if blocked&.>(now) + end end def to_s @@ -102,7 +140,7 @@ def to_log actor_share_used: actor_share_used, repository_share_used: repository_share_used, actor_guarantee: actor_guarantee, repository_guarantee: repository_guarantee, enrichment_used: enrichment_used, enrichment_allowance: enrichment_allowance, - window_status: window_status, + window_status: window_status, claimable_now: claimable_now, next_enrichment_at: Ingestion::Report.timestamp(next_enrichment_at) }.compact end @@ -121,8 +159,14 @@ def share_line(used, allowance) "#{Ingestion::Report.count(used)} of #{Ingestion::Report.count(allowance)}" end + # Three answers, not two. A nil instant means "no deferral applies", which is true + # both when a candidate is claimable this second and when the backlog is empty — + # and an operator reads those two states completely differently. claimable_now is + # what tells them apart; without it this line said "due now" to a reviewer whose + # very next line of output was "nothing to enrich". def next_enrichment - return DUE_NOW if next_enrichment_at.nil? + return DUE_NOW if claimable_now + return NOTHING_WAITING if next_enrichment_at.nil? Ingestion::Report.timestamp(next_enrichment_at) end diff --git a/app/services/github/enrichment_runner.rb b/app/services/github/enrichment_runner.rb index 55d964d..f4a0e2c 100644 --- a/app/services/github/enrichment_runner.rb +++ b/app/services/github/enrichment_runner.rb @@ -46,7 +46,7 @@ class EnrichmentRunner class Result < Data.define(:status, :entity_type, :github_id, :pool, :borrow, :classification, :enrichment_status, :last_error, :error_code, :deferral_reason, :next_retry_at, :aged_out, - :duration_ms) + :duration_ms, :enrichment_attempt) STATUSES = %w[ enriched failed deferred idle lease_lost ].freeze # §11 names the INFO events "enrichment completed/failed/skipped/reactivated", so the @@ -62,7 +62,7 @@ class Result < Data.define(:status, :entity_type, :github_id, :pool, :borrow, def initialize(status:, entity_type: nil, github_id: nil, pool: nil, borrow: false, classification: nil, enrichment_status: nil, last_error: nil, error_code: nil, deferral_reason: nil, next_retry_at: nil, - aged_out: 0, duration_ms: nil) + aged_out: 0, duration_ms: nil, enrichment_attempt: nil) raise ArgumentError, "unknown status #{status.inspect}" unless STATUSES.include?(status) super @@ -80,7 +80,8 @@ def attempted? = enriched? || failed? || lease_lost? def to_log { enrichment_outcome: status, entity_type: entity_type, github_id: github_id, pool: pool, borrow: (true if borrow), classification: classification, - entity_status: enrichment_status, error_code: error_code, + entity_status: enrichment_status, enrichment_attempt: enrichment_attempt, + error_code: error_code, error_message: last_error, deferral_reason: deferral_reason, next_retry_at: next_retry_at&.utc&.iso8601, aged_out: (aged_out if aged_out.positive?), duration_ms: duration_ms }.compact @@ -150,7 +151,14 @@ def enrich(choice, lease, aged:, started:) # PageWriter's reasoning: an unexpected error "is a defect to fix, not a payload to # classify". Fabricating an entity status from one would make the defect durable. @claim.release!(lease) - Rails.logger.error(event: "enrichment.failed", **lease.to_log, + # enrichment.cycle_failed, not enrichment.failed: Result::EVENTS owns that name for + # the *ordinary* outcome §11 lists — INFO, with an entity status and a scheduled + # retry. This is an escaped exception with a released lease, an error pair and no + # entity outcome at all, and one event name carrying two field sets means an alert + # filtered on it matches two structurally different records. + # PollEventSourceJob's ingestion.cycle_failed is the same fact one level up, and + # shares its name deliberately. + Rails.logger.error(event: "enrichment.cycle_failed", **lease.to_log, error_class: error.class.name, error_message: error.message) raise end @@ -184,6 +192,11 @@ def complete(choice, lease, fetched, written, aged:, started:) status: written.outcome, entity_type: choice.entity_type.key, github_id: lease.github_id, pool: choice.pool, borrow: choice.borrow, classification: fetched.classification, enrichment_status: written.enrichment_status, + # §11's "attempt number", spelled enrichment_attempt for the reason #request_for's + # comment gives: `attempt` on a github.* line is the HTTP one. lease.to_log already + # carries this onto the DEBUG request line; without it here it never reaches the + # INFO outcome line, which is the line §11 actually asks reviewers to read. + enrichment_attempt: lease.enrichment_attempts + 1, last_error: written.last_error, error_code: written.error_code, deferral_reason: (fetched.classification.to_s if written.deferred?), next_retry_at: written.next_retry_at, aged_out: aged, diff --git a/app/services/github/fetch_result.rb b/app/services/github/fetch_result.rb index be45307..38343ee 100644 --- a/app/services/github/fetch_result.rb +++ b/app/services/github/fetch_result.rb @@ -34,6 +34,21 @@ class FetchResult < Data.define( # reschedules rather than recording a failure (§9, §10). DEFERRED_CLASSIFICATIONS = %i[ budget_denied gate_unavailable ].freeze + # A conclusion was reached and it was a failure — the set §16's "failures contain + # actionable context" is about, and the one Github::RequestExecutor raises to warning + # level so it survives the default log_level of info. + # + # Neither deferral is one: nothing was attempted and nothing was spent, and the caller + # logs its own deferral line. Neither rate limit is one either — GitHub answered and + # declined, which §10 treats as something to reschedule rather than something that went + # wrong, and whose INFO line is budget.global_block_set, emitted once per block rather + # than once per request. :redirect is absent because it never escapes + # Github::RequestExecutor#follow_redirects: it is either followed or converted into + # RedirectLimitExceeded, which arrives here as :permanent_error. + FAILED_CLASSIFICATIONS = %i[ + not_found client_error server_error transport_error permanent_error + ].freeze + class << self def from_response(request:, status:, headers:, body:, duration_ms:, attempt: 0) new( @@ -64,6 +79,7 @@ def ok? = classification == :ok def not_modified? = classification == :not_modified def successful? = ResponseClassifier.successful?(classification) def deferred? = DEFERRED_CLASSIFICATIONS.include?(classification) + def failed? = FAILED_CLASSIFICATIONS.include?(classification) def header(name) headers[name.to_s.downcase] diff --git a/app/services/github/ingestion/poll_state.rb b/app/services/github/ingestion/poll_state.rb index 8ca263a..9c3842b 100644 --- a/app/services/github/ingestion/poll_state.rb +++ b/app/services/github/ingestion/poll_state.rb @@ -27,13 +27,18 @@ def initialize(configuration: Github.configuration, backoff: PollBackoff.new, end # @param outcome [Github::Ingestion::PageLoop::Outcome] + # @param run_id [String, nil] §11's correlation identifier, carried purely so the two + # failure lines below can be joined to the run that produced them. Optional because + # this class writes source state whether or not a run row exists, and a nil is + # compacted out rather than logged as null. # @return [Time, nil] the next_poll_at it wrote, which the runner puts on its Result # so the one-shot can name §9's "Ingestion deferred until T" for any reason. - def record!(event_source:, outcome:, now: @clock.call) + def record!(event_source:, outcome:, now: @clock.call, run_id: nil) attributes = outcome.attempted? ? attempted(event_source, outcome, now: now) : {} attributes[:next_poll_at] = projected(event_source, attributes, now: now) event_source.update!(attributes) + log_failure(event_source, outcome, attributes, run_id: run_id, now: now) attributes[:next_poll_at] end @@ -124,6 +129,60 @@ def projected(event_source, attributes, now:) PollSchedule.for(event_source: projection, now: now).effective_poll_time end + + # Logged from the attributes that were actually written, and only after the UPDATE + # committed them: a line claiming a source is out of service before the row says so is + # the one kind of log an operator cannot act on. Reading the written attributes rather + # than re-deriving outcome.source_failing also means a future second path to `failed` + # is reported without anyone remembering to extend this. + # + # This class logs rather than Github::IngestionRunner doing it on its behalf, for + # three reasons. Github::Enrichment::EntityState is this class's entity-side mirror and + # already logs three of its own anomalies, so a state writer announcing its own + # transitions is the established shape here. The runner would have to re-derive the + # predicate, and two readers of one rule is drift waiting to happen. And only this + # class knows the delay — backoff_seconds is retry_not_before_at minus its own `now`. + # + # ingestion.source_failed is §10's "/events returns permanent 4xx → source failed", and + # it was the largest failure-logging gap in the system: the transition is terminal and + # operator-recoverable only — nothing in this application writes `failed` back to + # `idle` — so it is the single poll outcome that will not resolve itself, and the only + # evidence of it was a status column nobody was told to read. Its entity-side twin, + # permanent_failure, already reaches the INFO stream as enrichment.failed's + # entity_status; this is the source-side line that was missing. + # + # It shares its token with IngestionRunner#out_of_service's deferral_reason, so one + # grep for source_failed returns the transition *and* every poll subsequently refused. + # + # ingestion.source_backoff is the counted-failure half. ingestion.run_completed already + # reports consecutive_failures and next_poll_at, but next_poll_at is the *maximum* of + # §9's five independent components, so it cannot say whether the source is deferred by + # its own backoff, by the server's poll floor, or by a global block. Naming the + # component and the delay is what makes the retry actionable — the same reason + # ingestion.not_due reports binding_component instead of only an instant. + # + # Nothing is logged for a run that was never attempted: attributes is empty, nothing + # was written, and the runner's own ERROR-level run_completed reports it. + def log_failure(event_source, outcome, attributes, run_id:, now:) + return unless outcome.failed? + + if attributes[:status] == "failed" + Rails.logger.error({ event: "ingestion.source_failed", run_id: run_id, + event_source_id: event_source.id, source_status: "failed", + classification: outcome.classification, + error_message: outcome.last_error }.compact) + elsif attributes[:retry_not_before_at] + retry_at = attributes[:retry_not_before_at] + + Rails.logger.warn({ event: "ingestion.source_backoff", run_id: run_id, + event_source_id: event_source.id, + classification: outcome.classification, + consecutive_failures: attributes[:consecutive_failures], + backoff_seconds: (retry_at - now).round(1), + retry_not_before_at: retry_at.utc.iso8601, + error_message: outcome.last_error }.compact) + end + end end end end diff --git a/app/services/github/ingestion/state_summary.rb b/app/services/github/ingestion/state_summary.rb index 59754ba..efb816b 100644 --- a/app/services/github/ingestion/state_summary.rb +++ b/app/services/github/ingestion/state_summary.rb @@ -14,8 +14,23 @@ module Ingestion # BudgetLedger#bootstrap! from a read path. # # Splitting the snapshot from its rendering is what lets a spec assert §9's "1,284" - # delimiter without inserting 1,284 rows, and it is the seam PR 10's /status consumes + # delimiter without inserting 1,284 rows, and it is the *pattern* PR 10's /status + # adopted — a read-only value object with .capture and no collaborator that writes — # while the one-shot consumes #to_s. + # + # /status does not consume this class, and deliberately. Github::Status::Snapshot reads + # the ledger row once and passes it into all three of its parts; composing this object + # with Github::Enrichment::Summary would read the singleton twice more, so a reservation + # committing mid-request could produce one response whose poll block contradicted its + # ledger block. It also collapses PollSchedule to a single instant, where §11 asks for + # the components. + # + # One name means two numbers across the two objects, and both are correct for their own + # question. pending_actor_count here is the enrichment_candidates scope — pending *plus* + # retryable_failure, which is what "still to enrich" means for the operator about to run + # bin/enrich. /status reports the literal status under that name and publishes the scope + # beside it as `candidates`, because a JSON consumer has no §9 context to disambiguate + # from. class StateSummary < Data.define( :latest_run_at, :latest_run_id, :push_event_count, :pending_actor_count, :pending_repository_count, diff --git a/app/services/github/ingestion_runner.rb b/app/services/github/ingestion_runner.rb index ae89dca..169e5a9 100644 --- a/app/services/github/ingestion_runner.rb +++ b/app/services/github/ingestion_runner.rb @@ -211,7 +211,8 @@ def finish(recorder, event_source, outcome, started_at:) # Poll state first: next_poll_at has to reflect both this run's own cadence and any # block the rate-limit policy wrote while the pages were being walked, and the run's # completion line reports it. - next_poll_at = @poll_state.record!(event_source: event_source, outcome: outcome) + next_poll_at = @poll_state.record!(event_source: event_source, outcome: outcome, + run_id: recorder.run_id) run = recorder.finish!(status: outcome.status, tally: outcome.tally, last_error: outcome.last_error) Rails.logger.public_send( diff --git a/app/services/github/request_executor.rb b/app/services/github/request_executor.rb index 9cdbab2..67daf35 100644 --- a/app/services/github/request_executor.rb +++ b/app/services/github/request_executor.rb @@ -45,11 +45,18 @@ def call(request) loop do result = follow_redirects(request, attempt: attempt) - return result unless @retry_policy.retry?(classification: result.classification, attempt: attempt) + unless @retry_policy.retry?(classification: result.classification, attempt: attempt) + return exhausted(result) + end + + # Computed once and both slept and logged, never recomputed: RetryPolicy jitters, so + # asking twice would report a delay this process never took. + backoff_seconds = @retry_policy.backoff_seconds(attempt) + log_retry_scheduled(result, backoff_seconds: backoff_seconds) # The backoff happens with no lock held and no reservation outstanding: the # previous attempt has already been debited and its gate hold released. - @sleeper.call(@retry_policy.backoff_seconds(attempt)) + @sleeper.call(backoff_seconds) attempt += 1 end end @@ -151,10 +158,62 @@ def failure(request, error, attempt:, classification: nil) ) end + # §11 names "retry scheduled" among the INFO events, and it is what makes §10's "retry + # up to MAX_HTTP_RETRIES with exponential backoff and jitter" observable rather than + # merely implemented. Without it a retried fetch is indistinguishable from a slow one, + # and the extra reservations it spends out of sixty an hour are invisible. + # + # Every §11 common field arrives free through FetchResult#to_log: it merges + # Request#to_log, whose context carries the run_id for a poll and the entity identifiers + # for an enrichment, so correlation needs no argument here. + # + # next_attempt is spelled out rather than left to arithmetic on a zero-based attempt, + # because the operator reading this line is being told what happens next. + def log_retry_scheduled(result, backoff_seconds:) + Rails.logger.info( + event: "github.retry_scheduled", **result.to_log, + next_attempt: result.attempt + 1, max_attempts: @retry_policy.max_attempts, + backoff_seconds: backoff_seconds.round(1) + ) + end + + # The loop stops for two different reasons and only one of them is news. A + # classification that was never retryable is an ordinary terminal outcome the caller + # already records; a retryable one that ran out of attempts is §10's "persist the + # failure after attempts are exhausted", and until now the stream could not tell them + # apart — "failed three times over seven seconds and gave up" was byte-identical to + # "failed once, permanently". + # + # WARN rather than ERROR, for the reason #log_result gives: the durable verdict belongs + # to the caller — a failed run, a retryable_failure entity — and this is the evidence + # behind it. With MAX_HTTP_RETRIES=0 the line still fires, carrying max_attempts: 0, + # which is the honest report that configuration rather than GitHub ended the attempt. + def exhausted(result) + return result unless RetryPolicy.retryable_classification?(result.classification) + return result unless result.attempt >= @retry_policy.max_attempts + + Rails.logger.warn(event: "github.retry_exhausted", **result.to_log, + max_attempts: @retry_policy.max_attempts) + result + end + # §11 pins the common fields; the JSON formatter merges a hash into the log root. - # DEBUG because §11 puts per-request lines there and keeps INFO for run summaries. + # + # The level is a function of the outcome, the way Github::IngestionRunner#finish and + # Github::Enrichment::Dispatch already vary theirs. §11 puts per-request lines at DEBUG + # and that is right for the ones that worked — but §11 also sizes the INFO stream so the + # events Story 4 asks reviewers to see are *in* it, and §16 requires failures to carry + # actionable context. config.log_level defaults to info, so before this a 500, a + # timeout, a refused URL and a deleted entity produced no HTTP detail at all in a + # running system: the classification, the status, the URL and the attempt number live + # here and nowhere else. + # + # One event name rather than two, so the same request never appears twice and + # `grep github.request` keeps meaning "every request". def log_result(result) - Rails.logger.debug(result.to_log.merge(event: "github.request")) + payload = { event: "github.request", **result.to_log } + + result.failed? ? Rails.logger.warn(payload) : Rails.logger.debug(payload) result end end diff --git a/app/services/github/retry_policy.rb b/app/services/github/retry_policy.rb index bd5e680..eb843e7 100644 --- a/app/services/github/retry_policy.rb +++ b/app/services/github/retry_policy.rb @@ -37,7 +37,7 @@ def initialize(max_attempts: Github.configuration.max_http_retries, random: Rand def retry?(classification:, attempt:) return false if attempt >= max_attempts - ResponseClassifier.retryable?(classification) || classification == :transport_error + self.class.retryable_classification?(classification) end # Full jitter on top of an exponential base. Jitter matters even with one process: @@ -66,6 +66,22 @@ def disposition(error) def classification_for(error) disposition(error) == :retry ? :transport_error : :permanent_error end + + # Whether this classification is retryable *at all*, with the attempt budget left out + # of the question. + # + # #retry? folds the two together, which is exactly what a caller deciding whether to + # loop again needs. A caller explaining why the loop *stopped* has to separate them: + # "never retryable" and "out of attempts" are different facts, and only the second is + # §10's "persist the failure after attempts are exhausted". Without the split, the + # exhaustion line would fire on every permanent 404. + # + # Named for the classification rather than as a bare retryable? because + # ResponseClassifier.retryable? answers a narrower question — only :server_error — + # and two same-named predicates with different answers is the drift trap. + def retryable_classification?(classification) + ResponseClassifier.retryable?(classification) || classification == :transport_error + end end end end diff --git a/app/services/github/status/ledger_state.rb b/app/services/github/status/ledger_state.rb new file mode 100644 index 0000000..88d49b0 --- /dev/null +++ b/app/services/github/status/ledger_state.rb @@ -0,0 +1,103 @@ +module Github + module Status + # The ledger half of IMPLEMENTATION_PLAN.md §11's /status: "window status, per-class + # used/allowance (actor_requests_used/available, repository_requests_used/available, + # poll used/allowance), remaining, reset_at, global_blocked_until, reserve." + # + # A projection of one already-loaded row plus one pure split. It issues no query of its + # own — Github::Status::Snapshot reads github_api_budget once and hands the row down, + # so every block of one response describes the same instant. + class LedgerState < Data.define(:present, :resource, :window_status, :limit, :remaining, + :reset_at, :observed_at, :window_initialized_at, + :reserve, :global_blocked_until, + :poll_used, :poll_allowance, + :enrichment_used, :enrichment_allowance, + :actor_share_used, :repository_share_used, + :actor_guarantee, :repository_guarantee) + class << self + # @param budget [GithubApiBudget, nil] nil on a clean checkout. Nothing seeds the + # row; only a reservation creates it. + def from(budget, configuration: Github.configuration) + return absent if budget.nil? + + guarantees = guarantees_for(budget, configuration) + + new(present: true, resource: budget.resource, window_status: budget.window_status, + limit: budget.limit, remaining: budget.remaining, reset_at: budget.reset_at, + observed_at: budget.observed_at, + window_initialized_at: budget.window_initialized_at, reserve: budget.reserve, + global_blocked_until: budget.global_blocked_until, + poll_used: budget.poll_used, poll_allowance: budget.poll_allowance, + enrichment_used: budget.enrichment_used, + enrichment_allowance: budget.enrichment_allowance, + actor_share_used: budget.actor_share_used, + repository_share_used: budget.repository_share_used, + actor_guarantee: guarantees.fetch(:actor), + repository_guarantee: guarantees.fetch(:repository)) + end + + # Every field null and one boolean saying why. "No ledger row at all" and "a window + # whose remaining is genuinely 0" are different facts an operator acts on + # differently, and without this flag both would render as an all-null-or-zero block. + # Spelled out rather than derived from .members so the null set is visible here. + def absent + new(present: false, resource: nil, window_status: nil, limit: nil, remaining: nil, + reset_at: nil, observed_at: nil, window_initialized_at: nil, reserve: nil, + global_blocked_until: nil, poll_used: nil, poll_allowance: nil, + enrichment_used: nil, enrichment_allowance: nil, actor_share_used: nil, + repository_share_used: nil, actor_guarantee: nil, repository_guarantee: nil) + end + + private + + # Derived from the ledger's **stored** enrichment_allowance, never from a fresh + # Allowances.derive. The allowances are fixed when the window is initialized and + # again when it rolls; a guarantee recomputed mid-window from a different total + # than the one reservations are checked against could exceed it, and /status would + # report headroom the ledger would refuse. The same call + # Github::Enrichment::Summary and Github::BudgetLedger#share_cap both make. + def guarantees_for(budget, configuration) + Allowances.split(budget.enrichment_allowance, configuration.actor_enrichment_share) + end + end + + # §11 writes "actor_requests_used/available". `available` never appears without the + # guarantee that produced it: on its own it cannot be told from the denominator, and + # a reader cannot check the subtraction. + # + # It is a **floor, not a ceiling**, and the distinction is load-bearing. §10 lets one + # class borrow the other's unspent capacity when the other has no currently eligible + # candidate, so a class does not stop at zero available — the real ceiling is the + # enrichment pair beside it. Clamped at zero because borrowing is what makes + # share_used exceed the guarantee, and a negative "available" reads as an accounting + # error rather than as the borrow it actually is. + def actor_available = available(actor_share_used, actor_guarantee) + def repository_available = available(repository_share_used, repository_guarantee) + + def payload + { present: present, resource: resource, window_status: window_status, + limit: limit, remaining: remaining, + reset_at: Ingestion::Report.timestamp(reset_at), + observed_at: Ingestion::Report.timestamp(observed_at), + window_initialized_at: Ingestion::Report.timestamp(window_initialized_at), + reserve: reserve, + global_blocked_until: Ingestion::Report.timestamp(global_blocked_until), + poll: { used: poll_used, allowance: poll_allowance }, + enrichment: { used: enrichment_used, allowance: enrichment_allowance }, + actor_requests: { used: actor_share_used, guarantee: actor_guarantee, + available: actor_available }, + repository_requests: { used: repository_share_used, + guarantee: repository_guarantee, + available: repository_available } } + end + + private + + def available(used, guarantee) + return nil if used.nil? || guarantee.nil? + + [ guarantee - used, 0 ].max + end + end + end +end diff --git a/app/services/github/status/snapshot.rb b/app/services/github/status/snapshot.rb new file mode 100644 index 0000000..ecb61f7 --- /dev/null +++ b/app/services/github/status/snapshot.rb @@ -0,0 +1,132 @@ +module Github + module Status + # Everything IMPLEMENTATION_PLAN.md §11 asks GET /status to report, taken as one + # snapshot of persisted state. + # + # **It never initiates a GitHub request**, and it is structural rather than a promise, + # exactly as Github::Ingestion::StateSummary states it: this class holds no executor, no + # transport and no ledger, and its only collaborators are Active Record models and pure + # value objects. Github::BudgetLedger is absent by construction — all four of its public + # methods write, and #bootstrap! would create from a read path the very row a + # reservation owns. Every ledger read here is find_by. Four specs pin it: a recording + # transport that must see nothing, an unchanged github_api_budget count, an unchanged + # event_sources count, and a SQL subscriber that must see no write statement. + # + # ## Why one aggregate rather than StateSummary + Summary side by side + # + # Three parts of this response need github_api_budget: the poll schedule, §11's ledger + # block, and the enrichment block. Composing the two existing summaries would read the + # singleton three times, so a reservation committing mid-request could produce one body + # whose poll block contradicts its ledger block. This reads the row **once** and passes + # it down. StateSummary additionally runs an unbounded PushEvent.count that §11 does not + # ask for here, collapses PollSchedule to a single instant behind a private method when + # §11 wants the components, and exposes neither poll_used, poll_allowance nor reserve. + # + # ## #payload, not #to_log + # + # A third rendering, deliberately named apart from the two that exist. #to_s is the + # CLI's column-aligned block and #to_log is the INFO stream's projection — and both + # #to_log implementations call .compact, dropping nil keys. A JSON client needs a fixed + # key set: a field that appears and disappears makes every consumer handle two shapes. + # Naming the three apart is what stops one being quietly changed to suit another. + class Snapshot < Data.define(:captured_at, :sources, :ledger, :enrichment, :coverage) + def self.capture(now: Time.current, configuration: Github.configuration) + budget = GithubApiBudget.find_by(id: GithubApiBudget::SINGLETON_ID) + runs = latest_runs + + new( + captured_at: now, + sources: EventSource.order(:id).map do |event_source| + SourceState.from(event_source, budget: budget, + last_run: runs[event_source.id], now: now) + end, + ledger: LedgerState.from(budget, configuration: configuration), + enrichment: Enrichment::Summary.capture(now: now, configuration: configuration, + budget: budget), + coverage: Enrichment::Coverage.capture(now: now, configuration: configuration) + ) + end + + # Every source's latest *finished* run, whatever its outcome — §11 asks /status for the + # "last run", and the field is named last_run rather than last_successful_run because + # that is what it is. + # + # Deliberately not IngestionRun.latest_successful, which is §9's question and belongs + # to Github::Ingestion::StateSummary's "Latest successful run" line. Filtering to + # successes here would hide a fresh failed or deferred run behind an older 200 or 304, + # so an operator opening /status to find out why nothing is moving would be shown a + # healthy last_run for a source that had just failed or backed off — the one state + # this endpoint exists to surface. The status is in the payload, so a failed run + # reports itself rather than being inferred from its absence. + # + # completed_at IS NOT NULL stays: it excludes exactly the `running` status, a run + # still in flight that has reached no outcome to report. It is also what the ORDER BY + # sorts on, so a NULL would sort unpredictably against the rest. + # + # One statement for every source rather than one per source: DISTINCT ON collapses to + # the first row of each event_source_id group, and the ORDER BY defines "first". id + # DESC is the tie-break for two runs that finished in the same microsecond — without + # it the winner is whichever the plan happened to emit. + def self.latest_runs + IngestionRun.where.not(completed_at: nil) + .select("DISTINCT ON (event_source_id) event_source_id, run_id, status, completed_at") + .order(:event_source_id, completed_at: :desc, id: :desc) + .index_by(&:event_source_id) + end + private_class_method :latest_runs + + # §11's key set, in §11's order: poll state, ledger state, then the enrichment + # counters and coverage percentages. + # + # `null` throughout, never a sentinel string and never a missing key. §16's rule is + # that an unknown must not read as a zero, and the way to honour that in JSON is not + # to swap the type — a `remaining` that is sometimes an Integer and sometimes + # "not yet initialized" forces every consumer to type-check. It is: a counted zero + # prints 0, a number that does not exist prints null, and wherever null would carry + # two meanings the disambiguating fact gets its own field — ledger.present, due_now, + # claimable_now. + def payload + { captured_at: Ingestion::Report.timestamp(captured_at), + sources: sources.map(&:payload), + ledger: ledger.payload, + enrichment: enrichment_payload, + coverage: coverage.payload } + end + + private + + # §11's "pending_actor_count / pending_repository_count / skipped_actor_count / + # skipped_repository_count", and the reason all five statuses are published rather + # than those two. + # + # §11 lists pending_* beside skipped_*, and skipped_budget is a value of + # Enrichable::ENRICHMENT_STATUSES — so its sibling is the status value too, and + # `pending` here means enrichment_status = 'pending' exactly. + # Github::Ingestion::StateSummary uses the same *name* for a different number: the + # enrichment_candidates scope, which is pending **plus** retryable_failure and is + # what "still to enrich" means when the question is how much work is left. Both are + # right for their own question, and publishing one of them under a name the other + # also uses is how two numbers silently become one. So this block names both: + # every status by its own name, and the scope as `candidates`. + def enrichment_payload + { actors: entity_counts(enrichment.actor_counts), + repositories: entity_counts(enrichment.repository_counts), + claimable_now: enrichment.claimable_now, + next_enrichment_at: Ingestion::Report.timestamp(enrichment.next_enrichment_at) } + end + + # fetch(status, 0) because GROUP BY returns no key for a status with no rows, and an + # absent key here would be the missing-key shape the payload rule forbids. These + # zeros are counted, not fabricated: the table was read and held nothing. + def entity_counts(counts) + Enrichable::ENRICHMENT_STATUSES.index_with { |status| counts.fetch(status, 0) } + .symbolize_keys + .merge(candidates: candidates(counts)) + end + + def candidates(counts) + Enrichable::CANDIDATE_STATUSES.sum { |status| counts.fetch(status, 0) } + end + end + end +end diff --git a/app/services/github/status/source_state.rb b/app/services/github/status/source_state.rb new file mode 100644 index 0000000..c4dc251 --- /dev/null +++ b/app/services/github/status/source_state.rb @@ -0,0 +1,74 @@ +module Github + module Status + # The poll half of IMPLEMENTATION_PLAN.md §11's /status: "poll state (scheduling + # components, last run)". + # + # One of these per event_sources row. §9's one-shot prints a single block because it + # runs one command against one source, and Github::Ingestion::StateSummary picks + # `EventSource.order(:id).first` accordingly — but /status describes the whole + # installation, and picking one row would name the wrong one in the database reviewers + # actually build. source_type carries no unique constraint, the README's reviewer path + # creates a second github_fixture_events row beside the live one, and + # ENABLED_LIVE_SOURCE_COUNT is an input to §10's allowance formula precisely because + # more than one live source is a supported configuration. So Snapshot renders an array + # at every cardinality, including one and zero. + class SourceState < Data.define(:id, :source_type, :enabled, :status, + :consecutive_failures, :last_polled_at, + :last_success_at, :schedule, :last_run, :now) + # @param event_source [EventSource] + # @param budget [GithubApiBudget, nil] the row Snapshot already read. + # @param last_run [IngestionRun, nil] this source's most recent successful run. + # @param now [Time] carried as a member rather than re-read in #payload. One + # poll_class_blocked_until is derived from it and one due? compares against it, and + # a snapshot whose two halves consulted the clock separately could report a source + # both blocked and due. + def self.from(event_source, budget:, last_run:, now:) + new(id: event_source.id, source_type: event_source.source_type, + enabled: event_source.enabled, status: event_source.status, + consecutive_failures: event_source.consecutive_failures, + last_polled_at: event_source.last_polled_at, + last_success_at: event_source.last_success_at, + schedule: PollSchedule.for(event_source: event_source, budget: budget, now: now), + last_run: last_run, now: now) + end + + # The five components computed live rather than the stored next_poll_at column. + # Github::Ingestion::PollState is explicit that nothing reads that column back to make + # a decision, because a cached instant goes stale the moment a block clears — and a + # status endpoint reporting a stale instant is the same mistake with a wider audience. + # + # due_now is emitted beside next_poll_at because nil here means "no constraint + # applies", not "unknown", and JSON has no way to say which without being told. + # scheduling_components carries only the constraints in play; binding_component names + # which of them produced the answer, so an operator changes one thing rather than + # auditing five. + def payload + components = schedule.components + + { id: id, source_type: source_type, enabled: enabled, status: status, + consecutive_failures: consecutive_failures, + last_polled_at: Ingestion::Report.timestamp(last_polled_at), + last_success_at: Ingestion::Report.timestamp(last_success_at), + due_now: schedule.due?(now: now), + next_poll_at: Ingestion::Report.timestamp(schedule.effective_poll_time), + binding_component: schedule.binding_component, + scheduling_components: PollSchedule::COMPONENTS.index_with do |name| + Ingestion::Report.timestamp(components[name]) + end, + last_run: run_payload } + end + + private + + # nil rather than an all-null object: "this source has never completed a run" is one + # fact, and spelling it as a nested shape of nulls would invite a consumer to read + # fields off it. + def run_payload + return nil if last_run.nil? + + { run_id: last_run.run_id, status: last_run.status, + completed_at: Ingestion::Report.timestamp(last_run.completed_at) } + end + end + end +end diff --git a/app/services/inspection.rb b/app/services/inspection.rb new file mode 100644 index 0000000..4a4225b --- /dev/null +++ b/app/services/inspection.rb @@ -0,0 +1,32 @@ +# IMPLEMENTATION_PLAN.md §11's event inspection API. +# +# The two limits every parameter destined for the database has to respect. They are +# properties of PostgreSQL's column types, not policy, which is why they are constants here +# rather than configuration — and why they are stated once for the two parsers that need +# them (Inspection::PushEventPage validates query parameters, Inspection::Cursor validates +# a position a client hands back). +# +# Both were verified against PostgreSQL 16 rather than taken from documentation, because +# the two paths fail *differently* and only one of them fails loudly: +# +# * A raw bind — the seek predicate's `push_events.id < :id` — raises +# ActiveRecord::RangeError (PG::NumericValueOutOfRange) one past BIGINT_MAX, which +# would surface as a 500. +# * A typed-column bind — `where(github_actor_id: …)` — does **not** raise. Active +# Record casts the out-of-range value and the query returns normally, so an id no row +# could ever hold produces a silent empty page that is indistinguishable from a +# genuine miss. +# +# The second is the reason these are checked in the parsers rather than left to the +# database: refusing the value up front is the only way both paths give the client the +# documented 400 instead of a 500 in one case and a plausible lie in the other. +module Inspection + # PostgreSQL bigint, which is the type of push_events.id, github_actor_id and + # github_repository_id. Verified: 2**63 - 1 binds cleanly and 2**63 raises. + BIGINT_MAX = 2**63 - 1 + + # PostgreSQL's timestamp ceiling. Verified: year 294276 binds cleanly and 294277 raises + # PG::DatetimeFieldOverflow. Ruby's Time.iso8601 happily parses years far beyond it, so + # a forged cursor reaches the database unless something between them says no. + MAX_TIMESTAMP_YEAR = 294_276 +end diff --git a/app/services/inspection/cursor.rb b/app/services/inspection/cursor.rb new file mode 100644 index 0000000..99d8ffd --- /dev/null +++ b/app/services/inspection/cursor.rb @@ -0,0 +1,69 @@ +module Inspection + # Keyset pagination's position marker: the (occurred_at, id) of the last row a page + # returned. + # + # Opaque rather than two plain query parameters, for a reason specific to this schema. + # The tiebreak has to be the surrogate primary key — occurred_at is not unique, since one + # poll commits a whole page of events, and github_event_id is text with no ordering index + # — but IMPLEMENTATION_PLAN.md §7 keeps that surrogate key out of this application's + # identity vocabulary entirely, to the point that even the foreign keys target github_id. + # Encoding it keeps the ordering contract on the server and makes a client that hard-codes + # "id > n" impossible to write. + # + # This is encoding, not security. Nothing is signed and nothing needs to be: .decode + # yields a Time and a non-negative Integer or it yields nil, and both reach PostgreSQL as + # bound parameters. A forged cursor can only ask for a different page of public data. + # + # Base64 needs no Gemfile entry — activesupport already depends on it. + class Cursor < Data.define(:occurred_at, :id) + SEPARATOR = "|".freeze + + # Microseconds, because push_events.occurred_at is timestamp(6). Truncating to whole + # seconds would make the cursor ambiguous inside a single second — which is exactly the + # window one poll writes an entire page of events into, and therefore exactly where a + # page boundary is most likely to fall. + PRECISION = 6 + + class << self + def from(record) + new(occurred_at: record.occurred_at, id: record.id) + end + + # @return [Cursor, nil] nil for anything this cannot read — including anything the + # *database* could not read. The caller turns that into a 400 rather than silently + # restarting from the top: a paging client that corrupts its cursor and gets page one + # back would loop forever without ever seeing an error. + # + # Both halves need a range check, and neither is hypothetical, because both reach + # the seek predicate as raw binds where PostgreSQL raises rather than casts. An id + # past BIGINT_MAX raises PG::NumericValueOutOfRange, and Time.iso8601 will happily + # parse a year in the hundreds of millions that raises PG::DatetimeFieldOverflow. + # Either would surface as a 500 on input a client fully controls. + def decode(value) + return nil if value.blank? + + timestamp, id = Base64.urlsafe_decode64(value.to_s).split(SEPARATOR, 2) + return nil unless timestamp.present? && id.to_s.match?(/\A\d+\z/) + + position = new(occurred_at: Time.iso8601(timestamp), id: Integer(id, 10)) + position if representable?(position) + rescue ArgumentError + # Both urlsafe_decode64 and Time.iso8601 signal unreadable input this way. + nil + end + + private + + def representable?(position) + position.id.between?(0, BIGINT_MAX) && + position.occurred_at.year.between?(0, MAX_TIMESTAMP_YEAR) + end + end + + def encode + Base64.urlsafe_encode64( + "#{occurred_at.utc.iso8601(PRECISION)}#{SEPARATOR}#{id}", padding: false + ) + end + end +end diff --git a/app/services/inspection/errors.rb b/app/services/inspection/errors.rb new file mode 100644 index 0000000..2ff2bcd --- /dev/null +++ b/app/services/inspection/errors.rb @@ -0,0 +1,23 @@ +module Inspection + # Every error the inspection endpoints raise, in one file under one namespace — the + # shape Github::Errors already establishes, and the reason Zeitwerk needs no help + # mapping it. + module Errors + Error = Class.new(StandardError) + + # A query parameter this endpoint understands but cannot use, or one it does not + # understand at all. ApplicationController maps it to 400. + # + # The offending parameter is a reader rather than only a phrase inside the message, so + # the response can name it in a machine-readable key and a spec can assert on that + # instead of on prose. + class InvalidParameter < Error + attr_reader :parameter + + def initialize(parameter, detail) + @parameter = parameter.to_s + super("#{@parameter} #{detail}") + end + end + end +end diff --git a/app/services/inspection/push_event_page.rb b/app/services/inspection/push_event_page.rb new file mode 100644 index 0000000..a7a9bfd --- /dev/null +++ b/app/services/inspection/push_event_page.rb @@ -0,0 +1,151 @@ +module Inspection + # One page of GET /api/push_events (IMPLEMENTATION_PLAN.md §11): parameter parsing, the + # keyset query, and the answer to "is there a next page", as a value object the controller + # only renders. + # + # **It never initiates a GitHub request** — §11's standing guarantee for the whole + # health-and-inspection surface — and it is structural in exactly the way + # Github::Ingestion::StateSummary's is: no executor, no transport, no ledger, and its only + # collaborator is PushEvent. It also never writes; there is nothing here that could. + # + # .for takes anything answering #keys and #[], so a spec can pass a plain Hash and never + # construct ActionController::Parameters. + class PushEventPage < Data.define(:records, :limit, :cursor, :actor_id, + :repository_id, :next_cursor) + DEFAULT_LIMIT = 25 + + # A page costs the same three statements regardless of size — the keyset SELECT plus two + # preloads — so the thing that scales is the row count. 100 rows without raw_payload is + # still a response a human can read, and it is the ceiling GitHub's own list endpoints + # use. + MAX_LIMIT = 100 + + PERMITTED = %w[limit cursor actor_id repository_id].freeze + + # Rails' own, never the client's. format is here because the route declares + # defaults: { format: :json }. + RESERVED = %w[controller action format].freeze + + # \A\d+\z rather than Kernel#Integer, and the difference is not pedantry: + # Integer("010") is 8, Integer("0x10") is 22 and Integer("1_0") is 10, so three + # different query strings would silently mean something other than what they read as. + # These parameters are decimal or they are refused. + DECIMAL = /\A\d+\z/ + + class << self + def for(params) + reject_unknown!(params) + + build( + limit: parse_limit(params[:limit]), + cursor: parse_cursor(params[:cursor]), + actor_id: parse_github_id(:actor_id, params[:actor_id]), + repository_id: parse_github_id(:repository_id, params[:repository_id]) + ) + end + + private + + def build(limit:, cursor:, actor_id:, repository_id:) + # limit + 1, then discard the extra. That one row is the entire evidence a next page + # exists, and it costs one tuple; the alternative is a second statement whose + # COUNT(*) is a sequential scan over an append-only table, on every request. + rows = relation(cursor: cursor, actor_id: actor_id, repository_id: repository_id) + .limit(limit + 1) + .to_a + records = rows.first(limit) + + new(records: records, limit: limit, cursor: cursor, + actor_id: actor_id, repository_id: repository_id, + next_cursor: rows.length > limit ? Cursor.from(records.last) : nil) + end + + def relation(cursor:, actor_id:, repository_id:) + # preload, not eager_load: two additional IN (…) statements against the unique + # index_github_*_on_github_id, rather than a two-way LEFT JOIN whose wide rows would + # then have to be de-duplicated. Both associations declare primary_key: :github_id, + # which preloading honours. + # + # id DESC is not decoration. occurred_at is not unique — one poll commits a whole + # page of events, and several corpus events share an instant — so without the + # tiebreak the order inside a group is whatever the plan happens to produce, and a + # paging client would see rows twice or not at all. + scope = PushEvent.preload(:github_actor, :github_repository) + .order(occurred_at: :desc, id: :desc) + scope = scope.where(github_actor_id: actor_id) if actor_id + scope = scope.where(github_repository_id: repository_id) if repository_id + cursor ? seek(scope, cursor) : scope + end + + # Not "(occurred_at, id) < (?, ?)". The row-value form is equivalent and reads better, + # but PostgreSQL only pushes a row comparison into an index when a matching + # *multicolumn* index exists, and this schema carries only + # index_push_events_on_occurred_at — so that form degrades to a filter over a full + # scan. This form splits it: occurred_at <= ? is a plain range predicate the existing + # index drives directly, and the parenthesised clause is a cheap recheck over the rows + # it returns. + # + # The follow-up, when volume demands it, is an index on (occurred_at, id) and a + # rewrite to the row-value form — the same "no index until a query demands one" + # posture spec/db/schema_spec.rb already takes on raw_payload. + def seek(scope, cursor) + scope.where( + "push_events.occurred_at <= :at AND " \ + "(push_events.occurred_at < :at OR push_events.id < :id)", + at: cursor.occurred_at, id: cursor.id + ) + end + + # Blank means absent, for every parameter: "?limit=" is what a form serialiser emits + # for an untouched field, and refusing it would fail a client that asked for nothing + # unusual. + def parse_limit(value) + return DEFAULT_LIMIT if value.blank? + + # Refused rather than clamped to MAX_LIMIT. Clamping makes the response lie about + # what was asked — a client that requested 500 and received 100 cannot tell whether + # it received everything — and §16 rules out exactly that kind of misleading answer. + # The ceiling is named in the message so the correction takes one round trip. + unless value.to_s.match?(DECIMAL) && value.to_i.between?(1, MAX_LIMIT) + raise Errors::InvalidParameter.new(:limit, "must be an integer from 1 to #{MAX_LIMIT}") + end + + value.to_i + end + + def parse_cursor(value) + return nil if value.blank? + + Cursor.decode(value) || + raise(Errors::InvalidParameter.new(:cursor, "is not a cursor this endpoint issued")) + end + + # The upper bound is not belt and braces. github_actor_id and github_repository_id are + # signed bigints, and Active Record does *not* raise when a larger value is bound to a + # typed column — it casts it and the query returns normally, so an id no row could ever + # hold produces an empty page indistinguishable from a genuine miss. Refusing it here + # is the only way the client gets the documented 400 rather than a plausible lie. + def parse_github_id(name, value) + return nil if value.blank? + + unless value.to_s.match?(DECIMAL) && value.to_i.between?(1, BIGINT_MAX) + raise Errors::InvalidParameter.new(name, "must be a GitHub id from 1 to #{BIGINT_MAX}") + end + + value.to_i + end + + # Refused, not ignored. "?repo_id=5" is a plausible typo for repository_id, and + # ignoring it answers a question nobody asked with the entire unfiltered feed while + # looking exactly like a successful filtered response. #keys rather than + # #to_unsafe_h so this stays a Hash-friendly value object. + def reject_unknown!(params) + unknown = params.keys.map(&:to_s) - PERMITTED - RESERVED + return if unknown.empty? + + raise Errors::InvalidParameter.new(unknown.min, + "is not a parameter this endpoint accepts") + end + end + end +end diff --git a/app/services/inspection/push_event_view.rb b/app/services/inspection/push_event_view.rb new file mode 100644 index 0000000..c645e94 --- /dev/null +++ b/app/services/inspection/push_event_view.rb @@ -0,0 +1,105 @@ +module Inspection + # A push_events row, shaped for IMPLEMENTATION_PLAN.md §11's inspection endpoints. + # + # A module of functions rather than a method on PushEvent, following the convention this + # codebase already holds twenty times over: there are twenty #to_log methods and not one + # of them lives on a model. A model owns its columns, its constraints and its idempotent + # write; how a row is shaped for a reader belongs to the reader — and there are two + # readers here whose answers deliberately differ, so a single #to_api would need a mode + # flag on the model. + # + # Timestamps go through Github::Ingestion::Report.timestamp, the one formatter this + # application uses everywhere, so a value in this response and the same value in the JSON + # log stream are byte-identical and directly greppable. + module PushEventView + module_function + + # The list shape, and the single most consequential decision on this endpoint: + # raw_payload is absent. + # + # push_events.raw_payload is jsonb NOT NULL holding a complete GitHub event envelope — + # kilobytes once the commits array is in it — which puts essentially every row over + # PostgreSQL's TOAST threshold and out of line. Selecting it for a page is that many + # extra detoasts, for a field nobody scans a list for, in a response two orders of + # magnitude larger than the fields anyone reads. No index can soften it, deliberately: + # ADR 0001 and spec/db/schema_spec.rb both pin the absence of a GIN index. #detail + # returns it; a list does not. + def summary(event) + { + id: event.github_event_id, + push_id: event.github_push_id, + ref: event.ref, + head_sha: event.head_sha, + before_sha: event.before_sha, + # Two different instants, and the gap between them is the ingestion latency §11 + # otherwise only exposes in logs: occurred_at is GitHub's clock, ingested_at is this + # application's commit. + occurred_at: Github::Ingestion::Report.timestamp(event.occurred_at), + ingested_at: Github::Ingestion::Report.timestamp(event.created_at), + actor: actor(event.github_actor, github_id: event.github_actor_id), + repository: repository(event.github_repository, github_id: event.github_repository_id) + } + end + + # The show shape: the list shape plus the retained payload. §16 makes "raw payload is + # retained" a functional gate, and this is the endpoint that makes it demonstrable + # without a psql session. + def detail(event) + summary(event).merge(raw_payload: event.raw_payload) + end + + def page(page) + { + data: page.records.map { |event| summary(event) }, + pagination: { + limit: page.limit, + count: page.records.length, + next_cursor: page.next_cursor&.encode + } + } + end + + # Nothing here is .compact-ed, and that is a deliberate departure from the #to_log + # convention this otherwise follows. A log line drops nil keys because an absent field + # is noise. A response body must not: "name": null means "this actor is not enriched + # yet", which is information, and a key that appears and disappears makes every client — + # and every spec — handle two shapes for one resource. Keys are stable; values may be + # null. + # + # enrichment_status and fetched_at are here for §16's gate that "both actor and + # repository enrichment demonstrably occur": a reviewer watches them flip from pending + # to complete while the worker runs, per row, in a browser. + # + # github_id is read off the push_events column rather than off the association, so the + # shape is identical even in the case the foreign keys make unreachable. + # + # Deliberately absent: the entity's own raw_payload (one payload per response is + # enough), and enrichment_attempts / next_retry_at / last_error — last_error can hold a + # fetch error's message verbatim, and HealthController already establishes the house + # rule that internals do not cross the HTTP boundary. §11 assigns the aggregate view of + # those to /status, which ships in this same PR. + def actor(actor, github_id:) + { + github_id: github_id, + login: actor&.login, + display_login: actor&.display_login, + name: actor&.name, + avatar_url: actor&.avatar_url, + enrichment_status: actor&.enrichment_status, + fetched_at: Github::Ingestion::Report.timestamp(actor&.fetched_at) + } + end + + def repository(repository, github_id:) + { + github_id: github_id, + full_name: repository&.full_name, + name: repository&.name, + description: repository&.description, + language: repository&.language, + enrichment_status: repository&.enrichment_status, + fetched_at: Github::Ingestion::Report.timestamp(repository&.fetched_at) + } + end + end +end diff --git a/config/routes.rb b/config/routes.rb index 01a9075..8e2834b 100644 --- a/config/routes.rb +++ b/config/routes.rb @@ -3,4 +3,21 @@ # or consumes request budget. get "/health/live", to: "health#live" get "/health/ready", to: "health#ready" + + # §11's status endpoint, under the same standing guarantee: reports persisted state only + # and never initiates a GitHub request, so reading it can never spend budget. + get "/status", to: "status#show" + + # §11's event inspection API, under that same guarantee. + # + # `namespace :api` camelizes to `Api`, not `API`: config/initializers/inflections.rb + # registers no acronym, so Zeitwerk expects app/controllers/api/. + # + # `resources` rather than two explicit `get` lines — unlike the health pair above, this + # is a genuine REST resource, and it generates the api_push_events_url helper the Link + # header needs. `only:` is not decoration: it keeps `rails routes` at exactly the two + # endpoints §11 names, with no create/update/destroy stubs on a read-only surface. + namespace :api, defaults: { format: :json } do + resources :push_events, only: %i[index show] + end end diff --git a/docker-compose.yml b/docker-compose.yml index 00101b7..33ba0dc 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -48,6 +48,13 @@ x-app-env: &app_env ENRICHMENT_ELIGIBILITY_WINDOW_SECONDS: ${ENRICHMENT_ELIGIBILITY_WINDOW_SECONDS:-3600} ACTOR_REFRESH_TTL_SECONDS: ${ACTOR_REFRESH_TTL_SECONDS:-86400} REPOSITORY_REFRESH_TTL_SECONDS: ${REPOSITORY_REFRESH_TTL_SECONDS:-86400} + # §11's coverage window, forwarded for the same reason the four allowance inputs are — + # without this line `ENRICHMENT_COVERAGE_WINDOW_SECONDS=604800 docker compose up` sets + # the variable in the reviewer's shell and nothing at all inside the container. It sits + # in the shared anchor for consistency rather than for correctness: unlike every other + # member here it changes only what /status *reports*, never what any process *does*, so + # a disagreement between two processes would be cosmetic rather than a policy split. + ENRICHMENT_COVERAGE_WINDOW_SECONDS: ${ENRICHMENT_COVERAGE_WINDOW_SECONDS:-86400} services: db: diff --git a/spec/requests/api/push_events_spec.rb b/spec/requests/api/push_events_spec.rb new file mode 100644 index 0000000..ec2626c --- /dev/null +++ b/spec/requests/api/push_events_spec.rb @@ -0,0 +1,190 @@ +require "rails_helper" + +RSpec.describe "Event inspection API", type: :request do + let(:actor) { create_actor(github_id: 1001) } + let(:repository) { create_repository(github_id: 2001) } + let!(:event) { create_push_event(actor: actor, repository: repository) } + + describe "GET /api/push_events" do + it "answers 200 with a data array and its paging position" do + get "/api/push_events" + + expect(response).to have_http_status(:ok) + expect(response.parsed_body.keys).to eq(%w[data pagination]) + expect(response.parsed_body["data"].first["id"]).to eq(event.github_event_id) + expect(response.parsed_body["pagination"]) + .to eq("limit" => 25, "count" => 1, "next_cursor" => nil) + end + + it "shows each row's enrichment state, which is §16's enrichment gate in a browser" do + get "/api/push_events" + row = response.parsed_body["data"].first + + expect(row["actor"]).to include("github_id" => 1001, "login" => "octocat", + "enrichment_status" => "pending") + expect(row["repository"]).to include("github_id" => 2001, + "enrichment_status" => "pending") + end + + it "keeps the retained payload out of the list" do + get "/api/push_events" + + expect(response.parsed_body["data"].first).not_to have_key("raw_payload") + end + + describe "the Link header" do + before do + create_push_event(actor: actor, repository: repository, + github_event_id: "40000000002", occurred_at: frozen_time - 60) + end + + # The emitter and this application's own inbound parser agree, which is the closing + # symmetry worth asserting: Github::LinkHeader reads GitHub's /events response, and + # this reads ours. + it "advertises the next page in the form this application already parses" do + get "/api/push_events?limit=1" + + next_url = Github::LinkHeader.next_url(response.headers["Link"]) + + expect(next_url).to be_present + expect(next_url).to include("cursor=", "limit=1") + end + + it "advertises nothing once the last row has been served" do + get "/api/push_events?limit=25" + + expect(response.headers["Link"]).to be_nil + end + end + + describe "parameter validation" do + it "answers 400 naming the parameter it refused" do + get "/api/push_events?limit=99999" + + expect(response).to have_http_status(:bad_request) + expect(response.parsed_body["error"]) + .to eq("code" => "invalid_parameter", + "message" => "limit must be an integer from 1 to 100", + "parameter" => "limit") + end + + it "answers 400 for a cursor it did not issue, rather than restarting from the top" do + get "/api/push_events?cursor=nonsense" + + expect(response).to have_http_status(:bad_request) + expect(response.parsed_body.dig("error", "parameter")).to eq("cursor") + end + + it "answers 400 for an unknown parameter rather than a different question's answer" do + get "/api/push_events?repo_id=5" + + expect(response).to have_http_status(:bad_request) + expect(response.parsed_body.dig("error", "parameter")).to eq("repo_id") + end + + # Asserted through HTTP as well as at the parser, because the two failure modes this + # replaces are exactly the ones a parser-only spec would not show: a 500 for the + # cursor, which PostgreSQL raises on, and a silent empty 200 for the filter, which + # Active Record casts rather than raising on. + it "answers 400 rather than 500 for an id past the bigint the column can hold" do + get "/api/push_events?actor_id=999999999999999999999999" + + expect(response).to have_http_status(:bad_request) + expect(response.parsed_body.dig("error", "parameter")).to eq("actor_id") + end + + it "answers 400 rather than 500 for a cursor the database could not compare" do + forged = Base64.urlsafe_encode64("999999999-01-01T00:00:00Z|42") + + get "/api/push_events?cursor=#{forged}" + + expect(response).to have_http_status(:bad_request) + expect(response.parsed_body.dig("error", "parameter")).to eq("cursor") + end + end + end + + describe "GET /api/push_events/:id" do + it "answers 200 with the retained payload, which §16 makes a functional gate" do + get "/api/push_events/#{event.github_event_id}" + + expect(response).to have_http_status(:ok) + expect(response.parsed_body.dig("data", "id")).to eq(event.github_event_id) + expect(response.parsed_body.dig("data", "raw_payload")).to eq(event.raw_payload) + end + + # Both identifiers are numeric strings, so :id is genuinely ambiguous and only one + # reading can be right. github_event_id is the unique index the idempotency story rests + # on and the identifier §11 puts on every log line — which is what makes "log line -> + # record" a URL a reviewer can type. + it "resolves :id as the GitHub event id, never as the surrogate primary key" do + get "/api/push_events/#{event.id}" + expect(response).to have_http_status(:not_found) + + get "/api/push_events/#{event.github_event_id}" + expect(response).to have_http_status(:ok) + end + + # Without ApplicationController's rescue_from this renders as a DebugExceptions body + # carrying the exception class and its full backtrace: consider_all_requests_local is + # true in test and development, and api_only makes that format JSON. + it "answers 404 with a fixed body, leaking neither internals nor a backtrace" do + get "/api/push_events/does-not-exist" + + expect(response).to have_http_status(:not_found) + expect(response.parsed_body) + .to eq("error" => { "code" => "not_found", + "message" => "no record matches that identifier" }) + end + end + + describe "the guarantee that reading events costs nothing (plan §11)" do + def row_counts + { push_events: PushEvent.count, actors: GithubActor.count, + repositories: GithubRepository.count, runs: IngestionRun.count, + quarantined: QuarantinedEvent.count, budget: GithubApiBudget.count, + sources: EventSource.count } + end + + it "initiates no GitHub request" do + transport = fixture_transport + allow(Github).to receive(:transport).and_return(transport) + expect(Github).not_to receive(:executor) + + get "/api/push_events" + get "/api/push_events/#{event.github_event_id}" + + expect(transport.requests).to be_empty + end + + it "creates no row, and never bootstraps the ledger it does not read" do + before_counts = row_counts + + get "/api/push_events" + get "/api/push_events/#{event.github_event_id}" + + expect(row_counts).to eq(before_counts) + end + + it "issues no write statement at all" do + expect(write_statements { get "/api/push_events" }).to be_empty + expect(write_statements { get "/api/push_events/#{event.github_event_id}" }).to be_empty + end + + # preload rather than eager_load, and the point of it: the statement count is a + # function of the page shape, not of the page size. + it "issues the same statements for fifty rows as for one" do + 50.times do |n| + create_push_event(actor: actor, repository: repository, + github_event_id: "5000000#{format("%04d", n)}", + occurred_at: frozen_time - n) + end + + one = capture_sql { get "/api/push_events?limit=1" }.grep(/\ASELECT/) + fifty = capture_sql { get "/api/push_events?limit=50" }.grep(/\ASELECT/) + + expect(fifty.length).to eq(one.length) + expect(fifty.length).to eq(3) + end + end +end diff --git a/spec/requests/status_spec.rb b/spec/requests/status_spec.rb new file mode 100644 index 0000000..21712e7 --- /dev/null +++ b/spec/requests/status_spec.rb @@ -0,0 +1,107 @@ +require "rails_helper" + +RSpec.describe "GET /status", type: :request do + # §11: "reports persisted state only; never initiates a GitHub request." + # + # Four examples rather than one, because the guarantee has four distinct ways to break + # and each fails silently. They are the pair Github::Ingestion::StateSummary's spec + # already carries, plus the two that only a controller can get wrong. + describe "the guarantee that reading state costs nothing (plan §11)" do + it "initiates no GitHub request" do + transport = fixture_transport + allow(Github).to receive(:transport).and_return(transport) + expect(Github).not_to receive(:executor) + + get "/status" + + expect(response).to have_http_status(:ok) + expect(transport.requests).to be_empty + end + + # The subtle one: Github::BudgetLedger#bootstrap! is public and issues an INSERT even + # when it inserts nothing, so reaching for the ledger instead of find_by would create + # from a read path the very row a reservation owns. + it "does not create the ledger row it reports on" do + expect { get "/status" }.not_to change(GithubApiBudget, :count).from(0) + end + + # The mirror hazard: reaching for Github::Ingestion::SourceProvisioner to find "the" + # event source would provision one from a GET. + it "does not provision the event source it reports on" do + expect { get "/status" }.not_to change(EventSource, :count).from(0) + end + + # Belt and braces over the three above: whatever the implementation reaches for, and + # whatever a future collaborator adds to it, no statement it issues may write. + it "issues no write statement at all" do + create_event_source + create_actor(github_id: 1) + active_budget_window + + expect(write_statements { get "/status" }).to be_empty + end + end + + describe "the response" do + it "answers 200 with §11's blocks on a clean checkout" do + get "/status" + + expect(response).to have_http_status(:ok) + expect(response.parsed_body.keys) + .to eq(%w[captured_at sources ledger enrichment coverage]) + expect(response.parsed_body["sources"]).to eq([]) + expect(response.parsed_body.dig("ledger", "present")).to be(false) + end + + # A snapshot is true for the instant it was taken. An intermediary serving a stale + # ledger to an operator diagnosing a live rate limit is the failure this prevents. + it "forbids caching, because a snapshot goes stale immediately" do + get "/status" + + expect(response.headers["Cache-Control"]).to eq("no-store") + end + + # These are the states the endpoint exists to report, not failures of the endpoint. + # A 503 here would pull the container out of a load balancer for something both health + # endpoints correctly call healthy. + it "answers 200 for a globally blocked ledger and an out-of-service source" do + active_budget_window(window_status: "globally_blocked", + global_blocked_until: Time.current + 300) + create_event_source(status: "failed") + + get "/status" + + expect(response).to have_http_status(:ok) + expect(response.parsed_body.dig("ledger", "window_status")).to eq("globally_blocked") + expect(response.parsed_body["sources"].first["status"]).to eq("failed") + end + + it "reports coverage over persisted events, joined to their entities" do + actor = create_actor(github_id: 1001) + repository = create_repository(github_id: 2001) + actor.update!(enrichment_status: "complete", fetched_at: Time.current) + create_push_event(actor: actor, repository: repository) + + get "/status" + + expect(response.parsed_body["coverage"]).to include( + "basis" => "created_at", "event_count" => 1, + "actor_coverage_pct" => 100.0, "repository_coverage_pct" => 0.0, + "events_with_both_entities_enriched_pct" => 0.0 + ) + end + end + + describe "when the database cannot answer" do + it "degrades to 503 without leaking internals" do + allow(Github::Status::Snapshot).to receive(:capture) + .and_raise(ActiveRecord::ConnectionNotEstablished) + + get "/status" + + expect(response).to have_http_status(:service_unavailable) + expect(response.parsed_body) + .to eq("status" => "unavailable", "reason" => "ActiveRecord::ConnectionNotEstablished") + end + end +end diff --git a/spec/services/github/configuration_spec.rb b/spec/services/github/configuration_spec.rb index a3f9468..4f435f9 100644 --- a/spec/services/github/configuration_spec.rb +++ b/spec/services/github/configuration_spec.rb @@ -27,15 +27,22 @@ def configuration(**overrides) actor_enrichment_share: 0.5, enrichment_eligibility_window_seconds: 3600, actor_refresh_ttl_seconds: 86_400, - repository_refresh_ttl_seconds: 86_400 + repository_refresh_ttl_seconds: 86_400, + # §11's coverage window, pinned at 86400 by §10. It arrives with the rich /status + # rather than earlier because until Github::Enrichment::Coverage existed nothing + # read it, and §16 forbids a knob with no consumer. + enrichment_coverage_window_seconds: 86_400 ) end - # §10 prints ENRICHMENT_COVERAGE_WINDOW_SECONDS in the same block as the three above, - # but it is an input to §11's coverage percentages, which §13 assigns to PR 10. §16 - # forbids speculative infrastructure, so it is absent until something reads it. - it "carries no coverage window, which is PR 10's input and has no consumer yet" do - expect(described_class::DEFAULTS.keys).not_to include("ENRICHMENT_COVERAGE_WINDOW_SECONDS") + # The one knob here that changes what the system *reports* rather than what it *does*. + # Stated as its own example because the distinction is the reason it is safe for two + # processes to disagree about it, which is not true of any of its neighbours. + it "reports through the coverage window without scheduling, reserving or deferring on it" do + expect(configuration(ENRICHMENT_COVERAGE_WINDOW_SECONDS: "60")) + .to have_attributes(enrichment_coverage_window_seconds: 60, + enrichment_eligibility_window_seconds: 3600, + poll_interval_seconds: 300) end it "reads an override from the environment it was given" do diff --git a/spec/services/github/enrichment/coverage_spec.rb b/spec/services/github/enrichment/coverage_spec.rb new file mode 100644 index 0000000..6ff554e --- /dev/null +++ b/spec/services/github/enrichment/coverage_spec.rb @@ -0,0 +1,162 @@ +require "rails_helper" + +RSpec.describe Github::Enrichment::Coverage do + # Time.current rather than frozen_time: the window is relative to `now`, and every + # example places its rows against the same instant it passes in. + let(:now) { Time.current } + + def configuration_with(**overrides) + Github::Configuration.new(overrides.transform_keys(&:to_s)) + end + + def capture(**overrides) + described_class.capture(now: now, configuration: configuration_with(**overrides)) + end + + # created_at defaults to inside the window; occurred_at is set independently so the two + # basis-discriminating examples below can pull them apart. + def event(id, actor:, repository:, created_at: now - 60, occurred_at: now - 60) + create_push_event(actor: actor, repository: repository, github_event_id: id, + created_at: created_at, occurred_at: occurred_at) + end + + let(:actor) { create_actor(github_id: 1001) } + let(:repository) { create_repository(github_id: 2001) } + + describe "the window basis (plan §11)" do + # The two examples that stop a later refactor silently changing what the metric means. + # created_at >= occurred_at always, so these are the only two rows that can distinguish + # the bases, and each one alone would pass under either. + it "includes an event that occurred long ago but was persisted inside the window" do + event("40000000001", actor: actor, repository: repository, + occurred_at: now - 100_000, created_at: now - 60) + + expect(capture.event_count).to eq(1) + end + + it "excludes an event that occurred inside the window but was persisted before it" do + event("40000000001", actor: actor, repository: repository, + occurred_at: now - 60, created_at: now - 100_000) + + expect(capture.event_count).to eq(0) + end + + it "names the basis in the payload rather than leaving the consumer to infer it" do + expect(capture.payload[:basis]).to eq("created_at") + end + + it "reads the window from the configuration it was given" do + event("40000000001", actor: actor, repository: repository, created_at: now - 600) + + expect(capture(ENRICHMENT_COVERAGE_WINDOW_SECONDS: "3600").event_count).to eq(1) + expect(capture(ENRICHMENT_COVERAGE_WINDOW_SECONDS: "60").event_count).to eq(0) + end + end + + describe "the three formulas (plan §11)" do + # An actor referenced by many events is one actor on both sides of its own ratio, while + # the event ratio counts rows. Without COUNT(DISTINCT …) the entity denominator would + # be the event count and every percentage would be wrong in the same direction. + it "counts an entity once however many events reference it" do + 3.times { |n| event("4000000000#{n}", actor: actor, repository: repository) } + + expect(capture).to have_attributes(event_count: 3, actor_count: 1, repository_count: 1) + end + + it "reports a fully enriched window as complete on all three" do + actor.update!(enrichment_status: "complete", fetched_at: now) + repository.update!(enrichment_status: "complete", fetched_at: now) + event("40000000001", actor: actor, repository: repository) + + expect(capture).to have_attributes(actor_coverage_pct: 100.0, + repository_coverage_pct: 100.0, + events_with_both_entities_enriched_pct: 100.0) + end + + # The third formula is not the product or the minimum of the other two — it is a + # per-event conjunction, and this is the arrangement that tells them apart. + it "counts an event only when both of its entities are complete" do + actor.update!(enrichment_status: "complete", fetched_at: now) + event("40000000001", actor: actor, repository: repository) + + expect(capture).to have_attributes(actor_coverage_pct: 100.0, + repository_coverage_pct: 0.0, + both_complete_event_count: 0, + events_with_both_entities_enriched_pct: 0.0) + end + + it "counts only complete, not the other four statuses" do + %w[pending retryable_failure permanent_failure skipped_budget].each_with_index do |status, n| + other = create_actor(github_id: 3000 + n, login: "user#{n}") + other.update!(enrichment_status: status) + event("4000000010#{n}", actor: other, repository: repository) + end + + expect(capture).to have_attributes(actor_count: 4, complete_actor_count: 0, + actor_coverage_pct: 0.0) + end + + it "rounds to the second decimal, which is the decimal the sampling rate moves" do + complete = create_actor(github_id: 1002, login: "enriched") + complete.update!(enrichment_status: "complete", fetched_at: now) + event("40000000001", actor: complete, repository: repository) + 2.times do |n| + other = create_actor(github_id: 4000 + n, login: "other#{n}") + event("4000000020#{n}", actor: other, repository: repository) + end + + expect(capture.actor_coverage_pct).to eq(33.33) + end + end + + describe "an empty window" do + # §16 forbids the fabricated zero. 0.0 here would read as "nothing is enriched" when + # the truth is "there is nothing in the window to enrich", and those are different + # facts an operator acts on differently. The denominator is published beside the ratio, + # so nil is self-explanatory. + it "reports no percentage rather than a zero one" do + expect(capture).to have_attributes(actor_coverage_pct: nil, + repository_coverage_pct: nil, + events_with_both_entities_enriched_pct: nil) + end + + it "still reports every count, because a counted zero is a fact" do + expect(capture).to have_attributes(event_count: 0, actor_count: 0, + complete_actor_count: 0, repository_count: 0, + complete_repository_count: 0, + both_complete_event_count: 0) + end + + it "publishes a fixed key set, so a client never handles two shapes" do + event("40000000001", actor: actor, repository: repository) + populated = capture.payload + + expect(capture(ENRICHMENT_COVERAGE_WINDOW_SECONDS: "1").payload.keys) + .to eq(populated.keys) + end + end + + describe "the structural guarantees §11 places on the read path" do + # The literal is interpolated into SQL rather than bound, so this pins it against the + # enum: a renamed status must not leave the filter matching a value that is gone. + it "pins its complete literal to the entity state machine" do + expect(Enrichable::ENRICHMENT_STATUSES).to include(described_class::COMPLETE) + end + + it "initiates no GitHub request" do + transport = fixture_transport + allow(Github).to receive(:transport).and_return(transport) + expect(Github).not_to receive(:executor) + + capture + + expect(transport.requests).to be_empty + end + + # The subtler mistake this catches is reaching Github::BudgetLedger#bootstrap! from a + # read path. This class should not touch the ledger at all. + it "does not create the ledger row" do + expect { capture }.not_to change(GithubApiBudget, :count).from(0) + end + end +end diff --git a/spec/services/github/enrichment/summary_spec.rb b/spec/services/github/enrichment/summary_spec.rb index 02f69a7..9ae1ec1 100644 --- a/spec/services/github/enrichment/summary_spec.rb +++ b/spec/services/github/enrichment/summary_spec.rb @@ -145,10 +145,62 @@ expect(described_class.capture(now: now).to_s).to include("Actors pending/complete/skipped:", "1 / 1 / 0") end - it "says due now rather than printing an instant that has already passed" do + it "says due now when a candidate is actually claimable" do + create_actor(github_id: 1) active_budget_window(now: now) expect(described_class.capture(now: now).to_s).to include(described_class::DUE_NOW) end + + # The reason claimable_now exists. A nil next_enrichment_at means "no deferral + # applies", which is equally true of a claimable candidate and of an empty backlog — + # and this line used to say "due now" to a reviewer whose next line of output was + # "nothing to enrich". + it "says nothing waiting rather than due now on an empty backlog" do + active_budget_window(now: now) + + expect(described_class.capture(now: now).to_s) + .to include(described_class::NOTHING_WAITING) + end + end + + describe "#claimable_now" do + it "is false when nothing is enrichable, so a nil instant is never ambiguous" do + active_budget_window(now: now) + + expect(described_class.capture(now: now)) + .to have_attributes(claimable_now: false, next_enrichment_at: nil) + end + + it "is true when a candidate could be claimed this second" do + create_actor(github_id: 1) + active_budget_window(now: now) + + expect(described_class.capture(now: now)) + .to have_attributes(claimable_now: true, next_enrichment_at: nil) + end + + # A ledger block outranks every per-entity instant: the candidate is there, but no + # request may be issued for it, so it is not claimable. + it "is false under a global block, however many candidates are waiting" do + create_actor(github_id: 1) + active_budget_window(now: now, global_blocked_until: now + 300) + + expect(described_class.capture(now: now)) + .to have_attributes(claimable_now: false, next_enrichment_at: now + 300) + end + end + + describe "the ledger row it reports on" do + # /status reads the singleton once and passes it down, so its poll block and its + # ledger block cannot straddle a committing reservation and disagree. + it "uses the row it was handed instead of reading its own" do + active_budget_window(now: now, enrichment_used: 7) + budget = current_budget + allow(GithubApiBudget).to receive(:find_by) + + expect(described_class.capture(now: now, budget: budget).enrichment_used).to eq(7) + expect(GithubApiBudget).not_to have_received(:find_by) + end end end diff --git a/spec/services/github/enrichment_runner_spec.rb b/spec/services/github/enrichment_runner_spec.rb index 404ada6..e483c87 100644 --- a/spec/services/github/enrichment_runner_spec.rb +++ b/spec/services/github/enrichment_runner_spec.rb @@ -267,5 +267,51 @@ def ghostuser(**overrides) expect(Rails.logger).to have_received(:debug).with(hash_including(event: "enrichment.deferred")) expect(Rails.logger).not_to have_received(:info).with(hash_including(event: "enrichment.deferred")) end + + # §11's common-field list includes the attempt number, and this is the line §11 actually + # asks reviewers to read. lease.to_log already carried it onto the DEBUG request line, + # so it was present exactly where nobody was looking and absent where they were. + it "carries §11's attempt number onto the outcome line, not only onto the request line" do + ghostuser(enrichment_attempts: 1) + allow(Rails.logger).to receive(:info) + + runner.call + + expect(Rails.logger).to have_received(:info).with( + hash_including(event: "enrichment.failed", enrichment_attempt: 2, + entity_status: "permanent_failure") + ) + end + + it "counts the attempt from zero on an entity that has never been fetched" do + octocat + allow(Rails.logger).to receive(:info) + + runner.call + + expect(Rails.logger).to have_received(:info) + .with(hash_including(event: "enrichment.completed", enrichment_attempt: 1)) + end + + # Result::EVENTS owns "enrichment.failed" for the ordinary outcome §11 lists — INFO, + # with an entity status and a scheduled retry. An escaped exception has a released + # lease, an error pair and no entity outcome at all, so sharing the name would make one + # alert match two structurally different records. + it "reports an escaped exception under its own name, not the outcome's" do + octocat + allow(Rails.logger).to receive(:error) + exploding = instance_double(Github::Enrichment::EntityState) + allow(exploding).to receive(:record!).and_raise(RuntimeError, "boom") + + expect { fixture_enrichment_runner(transport: transport, entity_state: exploding).call } + .to raise_error(RuntimeError, "boom") + + expect(Rails.logger).to have_received(:error).with( + hash_including(event: "enrichment.cycle_failed", entity_type: :actor, + error_class: "RuntimeError", error_message: "boom") + ) + expect(Rails.logger).not_to have_received(:error) + .with(hash_including(event: "enrichment.failed")) + end end end diff --git a/spec/services/github/ingestion/poll_state_spec.rb b/spec/services/github/ingestion/poll_state_spec.rb index 61b8764..4f6d562 100644 --- a/spec/services/github/ingestion/poll_state_spec.rb +++ b/spec/services/github/ingestion/poll_state_spec.rb @@ -26,8 +26,8 @@ def outcome(status:, **overrides) ) end - def record(outcome) - writer.record!(event_source: event_source, outcome: outcome, now: now) + def record(outcome, run_id: nil) + writer.record!(event_source: event_source, outcome: outcome, now: now, run_id: run_id) event_source.reload end @@ -113,6 +113,26 @@ def record(outcome) expect(event_source).to have_attributes(consecutive_failures: 2, retry_not_before_at: now + 120) end + + # ingestion.run_completed already reports consecutive_failures and next_poll_at, but + # next_poll_at is the *maximum* of §9's five independent components, so it cannot say + # whether the source is deferred by its own backoff, by the server's poll floor, or by + # a global block. Naming the component and the delay is what makes the retry + # actionable — the same reason ingestion.not_due reports binding_component. + it "names the backoff it wrote, which next_poll_at alone cannot attribute" do + allow(Rails.logger).to receive(:warn) + + record(outcome(status: "failed", classification: :server_error, last_error: "boom"), + run_id: "run-1") + + expect(Rails.logger).to have_received(:warn).with( + hash_including(event: "ingestion.source_backoff", run_id: "run-1", + event_source_id: event_source.id, classification: :server_error, + consecutive_failures: 2, backoff_seconds: 120.0, + retry_not_before_at: (now + 120).utc.iso8601, + error_message: "boom") + ) + end end # §10: "/events returns permanent 4xx → source failed/disabled". Terminal on first @@ -128,6 +148,35 @@ def record(outcome) consecutive_failures: 0, retry_not_before_at: nil, last_error: "gone") end + + # The transition is terminal and operator-recoverable only — nothing in this + # application writes `failed` back to `idle` — so it is the single poll outcome that + # will not resolve itself, and until now the only evidence of it was a status column + # nobody was told to read. Its entity-side twin, permanent_failure, already reaches the + # INFO stream through enrichment.failed's entity_status. + it "announces the terminal transition at error level" do + allow(Rails.logger).to receive(:error) + + record(outcome(status: "failed", classification: :not_found, last_error: "gone", + source_failing: true), run_id: "run-1") + + expect(Rails.logger).to have_received(:error).with( + hash_including(event: "ingestion.source_failed", run_id: "run-1", + event_source_id: event_source.id, source_status: "failed", + classification: :not_found, error_message: "gone") + ) + end + + # There is nothing to back off from: the source is out of service, not retrying. + # Emitting both would tell an operator to wait for a retry that will never come. + it "reports no backoff, because a terminal source is not retrying" do + allow(Rails.logger).to receive(:warn) + + record(outcome(status: "failed", classification: :not_found, source_failing: true)) + + expect(Rails.logger).not_to have_received(:warn) + .with(hash_including(event: "ingestion.source_backoff")) + end end # §10: a budget denial and a held gate mean the request never happened. Letting either @@ -155,6 +204,18 @@ def record(outcome) expect(event_source.next_poll_at).to eq(now + 120) end + + # Nothing was written, so there is nothing to announce. A line here would report a + # backoff a healthy source never took. + it "announces nothing, because no source state moved" do + allow(Rails.logger).to receive(:warn) + allow(Rails.logger).to receive(:error) + + record(outcome(status: "deferred", classification: :budget_denied, snapshot: nil)) + + expect(Rails.logger).not_to have_received(:warn) + expect(Rails.logger).not_to have_received(:error) + end end # GitHub answered, so the attempt is spent and the cadence moves — but §10 is explicit diff --git a/spec/services/github/ingestion_runner_spec.rb b/spec/services/github/ingestion_runner_spec.rb index 18d0338..4cfef4f 100644 --- a/spec/services/github/ingestion_runner_spec.rb +++ b/spec/services/github/ingestion_runner_spec.rb @@ -352,6 +352,27 @@ def ingest(runner = fixture_runner, **options) expect(result.last_error).to eq("GitHub returned 500 (server_error)") expect(IngestionRun.sole.last_error).to eq("GitHub returned 500 (server_error)") end + + # The whole retry ladder, end to end and joined to the run that produced it. Everything + # below reaches the stream at the default log level of info, which is the point: before + # PR 10 an operator running a 500 storm saw only the completion line. + it "shows the whole retry ladder against the run it belongs to" do + allow(Rails.logger).to receive(:info).and_call_original + allow(Rails.logger).to receive(:warn).and_call_original + + result = ingest(fixture_runner(transport: fixture_transport(scenario: "transient_failure_exhausted"))) + + expect(Rails.logger).to have_received(:info) + .with(hash_including(event: "github.retry_scheduled", run_id: result.run_id)).twice + expect(Rails.logger).to have_received(:warn) + .with(hash_including(event: "github.retry_exhausted", run_id: result.run_id)) + expect(Rails.logger).to have_received(:warn) + .with(hash_including(event: "github.request", classification: :server_error, + run_id: result.run_id)).exactly(3).times + expect(Rails.logger).to have_received(:warn) + .with(hash_including(event: "ingestion.source_backoff", run_id: result.run_id, + consecutive_failures: 1)) + end end # §10 makes every retry its own reservation "through the same gate and ledger", so the diff --git a/spec/services/github/request_executor_spec.rb b/spec/services/github/request_executor_spec.rb index 2e1c081..0a7f168 100644 --- a/spec/services/github/request_executor_spec.rb +++ b/spec/services/github/request_executor_spec.rb @@ -195,6 +195,137 @@ def executor(transport, **overrides) end end + describe "retry and failure logging (plan §11, §16)" do + def always(status) + recording_transport { response(status: status, headers: rate_limit_headers) } + end + + # §11 names "retry scheduled" among the INFO events, and it was the only one named + # there with no implementation at all. Without it a retried fetch is + # indistinguishable from a slow one, and the extra reservations it spends out of sixty + # an hour are invisible. + it "announces every scheduled retry at info, naming the delay it is about to sleep" do + active_budget_window + allow(Rails.logger).to receive(:info) + slept = [] + + executor(always(500), sleeper: ->(seconds) { slept << seconds }).call(poll_request) + + expect(Rails.logger).to have_received(:info) + .with(hash_including(event: "github.retry_scheduled", classification: :server_error, + http_status: 500, next_attempt: 1, max_attempts: 2)).once + expect(Rails.logger).to have_received(:info) + .with(hash_including(event: "github.retry_scheduled", next_attempt: 2)).once + end + + # RetryPolicy jitters, so a line that recomputed the delay would report a number this + # process never actually slept. + it "reports the delay it actually slept, not a freshly jittered one" do + active_budget_window + logged = [] + slept = [] + allow(Rails.logger).to receive(:info) { |payload| logged << payload } + + executor(always(500), sleeper: ->(seconds) { slept << seconds }).call(poll_request) + + scheduled = logged.select { |line| line[:event] == "github.retry_scheduled" } + expect(scheduled.map { |line| line[:backoff_seconds] }) + .to eq(slept.map { |seconds| seconds.round(1) }) + end + + # §10's "persist the failure after attempts are exhausted", and §16's "retry behavior + # is visible". Before this, "retried twice over seven seconds and gave up" was + # byte-identical in the log stream to "failed once, permanently". + it "distinguishes running out of attempts from failing once" do + active_budget_window + allow(Rails.logger).to receive(:warn) + + executor(always(500)).call(poll_request) + + expect(Rails.logger).to have_received(:warn) + .with(hash_including(event: "github.retry_exhausted", classification: :server_error, + attempt: 2, max_attempts: 2)).once + end + + # The other half of that distinction: a classification that was never retryable did not + # run out of anything, and reporting exhaustion on every permanent 404 would make the + # line meaningless. + it "reports no exhaustion for a classification that was never retryable" do + active_budget_window + allow(Rails.logger).to receive(:warn) + + executor(always(404)).call(poll_request) + + expect(Rails.logger).not_to have_received(:warn) + .with(hash_including(event: "github.retry_exhausted")) + end + + describe "the level of the per-request line" do + # §11 puts per-request lines at debug, and that is right for the ones that worked. + # But config.log_level defaults to info, so before this a 500, a timeout, a refused + # URL and a deleted entity produced no HTTP detail at all in a running system — while + # §11 also sizes the info stream so the events Story 4 asks reviewers to see are *in* + # it, and §16 requires failures to carry actionable context. + { + 500 => :server_error, 404 => :not_found, 400 => :client_error + }.each do |status, classification| + it "raises a #{classification} to warning, so it survives the default log level" do + active_budget_window + allow(Rails.logger).to receive(:warn) + + executor(always(status), retry_policy: Github::RetryPolicy.new(max_attempts: 0)) + .call(poll_request) + + expect(Rails.logger).to have_received(:warn) + .with(hash_including(event: "github.request", classification: classification, + http_status: status)) + end + end + + it "leaves a request that worked at debug, where §11 puts it" do + active_budget_window + allow(Rails.logger).to receive(:debug) + allow(Rails.logger).to receive(:warn) + + executor(always(200)).call(poll_request) + + expect(Rails.logger).to have_received(:debug) + .with(hash_including(event: "github.request", classification: :ok)) + expect(Rails.logger).not_to have_received(:warn) + end + + # Nothing was spent and nothing was attempted, and the caller emits its own deferral + # line. A rate limit is the same: GitHub answered and declined, and §11's line for + # that is budget.global_block_set — once per block rather than once per request. + it "leaves a deferral and a rate limit at debug, because neither is a failure" do + active_budget_window(poll_used: 12, poll_allowance: 12) + allow(Rails.logger).to receive(:debug) + allow(Rails.logger).to receive(:warn) + + executor(always(200)).call(poll_request) + + expect(Rails.logger).to have_received(:debug) + .with(hash_including(event: "github.request", classification: :budget_denied)) + expect(Rails.logger).not_to have_received(:warn) + end + + # One event name rather than two, so the same request never appears twice and + # `grep github.request` keeps meaning "every request". + it "keeps one event name across both levels" do + active_budget_window + logged = [] + allow(Rails.logger).to receive(:warn) { |payload| logged << payload } + allow(Rails.logger).to receive(:debug) { |payload| logged << payload } + + executor(always(500)).call(poll_request) + + requests = logged.select { |line| line[:event] == "github.request" } + expect(requests.length).to eq(3) + expect(requests.map { |line| line[:attempt] }).to eq([ 0, 1, 2 ]) + end + end + end + describe "redirects (plan §10)" do let(:repository_request) do Github::Request.new(url: "https://api.github.com/repos/octocat/Hello-World", request_class: :repository) diff --git a/spec/services/github/status/snapshot_spec.rb b/spec/services/github/status/snapshot_spec.rb new file mode 100644 index 0000000..ae0e308 --- /dev/null +++ b/spec/services/github/status/snapshot_spec.rb @@ -0,0 +1,214 @@ +require "rails_helper" + +RSpec.describe Github::Status::Snapshot do + let(:now) { Time.current } + + def payload + described_class.capture(now: now).payload + end + + describe "the response shape (plan §11)" do + it "names every block §11 asks for, in §11's order" do + expect(payload.keys).to eq(%i[captured_at sources ledger enrichment coverage]) + end + + it "answers on a clean checkout without inventing anything" do + body = payload + + expect(body[:sources]).to eq([]) + expect(body[:ledger][:present]).to be(false) + expect(body[:coverage][:actor_coverage_pct]).to be_nil + expect(body[:coverage][:event_count]).to eq(0) + end + end + + describe "the enrichment counts (plan §11)" do + # The example that keeps two numbers from silently becoming one. §11's + # pending_actor_count sits beside skipped_actor_count, so it means the *status*; + # Github::Ingestion::StateSummary uses the same name for the enrichment_candidates + # scope, which is pending plus retryable_failure. Both are right for their own + # question. Publishing both under distinct names is what makes them checkable. + it "reports pending as the status and the candidate scope under its own name" do + create_actor(github_id: 1) + create_actor(github_id: 2, login: "two", enrichment_status: "retryable_failure") + + actors = payload.dig(:enrichment, :actors) + + expect(actors).to include(pending: 1, retryable_failure: 1, candidates: 2) + expect(GithubActor.enrichment_candidates.count).to eq(2) + expect(Github::Ingestion::StateSummary.capture(now: now).pending_actor_count).to eq(2) + end + + it "names every status including the ones with no rows" do + expected = Enrichable::ENRICHMENT_STATUSES.map(&:to_sym) + [ :candidates ] + + expect(payload.dig(:enrichment, :actors).keys).to eq(expected) + expect(payload.dig(:enrichment, :repositories).keys).to eq(expected) + end + + it "counts each class separately, so one cannot mask the other" do + create_actor(github_id: 1) + create_repository(github_id: 2, enrichment_status: "skipped_budget") + + expect(payload.dig(:enrichment, :actors)).to include(pending: 1, skipped_budget: 0) + expect(payload.dig(:enrichment, :repositories)).to include(pending: 0, skipped_budget: 1) + end + end + + describe "the ledger block (plan §11)" do + it "distinguishes an absent row from an exhausted budget" do + expect(payload[:ledger]).to include(present: false, remaining: nil, reserve: nil) + + active_budget_window(now: now, remaining: 0) + + expect(payload[:ledger]).to include(present: true, remaining: 0, reserve: 8) + end + + it "reports every per-class counter §11 names" do + active_budget_window(now: now, poll_used: 7, enrichment_used: 23, + actor_share_used: 9, repository_share_used: 14) + + expect(payload[:ledger]).to include( + window_status: "active", resource: "core", limit: 60, remaining: 55, + poll: { used: 7, allowance: 12 }, + enrichment: { used: 23, allowance: 40 }, + actor_requests: { used: 9, guarantee: 20, available: 11 }, + repository_requests: { used: 14, guarantee: 20, available: 6 } + ) + end + + # available is the headroom inside a guarantee, and §10 lets a class borrow past it + # when the other has no eligible candidate. A negative number here would read as an + # accounting error rather than as the borrow it actually is. + it "floors available at zero, because borrowing takes a class past its guarantee" do + active_budget_window(now: now, actor_share_used: 26) + + expect(payload.dig(:ledger, :actor_requests)) + .to eq(used: 26, guarantee: 20, available: 0) + end + + it "keeps the two shares summing to the class counter it was split from" do + active_budget_window(now: now, enrichment_used: 23, + actor_share_used: 9, repository_share_used: 14) + ledger = payload[:ledger] + + expect(ledger.dig(:actor_requests, :used) + ledger.dig(:repository_requests, :used)) + .to eq(ledger.dig(:enrichment, :used)) + end + end + + describe "the poll block (plan §11)" do + it "reports no sources rather than a null one on a clean checkout" do + expect(payload[:sources]).to eq([]) + end + + # StateSummary picks EventSource.order(:id).first because §9's one-shot runs one + # command against one source. /status describes the installation, and the README's + # reviewer path routinely leaves two rows in the database — so a singular pick would + # name whichever was created first, quite possibly not the one running. + it "reports one entry per source, ordered by id" do + live = create_event_source + fixture = create_event_source(source_type: "github_fixture_events") + + expect(payload[:sources].map { |source| source[:id] }).to eq([ live.id, fixture.id ]) + expect(payload[:sources].map { |source| source[:source_type] }) + .to eq(%w[github_public_events github_fixture_events]) + end + + it "names every scheduling component, and only the ones in play carry an instant" do + create_event_source(cadence_due_at: now + 300, poll_floor_until: now + 60) + source = payload[:sources].first + + expect(source[:scheduling_components].keys).to eq(Github::PollSchedule::COMPONENTS) + expect(source[:scheduling_components]).to include( + cadence_due_at: (now + 300).utc.iso8601, + poll_floor_until: (now + 60).utc.iso8601, + retry_not_before_at: nil, global_blocked_until: nil, poll_class_blocked_until: nil + ) + expect(source[:binding_component]).to eq(:cadence_due_at) + expect(source[:next_poll_at]).to eq((now + 300).utc.iso8601) + expect(source[:due_now]).to be(false) + end + + # nil here means "no constraint applies", not "unknown" — and JSON cannot say which + # without being told, which is what due_now is for. + it "says a source with nothing holding it back is due now" do + create_event_source + + expect(payload[:sources].first) + .to include(due_now: true, next_poll_at: nil, binding_component: nil) + end + + it "surfaces a source taken out of service, which nothing else exposes over HTTP" do + create_event_source(status: "failed", consecutive_failures: 3, last_error: "410 Gone") + + expect(payload[:sources].first) + .to include(status: "failed", enabled: true, consecutive_failures: 3) + end + + it "reports each source's own latest finished run" do + first = create_event_source + second = create_event_source(source_type: "github_fixture_events") + IngestionRun.create!(event_source: first, started_at: now - 600, completed_at: now - 590, + status: "completed") + newest = IngestionRun.create!(event_source: first, started_at: now - 120, + completed_at: now - 110, status: "not_modified") + + runs = payload[:sources].map { |source| source[:last_run] } + + expect(runs.first).to eq(run_id: newest.run_id, status: "not_modified", + completed_at: (now - 110).utc.iso8601) + expect(runs.second).to be_nil + expect(second.reload).to be_present + end + + # §11 asks for the "last run", and the whole reason an operator opens /status is to + # find out why nothing is moving. Filtering to successes — §9's question, and the one + # StateSummary's "Latest successful run" line answers — would hide a fresh failure + # behind an older 200 and show a healthy last_run for a source that had just failed. + %w[failed deferred].each do |status| + it "does not hide a fresh #{status} run behind an older success" do + source = create_event_source + IngestionRun.create!(event_source: source, started_at: now - 600, + completed_at: now - 590, status: "completed") + newest = IngestionRun.create!(event_source: source, started_at: now - 120, + completed_at: now - 110, status: status) + + expect(payload[:sources].first[:last_run]) + .to eq(run_id: newest.run_id, status: status, + completed_at: (now - 110).utc.iso8601) + end + end + + it "ignores a run still in flight, which has completed nothing to report" do + source = create_event_source + IngestionRun.create!(event_source: source, started_at: now, status: "running") + + expect(payload[:sources].first[:last_run]).to be_nil + end + end + + describe "consistency of the snapshot" do + # The reason this is one aggregate rather than StateSummary and Summary side by side. + # Three independent reads could straddle a committing reservation and produce a body + # whose poll block contradicts its ledger block. + it "reads the ledger row exactly once" do + active_budget_window(now: now) + allow(GithubApiBudget).to receive(:find_by).and_call_original + + described_class.capture(now: now).payload + + expect(GithubApiBudget).to have_received(:find_by).once + end + + it "renders every timestamp the way the printed report does" do + create_event_source(cadence_due_at: now + 300) + active_budget_window(now: now) + body = payload + + expect(body[:captured_at]).to eq(now.utc.iso8601) + expect(body.dig(:ledger, :reset_at)).to eq((now + 3600).utc.iso8601) + expect(body[:sources].first[:next_poll_at]).to eq((now + 300).utc.iso8601) + end + end +end diff --git a/spec/services/inspection/cursor_spec.rb b/spec/services/inspection/cursor_spec.rb new file mode 100644 index 0000000..4641b5e --- /dev/null +++ b/spec/services/inspection/cursor_spec.rb @@ -0,0 +1,80 @@ +require "rails_helper" + +RSpec.describe Inspection::Cursor do + let(:occurred_at) { Time.utc(2026, 7, 29, 12, 0, 0, 123_456) } + + describe "the round trip" do + it "returns the position it encoded" do + decoded = described_class.decode(described_class.new(occurred_at: occurred_at, id: 42).encode) + + expect(decoded).to eq(described_class.new(occurred_at: occurred_at, id: 42)) + end + + # push_events.occurred_at is timestamp(6), and a whole-second cursor would be ambiguous + # inside a single second — which is exactly the window one poll writes an entire page of + # events into, and therefore exactly where a page boundary is most likely to fall. + it "keeps microseconds, because a whole second holds a whole page" do + decoded = described_class.decode(described_class.new(occurred_at: occurred_at, id: 1).encode) + + expect(decoded.occurred_at.usec).to eq(123_456) + end + + it "is URL-safe and unpadded, so it survives a query string untouched" do + encoded = described_class.new(occurred_at: occurred_at, id: 42).encode + + expect(encoded).to match(/\A[A-Za-z0-9\-_]+\z/) + end + + it "reads a position straight off a record" do + actor = create_actor(github_id: 1) + repository = create_repository(github_id: 2) + event = create_push_event(actor: actor, repository: repository) + + expect(described_class.from(event)) + .to eq(described_class.new(occurred_at: event.occurred_at, id: event.id)) + end + end + + # nil rather than a fallback to the first page. A paging client that corrupts its cursor + # and silently gets page one back would loop forever without ever seeing an error; the + # caller turns this nil into a 400. + describe "input it cannot read" do + it "refuses anything that is not a cursor it issued" do + [ "not-base64!", Base64.urlsafe_encode64("junk"), + Base64.urlsafe_encode64("2026-07-29T12:00:00Z|abc"), + Base64.urlsafe_encode64("|42"), + Base64.urlsafe_encode64("not-a-time|42") ].each do |value| + expect(described_class.decode(value)).to be_nil, "expected #{value.inspect} refused" + end + end + + it "treats blank as absent rather than as corrupt" do + expect(described_class.decode(nil)).to be_nil + expect(described_class.decode("")).to be_nil + end + + # Well-formed but unrepresentable. Both halves reach the seek predicate as raw binds, + # where PostgreSQL raises rather than casts — PG::NumericValueOutOfRange one past + # BIGINT_MAX, and PG::DatetimeFieldOverflow one year past MAX_TIMESTAMP_YEAR — so + # without this a forged cursor is a 500 on input the client fully controls. Ruby is no + # help: Time.iso8601 parses a year in the hundreds of millions without complaint. + it "refuses a position the database could not compare against" do + [ "2026-07-29T12:00:00Z|#{Inspection::BIGINT_MAX + 1}", + "999999999-01-01T00:00:00Z|42", + "#{Inspection::MAX_TIMESTAMP_YEAR + 1}-01-01T00:00:00Z|42" ].each do |forged| + expect(described_class.decode(Base64.urlsafe_encode64(forged))) + .to be_nil, "expected #{forged.inspect} refused" + end + end + + # The bounds are inclusive: the guard must refuse what the database cannot hold and + # nothing else. + it "accepts the exact edge of what the database can hold" do + edge = "#{Time.utc(Inspection::MAX_TIMESTAMP_YEAR).iso8601(6)}|#{Inspection::BIGINT_MAX}" + + expect(described_class.decode(Base64.urlsafe_encode64(edge))) + .to have_attributes(id: Inspection::BIGINT_MAX, + occurred_at: Time.utc(Inspection::MAX_TIMESTAMP_YEAR)) + end + end +end diff --git a/spec/services/inspection/push_event_page_spec.rb b/spec/services/inspection/push_event_page_spec.rb new file mode 100644 index 0000000..890820b --- /dev/null +++ b/spec/services/inspection/push_event_page_spec.rb @@ -0,0 +1,243 @@ +require "rails_helper" + +RSpec.describe Inspection::PushEventPage do + let(:actor) { create_actor(github_id: 1001) } + let(:repository) { create_repository(github_id: 2001) } + + # Explicit ids and explicit instants: the unique index on github_event_id is the arbiter, + # and an implicit sequence would hide the ordering under test from the example reading it. + # `prefix` is what lets one example build two series without colliding on that index. + def series(count, occurred_at: frozen_time, prefix: 4, actor: self.actor, + repository: self.repository) + (1..count).map do |n| + create_push_event(actor: actor, repository: repository, + github_event_id: "#{prefix}000000#{format("%04d", n)}", + occurred_at: occurred_at + n) + end + end + + def page(**params) = described_class.for(params) + def ids(page) = page.records.map(&:id) + + describe "ordering" do + it "returns the newest event first" do + oldest, middle, newest = series(3) + + expect(ids(page)).to eq([ newest.id, middle.id, oldest.id ]) + end + + # occurred_at is not unique — one poll commits a whole page of events at once — so + # without the id tiebreak the order inside a group is whatever the plan happens to + # produce, and a page boundary falling inside that group loses or repeats rows. + it "orders deterministically when occurred_at ties" do + tied = 3.times.map do |n| + create_push_event(actor: actor, repository: repository, + github_event_id: "5000000000#{n}", occurred_at: frozen_time) + end + + first = page(limit: 1) + second = page(limit: 1, cursor: first.next_cursor.encode) + third = page(limit: 1, cursor: second.next_cursor.encode) + + expect(ids(first) + ids(second) + ids(third)).to eq(tied.map(&:id).sort.reverse) + end + + it "answers identically to an identical request" do + series(3) + + expect(ids(page)).to eq(ids(page)) + end + end + + describe "keyset paging" do + # The limit + 1 probe. Without it every list advertises a phantom empty next page, and + # a client dutifully fetches it. + it "offers no next page when the last row fits exactly" do + series(3) + + expect(page(limit: 3).next_cursor).to be_nil + end + + it "offers a next page when one more row exists" do + series(4) + first = page(limit: 3) + + expect(first.next_cursor).to be_present + expect(ids(page(limit: 3, cursor: first.next_cursor.encode)).length).to eq(1) + end + + it "walks the whole table without repeating or skipping a row" do + all = series(5) + walked = [] + cursor = nil + + loop do + current = page(limit: 2, cursor: cursor&.encode) + walked.concat(ids(current)) + cursor = current.next_cursor + break if cursor.nil? + end + + expect(walked).to eq(all.reverse.map(&:id)) + expect(walked.uniq).to eq(walked) + end + + # The example that justifies keyset over offset. The poller writes continuously and this + # list is newest-first, so under ?offset=N a row that landed between pages shifts + # everything down: page 2 re-serves rows from page 1 and skips others. + it "neither repeats nor skips a row when a new event lands between pages" do + older = series(4) + first = page(limit: 2) + create_push_event(actor: actor, repository: repository, + github_event_id: "40000000099", occurred_at: frozen_time + 1.hour) + + second = page(limit: 2, cursor: first.next_cursor.encode) + + expect(ids(second)).not_to include(*ids(first)) + expect(ids(first) + ids(second)).to eq(older.reverse.map(&:id)) + end + + it "returns an empty page past the end rather than restarting" do + series(2) + last = page(limit: 2) + beyond = page(limit: 2, cursor: Inspection::Cursor.from(last.records.last).encode) + + expect(beyond.records).to be_empty + expect(beyond.next_cursor).to be_nil + end + + it "returns nothing at all on an empty table" do + expect(page).to have_attributes(records: [], next_cursor: nil, limit: 25) + end + end + + describe "filters" do + it "narrows to one actor and to one repository" do + other_actor = create_actor(github_id: 1002, login: "other") + other_repository = create_repository(github_id: 2002, full_name: "other/repo") + mine = series(1) + series(1, prefix: 5, actor: other_actor, repository: other_repository) + + expect(ids(page(actor_id: actor.github_id))).to eq(mine.map(&:id)) + expect(ids(page(repository_id: other_repository.github_id)).length).to eq(1) + end + + # A filter matching nothing is a true answer, not a missing resource. + it "answers an empty page for an id nothing references" do + series(2) + + expect(page(actor_id: 999_999).records).to be_empty + end + end + + describe "parameter validation" do + it "defaults the limit, and treats blank as absent rather than as zero" do + expect(page.limit).to eq(described_class::DEFAULT_LIMIT) + expect(page(limit: "").limit).to eq(described_class::DEFAULT_LIMIT) + expect(page(limit: "100").limit).to eq(100) + end + + # Refused rather than clamped to MAX_LIMIT: a client that asked for 500 and received + # 100 cannot tell whether it received everything, and §16 rules out that kind of + # misleading answer. The ceiling is named so the correction takes one round trip. + it "refuses an out-of-range limit instead of silently clamping it" do + expect { page(limit: "99999") } + .to raise_error(Inspection::Errors::InvalidParameter, /limit must be an integer from 1 to 100/) + expect { page(limit: "0") }.to raise_error(Inspection::Errors::InvalidParameter) + expect { page(limit: "-1") }.to raise_error(Inspection::Errors::InvalidParameter) + end + + it "refuses anything that is not a decimal integer" do + [ "abc", "1.5", "1e2", "0x10", "1_0", " 5", "+5" ].each do |value| + expect { page(limit: value) } + .to raise_error(Inspection::Errors::InvalidParameter), + "expected limit=#{value.inspect} refused" + end + end + + # The reason the regex is \A\d+\z rather than Kernel#Integer. Integer("010") is 8 — + # a leading zero silently switches the base, so "?limit=010" would return eight rows to + # a client that asked for ten. Read as decimal it means what it reads as. + it "reads a leading zero as decimal, not as octal" do + expect(page(limit: "010").limit).to eq(10) + end + + it "refuses a github id that is not a positive decimal" do + expect { page(actor_id: "abc") } + .to raise_error(Inspection::Errors::InvalidParameter, /actor_id must be a GitHub id/) + expect { page(repository_id: "0") }.to raise_error(Inspection::Errors::InvalidParameter) + end + + # The failure this prevents is silent, which is what makes it worth a guard rather than + # leaving it to the database. github_actor_id is a signed bigint, and Active Record does + # not raise when a larger value is bound to a typed column — it casts it and the query + # returns normally, so an id no row could ever hold yields an empty page a client cannot + # tell from a genuine miss. + it "refuses a github id past the bigint the column can hold" do + expect(page(actor_id: Inspection::BIGINT_MAX.to_s).actor_id) + .to eq(Inspection::BIGINT_MAX) + + [ Inspection::BIGINT_MAX + 1, 10**24 ].each do |value| + expect { page(actor_id: value.to_s) } + .to raise_error(Inspection::Errors::InvalidParameter, /actor_id/) + expect { page(repository_id: value.to_s) } + .to raise_error(Inspection::Errors::InvalidParameter, /repository_id/) + end + end + + # Unlike the filter above, these two reach the seek predicate as raw binds, where + # PostgreSQL raises rather than casts: PG::NumericValueOutOfRange for the id and + # PG::DatetimeFieldOverflow for the year. Either would be a 500 on input the client + # fully controls. + it "refuses a cursor the database could not compare against" do + [ "2026-07-29T12:00:00Z|#{Inspection::BIGINT_MAX + 1}", + "999999999-01-01T00:00:00Z|42" ].each do |forged| + expect { page(cursor: Base64.urlsafe_encode64(forged)) } + .to raise_error(Inspection::Errors::InvalidParameter, /cursor/), + "expected #{forged.inspect} refused" + end + end + + it "still accepts a cursor at the exact edge of what the database can hold" do + edge = "#{Time.utc(Inspection::MAX_TIMESTAMP_YEAR).iso8601(6)}|#{Inspection::BIGINT_MAX}" + + expect { page(cursor: Base64.urlsafe_encode64(edge)) }.not_to raise_error + end + + it "refuses a cursor it did not issue" do + expect { page(cursor: "not-a-cursor") } + .to raise_error(Inspection::Errors::InvalidParameter, /cursor is not a cursor/) + end + + # "?repo_id=5" is a plausible typo for repository_id. Ignoring it would answer a + # question nobody asked with the entire unfiltered feed, while looking exactly like a + # successful filtered response. + it "refuses an unknown parameter rather than answering a different question" do + expect { page(repo_id: "5") } + .to raise_error(Inspection::Errors::InvalidParameter, /repo_id is not a parameter/) + end + + it "ignores the keys Rails puts in params itself" do + expect { page(controller: "api/push_events", action: "index", format: :json) } + .not_to raise_error + end + end + + describe "the guarantee that reading events costs nothing (plan §11)" do + it "initiates no GitHub request" do + transport = fixture_transport + allow(Github).to receive(:transport).and_return(transport) + expect(Github).not_to receive(:executor) + + page + + expect(transport.requests).to be_empty + end + + it "issues no write statement" do + series(2) + + expect(write_statements { page }).to be_empty + end + end +end diff --git a/spec/services/inspection/push_event_view_spec.rb b/spec/services/inspection/push_event_view_spec.rb new file mode 100644 index 0000000..b7a547e --- /dev/null +++ b/spec/services/inspection/push_event_view_spec.rb @@ -0,0 +1,107 @@ +require "rails_helper" + +RSpec.describe Inspection::PushEventView do + let(:actor) { create_actor(github_id: 1001) } + let(:repository) { create_repository(github_id: 2001) } + let(:event) { create_push_event(actor: actor, repository: repository) } + + describe ".summary" do + it "identifies the event by the id §11 puts on every log line" do + expect(described_class.summary(event)).to include(id: event.github_event_id) + end + + # The surrogate primary key is not this application's identity vocabulary — even the + # foreign keys target github_id — and it survives only inside the opaque cursor. + it "exposes the surrogate primary key nowhere" do + expect(described_class.summary(event)).not_to have_key(:record_id) + expect(described_class.summary(event).values).not_to include(event.id) + end + + # push_events.raw_payload is jsonb NOT NULL holding a whole GitHub envelope, deliberately + # un-indexed and almost always TOASTed. A page of them is two orders of magnitude larger + # than the fields anyone reads in a list. + it "keeps the TOASTed payload out of the list shape" do + expect(described_class.summary(event)).not_to have_key(:raw_payload) + end + + # The gap between the two is the ingestion latency §11 otherwise exposes only in logs. + it "reports GitHub's clock and this application's separately" do + expect(described_class.summary(event)) + .to include(occurred_at: event.occurred_at.utc.iso8601, + ingested_at: event.created_at.utc.iso8601) + end + + it "nests both entities with the enrichment state a reviewer watches flip" do + actor.update!(enrichment_status: "complete", fetched_at: frozen_time, name: "The Octocat") + + summary = described_class.summary(event) + + expect(summary[:actor]).to include(github_id: 1001, login: "octocat", + name: "The Octocat", + enrichment_status: "complete", + fetched_at: frozen_time.utc.iso8601) + expect(summary[:repository]).to include(github_id: 2001, + full_name: "octocat/hello-world", + enrichment_status: "pending", + fetched_at: nil) + end + + # A log line drops nil keys because an absent field is noise. A response body must not: + # "name": null means "not enriched yet", which is information, and a key that appears + # and disappears makes every client handle two shapes for one resource. + it "keeps its key set stable whether or not the entities are enriched" do + unenriched = described_class.summary(event) + actor.update!(enrichment_status: "complete", fetched_at: frozen_time, name: "x") + repository.update!(enrichment_status: "complete", fetched_at: frozen_time, + description: "y", language: "Ruby") + + enriched = described_class.summary(event.reload) + + expect(enriched.keys).to eq(unenriched.keys) + expect(enriched[:actor].keys).to eq(unenriched[:actor].keys) + expect(enriched[:repository].keys).to eq(unenriched[:repository].keys) + end + + # last_error can hold a fetch error's message verbatim, and HealthController already + # establishes that internals do not cross the HTTP boundary. §11 assigns the aggregate + # view of retry state to /status. + it "leaks no per-entity retry diagnostics" do + summary = described_class.summary(event) + + expect(summary[:actor].keys) + .not_to include(:last_error, :next_retry_at, :enrichment_attempts, :raw_payload) + end + end + + describe ".detail" do + # §16 makes "raw payload is retained" a functional gate, and this is what makes it + # demonstrable without a psql session. + it "is the list shape plus the retained payload" do + detail = described_class.detail(event) + + expect(detail.except(:raw_payload)).to eq(described_class.summary(event)) + expect(detail[:raw_payload]).to eq(event.raw_payload) + end + end + + describe ".page" do + it "wraps the rows and reports the paging position beside them" do + event + rendered = described_class.page(Inspection::PushEventPage.for(limit: "1")) + + expect(rendered.keys).to eq(%i[data pagination]) + expect(rendered[:data].map { |row| row[:id] }).to eq([ event.github_event_id ]) + expect(rendered[:pagination]).to eq(limit: 1, count: 1, next_cursor: nil) + end + + it "hands back the cursor that reaches the next page" do + event + create_push_event(actor: actor, repository: repository, + github_event_id: "40000000002", occurred_at: frozen_time - 60) + + rendered = described_class.page(Inspection::PushEventPage.for(limit: "1")) + + expect(rendered[:pagination][:next_cursor]).to be_a(String) + end + end +end diff --git a/spec/support/model_builders.rb b/spec/support/model_builders.rb index 01e400e..0fcc478 100644 --- a/spec/support/model_builders.rb +++ b/spec/support/model_builders.rb @@ -82,6 +82,18 @@ def quarantined_event_attributes(**overrides) def create_budget(**overrides) GithubApiBudget.create!(overrides) end + + # create! rather than PushEvent.insert_if_new, deliberately: created_at bounds §11's + # coverage window, and record_timestamps on the real write path stamps Time.current with + # no way to override it. create! honours an explicit created_at, which is what lets a + # spec place a row on either side of the window without travelling time. + # + # github_event_id defaults to one constant in push_event_attributes, so a series needs an + # explicit id per row — the unique index is the arbiter and a silent sequence here would + # hide that from the example reading it. + def create_push_event(actor:, repository:, **overrides) + PushEvent.create!(push_event_attributes(actor: actor, repository: repository, **overrides)) + end end RSpec.configure do |config| diff --git a/spec/support/sql_helpers.rb b/spec/support/sql_helpers.rb new file mode 100644 index 0000000..b90228a --- /dev/null +++ b/spec/support/sql_helpers.rb @@ -0,0 +1,38 @@ +# §11 places one guarantee on every health and inspection endpoint: they report persisted +# state and never initiate a GitHub request. Github::Ingestion::StateSummary states the +# corollary its own specs pin — a read path must also not *write*, because the subtle +# version of the mistake is calling Github::BudgetLedger#bootstrap! and creating the very +# row a reservation owns. +# +# Counting rows before and after catches that only for tables a spec thought to count. +# Subscribing to the statements themselves catches it for every table, including the ones +# a future collaborator introduces. +module SqlHelpers + # Rails wraps each example in a transaction and emits savepoint statements around + # anything using requires_new, so those are not writes to the business tables and must + # not be reported as such. TRANSACTION-payload events (BEGIN/COMMIT) carry no :sql in + # some adapters, hence the guard. + WRITE = /\A\s*(INSERT|UPDATE|DELETE|TRUNCATE|CREATE|ALTER|DROP)\b/i + + def capture_sql + statements = [] + + subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*, payload| + statements << payload[:sql] if payload[:sql].present? + end + + yield + + statements + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def write_statements(&block) + capture_sql(&block).grep(WRITE) + end +end + +RSpec.configure do |config| + config.include SqlHelpers +end