-
Notifications
You must be signed in to change notification settings - Fork 499
Fix logs MCP tool truncating explicit date-range queries to a single stale day with no warning #54110
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Fix logs MCP tool truncating explicit date-range queries to a single stale day with no warning #54110
Changes from all commits
af642ec
302b3ee
e1e209d
ff272af
a7250d2
e0fd2b2
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,43 @@ | ||
| # ADR-54110: Surface Continuation Cursor When MaxIterations Is Hit During Explicit Date-Range Scans | ||
|
|
||
| **Date**: 2026-08-20 | ||
| **Status**: Draft | ||
| **Deciders**: Unknown | ||
|
|
||
| --- | ||
|
|
||
| ### Context | ||
|
|
||
| The `collectProcessedWorkflowRuns` pagination loop in `pkg/cli/logs_orchestrator_download.go` caps at `MaxIterations` (20). When an explicit `start_date`/`end_date` window is requested (`fetchAllInRange = true`) and many non-matching runs fill each batch, the loop can exhaust all iterations without reaching the requested `count` or triggering the timeout. Previously, the loop exited normally in this case with both `timeoutReached` and `countLimitReached` set to `false`, so no `continuation` cursor was emitted. Callers requesting wide windows (e.g., 90 days) silently received a narrow, potentially stale slice of data, which downstream trend-analysis consumers treated as a complete representative scan of the full range (see github/gh-aw#53995). | ||
|
|
||
| ### Decision | ||
|
|
||
| We decided to set `countLimitReached = true` whenever `collectProcessedWorkflowRuns` exits due to the `MaxIterations` cap during an explicit date-range scan (`fetchAllInRange && !timeoutReached && iteration >= MaxIterations`). This reuses the existing `countLimitReached` path to guarantee a `continuation` cursor and `"partial": true` are always emitted for incomplete date-range scans. We additionally added `dateRangeCoverageWarning` — a function that, when the result is partial and the returned runs span less than 20% of the requested window, emits an explicit warning via the existing `stale_warning` mechanism so callers know the result is a narrow slice rather than a representative multi-day sample. | ||
|
|
||
| ### Alternatives Considered | ||
|
|
||
| #### Alternative 1: Increase or Remove MaxIterations | ||
|
|
||
| Raising or removing the `MaxIterations` cap would allow the loop to scan deeper into a wide date range before stopping. This was rejected because the cap exists to bound API cost and wall-clock time per call; removing it could cause runaway pagination that exhausts rate limits or blocks other callers. Raising it only defers the problem without fixing the signaling gap. | ||
|
|
||
| #### Alternative 2: Add a Top-Level Post-Scan Incomplete-Range Check | ||
|
|
||
| An alternative was to detect incompleteness after the loop by comparing the oldest fetched run's date against the requested `start_date`, and emit a warning only at the render layer. This would avoid changing loop semantics. It was rejected because the root cause is a missing signal (`countLimitReached`), not just a missing warning — consumers that rely on the continuation cursor to decide whether to page would still receive no cursor and would have no way to resume the scan, even if the render layer warned them. | ||
|
|
||
| ### Consequences | ||
|
|
||
| #### Positive | ||
| - Callers always receive a `continuation` cursor when pagination stops due to the iteration cap on explicit date-range scans, enabling them to resume the scan rather than silently consuming incomplete data. | ||
| - The `dateRangeCoverageWarning` gives users an actionable message when results are a narrow slice of the requested window, preventing silent multi-day trend analysis on unrepresentative data. | ||
|
|
||
| #### Negative | ||
| - The 20% coverage threshold (`dateRangeCoverageMinFraction = 0.2`) is a heuristic; edge cases exist where legitimate results cluster in a short sub-window without this being a data quality problem, causing false-positive warnings. | ||
| - Changing `countLimitReached` semantics to include iteration-cap exits means the continuation signal now appears in cases where it was previously absent — consumers must handle this cursor correctly or may perform unnecessary extra fetches. | ||
|
|
||
| #### Neutral | ||
| - Regression tests were added for both the iteration-cap continuation behavior and the coverage-warning threshold logic, establishing a baseline for future changes to the pagination semantics. | ||
| - The fix applies only when `fetchAllInRange` is `true` (i.e., an explicit date range was requested); the no-date-range code path is unaffected. | ||
|
|
||
| --- | ||
|
|
||
| *ADR created by [adr-writer agent]. Review and finalize before changing status from Draft to Accepted.* |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -103,6 +103,67 @@ func staleLogsWarning(processedRuns []ProcessedRun, startDate, endDate string) s | |
| humanizeDuration(age), newest.Format(time.RFC3339)) | ||
| } | ||
|
|
||
| // dateRangeCoverageMinFraction is the minimum fraction of the requested | ||
| // start_date/end_date window that returned runs must span before a partial | ||
| // (count-limit-truncated) result is considered a reasonable sample of the | ||
| // requested range. Below this fraction, callers are warned that the result is | ||
| // a narrow slice of the range, not a representative multi-day sample. | ||
| const dateRangeCoverageMinFraction = 0.2 | ||
|
|
||
| // dateRangeCoverageWarning returns a warning when an explicit start_date/end_date | ||
| // range was requested, the result was truncated before the range was fully | ||
| // scanned (partial=true, i.e. a continuation cursor was produced), and the runs | ||
| // actually returned span only a small fraction of the requested window. Without | ||
| // this warning, a caller can mistake a single busy (and possibly old) day for a | ||
| // representative sample of a much wider requested range, silently invalidating | ||
| // multi-day trend analysis built on top of it (see github/gh-aw#53995). | ||
| // Returns "" when no warning is warranted. | ||
| func dateRangeCoverageWarning(processedRuns []ProcessedRun, startDate, endDate string, partial bool) string { | ||
| if !partial || startDate == "" || len(processedRuns) == 0 { | ||
| return "" | ||
| } | ||
| start, err := parseFilterDate(startDate) | ||
| if err != nil { | ||
| return "" | ||
| } | ||
| end := time.Now() | ||
| if endDate != "" { | ||
| if parsedEnd, err := parseFilterDate(endDate); err == nil { | ||
| end = parsedEnd | ||
| } | ||
| } | ||
| requestedSpan := end.Sub(start) | ||
| if requestedSpan <= 0 { | ||
| return "" | ||
| } | ||
| // A single returned run trivially has a zero-length covered span | ||
| // (newest.Sub(oldest) == 0), which would always look like a narrow slice | ||
| // even when that one run legitimately falls within the requested window. | ||
| // Require at least two runs before computing a meaningful coverage ratio. | ||
| if len(processedRuns) < 2 { | ||
| return "" | ||
| } | ||
| var oldest, newest time.Time | ||
| for _, pr := range processedRuns { | ||
| created := pr.Run.CreatedAt | ||
| if oldest.IsZero() || created.Before(oldest) { | ||
| oldest = created | ||
| } | ||
| if created.After(newest) { | ||
| newest = created | ||
| } | ||
| } | ||
| coveredSpan := newest.Sub(oldest) | ||
| if coveredSpan.Seconds()/requestedSpan.Seconds() >= dateRangeCoverageMinFraction { | ||
| return "" | ||
| } | ||
| return fmt.Sprintf( | ||
| "An explicit date range was requested (%s), but the count limit was reached after collecting runs spanning only %s "+ | ||
| "(from %s to %s). This is a narrow slice of the requested range and may not represent overall trends. "+ | ||
| "Use the continuation cursor to fetch the remaining time range, or increase 'count' to cover the full window.", | ||
| humanizeDuration(requestedSpan), humanizeDuration(coveredSpan), oldest.Format(time.RFC3339), newest.Format(time.RFC3339)) | ||
|
Comment on lines
+160
to
+164
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Fixed: |
||
| } | ||
|
|
||
| // noRunsMessage returns a human-readable explanation for why zero workflow runs | ||
| // were returned. It inspects the startDate filter and the timeoutReached flag | ||
| // so callers receive actionable guidance instead of a silent empty result. | ||
|
|
@@ -183,7 +244,19 @@ func buildContinuationIfNeeded( | |
| } | ||
| // Use the oldest processed run as the before_run_id cursor for the next page. | ||
| oldestRunID := processedRuns[len(processedRuns)-1].Run.DatabaseID | ||
| logsOrchestratorLog.Printf("Building continuation cursor: before_run_id=%d, timeoutReached=%v, countLimitReached=%v", oldestRunID, timeoutReached, countLimitReached) | ||
| // Prefer the actual pagination date cursor over the fixed request end_date: when | ||
| // many non-matching runs are interspersed across the window (the scenario this | ||
| // guards against), the oldest *matching* run can be far newer than the point the | ||
| // scan actually reached. Using before_run_id alone in that case makes a resumed | ||
| // request re-fetch pages already scanned (from end_date/now down to oldestRunID), | ||
| // wasting iterations and potentially exhausting them again with zero new matches | ||
| // and no further continuation (see github/gh-aw#54110). Persisting the real | ||
| // fetch cursor as end_date bounds the resumed query server-side instead. | ||
| endDate := opts.endDate | ||
| if opts.lastFetchedBeforeDate != "" { | ||
| endDate = opts.lastFetchedBeforeDate | ||
| } | ||
| logsOrchestratorLog.Printf("Building continuation cursor: before_run_id=%d, end_date=%s, timeoutReached=%v, countLimitReached=%v", oldestRunID, endDate, timeoutReached, countLimitReached) | ||
| message := "Timeout reached. Use these parameters to continue fetching more logs." | ||
| if countLimitReached { | ||
| // In fetchAllInRange mode the date window may contain more runs than count. | ||
|
|
@@ -194,7 +267,7 @@ func buildContinuationIfNeeded( | |
| WorkflowName: opts.workflowName, | ||
| Count: opts.count, | ||
| StartDate: opts.startDate, | ||
| EndDate: opts.endDate, | ||
| EndDate: endDate, | ||
| Engine: opts.engine, | ||
| Branch: opts.branch, | ||
| AfterRunID: opts.afterRunID, | ||
|
|
@@ -212,7 +285,7 @@ func DownloadWorkflowLogs(ctx context.Context, opts LogsDownloadOptions) error { | |
| } | ||
| defer cancelLogsDownload(runtime.timeoutCancel) | ||
|
|
||
| processedRuns, timeoutReached, countLimitReached, err := collectProcessedWorkflowRuns(runtime, opts) | ||
| processedRuns, timeoutReached, countLimitReached, lastFetchedBeforeDate, err := collectProcessedWorkflowRuns(runtime, opts) | ||
| if err != nil { | ||
| return err | ||
| } | ||
|
|
@@ -224,29 +297,31 @@ func DownloadWorkflowLogs(ctx context.Context, opts LogsDownloadOptions) error { | |
| processedRuns = limitProcessedRuns(processedRuns, opts.Count, opts.Verbose) | ||
| logsOrchestratorLog.Printf("Collected %d processed runs (timeoutReached=%v, countLimitReached=%v)", len(processedRuns), timeoutReached, countLimitReached) | ||
| continuation := buildContinuationIfNeeded(processedRuns, timeoutReached, countLimitReached, continuationOptions{ | ||
| workflowName: opts.WorkflowName, | ||
| startDate: opts.StartDate, | ||
| endDate: opts.EndDate, | ||
| engine: opts.Engine, | ||
| branch: opts.Ref, | ||
| afterRunID: opts.AfterRunID, | ||
| count: opts.Count, | ||
| timeoutMinutes: opts.TimeoutMinutes, | ||
| workflowName: opts.WorkflowName, | ||
| startDate: opts.StartDate, | ||
| endDate: opts.EndDate, | ||
| engine: opts.Engine, | ||
| branch: opts.Ref, | ||
| afterRunID: opts.AfterRunID, | ||
| count: opts.Count, | ||
| timeoutMinutes: opts.TimeoutMinutes, | ||
| lastFetchedBeforeDate: lastFetchedBeforeDate, | ||
| }) | ||
|
|
||
| return renderLogsOutput(processedRuns, renderLogsOutputOptions{ | ||
| outputDir: opts.OutputDir, | ||
| summaryFile: opts.SummaryFile, | ||
| format: opts.Format, | ||
| reportFile: opts.ReportFile, | ||
| jsonOutput: opts.JSONOutput, | ||
| toolGraph: opts.ToolGraph, | ||
| train: opts.Train, | ||
| continuation: continuation, | ||
| verbose: opts.Verbose, | ||
| artifactFilter: runtime.artifactFilter, | ||
| startDate: opts.StartDate, | ||
| endDate: opts.EndDate, | ||
| checkStaleness: true, | ||
| outputDir: opts.OutputDir, | ||
| summaryFile: opts.SummaryFile, | ||
| format: opts.Format, | ||
| reportFile: opts.ReportFile, | ||
| jsonOutput: opts.JSONOutput, | ||
| toolGraph: opts.ToolGraph, | ||
| train: opts.Train, | ||
| continuation: continuation, | ||
| verbose: opts.Verbose, | ||
| artifactFilter: runtime.artifactFilter, | ||
| startDate: opts.StartDate, | ||
| endDate: opts.EndDate, | ||
| checkStaleness: true, | ||
| countLimitReached: countLimitReached, | ||
| }) | ||
| } | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -182,15 +182,15 @@ var ( | |
| logsProcessWorkflowRunBatch = processWorkflowRunBatch | ||
| ) | ||
|
|
||
| func collectProcessedWorkflowRuns(runtime logsDownloadRuntime, opts LogsDownloadOptions) ([]ProcessedRun, bool, bool, error) { | ||
| func collectProcessedWorkflowRuns(runtime logsDownloadRuntime, opts LogsDownloadOptions) ([]ProcessedRun, bool, bool, string, error) { | ||
| var processedRuns []ProcessedRun | ||
| var beforeDate string | ||
| var iteration int | ||
| var timeoutReached, countLimitReached bool | ||
| for iteration < MaxIterations { | ||
| stop, timedOut, err := shouldStopLogsIteration(runtime, opts) | ||
| if err != nil { | ||
| return processedRuns, timeoutReached || timedOut, countLimitReached, err | ||
| return processedRuns, timeoutReached || timedOut, countLimitReached, beforeDate, err | ||
| } | ||
| if stop { | ||
| timeoutReached = timeoutReached || timedOut | ||
|
|
@@ -219,9 +219,9 @@ func collectProcessedWorkflowRuns(runtime logsDownloadRuntime, opts LogsDownload | |
| // timeoutReached=false because this is an external cancellation, not the | ||
| // internal --timeout deadline firing. | ||
| if errors.Is(err, context.Canceled) { | ||
| return nil, false, false, err | ||
| return nil, false, false, "", err | ||
| } | ||
| return nil, false, false, err | ||
| return nil, false, false, "", err | ||
| } | ||
| if len(batch.runs) == 0 { | ||
| cursor, shouldContinue, shouldStop := handleEmptyWorkflowRunBatch(batch, opts.Verbose) | ||
|
|
@@ -261,7 +261,23 @@ func collectProcessedWorkflowRuns(runtime logsDownloadRuntime, opts LogsDownload | |
| } | ||
| logLogsIterationLimit(runtime.fetchAllInRange, iteration, len(processedRuns), opts.Count) | ||
| logLogsTimeoutResult(timeoutReached, len(processedRuns)) | ||
| return processedRuns, timeoutReached, countLimitReached, nil | ||
| // Hitting MaxIterations without reaching the requested count or the timeout | ||
| // means pagination stopped before the explicit date range was fully scanned | ||
| // (e.g. a burst of non-matching runs consumed every iteration's batch before | ||
| // the cursor could walk across the whole window). Previously this silently | ||
| // returned whatever partial data had accumulated with no continuation cursor, | ||
| // so callers requesting a wide start_date/end_date window could mistake a | ||
| // narrow, stale slice of results for a complete scan of the range (see | ||
| // github/gh-aw#53995). Treat it the same as a count-limit break so a | ||
| // continuation is always surfaced for explicit date-range queries. | ||
| if runtime.fetchAllInRange && !timeoutReached && iteration >= MaxIterations { | ||
| countLimitReached = true | ||
|
Comment on lines
+273
to
+274
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Fixed: |
||
| } | ||
| // beforeDate reflects the pagination cursor collectProcessedWorkflowRuns actually | ||
| // advanced to (including iterations that fetched runs but matched none of them), | ||
| // so callers building a continuation can resume the scan from here instead of | ||
| // re-fetching pages already visited (see github/gh-aw#54110). | ||
| return processedRuns, timeoutReached, countLimitReached, beforeDate, nil | ||
| } | ||
|
|
||
| func shouldStopLogsIteration(runtime logsDownloadRuntime, opts LogsDownloadOptions) (bool, bool, error) { | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
[/diagnosing-bugs]
coveredSpanis zero when exactly one run is returned —newest.Sub(oldest)== 0 — so the warning always fires for any partial result with a single run, even when that run falls well within the requested window. This is a false positive.💡 Suggested fix
Guard against the single-run case before computing coverage:
Alternatively, measure
newest.Sub(start)(how far back into the requested window runs actually reach) instead ofnewest.Sub(oldest), which avoids the zero-span degenerate case and better models "how much of the window was scanned".@copilot please address this.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Fixed — added a guard returning "" when fewer than 2 runs are returned, so a single in-window run no longer produces a zero-span false positive.