diff --git a/src/browser/actions/promptComposer.ts b/src/browser/actions/promptComposer.ts index 966bebb71..cb27d982e 100644 --- a/src/browser/actions/promptComposer.ts +++ b/src/browser/actions/promptComposer.ts @@ -23,6 +23,58 @@ const ENTER_KEY_EVENT = { nativeVirtualKeyCode: 13, } as const; const ENTER_KEY_TEXT = "\r"; +const PROMPT_COMMIT_DIAGNOSTIC_PREFIX = "ORACLE_PROMPT_COMMIT_DIAGNOSTIC "; + +interface PromptCommitDiagnostics { + trustedPointClick: boolean; + record: (phase: string, status: string, actionKind: string) => void; + immediateProbe: (Runtime: ChromeClient["Runtime"]) => Promise; +} + +function createPromptCommitDiagnostics(logger: BrowserLogger): PromptCommitDiagnostics | undefined { + if (process.env.ORACLE_PROMPT_COMMIT_DIAGNOSTICS !== "1") return undefined; + let sequence = 0; + const record = (phase: string, status: string, actionKind: string) => { + try { + logger( + PROMPT_COMMIT_DIAGNOSTIC_PREFIX + + JSON.stringify({ phase, sequence: sequence++, status, actionKind }), + ); + } catch { + // Diagnostics must never affect submission behavior. + } + }; + return { + trustedPointClick: false, + record, + immediateProbe: async (Runtime) => { + let status = "evaluate_rejected"; + try { + const response = await Runtime.evaluate({ + expression: `(() => { + const __oraclePromptCommitDiagnosticProbe = true; + return { probe: __oraclePromptCommitDiagnosticProbe }; + })()`, + returnByValue: true, + }); + if (response.exceptionDetails) { + status = "protocol_exception"; + } else if ( + response.result?.value !== null && + typeof response.result?.value === "object" && + response.result.value.probe === true + ) { + status = "observed"; + } else { + status = "unexpected_result"; + } + } catch { + // Diagnostics must never affect submission behavior. + } + record("immediate_post_click_probe", status, "point_click"); + }, + }; +} export interface AttachmentReadyExpectation { name: string; @@ -45,6 +97,7 @@ export async function submitPrompt( logger: BrowserLogger, ): Promise { const { runtime, input } = deps; + const diagnostics = createPromptCommitDiagnostics(logger); await waitForDomReady(runtime, logger, deps.inputTimeoutMs ?? undefined); const encodedPrompt = JSON.stringify(prompt); @@ -219,6 +272,7 @@ export async function submitPrompt( logger, deps?.attachmentNames, deps?.attachmentTimeoutMs, + diagnostics, ); if (!clicked) { await input.dispatchKeyEvent({ @@ -245,6 +299,7 @@ export async function submitPrompt( commitTimeoutMs, logger, deps.baselineTurns ?? undefined, + diagnostics, ); } @@ -651,6 +706,7 @@ async function attemptSendButton( _logger?: BrowserLogger, attachmentNames?: AttachmentReadyInput[], attachmentTimeoutMs?: number | null, + diagnostics?: PromptCommitDiagnostics, ): Promise { const needAttachment = Array.isArray(attachmentNames) && attachmentNames.length > 0; const script = `(() => { @@ -719,7 +775,8 @@ async function attemptSendButton( typeof value.x === "number" && typeof value.y === "number" ) { - await clickTrustedPoint(Runtime, Input, value.x, value.y); + diagnostics?.record("candidate_selected", "selected", "point_click"); + await clickTrustedPoint(Runtime, Input, value.x, value.y, diagnostics); return true; } if (status === "clicked") { @@ -751,11 +808,15 @@ async function clickTrustedPoint( Input: ChromeClient["Input"], x: number, y: number, + diagnostics?: PromptCommitDiagnostics, ): Promise { if (Input && typeof Input.dispatchMouseEvent === "function") { await Input.dispatchMouseEvent({ type: "mouseMoved", x, y }); await Input.dispatchMouseEvent({ type: "mousePressed", x, y, button: "left", clickCount: 1 }); await Input.dispatchMouseEvent({ type: "mouseReleased", x, y, button: "left", clickCount: 1 }); + diagnostics?.record("trusted_click_dispatched", "dispatched", "point_click"); + if (diagnostics) diagnostics.trustedPointClick = true; + await diagnostics?.immediateProbe(Runtime); return; } await Runtime.evaluate({ @@ -787,6 +848,7 @@ async function verifyPromptCommitted( timeoutMs: number, logger?: BrowserLogger, baselineTurns?: number, + diagnostics?: PromptCommitDiagnostics, ): Promise { const deadline = Date.now() + timeoutMs; const encodedPrompt = JSON.stringify(prompt.trim()); @@ -901,6 +963,9 @@ async function verifyPromptCommitted( const baselineUnknown = typeof info?.baseline === "number" ? info.baseline < 0 : baselineLiteral < 0; if (matchesPrompt && (baselineUnknown || info?.hasNewTurn)) { + if (diagnostics?.trustedPointClick) { + diagnostics.record("commit_accepted", "accepted", "point_click"); + } return typeof turnsCount === "number" && Number.isFinite(turnsCount) ? turnsCount : null; } const fallbackCommit = @@ -908,6 +973,9 @@ async function verifyPromptCommitted( Boolean(info?.hasNewTurn) && ((info?.stopVisible ?? false) || info?.assistantVisible || info?.inConversation); if (fallbackCommit) { + if (diagnostics?.trustedPointClick) { + diagnostics.record("commit_accepted", "accepted", "point_click"); + } return typeof turnsCount === "number" && Number.isFinite(turnsCount) ? turnsCount : null; } await delay(100); @@ -918,10 +986,13 @@ async function verifyPromptCommitted( const probe = finalProbe && typeof finalProbe === "object" ? finalProbe : lastProbe; if (logger) { logger( - `Prompt commit check failed; latest state: ${probe ? JSON.stringify(probe) : "unavailable"}`, + `Prompt commit check failed; latest state: ${probe ? JSON.stringify(summarizeCommitProbe(probe)) : "unavailable"}`, ); await logDomFailure(Runtime, logger, "prompt-commit"); } + if (diagnostics?.trustedPointClick) { + diagnostics.record("commit_timeout", "timeout", "point_click"); + } if (prompt.trim().length >= 50_000) { throw new BrowserAutomationError( "Prompt did not appear in conversation before timeout (likely too large).", diff --git a/tests/browser/promptComposer.test.ts b/tests/browser/promptComposer.test.ts index 6bd8edb11..33e366209 100644 --- a/tests/browser/promptComposer.test.ts +++ b/tests/browser/promptComposer.test.ts @@ -324,4 +324,421 @@ describe("promptComposer", () => { vi.useRealTimers(); } }); + + const diagnosticPrefix = "ORACLE_PROMPT_COMMIT_DIAGNOSTIC "; + const diagnosticProbeMarker = "__oraclePromptCommitDiagnosticProbe"; + + function createPromptCommitFixture( + outcome: "accepted" | "timeout", + sendStatus: "point" | "clicked" | "missing" = "point", + immediateProbeOutcome: + | "expected" + | "rejected" + | "protocol_exception" + | "unexpected_result" = "expected", + ) { + let commitProbeCalls = 0; + const evaluate = vi.fn(async ({ expression }: { expression: string }) => { + if (expression.includes("document.readyState")) { + return { result: { value: { ready: true, composer: true, fileInput: false } } }; + } + if (expression.includes("focused: true")) { + return { result: { value: { focused: true } } }; + } + if (expression.includes("const selectors =")) { + return { + result: { + value: + sendStatus === "point" ? { status: "point", x: 120, y: 48 } : { status: sendStatus }, + }, + }; + } + if (expression.includes("editorText")) { + return { + result: { + value: { + editorText: "fixture prompt", + fallbackValue: "", + activeValue: "fixture prompt", + }, + }, + }; + } + if (expression.includes(diagnosticProbeMarker)) { + if (immediateProbeOutcome === "rejected") throw new Error("probe rejection text"); + if (immediateProbeOutcome === "protocol_exception") { + return { + exceptionDetails: { text: "protocol exception details" }, + result: { value: { probe: true } }, + }; + } + return { result: { value: { probe: immediateProbeOutcome === "expected" } } }; + } + if (expression.includes("normalizedPrompt")) { + commitProbeCalls += 1; + const accepted = outcome === "accepted" && commitProbeCalls > 1; + return { + result: { + value: { + baseline: 0, + turnsCount: accepted ? 1 : 0, + userMatched: accepted, + prefixMatched: accepted, + lastMatched: accepted, + hasNewTurn: accepted, + stopVisible: false, + assistantVisible: false, + composerCleared: accepted, + inConversation: accepted, + editorValue: `${diagnosticProbeMarker}-editor`, + fallbackValue: `${diagnosticProbeMarker}-fallback`, + lastTurn: `${diagnosticProbeMarker}-last-turn`, + href: `${diagnosticProbeMarker}-href`, + }, + }, + }; + } + return { result: { value: { editorText: "", fallbackValue: "", activeValue: "" } } }; + }); + const input = { + insertText: vi.fn().mockResolvedValue(undefined), + dispatchKeyEvent: vi.fn(), + dispatchMouseEvent: vi.fn().mockResolvedValue(undefined), + }; + const logger = Object.assign(vi.fn(), { verbose: false }); + return { + evaluate, + input, + logger, + get commitProbeCalls() { + return commitProbeCalls; + }, + }; + } + + function assertPointClickFixtureSanity( + fixture: ReturnType, + prompt: string, + ) { + expect(fixture.input.insertText).toHaveBeenCalledWith({ text: prompt }); + expect(fixture.input.dispatchKeyEvent).not.toHaveBeenCalled(); + expect(fixture.input.dispatchMouseEvent).toHaveBeenCalledTimes(3); + expect(fixture.input.dispatchMouseEvent.mock.calls.map(([event]) => event.type)).toEqual([ + "mouseMoved", + "mousePressed", + "mouseReleased", + ]); + expect(fixture.input.dispatchMouseEvent).toHaveBeenNthCalledWith(2, { + type: "mousePressed", + x: 120, + y: 48, + button: "left", + clickCount: 1, + }); + expect(fixture.input.dispatchMouseEvent).toHaveBeenNthCalledWith(3, { + type: "mouseReleased", + x: 120, + y: 48, + button: "left", + clickCount: 1, + }); + expect( + fixture.evaluate.mock.calls.filter(([args]) => args.expression.includes("const selectors =")), + ).toHaveLength(1); + expect(fixture.commitProbeCalls).toBeGreaterThanOrEqual(2); + } + + function assertPromptCommitDiagnosticRed( + fixture: ReturnType, + terminalPhase: "commit_accepted" | "commit_timeout", + prompt: string, + ) { + const lines = fixture.logger.mock.calls + .map(([line]) => String(line)) + .filter((line) => line.startsWith(diagnosticPrefix)); + const records = lines.map((line) => { + const payload = line.slice(diagnosticPrefix.length); + expect.soft(payload).not.toMatch(/^\s|\s$/); + try { + const record = JSON.parse(payload) as Record; + expect.soft(payload).toBe(JSON.stringify(record)); + return record; + } catch { + expect.soft(false).toBe(true); + return {}; + } + }); + const expectedPhases = [ + "candidate_selected", + "trusted_click_dispatched", + "immediate_post_click_probe", + terminalPhase, + ]; + expect.soft(records).toHaveLength(4); + expect.soft(records.map((record) => record.phase)).toEqual(expectedPhases); + for (const [index, record] of records.entries()) { + expect + .soft(Object.keys(record).sort()) + .toEqual(["actionKind", "phase", "sequence", "status"]); + expect.soft(record.sequence).toBe(index); + expect.soft(record.phase).toBe(expectedPhases[index]); + expect.soft(record.status).toMatch(/^[a-z][a-z0-9_-]{0,31}$/); + expect.soft(record.actionKind).toMatch(/^[a-z][a-z0-9_-]{0,31}$/); + expect.soft(JSON.stringify(record)).not.toContain(prompt); + expect + .soft(JSON.stringify(record)) + .not.toMatch(/editor|fallback|last[-_]?turn|href|selector|profile|token/i); + } + + const expressions = fixture.evaluate.mock.calls.map(([args]) => args.expression); + const immediateProbeExpressions = expressions.filter((expression) => + expression.includes(diagnosticProbeMarker), + ); + expect.soft(immediateProbeExpressions).toHaveLength(1); + const immediateProbeExpression = immediateProbeExpressions[0]; + if (immediateProbeExpression) { + expect.soft(immediateProbeExpression).not.toContain("dispatchMouseEvent"); + expect.soft(immediateProbeExpression).not.toContain("dispatchKeyEvent"); + } + expect + .soft(expressions.filter((expression) => expression.includes("normalizedPrompt")).length) + .toBeGreaterThan(1); + return records; + } + + test.each([ + ["Runtime.evaluate rejects or throws", "rejected", "evaluate_rejected"], + ["Runtime.evaluate resolves with exceptionDetails", "protocol_exception", "protocol_exception"], + [ + "evaluation resolves without exceptionDetails but lacks exact result.value.probe === true", + "unexpected_result", + "unexpected_result", + ], + ] as const)("causal RED: %s", async (_name, immediateProbeOutcome, expectedStatus) => { + vi.useFakeTimers(); + vi.stubEnv("ORACLE_PROMPT_COMMIT_DIAGNOSTICS", "1"); + try { + const prompt = "fixture prompt"; + const fixture = createPromptCommitFixture("accepted", "point", immediateProbeOutcome); + const submission = submitPrompt( + { runtime: fixture as never, input: fixture.input as never, baselineTurns: 0 }, + prompt, + fixture.logger as never, + ); + + await vi.advanceTimersByTimeAsync(499); + expect(fixture.input.dispatchMouseEvent).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1); + await vi.advanceTimersByTimeAsync(100); + await expect(submission).resolves.toBe(1); + + const records = assertPromptCommitDiagnosticRed(fixture, "commit_accepted", prompt); + expect(records[2]?.status).toBe(expectedStatus); + expect(fixture.logger.mock.calls.flat().join(" ")).not.toMatch( + /exceptionDetails|protocol exception details|probe rejection text|probe:false|probe: false/i, + ); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + test("causal RED: immediate-probe logger failure does not interfere", async () => { + vi.useFakeTimers(); + vi.stubEnv("ORACLE_PROMPT_COMMIT_DIAGNOSTICS", "1"); + try { + const fixture = createPromptCommitFixture("accepted"); + const deliveredLines: string[] = []; + fixture.logger.mockImplementation((line) => { + const text = String(line); + if (text.startsWith(diagnosticPrefix)) { + const record = JSON.parse(text.slice(diagnosticPrefix.length)) as { phase?: string }; + if (record.phase === "immediate_post_click_probe") throw new Error("logger failure"); + deliveredLines.push(text); + } + }); + const submission = submitPrompt( + { runtime: fixture as never, input: fixture.input as never, baselineTurns: 0 }, + "fixture prompt", + fixture.logger as never, + ); + + await vi.advanceTimersByTimeAsync(499); + expect(fixture.input.dispatchMouseEvent).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1); + await vi.advanceTimersByTimeAsync(100); + await expect(submission).resolves.toBe(1); + + const records = deliveredLines.map( + (line) => JSON.parse(line.slice(diagnosticPrefix.length)) as Record, + ); + expect(records.map((record) => record.phase)).toEqual([ + "candidate_selected", + "trusted_click_dispatched", + "commit_accepted", + ]); + expect(records.at(-1)?.status).toBe("accepted"); + expect(fixture.input.dispatchKeyEvent).not.toHaveBeenCalled(); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + test("causal RED: accepted point-click commit emits bounded diagnostics", async () => { + vi.useFakeTimers(); + vi.stubEnv("ORACLE_PROMPT_COMMIT_DIAGNOSTICS", "1"); + try { + const prompt = "fixture prompt"; + const fixture = createPromptCommitFixture("accepted"); + const submission = submitPrompt( + { runtime: fixture as never, input: fixture.input as never, baselineTurns: 0 }, + prompt, + fixture.logger as never, + ); + + await vi.advanceTimersByTimeAsync(499); + expect(fixture.input.dispatchMouseEvent).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1); + await vi.advanceTimersByTimeAsync(100); + await expect(submission).resolves.toBe(1); + + assertPointClickFixtureSanity(fixture, prompt); + assertPromptCommitDiagnosticRed(fixture, "commit_accepted", prompt); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + test("causal RED: timeout diagnostics redact the raw probe", async () => { + vi.useFakeTimers(); + vi.stubEnv("ORACLE_PROMPT_COMMIT_DIAGNOSTICS", "1"); + try { + const prompt = "fixture prompt"; + const fixture = createPromptCommitFixture("timeout"); + const submission = submitPrompt( + { runtime: fixture as never, input: fixture.input as never, baselineTurns: 0 }, + prompt, + fixture.logger as never, + ); + const rejection = expect(submission).rejects.toMatchObject({ + name: "BrowserAutomationError", + details: { code: "prompt-commit-timeout" }, + }); + + await vi.advanceTimersByTimeAsync(499); + expect(fixture.input.dispatchMouseEvent).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1); + await vi.advanceTimersByTimeAsync(60_100); + await rejection; + + assertPointClickFixtureSanity(fixture, prompt); + expect.soft(fixture.logger.mock.calls.flat().join(" ")).not.toContain(diagnosticProbeMarker); + assertPromptCommitDiagnosticRed(fixture, "commit_timeout", prompt); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + test("does not emit diagnostics for DOM-click fallback", async () => { + vi.useFakeTimers(); + vi.stubEnv("ORACLE_PROMPT_COMMIT_DIAGNOSTICS", "1"); + try { + const fixture = createPromptCommitFixture("accepted", "clicked"); + const submission = submitPrompt( + { runtime: fixture as never, input: fixture.input as never, baselineTurns: 0 }, + "fixture prompt", + fixture.logger as never, + ); + + await vi.advanceTimersByTimeAsync(499); + await vi.advanceTimersByTimeAsync(1); + await vi.advanceTimersByTimeAsync(100); + await expect(submission).resolves.toBe(1); + + expect(fixture.input.dispatchMouseEvent).not.toHaveBeenCalled(); + expect(fixture.input.dispatchKeyEvent).not.toHaveBeenCalled(); + expect( + fixture.evaluate.mock.calls.filter(([args]) => + args.expression.includes(diagnosticProbeMarker), + ), + ).toHaveLength(0); + expect( + fixture.logger.mock.calls + .map(([line]) => String(line)) + .some((line) => line.startsWith(diagnosticPrefix)), + ).toBe(false); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + test("does not emit diagnostics for missing-button Enter fallback", async () => { + vi.useFakeTimers(); + vi.stubEnv("ORACLE_PROMPT_COMMIT_DIAGNOSTICS", "1"); + try { + const fixture = createPromptCommitFixture("accepted", "missing"); + const submission = submitPrompt( + { runtime: fixture as never, input: fixture.input as never, baselineTurns: 0 }, + "fixture prompt", + fixture.logger as never, + ); + + await vi.advanceTimersByTimeAsync(499); + await vi.advanceTimersByTimeAsync(1); + await vi.advanceTimersByTimeAsync(100); + await expect(submission).resolves.toBe(1); + + expect(fixture.input.dispatchMouseEvent).not.toHaveBeenCalled(); + expect(fixture.input.dispatchKeyEvent).toHaveBeenCalledTimes(2); + expect( + fixture.evaluate.mock.calls.filter(([args]) => + args.expression.includes(diagnosticProbeMarker), + ), + ).toHaveLength(0); + expect( + fixture.logger.mock.calls + .map(([line]) => String(line)) + .some((line) => line.startsWith(diagnosticPrefix)), + ).toBe(false); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + test("does not emit prefixed diagnostics when the env variable is unset", async () => { + vi.useFakeTimers(); + const previous = process.env.ORACLE_PROMPT_COMMIT_DIAGNOSTICS; + delete process.env.ORACLE_PROMPT_COMMIT_DIAGNOSTICS; + try { + const prompt = "fixture prompt"; + const fixture = createPromptCommitFixture("accepted"); + const submission = submitPrompt( + { runtime: fixture as never, input: fixture.input as never, baselineTurns: 0 }, + prompt, + fixture.logger as never, + ); + + await vi.advanceTimersByTimeAsync(499); + expect(fixture.input.dispatchMouseEvent).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1); + await vi.advanceTimersByTimeAsync(100); + await expect(submission).resolves.toBe(1); + + assertPointClickFixtureSanity(fixture, prompt); + expect( + fixture.logger.mock.calls + .map(([line]) => String(line)) + .some((line) => line.startsWith(diagnosticPrefix)), + ).toBe(false); + } finally { + if (previous === undefined) delete process.env.ORACLE_PROMPT_COMMIT_DIAGNOSTICS; + else process.env.ORACLE_PROMPT_COMMIT_DIAGNOSTICS = previous; + vi.useRealTimers(); + } + }); });