Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 7 additions & 1 deletion vortex-extension/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
131 changes: 131 additions & 0 deletions vortex-extension/src/mcpClient.test.ts
Original file line number Diff line number Diff line change
@@ -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;
});
});
25 changes: 18 additions & 7 deletions vortex-extension/src/mcpClient.ts
Original file line number Diff line number Diff line change
Expand Up @@ -322,11 +322,21 @@ export class WsmMcpClient {
return result.tools ?? [];
}

async callTool<T = unknown>(name: string, args?: Record<string, unknown>): Promise<T> {
/**
* `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<T = unknown>(name: string, args?: Record<string, unknown>, timeoutMs?: number): Promise<T> {
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.`;
Expand Down Expand Up @@ -359,8 +369,8 @@ export class WsmMcpClient {
return this.callTool<ScanConflictsResult>('scan_conflicts');
}

mergeConflicts(args?: MergeConflictsArgs): Promise<MergeConflictsResult> {
return this.callTool<MergeConflictsResult>('merge_conflicts', args as Record<string, unknown> | undefined);
mergeConflicts(args?: MergeConflictsArgs, timeoutMs?: number): Promise<MergeConflictsResult> {
return this.callTool<MergeConflictsResult>('merge_conflicts', args as Record<string, unknown> | undefined, timeoutMs);
}

getStatus(): Promise<GetStatusResult> {
Expand Down Expand Up @@ -412,15 +422,16 @@ export class WsmMcpClient {
}
}

private request(method: string, params?: unknown): Promise<unknown> {
private request(method: string, params?: unknown, timeoutMs?: number): Promise<unknown> {
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);
Expand Down
87 changes: 85 additions & 2 deletions vortex-extension/src/resolveAction.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -116,14 +116,18 @@ function fakeStatus(overrides: Partial<GetStatusResult> = {}): 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;

const connect = vi.fn(async (options: WsmMcpClientOptions): Promise<WsmMergeClient> => {
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;
}
Expand All @@ -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', () => {
Expand Down Expand Up @@ -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');
});
});
50 changes: 47 additions & 3 deletions vortex-extension/src/resolveAction.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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<MergeConflictsResult>;
mergeConflicts(args?: MergeConflictsArgs, timeoutMs?: number): Promise<MergeConflictsResult>;
getStatus(): Promise<GetStatusResult>;
listMerges(): Promise<ListMergesResult>;
close(): Promise<void>;
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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);
}

/**
Expand Down
Loading