From 604dc0fb995a69776105254cecb70785041304fe Mon Sep 17 00:00:00 2001 From: Arun Sunny Date: Mon, 3 Aug 2026 11:15:00 +0530 Subject: [PATCH] fix(extension): stop iframe hangs and add debug mode chrome.scripting.executeScript({ allFrames: true }) could block forever on unresponsive cross-origin frames; add timeouts with main-frame fallbacks, raise snapshot depth for Draft.js widgets, and ship a debug-log UI for runs. Co-authored-by: Cursor --- runners/extension/agentContext.js | 35 +- runners/extension/chatLocator.js | 599 +++++++++++++++---------- runners/extension/debugLog.js | 118 +++++ runners/extension/domActions.js | 158 +++++-- runners/extension/domTarget.js | 55 ++- runners/extension/frameDiscovery.js | 61 ++- runners/extension/frame_actuate.js | 31 +- runners/extension/frame_snapshot.js | 2 +- runners/extension/llm.js | 19 +- runners/extension/llmUiActions.js | 36 +- runners/extension/orchestrator.js | 51 ++- runners/extension/popup.html | 62 +++ runners/extension/popup.js | 26 ++ runners/extension/responseExtractor.js | 58 ++- runners/extension/service_worker.js | 45 ++ 15 files changed, 1052 insertions(+), 304 deletions(-) create mode 100644 runners/extension/debugLog.js diff --git a/runners/extension/agentContext.js b/runners/extension/agentContext.js index 1ebfb3a4..92cb0312 100644 --- a/runners/extension/agentContext.js +++ b/runners/extension/agentContext.js @@ -1,6 +1,7 @@ import { callLlm } from "./llm.js"; import { collectFrames } from "./frameDiscovery.js"; import { state } from "./state.js"; +import { dbg } from "./debugLog.js"; /** * Merge homepage agent context with optional Advanced "business use case" text. @@ -12,15 +13,40 @@ export function mergeBusinessContext(agentContext, extraBusinessUseCase) { return a || b || ""; } +const CONTEXT_TIMEOUT_MS = 45_000; + /** * Use the reader LLM to infer what the on-page chat agent is from DOM snapshots. */ export async function summarizeAgentFromTab(tabId, readerCfg, siteUrl = "") { + dbg("context", "summarizeAgentFromTab called", { tabId, siteUrl: String(siteUrl).slice(0, 120) }); + + return Promise.race([ + _summarizeAgentFromTabInner(tabId, readerCfg, siteUrl), + new Promise((_, reject) => + setTimeout( + () => + reject( + new Error(`Agent context detection timed out after ${CONTEXT_TIMEOUT_MS / 1000}s`) + ), + CONTEXT_TIMEOUT_MS + ) + ), + ]); +} + +async function _summarizeAgentFromTabInner(tabId, readerCfg, siteUrl) { let frames = []; try { frames = await collectFrames(tabId); - } catch { - // proceed with empty frames; prompt will note missing snapshot + dbg("context", "Collected frames for agent summary", { + count: frames.length, + chatFrames: frames.filter((f) => (f.chatScore || 0) > 0).length, + }); + } catch (e) { + dbg("context", "Frame collection failed — proceeding with empty frames", { + error: e instanceof Error ? e.message : String(e), + }); } const top = frames.find((f) => f.frameId === 0); @@ -78,8 +104,13 @@ export async function summarizeAgentFromTab(tabId, readerCfg, siteUrl = "") { const summary = typeof out?.summary === "string" ? out.summary.trim() : ""; if (!summary) { + dbg("context", "Agent summary LLM returned empty summary"); throw new Error("Agent summary LLM returned empty summary"); } + dbg("context", "Agent summary generated", { + summaryLen: summary.length, + preview: summary.slice(0, 300), + }); return summary; } diff --git a/runners/extension/chatLocator.js b/runners/extension/chatLocator.js index 22b26680..4b6eafe4 100644 --- a/runners/extension/chatLocator.js +++ b/runners/extension/chatLocator.js @@ -3,6 +3,7 @@ import { state } from "./state.js"; import { actClickSelector, actVerifyInputVisible, preparePageForChat } from "./domActions.js"; import { collectFrames } from "./frameDiscovery.js"; import { aiUiNextAction } from "./llmUiActions.js"; +import { dbg } from "./debugLog.js"; /** * Locate an open chat widget input using accessibility-tree-first LLM actions. @@ -23,6 +24,8 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { const maxAiAttempts = Math.max(2, Math.min(12, Number(options.maxAiAttempts ?? 8))); if (state.OPFOR_STOP) return { ok: false, error: "Run stopped." }; + dbg("locate", "locateChatWidget called", { tabId, openWidget, maxAiAttempts }); + if (openWidget) { await preparePageForChat(tabId); } @@ -37,14 +40,43 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { // open yet, or only ambiguous/low-score inputs present). try { const detFrames = await collectFrames(tabId); + dbg("locate", "Deterministic fast-path: collected frames", { + count: detFrames.length, + frames: detFrames.map((f) => ({ + frameId: f.frameId, + url: String(f.frameUrl || "").slice(0, 120), + chatScore: f.chatScore, + bestInputSelector: f.bestInputSelector || null, + bestInputScore: f.bestInputScore, + bestSendSelector: f.bestSendSelector || null, + })), + }); const ranked = detFrames .filter((f) => f.bestInputSelector && (f.bestInputScore || 0) >= 12) .sort((a, b) => (b.bestInputScore || 0) - (a.bestInputScore || 0)); + dbg("locate", "High-confidence inputs after filter (score>=12)", { + count: ranked.length, + selectors: ranked.map((f) => ({ + frameId: f.frameId, + sel: f.bestInputSelector, + score: f.bestInputScore, + })), + }); for (const f of ranked) { if (state.OPFOR_STOP) return { ok: false, error: "Run stopped." }; const visible = await actVerifyInputVisible(tabId, f.frameId, f.bestInputSelector); + dbg("locate", `Verify input visible: ${visible ? "YES" : "NO"}`, { + frameId: f.frameId, + selector: f.bestInputSelector, + visible, + }); if (!visible) continue; const siteSnapshot = detFrames.find((x) => x.frameId === 0)?.snapshot || f.snapshot || ""; + dbg("locate", "Fast-path SUCCESS — using deterministic input", { + frameId: f.frameId, + selector: f.bestInputSelector, + sendSelector: f.bestSendSelector || null, + }); return { ok: true, plan: { @@ -58,269 +90,330 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { siteSnapshot, }; } - } catch { - /* fall through to the LLM planner */ + dbg("locate", "Fast-path miss — falling through to LLM planner"); + } catch (e) { + dbg("locate", "Fast-path error, falling through to LLM planner", { + error: e instanceof Error ? e.message : String(e), + }); } + const AX_COLLECT_TIMEOUT_MS = 15_000; const collectAxSnapshots = async () => { let results; try { - results = await chrome.scripting.executeScript({ - target: { tabId, allFrames: true }, - func: () => { - const MAX_NODES = 1400; - const MAX_LINES = 700; - const MAX_NAME = 140; - - const escapeCss = (v) => { - if (typeof CSS !== "undefined" && CSS.escape) return CSS.escape(String(v)); - return String(v).replace(/["\\]/g, "\\$&"); - }; + results = await Promise.race([ + chrome.scripting.executeScript({ + target: { tabId, allFrames: true }, + func: () => { + const MAX_NODES = 1400; + const MAX_LINES = 700; + const MAX_NAME = 140; + + const escapeCss = (v) => { + if (typeof CSS !== "undefined" && CSS.escape) return CSS.escape(String(v)); + return String(v).replace(/["\\]/g, "\\$&"); + }; - const short = (s, n) => { - const str = String(s || ""); - return str.length > n ? str.slice(0, n) : str; - }; + const short = (s, n) => { + const str = String(s || ""); + return str.length > n ? str.slice(0, n) : str; + }; - const isVisible = (el) => { - if (!(el instanceof Element)) return false; - if (!el.isConnected) return false; - const rect = el.getBoundingClientRect?.(); - if (!rect || rect.width <= 0 || rect.height <= 0) return false; - const style = window.getComputedStyle(el); - if (style.display === "none") return false; - if (style.visibility === "hidden") return false; - if (style.opacity === "0") return false; - return true; - }; + const isVisible = (el) => { + if (!(el instanceof Element)) return false; + if (!el.isConnected) return false; + const rect = el.getBoundingClientRect?.(); + if (!rect || rect.width <= 0 || rect.height <= 0) return false; + const style = window.getComputedStyle(el); + if (style.display === "none") return false; + if (style.visibility === "hidden") return false; + if (style.opacity === "0") return false; + return true; + }; - const selectorFromEl = (el) => { - if (!(el instanceof Element)) return null; - const testid = el.getAttribute("data-testid"); - if (testid) return `[data-testid="${escapeCss(testid)}"]`; - const aria = el.getAttribute("aria-label"); - if (aria) return `${el.tagName.toLowerCase()}[aria-label="${escapeCss(aria)}"]`; - const id = el.getAttribute("id"); - if (id) return `#${escapeCss(id)}`; - const name = el.getAttribute("name"); - if (name) return `${el.tagName.toLowerCase()}[name="${escapeCss(name)}"]`; - const ph = el.getAttribute("placeholder"); - if (ph) return `${el.tagName.toLowerCase()}[placeholder="${escapeCss(ph)}"]`; - - try { - const parts = []; - let cur = el; - for (let i = 0; i < 4 && cur && cur instanceof Element && cur.tagName; i++) { - const tag = cur.tagName.toLowerCase(); - const parent = cur.parentElement; - if (!parent) { - parts.unshift(tag); - break; + const selectorFromEl = (el) => { + if (!(el instanceof Element)) return null; + const testid = el.getAttribute("data-testid"); + if (testid) return `[data-testid="${escapeCss(testid)}"]`; + const aria = el.getAttribute("aria-label"); + if (aria) return `${el.tagName.toLowerCase()}[aria-label="${escapeCss(aria)}"]`; + const id = el.getAttribute("id"); + if (id) return `#${escapeCss(id)}`; + const name = el.getAttribute("name"); + if (name) return `${el.tagName.toLowerCase()}[name="${escapeCss(name)}"]`; + const ph = el.getAttribute("placeholder"); + if (ph) return `${el.tagName.toLowerCase()}[placeholder="${escapeCss(ph)}"]`; + + try { + const parts = []; + let cur = el; + for (let i = 0; i < 4 && cur && cur instanceof Element && cur.tagName; i++) { + const tag = cur.tagName.toLowerCase(); + const parent = cur.parentElement; + if (!parent) { + parts.unshift(tag); + break; + } + const sibs = Array.from(parent.children).filter( + (c) => c instanceof Element && c.tagName.toLowerCase() === tag + ); + const idx = Math.max(1, sibs.indexOf(cur) + 1); + parts.unshift(`${tag}:nth-of-type(${idx})`); + if (cur.id) break; + cur = parent; } - const sibs = Array.from(parent.children).filter( - (c) => c instanceof Element && c.tagName.toLowerCase() === tag - ); - const idx = Math.max(1, sibs.indexOf(cur) + 1); - parts.unshift(`${tag}:nth-of-type(${idx})`); - if (cur.id) break; - cur = parent; + const sel = parts.join(" > "); + if (sel && document.querySelector(sel)) return sel; + } catch { + /* swallowed */ } - const sel = parts.join(" > "); - if (sel && document.querySelector(sel)) return sel; - } catch { - /* swallowed */ - } - return el.tagName.toLowerCase(); - }; + return el.tagName.toLowerCase(); + }; - const roleForEl = (el) => { - if (!(el instanceof Element)) return ""; - const ariaRole = (el.getAttribute("role") || "").trim().toLowerCase(); - if (ariaRole) return ariaRole; - const tag = el.tagName.toLowerCase(); - if (tag === "textarea") return "textbox"; - if (tag === "input") { - const t = (el.getAttribute("type") || "text").toLowerCase(); - if (t === "search") return "searchbox"; - if (t === "button" || t === "submit") return "button"; - return "textbox"; - } - if (tag === "button") return "button"; - if (tag === "a") return "link"; - if (tag === "select") return "combobox"; - if (tag === "summary") return "button"; - if (el.isContentEditable) return "textbox"; - return tag; - }; + const roleForEl = (el) => { + if (!(el instanceof Element)) return ""; + const ariaRole = (el.getAttribute("role") || "").trim().toLowerCase(); + if (ariaRole) return ariaRole; + const tag = el.tagName.toLowerCase(); + if (tag === "textarea") return "textbox"; + if (tag === "input") { + const t = (el.getAttribute("type") || "text").toLowerCase(); + if (t === "search") return "searchbox"; + if (t === "button" || t === "submit") return "button"; + return "textbox"; + } + if (tag === "button") return "button"; + if (tag === "a") return "link"; + if (tag === "select") return "combobox"; + if (tag === "summary") return "button"; + if (el.isContentEditable) return "textbox"; + return tag; + }; - const nameForEl = (el) => { - if (!(el instanceof Element)) return ""; - const aria = el.getAttribute("aria-label"); - if (aria) return aria; - const title = el.getAttribute("title"); - if (title) return title; - const alt = el.getAttribute("alt"); - if (alt) return alt; - const ph = el.getAttribute("placeholder"); - if (ph) return ph; - const tc = (el.textContent || "").replace(/\s+/g, " ").trim(); - if (tc) return tc; - return ""; - }; + const nameForEl = (el) => { + if (!(el instanceof Element)) return ""; + const aria = el.getAttribute("aria-label"); + if (aria) return aria; + const title = el.getAttribute("title"); + if (title) return title; + const alt = el.getAttribute("alt"); + if (alt) return alt; + const ph = el.getAttribute("placeholder"); + if (ph) return ph; + const tc = (el.textContent || "").replace(/\s+/g, " ").trim(); + if (tc) return tc; + return ""; + }; - const isNavigatingLink = (el) => { - if (!(el instanceof HTMLAnchorElement)) return false; - const raw = (el.getAttribute("href") || "").trim(); - if (!raw) return false; - if (raw.startsWith("#")) return false; - if (/^javascript:/i.test(raw)) return false; - if (/^(https?:|\/)/i.test(raw)) return true; - return false; - }; + const isNavigatingLink = (el) => { + if (!(el instanceof HTMLAnchorElement)) return false; + const raw = (el.getAttribute("href") || "").trim(); + if (!raw) return false; + if (raw.startsWith("#")) return false; + if (/^javascript:/i.test(raw)) return false; + if (/^(https?:|\/)/i.test(raw)) return true; + return false; + }; - const isInteractive = (el, role) => { - if (!(el instanceof Element)) return false; - const tag = el.tagName.toLowerCase(); - if (tag === "button" || tag === "textarea" || tag === "select") return true; - if (tag === "input") return true; - if (tag === "a") return true; - if (role === "button" || role === "link" || role === "textbox" || role === "combobox") - return true; - if (el.isContentEditable) return true; - if (typeof el.onclick === "function") return true; - if (el.hasAttribute("tabindex")) return true; - return false; - }; + const isInteractive = (el, role) => { + if (!(el instanceof Element)) return false; + const tag = el.tagName.toLowerCase(); + if (tag === "button" || tag === "textarea" || tag === "select") return true; + if (tag === "input") return true; + if (tag === "a") return true; + if (role === "button" || role === "link" || role === "textbox" || role === "combobox") + return true; + if (el.isContentEditable) return true; + if (typeof el.onclick === "function") return true; + if (el.hasAttribute("tabindex")) return true; + return false; + }; - const getShadowRoot = (el) => { - if (el?.shadowRoot) return el.shadowRoot; - if (el?.__closedShadowRoot) return el.__closedShadowRoot; - return null; - }; + const getShadowRoot = (el) => { + if (el?.shadowRoot) return el.shadowRoot; + if (el?.__closedShadowRoot) return el.__closedShadowRoot; + return null; + }; - function* walkNodes(root) { - const stack = [root]; - while (stack.length) { - const node = stack.pop(); - if (!node) continue; - yield node; - - if (node instanceof Element) { - const shadow = getShadowRoot(node); - if (shadow) stack.push(shadow); - const children = node.children; - for (let i = children.length - 1; i >= 0; i--) stack.push(children[i]); - continue; - } + function* walkNodes(root) { + const stack = [root]; + while (stack.length) { + const node = stack.pop(); + if (!node) continue; + yield node; + + if (node instanceof Element) { + const shadow = getShadowRoot(node); + if (shadow) stack.push(shadow); + const children = node.children; + for (let i = children.length - 1; i >= 0; i--) stack.push(children[i]); + continue; + } - if ( - node instanceof ShadowRoot || - node instanceof Document || - node instanceof DocumentFragment - ) { - const children = node.children || node.childNodes; - if (!children) continue; - for (let i = children.length - 1; i >= 0; i--) stack.push(children[i]); + if ( + node instanceof ShadowRoot || + node instanceof Document || + node instanceof DocumentFragment + ) { + const children = node.children || node.childNodes; + if (!children) continue; + for (let i = children.length - 1; i >= 0; i--) stack.push(children[i]); + } } } - } - const deepPathSelector = (el) => { - if (!(el instanceof Element)) return null; - const parts = [selectorFromEl(el)]; - let cur = el; - while (cur) { - const root = cur.getRootNode?.(); - if (root instanceof ShadowRoot) { - const hostSel = selectorFromEl(root.host); - parts.unshift(`shadow(${hostSel})`); - cur = root.host; - continue; + const deepPathSelector = (el) => { + if (!(el instanceof Element)) return null; + const parts = [selectorFromEl(el)]; + let cur = el; + while (cur) { + const root = cur.getRootNode?.(); + if (root instanceof ShadowRoot) { + const hostSel = selectorFromEl(root.host); + parts.unshift(`shadow(${hostSel})`); + cur = root.host; + continue; + } + break; } - break; - } - return parts.join(" >> "); - }; - - const lines = []; - const push = (line) => { - if (lines.length >= MAX_LINES) return; - lines.push(line); - }; - - push(`frame_url="${location.href}"`); - const title = document.title || ""; - if (title) push(`title="${short(title, 140)}"`); + return parts.join(" >> "); + }; - // Prioritize inputs first so we don't truncate them away. - const inputs = []; - const others = []; - let seen = 0; + const lines = []; + const push = (line) => { + if (lines.length >= MAX_LINES) return; + lines.push(line); + }; - for (const node of walkNodes(document)) { - if (!(node instanceof Element)) continue; - if (!isVisible(node)) continue; - const role = roleForEl(node); - if (!isInteractive(node, role)) continue; + push(`frame_url="${location.href}"`); + const title = document.title || ""; + if (title) push(`title="${short(title, 140)}"`); + + // Prioritize inputs first so we don't truncate them away. + const inputs = []; + const others = []; + let seen = 0; + + for (const node of walkNodes(document)) { + if (!(node instanceof Element)) continue; + if (!isVisible(node)) continue; + const role = roleForEl(node); + if (!isInteractive(node, role)) continue; + + const entry = { + el: node, + role, + }; + const roleKey = String(role || "").toLowerCase(); + const tag = node.tagName.toLowerCase(); + const isInput = + roleKey === "textbox" || + roleKey === "combobox" || + roleKey === "searchbox" || + tag === "textarea" || + tag === "input" || + node.isContentEditable; + (isInput ? inputs : others).push(entry); + seen++; + if (seen >= MAX_NODES * 2) break; + } - const entry = { - el: node, - role, + const emit = (entry) => { + const el = entry.el; + const role = entry.role; + const name = short(nameForEl(el), MAX_NAME).replace(/\n/g, " "); + const sel = deepPathSelector(el) || selectorFromEl(el); + const href = + el instanceof HTMLAnchorElement ? short(el.getAttribute("href") || "", 160) : ""; + const nav = + el instanceof HTMLAnchorElement && isNavigatingLink(el) ? " nav=true" : ""; + const disabled = + el instanceof HTMLButtonElement && el.disabled ? " disabled=true" : ""; + push( + `- role=${role || "unknown"} name="${name}" selector="${sel}"${ + href ? ` href="${href}"` : "" + }${nav}${disabled}` + ); }; - const roleKey = String(role || "").toLowerCase(); - const tag = node.tagName.toLowerCase(); - const isInput = - roleKey === "textbox" || - roleKey === "combobox" || - roleKey === "searchbox" || - tag === "textarea" || - tag === "input" || - node.isContentEditable; - (isInput ? inputs : others).push(entry); - seen++; - if (seen >= MAX_NODES * 2) break; - } - const emit = (entry) => { - const el = entry.el; - const role = entry.role; - const name = short(nameForEl(el), MAX_NAME).replace(/\n/g, " "); - const sel = deepPathSelector(el) || selectorFromEl(el); - const href = - el instanceof HTMLAnchorElement ? short(el.getAttribute("href") || "", 160) : ""; - const nav = el instanceof HTMLAnchorElement && isNavigatingLink(el) ? " nav=true" : ""; - const disabled = el instanceof HTMLButtonElement && el.disabled ? " disabled=true" : ""; - push( - `- role=${role || "unknown"} name="${name}" selector="${sel}"${ - href ? ` href="${href}"` : "" - }${nav}${disabled}` - ); - }; - - let emitted = 0; - for (const e of inputs) { - if (lines.length >= MAX_LINES) break; - emit(e); - emitted++; - if (emitted >= MAX_NODES) break; - } - for (const e of others) { - if (lines.length >= MAX_LINES) break; - emit(e); - emitted++; - if (emitted >= MAX_NODES) break; - } + let emitted = 0; + for (const e of inputs) { + if (lines.length >= MAX_LINES) break; + emit(e); + emitted++; + if (emitted >= MAX_NODES) break; + } + for (const e of others) { + if (lines.length >= MAX_LINES) break; + emit(e); + emitted++; + if (emitted >= MAX_NODES) break; + } - return { - frameUrl: location.href, - axSnapshot: lines.join("\n").slice(0, 60_000), - }; - }, - }); + return { + frameUrl: location.href, + axSnapshot: lines.join("\n").slice(0, 60_000), + }; + }, + }), + new Promise((_, reject) => + setTimeout( + () => reject(new Error(`AX snapshot timed out after ${AX_COLLECT_TIMEOUT_MS}ms`)), + AX_COLLECT_TIMEOUT_MS + ) + ), + ]); } catch (err) { - console.error("[chatLocator] executeScript failed:", err); - return []; + dbg("locate", "collectAxSnapshots failed, trying main frame only", { + error: err instanceof Error ? err.message : String(err), + }); + try { + results = await Promise.race([ + chrome.scripting.executeScript({ + target: { tabId, frameIds: [0] }, + func: () => { + const lines = [`frame_url="${location.href}"`]; + const title = document.title || ""; + if (title) lines.push(`title="${title.slice(0, 140)}"`); + for (const el of document.querySelectorAll( + "textarea, input, [contenteditable='true'], [role='textbox'], button, [role='button'], a, select" + )) { + if (!(el instanceof Element)) continue; + const rect = el.getBoundingClientRect?.(); + if (!rect || rect.width <= 0 || rect.height <= 0) continue; + const style = window.getComputedStyle(el); + if ( + style.display === "none" || + style.visibility === "hidden" || + style.opacity === "0" + ) + continue; + const tag = el.tagName.toLowerCase(); + const role = el.getAttribute("role") || ""; + const name = ( + el.getAttribute("aria-label") || + el.getAttribute("placeholder") || + el.textContent || + "" + ) + .replace(/\s+/g, " ") + .trim() + .slice(0, 140); + lines.push(`- role=${role || tag} name="${name}" selector="${tag}"`); + if (lines.length > 500) break; + } + return { frameUrl: location.href, axSnapshot: lines.join("\n").slice(0, 60_000) }; + }, + }), + new Promise((_, reject) => + setTimeout(() => reject(new Error("main-frame AX fallback timed out")), 10_000) + ), + ]); + } catch { + dbg("locate", "collectAxSnapshots main-frame fallback also failed"); + return []; + } } const mapped = (results || []).map((r) => ({ @@ -395,6 +488,12 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { ), ].join("\n\n"); + dbg("locate", `LLM planner attempt ${attempt + 1}/${maxAiAttempts}`, { + frameCount: frames.length, + snapshotLen: combinedSnapshot.length, + lastErr: lastErr || null, + }); + const decision = await aiUiNextAction(readerCfg, { frameUrl: frames.find((f) => f.frameId === 0)?.frameUrl || "", snapshot: combinedSnapshot, @@ -403,10 +502,27 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { clickedLaunchers, }); + dbg("locate", `LLM decision: ${decision?.action || "null"}`, { + action: decision?.action, + inputSelector: decision?.inputSelector, + launcherSelector: decision?.launcherSelector, + submit: decision?.submit, + confidence: decision?.confidence, + notes: decision?.notes, + }); + if (decision?.action === "set_input" && typeof decision.inputSelector === "string") { - // We don't know which frame the selector belongs to; verify across frames. for (const f of frames) { const visible = await actVerifyInputVisible(tabId, f.frameId, decision.inputSelector); + dbg( + "locate", + `Verify LLM-picked input in frame ${f.frameId}: ${visible ? "VISIBLE" : "not found"}`, + { + frameId: f.frameId, + selector: decision.inputSelector, + visible, + } + ); if (visible) { chosen = { frameId: f.frameId, @@ -418,8 +534,12 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { break; } } - if (chosen) break; + if (chosen) { + dbg("locate", "LLM set_input SUCCESS", chosen); + break; + } lastErr = "LLM picked input but it was not visible in any frame."; + dbg("locate", lastErr, { selector: decision.inputSelector }); continue; } @@ -469,6 +589,11 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { ]; for (const f of ordered) { const res = await actClickSelector(tabId, f.frameId, decision.launcherSelector); + dbg("locate", `Click launcher in frame ${f.frameId}: ${res?.ok ? "OK" : "FAIL"}`, { + frameId: f.frameId, + selector: decision.launcherSelector, + result: res, + }); if (res?.ok) { clicked = true; clickedLaunchers.push(decision.launcherSelector); @@ -477,6 +602,7 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { } if (!clicked) { lastErr = "LLM picked launcher but click failed in all frames."; + dbg("locate", lastErr); } await sleep(2200); continue; @@ -496,6 +622,7 @@ export async function locateChatWidget(tabId, readerCfg, options = {}) { } if (!chosen?.inputSelector) { + dbg("locate", "FAILED — no chat input found after all attempts", { lastErr }); return { ok: false, error: lastErr || "Could not find (or open) the chat input." }; } diff --git a/runners/extension/debugLog.js b/runners/extension/debugLog.js new file mode 100644 index 00000000..58ffdba1 --- /dev/null +++ b/runners/extension/debugLog.js @@ -0,0 +1,118 @@ +/** + * Debug logging for the OPFOR browser extension. + * + * Toggle via chrome.storage.local `opforDebug: true/false` or the sidepanel UI. + * Logs go to console AND a ring buffer in storage (viewable / exportable from UI). + * + * Usage: + * import { dbg, isDebugEnabled, setDebugEnabled, getDebugLogs, clearDebugLogs } from "./debugLog.js"; + * dbg("locate", "Found chat input", { selector, frameId, confidence }); + */ + +const MAX_LOG_ENTRIES = 500; +const STORAGE_KEY = "opforDebugLogs"; +const FLAG_KEY = "opforDebug"; + +let _enabled = false; +let _buffer = []; +let _flushTimer = null; + +// Boot: read the stored flag once so hot-path checks are synchronous. +chrome.storage.local.get([FLAG_KEY], (data) => { + _enabled = !!data?.[FLAG_KEY]; +}); + +// React to live toggles (from the sidepanel or another context). +chrome.storage.onChanged.addListener((changes) => { + if (changes[FLAG_KEY]) { + _enabled = !!changes[FLAG_KEY].newValue; + } +}); + +export function isDebugEnabled() { + return _enabled; +} + +export async function setDebugEnabled(on) { + _enabled = !!on; + await chrome.storage.local.set({ [FLAG_KEY]: _enabled }); +} + +/** + * Log a debug entry. No-op when debug mode is off. + * + * @param {string} category Short tag — "locate", "send", "extract", "llm", "frame", etc. + * @param {string} message Human-readable one-liner. + * @param {Record} [data] Structured payload (selectors, scores, LLM decisions…). + */ +export function dbg(category, message, data) { + if (!_enabled) return; + + const entry = { + t: Date.now(), + cat: category, + msg: message, + ...(data !== undefined && { d: sanitize(data) }), + }; + + console.log(`[OPFOR:${category}]`, message, data ?? ""); + + _buffer.push(entry); + scheduleFlush(); +} + +function sanitize(obj) { + try { + const json = JSON.stringify(obj, (_k, v) => { + if (typeof v === "string" && v.length > 2000) return v.slice(0, 2000) + "…"; + return v; + }); + return JSON.parse(json); + } catch { + return String(obj); + } +} + +function scheduleFlush() { + if (_flushTimer) return; + _flushTimer = setTimeout(flush, 300); +} + +async function flush() { + _flushTimer = null; + if (!_buffer.length) return; + + const batch = _buffer.splice(0); + try { + const data = await chrome.storage.local.get(STORAGE_KEY); + const existing = Array.isArray(data?.[STORAGE_KEY]) ? data[STORAGE_KEY] : []; + const merged = [...existing, ...batch].slice(-MAX_LOG_ENTRIES); + await chrome.storage.local.set({ [STORAGE_KEY]: merged }); + } catch { + // Storage full or unavailable — logs are still in the console. + } +} + +export async function getDebugLogs() { + const data = await chrome.storage.local.get(STORAGE_KEY); + return Array.isArray(data?.[STORAGE_KEY]) ? data[STORAGE_KEY] : []; +} + +export async function clearDebugLogs() { + _buffer = []; + await chrome.storage.local.remove(STORAGE_KEY); +} + +/** + * Format stored logs as a downloadable text blob. + */ +export async function exportDebugLogs() { + const logs = await getDebugLogs(); + return logs + .map((e) => { + const ts = new Date(e.t).toISOString(); + const payload = e.d ? ` ${JSON.stringify(e.d)}` : ""; + return `${ts} [${e.cat}] ${e.msg}${payload}`; + }) + .join("\n"); +} diff --git a/runners/extension/domActions.js b/runners/extension/domActions.js index 1f012300..a9304de5 100644 --- a/runners/extension/domActions.js +++ b/runners/extension/domActions.js @@ -1,15 +1,30 @@ import { sleep } from "./utils.js"; +import { dbg } from "./debugLog.js"; /** Inject shadow DOM patch in MAIN world so closed shadow roots become accessible. */ export async function injectShadowPatch(tabId) { try { - await chrome.scripting.executeScript({ - target: { tabId, allFrames: true }, - files: ["frame_shadow_patch.js"], - world: "MAIN", - }); + await Promise.race([ + chrome.scripting.executeScript({ + target: { tabId, allFrames: true }, + files: ["frame_shadow_patch.js"], + world: "MAIN", + }), + new Promise((_, reject) => + setTimeout(() => reject(new Error("shadow patch timed out")), 10_000) + ), + ]); } catch { - /* swallowed */ + dbg("dom", "injectShadowPatch allFrames failed/timed out, trying main frame only"); + try { + await chrome.scripting.executeScript({ + target: { tabId, frameIds: [0] }, + files: ["frame_shadow_patch.js"], + world: "MAIN", + }); + } catch { + /* swallowed */ + } } } @@ -28,42 +43,111 @@ export async function preparePageForChat(tabId) { } export async function actSendText(tabId, frameId, plan) { - await chrome.scripting.executeScript({ - target: { tabId, frameIds: [frameId] }, - func: (p) => { - globalThis.__OPFOR_PLAN__ = p; - }, - args: [plan], - }); - const act2 = await chrome.scripting.executeScript({ - target: { tabId, frameIds: [frameId] }, - files: ["frame_actuate.js"], + dbg("dom", "actSendText", { + frameId, + inputSelector: plan?.inputSelector, + submitMethod: plan?.submit?.method, + buttonSelector: plan?.submit?.buttonSelector, + textLen: plan?.text?.length, }); - return act2?.[0]?.result; + try { + await chrome.scripting.executeScript({ + target: { tabId, frameIds: [frameId] }, + func: (p) => { + globalThis.__OPFOR_PLAN__ = p; + }, + args: [plan], + }); + } catch (e) { + const msg = e instanceof Error ? e.message : String(e); + dbg("dom", "actSendText plan inject FAILED", { frameId, error: msg }); + return { + ok: false, + error: `script_inject_failed`, + detail: `Could not inject plan into frame ${frameId}: ${msg}`, + }; + } + try { + const act2 = await chrome.scripting.executeScript({ + target: { tabId, frameIds: [frameId] }, + files: ["frame_actuate.js"], + }); + const result = act2?.[0]?.result; + if (result === undefined || result === null) { + dbg("dom", "actSendText frame_actuate returned null", { frameId, result }); + return { + ok: false, + error: "script_no_result", + detail: `frame_actuate.js returned ${result} in frame ${frameId} — the frame may have been removed or navigated`, + }; + } + dbg("dom", `actSendText result: ${result.ok ? "OK" : "FAIL"}`, { + frameId, + ok: result.ok, + error: result.error, + detail: result.detail, + }); + return result; + } catch (e) { + const msg = e instanceof Error ? e.message : String(e); + dbg("dom", "actSendText frame_actuate threw", { frameId, error: msg }); + return { + ok: false, + error: "script_exec_failed", + detail: `frame_actuate.js threw in frame ${frameId}: ${msg}`, + }; + } } export async function actVendorSendText(tabId, text) { - await chrome.scripting.executeScript({ - target: { tabId, frameIds: [0] }, - func: (t) => { - globalThis.__opforVendorText = t; - }, - args: [text], - world: "MAIN", - }); - // Re-discover vendor input in case page re-rendered. - await chrome.scripting.executeScript({ - target: { tabId, frameIds: [0] }, - files: ["frame_vendor_api.js"], - world: "MAIN", - }); + dbg("dom", "actVendorSendText", { textLen: text?.length }); + try { + await chrome.scripting.executeScript({ + target: { tabId, frameIds: [0] }, + func: (t) => { + globalThis.__opforVendorText = t; + }, + args: [text], + world: "MAIN", + }); + } catch (e) { + const msg = e instanceof Error ? e.message : String(e); + return { + ok: false, + error: "vendor_inject_failed", + detail: `Could not inject text into main frame: ${msg}`, + }; + } + try { + await chrome.scripting.executeScript({ + target: { tabId, frameIds: [0] }, + files: ["frame_vendor_api.js"], + world: "MAIN", + }); + } catch (e) { + const msg = e instanceof Error ? e.message : String(e); + return { ok: false, error: "vendor_api_failed", detail: `frame_vendor_api.js failed: ${msg}` }; + } await sleep(200); - const res = await chrome.scripting.executeScript({ - target: { tabId, frameIds: [0] }, - files: ["frame_vendor_send.js"], - world: "MAIN", - }); - return res?.[0]?.result; + try { + const res = await chrome.scripting.executeScript({ + target: { tabId, frameIds: [0] }, + files: ["frame_vendor_send.js"], + world: "MAIN", + }); + const result = res?.[0]?.result; + if (result === undefined || result === null) { + return { + ok: false, + error: "vendor_no_result", + detail: "frame_vendor_send.js returned no result — vendor API may have changed", + }; + } + return result; + } catch (e) { + const msg = e instanceof Error ? e.message : String(e); + return { ok: false, error: "vendor_send_failed", detail: `frame_vendor_send.js threw: ${msg}` }; + } } export async function actClickSelector(tabId, frameId, selector) { diff --git a/runners/extension/domTarget.js b/runners/extension/domTarget.js index 0f42436e..2993af60 100644 --- a/runners/extension/domTarget.js +++ b/runners/extension/domTarget.js @@ -2,6 +2,7 @@ import { actSendText, actVendorSendText } from "./domActions.js"; import { snapshotCurrentResponse, extractResponse } from "./responseExtractor.js"; import { llmShortenMessage } from "./llmUiActions.js"; import { state } from "./state.js"; +import { dbg } from "./debugLog.js"; const SHORTEN_MAX_RETRIES = 3; const PAUSE_POLL_MS = 300; @@ -57,31 +58,56 @@ export function createDomTarget(tabId, frameId, plan, readerCfg, options = {}) { async function tryRecovery() { if (!onRecovery) return false; + dbg("send", "Attempting recovery (re-locate widget)", { consecutiveFailures }); const recovered = await onRecovery().catch(() => null); if (recovered?.plan) { + dbg("send", "Recovery SUCCESS — widget re-located", { + newSelector: recovered.plan.inputSelector, + newFrameId: recovered.frameId, + }); currentPlan = recovered.plan; currentFrameId = recovered.frameId ?? currentFrameId; consecutiveFailures = 0; return true; } + dbg("send", "Recovery FAILED — could not re-locate widget"); return false; } return { async send(prompt, _options) { - // Honor pause: block until unpaused or stopped while (state.pauseRequested && !state.OPFOR_STOP) { await sleep(PAUSE_POLL_MS); } if (state.OPFOR_STOP) throw domTargetStopError(); const round = roundOffset + turns.length + 1; + dbg("send", `Round ${round}: sending prompt`, { + round, + promptLen: prompt.length, + promptPreview: prompt.slice(0, 200), + frameId: currentFrameId, + inputSelector: currentPlan?.inputSelector, + submitMethod: currentPlan?.submit?.method, + vendorMode: !!currentPlan?.vendorMode, + }); - // Pre-send snapshot (used for diff extraction) const prevSnapshot = await snapshotCurrentResponse(tabId, currentFrameId); + dbg("send", `Pre-send snapshot taken`, { + round, + nodeCount: prevSnapshot?.nodeCount ?? 0, + textLen: (prevSnapshot?.fullText || prevSnapshot?.text || "").length, + }); - // Send with message_too_long retry and optional LLM shortening let { sendResult, textToSend } = await attemptSend(prompt); + dbg("send", `Send result: ${sendResult?.ok ? "OK" : "FAIL"}`, { + round, + ok: sendResult?.ok, + error: sendResult?.error, + detail: sendResult?.detail, + textLen: textToSend?.length, + shortened: textToSend !== prompt, + }); // On send failure: try recovery (re-locate widget) before giving up if (!sendResult?.ok) { @@ -92,7 +118,20 @@ export function createDomTarget(tabId, frameId, plan, readerCfg, options = {}) { } } if (!sendResult?.ok) { - throw new Error(`DomTarget send failed: ${sendResult?.error ?? "unknown error"}`); + const errCode = sendResult?.error ?? "no_result"; + const detail = sendResult?.detail ?? ""; + const selector = currentPlan?.inputSelector ?? "?"; + const diag = [ + `error=${errCode}`, + `frame=${currentFrameId}`, + `selector="${selector}"`, + `consecutiveFailures=${consecutiveFailures}`, + `recoveryAttempted=${consecutiveFailures >= MAX_CONSECUTIVE_FAILURES}`, + detail ? `detail: ${detail}` : "", + ] + .filter(Boolean) + .join(", "); + throw new Error(`DomTarget send failed: ${diag}`); } } @@ -105,9 +144,15 @@ export function createDomTarget(tabId, frameId, plan, readerCfg, options = {}) { if (state.OPFOR_STOP) throw domTargetStopError(); - // Extract response const extraction = await extractResponse(tabId, currentFrameId, textToSend, prevSnapshot); const assistantText = extraction?.ok ? String(extraction.text || "").trim() : ""; + dbg("send", `Response extraction: ${extraction?.ok ? "OK" : "FAIL"}`, { + round, + ok: extraction?.ok, + error: extraction?.error, + textLen: assistantText.length, + textPreview: assistantText.slice(0, 300), + }); if (assistantText) { consecutiveFailures = 0; diff --git a/runners/extension/frameDiscovery.js b/runners/extension/frameDiscovery.js index da3fb6b7..99a8e07e 100644 --- a/runners/extension/frameDiscovery.js +++ b/runners/extension/frameDiscovery.js @@ -1,12 +1,48 @@ import { sleep } from "./utils.js"; +import { dbg } from "./debugLog.js"; + +const COLLECT_TIMEOUT_MS = 15_000; export async function collectFrames(tabId) { - const frameSnapshots = await chrome.scripting.executeScript({ - target: { tabId, allFrames: true }, - files: ["frame_collect.js"], - }); + dbg("frame", "collectFrames starting", { tabId }); - return (frameSnapshots || []) + let frameSnapshots; + try { + frameSnapshots = await Promise.race([ + chrome.scripting.executeScript({ + target: { tabId, allFrames: true }, + files: ["frame_collect.js"], + }), + new Promise((_, reject) => + setTimeout( + () => reject(new Error(`frame_collect timed out after ${COLLECT_TIMEOUT_MS}ms`)), + COLLECT_TIMEOUT_MS + ) + ), + ]); + } catch (e) { + dbg("frame", "collectFrames allFrames failed, falling back to main frame only", { + error: e instanceof Error ? e.message : String(e), + }); + try { + frameSnapshots = await Promise.race([ + chrome.scripting.executeScript({ + target: { tabId, frameIds: [0] }, + files: ["frame_collect.js"], + }), + new Promise((_, reject) => + setTimeout(() => reject(new Error("main-frame-only collect timed out")), 10_000) + ), + ]); + } catch (e2) { + dbg("frame", "collectFrames main-frame fallback also failed", { + error: e2 instanceof Error ? e2.message : String(e2), + }); + return []; + } + } + + const frames = (frameSnapshots || []) .map((r) => ({ frameId: r.frameId, snapshot: r.result?.snapshot, @@ -18,6 +54,21 @@ export async function collectFrames(tabId) { bestSendSelector: r.result?.bestSendSelector ?? "", })) .filter((f) => typeof f.snapshot === "string" && f.snapshot.length > 0); + + dbg("frame", "collectFrames done", { + rawCount: (frameSnapshots || []).length, + filteredCount: frames.length, + frames: frames.map((f) => ({ + frameId: f.frameId, + url: String(f.frameUrl || "").slice(0, 100), + inputCount: f.inputCount, + chatScore: f.chatScore, + bestInputSelector: f.bestInputSelector || null, + bestInputScore: f.bestInputScore, + })), + }); + + return frames; } /** Boost score for frames that are clearly dedicated chat surfaces (not the parent page). */ diff --git a/runners/extension/frame_actuate.js b/runners/extension/frame_actuate.js index 47b81ceb..1e593bda 100644 --- a/runners/extension/frame_actuate.js +++ b/runners/extension/frame_actuate.js @@ -430,17 +430,42 @@ async function submitWithRetries({ inputEl, desiredMethod, buttonEl, originalTex }; } - return { ok: false, attempts }; + const inputTag = inputEl.tagName?.toLowerCase() || "?"; + const inputVisible = isVisible(inputEl); + const inputText = getInputText(inputEl); + const textStillPresent = inputText.trim().length > 0; + const sendBtn = findGlobalSendButton(); + const sendBtnDisabled = sendBtn ? isDisabledButton(sendBtn) : null; + + return { + ok: false, + error: "submit_not_accepted", + detail: [ + `input <${inputTag}> visible=${inputVisible}`, + `text_still_in_input=${textStillPresent} (${inputText.length} chars)`, + sendBtn + ? `send_button found=${selectorFromEl(sendBtn)} disabled=${sendBtnDisabled}` + : "send_button not_found", + `attempts=${attempts.length} (${attempts.map((a) => a.action).join(", ")})`, + ].join("; "), + attempts, + }; } (() => { try { const plan = globalThis.__OPFOR_PLAN__; - if (!plan?.inputSelector) return { ok: false, error: "Missing plan.inputSelector" }; + if (!plan?.inputSelector) + return { ok: false, error: "missing_plan", detail: "No plan.inputSelector provided" }; // Never pass deep-selector syntax into querySelector (it will throw). Use deep resolver first. const input = resolveDeepSelector(plan.inputSelector) || safeQuerySelector(document, plan.inputSelector); - if (!input) return { ok: false, error: "inputSelector did not match" }; + if (!input) + return { + ok: false, + error: "selector_not_found", + detail: `inputSelector "${plan.inputSelector}" matched no element — the widget may have closed or the page re-rendered`, + }; const injectedText = String(plan.text ?? "hi"); const setResult = setInputValue(input, injectedText); diff --git a/runners/extension/frame_snapshot.js b/runners/extension/frame_snapshot.js index 0c6cd25a..d974147c 100644 --- a/runners/extension/frame_snapshot.js +++ b/runners/extension/frame_snapshot.js @@ -95,7 +95,7 @@ // ── Text collector (shared by both fast and full paths) ────────────────────── function collectText(node, depth, out) { - if (!node || depth > 15) return; + if (!node || depth > 25) return; if (node.nodeType === 1) { try { const st = window.getComputedStyle(node); diff --git a/runners/extension/llm.js b/runners/extension/llm.js index 3743992e..4ce6b847 100644 --- a/runners/extension/llm.js +++ b/runners/extension/llm.js @@ -6,6 +6,7 @@ import { setEnvProvider, } from "./dist/core.bundle.js"; import { state } from "./state.js"; +import { dbg } from "./debugLog.js"; // 0 for determinism, except gpt-5 (LiteLLM/OpenAI reject 0) and Anthropic (left unset). function providerTemperature(provider, model) { @@ -25,12 +26,28 @@ export async function callLlm({ provider, baseUrl, apiKey, model, messages, sign apiKeyEnv: envVar, baseURL: baseUrl || undefined, }); + const systemRole = messages?.find((m) => m.role === "system")?.content || ""; + dbg("llm-call", `${provider}/${model}`, { + provider, + model, + messageCount: messages?.length, + systemPromptPreview: systemRole.slice(0, 150), + userPromptLen: messages?.find((m) => m.role === "user")?.content?.length, + }); try { - return await generateJsonObject(llmModel, messages, { + const result = await generateJsonObject(llmModel, messages, { abortSignal: signal, temperature: providerTemperature(provider, model), }); + dbg("llm-call", `${provider}/${model} -> OK`, { + resultKeys: result ? Object.keys(result) : null, + }); + return result; } catch (e) { + dbg("llm-call", `${provider}/${model} -> ERROR`, { + error: e instanceof Error ? e.message : String(e), + name: e?.name, + }); if (e?.name === "AbortError" || state.OPFOR_STOP) throw new Error("Run stopped.", { cause: e }); throw e; } diff --git a/runners/extension/llmUiActions.js b/runners/extension/llmUiActions.js index 014be405..a8ec25f4 100644 --- a/runners/extension/llmUiActions.js +++ b/runners/extension/llmUiActions.js @@ -1,6 +1,12 @@ import { callLlm } from "./llm.js"; +import { dbg } from "./debugLog.js"; export async function aiPickInputInFrame(cfg, frame) { + dbg("llm", "aiPickInputInFrame called", { + frameId: frame?.frameId, + frameUrl: String(frame?.frameUrl || "").slice(0, 120), + snapshotLen: String(frame?.snapshot || "").length, + }); const system = [ "You are helping a browser extension identify a chat input box INSIDE A SINGLE FRAME.", "You receive a SANITIZED DOM snapshot for that frame only.", @@ -28,7 +34,7 @@ export async function aiPickInputInFrame(cfg, frame) { String(frame.snapshot).slice(0, 60_000), ].join("\n"); - return await callLlm({ + const result = await callLlm({ provider: cfg.provider, baseUrl: cfg.baseUrl, apiKey: cfg.apiKey, @@ -38,6 +44,14 @@ export async function aiPickInputInFrame(cfg, frame) { { role: "user", content: user }, ], }); + dbg("llm", "aiPickInputInFrame result", { + inputSelector: result?.inputSelector, + launcherSelector: result?.launcherSelector, + submit: result?.submit, + confidence: result?.confidence, + notes: result?.notes, + }); + return result; } function isAccessibilitySnapshot(snapshot) { @@ -116,6 +130,14 @@ export async function aiUiNextAction( readerCfg, { frameUrl, snapshot, lastError, attempts, clickedLaunchers } ) { + dbg("llm", "aiUiNextAction called", { + frameUrl: String(frameUrl || "").slice(0, 120), + snapshotLen: String(snapshot || "").length, + attempts, + lastError: lastError || null, + clickedLaunchers, + mode: isAccessibilitySnapshot(snapshot) ? "ax-tree" : "dom-snapshot", + }); const clickedNote = clickedLaunchers?.length ? `\nLaunchers already clicked (DO NOT click these again): ${clickedLaunchers.join(", ")}` : ""; @@ -135,7 +157,7 @@ export async function aiUiNextAction( .filter(Boolean) .join("\n"); - return await callLlm({ + const result = await callLlm({ provider: readerCfg.provider, baseUrl: readerCfg.baseUrl, apiKey: readerCfg.apiKey, @@ -145,6 +167,16 @@ export async function aiUiNextAction( { role: "user", content: user }, ], }); + dbg("llm", "aiUiNextAction result", { + action: result?.action, + inputSelector: result?.inputSelector, + launcherSelector: result?.launcherSelector, + submit: result?.submit, + confidence: result?.confidence, + waitMs: result?.waitMs, + notes: result?.notes, + }); + return result; } export async function llmShortenMessage(cfg, originalMessage, maxLength) { diff --git a/runners/extension/orchestrator.js b/runners/extension/orchestrator.js index 45f7b420..eb78e34a 100644 --- a/runners/extension/orchestrator.js +++ b/runners/extension/orchestrator.js @@ -29,6 +29,7 @@ import { actClickSelector, actVerifyInputVisible } from "./domActions.js"; import { extractResponse } from "./responseExtractor.js"; import { aiPickInputInFrame, llmShortenMessage } from "./llmUiActions.js"; import { resolveAgentBusinessContext, mergeBusinessContext } from "./agentContext.js"; +import { dbg } from "./debugLog.js"; export async function sleepInterruptible(ms) { const step = 250; @@ -276,6 +277,12 @@ export async function resetChatSession(tabId, readerCfg) { } export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { + dbg("run", resume ? "RESUMING run" : "STARTING new run", { + suiteId: message?.suiteId, + evaluatorId: message?.evaluatorId, + maxRounds: message?.maxRounds ?? message?.turns, + scrapeFromSite: message?.scrapeFromSite, + }); beginUiRunAbortController(); state.OPFOR_STOP = false; state.OPFOR_STOP_INTENT = "cancel"; @@ -330,6 +337,11 @@ export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { judgeLlmConfig = profileToLlmConfig(judgeCfg); attackerModel = createModel(attackerLlmConfig); judgeModel = createModel(judgeLlmConfig); + dbg("run", "LLM profiles loaded", { + attacker: { provider: attackerCfg.provider, model: attackerCfg.model }, + judge: { provider: judgeCfg.provider, model: judgeCfg.model }, + reader: { provider: readerCfg.provider, model: readerCfg.model }, + }); } catch (e) { const msg = e instanceof Error ? e.message : String(e); try { @@ -534,6 +546,10 @@ export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { }); try { + dbg("run", "Resolving agent business context", { + scrapeFromSite, + agentDescription: agentDescription?.slice(0, 200), + }); businessUseCase = await resolveAgentBusinessContext({ scrapeFromSite, agentDescription, @@ -542,6 +558,10 @@ export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { siteUrl: tab.url || "", readerCfg, }); + dbg("run", "Business context resolved", { + length: businessUseCase?.length, + preview: businessUseCase?.slice(0, 300), + }); } catch (detectErr) { if (!detectErr?.needsAgentDescription || state.OPFOR_STOP) throw detectErr; @@ -624,7 +644,15 @@ export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { evaluatorId: evaluatorSnapshot?.id, }); + dbg("run", "Phase: locating chat widget"); let located = await locateChatWidget(tab.id, readerCfg); + dbg("run", `Chat widget locate result: ${located.ok ? "OK" : "FAIL"}`, { + ok: located.ok, + error: located.error, + inputSelector: located.plan?.inputSelector, + frameId: located.best?.frameId, + confidence: located.plan?.confidence, + }); const MAX_USER_RETRIES = 5; let userRetryCount = 0; @@ -712,7 +740,15 @@ export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { const suiteRec = catalog.suites.find((s) => s.id === suiteId); const suiteLabel = suiteRec ? `${suiteRec.name} (${suiteRec.id})` : suiteId; - // Build DomTarget adapter — handles send/extract/pause/stop/recovery + dbg("run", "Phase: running attacks", { + inputSelector: plan?.inputSelector, + submitMethod: plan?.submit?.method, + buttonSelector: plan?.submit?.buttonSelector, + frameId: best?.frameId, + maxRounds, + evaluatorId: evaluatorSnapshot?.id, + }); + const domTarget = createDomTarget(tab.id, best.frameId, plan, readerCfg, { waitMs, roundOffset: priorRounds, @@ -870,6 +906,12 @@ export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { // is reported as CANCELLED, not judged. Running the judge LLM here would // both delay the stop and produce a misleading PASS/FAIL-shaped verdict // for a turn the target never got to finish. + if (runError && runError.code !== "OPFOR_STOP") { + dbg("run", "runAllBrowser error", { + error: runError instanceof Error ? runError.message : String(runError), + }); + } + if (runError?.code === "OPFOR_STOP" || state.OPFOR_STOP) { // A pause with no usable widget plan can't be resumed — degrade it to a // cancel so the popup still gets a report instead of a dead snapshot. @@ -973,6 +1015,13 @@ export async function executeAdaptiveRedTeamRun(sendResponse, message, resume) { } // ── SUCCESS path ───────────────────────────────────────────────────────── + dbg("run", "Run completed successfully", { + evaluators: report.evaluators?.length, + verdict: report.evaluators?.[0]?.attacks?.[0]?.judge?.verdict, + score: report.evaluators?.[0]?.attacks?.[0]?.judge?.score, + transcriptLen: fullTranscript.length, + tokenUsage: report.summary?.tokenUsage, + }); const attack = report.evaluators?.[0]?.attacks?.[0]; const judgment = attack ? adaptJudgeResult(attack.judge) diff --git a/runners/extension/popup.html b/runners/extension/popup.html index 04b59ee3..19158998 100644 --- a/runners/extension/popup.html +++ b/runners/extension/popup.html @@ -2801,6 +2801,68 @@ +
+
+
+
Debug mode
+
Log every step to the service-worker console and storage.
+
+ +
+
+ + +
+
diff --git a/runners/extension/popup.js b/runners/extension/popup.js index 7d62296c..10a3334b 100644 --- a/runners/extension/popup.js +++ b/runners/extension/popup.js @@ -3012,6 +3012,32 @@ function wire() { saveSettings(); }); + // Debug mode controls + chrome.runtime.sendMessage({ type: "OPFOR_DEBUG_STATUS" }, (res) => { + if (res?.ok) $("debugToggle").setAttribute("aria-checked", String(!!res.enabled)); + }); + $("debugToggle").addEventListener("click", () => { + const cur = $("debugToggle").getAttribute("aria-checked") === "true"; + const next = !cur; + $("debugToggle").setAttribute("aria-checked", String(next)); + chrome.runtime.sendMessage({ type: "OPFOR_DEBUG_TOGGLE", enabled: next }); + }); + $("debugExportBtn").addEventListener("click", () => { + chrome.runtime.sendMessage({ type: "OPFOR_DEBUG_EXPORT" }, (res) => { + if (!res?.ok || !res.text) return; + const blob = new Blob([res.text], { type: "text/plain" }); + const url = URL.createObjectURL(blob); + const a = document.createElement("a"); + a.href = url; + a.download = `opfor-debug-${new Date().toISOString().replace(/[:.]/g, "-")}.log`; + a.click(); + URL.revokeObjectURL(url); + }); + }); + $("debugClearBtn").addEventListener("click", () => { + chrome.runtime.sendMessage({ type: "OPFOR_DEBUG_CLEAR" }); + }); + // NOTE: We intentionally do NOT stop the background run on popup close. // The service worker can continue running; the popup can be reopened to Stop or view status. diff --git a/runners/extension/responseExtractor.js b/runners/extension/responseExtractor.js index 51e556ed..1da67e68 100644 --- a/runners/extension/responseExtractor.js +++ b/runners/extension/responseExtractor.js @@ -1,5 +1,6 @@ import { sleep } from "./utils.js"; import { state } from "./state.js"; +import { dbg } from "./debugLog.js"; // ── Timestamp normalization ─────────────────────────────────────────────────── // Many widgets prepend a changing timestamp to each message element's @@ -47,17 +48,33 @@ function diffTextNodes(pre, post) { // ── Scan all frames, return the best container snapshot ─────────────────────── async function scanBestFrame(tabId) { - const results = await chrome.scripting.executeScript({ - target: { tabId, allFrames: true }, - files: ["frame_snapshot.js"], - }); + let results; + try { + results = await Promise.race([ + chrome.scripting.executeScript({ + target: { tabId, allFrames: true }, + files: ["frame_snapshot.js"], + }), + new Promise((_, reject) => + setTimeout(() => reject(new Error("scanBestFrame timed out")), 15_000) + ), + ]); + } catch { + try { + results = await chrome.scripting.executeScript({ + target: { tabId, frameIds: [0] }, + files: ["frame_snapshot.js"], + }); + } catch { + return null; + } + } - const hits = results + const hits = (results || []) .filter((r) => r.result?.ok) .map((r) => ({ frameId: r.frameId, ...r.result })) .sort((a, b) => b.score - a.score); - // Chat containers almost always live in iframes — prefer them over main frame const iframeHits = hits.filter((h) => h.frameId !== 0); return iframeHits.length > 0 ? iframeHits[0] : hits[0] || null; } @@ -130,12 +147,19 @@ function hasFrameIdSafe(frameId) { * Falls back gracefully if prevSnapshot is a plain string or missing textNodes. */ export async function extractResponse(tabId, frameId, lastUserText = "", prevSnapshot = "") { - const POLL_FAST = 350; // ms between polls while waiting / stabilising - const POLL_SLOW = 600; // ms while waiting for the first change - const GROWTH_COOLDOWN = 3000; // ms of no-growth required before accepting stable + const POLL_FAST = 350; + const POLL_SLOW = 600; + const GROWTH_COOLDOWN = 3000; const BASE_MAX_POLLS = 60; const GROWTH_MAX_WAIT = 180_000; + dbg("extract", "extractResponse started", { + frameId, + lastUserTextLen: lastUserText?.length, + prevSnapshotType: typeof prevSnapshot === "object" ? "object" : "string", + prevNodeCount: typeof prevSnapshot === "object" ? prevSnapshot?.nodeCount : undefined, + }); + // Normalise prevSnapshot — accept both old string format and new object format const prev = typeof prevSnapshot === "object" && prevSnapshot !== null @@ -248,6 +272,7 @@ export async function extractResponse(tabId, frameId, lastUserText = "", prevSna if (textGrowthStreak >= 2 && !sawTextGrowth) { sawTextGrowth = true; growthStartedAt = Date.now(); + dbg("extract", "Streaming detected (text growing across polls)", { poll, curTextLen }); } if (sawTextGrowth && poll >= maxPolls - 5) { const elapsed = Date.now() - growthStartedAt; @@ -301,6 +326,13 @@ export async function extractResponse(tabId, frameId, lastUserText = "", prevSna ); if (botLines.length > 0) { + dbg("extract", "Response extracted successfully", { + poll, + botLineCount: botLines.length, + textLen: botLines.join("\n").length, + textPreview: botLines.join("\n").slice(0, 200), + streaming: sawTextGrowth, + }); return { ok: true, text: botLines.join("\n"), @@ -326,8 +358,11 @@ export async function extractResponse(tabId, frameId, lastUserText = "", prevSna await sleep(sawTextGrowth ? POLL_FAST : POLL_SLOW); } - // Timeout — return whatever diff we have (without echo-filtering so we don't - // silently drop content when lastUserText wasn't available or didn't match) + dbg("extract", "Polling exhausted — checking for partial result", { + maxPolls, + sawTextGrowth, + hasBestSnap: !!bestSnap, + }); if (bestSnap) { const { text } = diffTextNodes(baseTextNodes, bestSnap.textNodes); if (text.trim()) { @@ -340,5 +375,6 @@ export async function extractResponse(tabId, frameId, lastUserText = "", prevSna }; } } + dbg("extract", "TIMEOUT — no response extracted"); return { ok: false, error: "Timeout waiting for response", text: "" }; } diff --git a/runners/extension/service_worker.js b/runners/extension/service_worker.js index 5478ae2c..7dbd8997 100644 --- a/runners/extension/service_worker.js +++ b/runners/extension/service_worker.js @@ -10,6 +10,13 @@ import { } from "./dist/core.bundle.js"; import { resetChatSession, executeAdaptiveRedTeamRun } from "./orchestrator.js"; import { persistPartialResult } from "./storage.js"; +import { + isDebugEnabled, + setDebugEnabled, + getDebugLogs, + clearDebugLogs, + exportDebugLogs, +} from "./debugLog.js"; async function configureSidePanel() { if (!chrome.sidePanel?.setPanelBehavior) return; @@ -298,6 +305,44 @@ function handleMainMessages(message, sendResponse) { return true; } + if (message?.type === "OPFOR_DEBUG_TOGGLE") { + (async () => { + const on = !!message.enabled; + await setDebugEnabled(on); + sendResponse({ ok: true, enabled: on }); + })(); + return true; + } + + if (message?.type === "OPFOR_DEBUG_STATUS") { + sendResponse({ ok: true, enabled: isDebugEnabled() }); + return true; + } + + if (message?.type === "OPFOR_DEBUG_EXPORT") { + (async () => { + const text = await exportDebugLogs(); + sendResponse({ ok: true, text }); + })(); + return true; + } + + if (message?.type === "OPFOR_DEBUG_CLEAR") { + (async () => { + await clearDebugLogs(); + sendResponse({ ok: true }); + })(); + return true; + } + + if (message?.type === "OPFOR_DEBUG_GET_LOGS") { + (async () => { + const logs = await getDebugLogs(); + sendResponse({ ok: true, logs }); + })(); + return true; + } + if (message?.type !== "OPFOR_UI_RUN") return; (async () => {