Skip to content

Commit 0b22462

Browse files
authored
Fix logs tool: context deadline exceeded without workflow_name filter (#46554)
1 parent bd8bf24 commit 0b22462

8 files changed

Lines changed: 166 additions & 41 deletions
Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,48 @@
1+
# ADR-46554: Dynamic Timeout Computation for the MCP Logs Tool
2+
3+
**Date**: 2026-07-19
4+
**Status**: Draft
5+
**Deciders**: pelikhan, copilot-swe-agent
6+
7+
---
8+
9+
### Context
10+
11+
The `agenticworkflows logs` MCP tool timed out (hitting the MCP gateway's 60-second hard limit) whenever it was called without a `--workflow_name` filter. Three compounding issues caused this: (1) `BatchSizeForAllWorkflows` was set to 250, which paginated as three sequential GitHub API calls per batch (the GitHub API caps per-page results at 100), producing 45–60+ seconds of latency on large repositories; (2) `fetchWorkflowRunBatch` called the GitHub API with `Context: nil`, meaning the subprocess had no deadline and could not be cancelled by the caller's context; (3) a static `timeout` schema default was registered in the MCP tool schema, causing the go-sdk to pre-fill `args.Timeout` before the handler ran, bypassing the per-request runtime computation that would have applied a higher floor for all-workflow queries.
12+
13+
### Decision
14+
15+
We will compute the MCP logs tool timeout dynamically at request time based on two parameters: the effective `count` and whether `workflowName` is empty. When no workflow filter is provided, a minimum floor of 5 minutes (`defaultMCPLogsMinTimeoutMinutesAllWorkflows`) is enforced, because unfiltered GitHub API queries scan all workflow runs and are significantly slower on large repositories. The static MCP schema default for `timeout` is removed so the go-sdk cannot pre-fill the value and short-circuit the runtime computation. Additionally, `BatchSizeForAllWorkflows` is reduced from 250 to 100 (the GitHub API's `per_page` maximum) so each batch requires only a single API round-trip, and the request context is threaded into `fetchWorkflowRunBatch` to allow graceful cancellation distinguishing internal deadline expiry from external context cancellation.
16+
17+
### Alternatives Considered
18+
19+
#### Alternative 1: Increase or Remove the MCP Gateway Timeout Limit
20+
21+
Configure the MCP gateway to allow a longer (or unlimited) per-tool timeout so that the existing logic with `BatchSizeForAllWorkflows = 250` and no context propagation could still succeed on large repositories. This was not chosen because the 60-second limit is an external constraint of the MCP gateway infrastructure that the tool cannot unilaterally change. Relying on a large external timeout also hides performance problems rather than fixing them; a slow tool would remain slow for users even if it eventually completed.
22+
23+
#### Alternative 2: Parallelise GitHub API Calls Within a Batch
24+
25+
Instead of reducing `BatchSizeForAllWorkflows` from 250 to 100, keep the larger batch and issue the three required API pages concurrently. This would reduce the wall-clock time for a 250-run batch to approximately the latency of one API call. This was not chosen because it adds concurrency complexity and risk (rate-limiting, partial-failure handling) to code that was otherwise sequential by design. Aligning with the API's per-page maximum of 100 is simpler, predictable, and sufficient to keep individual batch fetches within acceptable latency bounds.
26+
27+
#### Alternative 3: Cache Workflow Run Listings Between Requests
28+
29+
Introduce a short-lived cache of recent `gh run list` results so that consecutive calls (e.g. from retried or paginated MCP requests) avoid redundant API round-trips. This would reduce latency for repeated queries at the cost of potentially serving stale data. This was not chosen because it introduces state management complexity and cache invalidation risk in a tool that needs to return current data; the simpler approach of aligning batch size with API limits is sufficient for the latency problem at hand.
30+
31+
### Consequences
32+
33+
#### Positive
34+
- The MCP logs tool no longer times out on large repositories when `--workflow_name` is omitted, making the common fleet-wide log inspection use-case reliable.
35+
- The distinction between internal deadline expiry (`context.DeadlineExceeded`) and external cancellation (`context.Canceled`) is now surfaced to callers, enabling better error handling and partial-result recovery.
36+
- Removing the static schema default makes the timeout computation self-consistent: the value callers see in the MCP schema (no default) matches the actual runtime behaviour (computed per-request).
37+
38+
#### Negative
39+
- Reducing `BatchSizeForAllWorkflows` from 250 to 100 means that retrieving a large number of runs requires more loop iterations, which slightly increases total latency when the repository has many workflow runs and the result count is large.
40+
- Removing the static schema default for `timeout` means MCP clients that relied on schema introspection to determine a default timeout value will no longer find one; they must accept that the timeout is opaque and server-determined.
41+
42+
#### Neutral
43+
- The `effectiveMCPLogsToolTimeoutMinutes` function signature now accepts a `workflowName string` parameter; all call sites must be updated accordingly (done in this PR).
44+
- Tests for timeout computation are extended with a `workflowName` dimension, increasing test coverage but also test verbosity.
45+
46+
---
47+
48+
*ADR created by [adr-writer agent]. Review and finalize before changing status from Draft to Accepted.*

pkg/cli/logs_github_api.go

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -255,6 +255,16 @@ func listWorkflowRunsWithPagination(opts ListWorkflowRunsOptions) ([]WorkflowRun
255255
logsGitHubAPILog.Printf("gh run list command failed (not ExitError): %v. Command: gh %v", err, args)
256256
}
257257

258+
// When exec.CommandContext cancels the subprocess it returns an *exec.ExitError
259+
// ("signal: killed") rather than the context error, so errors.Is checks in
260+
// callers would not recognise it. Surface the context error directly so that
261+
// errors.Is(err, context.DeadlineExceeded) / errors.Is(err, context.Canceled)
262+
// work as expected.
263+
if ctxErr := cmdCtx.Err(); ctxErr != nil {
264+
logsGitHubAPILog.Printf("gh run list interrupted by context: %v", ctxErr)
265+
return nil, 0, ctxErr
266+
}
267+
258268
// Check for different error types with heuristics
259269
errMsg := err.Error()
260270
outputMsg := string(output)

pkg/cli/logs_models.go

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -26,10 +26,11 @@ const (
2626
MaxIterations = 20
2727
// BatchSize is the number of runs to fetch in each iteration
2828
BatchSize = 100
29-
// BatchSizeForAllWorkflows is the larger batch size when searching for agentic workflows
30-
// There can be a really large number of workflow runs in a repository, so
31-
// we are generous in the batch size when used without qualification.
32-
BatchSizeForAllWorkflows = 250
29+
// BatchSizeForAllWorkflows is the batch size when searching across all agentic workflows.
30+
// We cap this at 100 (the GitHub API max per_page) so each batch requires only a single
31+
// API call. Using 250 previously caused three API round-trips per batch, making the
32+
// unfiltered list slow enough to exceed the MCP gateway's default 60-second tool timeout.
33+
BatchSizeForAllWorkflows = 100
3334
// MaxConcurrentDownloads limits the number of parallel artifact downloads
3435
MaxConcurrentDownloads = 10
3536
// APICallCooldown is the minimum pause between successive batch-fetch iterations to

pkg/cli/logs_orchestrator_download.go

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -189,8 +189,22 @@ func collectProcessedWorkflowRuns(runtime logsDownloadRuntime, opts LogsDownload
189189
}
190190
iteration++
191191
logLogsIterationFetch(opts, runtime.fetchAllInRange, iteration, len(processedRuns))
192-
batch, err := fetchWorkflowRunBatch(opts, beforeDate, len(processedRuns), runtime.fetchAllInRange)
192+
batch, err := fetchWorkflowRunBatch(runtime.activeCtx, opts, beforeDate, len(processedRuns), runtime.fetchAllInRange)
193193
if err != nil {
194+
// Context deadline exceeded means our own timeout fired mid-call.
195+
// Treat it like a graceful timeout: return whatever was collected so far.
196+
if errors.Is(err, context.DeadlineExceeded) {
197+
timeoutReached = true
198+
break
199+
}
200+
// Context cancelled (e.g. user signal or outer gateway timeout): propagate
201+
// the error without partial results. The caller discards partial runs on
202+
// error, so returning them here would be misleading. We leave
203+
// timeoutReached=false because this is an external cancellation, not the
204+
// internal --timeout deadline firing.
205+
if errors.Is(err, context.Canceled) {
206+
return nil, false, false, err
207+
}
194208
return nil, false, false, err
195209
}
196210
if len(batch.runs) == 0 {
@@ -277,10 +291,11 @@ func logLogsIterationFetch(opts LogsDownloadOptions, fetchAllInRange bool, itera
277291
fmt.Fprintln(os.Stderr, console.FormatInfoMessage(fmt.Sprintf("Iteration %d: Need %d more runs with artifacts, fetching more...", iteration, opts.Count-processedCount)))
278292
}
279293

280-
func fetchWorkflowRunBatch(opts LogsDownloadOptions, beforeDate string, processedCount int, fetchAllInRange bool) (workflowRunBatch, error) {
294+
func fetchWorkflowRunBatch(ctx context.Context, opts LogsDownloadOptions, beforeDate string, processedCount int, fetchAllInRange bool) (workflowRunBatch, error) {
281295
batchSize := computeLogsBatchSize(opts.WorkflowName, opts.Count, processedCount, fetchAllInRange)
282296
var oldestFetchedCreatedAt time.Time
283297
runs, totalFetched, err := listWorkflowRunsWithPagination(ListWorkflowRunsOptions{
298+
Context: ctx,
284299
WorkflowName: opts.WorkflowName,
285300
Limit: batchSize,
286301
StartDate: opts.StartDate,

pkg/cli/logs_timeout_test.go

Lines changed: 45 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -117,56 +117,93 @@ func TestEffectiveMCPLogsToolTimeoutMinutes(t *testing.T) {
117117
name string
118118
requestedTimeout int
119119
count int
120+
workflowName string
120121
want int
121122
}{
122123
{
123124
name: "explicit timeout is preserved",
124125
requestedTimeout: 5,
125126
count: 100,
127+
workflowName: "my-workflow",
126128
want: 5,
127129
},
128130
{
129-
name: "small fetch window keeps one minute default",
131+
name: "explicit timeout is preserved even without workflow name",
132+
requestedTimeout: 5,
133+
count: 100,
134+
workflowName: "",
135+
want: 5,
136+
},
137+
{
138+
name: "small fetch window keeps one minute default (named workflow)",
130139
requestedTimeout: 0,
131140
count: 40,
141+
workflowName: "my-workflow",
132142
want: 1,
133143
},
134144
{
135-
name: "fetch window above forty runs gets two minutes",
145+
name: "fetch window above forty runs gets two minutes (named workflow)",
136146
requestedTimeout: 0,
137147
count: 41,
148+
workflowName: "my-workflow",
138149
want: 2,
139150
},
140151
{
141-
name: "eighty run fetch window stays in two minute tier",
152+
name: "eighty run fetch window stays in two minute tier (named workflow)",
142153
requestedTimeout: 0,
143154
count: 80,
155+
workflowName: "my-workflow",
144156
want: 2,
145157
},
146158
{
147-
name: "eighty one run fetch window enters three minute tier",
159+
name: "eighty one run fetch window enters three minute tier (named workflow)",
148160
requestedTimeout: 0,
149161
count: 81,
162+
workflowName: "my-workflow",
150163
want: 3,
151164
},
152165
{
153-
name: "default hundred run window gets three minutes",
166+
name: "default hundred run window gets three minutes (named workflow)",
154167
requestedTimeout: 0,
155168
count: 100,
169+
workflowName: "my-workflow",
156170
want: 3,
157171
},
158172
{
159-
name: "unspecified count falls back to default window size",
173+
name: "unspecified count falls back to default window size (named workflow)",
160174
requestedTimeout: 0,
161175
count: 0,
176+
workflowName: "my-workflow",
162177
want: 3,
163178
},
179+
// All-workflow cases: minimum 5 minutes when no workflow_name is given
180+
{
181+
name: "small count uses all-workflow minimum (no workflow name)",
182+
requestedTimeout: 0,
183+
count: 3,
184+
workflowName: "",
185+
want: defaultMCPLogsMinTimeoutMinutesAllWorkflows,
186+
},
187+
{
188+
name: "default count uses all-workflow minimum (no workflow name)",
189+
requestedTimeout: 0,
190+
count: 100,
191+
workflowName: "",
192+
want: defaultMCPLogsMinTimeoutMinutesAllWorkflows,
193+
},
194+
{
195+
name: "very large count exceeds all-workflow minimum (no workflow name)",
196+
requestedTimeout: 0,
197+
count: 250,
198+
workflowName: "",
199+
want: (250 + mcpLogsRunsPerDefaultTimeoutMinute - 1) / mcpLogsRunsPerDefaultTimeoutMinute, // ceil(250/mcpLogsRunsPerDefaultTimeoutMinute) > defaultMCPLogsMinTimeoutMinutesAllWorkflows
200+
},
164201
}
165202

166203
for _, tt := range tests {
167204
t.Run(tt.name, func(t *testing.T) {
168-
if got := effectiveMCPLogsToolTimeoutMinutes(tt.requestedTimeout, tt.count); got != tt.want {
169-
t.Errorf("effectiveMCPLogsToolTimeoutMinutes(%d, %d) = %d, want %d", tt.requestedTimeout, tt.count, got, tt.want)
205+
if got := effectiveMCPLogsToolTimeoutMinutes(tt.requestedTimeout, tt.count, tt.workflowName); got != tt.want {
206+
t.Errorf("effectiveMCPLogsToolTimeoutMinutes(%d, %d, %q) = %d, want %d", tt.requestedTimeout, tt.count, tt.workflowName, got, tt.want)
170207
}
171208
})
172209
}

pkg/cli/mcp_server_defaults_test.go

Lines changed: 10 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -52,7 +52,7 @@ func TestMCPToolElicitationDefaults(t *testing.T) {
5252
}
5353
})
5454

55-
t.Run("logs tool has count, timeout, max_tokens and artifacts defaults", func(t *testing.T) {
55+
t.Run("logs tool has count, max_tokens and artifacts defaults (no timeout default)", func(t *testing.T) {
5656
type logsArgs struct {
5757
WorkflowName string `json:"workflow_name,omitempty" jsonschema:"Name of the workflow to download logs for (empty for all)"`
5858
Count int `json:"count,omitempty" jsonschema:"Number of workflow runs to download"`
@@ -66,13 +66,12 @@ func TestMCPToolElicitationDefaults(t *testing.T) {
6666
t.Fatalf("Failed to generate schema: %v", err)
6767
}
6868

69-
// Add defaults as done in registerLogsTool
69+
// Add defaults as done in registerLogsTool (no timeout default: it is
70+
// computed at runtime from count and workflow_name so the go-sdk cannot
71+
// fill it in statically without bypassing the per-request computation).
7072
if err := AddSchemaDefault(schema, "count", defaultMCPLogsToolCount); err != nil {
7173
t.Fatalf("Failed to add count default: %v", err)
7274
}
73-
if err := AddSchemaDefault(schema, "timeout", defaultMCPLogsToolTimeoutMinutesForCount(defaultMCPLogsToolCount)); err != nil {
74-
t.Fatalf("Failed to add timeout default: %v", err)
75-
}
7675
if err := AddSchemaDefault(schema, "max_tokens", 12000); err != nil {
7776
t.Fatalf("Failed to add max_tokens default: %v", err)
7877
}
@@ -96,21 +95,16 @@ func TestMCPToolElicitationDefaults(t *testing.T) {
9695
t.Errorf("Expected count default to be %d, got %v", defaultMCPLogsToolCount, countDefault)
9796
}
9897

99-
// Verify timeout default
98+
// Verify timeout has NO schema default: registerLogsTool intentionally
99+
// omits a static timeout default because the runtime computes it from
100+
// both the effective count and workflow_name. A static default would be
101+
// applied by the go-sdk before the handler runs, bypassing that logic.
100102
timeoutProp, ok := schema.Properties["timeout"]
101103
if !ok {
102104
t.Fatal("Expected 'timeout' property to exist")
103105
}
104-
if len(timeoutProp.Default) == 0 {
105-
t.Error("Expected 'timeout' property to have a default value")
106-
}
107-
var timeoutDefault int
108-
if err := json.Unmarshal(timeoutProp.Default, &timeoutDefault); err != nil {
109-
t.Fatalf("Failed to unmarshal timeout default: %v", err)
110-
}
111-
expectedTimeoutDefault := defaultMCPLogsToolTimeoutMinutesForCount(defaultMCPLogsToolCount)
112-
if timeoutDefault != expectedTimeoutDefault {
113-
t.Errorf("Expected timeout default to be %d, got %v", expectedTimeoutDefault, timeoutDefault)
106+
if len(timeoutProp.Default) != 0 {
107+
t.Errorf("Expected 'timeout' property to have no schema default (runtime-computed), got %s", timeoutProp.Default)
114108
}
115109

116110
// Verify max_tokens default (backward-compat field)

pkg/cli/mcp_tools_privileged.go

Lines changed: 21 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,12 @@ const (
1919
defaultMCPLogsToolCount = 100
2020
defaultMCPLogsTimeoutMinutes = 1
2121
mcpLogsRunsPerDefaultTimeoutMinute = 40
22+
// defaultMCPLogsMinTimeoutMinutesAllWorkflows is the minimum timeout (in minutes)
23+
// used when no workflow_name filter is provided. Querying all workflow runs at once
24+
// requires a single GitHub API call rather than a workflow-scoped call, but for
25+
// large repositories the unfiltered endpoint can be significantly slower. A higher
26+
// floor gives the tool enough headroom in those cases.
27+
defaultMCPLogsMinTimeoutMinutesAllWorkflows = 5
2228
)
2329

2430
// appendRepoFlagFromEnv appends "--repo <owner/repo>" to args when GITHUB_REPOSITORY
@@ -67,12 +73,19 @@ func effectiveMCPLogsToolCount(count int) int {
6773
return defaultMCPLogsToolCount
6874
}
6975

70-
func effectiveMCPLogsToolTimeoutMinutes(requestedTimeout, count int) int {
76+
func effectiveMCPLogsToolTimeoutMinutes(requestedTimeout, count int, workflowName string) int {
7177
if requestedTimeout > 0 {
7278
return requestedTimeout
7379
}
7480

75-
return defaultMCPLogsToolTimeoutMinutesForCount(count)
81+
base := defaultMCPLogsToolTimeoutMinutesForCount(count)
82+
if workflowName == "" {
83+
// Without a workflow filter the GitHub API must scan all workflow runs, which
84+
// is substantially slower for large repositories. Apply a higher minimum so
85+
// the tool is less likely to exhaust the MCP gateway's per-tool timeout.
86+
return max(defaultMCPLogsMinTimeoutMinutesAllWorkflows, base)
87+
}
88+
return base
7689
}
7790

7891
// The logs tool requires write+ access and checks actor permissions.
@@ -88,11 +101,11 @@ func registerLogsTool(server *mcp.Server, execCmd execCmdFunc, actor string, val
88101
if err := AddSchemaDefault(logsSchema, "count", defaultMCPLogsToolCount); err != nil {
89102
mcpLog.Printf("Failed to add default for count: %v", err)
90103
}
91-
// Schema default corresponds to defaultMCPLogsToolCount; runtime timeout
92-
// scales with the effective count used for the request.
93-
if err := AddSchemaDefault(logsSchema, "timeout", defaultMCPLogsToolTimeoutMinutesForCount(defaultMCPLogsToolCount)); err != nil {
94-
mcpLog.Printf("Failed to add default for timeout: %v", err)
95-
}
104+
// No schema default for timeout: the runtime auto-computes it from the effective
105+
// count and workflow_name so that no-workflow queries (which scan across all runs)
106+
// receive a higher floor than single-workflow queries. Setting a static default
107+
// here would cause the go-sdk to fill it in before the handler sees the arguments,
108+
// bypassing the per-request computation.
96109
if err := AddSchemaDefault(logsSchema, "max_tokens", 12000); err != nil {
97110
mcpLog.Printf("Failed to add default for max_tokens: %v", err)
98111
}
@@ -209,7 +222,7 @@ from where the previous request stopped due to timeout.`,
209222

210223
// Scale the implicit MCP timeout with the requested fetch window so
211224
// larger fleet-wide requests do not hit the default per-tool timeout.
212-
timeoutValue := effectiveMCPLogsToolTimeoutMinutes(args.Timeout, effectiveCount)
225+
timeoutValue := effectiveMCPLogsToolTimeoutMinutes(args.Timeout, effectiveCount, args.WorkflowName)
213226
cmdArgs = append(cmdArgs, "--timeout", strconv.Itoa(timeoutValue))
214227

215228
// Always use --json mode in MCP server

0 commit comments

Comments
 (0)