github / github/copilot-cli

MCP initialize handshake has a fixed, non-configurable 60s budget with no retry - npx-launched stdio servers fail ~29% of sessions and never recover

Abierto
#4,421 2 comentarios 0 reacciones 0 asignados Ver en GitHub
area:mcp
Lenguaje dominante
Shell
Estrellas
11.2k
Forks
1.9k
Merge medio
14 h 16 min
PR fusionados (30 d)
6

Descripción

## Describe the bug

The MCP `initialize` handshake is governed by a **hard-coded 60 000 ms budget**. When it expires the CLI logs `Recorded failure for server ` and **never respawns that server for the life of the session**. There is no retry, no backoff, and no way to raise the budget.

For any stdio server launched via `npx`, this budget is far too close to the real startup cost, so sessions fail probabilistically. On one developer machine, log analysis of a single day shows **22 of 76 handshake attempts (29%) exceeded 60 s and failed**, while the other 54 succeeded in **8.6 s - 56.3 s** (median ~17 s). Same machine, same config, same package - the outcome is a coin flip.

The user-visible symptom is severe and misleading: the session simply has no tools from that server. The agent reports the tools don't exist and silently falls back to worse strategies. Nothing tells the user a server failed to start.

## Root cause of the latency (not a CLI bug, but the CLI has no headroom for it)

`npx` adds a large, highly variable fixed cost to every spawn even when the package is already installed locally. Measured against `@azure-devops/mcp` (present in the npx cache for three weeks prior, unchanged):

| launch form | avg | individual runs |
|---|---|---|
| `npx -y @azure-devops/mcp ...` | **15.39 s** | 27.91 / 8.31 / 9.96 s |
| globally-installed `.cmd` shim | **3.32 s** | 3.28 / 3.16 / 3.50 s |
| `node /dist/index.js` | **3.21 s** | 3.16 / 3.20 / 3.28 s |

A second run isolating the wrapper alone (n=3 each, back to back):

| | run 1 | run 2 | run 3 |
|---|---|---|---|
| direct `node` | 3.46 s | 3.58 s | 3.53 s |
| via `npx -y` | 16.71 s | 16.80 s | 17.06 s |

So `npx` contributes a **flat ~13.3 s**, and its spread on a warm idle machine is **8.3 s -> 27.9 s (3.4x)**. That variance is what crosses 60 s.

Ruled out as causes:

- **Cold package cache** - the package was resolved into the npx cache three weeks earlier and was unchanged.
- **Slow registry** - packument fetch measured at 0.76 / 1.18 / 1.34 s.
- **Concurrency/contention** - failures had a *lower* mean number of concurrent spawns (2.00) than successes (2.78).
- **The server being slow** - it answers `initialize` in ~3.2 s when launched without `npx`.

Failures do skew toward early in the CLI process's life (median 54 s after process start, vs 222 s for successes), consistent with the npx child competing with the CLI's own startup work. But the fundamental problem is that a ~17 s median with a ~28 s tail is being measured against a 60 s ceiling with zero retries.

## Why recovery never happens

On timeout the server is marked failed and left alone. In logs where a session *did* recover, recovery was incidental: an unrelated full MCP client rebuild fired ~1.6 s later and re-spawned everything, and that attempt happened to finish in 56.3 s. Sessions where no rebuild happens to occur stay permanently toolless. One session observed here went 35 minutes with no tools from those servers before the host process was replaced.

Representative log (server names generalised):

```
18:47:25.694Z Starting MCP client for ado-a with command: cmd and args: /c cd /d && npx -y @azure-devops/mcp -d work-items search repositories
18:47:25.694Z Connecting MCP client for ado-a...
18:47:25.697Z Starting MCP client for ado-b ...
18:48:31.706Z Failed to start MCP client for ado-b: initialize handshake did not complete within 60000 ms
18:48:31.706Z Recorded failure for server ado-b: ...
18:48:31.759Z Failed to start MCP client for ado-a: initialize handshake did not complete within 60000 ms
18:48:31.759Z Recorded failure for server ado-a: ...

```

Note the elapsed time from `Connecting` to failure is ~66 s, so the 60 s timer appears to start ~6 s after the connect log line.

## Not configurable, and not fixed in newer builds

Scanning `prebuilds/win32-x64/runtime.node` finds two parameterised format strings:

- `initialize handshake did not complete within {} ms`
- `MCP initialize handshake timed out after {}ms`

There is **no** `startup_timeout`, `handshake_timeout` or `connect_timeout` field for MCP server config, and **no** `COPILOT_*` environment variable for an MCP startup/handshake timeout. The per-server `timeout` field discussed in #1378 governs *tool-call* requests (default 180 s), not the handshake.

Both strings are present, unchanged, and with no accompanying knob, in **1.0.71** and in **1.0.79-9** - so upgrading is not a remedy.

## Steps to reproduce

1. Configure any stdio MCP server whose launch takes 15-60 s. The reliable way to manufacture this is `npx`:

```json
{
"mcpServers": {
"slow": {
"type": "local",
"command": "npx",
"args": ["-y", "@azure-devops/mcp", ""],
"tools": ["*"]
}
}
}
```

2. Start sessions repeatedly. A meaningful fraction exceed 60 s.
3. Observe: the server is absent from the tool surface for the entire session, with no retry and no user-facing notification.

## Expected behavior

1. **Make the handshake budget configurable per server** - e.g. a `startupTimeout` field in `mcp-config.json`, or extend the existing `timeout` field to cover startup. Today there is no escape hatch of any kind.
2. **Retry a timed-out handshake with bounded exponential backoff.** A single attempt against a heavy-tailed latency distribution guarantees recurring failures. This should be bounded - #3782 describes the opposite failure of unbounded respawning.
3. **Surface the failure to the user and the model.** Today a failed server is indistinguishable from a server that was never configured, which causes the agent to confidently report that the tools do not exist.

## Related

- #2907 - allow configuring the MCP slow-connection *warning* threshold (adjacent; this issue is about the hard budget)
- #3329 - prompt executes before MCP servers finish connecting
- #1938 - RFC `autoConnect: false` / deferred registration, which would sidestep startup-window contention
- #3782 - unbounded respawn loop (the opposite failure; any retry added here must be bounded)
- microsoft/azure-devops-mcp#1214 - users reporting that server "works 10% of the time", with agents reporting no ADO MCP tools; closed as not reproducible. The measurements above appear to explain those reports.

## Affected versions

- Copilot CLI **1.0.71** (confirmed in logs and in the shipped binary)
- Copilot CLI **1.0.79-9** (same strings, still no knob)
- OS: Windows 11 (x64)

## Workaround

Avoid `npx` in `command`. Install the server globally and invoke the binary or its entry point directly. This cut the handshake from ~15.4 s (8.3-27.9 s) to ~3.3 s (3.16-3.50 s), restoring a ~18x margin under the 60 s cap instead of ~2x. It also keeps the server as a local stdio process, which matters when the server resolves paths relative to its working directory.

Guía de contribución

Abrir la guía de contribución

Línea de trabajo

Comienza rastreando la ruta de inicio de MCP stdio que emite “initialize handshake did not complete within {} ms” y registra los fallos del servidor; después, revisa cómo mcp-config.json gestiona el timeout existente por servidor. Define un comportamiento de reintentos acotado, la notificación de fallos visible para el usuario/modelo y un presupuesto de inicio configurable; la tarea estará terminada cuando los servidores iniciados lentamente mediante npx puedan recuperarse sin respawning ilimitado.

Escrito por el modelo de indexación a partir del texto del issue.

Evaluación

Stack tecnológico
node.js
Área
cli, tooling
Tipo de issue
Nueva funcionalidad
Dificultad
5/5
Tiempo estimado
Más de una semana
Estado de actividad
Activo
Claridad
Bastante claro
Aptitud para principiantes
42/100

Recibe los nuevos issues en tu correo

Un resumen breve de issues de GitHub para principiantes.