MCP initialize handshake has a fixed, non-configurable 60s budget with no retry - npx-launched stdio servers fail ~29% of sessions and never recover
- Lingua principale
- Shell
- Stelle
- 11.2k
- Fork
- 1.9k
- Merge medio
- 14h 16m
- PR unite (30g)
- 6
Descrizione
## 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.
Guida per i contributori
Apri la guida per i contributori
Direzione di ricerca
Inizia tracciando il percorso di avvio MCP stdio che emette “initialize handshake did not complete within {} ms” e registra i fallimenti del server, quindi esamina come mcp-config.json gestisce il timeout esistente per server. Definisci un comportamento di retry limitato, la segnalazione dei fallimenti visibile all’utente/al modello e un budget di avvio configurabile; il lavoro è completato quando i server avviati lentamente tramite npx possono recuperare senza respawning illimitato.
Scritto dal modello di indicizzazione a partire dal testo della issue.
Valutazione
- Stack tecnologico
- node.js
- Ambito
- cli, tooling
- Tipo di issue
- Funzionalità
- Difficoltà
- 5/5
- Tempo stimato
- Più di una settimana
- Stato di attività
- Attiva
- Chiarezza
- Abbastanza chiara
- Idoneità per principianti
- 42/100