cdp debug logging [STG-593]

.gitignore

@@ -19,3 +19,4 @@ eval-summary.json
 package-lock.json
 evals/deterministic/tests/BrowserContext/tmp-test.har
 lib/version.ts
+*.log

evals/deterministic/tests/page/livePageProxy.test.ts

@@ -8,13 +8,16 @@ test.describe("StagehandPage - live page proxy", () => {
     await stagehand.init();
 
     const page = stagehand.page;
-    await page.goto("https://browserbase.github.io/stagehand-eval-sites/sites/five-tab/");
+    await page.goto(
+      "https://browserbase.github.io/stagehand-eval-sites/sites/five-tab/",
+    );
     await page.locator("body > button").click();
-    await new Promise(resolve => setTimeout(resolve, 1000));
-    await page.waitForURL('**/page2.html', {waitUntil: "commit"});
+    await new Promise((resolve) => setTimeout(resolve, 1000));
+    await page.waitForURL("**/page2.html", { waitUntil: "commit" });
     // await new Promise(resolve => setTimeout(resolve, 1000));
     const currentURL = page.url();
-    const expectedURL = "https://browserbase.github.io/stagehand-eval-sites/sites/five-tab/page2.html";
+    const expectedURL =
+      "https://browserbase.github.io/stagehand-eval-sites/sites/five-tab/page2.html";
 
     expect(currentURL).toBe(expectedURL);
 
@@ -26,9 +29,11 @@ test.describe("StagehandPage - live page proxy", () => {
     await stagehand.init();
 
     const page = stagehand.page;
-    await page.goto("https://browserbase.github.io/stagehand-eval-sites/sites/five-tab/");
+    await page.goto(
+      "https://browserbase.github.io/stagehand-eval-sites/sites/five-tab/",
+    );
     await page.locator("body > button").click();
-    await new Promise(resolve => setTimeout(resolve, 1000));
+    await new Promise((resolve) => setTimeout(resolve, 1000));
 
     const expectedNumPages = 2;
     const actualNumPages = stagehand.context.pages().length;

examples/test-api-logger.ts

@@ -0,0 +1,44 @@
+import { Stagehand } from "../lib/index";
+import { createStagehandApiLogger } from "../lib/stagehandApiLogger";
+
+async function testApiLogger() {
+  console.log("Starting test with custom sh:api logger...\n");
+
+  const stagehand = new Stagehand({
+    env: "LOCAL",
+    logger: createStagehandApiLogger(),
+    localBrowserLaunchOptions: {
+      headless: false,
+    },
+  });
+
+  try {
+    await stagehand.init();
+    const page = stagehand.page;
+
+    console.log("\nNavigating to example.com...");
+    await page.goto("https://example.com");
+
+    console.log("\nExtracting page title...");
+    const title = await page.extract({
+      instruction: "Extract the main heading of the page",
+    });
+    console.log("Extracted title:", title);
+
+    console.log("\nPerforming a simple action...");
+    await page.act({
+      action: "click on the 'More information' link",
+    });
+
+    console.log("\nObserving the page...");
+    const observation = await page.observe();
+    console.log("Observation result:", observation);
+  } catch (error) {
+    console.error("Error during test:", error);
+  } finally {
+    await stagehand.close();
+  }
+}
+
+// Run the test
+testApiLogger().catch(console.error);

lib/StagehandContext.ts

@@ -1,3 +1,4 @@
+import "./debug";
 import type {
   BrowserContext as PlaywrightContext,
   Page as PlaywrightPage,

lib/StagehandPage.ts

@@ -1,3 +1,4 @@
+import "./debug";
 import { Browserbase } from "@browserbasehq/sdk";
 import type { CDPSession, Page as PlaywrightPage, Frame } from "playwright";
 import { chromium } from "playwright";
@@ -33,6 +34,7 @@ import {
 import { StagehandAPIError } from "@/types/stagehandApiErrors";
 import { scriptContent } from "@/lib/dom/build/scriptContent";
 import type { Protocol } from "devtools-protocol";
+import { markStagehandCDPCall } from "./debug";
 
 export class StagehandPage {
   private stagehand: Stagehand;
@@ -351,13 +353,13 @@ ${scriptContent} \
 
           // Handle goto specially
           if (prop === "goto") {
-            const rawGoto: typeof target.goto =
-              Object.getPrototypeOf(target).goto.bind(target);
             return async (url: string, options: GotoOptions) => {
               this.intContext.setActivePage(this);
+
+              // Use the raw page directly for navigation
               const result = this.api
                 ? await this.api.goto(url, options)
-                : await rawGoto(url, options);
+                : await target.goto(url, options);
 
               this.stagehand.addToHistory("navigate", { url, options }, result);
 
@@ -381,7 +383,24 @@ ${scriptContent} \
                   });
                 }
                 await target.waitForLoadState("domcontentloaded");
-                await this._waitForSettledDom();
+                // Skip DOM settling during initial navigation
+                if (this.initialized) {
+                  try {
+                    await this._waitForSettledDom();
+                  } catch (err) {
+                    this.stagehand.log({
+                      category: "navigation",
+                      message: "Failed to wait for settled DOM, continuing",
+                      level: 2,
+                      auxiliary: {
+                        error: {
+                          value: (err as Error).message,
+                          type: "string",
+                        },
+                      },
+                    });
+                  }
+                }
               }
               return result;
             };
@@ -482,8 +501,13 @@ ${scriptContent} \
     const hasDoc = !!(await this.page.title().catch(() => false));
     if (!hasDoc) await this.page.waitForLoadState("domcontentloaded");
 
+    markStagehandCDPCall("Network.enable");
     await client.send("Network.enable");
+
+    markStagehandCDPCall("Page.enable");
     await client.send("Page.enable");
+
+    markStagehandCDPCall("Target.setAutoAttach");
     await client.send("Target.setAutoAttach", {
       autoAttach: true,
       waitForDebuggerOnStart: false,
@@ -964,7 +988,9 @@ ${scriptContent} \
     target: PlaywrightPage | Frame = this.page,
   ): Promise<CDPSession> {
     const cached = this.cdpClients.get(target);
-    if (cached) return cached;
+    if (cached) {
+      return cached;
+    }
 
     try {
       const session = await this.context.newCDPSession(target);
@@ -1000,10 +1026,15 @@ ${scriptContent} \
   ): Promise<T> {
     const client = await this.getCDPClient(target ?? this.page);
 
-    return client.send(
+    // Mark this as a Stagehand CDP call
+    markStagehandCDPCall(method);
+
+    const result = (await client.send(
       method as Parameters<CDPSession["send"]>[0],
       params as Parameters<CDPSession["send"]>[1],
-    ) as Promise<T>;
+    )) as T;
+
+    return result;
   }
 
   /** Enable a CDP domain (e.g. `"Network"` or `"DOM"`) on the chosen target. */

lib/a11y/utils.ts

@@ -14,6 +14,7 @@ import {
 } from "../../types/context";
 import { StagehandPage } from "../StagehandPage";
 import { LogLine } from "../../types/log";
+import { markStagehandCDPCall } from "../debug";
 import {
   ContentFrameNotFoundError,
   StagehandDomProcessError,
@@ -144,10 +145,15 @@ export async function buildBackendIdMaps(
 
   try {
     // 1. full DOM tree
-    const { root } = (await session.send("DOM.getDocument", {
+    markStagehandCDPCall("DOM.getDocument");
+    const result = (await session.send("DOM.getDocument", {
       depth: -1,
       pierce: true,
-    })) as { root: DOMNode };
+    })) as {
+      root: DOMNode;
+    };
+
+    const { root } = result;
 
     // 2. pick start node + root frame-id
     let startNode: DOMNode = root;
@@ -462,7 +468,9 @@ export async function getCDPFrameId(
   try {
     const sess = await sp.context.newCDPSession(frame); // throws if detached
 
+    markStagehandCDPCall("Page.getFrameTree");
     const ownResp = (await sess.send("Page.getFrameTree")) as unknown;
+
     const { frameTree } = ownResp as { frameTree: CdpFrameTree };
 
     return frameTree.frame.id; // root of OOPIF
@@ -684,10 +692,13 @@ export async function getFrameRootBackendNodeId(
   }
 
   // Retrieve the DOM node that owns the frame via CDP
-  const { backendNodeId } = (await cdp.send("DOM.getFrameOwner", {
+  markStagehandCDPCall("DOM.getFrameOwner");
+  const frameOwnerResult = (await cdp.send("DOM.getFrameOwner", {
     frameId: fid,
   })) as FrameOwnerResult;
 
+  const { backendNodeId } = frameOwnerResult;
+
   return backendNodeId ?? null;
 }
 

lib/debug.ts

@@ -0,0 +1,150 @@
+/**
+ * Debug utility for Stagehand that intercepts Playwright's CDP protocol logs
+ * and marks calls that originated from Stagehand code
+ */
+
+const DEBUG = process.env.DEBUG || "";
+const debugNamespaces = DEBUG.split(",").map((ns) => ns.trim());
+
+// If sh:protocol is enabled, automatically enable pw:protocol
+// This must happen before any Playwright imports
+if (
+  debugNamespaces.includes("sh:protocol") &&
+  !debugNamespaces.some((ns) => ns.includes("pw:protocol"))
+) {
+  debugNamespaces.push("pw:protocol");
+  // Update process.env.DEBUG to include pw:protocol
+  process.env.DEBUG = debugNamespaces.join(",");
+}
+
+// Track pending Stagehand CDP calls by method name and timestamp
+interface PendingCall {
+  method: string;
+  timestamp: number;
+  sessionId?: string;
+}
+
+const pendingStagehandCalls: PendingCall[] = [];
+const CALL_TIMEOUT_MS = 100; // Clear old pending calls after 100ms
+
+// Clean up old pending calls
+function cleanupOldCalls() {
+  const now = Date.now();
+  const index = pendingStagehandCalls.findIndex(
+    (call) => now - call.timestamp > CALL_TIMEOUT_MS,
+  );
+  if (index > 0) {
+    pendingStagehandCalls.splice(0, index);
+  }
+}
+
+// Intercept stderr to rewrite Playwright protocol logs for Stagehand-originated calls
+if (
+  debugNamespaces.includes("sh:protocol") &&
+  debugNamespaces.some((ns) => ns.includes("pw:protocol"))
+) {
+  const originalStderrWrite = process.stderr.write;
+
+  // Track message IDs that we've identified as Stagehand calls
+  const stagehandMessageIds = new Set<number>();
+
+  process.stderr.write = function (
+    chunk: unknown,
+    ...args: unknown[]
+  ): boolean {
+    const str = chunk?.toString();
+
+    if (str && str.includes("pw:protocol")) {
+      // Check if this is a SEND
+      const sendMatch = str.match(/pw:protocol SEND ► ({.*})/);
+      if (sendMatch) {
+        try {
+          const message = JSON.parse(sendMatch[1]);
+
+          // Check if this matches a pending Stagehand call
+          cleanupOldCalls();
+          const pendingIndex = pendingStagehandCalls.findIndex(
+            (call) =>
+              call.method === message.method &&
+              (!call.sessionId || call.sessionId === message.sessionId),
+          );
+
+          if (pendingIndex >= 0) {
+            // This is a Stagehand call - mark it and rewrite the log
+            stagehandMessageIds.add(message.id);
+            pendingStagehandCalls.splice(pendingIndex, 1);
+            chunk = str.replace("pw:protocol", "sh:protocol");
+          }
+        } catch {
+          // Ignore JSON parse errors
+        }
+      }
+
+      // Check if this is a RECV for a Stagehand request
+      const recvMatch = str.match(/pw:protocol ◀ RECV ({.*})/);
+      if (recvMatch) {
+        try {
+          const message = JSON.parse(recvMatch[1]);
+          if (message.id && stagehandMessageIds.has(message.id)) {
+            // This is a response to a Stagehand call
+            chunk = str.replace("pw:protocol", "sh:protocol");
+            stagehandMessageIds.delete(message.id);
+          }
+        } catch {
+          // Ignore JSON parse errors
+        }
+      }
+    }
+
+    return originalStderrWrite.apply(process.stderr, [chunk, ...args]);
+  };
+}
+
+// Mark that a CDP call is about to be made from Stagehand
+export function markStagehandCDPCall(method: string, sessionId?: string) {
+  if (debugNamespaces.includes("sh:protocol")) {
+    pendingStagehandCalls.push({
+      method,
+      timestamp: Date.now(),
+      sessionId,
+    });
+  }
+}
+
+// Simple logger for non-CDP messages
+export function createDebugLogger(namespace: string) {
+  const enabled = debugNamespaces.some((ns) => {
+    if (ns.endsWith("*")) {
+      return namespace.startsWith(ns.slice(0, -1));
+    }
+    return ns === namespace;
+  });
+
+  return {
+    enabled,
+    log: (...args: unknown[]) => {
+      if (!enabled) return;
+
+      const timestamp = new Date().toISOString();
+      const prefix = `${timestamp} ${namespace} `;
+
+      const message = args
+        .map((arg) => {
+          if (typeof arg === "object") {
+            try {
+              return JSON.stringify(arg, null, 2);
+            } catch {
+              // Fallback to String for circular objects
+              return String(arg);
+            }
+          }
+          return String(arg);
+        })
+        .join(" ");
+
+      process.stderr.write(`${prefix}${message}\n`);
+    },
+  };
+}
+
+export const shProtocolDebug = createDebugLogger("sh:protocol");