Skip to content

Commit 0c04309

Browse files
authored
fix(core): F2 cleanup PR B — self-heal observability (W133-a + W134) (QwenLM#4460)
* fix(core): F2 cleanup PR B — self-heal observability (W133-a + W134) W93 declined as already satisfied by W1 fix in QwenLM#4336 commit 6 (spawnEntry's catch already calls forceShutdown which runs the full cleanup table — listener removal, timer clear, subscriber detach, sweep+disconnect, onClosed eviction). Source-verified non-repro. W133-a: McpClient.onerror now captures the error in a private `lastTransportError` field (reset at each connect()); the W120 silent-drop block at mcp-pool-entry.ts:346 reads it via the new `getLastTransportError()` getter and appends `: <error.message>` to the lastError string on the emitted 'failed' event. Preserves the literal "silent transport drop" prefix invariant for log-grep backward compat — pre-fix marker stays a substring. W134: sweepAndDisconnect now returns SweepResult instead of void — { pidSweepError?, disconnectError?, descendantsFound?, descendantsSignaled? }. The silent-drop fire-and-forget caller chains to inspect the result and emits a structured warn log when either pid-sweep threw OR sigtermPids partially signaled (signaled < found) — surfaces orphan-process pressure without inflating PR scope (no new SSE event or SDK reducer state; deferred to W134-followup if maintainers want metrics). forceShutdown / doRestart sweep callers ignore the return value (JS implicit-void at await sites preserves behavior). 4 new tests in mcp-transport-pool.test.ts covering W133-a happy path + fallback (no prior onerror) + W134 pidSweepError + W134 partial-signal failure modes. Module-mocks pid-descendants.js for controllable sweep behavior, and debugLogger.js to observe warn calls (production logger is session-gated and a no-op in tests). Singleton-stub debugLogger mock so production module-load `createDebugLogger('McpPool:Entry')` and the test's retrieval get the same vi.fn instances. Verification: - tsc clean: packages/core, packages/cli (server.ts pre-existing errors unchanged) - F2 transport-pool: 32/32 pass (28 pre-existing + 4 new) - mcp-client: 46/46 pass - eslint --max-warnings 0 clean on 3 touched files Part of QwenLM#4175 QwenLM#4336 follow-up bucket. * fix(core): QwenLM#4460 round 1 fold-in — 4 copilot doc/comment threads adopted T1 [copilot mcp-pool-entry.ts:116 — stale line ref in SweepResult JSDoc]: replaced `mcp-pool-entry.ts:383` with stable method-anchor reference to the W120 silent-drop block inside `statusChangeListener`. Line numbers drift on every edit; method names don't. T2 [copilot mcp-pool-entry.ts:453 — `?? 0` ambiguous in warn payload]: silent-drop warn log now prints `descendantsFound=unknown` and `descendantsSignaled=unknown` when the values are undefined (only reachable in the pidSweepError branch — sweep threw before assignment). Operators triaging the warn can now distinguish "sweep succeeded but found 0 descendants" from "sweep itself threw, count is genuinely unmeasured". Locked in via a new assertion in the W134 pidSweepError test. T3 [copilot mcp-client.ts:116 — brittle line refs in lastTransportError JSDoc]: replaced `mcp-pool-entry.ts:346` and `mcp-client.ts:130` with stable method/block names (the `statusChangeListener` silent- drop block; the `client.onerror` arrow inside connect()). Same fix applied to the parallel comment in mcp-transport-pool.test.ts:730 for consistency. T4 [copilot mcp-transport-pool.test.ts:797 — singleton-stub mock comment contradictory]: rewrote the comment to unambiguously describe what the mock DOES (factory body runs once; inner arrow returns the same object on every call) instead of the prior hypothetical phrasing ("Returning a fresh object would have...") which read as a description of current behavior at first glance. All 4 are doc/comment fixes — zero behavior change apart from the T2 string format ('unknown' instead of '0'). Verified: - 32/32 mcp-transport-pool.test.ts pass - tsc clean on packages/core - eslint --max-warnings 0 clean on 3 touched files * fix(core): QwenLM#4460 round 2 fold-in — remove dead SweepResult.disconnectError field T5 [wenshao mcp-pool-entry.ts:134 — `disconnectError` is dead data]: glm-5.1 review caught that the field was populated when `client.disconnect()` threw (line 844) but no consumer ever read it — the silent-drop `.then()` handler gated only on `pidSweepError` and partial-signal; `forceShutdown` and `doRestart` ignore the return; no test asserted on it. Removed the field from `SweepResult` and the assignment in the disconnect catch. The pre-existing `debugLogger.error(`client.disconnect failed for ...`)` inside `sweepAndDisconnect` already gives operators the signal — adding it to the outer silent-drop warn would have been duplicate noise. If a future consumer needs to gate logic on disconnect failures, re-add the field + reader at that point. Verification: 32/32 mcp-transport-pool.test.ts pass; tsc + eslint clean on the touched file.
1 parent 57d0478 commit 0c04309

3 files changed

Lines changed: 405 additions & 5 deletions

File tree

packages/core/src/tools/mcp-client.ts

Lines changed: 42 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -102,6 +102,21 @@ export class McpClient {
102102
private transport: Transport | undefined;
103103
private status: MCPServerStatus = MCPServerStatus.DISCONNECTED;
104104
private isDisconnecting = false;
105+
/**
106+
* F2 (#4175 follow-up — W133-a): captures the most recent error
107+
* delivered to the SDK Client's `onerror` callback. The pool entry's
108+
* W120 silent-drop block (the DISCONNECTED-on-active branch inside
109+
* `PoolEntry.statusChangeListener`) reads this via
110+
* `getLastTransportError()` to thread the upstream cause (EPIPE,
111+
* OAuth 401, server crash) into the `'failed'` event's `lastError`
112+
* string instead of emitting only the synthetic
113+
* `'transport disconnected (silent transport drop)'` marker. Reset
114+
* at the top of `connect()` so a successful reconnect clears stale
115+
* state. No reset on `disconnect()` — McpClient instances are GC'd
116+
* at pool entry teardown; field staleness has no observable
117+
* consumer post-disconnect.
118+
*/
119+
private lastTransportError?: Error;
105120

106121
constructor(
107122
private readonly serverName: string,
@@ -123,6 +138,12 @@ export class McpClient {
123138
*/
124139
async connect(): Promise<void> {
125140
this.isDisconnecting = false;
141+
// F2 (#4175 follow-up — W133-a): clear stale upstream error from
142+
// any prior connect/disconnect cycle. The W120 silent-drop reader
143+
// is otherwise satisfied by `undefined` and falls back to the
144+
// synthetic marker — but a stale error from a previous incarnation
145+
// would mis-attribute a fresh transport drop to an old cause.
146+
this.lastTransportError = undefined;
126147
this.updateStatus(MCPServerStatus.CONNECTING);
127148
try {
128149
this.transport = await this.createTransport();
@@ -131,6 +152,13 @@ export class McpClient {
131152
if (this.isDisconnecting) {
132153
return;
133154
}
155+
// F2 (#4175 follow-up — W133-a): capture the upstream error
156+
// BEFORE the synchronous `updateStatus(DISCONNECTED)` cascades
157+
// to PoolEntry's statusChangeListener. The listener's W120
158+
// silent-drop block reads `lastTransportError` inline; setting
159+
// it ahead of `updateStatus` guarantees the field is populated
160+
// by the time the listener fires.
161+
this.lastTransportError = error;
134162
debugLogger.error(`MCP ERROR (${this.serverName}):`, error.toString());
135163
this.updateStatus(MCPServerStatus.DISCONNECTED);
136164
};
@@ -304,6 +332,20 @@ export class McpClient {
304332
return t.pid;
305333
}
306334

335+
/**
336+
* F2 (#4175 follow-up — W133-a): expose the most recent SDK Client
337+
* `onerror` payload so PoolEntry's W120 silent-drop block can thread
338+
* the upstream cause (EPIPE, OAuth 401, server-side crash) into the
339+
* `'failed'` event's `lastError` string. Returns `undefined` if no
340+
* error has been observed since the last `connect()`. Caller falls
341+
* back to the synthetic marker on `undefined`. Population site: the
342+
* `client.onerror` arrow inside `connect()` (this file). Consumer:
343+
* the W120 silent-drop block inside `PoolEntry.statusChangeListener`.
344+
*/
345+
getLastTransportError(): Error | undefined {
346+
return this.lastTransportError;
347+
}
348+
307349
async readResource(
308350
uri: string,
309351
options?: { signal?: AbortSignal },

packages/core/src/tools/mcp-pool-entry.ts

Lines changed: 113 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -107,6 +107,35 @@ export interface PooledConnection {
107107
release(): void;
108108
}
109109

110+
/**
111+
* F2 (#4175 follow-up — W134): structured outcome of
112+
* `PoolEntry.sweepAndDisconnect`. The silent-drop fire-and-forget
113+
* caller (the W120 silent-drop block inside `statusChangeListener`)
114+
* reads this off the chained promise to surface orphan-process
115+
* pressure to operators via a structured `warn` log. `forceShutdown`
116+
* and `doRestart` callers ignore the return — their own catch paths
117+
* carry richer error signals already.
118+
*
119+
* Both `descendantsFound` and `descendantsSignaled` are tracked
120+
* because partial-signal failure (`signaled < found`) is itself
121+
* orphan-process-pressure evidence even when the sweep itself does
122+
* NOT throw — e.g. a child exited between `listDescendantPids` and
123+
* `sigtermPids`, OR EPERM on a child the daemon doesn't own.
124+
*
125+
* Internal — NOT exported. The sweep result never crosses the wire
126+
* (pool events stay shape-compatible per `PoolEvent` union); this
127+
* type only exists to give the in-process caller something to chain
128+
* a log decision on.
129+
*/
130+
interface SweepResult {
131+
/** Set when `listDescendantPids` itself threw (sandbox blocking pgrep, ESRCH on root, etc.). */
132+
pidSweepError?: Error;
133+
/** Number of descendant pids `listDescendantPids` returned. Undefined if root pid unavailable or sweep threw. */
134+
descendantsFound?: number;
135+
/** Number of descendant pids `sigtermPids` successfully signaled. May be < `descendantsFound`. */
136+
descendantsSignaled?: number;
137+
}
138+
110139
/**
111140
* Internal pool-entry record. Created once per `ConnectionId`,
112141
* holds the shared `McpClient` + its tool/prompt snapshots + ref
@@ -343,11 +372,25 @@ export class PoolEntry {
343372
// 'failed' event and can route any pending callTool promises
344373
// to MCPCallInterruptedError. Mirrors forceShutdown's
345374
// emit→detach ordering at line 583-593.
375+
//
376+
// F2 (#4175 follow-up — W133-a): thread the upstream
377+
// McpClient.onerror cause (EPIPE, OAuth 401, server crash)
378+
// into `lastError` instead of emitting only the synthetic
379+
// marker. Pre-fix the only diagnostic carrier was the synthetic
380+
// string; operators triaging a 'failed' event had to grep
381+
// daemon `--debug` logs for the matching `MCP ERROR (...)` line
382+
// out of band. Now the actual error message is on the wire.
383+
// Preserves the literal `"silent transport drop"` substring so
384+
// any operator log-grep tooling that targets the pre-fix marker
385+
// keeps matching post-fix.
386+
const upstreamError = this.client.getLastTransportError();
346387
this.emit({
347388
kind: 'failed',
348389
serverName: this.serverName,
349390
generation: this._generation,
350-
lastError: 'transport disconnected (silent transport drop)',
391+
lastError: upstreamError
392+
? `transport disconnected (silent transport drop): ${upstreamError.message}`
393+
: 'transport disconnected (silent transport drop)',
351394
});
352395
// Detach all subscriber views (W122 cleanup). Snapshot keys
353396
// because detach mutates `subscribers`.
@@ -381,7 +424,48 @@ export class PoolEntry {
381424
// Errors inside the chain log at warn/error via
382425
// `sweepAndDisconnect`'s own catches.
383426
void this.sweepAndDisconnect('silent_drop').then(
384-
() => {
427+
(result) => {
428+
// F2 (#4175 follow-up — W134): surface orphan-process
429+
// pressure to operators. Two failure shapes worth a
430+
// structured `warn` here:
431+
// (a) `pidSweepError`: pid-discovery itself threw
432+
// (pgrep blocked by sandbox, ESRCH at root pid,
433+
// etc.). We may have leaked descendants we never
434+
// enumerated.
435+
// (b) Partial signal: discovery succeeded but
436+
// `sigtermPids` killed fewer than discovered
437+
// (some children already exited between listing
438+
// and signaling, OR EPERM on a child the daemon
439+
// doesn't own). Less alarming than (a) but still
440+
// worth surfacing during silent drops.
441+
// Pre-fix `void` discarded both signals; the only
442+
// observability path was tailing `--debug warn+` for
443+
// the inner `sweepAndDisconnect` log line out of band.
444+
const partialSignal =
445+
result.descendantsFound !== undefined &&
446+
result.descendantsSignaled !== undefined &&
447+
result.descendantsSignaled < result.descendantsFound;
448+
if (result.pidSweepError !== undefined || partialSignal) {
449+
// F2 (#4175 follow-up — copilot review T2 on #4460):
450+
// log `'unknown'` instead of `0` when the count fields are
451+
// undefined. They are undefined ONLY in the
452+
// `pidSweepError` branch (the throw happened before
453+
// assignment); operators triaging the warn should be able
454+
// to distinguish "0 found" (sweep succeeded, no children
455+
// — unusual but possible if grandchildren already exited)
456+
// from "not measured" (sweep itself threw, count is
457+
// genuinely unknown). Logging `0` for both was factually
458+
// ambiguous.
459+
debugLogger.warn(
460+
`PoolEntry ${this.id} silent-drop sweep observability: ` +
461+
`descendantsFound=${result.descendantsFound ?? 'unknown'}, ` +
462+
`descendantsSignaled=${result.descendantsSignaled ?? 'unknown'}, ` +
463+
`pidSweepError=${result.pidSweepError?.message ?? 'none'}. ` +
464+
`Possible orphan-process pressure — operator should ` +
465+
`check for lingering subprocess descendants of the dead ` +
466+
`transport.`,
467+
);
468+
}
385469
this.updateGlobalStatus();
386470
},
387471
() => {
@@ -716,21 +800,36 @@ export class PoolEntry {
716800
* usually indicates a transport bug worth surfacing). Pre-W35
717801
* `doRestart` had logged both at `debug` — production
718802
* observability gap that masked PID exhaustion.
803+
*
804+
* F2 (#4175 follow-up — W134): now returns a `SweepResult` so the
805+
* silent-drop fire-and-forget caller (which `void`-discards the
806+
* promise and would otherwise lose the orphan-process-pressure
807+
* signal entirely) can chain a structured warn log when either pid
808+
* sweep threw or `sigtermPids` partially signaled. The `forceShutdown`
809+
* and `doRestart` callers continue to ignore the return value (their
810+
* caller-side `await` discards it) — those paths already carry rich
811+
* error signals via their own catches and don't need the extra
812+
* surface. The internal log lines stay unchanged for backward
813+
* compat with existing log-tail tooling.
719814
*/
720-
private async sweepAndDisconnect(reason: string): Promise<void> {
815+
private async sweepAndDisconnect(reason: string): Promise<SweepResult> {
816+
const result: SweepResult = {};
721817
try {
722818
const rootPid = this.client.getTransportPid?.();
723819
if (rootPid !== undefined) {
724820
const descendants = await listDescendantPids(rootPid);
725821
if (descendants.length > 0) {
726-
const signaled = sigtermPids(descendants);
822+
result.descendantsFound = descendants.length;
823+
result.descendantsSignaled = sigtermPids(descendants);
727824
debugLogger.debug(
728-
`Sent SIGTERM to ${signaled}/${descendants.length} descendants ` +
825+
`Sent SIGTERM to ${result.descendantsSignaled}/${descendants.length} descendants ` +
729826
`of pid ${rootPid} for ${this.id} (${reason})`,
730827
);
731828
}
732829
}
733830
} catch (err) {
831+
result.pidSweepError =
832+
err instanceof Error ? err : new Error(String(err));
734833
debugLogger.warn(
735834
`Descendant pid sweep failed for ${this.id} (${reason}): ${String(
736835
err,
@@ -740,10 +839,19 @@ export class PoolEntry {
740839
try {
741840
await this.client.disconnect();
742841
} catch (err) {
842+
// Disconnect failure is rare (usually a transport bug worth
843+
// surfacing) and gets a structured error log here. No
844+
// SweepResult field captures this — the silent-drop chain
845+
// doesn't gate the outer warn on it (the inner error log
846+
// already gives operators the signal), and forceShutdown /
847+
// doRestart callers ignore the return entirely. Per wenshao
848+
// review #4460: was previously stored on `SweepResult.disconnectError`
849+
// but had no reader — removed as dead data.
743850
debugLogger.error(
744851
`client.disconnect failed for ${this.id} (${reason}): ${String(err)}`,
745852
);
746853
}
854+
return result;
747855
}
748856

749857
/**

0 commit comments

Comments
 (0)