Negotiated timeout observer grants extensions past hard timeout ceiling

[buger]

Bug

The negotiated timeout observer in ProbeAgent.run() can grant extensions that push the effective ai_timeout past the external hard timeout (visor_timeout / maxOperationTimeout's caller-side Promise.race). When this happens:

1. The extension suppresses the wind-down (observer granted more time → no gracefulTimeoutState.triggered)
2. The external hard timeout fires → kills the agent instantly via AbortController.abort() or Promise.race rejection
3. Result: undefined or generic timeout message instead of partial results

Observed in production

Trace: 2793eb7d734bcec534a080c0d7e4cf20

• explore-code check: maxOperationTimeout = 25min, external hard timeout = 30min
• At T=25min: observer fires, sees 1 active search tool (running 3.4min), grants +10min extension
• New effective deadline: 35min — exceeds the 30min hard timeout
• Between T=25-30min: agent keeps working (extension suppressed wind-down)
• At T=30min: external hard timeout fires → output = undefined
• Wind-down steps never executed despite timeout_behavior: negotiated being configured

Root cause

In ProbeAgent.js around line 3681-3704, the observer grants extensions capped to min(requested, maxPerRequest, remainingBudget) but never checks against the external hard timeout:

const grantedMs = Math.min(requestedMs, maxPerRequest, remainingBudget);
// Missing: Math.min(..., externalHardTimeout - elapsed)

The observer has no knowledge of the external hard timeout ceiling, so it can grant useless extensions that will never be utilized.

Additional issue: history_length: 0 for MCP bridge tool calls

The observer reads this.history.slice(-6) and activeTools to make its decision. When the agent dispatches tools via the MCP bridge (SSE custom tools server), both are empty:

• this.history is only populated after streamText() resolves, not during tool execution
• activeTools tracks Vercel AI SDK-level tool calls, but pending MCP responses aren't tracked there

This causes the observer to see history_length=0 and active_tools_count=0 even when the agent is actively waiting for MCP tool responses. In trace 2793eb7d734bcec534a080c0d7e4cf20, the generate-response observer saw history_length=0 at both 30min and 50min checkpoints, despite multiple successful MCP tool completions.

Suggested fixes

1. Cap extensions to external timeout headroom: Accept an optional externalHardTimeout parameter in ProbeAgent options and cap grantedMs to Math.min(grantedMs, externalHardTimeout - elapsed). Decline extensions when headroom < minimum useful time (e.g., 60s).

2. Track MCP bridge tool calls in activeTools: When the agent dispatches a tool call that goes through the MCP bridge, record it in the activeTools map so the observer can see pending MCP responses as "active tools."

Workaround (implemented in Visor)

We've added capping on the Visor side (ai-review-service.ts):

• Cap negotiatedTimeoutBudget and negotiatedTimeoutMaxPerRequest to visorTimeout - aiTimeout before passing to ProbeAgent
• Call triggerGracefulWindDown() on the agent when the external Promise.race timeout fires

This prevents the overshoot but doesn't fix the observer's blindness to MCP activity (history_length=0).

[probelabs]

Summary

Thank you for this detailed bug report, @buger! You've clearly identified two distinct issues in the negotiated timeout observer implementation, complete with production trace evidence and a well-analyzed root cause.

What I Understand

Issue 1: Extension Overshoot Past External Hard Timeout

The timeout observer at ProbeAgent.js:3799 calculates grantedMs as:

const grantedMs = Math.min(requestedMs, remainingBudgetMs, negotiatedTimeoutState.maxPerRequestMs);

As you correctly identified, this caps extensions to the internal budget (negotiatedTimeoutBudget) and per-request limit (negotiatedTimeoutMaxPerRequest), but has no visibility into the external hard timeout (e.g., Visor's Promise.race ceiling). This allows the observer to grant extensions that push the effective deadline past the external kill point, resulting in:

1. Wind-down being suppressed (observer thinks there's more time)
2. External hard timeout firing → instant abort → undefined output
3. No partial results despite timeout_behavior: negotiated

Issue 2: MCP Bridge Tool Calls Not Tracked in activeTools

The observer relies on activeTools (populated via toolCall events) and this.history.slice(-6) to make extension decisions. However:

• MCP tools dispatched through the SSE bridge don't emit toolCall events through the same path
• this.history is only populated after streamText() resolves, not during tool execution
• Result: observer sees history_length=0 and active_tools_count=0 even when MCP tools are actively running

Assessment

Aspect	Evaluation
Category	Bug
Priority	High — production impact with data loss (partial results discarded)
Complexity	Moderate — requires changes to timeout calculation and MCP tool tracking
Affected Areas	ProbeAgent.js (timeout observer), MCP bridge tool dispatch

Clarifying Questions

1. External timeout interface: Should the externalHardTimeout parameter be passed via ProbeAgentOptions, or would you prefer a callback/hook that the observer can query at decision time? The latter might be more flexible for dynamic external deadlines.

2. MCP tool tracking: Looking at the code, MCP tools are wrapped via mcpBridge.getVercelTools() and their execute functions call mcpManager.callTool(). Should the toolCall event emission be added in MCPClientManager.callTool(), or should there be a separate tracking mechanism for MCP-specific tools?

3. Minimum useful headroom: You suggested 60s as the minimum useful time before declining an extension. Is this a hardcoded constant, or should it be configurable (similar to gracefulStopDeadline)?

Suggested Implementation Approach

Fix 1: Cap Extensions to External Timeout

// In runTimeoutObserver(), after calculating grantedMs:
const elapsed = Date.now() - negotiatedTimeoutState.startTime;
const externalHeadroom = this.externalHardTimeout 
  ? Math.max(0, this.externalHardTimeout - elapsed) 
  : Infinity;

if (externalHeadroom < 60000) { // minimum useful time
  // Decline extension — not enough headroom
  await this._initiateGracefulStop(gracefulTimeoutState, 'external timeout headroom exhausted');
  return;
}

const cappedMs = Math.min(grantedMs, externalHeadroom);

Fix 2: Track MCP Tool Calls

Add toolCall event emission in MCPClientManager.callTool() (around line 530 in client.js):

// Before the actual call:
this.recordMcpEvent('tool.call_started', { ... });
// Also emit to agent's event emitter if available
this.agentEvents?.emit('toolCall', {
  toolCallId: `${toolName}-${Date.now()}`,
  name: toolName,
  args,
  status: 'started',
  timestamp: new Date().toISOString(),
});

Workaround Validation

Your Visor-side workaround (capping negotiatedTimeoutBudget and negotiatedTimeoutMaxPerRequest to visorTimeout - aiTimeout) is a solid defensive measure. The second part (calling triggerGracefulWindDown() when the external Promise.race fires) ensures wind-down executes even if the observer overshoots.

---

References:

• probe/npm/src/agent/ProbeAgent.js:3799 – grantedMs calculation missing external timeout cap
• probe/npm/src/agent/ProbeAgent.js:3677-3890 – runTimeoutObserver implementation
• probe/npm/src/agent/mcp/client.js:530 – callTool method (potential location for MCP tool tracking)
• probe/docs/probe-agent/sdk/timeout-modes.md:95-145 – Negotiated timeout documentation

---

Powered by Visor from Probelabs

💡 TIP: You can chat with Visor using /visor ask <your question>