From 6657f00db1b01071a58c888a574ac9936af1accf Mon Sep 17 00:00:00 2001 From: Chris Knight Date: Fri, 21 Aug 2026 09:07:17 -0400 Subject: [PATCH] Give merge_conflicts its own deadline instead of the 30s request default The "Resolve Script Conflicts" action ran both its dry-run preview and the real merge through a client left on mcpClient.ts's general-purpose DEFAULT_REQUEST_TIMEOUT_MS (30s). A merge's runtime scales with the size of the load order, so on a large one it simply cannot finish in that window. Hit for real on a 274-mod install with 44 conflicting script files: the preview alone exceeded 30s, so resolveScriptConflicts reported "Failed to preview script-conflict merges" and returned at the preview stage - the real merge below it never ran. Because a deploy had already cleared mod0000_MergedFiles, that left an empty merged mod and a game that wouldn't start, with ~200 script compile errors naming members the merge is supposed to add to vanilla scripts ('scmcc' is not a member of 'CNewNPC', Could not find function 'SSS_AddSkillSlot', and so on). Vortex's log recorded only the transport error: [WARN] witcherscriptmerger-vortex: resolveScriptConflicts failed {"error":"WSM MCP request 'tools/call' timed out after 30000ms"} Both call sites now pass MERGE_CALL_TIMEOUT_MS (10 minutes, matching nexusDownloader.ts's own precedent for an operation whose runtime is the user's data rather than a round trip). The preview gets it too, deliberately: a dry run does the entire scan-and-three-way-merge computation and only skips the writes, so sizing it as if it were cheap is exactly what broke. The deadline is passed per call - callTool/request take an optional override - rather than raised on the client at connect time, because requestTimeoutMs also bounds the initialize handshake, and a WSM process that fails to start should keep failing fast instead of hanging for ten minutes. A timeout also now reports what it means for the install ("nothing was merged", plus the note that an empty or stale merged mod can stop the game starting) rather than surfacing a bare transport error; the original error is still passed through as the notification detail. 9 new tests (217 total): the timeout reaching both call sites, connect not being widened, the per-call override winning over the client default, not leaking to later calls on the same client, the handshake keeping the short default, and the timeout vs. non-timeout notification wording. typecheck and lint clean. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01FP8H6rBLCGPBFRSVsF3Kgw --- vortex-extension/README.md | 8 +- vortex-extension/src/mcpClient.test.ts | 131 +++++++++++++++++++++ vortex-extension/src/mcpClient.ts | 25 ++-- vortex-extension/src/resolveAction.test.ts | 87 +++++++++++++- vortex-extension/src/resolveAction.ts | 50 +++++++- 5 files changed, 288 insertions(+), 13 deletions(-) create mode 100644 vortex-extension/src/mcpClient.test.ts diff --git a/vortex-extension/README.md b/vortex-extension/README.md index 4852898..197d02f 100644 --- a/vortex-extension/README.md +++ b/vortex-extension/README.md @@ -53,7 +53,13 @@ does anything for any other game. whole-file merge failed but merging function-by-function succeeded), and - only on confirmation - spawns a second process to run the real merge and shows its result. v1 scope, deliberately: merges every detected conflict in one pass; there's no per-file - selection or custom merge-order override yet. + selection or custom merge-order override yet. Both `merge_conflicts` calls get their own + ten-minute deadline (`MERGE_CALL_TIMEOUT_MS`) rather than `mcpClient.ts`'s + general-purpose 30s `DEFAULT_REQUEST_TIMEOUT_MS` — a merge's runtime scales with the + load order, and the dry-run preview costs the same as the merge it previews (it does the + full three-way merge and only skips the writes). The deadline is passed per call, so the + `initialize` handshake keeps the short default and a WSM process that fails to start + still fails fast. - **A merge-history dashboard tile** (`src/mergeHistoryDashlet.ts`): lists every merge WSM has already recorded (via its MCP `list_merges` tool) - relative path, which merged mod folder holds the result, and each source mod's recorded hash - with a manual diff --git a/vortex-extension/src/mcpClient.test.ts b/vortex-extension/src/mcpClient.test.ts new file mode 100644 index 0000000..cea65de --- /dev/null +++ b/vortex-extension/src/mcpClient.test.ts @@ -0,0 +1,131 @@ +import { EventEmitter } from 'events'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; + +// Mocked before the module under test is imported, so WsmMcpClient.connect spawns this +// fake instead of a real WSM process. The integration suite (test/mcpClient.integration.test.ts) +// covers the real binary; this file covers only the request-deadline plumbing, which +// needs no process at all and would otherwise be untestable without one. +const { spawnMock } = vi.hoisted(() => ({ spawnMock: vi.fn() })); +vi.mock('child_process', () => ({ spawn: spawnMock })); + +const { WsmMcpClient } = await import('./mcpClient'); + +/** A newline-delimited-JSON stand-in for a spawned WSM `mcp` process. Answers + * `initialize` (so connect() resolves) and, by default, nothing else - leaving a + * `tools/call` pending forever so a test can drive it purely off the request timer. */ +function fakeChild() { + const stdout = new EventEmitter() as EventEmitter & { setEncoding(enc: string): void }; + stdout.setEncoding = () => undefined; + const stderr = new EventEmitter() as EventEmitter & { setEncoding(enc: string): void }; + stderr.setEncoding = () => undefined; + + const written: string[] = []; + const stdin = Object.assign(new EventEmitter(), { + write: (chunk: string) => { + written.push(chunk); + for (const line of chunk.split('\n').filter((l) => l.trim() !== '')) { + const msg = JSON.parse(line) as { id?: number; method?: string }; + // Answer only the handshake; every other request is left hanging on purpose. + // Emitted synchronously rather than via queueMicrotask/setTimeout: vi.useFakeTimers + // controls both of those, and the reply has to land without any timer being + // advanced (advancing time is exactly what these tests use to trigger the + // deadlines under test). Safe because request() registers its pending entry + // before calling writeMessage, so the response can never arrive "too early". + if (msg.method === 'initialize' && msg.id !== undefined) { + stdout.emit('data', JSON.stringify({ jsonrpc: '2.0', id: msg.id, result: {} }) + '\n'); + } + } + return true; + }, + end: () => undefined, + }); + + const child = Object.assign(new EventEmitter(), { + stdout, + stderr, + stdin, + kill: vi.fn(), + killed: false, + pid: 1234, + }); + + return { child, written }; +} + +describe('WsmMcpClient request deadlines', () => { + beforeEach(() => { + spawnMock.mockReset(); + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + async function connectFake(requestTimeoutMs?: number) { + const { child, written } = fakeChild(); + spawnMock.mockReturnValue(child); + return { client: await WsmMcpClient.connect({ exePath: 'C:\\wsm\\fake.exe', requestTimeoutMs }), written }; + } + + // The bug this whole change exists for: merge_conflicts used to inherit the 30s + // general-purpose default, and a big load order's merge (or its equally expensive + // dry-run preview) blew straight through it. + it('honors a per-call timeout override instead of the client default', async () => { + const { client } = await connectFake(30_000); + + const pending = client.mergeConflicts({ dryRun: true }, 600_000); + const assertion = expect(pending).rejects.toThrow(/timed out after 600000ms/); + + // Well past the 30s client default - must NOT have rejected yet. + await vi.advanceTimersByTimeAsync(120_000); + // ...and now past the override. + await vi.advanceTimersByTimeAsync(600_000); + + await assertion; + }); + + it('falls back to the client default when no override is given', async () => { + const { client } = await connectFake(30_000); + + const pending = client.getStatus(); + const assertion = expect(pending).rejects.toThrow(/timed out after 30000ms/); + + await vi.advanceTimersByTimeAsync(30_000); + + await assertion; + }); + + // The override must stay scoped to the one call. If it leaked onto the client it would + // also bound the initialize handshake, and a WSM process that fails to start would hang + // for the full merge-sized deadline instead of failing fast. + it('does not let a per-call override leak into later calls on the same client', async () => { + const { client } = await connectFake(30_000); + + const long = client.mergeConflicts({ dryRun: true }, 600_000); + const longAssertion = expect(long).rejects.toThrow(/timed out after 600000ms/); + + const short = client.getStatus(); + const shortAssertion = expect(short).rejects.toThrow(/timed out after 30000ms/); + + await vi.advanceTimersByTimeAsync(30_000); + await shortAssertion; + + await vi.advanceTimersByTimeAsync(600_000); + await longAssertion; + }); + + it('uses the client default for the initialize handshake', async () => { + const { child } = fakeChild(); + // Swallow the handshake so it can only ever end in a timeout. + child.stdin.write = () => true; + spawnMock.mockReturnValue(child); + + const connecting = WsmMcpClient.connect({ exePath: 'C:\\wsm\\fake.exe', requestTimeoutMs: 30_000 }); + const assertion = expect(connecting).rejects.toThrow(/'initialize' timed out after 30000ms/); + + await vi.advanceTimersByTimeAsync(30_000); + + await assertion; + }); +}); diff --git a/vortex-extension/src/mcpClient.ts b/vortex-extension/src/mcpClient.ts index 3500915..151c937 100644 --- a/vortex-extension/src/mcpClient.ts +++ b/vortex-extension/src/mcpClient.ts @@ -322,11 +322,21 @@ export class WsmMcpClient { return result.tools ?? []; } - async callTool(name: string, args?: Record): Promise { + /** + * `timeoutMs` overrides this client's `requestTimeoutMs` for this one call. Use it for a + * tool whose runtime scales with the user's data rather than being bounded by round-trip + * latency - `merge_conflicts` above all (see `resolveAction.ts`'s + * `MERGE_CALL_TIMEOUT_MS`). Overriding per-call, rather than raising the whole client's + * `requestTimeoutMs` at `connect` time, is deliberate: that value also bounds the + * `initialize` handshake, and a handshake that hasn't answered in a few seconds means a + * WSM process that failed to start, not one that's working hard - it should fail fast + * instead of inheriting a merge-sized deadline. + */ + async callTool(name: string, args?: Record, timeoutMs?: number): Promise { const result = (await this.request('tools/call', { name, arguments: args ?? {}, - })) as McpToolCallResult; + }, timeoutMs)) as McpToolCallResult; if (result.isError) { const message = result.content?.find((c) => c.type === 'text')?.text ?? `Tool '${name}' reported an error.`; @@ -359,8 +369,8 @@ export class WsmMcpClient { return this.callTool('scan_conflicts'); } - mergeConflicts(args?: MergeConflictsArgs): Promise { - return this.callTool('merge_conflicts', args as Record | undefined); + mergeConflicts(args?: MergeConflictsArgs, timeoutMs?: number): Promise { + return this.callTool('merge_conflicts', args as Record | undefined, timeoutMs); } getStatus(): Promise { @@ -412,15 +422,16 @@ export class WsmMcpClient { } } - private request(method: string, params?: unknown): Promise { + private request(method: string, params?: unknown, timeoutMs?: number): Promise { const id = this.nextId++; const message: JsonRpcRequest = { jsonrpc: '2.0', id, method, params }; + const deadlineMs = timeoutMs ?? this.requestTimeoutMs; return new Promise((resolve, reject) => { const timer = setTimeout(() => { this.pending.delete(id); - reject(new Error(`WSM MCP request '${method}' timed out after ${this.requestTimeoutMs}ms`)); - }, this.requestTimeoutMs); + reject(new Error(`WSM MCP request '${method}' timed out after ${deadlineMs}ms`)); + }, deadlineMs); this.pending.set(id, { resolve, reject, timer }); this.writeMessage(message); diff --git a/vortex-extension/src/resolveAction.test.ts b/vortex-extension/src/resolveAction.test.ts index f796cf6..c754c01 100644 --- a/vortex-extension/src/resolveAction.test.ts +++ b/vortex-extension/src/resolveAction.test.ts @@ -116,6 +116,9 @@ function fakeStatus(overrides: Partial = {}): GetStatusResult { * satisfy `WsmMergeClient`'s type. */ function fakeConnect(outcomes: Array<{ result?: MergeConflictsResult; error?: Error }>) { const calls: WsmMcpClientOptions[] = []; + // Every mergeConflicts invocation, so a test can assert what deadline the call was + // given - see the MERGE_CALL_TIMEOUT_MS tests below. + const mergeCalls: Array<{ args: unknown; timeoutMs: number | undefined }> = []; let closedCount = 0; let callIndex = 0; @@ -123,7 +126,8 @@ function fakeConnect(outcomes: Array<{ result?: MergeConflictsResult; error?: Er calls.push(options); const outcome = outcomes[callIndex++]; return { - mergeConflicts: async () => { + mergeConflicts: async (args?: unknown, timeoutMs?: number) => { + mergeCalls.push({ args, timeoutMs }); if (outcome.error) { throw outcome.error; } @@ -137,7 +141,7 @@ function fakeConnect(outcomes: Array<{ result?: MergeConflictsResult; error?: Er }; }); - return { connect, calls, closedCount: () => closedCount }; + return { connect, calls, mergeCalls, closedCount: () => closedCount }; } describe('resolveScriptConflicts', () => { @@ -348,4 +352,83 @@ describe('resolveScriptConflicts', () => { await expect(resolveScriptConflicts(api, { connect })).resolves.toBeUndefined(); expect(errorNotifications).toHaveLength(1); }); + + // Regression coverage for a real failure on a 274-mod install: merge_conflicts inherited + // mcpClient.ts's general-purpose 30s DEFAULT_REQUEST_TIMEOUT_MS, the dry-run preview + // exceeded it, and resolveScriptConflicts bailed at the preview stage - the real merge + // never ran, leaving an unmerged mod0000_MergedFiles and a game that wouldn't start. + // Both calls must carry the long, merge-sized deadline: a preview does the same + // scan-and-merge computation as the real merge and only skips the writes, so sizing it + // as if it were cheap is precisely what broke. + const TEN_MINUTES_MS = 10 * 60 * 1000; + + it('gives the dry-run preview a merge-sized timeout, not the general-purpose request default', async () => { + const { api } = fakeApi({ toolPath: 'C:\\wsm\\WitcherScriptMerger.Headless.exe' }); + const { connect, mergeCalls } = fakeConnect([{ result: mergeResult() }]); + + await resolveScriptConflicts(api, { connect }); + + expect(mergeCalls).toHaveLength(1); + expect(mergeCalls[0].timeoutMs).toBe(TEN_MINUTES_MS); + expect((mergeCalls[0].args as { dryRun?: boolean }).dryRun).toBe(true); + }); + + it('gives the real merge the same merge-sized timeout as the preview', async () => { + const { api } = fakeApi({ + toolPath: 'C:\\wsm\\WitcherScriptMerger.Headless.exe', + dialogResponses: [{ action: 'Merge Now' }], + }); + const preview = mergeResult({ merged: ['a.ws'] }); + const final = mergeResult({ merged: ['a.ws'], dryRun: false }); + const { connect, mergeCalls } = fakeConnect([{ result: preview }, { result: final }]); + + await resolveScriptConflicts(api, { connect }); + + expect(mergeCalls).toHaveLength(2); + expect(mergeCalls[0].timeoutMs).toBe(TEN_MINUTES_MS); + expect(mergeCalls[1].timeoutMs).toBe(TEN_MINUTES_MS); + expect((mergeCalls[1].args as { dryRun?: boolean }).dryRun).toBe(false); + }); + + // The long deadline belongs to the merge call alone. connect() must NOT be handed it as + // the client-wide requestTimeoutMs, which also bounds the initialize handshake - a WSM + // process that fails to start should still fail fast rather than hang for ten minutes. + it('does not widen the client-wide request timeout (the initialize handshake must still fail fast)', async () => { + const { api } = fakeApi({ toolPath: 'C:\\wsm\\WitcherScriptMerger.Headless.exe' }); + const { connect, calls } = fakeConnect([{ result: mergeResult() }]); + + await resolveScriptConflicts(api, { connect }); + + expect(calls[0].requestTimeoutMs).toBeUndefined(); + }); + + it('explains that nothing was merged when the merge call times out, rather than surfacing a bare transport error', async () => { + const { api, errorNotifications } = fakeApi({ + toolPath: 'C:\\wsm\\WitcherScriptMerger.Headless.exe', + }); + const timeout = new Error("WSM MCP request 'tools/call' timed out after 600000ms"); + const { connect } = fakeConnect([{ error: timeout }]); + + await resolveScriptConflicts(api, { connect }); + + expect(errorNotifications).toHaveLength(1); + const shown = errorNotifications[0].message; + expect(shown).toContain('nothing was merged'); + expect(shown).toContain('10 minutes'); + // the original error is still handed over as the detail, not swallowed + expect(errorNotifications[0].detail).toBe(timeout); + }); + + it('leaves a non-timeout failure message unchanged', async () => { + const { api, errorNotifications } = fakeApi({ + toolPath: 'C:\\wsm\\WitcherScriptMerger.Headless.exe', + }); + const { connect } = fakeConnect([{ error: new Error('spawn ENOENT') }]); + + await resolveScriptConflicts(api, { connect }); + + expect(errorNotifications).toHaveLength(1); + expect(errorNotifications[0].message).toBe('Failed to preview script-conflict merges'); + expect(errorNotifications[0].message).not.toContain('nothing was merged'); + }); }); diff --git a/vortex-extension/src/resolveAction.ts b/vortex-extension/src/resolveAction.ts index c6821fe..391e8d5 100644 --- a/vortex-extension/src/resolveAction.ts +++ b/vortex-extension/src/resolveAction.ts @@ -54,8 +54,33 @@ const ACTIVITY_NOTIFICATION_ID = 'witcherscriptmerger-vortex-resolve-conflicts-a * needs both. Reusing the same already-connected client (rather than opening a third * one just for this) is the entire point - see that function's own doc comment on why * it takes a client instead of connecting its own. */ +/** + * How long to allow a single `merge_conflicts` MCP call - preview or real merge - before + * giving up. Ten minutes, matching `nexusDownloader.ts`'s `DEFAULT_DOWNLOAD_TIMEOUT_MS` + * precedent for "an operation whose runtime is the user's data, not a round trip". + * + * `mcpClient.ts`'s general-purpose `DEFAULT_REQUEST_TIMEOUT_MS` (30s) is far too short + * here, and this is not theoretical: on a real 274-mod load order with 44 conflicting + * script files, the *preview* alone blew past 30s, so `resolveScriptConflicts` reported + * "Failed to preview script-conflict merges" and returned at the preview stage - the real + * merge below it never ran at all. The user was left with an unmerged (and, because a + * prior deploy had already cleared it, empty) `mod0000_MergedFiles` and a game that + * refused to start, with ~200 script compile errors naming members the merge is supposed + * to add to vanilla scripts. + * + * Note this applies to the dry-run preview just as much as the real merge: a preview does + * the entire scan-and-three-way-merge computation and only skips the writes, so it costs + * essentially the same time as the merge it is previewing. Sizing this off "it's only a + * preview" would reintroduce the same bug. + * + * Deliberately NOT passed to `connect` as the client-wide `requestTimeoutMs`: that also + * bounds the `initialize` handshake, which should still fail fast when WSM can't start - + * see `WsmMcpClient.callTool`'s own comment on the per-call override. + */ +const MERGE_CALL_TIMEOUT_MS = 10 * 60 * 1000; + export interface WsmMergeClient { - mergeConflicts(args?: MergeConflictsArgs): Promise; + mergeConflicts(args?: MergeConflictsArgs, timeoutMs?: number): Promise; getStatus(): Promise; listMerges(): Promise; close(): Promise; @@ -215,7 +240,7 @@ async function runMergeConflictsWorkflow( try { const client = await connect({ exePath, env }); try { - const result = await client.mergeConflicts(args); + const result = await client.mergeConflicts(args, MERGE_CALL_TIMEOUT_MS); // Unit K: reconciles coexistenceGuard.ts's own "last known merge state" against // this extension's own just-completed workflow, using the same still-open client @@ -273,13 +298,32 @@ async function runMergeConflictsWorkflow( } } +/** + * A timed-out `merge_conflicts` call reads, on its own, as a bare transport error + * ("request 'tools/call' timed out after ...ms") that says nothing about what it means for + * the user's install. It means specifically that *no merge was written* - and if a deploy + * had already cleared the merged mod, that leaves the game unable to start, which is a far + * worse outcome than the wording suggests. `isTimeout` spots that case so `reportFailure` + * can say so, and point at the one thing that actually helps (a huge load order simply + * needing longer than `MERGE_CALL_TIMEOUT_MS`). + */ +function isTimeout(err: unknown): boolean { + return err instanceof Error && /timed out after \d+ms/.test(err.message); +} + function reportFailure(api: types.IExtensionApi, message: string, err: unknown): void { const detail = err instanceof Error ? err : String(err); log('warn', 'witcherscriptmerger-vortex: resolveScriptConflicts failed', { message, error: err instanceof Error ? err.message : String(err), + timedOut: isTimeout(err), }); - api.showErrorNotification?.(message, detail); + const shown = isTimeout(err) + ? `${message}: Script Merger did not finish within ${Math.round(MERGE_CALL_TIMEOUT_MS / 60000)} minutes, so nothing was merged. ` + + 'Your merged mod has been left untouched - if it is empty or out of date, the game may fail to start until a merge completes. ' + + 'Very large load orders can need longer; running Script Merger directly will also do the merge.' + : message; + api.showErrorNotification?.(shown, detail); } /**