feat(FN-2659): add merger verification agent log events

- Emit merger agent log entries when deterministic verification starts, runs commands, and completes successfully
- Record tool_result/tool_error details for verification command outcomes including timing and truncated output summaries
- Add agent-log coverage for in-merge verification fix lifecycle events (start, retry, success, and failure)
- Extend merger deterministic verification tests to assert start/success and failure agent log entries
This commit is contained in:
Fusion
2026-04-27 01:03:16 -07:00
committed by gsxdsm
parent 7691babb23
commit 479230634b
2 changed files with 244 additions and 4 deletions

View File

@@ -3355,6 +3355,130 @@ describe("aiMergeTask — deterministic merge verification", () => {
expect(verificationOrder).toEqual(["test", "build"]); expect(verificationOrder).toEqual(["test", "build"]);
}); });
it("writes verification start/success entries to agent log", async () => {
mockedExecSync.mockImplementation((cmd: any) => {
const cmdStr = String(cmd);
if (cmdStr.includes("rev-parse --verify")) return Buffer.from("abc123");
if (cmdStr.includes("git log")) return "- feat: something" as any;
if (cmdStr.includes("merge-base")) return Buffer.from("abc123");
if (cmdStr.includes("git diff") && cmdStr.includes("--stat")) return "1 file changed" as any;
if (cmdStr.includes("merge --squash")) return Buffer.from("");
if (cmdStr.includes("vitest run")) return Buffer.from("");
if (cmdStr.includes("diff --cached --quiet")) return "1" as any;
if (cmdStr.includes("diff --cached") && !cmdStr.includes("--quiet")) return "" as any;
if (cmdStr.includes("branch -d") || cmdStr.includes("branch -D")) return Buffer.from("");
if (cmdStr.includes("worktree remove")) return Buffer.from("");
if (cmdStr === "git rev-parse HEAD" || cmdStr.startsWith("git rev-parse HEAD ")) return "mergedcommit123";
if (cmdStr.includes("show --shortstat")) return "1 file changed, 1 insertion(+)" as any;
return Buffer.from("");
});
mockedCreateFnAgent.mockResolvedValue({
session: {
prompt: vi.fn().mockResolvedValue(undefined),
dispose: vi.fn(),
},
} as any);
const store = createMockStore(
{ id: "FN-050", worktree: "/tmp/root/.worktrees/KB-050" },
[{ id: "FN-050", worktree: "/tmp/root/.worktrees/KB-050", column: "in-review" } as Task],
);
(store.getSettings as ReturnType<typeof vi.fn>).mockResolvedValue({
...DEFAULT_SETTINGS,
testCommand: "vitest run",
});
const result = await aiMergeTask(store, "/tmp/root", "FN-050");
expect(result.merged).toBe(true);
expect(store.appendAgentLog).toHaveBeenCalledWith(
"FN-050",
"Running deterministic merge verification (test: vitest run)",
"text",
undefined,
"merger",
);
expect(store.appendAgentLog).toHaveBeenCalledWith(
"FN-050",
"Running test command",
"tool",
"vitest run",
"merger",
);
const appendAgentLogCalls = (store.appendAgentLog as ReturnType<typeof vi.fn>).mock.calls;
const successCall = appendAgentLogCalls.find(
([task, message, type]) => task === "FN-050"
&& message === "test command succeeded (exit 0)"
&& type === "tool_result",
);
expect(successCall).toBeTruthy();
expect(successCall?.[3]).toMatch(/^\d+ms$/);
expect(successCall?.[4]).toBe("merger");
expect(store.appendAgentLog).toHaveBeenCalledWith(
"FN-050",
"Deterministic merge verification passed",
"text",
undefined,
"merger",
);
});
it("writes verification failure output summaries to agent log", async () => {
mockedExecSync.mockImplementation((cmd: any) => {
const cmdStr = String(cmd);
if (cmdStr.includes("rev-parse --verify")) return Buffer.from("abc123");
if (cmdStr.includes("git log")) return "- feat: something" as any;
if (cmdStr.includes("merge-base")) return Buffer.from("abc123");
if (cmdStr.includes("git diff") && cmdStr.includes("--stat")) return "1 file changed" as any;
if (cmdStr.includes("merge --squash")) return Buffer.from("");
if (cmdStr.includes("vitest run")) {
const error = new Error("Test failed") as any;
error.status = 1;
error.stdout = "FAIL: some test failed";
error.stderr = "";
throw error;
}
if (cmdStr.includes("diff --cached --quiet")) return "1" as any;
if (cmdStr.includes("branch -d") || cmdStr.includes("branch -D")) return Buffer.from("");
if (cmdStr.includes("worktree remove")) return Buffer.from("");
return Buffer.from("");
});
mockedCreateFnAgent.mockResolvedValue({
session: {
prompt: vi.fn().mockResolvedValue(undefined),
dispose: vi.fn(),
},
} as any);
const store = createMockStore(
{ id: "FN-050", worktree: "/tmp/root/.worktrees/KB-050" },
[{ id: "FN-050", worktree: "/tmp/root/.worktrees/KB-050", column: "in-review" } as Task],
);
(store.getSettings as ReturnType<typeof vi.fn>).mockResolvedValue({
...DEFAULT_SETTINGS,
testCommand: "vitest run",
verificationFixRetries: 0,
});
await expect(aiMergeTask(store, "/tmp/root", "FN-050")).rejects.toThrow(
"Deterministic test verification failed",
);
const appendAgentLogCalls = (store.appendAgentLog as ReturnType<typeof vi.fn>).mock.calls;
const failureCall = appendAgentLogCalls.find(
([task, message, type]) => task === "FN-050"
&& message === "test command failed (exit 1)"
&& type === "tool_error",
);
expect(failureCall).toBeTruthy();
expect(failureCall?.[3]).toContain("full output available in engine logs");
expect(failureCall?.[4]).toBe("merger");
});
it("fails merge when testCommand fails and does not move task to done", async () => { it("fails merge when testCommand fails and does not move task to done", async () => {
const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
mockedExecSync.mockImplementation((cmd: any) => { mockedExecSync.mockImplementation((cmd: any) => {

View File

@@ -655,12 +655,12 @@ async function runDeterministicVerification(
(hasTestCommand ? ` [test:${testSourceLabel} ${normalizedTestCommand}]` : "") + (hasTestCommand ? ` [test:${testSourceLabel} ${normalizedTestCommand}]` : "") +
(hasBuildCommand ? ` [build:${buildSourceLabel} ${normalizedBuildCommand}]` : ""), (hasBuildCommand ? ` [build:${buildSourceLabel} ${normalizedBuildCommand}]` : ""),
); );
await store.logEntry( const deterministicVerificationMessage =
taskId,
"Running deterministic merge verification" + "Running deterministic merge verification" +
(hasTestCommand ? ` (test${testSource === "inferred" ? " [inferred]" : ""}: ${normalizedTestCommand})` : "") + (hasTestCommand ? ` (test${testSource === "inferred" ? " [inferred]" : ""}: ${normalizedTestCommand})` : "") +
(hasBuildCommand ? ` (build${buildSource === "inferred" ? " [inferred]" : ""}: ${normalizedBuildCommand})` : ""), (hasBuildCommand ? ` (build${buildSource === "inferred" ? " [inferred]" : ""}: ${normalizedBuildCommand})` : "");
); await store.logEntry(taskId, deterministicVerificationMessage);
await store.appendAgentLog(taskId, deterministicVerificationMessage, "text", undefined, "merger");
// Run test command first if configured // Run test command first if configured
if (hasTestCommand) { if (hasTestCommand) {
@@ -677,6 +677,13 @@ async function runDeterministicVerification(
`Deterministic test verification failed (exit ${testResult.exitCode}) — see prior [verification] entry for truncated output`, `Deterministic test verification failed (exit ${testResult.exitCode}) — see prior [verification] entry for truncated output`,
"VerificationError", "VerificationError",
); );
await store.appendAgentLog(
taskId,
"Verification failed",
"tool_error",
`exit ${testResult.exitCode}`,
"merger",
);
throw new VerificationError( throw new VerificationError(
`Deterministic test verification failed for ${taskId}`, `Deterministic test verification failed for ${taskId}`,
result, result,
@@ -699,6 +706,13 @@ async function runDeterministicVerification(
`Deterministic build verification failed (exit ${buildResult.exitCode}) — see prior [verification] entry for truncated output`, `Deterministic build verification failed (exit ${buildResult.exitCode}) — see prior [verification] entry for truncated output`,
"VerificationError", "VerificationError",
); );
await store.appendAgentLog(
taskId,
"Verification failed",
"tool_error",
`exit ${buildResult.exitCode}`,
"merger",
);
throw new VerificationError( throw new VerificationError(
`Deterministic build verification failed for ${taskId}`, `Deterministic build verification failed for ${taskId}`,
result, result,
@@ -708,6 +722,7 @@ async function runDeterministicVerification(
mergerLog.log(`${taskId}: deterministic verification passed`); mergerLog.log(`${taskId}: deterministic verification passed`);
await store.logEntry(taskId, "Deterministic merge verification passed"); await store.logEntry(taskId, "Deterministic merge verification passed");
await store.appendAgentLog(taskId, "Deterministic merge verification passed", "text", undefined, "merger");
return result; return result;
} }
@@ -722,6 +737,7 @@ async function runVerificationCommand(
throwIfAborted(signal, taskId); throwIfAborted(signal, taskId);
mergerLog.log(`${taskId}: running ${type} command: ${command}`); mergerLog.log(`${taskId}: running ${type} command: ${command}`);
await store.logEntry(taskId, `[verification] Running ${type} command: ${command}`); await store.logEntry(taskId, `[verification] Running ${type} command: ${command}`);
await store.appendAgentLog(taskId, `Running ${type} command`, "tool", command, "merger");
const result: VerificationCommandResult = { const result: VerificationCommandResult = {
command, command,
@@ -748,15 +764,30 @@ async function runVerificationCommand(
result.success = true; result.success = true;
const verificationDurationMs = Date.now() - verificationStartedAt; const verificationDurationMs = Date.now() - verificationStartedAt;
const timingDetail = `${verificationDurationMs}ms`;
if (bufferOverflow) { if (bufferOverflow) {
mergerLog.log(`${taskId}: ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`); mergerLog.log(`${taskId}: ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`);
await store.logEntry( await store.logEntry(
taskId, taskId,
`[timing] [verification] ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`, `[timing] [verification] ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`,
); );
await store.appendAgentLog(
taskId,
`${type} command succeeded (exit 0)`,
"tool_result",
timingDetail,
"merger",
);
} else { } else {
mergerLog.log(`${taskId}: ${type} command succeeded in ${verificationDurationMs}ms`); mergerLog.log(`${taskId}: ${type} command succeeded in ${verificationDurationMs}ms`);
await store.logEntry(taskId, `[timing] [verification] ${type} command succeeded (exit 0) in ${verificationDurationMs}ms`); await store.logEntry(taskId, `[timing] [verification] ${type} command succeeded (exit 0) in ${verificationDurationMs}ms`);
await store.appendAgentLog(
taskId,
`${type} command succeeded (exit 0)`,
"tool_result",
timingDetail,
"merger",
);
} }
return result; return result;
} catch (error: any) { } catch (error: any) {
@@ -779,6 +810,13 @@ async function runVerificationCommand(
taskId, taskId,
`[timing] [verification] ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`, `[timing] [verification] ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`,
); );
await store.appendAgentLog(
taskId,
`${type} command succeeded (exit 0)`,
"tool_result",
`${verificationDurationMs}ms`,
"merger",
);
return result; return result;
} }
@@ -791,6 +829,13 @@ async function runVerificationCommand(
taskId, taskId,
`[timing] [verification] ${type} command failed (exit ${result.exitCode}) after ${verificationDurationMs}ms:\n${summary}`, `[timing] [verification] ${type} command failed (exit ${result.exitCode}) after ${verificationDurationMs}ms:\n${summary}`,
); );
await store.appendAgentLog(
taskId,
`${type} command failed (exit ${result.exitCode})`,
"tool_error",
summary,
"merger",
);
} }
return result; return result;
@@ -890,6 +935,13 @@ A merge has been applied and the verification command failed. Your job is to fix
taskId, taskId,
`In-merge verification fix agent started (model: ${describeModel(session)}, runId: ${runId ?? "unknown"}, agentId: ${agentId})`, `In-merge verification fix agent started (model: ${describeModel(session)}, runId: ${runId ?? "unknown"}, agentId: ${agentId})`,
); );
await store.appendAgentLog(
taskId,
`Fix agent started (model: ${describeModel(session)})`,
"text",
undefined,
"merger",
);
try { try {
// Build the fix prompt // Build the fix prompt
@@ -926,6 +978,13 @@ ${failureContext.output.slice(0, VERIFICATION_LOG_MAX_CHARS)}
taskId, taskId,
`Re-running deterministic merge verification (attempt ${fixAttemptNumber ?? "unknown"})`, `Re-running deterministic merge verification (attempt ${fixAttemptNumber ?? "unknown"})`,
); );
await store.appendAgentLog(
taskId,
`Re-running verification (attempt ${fixAttemptNumber ?? "unknown"})`,
"text",
undefined,
"merger",
);
const reRunResult = await runVerificationCommand( const reRunResult = await runVerificationCommand(
store, store,
rootDir, rootDir,
@@ -946,6 +1005,7 @@ ${failureContext.output.slice(0, VERIFICATION_LOG_MAX_CHARS)}
const errorMessage = err instanceof Error ? err.message : String(err); const errorMessage = err instanceof Error ? err.message : String(err);
mergerLog.warn(`${taskId}: in-merge fix agent error: ${errorMessage}`); mergerLog.warn(`${taskId}: in-merge fix agent error: ${errorMessage}`);
await store.logEntry(taskId, "In-merge verification fix agent encountered an error", errorMessage); await store.logEntry(taskId, "In-merge verification fix agent encountered an error", errorMessage);
await store.appendAgentLog(taskId, "Fix agent encountered an error", "tool_error", errorMessage, "merger");
return false; return false;
} }
} }
@@ -2401,6 +2461,13 @@ export async function aiMergeTask(
if (maxFixRetries > 0 && (verificationErr.verificationResult.testResult || verificationErr.verificationResult.buildResult)) { if (maxFixRetries > 0 && (verificationErr.verificationResult.testResult || verificationErr.verificationResult.buildResult)) {
mergerLog.log(`${taskId}: deterministic verification failed — attempting in-merge fix (up to ${maxFixRetries} attempts)`); mergerLog.log(`${taskId}: deterministic verification failed — attempting in-merge fix (up to ${maxFixRetries} attempts)`);
await store.logEntry(taskId, `Verification failed during merge — attempting in-merge fix (up to ${maxFixRetries} attempts)`); await store.logEntry(taskId, `Verification failed during merge — attempting in-merge fix (up to ${maxFixRetries} attempts)`);
await store.appendAgentLog(
taskId,
`Verification failed — attempting in-merge fix (up to ${maxFixRetries} attempts)`,
"text",
undefined,
"merger",
);
// Extract failure context from the VerificationError // Extract failure context from the VerificationError
const failedResult = verificationErr.verificationResult.testResult?.success === false const failedResult = verificationErr.verificationResult.testResult?.success === false
@@ -2416,6 +2483,13 @@ export async function aiMergeTask(
const fixAttemptStartedAt = Date.now(); const fixAttemptStartedAt = Date.now();
mergerLog.log(`${taskId}: in-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`); mergerLog.log(`${taskId}: in-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
await store.logEntry(taskId, `In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`); await store.logEntry(taskId, `In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
await store.appendAgentLog(
taskId,
`In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`,
"text",
undefined,
"merger",
);
throwIfAborted(options.signal, taskId); throwIfAborted(options.signal, taskId);
fixSuccess = await attemptInMergeVerificationFix( fixSuccess = await attemptInMergeVerificationFix(
@@ -2438,11 +2512,25 @@ export async function aiMergeTask(
if (fixSuccess) { if (fixSuccess) {
mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`); mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`);
await store.logEntry(taskId, `[timing] In-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms — verification now passes`); await store.logEntry(taskId, `[timing] In-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms — verification now passes`);
await store.appendAgentLog(
taskId,
`In-merge verification fix succeeded on attempt ${fixAttempt}`,
"tool_result",
`${fixAttemptDurationMs}ms — verification now passes`,
"merger",
);
break; break;
} }
mergerLog.warn(`${taskId}: in-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`); mergerLog.warn(`${taskId}: in-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`);
await store.logEntry(taskId, `[timing] In-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`); await store.logEntry(taskId, `[timing] In-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`);
await store.appendAgentLog(
taskId,
`In-merge verification fix attempt ${fixAttempt} failed`,
"tool_error",
`${fixAttemptDurationMs}ms — verification still fails`,
"merger",
);
} }
if (fixSuccess) { if (fixSuccess) {
@@ -2467,6 +2555,13 @@ export async function aiMergeTask(
if (maxFixRetries > 0 && (effectiveTestCommand || effectiveBuildCommand)) { if (maxFixRetries > 0 && (effectiveTestCommand || effectiveBuildCommand)) {
mergerLog.log(`${taskId}: build verification failed — attempting in-merge fix`); mergerLog.log(`${taskId}: build verification failed — attempting in-merge fix`);
await store.logEntry(taskId, `Build verification failed during merge — attempting in-merge fix`); await store.logEntry(taskId, `Build verification failed during merge — attempting in-merge fix`);
await store.appendAgentLog(
taskId,
"Build verification failed — attempting in-merge fix",
"text",
undefined,
"merger",
);
const fixCommand = effectiveBuildCommand || effectiveTestCommand!; const fixCommand = effectiveBuildCommand || effectiveTestCommand!;
const fixType = effectiveBuildCommand ? "build" as const : "test" as const; const fixType = effectiveBuildCommand ? "build" as const : "test" as const;
@@ -2476,6 +2571,13 @@ export async function aiMergeTask(
const fixAttemptStartedAt = Date.now(); const fixAttemptStartedAt = Date.now();
mergerLog.log(`${taskId}: in-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`); mergerLog.log(`${taskId}: in-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
await store.logEntry(taskId, `In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`); await store.logEntry(taskId, `In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
await store.appendAgentLog(
taskId,
`In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`,
"text",
undefined,
"merger",
);
throwIfAborted(options.signal, taskId); throwIfAborted(options.signal, taskId);
fixSuccess = await attemptInMergeVerificationFix( fixSuccess = await attemptInMergeVerificationFix(
@@ -2498,9 +2600,23 @@ export async function aiMergeTask(
if (fixSuccess) { if (fixSuccess) {
mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`); mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`);
await store.logEntry(taskId, `[timing] In-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`); await store.logEntry(taskId, `[timing] In-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`);
await store.appendAgentLog(
taskId,
`In-merge verification fix succeeded on attempt ${fixAttempt}`,
"tool_result",
`${fixAttemptDurationMs}ms`,
"merger",
);
break; break;
} }
await store.logEntry(taskId, `[timing] In-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`); await store.logEntry(taskId, `[timing] In-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`);
await store.appendAgentLog(
taskId,
`In-merge verification fix attempt ${fixAttempt} failed`,
"tool_error",
`${fixAttemptDurationMs}ms — verification still fails`,
"merger",
);
} }
if (fixSuccess) { if (fixSuccess) {