diff --git a/docs/TELEMETRY.md b/docs/TELEMETRY.md index 611136de5..cf456aeb1 100644 --- a/docs/TELEMETRY.md +++ b/docs/TELEMETRY.md @@ -85,7 +85,7 @@ writes by name. | `devops_cli_rag_query_duration_ms` | Histogram | `ms` | RAG retrieval time, by stage: embedding, search, ranking, or total for the whole query. | | `devops_cli_qdrant_retries_total` | Counter | `1` | Qdrant requests retried after a transient error, by operation and error type. | | `devops_cli_rag_points` | Gauge | `1` | Points stored in RAG vector collections, by collection. | -| `devops_cli_github_requests_total` | Counter | `1` | GitHub requests the rate limiter paced, each attempt and retry once, by resource, method, repo and row. The resource is the rate limit resource the request spends, such as core, graphql or search. The method is the HTTP method; a GraphQL request is a POST, and a gh command other than gh api is a POST when it writes and a GET when it reads. The repo is the repository of the roadmap Service worker that sent the request, one of service.repos, and the row is the job row that sent it, such as metrics, intake, refine or alternatives; each is other outside a worker or a row. A gh command and a request of the GitHub session both count. | +| `devops_cli_github_requests_total` | Counter | `1` | GitHub requests the rate limiter paced, each attempt and retry once, by resource, method, status, repo and row. The resource is the rate limit resource the request spends, such as core, graphql or search. The method is the HTTP method; a GraphQL request is a POST, and a gh command other than gh api is a POST when it writes and a GET when it reads. The status is the HTTP status of the answer, such as 200 or 304. It is none for a gh command or for an attempt that got no answer. The repo is the repository of the roadmap Service worker that sent the request, one of service.repos, and the row is the job row that sent it, such as metrics, intake, refine or alternatives; each is other outside a worker or a row. A gh command and a request of the GitHub session both count. | | `devops_cli_github_throttle_wait_seconds` | Histogram | `s` | Time devops-cli waited before it sent a refused GitHub request again, by resource: one observation for each throttle. GitHub refused the request with a rate limit, or the GitHub session got a 5xx for a read. | | `devops_cli_github_graphql_points_total` | Counter | `1` | GraphQL points that GitHub reported each answer cost in its rateLimit field. | | `devops_cli_firecrawl_searches_total` | Counter | `1` | Firecrawl web searches, by result: ok, the HTTP status of a search that Firecrawl refused, such as 402 when the account has no credits or 429 at its rate limit, or error for a search that got no answer or a reply with no web results. | diff --git a/k8s/README.md b/k8s/README.md index 4951312fd..90b25cf9c 100644 --- a/k8s/README.md +++ b/k8s/README.md @@ -627,7 +627,7 @@ kubectl -n devops logs -f job/ 9. To rotate a credential, update it in the keyring: `uv run devops config set service.webhook_secrets`, or, for the App, generate a new private key and run `uv run devops config set service.github_app.private_key --from-file `. Then run `uv run devops k8s push-secrets --only devops/devops-cli --rotate`. It restarts `roadmap-service`. Delete the old private key on the App's page after the restart. 10. Run one service per set of repos. While it runs, use `devops roadmap run --dry-run` (#981). 11. The Service keeps three files in `/home/devops/.data/roadmap/` on volume `roadmap-service-home`, beside the `schedule.json` of each repository: `service-halt.json` (GitHub refused the identity), `service-budget.json` (the GitHub requests of the last hour) and `service-failures.json` (the jobs that failed rounds in a row). A restart reads them back, so a restart does not clear a halt, the budget or a suspended job. A round that ends because the Service is stopping, for example in a rollout, does not count as a failed round: the count of its job stays as it was. The log line that suspends a job names the class of the error of each of its failed rounds in a row; the file keeps only the count, so a round that an earlier process counted reads as `unknown`. A rate limit that one request gets stops the requests of all workers until its wait ends. When GitHub refuses the identity, for example because the App's installation is suspended, the Service halts and logs `GitHub refused the identity`. To clear the halt after you fix the cause, remove the file and restart the Service: `kubectl -n devops exec deploy/roadmap-service -- rm /home/devops/.data/roadmap/service-halt.json`, then `kubectl -n devops delete pod -l app.kubernetes.io/name=roadmap-service`. -12. The Service's `/metrics` shows the budget and the suspended jobs (#2475): `devops_cli_service_budget_limit_requests` (the hourly budget), `devops_cli_service_budget_spent_requests` (the GitHub requests of the last hour), `devops_cli_service_budget_holds_total` (one count each time a hold begins), `devops_cli_service_job_suspended` (1 while a job of a repository, by `repo` and `row`, waits for new input after it failed 3 rounds in a row) and `devops_cli_service_implement_failures_total` (one count for each runner Job that left a stop, by the failure `class` and `repo`, when a round reports the Job; #3065; the values of `class` are the classes in [docs/ROADMAP_WORKFLOW.md](../docs/ROADMAP_WORKFLOW.md), The failure classes, and a panel or rule matches no other value, #3476). Each counter of the Service starts its label sets at zero (#3495, [docs/TELEMETRY.md](../docs/TELEMETRY.md)), except `devops_cli_service_identity_refused_total`, whose label set starts with the first refusal. Each GitHub request counts in `devops_cli_github_requests_total` under its `method`, the `repo` of the worker that sent it and the job `row` (`metrics`, `intake`, `refine`, `stage`, `implement`, `stage_ready` or `alternatives`); a request outside a worker or a row counts as `other`. To find what spent the budget, run `sum by (repo, row, method) (increase(devops_cli_github_requests_total{job="roadmap-service"}[1h]))` in Grafana Explore. A delivery of the App bot's own write counts as outcome `self` in `devops_cli_service_webhook_deliveries_total`. +12. The Service's `/metrics` shows the budget and the suspended jobs (#2475): `devops_cli_service_budget_limit_requests` (the hourly budget), `devops_cli_service_budget_spent_requests` (the GitHub requests of the last hour), `devops_cli_service_budget_holds_total` (one count each time a hold begins), `devops_cli_service_job_suspended` (1 while a job of a repository, by `repo` and `row`, waits for new input after it failed 3 rounds in a row) and `devops_cli_service_implement_failures_total` (one count for each runner Job that left a stop, by the failure `class` and `repo`, when a round reports the Job; #3065; the values of `class` are the classes in [docs/ROADMAP_WORKFLOW.md](../docs/ROADMAP_WORKFLOW.md), The failure classes, and a panel or rule matches no other value, #3476). Each counter of the Service starts its label sets at zero (#3495, [docs/TELEMETRY.md](../docs/TELEMETRY.md)), except `devops_cli_service_identity_refused_total`, whose label set starts with the first refusal. Each GitHub request counts in `devops_cli_github_requests_total` under its `method`, its `status` (the HTTP status of the answer, or `none` for a gh command or an attempt with no answer), the `repo` of the worker that sent it and the job `row` (`metrics`, `intake`, `refine`, `stage`, `implement`, `stage_ready` or `alternatives`); a request outside a worker or a row counts as `other`. To find what spent the budget, run `sum by (repo, row, method) (increase(devops_cli_github_requests_total{job="roadmap-service"}[1h]))` in Grafana Explore. A delivery of the App bot's own write counts as outcome `self` in `devops_cli_service_webhook_deliveries_total`. 13. A refine round writes at most 2 comments on one item in 24 hours. A round that finds 2 refine comments of the last 24 hours on an item leaves the item alone, with no model call and no comment. The item waits on a person and takes no place under the round's limit, so the round refines the next item. For each newest comment on the item that the cap leaves with no answer, the round records the time of that comment in the item's job record (`refine.capped_after`), logs `Refine left # alone and wrote no comment`, and adds 1 to `devops_cli_roadmap_refine_comments_capped_total`. A later round that finds no newer comment does not log or count the item again. A person refines the item at the cap with `devops roadmap refine --item --confirm`. Each Firecrawl search counts in `devops_cli_firecrawl_searches_total` by `result`: `ok`, the HTTP status of a refused search, or `error`. A failed search logs `A Firecrawl web search failed` with the status or the error class, and never the key or the query. 14. The row `alternatives` of the model lane runs after `refine`: on a first run, and 719 minutes after its last success. It runs `devops roadmap alternatives --confirm` for the repository. A round checks at most `roadmap.alternatives.first_pass_limit` items (20 by default) while an item has no check, and at most `roadmap.alternatives.limit` items (5 by default) after. The row runs about twice a day, so a first pass of 141 items takes about 4 days. A round takes first the items with no check, then the items whose check is older than `roadmap.alternatives.recheck_days` (30 by default) or whose text changed. A webhook makes the row due at no other time. The row changes no label and closes no issue. It does nothing, and logs `The alternatives check of is off`, for a private repository and when no Firecrawl key is set. If the check of an item fails, the row records the failure in the item's job record (`alternatives.failed_at` and `alternatives.failed_error`, the class of the error), writes the other checks and succeeds. The row fails, and counts toward the suspension after 3 failed rounds, only when it tried items and checked none. A round takes a failed item again after `roadmap.alternatives.retry_days` (3 by default). Each written check adds 1 to `devops_cli_roadmap_alternatives_total` by `verdict`: `covers`, `partly`, `none` or `not-applicable`. An item of the type `test`, `docs`, `refactor`, `chore`, `ci` or `perf`, and a `fix` with a Python traceback in its body, gets `not-applicable` with no model call; every other item must run a search before the check accepts a verdict, and gets one more turn to search. A `covers` verdict makes refine ask a person to adopt the tool or to keep the item with a reason. The item waits on a person until a reply answers the question, and Ready items with a new covering tool go back to New. Refine records the tool it asked about in the job record (`refine.alternatives_asked`). `devops roadmap run --dry-run` lists the row when it is due. 15. The row `stage` follows `refine` on the model lane (#2659). It runs `devops roadmap stage --confirm` in the model clone: it is due every 37 minutes, on a first run, and in a round where `refine` set an item Ready. It stages the Ready items that `roadmap.stage.filter` names, at most `roadmap.stage.limit` in a round, plans no new item while the count of open Planned items is at `roadmap.stage.planned_limit` (an item with the priority `P0-Critical` passes it, #3487), and splits a task group over `roadmap.stage.step_tokens`. Each task group has a kind (#3005): a `behavior` group has a failing test, and an `other` group has no test but a command or the steps of a manual check that prove it. The job sends a reply that breaks this rule back to the model once. It leaves out an item whose change folder is on the default branch or in its archive (#2714): a round reads that tree once with `git ls-tree`, so a merged staging pull request never makes a second one. The pull request it opens is a draft with the title `docs(openspec): plan # `. The job does not mark it ready: the row `stage_ready` does (step 18). Before it opens one, it checks each path of the plan (`reads`, `changes`, the code spans of the tasks and `verify`) against the tracked files of the commit it plans, read with one `git ls-files` for the round (#3010). A path that is no file there, and that no group up to its own creates, goes back to the model once with the files of the same name. When a later group creates the path, the problem names that group and tells the model to move it before the group that names the path (#3017). A second reply with a missing path stops the item, so no draft opens and the implement Job never meets a wrong path. `k8s/devops/configmap.example.yaml` holds the five settings, and `devops k8s deploy-stack --stack devops` applies them; each also has a variable, `DEVOPS_CLI_ROADMAP_STAGE_FILTER`, `DEVOPS_CLI_ROADMAP_STAGE_LIMIT`, `DEVOPS_CLI_ROADMAP_STAGE_PLANNED_LIMIT`, `DEVOPS_CLI_ROADMAP_STAGE_STEP_TOKENS` and `DEVOPS_CLI_ROADMAP_STAGE_TOOLSET`. The setting `roadmap.stage.toolset` is `extended` by default (#3238): a plan run then has three tools more than the nine that read the staged commit. `references` counts a text in every file of the commit. `read_issue` and `find_issues` read issues and pull requests of the repository on GitHub, as GET requests with the token of the Service and no other permission. `base` leaves them out. Each item of a round counts once in `devops_cli_roadmap_stage_total` by its `result`: `staged`, `skipped`, `needs_split` or `failed`. A failed item is recorded in its job record with the class of its error and the time (#3493), and the job leaves it out for `roadmap.stage.retry_hours` hours (6 by default) while it takes the other items. The row fails a round only when it tried items and staged, stopped or returned none, or when a failure belongs to no item; three such rounds on the same input suspend the row. The ledger file keeps the class of each error, and a round that the stop of the Service ends counts as `stopped`, not as an error. The image carries the pinned OpenSpec and a Node runtime, so the job validates each change before it pushes: `kubectl -n devops exec deploy/roadmap-service -- openspec --version` prints the locked version. diff --git a/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/.openspec.yaml b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/.openspec.yaml new file mode 100644 index 000000000..1491b921e --- /dev/null +++ b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-11-05 diff --git a/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/design.md b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/design.md new file mode 100644 index 000000000..3cee719b6 --- /dev/null +++ b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/design.md @@ -0,0 +1,36 @@ +# Design + +## Decisions + +### The status is a label of the request counter + +The counter keeps its name and its total. It gains a `status` label. The issue allows a status label or a separate 304 counter. A separate counter makes the total the sum of two metrics. The refine plan in #3497 rejects that option for this reason. + +### The request is counted after its answer + +`acquire` no longer counts a request. It runs before the request is sent, so it cannot know the status. `SessionGitHubAPI._request` counts each attempt after its answer, with the status `answer[0]`. A 304 therefore counts with status `304`. + +The session reads the token of a GitHub App after the attempt is paced. An attempt that raises before an answer counts with status `none`, a refused token included. The count is made in a `finally` block, and the error still propagates. A lost GET that the session sends again (#3506) counts each attempt, because the ledger paces each attempt. `run_gh` counts each paced attempt with status `none`, because gh does not report the HTTP status. + +### The labels are read in the thread that paces the request + +The request scope is a context variable. The session paces each request in a worker thread. So `pace_request` reads the request labels in that thread, and `_request` carries them to the count. The test `test_a_session_request_counts_the_scope_of_the_thread_that_sent_it` checks that the labels are those of the thread that sent the request. + +### A request that is not paced is not counted + +`gh_request_is_paced` exempts `gh api rate_limit`, and `run_gh` skips `acquire` for it. The count follows the same rule. An exempt request therefore counts nothing, as before. + +### The 304 charge stays + +The limiter charges each attempt, a 304 too. ADR 0006 records that every attempt is paced and charged. The issue allows a charge of 0 only when a measure shows that GitHub does not count the 304. The local ledger has no such measure. The charge therefore stays, and the metric keeps each 304 in its total. + +### The pace lines log at DEBUG + +Each pace line writes one record for a request that waits. The issue measured that these lines wrote 53.6% of a log sample at INFO. A per-request detail belongs at DEBUG. + +## Rejected alternatives + +- A separate 304 counter: it makes the total the sum of two metrics (see above). +- Keep the count in `acquire` with status `none`: the status of the answer would be lost. +- A charge of 0 for a 304: no local measure shows that GitHub does not count it, and the ledger would undercount. +- Keep INFO: it keeps the log volume that the issue reports. diff --git a/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/proposal.md b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/proposal.md new file mode 100644 index 000000000..426b7fa07 --- /dev/null +++ b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/proposal.md @@ -0,0 +1,45 @@ +# Proposal + +## Why + +Issue #3497: the Service spends most of its GitHub budget on reads. The request counter `devops_cli_github_requests_total` does not show whether an answer is a 304 or a 200. So the share of answers that find no change is not known. The rate limiter also logs each pace line at INFO. These lines wrote 53.6% of a log sample. + +## What Changes + +- Each paced attempt of the GitHub session counts once. Its `status` label holds the HTTP status of its answer. A 304 answer counts with status `304`. An attempt that gets no answer counts with status `none`, and that includes each lost GET that the session sends again. +- A gh command counts with status `none`, because gh does not report the HTTP status. +- The two pace lines of the rate limiter, the mandatory pause and the quota window reset, log at DEBUG. +- The counter keeps its name and its total. Every sum over the labels gives the value it gave before. +- The change adds a label to a metric that operators query. It carries a spec delta: two ADDED requirements in `github-api-metrics`. +- This change delivers criteria 1, 5 and 9 of #3497, and it fits one pull request. The status label comes first, because the other parts need it to measure the share of 304 answers. The other criteria moved to their own issues: #3667 (refine, and the live sum query), #3670 (scoped intake), #3671 (stage_ready) and #3672 (idle poll). + +## Capabilities + +### Modified Capabilities + +- `github-api-metrics`: each paced request names the status of its answer, and the pace lines log at DEBUG. + +## Impact + +- `src/devops_cli/telemetry/instruments.py`: the description of `devops_cli_github_requests_total` names the `status` label. +- `src/devops_cli/github/rate_limiter.py`: `acquire` no longer counts a request. `count_request` counts one with its status. `run_gh` counts each paced attempt with status `none`. The two pace lines log at DEBUG. +- `src/devops_cli/github/session_transport.py`: `pace_request` returns the request labels. `SessionGitHubAPI._request` reads the token of a GitHub App after the attempt is paced, and counts each attempt with the status of its answer. +- `tests/github/test_github_api_metrics.py`, `tests/github/test_github_app_identity.py`, `tests/github/test_github_rate_limiter.py`. +- `docs/TELEMETRY.md`, regenerated from the instrument description. +- `k8s/README.md`: the Service guide names the `status` label. + +## Feasibility + +The premise holds at origin/main d254410c, checked on 2026-11-05 with these reads: + +- `src/devops_cli/telemetry/instruments.py` lines 200 to 211: the description of `devops_cli_github_requests_total` names resource, method, repo and row. It has no status label. +- `src/devops_cli/github/rate_limiter.py` lines 1046 and 1092: both pace lines call `logger.info`. +- `src/devops_cli/github/rate_limiter.py` line 1089: `acquire` emits the counter before the request is sent, so it cannot know the status. +- `src/devops_cli/github/session_transport.py` `SessionGitHubAPI._request`: the answer tuple holds the HTTP status as `answer[0]`, so the session can count it. +- `.venv/lib/python3.14/site-packages/gidgethub/abc.py` lines 186 to 245: a 304 with a stored answer returns the stored data and its next link. The status of that answer stays 304. +- The local ledger keeps its charge of a 304, as ADR 0006 records. The metric therefore keeps the 304 attempts in its total. +- At origin/main f6d57ecd, after the rebase, `SessionGitHubAPI._request` sends a lost GET again in a loop (#3506). Each attempt of that loop is paced, so each attempt counts. + +## Existing Tool Considered + +The counter is an instrument that `emit()` sends over OTLP through the telemetry layer. The status is a label of that instrument. The change adds no library. It adds one function, `count_request`, beside the limiter that paces each request. The session already receives the status of each answer. The change deletes the emit in `acquire`, and its `method` parameter, which only the emit used. diff --git a/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/specs/github-api-metrics/spec.md b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/specs/github-api-metrics/spec.md new file mode 100644 index 000000000..b405b0a73 --- /dev/null +++ b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/specs/github-api-metrics/spec.md @@ -0,0 +1,21 @@ +## ADDED Requirements + +### Requirement: Each paced GitHub request names the HTTP status of its answer + +The request counter SHALL name the HTTP status of the answer to each paced GitHub request in its `status` label. A request that gets no answer, and a gh command, SHALL name the status `none`. + +#### Scenario: A 304 answer counts with its status +- **WHEN** the GitHub session sends a conditional GET and GitHub answers 304. +- **THEN** the counter has one sample for that attempt with `status` `304`. + +#### Scenario: A gh command counts with status none +- **WHEN** the rate limiter paces a gh command. +- **THEN** the counter has one sample for that attempt with `status` `none`. + +### Requirement: The rate limiter logs its pace lines at DEBUG + +The rate limiter SHALL log each mandatory pause and each quota window reset at DEBUG level. + +#### Scenario: A mandatory pause is logged at DEBUG +- **WHEN** the rate limiter delays a request for its quota. +- **THEN** the pause record has level DEBUG, and no record of that pause has level INFO. diff --git a/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/tasks.md b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/tasks.md new file mode 100644 index 000000000..b4d256fc5 --- /dev/null +++ b/openspec/changes/archive/2026-11-05-3497-cut-unchanged-github-reads/tasks.md @@ -0,0 +1,34 @@ +# Tasks + +## 1. The request counter names the HTTP status (behavior) + +- [x] 1.1 Write the failing tests. A session answer counts with its status, a 304 included. A gh command and an attempt with no answer count with status `none`. + Verification: `uv run devops ci test tests/github/test_github_api_metrics.py` +- [x] 1.2 Count each paced session attempt after its answer. Count each paced gh attempt with status `none`. Remove the emit from `acquire`. + Verification: `uv run devops ci test tests/github/test_github_api_metrics.py` +- [x] 1.3 Write the failing test for a paced attempt whose token is refused. It counts with status `none`. Then read the token inside that count. + Verification: `uv run devops ci test tests/github/test_github_app_identity.py` +- [x] 1.4 Write the test for a lost GET that the session sends again. Each attempt counts with its status. + Verification: `uv run devops ci test tests/github/test_github_api_metrics.py` + +## 2. The pace lines log at DEBUG (behavior) + +- [x] 2.1 Write the failing test. The mandatory pause and the quota window reset log at DEBUG. No record of them has level INFO. + Verification: `uv run devops ci test tests/github/test_github_rate_limiter.py` +- [x] 2.2 Change the two `logger.info` calls to `logger.debug`. Correct the docstring of `_passed_reset_delay`. + Verification: `uv run devops ci test tests/github/test_github_rate_limiter.py` + +## 3. Documents (other) + +- [x] 3.1 Regenerate the telemetry reference with `uv run devops docs generate --sync-readme`. + Verification: `uv run devops ci docs` +- [x] 3.2 Name the `status` label in the Service guide, `k8s/README.md`. + Verification: `grep -n 'under its `method`, its `status`' k8s/README.md` + +## Workflow follow-up + +- This change closes #3497. The other criteria of #3497 moved to these issues: +- #3667: an unchanged refine item reads no comments, and the live sum query. +- #3670: scoped intake reads a bounded page count. +- #3671: stage_ready backs off after a failed check. +- #3672: an idle repository polls less often. diff --git a/openspec/specs/github-api-metrics/spec.md b/openspec/specs/github-api-metrics/spec.md index 32d19410a..b48eccc99 100644 --- a/openspec/specs/github-api-metrics/spec.md +++ b/openspec/specs/github-api-metrics/spec.md @@ -71,3 +71,23 @@ Each count of `devops_cli_github_requests_total` SHALL carry the labels `repo`, #### Scenario: A round of a Service worker - **WHEN** a worker of the repository `example-org/repo1` runs a round with the rows `intake` and `refine` - **THEN** the round's own requests name `example-org/repo1` and the row `other`, and each row's requests name `example-org/repo1` and that row + +### Requirement: Each paced GitHub request names the HTTP status of its answer + +The request counter SHALL name the HTTP status of the answer to each paced GitHub request in its `status` label. A request that gets no answer, and a gh command, SHALL name the status `none`. + +#### Scenario: A 304 answer counts with its status +- **WHEN** the GitHub session sends a conditional GET and GitHub answers 304. +- **THEN** the counter has one sample for that attempt with `status` `304`. + +#### Scenario: A gh command counts with status none +- **WHEN** the rate limiter paces a gh command. +- **THEN** the counter has one sample for that attempt with `status` `none`. + +### Requirement: The rate limiter logs its pace lines at DEBUG + +The rate limiter SHALL log each mandatory pause and each quota window reset at DEBUG level. + +#### Scenario: A mandatory pause is logged at DEBUG +- **WHEN** the rate limiter delays a request for its quota. +- **THEN** the pause record has level DEBUG, and no record of that pause has level INFO. diff --git a/src/devops_cli/github/rate_limiter.py b/src/devops_cli/github/rate_limiter.py index 3b07186cb..582c5e5cc 100644 --- a/src/devops_cli/github/rate_limiter.py +++ b/src/devops_cli/github/rate_limiter.py @@ -1039,11 +1039,11 @@ def calculate_delay(self, subcommand: str = "core") -> float: def _passed_reset_delay(self, subcommand: str, reset_epoch: float, now: float) -> float: """The delay at a reset that has passed: until the margin past it, since GitHub's reset - is whole seconds and GitHub may still report the ended window. Logs one INFO record.""" + is whole seconds and GitHub may still report the ended window. Logs one DEBUG record.""" delay = max( self.min_interval, reset_epoch + CONST_GH_RATE_LIMIT_RESET_MARGIN_SECONDS - now, 0.0 ) - logger.info( + logger.debug( "[RateLimit] '%s' quota window reset at %s, %.2fs ago; waiting until at least %s", subcommand, _utc_text(reset_epoch), @@ -1065,13 +1065,11 @@ def acquire( resource: str | None = None, is_mutation: bool = False, cost: int = 1, - method: str = CONST_GH_API_DEFAULT_METHOD, ) -> float: """Institute mandatory pause of the request delay calculated for that subcommand. - Synchronizes global tracking across processes and serializes requests. Each request it - lets go adds 1 to `devops_cli_github_requests_total` for its resource, its HTTP `method`, - and the repository and job row of its request scope (#2475). + Synchronizes global tracking across processes and serializes requests. The caller counts + each request it lets go with `count_request` (#3497). """ gate = _request_gate if gate is not None: @@ -1086,10 +1084,9 @@ def acquire( ) else: sleep_duration = self._acquire_locked(target, is_mutation=is_mutation, cost=cost) - emit(GITHUB_REQUESTS_TOTAL, 1, {"resource": target, "method": method, **request_labels()}) if sleep_duration > 0.0: - logger.info( + logger.debug( "[RateLimit] Mandatory pause for '%s': delaying %.2fs", target, sleep_duration, @@ -1702,6 +1699,18 @@ def gh_request_method(clean_args: Sequence[str], *, is_mutation: bool) -> str: return CONST_GH_API_PARAMS_METHOD if is_mutation else CONST_GH_API_DEFAULT_METHOD +def count_request(resource: str, method: str, status: int | None, labels: dict[str, str]) -> None: + """Count one paced attempt in `devops_cli_github_requests_total` with the HTTP status of its + answer. An attempt with no answer, and a gh command, count with status `none` (#3497). + `labels` hold the repository and job row of the sender's request scope.""" + status_label = "none" if status is None else str(status) + emit( + GITHUB_REQUESTS_TOTAL, + 1, + {"resource": resource, "method": method, "status": status_label, **labels}, + ) + + def _execute_gh_single_attempt( full_cmd: list[str], input: str | None, @@ -1719,9 +1728,8 @@ def _execute_gh_single_attempt( ) -> subprocess.CompletedProcess[str]: """Execute a single attempt of GitHub CLI command under rate limiting.""" if not is_exempt: - limiter.acquire( - subcommand=target_resource, is_mutation=is_mutation, cost=cost, method=method - ) + limiter.acquire(subcommand=target_resource, is_mutation=is_mutation, cost=cost) + count_request(target_resource, method, None, request_labels()) try: proc = run_subprocess( full_cmd, diff --git a/src/devops_cli/github/session_transport.py b/src/devops_cli/github/session_transport.py index 3326cf070..defe2e65b 100644 --- a/src/devops_cli/github/session_transport.py +++ b/src/devops_cli/github/session_transport.py @@ -90,11 +90,13 @@ unread_after_close, ) from devops_cli.github.rate_limiter import ( + count_request, gh_request_is_paced, gh_request_resource, identity_rate_limiter, ) from devops_cli.github.request_classifier import GitHubRequest, is_write_request +from devops_cli.github.request_scope import request_labels from devops_cli.http.client import ClientOptions, new_async_http_client, request_timeout from devops_cli.http.egress import EgressLevel @@ -164,18 +166,18 @@ def _gh_api_command(url: str) -> list[str]: return [CONST_GH_API_SUBCOMMAND, httpx2.URL(url).path] -def pace_request(method: str, url: str, identity: str) -> str: +def pace_request(method: str, url: str, identity: str) -> tuple[str, dict[str, str] | None]: """Wait for the request's turn on the ledger of the identity `identity` names, as `run_gh` - waits for `gh api `, a write as a write, counted under its method; return the - rate-limit resource it spends.""" + waits for `gh api `. A write waits as a write. Return the rate-limit resource that the + request spends, and for a paced request the labels of its request scope, read in this thread + (#3497).""" command = _gh_api_command(url) resource = gh_request_resource(command) - if gh_request_is_paced(command): - is_mutation = is_write_request(GitHubRequest(method, command[1])) - identity_rate_limiter(identity).acquire( - subcommand=resource, is_mutation=is_mutation, method=method.upper() - ) - return resource + if not gh_request_is_paced(command): + return resource, None + is_mutation = is_write_request(GitHubRequest(method, command[1])) + identity_rate_limiter(identity).acquire(subcommand=resource, is_mutation=is_mutation) + return resource, request_labels() def charge_response(headers: Mapping[str, str], resource: str, identity: str) -> None: @@ -277,28 +279,33 @@ def __init__(self, client: httpx2.AsyncClient, identity: GitHubIdentity) -> None ) self._identity = identity - def _pace(self, method: str, url: str) -> tuple[str, str]: - """Wait for the attempt's turn on the ledger, then read the token to send it with: a - GitHub App's token is minted again when it nears its expiry during the wait.""" - return pace_request(method, url, self._identity.key), self._identity.token() + def _pace(self, method: str, url: str) -> tuple[str, dict[str, str] | None]: + """Wait for the attempt's turn on the ledger. Return the resource it spends, and the + labels that count it, or None when it is not paced.""" + return pace_request(method, url, self._identity.key) async def _request( self, method: str, url: str, headers: Mapping[str, str], body: bytes = b"" ) -> tuple[int, Mapping[str, str], bytes]: - """Send one attempt once the ledger allows it, with the current token, and charge what - its answer reports. A GET whose connection is lost is paced and sent again, after the - ledger's wait, while `_resend_after_lost` allows it. + """Send one attempt once the ledger allows it, with the current token. Count the attempt + with the status of its answer, or `none` when it gets no answer, a refused token included. + Charge what the answer reports. A GET whose connection is lost is paced, counted and sent + again, after the ledger's wait, while `_resend_after_lost` allows it. - The pacing wait may run until the quota resets, so a close does not wait it out. + The pacing wait may run until the quota resets, so a close does not wait it out. A GitHub + App's token is minted again here, when it nears its expiry, after the attempt is paced. """ attempt = 1 while True: - resource, token = await anyio.to_thread.run_sync( + resource, labels = await anyio.to_thread.run_sync( self._pace, method, url, abandon_on_cancel=True ) - sent = {**headers, "authorization": f"token {token}"} + status: int | None = None try: + token = await anyio.to_thread.run_sync(self._identity.token, abandon_on_cancel=True) + sent = {**headers, "authorization": f"token {token}"} answer = await super()._request(method, url, sent, body) + status = answer[0] except _LOST_CONNECTION as error: if not await self._resend_after_lost( error, method=method, url=url, attempt=attempt @@ -306,6 +313,9 @@ async def _request( raise attempt += 1 continue + finally: + if labels is not None: + count_request(resource, method.upper(), status, labels) self._last_body_empty = (answer[2] == b"") and bool(answer[1].get("content-type")) await anyio.to_thread.run_sync(charge_response, answer[1], resource, self._identity.key) return answer diff --git a/src/devops_cli/telemetry/instruments.py b/src/devops_cli/telemetry/instruments.py index 2db70bc63..c87b2356a 100644 --- a/src/devops_cli/telemetry/instruments.py +++ b/src/devops_cli/telemetry/instruments.py @@ -202,10 +202,12 @@ class Instrument: InstrumentKind.COUNTER, "1", "GitHub requests the rate limiter paced, each attempt and retry once, by resource, method, " - "repo and row. The resource is the rate limit resource the request spends, such as core, " - "graphql or search. The method is the HTTP method; a GraphQL request is a POST, and a gh " - "command other than gh api is a POST when it writes and a GET when it reads. The repo is the " - "repository of the roadmap Service worker that sent the request, one of service.repos, and " + "status, repo and row. The resource is the rate limit resource the request spends, such as " + "core, graphql or search. The method is the HTTP method; a GraphQL request is a POST, and a gh " + "command other than gh api is a POST when it writes and a GET when it reads. The status is the " + "HTTP status of the answer, such as 200 or 304. It is none for a gh command or for an attempt " + "that got no answer. The repo is the repository of the roadmap Service worker that sent the " + "request, one of service.repos, and " "the row is the job row that sent it, such as metrics, intake, refine or alternatives; each is " "other outside a worker or a row. A gh command and a request of the GitHub session both count", ) diff --git a/tests/github/test_github_api_metrics.py b/tests/github/test_github_api_metrics.py index 9eccab51e..43d920773 100644 --- a/tests/github/test_github_api_metrics.py +++ b/tests/github/test_github_api_metrics.py @@ -15,8 +15,10 @@ from datetime import UTC, datetime, timedelta from typing import Any +import httpx2 import pytest +from devops_cli.exceptions import GitHubUnreadError from devops_cli.github.rate_limiter import get_github_rate_limiter, run_gh from devops_cli.github.request_scope import request_scope from devops_cli.github.session import get_github_session @@ -78,7 +80,7 @@ def test_a_refused_and_retried_gh_command_counts_two_requests_and_one_wait( _histogram_points(otlp, GITHUB_THROTTLE_WAIT.name), ) == ( 0, - [({"resource": "core", "method": "GET", **_UNSCOPED}, 2.0)], + [({"resource": "core", "method": "GET", "status": "none", **_UNSCOPED}, 2.0)], [({"resource": "core"}, 1, 7.0)], ) @@ -103,7 +105,11 @@ def test_a_graphql_answer_counts_its_request_and_the_points_it_reports( otlp.points(GITHUB_REQUESTS_TOTAL.name), otlp.points(GITHUB_GRAPHQL_POINTS_TOTAL.name), _histogram_points(otlp, GITHUB_THROTTLE_WAIT.name), - ) == ([({"resource": "graphql", "method": "POST", **_UNSCOPED}, 1.0)], [({}, 3.0)], []) + ) == ( + [({"resource": "graphql", "method": "POST", "status": "none", **_UNSCOPED}, 1.0)], + [({}, 3.0)], + [], + ) def test_a_session_request_refused_once_counts_two_requests_and_its_wait( @@ -123,7 +129,10 @@ def test_a_session_request_refused_once_counts_two_requests_and_its_wait( otlp.points(GITHUB_REQUESTS_TOTAL.name), _histogram_points(otlp, GITHUB_THROTTLE_WAIT.name), ) == ( - [({"resource": "core", "method": "GET", **_UNSCOPED}, 2.0)], + [ + ({"resource": "core", "method": "GET", "status": "429", **_UNSCOPED}, 1.0), + ({"resource": "core", "method": "GET", "status": "200", **_UNSCOPED}, 1.0), + ], [({"resource": "core"}, 1, 1.0)], ) @@ -141,8 +150,17 @@ def test_a_write_of_a_job_row_counts_its_method_repository_and_row( run_gh(_COMMENT) assert otlp.points(GITHUB_REQUESTS_TOTAL.name) == [ - ({"resource": "core", "method": "POST", "repo": "octo/repo", "row": "refine"}, 1.0), - ({"resource": "core", "method": "POST", **_UNSCOPED}, 1.0), + ( + { + "resource": "core", + "method": "POST", + "status": "none", + "repo": "octo/repo", + "row": "refine", + }, + 1.0, + ), + ({"resource": "core", "method": "POST", "status": "none", **_UNSCOPED}, 1.0), ] @@ -175,5 +193,71 @@ def test_a_session_request_counts_the_scope_of_the_thread_that_sent_it( get_github_session().rest("PATCH", "/repos/octo/repo/issues/7", body={"title": "T"}) assert otlp.points(GITHUB_REQUESTS_TOTAL.name) == [ - ({"resource": "core", "method": "PATCH", "repo": "octo/repo", "row": "intake"}, 1.0) + ( + { + "resource": "core", + "method": "PATCH", + "status": "200", + "repo": "octo/repo", + "row": "intake", + }, + 1.0, + ) + ] + + +def test_a_304_answer_counts_once_with_status_304( + github_api: GitHubApiFake, otlp: FakeCollector +) -> None: + """A conditional GET that GitHub answers 304 is one paced request with status 304. The first + GET of that URL is one request with status 200.""" + etag = {"etag": '"v1"'} + github_api.route( + "GET", + "/user", + github_json({"login": "octocat"}, headers=etag), + github_json({"login": "octocat"}, headers=etag), + ) + session = get_github_session() + + session.rest("GET", "/user") + session.rest("GET", "/user") + + assert otlp.points(GITHUB_REQUESTS_TOTAL.name) == [ + ({"resource": "core", "method": "GET", "status": "200", **_UNSCOPED}, 1.0), + ({"resource": "core", "method": "GET", "status": "304", **_UNSCOPED}, 1.0), + ] + + +def test_a_get_that_loses_its_connection_counts_each_attempt_with_its_status( + github_api: GitHubApiFake, otlp: FakeCollector +) -> None: + """A lost GET is sent again (#3506). The lost attempt counts with status none, and the attempt + that gets the answer counts with its status.""" + github_api.route("GET", "/user", httpx2.RemoteProtocolError, github_json({"login": "octocat"})) + + get_github_session().rest("GET", "/user") + + assert otlp.points(GITHUB_REQUESTS_TOTAL.name) == [ + ({"resource": "core", "method": "GET", "status": "none", **_UNSCOPED}, 1.0), + ({"resource": "core", "method": "GET", "status": "200", **_UNSCOPED}, 1.0), ] + + +def test_a_request_that_gets_no_answer_counts_with_status_none( + github_api: GitHubApiFake, otlp: FakeCollector +) -> None: + """A refused connect gets no answer, so its one paced attempt counts with status none, and + the error still reaches the caller.""" + github_api.route("GET", "/user", httpx2.ConnectError) + + with pytest.raises(GitHubUnreadError) as raised: + get_github_session().rest("GET", "/user") + + assert ( + (type(raised.value), raised.value.error_code, raised.value.exit_code), + otlp.points(GITHUB_REQUESTS_TOTAL.name), + ) == ( + (GitHubUnreadError, "GITHUB_UNREAD", 1), + [({"resource": "core", "method": "GET", "status": "none", **_UNSCOPED}, 1.0)], + ) diff --git a/tests/github/test_github_app_identity.py b/tests/github/test_github_app_identity.py index f293e6e11..e53a8dd7f 100644 --- a/tests/github/test_github_app_identity.py +++ b/tests/github/test_github_app_identity.py @@ -30,7 +30,9 @@ from devops_cli.exceptions.git import GitHubUnauthenticatedError from devops_cli.github.rate_limiter import get_github_rate_limiter from devops_cli.github.session import get_github_session, reset_github_session +from devops_cli.telemetry.instruments import GITHUB_REQUESTS_TOTAL from tests.support.fakes.github import API, GitHubApiFake, github_json, quota_headers +from tests.support.fakes.otlp import FakeCollector APP_SETTINGS = {"app_id": 1001, "installation_id": 42, "slug": "devops-roadmap"} BOT_LOGIN = "devops-roadmap[bot]" @@ -368,3 +370,33 @@ def test_a_key_that_is_no_rsa_key_fails_before_any_request( "details": {"operation": "gh_auth_token"}, } assert app_identity.requested == [] + + +def test_an_app_request_whose_token_is_refused_counts_once_with_status_none( + app_identity: GitHubApiFake, otlp: FakeCollector +) -> None: + """The request waits its turn on the ledger before its token is minted. A refused mint still + counts the paced request with status none, and the refusal reaches the caller (#3497).""" + app_identity.route("POST", MINT, github_json({"message": "Bad credentials"}, status=401)) + + with pytest.raises(GitHubUnauthenticatedError) as raised: + get_github_session().rest("GET", "/user") + + assert ( + (type(raised.value), raised.value.error_code, raised.value.exit_code), + otlp.points(GITHUB_REQUESTS_TOTAL.name), + ) == ( + (GitHubUnauthenticatedError, "GITHUB_UNAUTHENTICATED", 1), + [ + ( + { + "resource": "core", + "method": "GET", + "status": "none", + "repo": "other", + "row": "other", + }, + 1.0, + ) + ], + ) diff --git a/tests/github/test_github_rate_limiter.py b/tests/github/test_github_rate_limiter.py index 932d3ae09..5f256b83b 100644 --- a/tests/github/test_github_rate_limiter.py +++ b/tests/github/test_github_rate_limiter.py @@ -195,6 +195,20 @@ def test_rate_limiter_mandatory_pause_when_quota_exhausted(clock: ClockFake) -> assert clock.waits[0] == pytest.approx(20.0, abs=0.5) +def test_a_mandatory_pause_logs_one_debug_record_and_no_info_record( + caplog: pytest.LogCaptureFixture, clock: ClockFake +) -> None: + """A pause is per-request detail: one DEBUG record names it, and no record of it is at INFO.""" + caplog.set_level(logging.DEBUG, logger="devops_cli.github.rate_limiter") + limiter = GitHubRateLimiter() + limiter.update_quota("core", remaining=0, limit=5000, reset_epoch=time.time() + 20.0) + + limiter.acquire("core") + + pause_levels = [r.levelno for r in caplog.records if "Mandatory pause" in r.getMessage()] + assert (len(clock.waits), pause_levels) == (1, [logging.DEBUG]) + + def test_rate_limiter_acquire_mandatory_pacing(tmp_path: Path, clock: ClockFake) -> None: """Verify acquire always applies calculated pacing delay with zero threshold bypass.""" cache_file = tmp_path / "gh_quota.json" @@ -1870,7 +1884,7 @@ def test_a_call_just_past_a_reset_waits_out_the_reset_second( """GitHub still reports the window that reset 0.5 s ago: the call refreshes once, waits until a second past that reset and runs, logging the boundary once. The request is not counted against the old window.""" - caplog.set_level(logging.INFO, logger="devops_cli.github.rate_limiter") + caplog.set_level(logging.DEBUG, logger="devops_cli.github.rate_limiter") gh = _GhAtTheReset({"core": _window(7, _RESET)}) with _clock_at(clock, _RESET + 0.5, gh, stored_core_reset=_RESET): proc = run_gh(_ISSUES) @@ -1894,6 +1908,8 @@ def test_a_call_just_past_a_reset_waits_out_the_reset_second( "waiting until at least 2026-10-08T12:00:01Z" ], ) + reset_levels = [r.levelno for r in caplog.records if "quota window reset" in r.getMessage()] + assert reset_levels == [logging.DEBUG] def test_a_call_after_an_idle_hour_paces_from_the_new_window(clock: ClockFake) -> None: