diff --git a/docs/adr/46554-dynamic-timeout-computation-for-mcp-logs-tool.md b/docs/adr/46554-dynamic-timeout-computation-for-mcp-logs-tool.md new file mode 100644 index 00000000000..3a80b3fee7c --- /dev/null +++ b/docs/adr/46554-dynamic-timeout-computation-for-mcp-logs-tool.md @@ -0,0 +1,48 @@ +# ADR-46554: Dynamic Timeout Computation for the MCP Logs Tool + +**Date**: 2026-07-19 +**Status**: Draft +**Deciders**: pelikhan, copilot-swe-agent + +--- + +### Context + +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. + +### Decision + +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. + +### Alternatives Considered + +#### Alternative 1: Increase or Remove the MCP Gateway Timeout Limit + +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. + +#### Alternative 2: Parallelise GitHub API Calls Within a Batch + +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. + +#### Alternative 3: Cache Workflow Run Listings Between Requests + +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. + +### Consequences + +#### Positive +- 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. +- 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. +- 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). + +#### Negative +- 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. +- 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. + +#### Neutral +- The `effectiveMCPLogsToolTimeoutMinutes` function signature now accepts a `workflowName string` parameter; all call sites must be updated accordingly (done in this PR). +- Tests for timeout computation are extended with a `workflowName` dimension, increasing test coverage but also test verbosity. + +--- + +*ADR created by [adr-writer agent]. Review and finalize before changing status from Draft to Accepted.* diff --git a/pkg/cli/logs_github_api.go b/pkg/cli/logs_github_api.go index 7994475e50a..582d2be9576 100644 --- a/pkg/cli/logs_github_api.go +++ b/pkg/cli/logs_github_api.go @@ -255,6 +255,16 @@ func listWorkflowRunsWithPagination(opts ListWorkflowRunsOptions) ([]WorkflowRun logsGitHubAPILog.Printf("gh run list command failed (not ExitError): %v. Command: gh %v", err, args) } + // When exec.CommandContext cancels the subprocess it returns an *exec.ExitError + // ("signal: killed") rather than the context error, so errors.Is checks in + // callers would not recognise it. Surface the context error directly so that + // errors.Is(err, context.DeadlineExceeded) / errors.Is(err, context.Canceled) + // work as expected. + if ctxErr := cmdCtx.Err(); ctxErr != nil { + logsGitHubAPILog.Printf("gh run list interrupted by context: %v", ctxErr) + return nil, 0, ctxErr + } + // Check for different error types with heuristics errMsg := err.Error() outputMsg := string(output) diff --git a/pkg/cli/logs_models.go b/pkg/cli/logs_models.go index 5df081f60e3..1b43bd99ead 100644 --- a/pkg/cli/logs_models.go +++ b/pkg/cli/logs_models.go @@ -26,10 +26,11 @@ const ( MaxIterations = 20 // BatchSize is the number of runs to fetch in each iteration BatchSize = 100 - // BatchSizeForAllWorkflows is the larger batch size when searching for agentic workflows - // There can be a really large number of workflow runs in a repository, so - // we are generous in the batch size when used without qualification. - BatchSizeForAllWorkflows = 250 + // BatchSizeForAllWorkflows is the batch size when searching across all agentic workflows. + // We cap this at 100 (the GitHub API max per_page) so each batch requires only a single + // API call. Using 250 previously caused three API round-trips per batch, making the + // unfiltered list slow enough to exceed the MCP gateway's default 60-second tool timeout. + BatchSizeForAllWorkflows = 100 // MaxConcurrentDownloads limits the number of parallel artifact downloads MaxConcurrentDownloads = 10 // APICallCooldown is the minimum pause between successive batch-fetch iterations to diff --git a/pkg/cli/logs_orchestrator_download.go b/pkg/cli/logs_orchestrator_download.go index a221780fee4..683a0908cab 100644 --- a/pkg/cli/logs_orchestrator_download.go +++ b/pkg/cli/logs_orchestrator_download.go @@ -189,8 +189,22 @@ func collectProcessedWorkflowRuns(runtime logsDownloadRuntime, opts LogsDownload } iteration++ logLogsIterationFetch(opts, runtime.fetchAllInRange, iteration, len(processedRuns)) - batch, err := fetchWorkflowRunBatch(opts, beforeDate, len(processedRuns), runtime.fetchAllInRange) + batch, err := fetchWorkflowRunBatch(runtime.activeCtx, opts, beforeDate, len(processedRuns), runtime.fetchAllInRange) if err != nil { + // Context deadline exceeded means our own timeout fired mid-call. + // Treat it like a graceful timeout: return whatever was collected so far. + if errors.Is(err, context.DeadlineExceeded) { + timeoutReached = true + break + } + // Context cancelled (e.g. user signal or outer gateway timeout): propagate + // the error without partial results. The caller discards partial runs on + // error, so returning them here would be misleading. We leave + // 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 } if len(batch.runs) == 0 { @@ -277,10 +291,11 @@ func logLogsIterationFetch(opts LogsDownloadOptions, fetchAllInRange bool, itera fmt.Fprintln(os.Stderr, console.FormatInfoMessage(fmt.Sprintf("Iteration %d: Need %d more runs with artifacts, fetching more...", iteration, opts.Count-processedCount))) } -func fetchWorkflowRunBatch(opts LogsDownloadOptions, beforeDate string, processedCount int, fetchAllInRange bool) (workflowRunBatch, error) { +func fetchWorkflowRunBatch(ctx context.Context, opts LogsDownloadOptions, beforeDate string, processedCount int, fetchAllInRange bool) (workflowRunBatch, error) { batchSize := computeLogsBatchSize(opts.WorkflowName, opts.Count, processedCount, fetchAllInRange) var oldestFetchedCreatedAt time.Time runs, totalFetched, err := listWorkflowRunsWithPagination(ListWorkflowRunsOptions{ + Context: ctx, WorkflowName: opts.WorkflowName, Limit: batchSize, StartDate: opts.StartDate, diff --git a/pkg/cli/logs_timeout_test.go b/pkg/cli/logs_timeout_test.go index 9a07d2543aa..aa4d74c9a0f 100644 --- a/pkg/cli/logs_timeout_test.go +++ b/pkg/cli/logs_timeout_test.go @@ -117,56 +117,93 @@ func TestEffectiveMCPLogsToolTimeoutMinutes(t *testing.T) { name string requestedTimeout int count int + workflowName string want int }{ { name: "explicit timeout is preserved", requestedTimeout: 5, count: 100, + workflowName: "my-workflow", want: 5, }, { - name: "small fetch window keeps one minute default", + name: "explicit timeout is preserved even without workflow name", + requestedTimeout: 5, + count: 100, + workflowName: "", + want: 5, + }, + { + name: "small fetch window keeps one minute default (named workflow)", requestedTimeout: 0, count: 40, + workflowName: "my-workflow", want: 1, }, { - name: "fetch window above forty runs gets two minutes", + name: "fetch window above forty runs gets two minutes (named workflow)", requestedTimeout: 0, count: 41, + workflowName: "my-workflow", want: 2, }, { - name: "eighty run fetch window stays in two minute tier", + name: "eighty run fetch window stays in two minute tier (named workflow)", requestedTimeout: 0, count: 80, + workflowName: "my-workflow", want: 2, }, { - name: "eighty one run fetch window enters three minute tier", + name: "eighty one run fetch window enters three minute tier (named workflow)", requestedTimeout: 0, count: 81, + workflowName: "my-workflow", want: 3, }, { - name: "default hundred run window gets three minutes", + name: "default hundred run window gets three minutes (named workflow)", requestedTimeout: 0, count: 100, + workflowName: "my-workflow", want: 3, }, { - name: "unspecified count falls back to default window size", + name: "unspecified count falls back to default window size (named workflow)", requestedTimeout: 0, count: 0, + workflowName: "my-workflow", want: 3, }, + // All-workflow cases: minimum 5 minutes when no workflow_name is given + { + name: "small count uses all-workflow minimum (no workflow name)", + requestedTimeout: 0, + count: 3, + workflowName: "", + want: defaultMCPLogsMinTimeoutMinutesAllWorkflows, + }, + { + name: "default count uses all-workflow minimum (no workflow name)", + requestedTimeout: 0, + count: 100, + workflowName: "", + want: defaultMCPLogsMinTimeoutMinutesAllWorkflows, + }, + { + name: "very large count exceeds all-workflow minimum (no workflow name)", + requestedTimeout: 0, + count: 250, + workflowName: "", + want: (250 + mcpLogsRunsPerDefaultTimeoutMinute - 1) / mcpLogsRunsPerDefaultTimeoutMinute, // ceil(250/mcpLogsRunsPerDefaultTimeoutMinute) > defaultMCPLogsMinTimeoutMinutesAllWorkflows + }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - if got := effectiveMCPLogsToolTimeoutMinutes(tt.requestedTimeout, tt.count); got != tt.want { - t.Errorf("effectiveMCPLogsToolTimeoutMinutes(%d, %d) = %d, want %d", tt.requestedTimeout, tt.count, got, tt.want) + if got := effectiveMCPLogsToolTimeoutMinutes(tt.requestedTimeout, tt.count, tt.workflowName); got != tt.want { + t.Errorf("effectiveMCPLogsToolTimeoutMinutes(%d, %d, %q) = %d, want %d", tt.requestedTimeout, tt.count, tt.workflowName, got, tt.want) } }) } diff --git a/pkg/cli/mcp_server_defaults_test.go b/pkg/cli/mcp_server_defaults_test.go index b2ab9f6ebca..3227e2c0f36 100644 --- a/pkg/cli/mcp_server_defaults_test.go +++ b/pkg/cli/mcp_server_defaults_test.go @@ -52,7 +52,7 @@ func TestMCPToolElicitationDefaults(t *testing.T) { } }) - t.Run("logs tool has count, timeout, max_tokens and artifacts defaults", func(t *testing.T) { + t.Run("logs tool has count, max_tokens and artifacts defaults (no timeout default)", func(t *testing.T) { type logsArgs struct { WorkflowName string `json:"workflow_name,omitempty" jsonschema:"Name of the workflow to download logs for (empty for all)"` Count int `json:"count,omitempty" jsonschema:"Number of workflow runs to download"` @@ -66,13 +66,12 @@ func TestMCPToolElicitationDefaults(t *testing.T) { t.Fatalf("Failed to generate schema: %v", err) } - // Add defaults as done in registerLogsTool + // Add defaults as done in registerLogsTool (no timeout default: it is + // computed at runtime from count and workflow_name so the go-sdk cannot + // fill it in statically without bypassing the per-request computation). if err := AddSchemaDefault(schema, "count", defaultMCPLogsToolCount); err != nil { t.Fatalf("Failed to add count default: %v", err) } - if err := AddSchemaDefault(schema, "timeout", defaultMCPLogsToolTimeoutMinutesForCount(defaultMCPLogsToolCount)); err != nil { - t.Fatalf("Failed to add timeout default: %v", err) - } if err := AddSchemaDefault(schema, "max_tokens", 12000); err != nil { t.Fatalf("Failed to add max_tokens default: %v", err) } @@ -96,21 +95,16 @@ func TestMCPToolElicitationDefaults(t *testing.T) { t.Errorf("Expected count default to be %d, got %v", defaultMCPLogsToolCount, countDefault) } - // Verify timeout default + // Verify timeout has NO schema default: registerLogsTool intentionally + // omits a static timeout default because the runtime computes it from + // both the effective count and workflow_name. A static default would be + // applied by the go-sdk before the handler runs, bypassing that logic. timeoutProp, ok := schema.Properties["timeout"] if !ok { t.Fatal("Expected 'timeout' property to exist") } - if len(timeoutProp.Default) == 0 { - t.Error("Expected 'timeout' property to have a default value") - } - var timeoutDefault int - if err := json.Unmarshal(timeoutProp.Default, &timeoutDefault); err != nil { - t.Fatalf("Failed to unmarshal timeout default: %v", err) - } - expectedTimeoutDefault := defaultMCPLogsToolTimeoutMinutesForCount(defaultMCPLogsToolCount) - if timeoutDefault != expectedTimeoutDefault { - t.Errorf("Expected timeout default to be %d, got %v", expectedTimeoutDefault, timeoutDefault) + if len(timeoutProp.Default) != 0 { + t.Errorf("Expected 'timeout' property to have no schema default (runtime-computed), got %s", timeoutProp.Default) } // Verify max_tokens default (backward-compat field) diff --git a/pkg/cli/mcp_tools_privileged.go b/pkg/cli/mcp_tools_privileged.go index 3ab9282b644..e48ef0170f8 100644 --- a/pkg/cli/mcp_tools_privileged.go +++ b/pkg/cli/mcp_tools_privileged.go @@ -19,6 +19,12 @@ const ( defaultMCPLogsToolCount = 100 defaultMCPLogsTimeoutMinutes = 1 mcpLogsRunsPerDefaultTimeoutMinute = 40 + // defaultMCPLogsMinTimeoutMinutesAllWorkflows is the minimum timeout (in minutes) + // used when no workflow_name filter is provided. Querying all workflow runs at once + // requires a single GitHub API call rather than a workflow-scoped call, but for + // large repositories the unfiltered endpoint can be significantly slower. A higher + // floor gives the tool enough headroom in those cases. + defaultMCPLogsMinTimeoutMinutesAllWorkflows = 5 ) // appendRepoFlagFromEnv appends "--repo " to args when GITHUB_REPOSITORY @@ -67,12 +73,19 @@ func effectiveMCPLogsToolCount(count int) int { return defaultMCPLogsToolCount } -func effectiveMCPLogsToolTimeoutMinutes(requestedTimeout, count int) int { +func effectiveMCPLogsToolTimeoutMinutes(requestedTimeout, count int, workflowName string) int { if requestedTimeout > 0 { return requestedTimeout } - return defaultMCPLogsToolTimeoutMinutesForCount(count) + base := defaultMCPLogsToolTimeoutMinutesForCount(count) + if workflowName == "" { + // Without a workflow filter the GitHub API must scan all workflow runs, which + // is substantially slower for large repositories. Apply a higher minimum so + // the tool is less likely to exhaust the MCP gateway's per-tool timeout. + return max(defaultMCPLogsMinTimeoutMinutesAllWorkflows, base) + } + return base } // The logs tool requires write+ access and checks actor permissions. @@ -88,11 +101,11 @@ func registerLogsTool(server *mcp.Server, execCmd execCmdFunc, actor string, val if err := AddSchemaDefault(logsSchema, "count", defaultMCPLogsToolCount); err != nil { mcpLog.Printf("Failed to add default for count: %v", err) } - // Schema default corresponds to defaultMCPLogsToolCount; runtime timeout - // scales with the effective count used for the request. - if err := AddSchemaDefault(logsSchema, "timeout", defaultMCPLogsToolTimeoutMinutesForCount(defaultMCPLogsToolCount)); err != nil { - mcpLog.Printf("Failed to add default for timeout: %v", err) - } + // No schema default for timeout: the runtime auto-computes it from the effective + // count and workflow_name so that no-workflow queries (which scan across all runs) + // receive a higher floor than single-workflow queries. Setting a static default + // here would cause the go-sdk to fill it in before the handler sees the arguments, + // bypassing the per-request computation. if err := AddSchemaDefault(logsSchema, "max_tokens", 12000); err != nil { mcpLog.Printf("Failed to add default for max_tokens: %v", err) } @@ -209,7 +222,7 @@ from where the previous request stopped due to timeout.`, // Scale the implicit MCP timeout with the requested fetch window so // larger fleet-wide requests do not hit the default per-tool timeout. - timeoutValue := effectiveMCPLogsToolTimeoutMinutes(args.Timeout, effectiveCount) + timeoutValue := effectiveMCPLogsToolTimeoutMinutes(args.Timeout, effectiveCount, args.WorkflowName) cmdArgs = append(cmdArgs, "--timeout", strconv.Itoa(timeoutValue)) // Always use --json mode in MCP server diff --git a/pkg/cli/mcp_tools_privileged_test.go b/pkg/cli/mcp_tools_privileged_test.go index 0d3c2e2b858..3bb91068d38 100644 --- a/pkg/cli/mcp_tools_privileged_test.go +++ b/pkg/cli/mcp_tools_privileged_test.go @@ -263,7 +263,7 @@ func TestLogsToolPassesArtifactsArgument(t *testing.T) { } func TestLogsToolUsesEffectiveCountForTimeoutScaling(t *testing.T) { - t.Run("omitted count uses MCP default for both -c and --timeout", func(t *testing.T) { + t.Run("omitted count and no workflow name use all-workflow minimum timeout", func(t *testing.T) { var capturedArgs []string mockExecCmd := func(ctx context.Context, args ...string) *exec.Cmd { capturedArgs = append([]string(nil), args...) @@ -289,9 +289,16 @@ func TestLogsToolUsesEffectiveCountForTimeoutScaling(t *testing.T) { timeoutIndex := slices.Index(capturedArgs, "--timeout") require.NotEqual(t, -1, timeoutIndex, "logs tool should pass --timeout") require.Less(t, timeoutIndex+1, len(capturedArgs), "--timeout should have a value") - assert.Equal(t, strconv.Itoa(defaultMCPLogsToolTimeoutMinutesForCount(defaultMCPLogsToolCount)), capturedArgs[timeoutIndex+1]) + // Without a workflow_name the timeout uses the all-workflow minimum floor. + // The timeout schema default was intentionally removed so that args.Timeout == 0 + // (the zero value) when the caller omits it, allowing the runtime to apply the floor. + expectedTimeout := effectiveMCPLogsToolTimeoutMinutes(0, defaultMCPLogsToolCount, "") + assert.Equal(t, strconv.Itoa(expectedTimeout), capturedArgs[timeoutIndex+1]) }) - + // Note: the named-workflow timeout behaviour (count-based, no all-workflow floor) is + // verified by TestEffectiveMCPLogsToolTimeoutMinutes in logs_timeout_test.go. + // An integration test is not feasible here because validateMCPWorkflowName rejects + // synthetic names that lack a corresponding .lock.yml file in the test environment. } // TestAuditToolPassesGithubRepositoryAsRepoFlag verifies that the audit MCP tool