feat(seer): Structured logging for the automated PR-iteration flow - #122088
Open
joseph-sentry wants to merge 10 commits into
Open
feat(seer): Structured logging for the automated PR-iteration flow#122088joseph-sentry wants to merge 10 commits into
joseph-sentry wants to merge 10 commits into
Conversation
The automated PR-iteration flow spans four entry points that can run minutes or hours apart: a GitHub check_suite webhook arrives, a task later drains the feedback queue and calls Seer, Seer calls back when the iteration completes, and the push that follows calls back again. Debugging one occurrence means pulling all four back together. PrIterationLogContext gives them a shared identity block anchored on the Autofix run id. Call sites hand it whole objects they already hold -- an Organization, a Group, the run state, the resolved run -- and it derives the fields worth logging from them. Identity accumulates across updates, so the check-suite listener can start with nothing and gain the rest once Seer says which run owns the PR. Building identity issues no queries and does not touch the Sentry scope, so adding it to a code path cannot change that path's behaviour. No call sites are wired up yet.
Every check suite of every GitHub App installation reaches `pr_iteration_from_check_suite_listener`, and both branches below it go on to query repositories and call Seer once per pull request. Most of those suites belong to organizations that run no part of PR iteration at all. Resolve the installation's organizations first and drop the event unless one of them has `autofix-pr-iteration`, `-manual`, or `-review-request` enabled. `cap-assign` is deliberately not in that set: it only changes what happens once an iteration has already run, so it can never be the sole reason to keep an event. The gate stops at organizations. It reads the installation id off `subscription_event["extra"]`, which the GitHub webhook populates for every stream event, so it neither parses the event body nor queries `Repository` -- a malformed body still gets a verdict. Both branches go on to resolve from scratch: the repeated integration lookup costs less than threading a half-resolved state through them. It runs after the action and conclusion checks, which are free, and before either branch. Metrics on `autofix.pr_iteration.check_suite.flag_gate`: a timer tagged with the outcome, plus distributions of how many organizations sit behind an installation and how many of them survive. Both distributions are emitted on every path, so an installation that resolves to nothing counts as a zero rather than going missing and biasing the average upward.
`should_queue`, `should_consume` and `should_trigger` decided whether a piece of feedback moves forward and returned only the verdict, so every caller that wanted to say *why* had to re-derive it or the method had to log it inline. Two of them did log inline, which is why the reason for a `ConsumeTask.Now` or the countdown on a `Later` was never recorded anywhere: those returns had no log next to them. Return a `Decision(ok, reason)` -- `TriggerDecision(task, reason)` for `should_trigger` -- so the verdict arrives with the input that settled it. Reasons name what was read rather than what was concluded (`stale_head`, `already_processed`, `sweep_incomplete`), on the allow path as much as the deny path, and come from a small fixed vocabulary per method so they are safe as a metric tag. A source that overrides nothing reports `no_gate`, which is worth telling apart from a gate that ran and passed. Pure refactor: the three call sites unwrap `.ok` / `.task` and behave exactly as before, and the existing logs are left firing untouched -- they are replaced in a follow-up, not dropped ahead of it. Tests now pin the reason rather than the bare boolean.
…back Feedback arriving for a run was gated twice with nothing recorded but a pair of pre-decision ``evaluated`` lines on one source: whether it went into the Redis queue, and whether a consume task was scheduled for it. Neither outcome was searchable, so a run that quietly stopped iterating left no line saying which gate stopped it. Both shared callers now emit one line per decision -- ``autofix.pr_iteration.feedback.queue`` and ``...feedback.trigger`` -- with ``outcome`` for which way it went and ``reason`` for what settled it. One name per decision rather than one per branch, so a search finds every occurrence and the allow path is as visible as the deny path. The listener builds the log context once and threads it through both calls, so a single check suite's two lines share an identity and are found by the same search. Sources project the inputs their gates read via a new ``log_fields``, which takes the run state so a comparison lands with both operands: a ``stale_head`` verdict can be re-derived from the line rather than taken on trust. The raw webhook body stays out -- ``Config.extra = "allow"` retains the whole delivery, which is tens of kilobytes and no more identifying than the ids already there. ``check_suite.should_queue.evaluated`` is retired: every field it carried is covered, with ``matched``/``hard_cap_reached`` collapsing losslessly into ``reason`` (the cap was only ever evaluated when the head matched). The two ``should_trigger`` info lines go the same way. ``scm_init_failed`` stays a warning with its traceback, and ``should_consume.evaluated`` stays until the consume path gets the same treatment.
The check-suite listener could fail two ways without leaving anything that names the iteration it broke. A payload that would not parse returned silently, and an unexpected exception escaped to `exec_listener`, which counts it against the SCM stream rather than against the run. Both log now. The parse branch carries what the SCM stream attached to the envelope, since nothing was read out of the body; the wrap around enqueue, cap-assign and trigger carries the full run identity. It reports once and drops the event rather than re-raising, so a single failure is not counted twice. `PrIterationLogContext.failed` becomes `error`, naming the level it logs at the way `info` does, and it now logs at error rather than warning: finding every broken iteration should be one search for errors under `autofix.pr_iteration`, not a list of names you have to know in advance. The `reason` argument and its metric go with the rename -- the log name already identifies the failure, so the tag was a second vocabulary to keep in sync with it.
The listener's flag gate asked one question for both of its branches: does any organization behind this installation run some part of PR iteration. That kept a green suite alive for an installation whose only flag is `autofix-pr-iteration`, and a failing one for an installation whose only flag is `-review-request` -- in each case to resolve a run the surviving branch had no side effect left for. The green branch pays a body parse and a `Repository` query before it finds that out; the failing branch pays a round trip to Seer. `resolve_check_suite_flag_gate` now takes the flags the calling branch can act on and reports which organizations hold each of them. The listener asks about `GREEN_CHECK_SUITE_FLAGS` for a green suite and `FAILING_CHECK_SUITE_FLAGS` for a failing one, and `flagged_organization_ids` becomes the deduped union of what came back, so the call site stays a single emptiness check. `-manual` sits in the failing set rather than the green one because `trigger_autofix_agent` admits the PR_ITERATION step under either iteration flag. `cap-assign` stays out of both sets for the reason it was out of the combined one: it only changes what happens once iteration has already run, so it can never be the sole reason to keep an event. It becomes a named constant that `assign_user_for_exhausted_cap` reads instead of a literal, since that check is per organization and belongs where the run's organization is known.
The consume task went quiet in the middle: a run that was still processing, an already-drained queue, and a batch where nothing survived the dedupe gates all returned without a line, so a piece of feedback that never reached Seer left nothing to search for. Every exit from the drain now emits one `consume_feedback.drain` line with the same `outcome`/`reason` pair the queue and trigger lines use, and items that did not make it ride along on it in `dropped` rather than getting a line each, so one drain stays one search result however much was queued. Feedback items are named by a new `Feedback.feedback_id` -- `<source type>:<provider id>` -- rather than by their payload, and the same id now appears on the queue and trigger lines, so one item can be followed from arrival to hand-off. The trigger mints a `trigger_id` and passes it down as a task kwarg, linking a drain back to the trigger that scheduled it; `apply_async` returns nothing, so passing our own id down is the only direction that link can travel. The two pre-run-state lookups keep the plain logger -- neither has anything to anchor to beyond the two ids the task was called with. Retires `consume_feedback.stale_feedback`, `consume_feedback.no_consumable_feedback`, and `consume_feedback.skipped`, which are now reasons on the drain line.
``autofix.pr_iteration.feedback.trigger`` reported ``outcome`` as a yes/no on whether a consume task was scheduled, which put a deferral in the same bucket as an immediate consume. A check suite whose runs are still incomplete schedules an hour out rather than dropping the task, so the line read ``outcome=triggered reason=sweep_incomplete`` -- a pairing that scans as a contradiction, with only ``countdown`` further along the line to say the consume had not happened yet. ``outcome`` now takes three values: ``triggered`` when the task runs now, ``delayed`` when it was scheduled with a countdown, and ``not_triggered`` when the run hit its cap and nothing was queued at all. ``reason`` is untouched and still names what settled the timing. The split keys on the countdown the task was given rather than on what the source asked for, matching the rule the line already followed for ``countdown`` itself: an explicit ``delay=0`` collapses a deferring source to an immediate consume and reads ``triggered``, as does ``ConsumeTask.Now``, which reports no countdown at all. The vocabulary stays small and fixed, so it remains safe as a metric tag.
An iteration passes through the completion hook at least twice -- once when the agent finishes and a push is owed, once more when that push has landed -- and every branch was a silent return, so nothing recorded that the hook ran for a run at all, let alone which pass it was. Three lines now cover it, all gated on the step because `execute` serves every autofix run and not just this flow: - `completion_hook.received` carries the (has_changes, is_synced) pair that names the pass, plus the repos with diffs. - `iteration_outcome` says where the iteration's changes stand in its own terms -- `changes_pushed`, `awaiting_push`, or `push_failed` -- with the per-repo shas and creation status it read to decide. Whether ITERATION_COMPLETED goes out follows from that rather than being the subject, so it rides along as `webhook_emitted`. - `push` says what this pass did, separating a push that landed on the previous pass (`already_synced`) from an agent that changed nothing (`no_changes`); both were one line reading two booleans before. PR iteration branches off `_push_changes` into `_push_iteration_changes`. The two share the call to Seer and nothing else: the pipeline pushes once, into repos with no PR yet, while an iteration pushes every pass against PRs that exist, and a repo whose PR creation errored is terminal for it. That check moves with it, off a path where there are no PRs to have failed, and `_push_changes` drops the `author` only the iteration caller passed. The hand-back to the queue and the manual UI request were both scheduling a drain by calling `apply_async` directly, so neither reported itself and both handed the drain a null `trigger_id`. The UI path now routes through `trigger_consume_pr_iteration_feedback` -- its source has no gate, so it still consumes immediately -- and the hand-back writes the same `feedback.trigger` line under `reason=iteration_finished`. A new `triggered_by` field says which producer scheduled a drain, so counting arrivals against hand-backs is a filter rather than a list of reasons someone has to know in advance. The `assert state.repo_pr_states` in the iteration webhook branch becomes a logged error. It took the whole hook down from inside an RPC, and with it the push, so an iteration that lost its PR states also stopped making progress. Finally, the drain's `run_processing` skip reports `left_queued_count`. It is the one exit that returns before popping, and nothing reschedules from there -- what it leaves behind is the difference between nothing waiting and work owed to whoever comes back for it.
github-actions
Bot
added
the
Scope: Backend
joseph-sentry
marked this pull request as ready for review
August 14, 2026 20:14
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
adding more structured logging for PR iteration, with the goal of making it easy to find errors and debug specific PR iteration runs
yday we had a case where an autofix run looked wrong in the UI and it took a bit of time to debug what had happened
so im adding logging so we can for a given autofix run trace through the steps of PR iteration
i'm also fixing some papercut bugs along the way
and i'm fixing up our error handling so that we capture exceptions and forward them to sentry in the right places
I accomplished the work by breaking up CI PR iteration into 3 stages:
when looking at an autofix run we should basically be seeing some enqueues, then a consume, then some completion hook events (code changes done, push done) and we should have sufficient information to understand what happened if there's a logical error