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); } /**