diff --git a/README.md b/README.md index 3cb2e26..efdc666 100644 --- a/README.md +++ b/README.md @@ -73,6 +73,24 @@ rodney attr "a#link" href # Print attribute value rodney pdf output.pdf # Save page as PDF ``` +### Console logs + +```bash +rodney logs # Print all buffered console logs and exit +rodney logs -n 5 # Print last 5 buffered log entries +rodney logs -f # Print buffered logs, then stream new ones (Ctrl+C to stop) +rodney logs -f -n 5 # Print last 5 buffered logs, then stream new ones +rodney logs --json # JSON output (one object per line) +``` + +Text output format: `[level] message` (e.g. `[error] Uncaught TypeError: ...`). + +JSON output format (one object per line): +```json +{"level":"info","source":"javascript","text":"Page initialized","timestamp":"2024-01-01T12:00:00.123Z"} +{"level":"error","source":"javascript","text":"Uncaught TypeError: ...","timestamp":"2024-01-01T12:00:00.456Z","url":"https://example.com/app.js","line":42} +``` + ### Run JavaScript ```bash diff --git a/help.txt b/help.txt index 79bac7f..f75a61e 100644 --- a/help.txt +++ b/help.txt @@ -21,6 +21,9 @@ Page info: rodney attr Print attribute value rodney pdf [file] Save page as PDF +Console: + rodney logs [-f] [-n N] [--json] Print console logs (default: snapshot, -f to stream) + Interaction: rodney js Evaluate JavaScript expression rodney click Click an element diff --git a/main.go b/main.go index 0b2531a..efee92b 100644 --- a/main.go +++ b/main.go @@ -2,6 +2,7 @@ package main import ( _ "embed" + "bufio" "encoding/base64" "encoding/json" "fmt" @@ -12,6 +13,7 @@ import ( "os" "os/exec" "os/signal" + "sync" "path/filepath" "strconv" "strings" @@ -82,8 +84,10 @@ type State struct { ChromePID int `json:"chrome_pid"` ActivePage int `json:"active_page"` // index into pages list DataDir string `json:"data_dir"` - ProxyPID int `json:"proxy_pid,omitempty"` // PID of auth proxy helper - ProxyPort int `json:"proxy_port,omitempty"` // local port of auth proxy + ProxyPID int `json:"proxy_pid,omitempty"` // PID of auth proxy helper + ProxyPort int `json:"proxy_port,omitempty"` // local port of auth proxy + Logs bool `json:"logs,omitempty"` // console log capture enabled + LoggerPID int `json:"logger_pid,omitempty"` // PID of _logger subprocess } func stateDir() string { @@ -189,6 +193,8 @@ func main() { switch cmd { case "_proxy": cmdInternalProxy(args) // hidden: runs the auth proxy helper + case "_logger": + cmdInternalLogger(args) // hidden: runs the browser console logger case "start": cmdStart(args) case "connect": @@ -269,6 +275,8 @@ func main() { cmdVisible(args) case "assert": cmdAssert(args) + case "logs": + cmdLogs(args) case "ax-tree": cmdAXTree(args) case "ax-find": @@ -320,12 +328,15 @@ func withPage() (*State, *rod.Browser, *rod.Page) { func cmdStart(args []string) { ignoreCertErrors := false + enableLogs := false for i := 0; i < len(args); i++ { switch args[i] { case "--insecure", "-k": ignoreCertErrors = true + case "--logs": + enableLogs = true default: - fatal("unknown flag: %s\nusage: rodney start [--insecure]", args[i]) + fatal("unknown flag: %s\nusage: rodney start [--insecure] [--logs]", args[i]) } } @@ -410,6 +421,22 @@ func cmdStart(args []string) { // Get Chrome PID from the launcher pid := l.PID() + // Launch logger subprocess if --logs was specified + var loggerPID int + if enableLogs { + logsDir := filepath.Join(stateDir(), "logs") + os.MkdirAll(logsDir, 0755) + exe, _ := os.Executable() + cmd := exec.Command(exe, "_logger", debugURL, logsDir) + setSysProcAttr(cmd) + if err := cmd.Start(); err != nil { + fatal("failed to start logger: %v", err) + } + loggerPID = cmd.Process.Pid + cmd.Process.Release() + fmt.Printf("Logger started (PID %d)\n", loggerPID) + } + state := &State{ DebugURL: debugURL, ChromePID: pid, @@ -417,6 +444,8 @@ func cmdStart(args []string) { DataDir: dataDir, ProxyPID: proxyPID, ProxyPort: proxyPort, + Logs: enableLogs, + LoggerPID: loggerPID, } if err := saveState(state); err != nil { @@ -498,6 +527,12 @@ func cmdStop(args []string) { proc.Signal(syscall.SIGTERM) } } + // Kill the logger subprocess if running + if s.LoggerPID > 0 { + if proc, err := os.FindProcess(s.LoggerPID); err == nil { + proc.Signal(syscall.SIGTERM) + } + } removeState() fmt.Println("Chrome stopped") } @@ -549,7 +584,20 @@ func cmdOpen(args []string) { pages, _ := browser.Pages() var page *rod.Page if len(pages) == 0 { - page = browser.MustPage(url) + if s.Logs { + // Create a blank page first so _logger receives TargetTargetCreated and + // calls RuntimeEnable before any scripts execute. RuntimeEnable persists + // across same-target navigations, so inline scripts on the real URL are + // captured. Poll for the log file: trackPage creates it only after + // RuntimeEnable returns, so its existence is an exact ready signal. + page = browser.MustPage("") + waitForLogger(page) + if err := page.Navigate(url); err != nil { + fatal("navigation failed: %v", err) + } + } else { + page = browser.MustPage(url) + } s.ActivePage = 0 saveState(s) } else { @@ -724,6 +772,7 @@ func cmdJS(args []string) { // Wrap bare expressions in a function js := fmt.Sprintf(`() => { return (%s); }`, expr) result, err := page.Eval(js) + if err != nil { fatal("JS error: %v", err) } @@ -1272,7 +1321,16 @@ func cmdNewPage(args []string) { var page *rod.Page if url != "" { - page = browser.MustPage(url) + if s.Logs { + // Same blank-page-first strategy as cmdOpen. + page = browser.MustPage("") + waitForLogger(page) + if err := page.Navigate(url); err != nil { + fatal("navigation failed: %v", err) + } + } else { + page = browser.MustPage(url) + } page.MustWaitLoad() } else { page = browser.MustPage("") @@ -1493,6 +1551,316 @@ func init() { signal.Ignore(syscall.SIGPIPE) } +// --- Console log commands --- + +// consoleEntry holds a normalized console log entry. +type consoleEntry struct { + level string + source string + text string + timestamp float64 // Unix milliseconds + url string + line *int +} + +// formatLogLevel formats a proto.LogLogEntryLevel value as a string. +// Kept for compatibility and unit-testing. +func formatLogLevel(level proto.LogLogEntryLevel) string { + switch level { + case proto.LogLogEntryLevelVerbose: + return "verbose" + case proto.LogLogEntryLevelInfo: + return "info" + case proto.LogLogEntryLevelWarning: + return "warning" + case proto.LogLogEntryLevelError: + return "error" + default: + return string(level) + } +} + +// consoleTypeToLevel maps a Runtime.consoleAPICalled type to a log level string. +func consoleTypeToLevel(t proto.RuntimeConsoleAPICalledType) string { + switch t { + case proto.RuntimeConsoleAPICalledTypeDebug: + return "verbose" + case proto.RuntimeConsoleAPICalledTypeLog, proto.RuntimeConsoleAPICalledTypeInfo, + proto.RuntimeConsoleAPICalledTypeDir, proto.RuntimeConsoleAPICalledTypeDirxml, + proto.RuntimeConsoleAPICalledTypeTable, proto.RuntimeConsoleAPICalledTypeTrace, + proto.RuntimeConsoleAPICalledTypeStartGroup, proto.RuntimeConsoleAPICalledTypeStartGroupCollapsed, + proto.RuntimeConsoleAPICalledTypeEndGroup, proto.RuntimeConsoleAPICalledTypeClear, + proto.RuntimeConsoleAPICalledTypeCount, proto.RuntimeConsoleAPICalledTypeTimeEnd, + proto.RuntimeConsoleAPICalledTypeProfile, proto.RuntimeConsoleAPICalledTypeProfileEnd: + return "info" + case proto.RuntimeConsoleAPICalledTypeWarning: + return "warning" + case proto.RuntimeConsoleAPICalledTypeError, proto.RuntimeConsoleAPICalledTypeAssert: + return "error" + default: + return string(t) + } +} + +// formatConsoleArgs converts Runtime RemoteObjects to a human-readable string. +func formatConsoleArgs(args []*proto.RuntimeRemoteObject) string { + var parts []string + for _, arg := range args { + switch string(arg.Type) { + case "string": + parts = append(parts, arg.Value.Str()) + case "number", "boolean": + parts = append(parts, arg.Value.JSON("", "")) + case "undefined": + parts = append(parts, "undefined") + case "null": + parts = append(parts, "null") + default: + if arg.Description != "" { + parts = append(parts, arg.Description) + } else { + parts = append(parts, arg.Value.JSON("", "")) + } + } + } + return strings.Join(parts, " ") +} + +func printLogEntry(entry consoleEntry, jsonOutput bool) { + if jsonOutput { + ts := time.UnixMilli(int64(entry.timestamp)).UTC() + obj := map[string]interface{}{ + "level": entry.level, + "source": entry.source, + "text": entry.text, + "timestamp": ts.Format("2006-01-02T15:04:05.000Z07:00"), + } + if entry.url != "" { + obj["url"] = entry.url + } + if entry.line != nil { + obj["line"] = *entry.line + } + data, _ := json.Marshal(obj) + fmt.Println(string(data)) + } else { + fmt.Printf("[%s] %s\n", entry.level, entry.text) + } +} + +func cmdLogs(args []string) { + followMode := false + jsonOutput := false + limitN := -1 + + for i := 0; i < len(args); i++ { + switch args[i] { + case "-f", "--follow": + followMode = true + case "--json": + jsonOutput = true + case "-n": + i++ + if i >= len(args) { + fatal("missing value for -n") + } + n, err := strconv.Atoi(args[i]) + if err != nil || n < 1 { + fatal("invalid value for -n: %s", args[i]) + } + limitN = n + default: + fatal("unknown flag: %s\nusage: rodney logs [-f] [-n N] [--json]", args[i]) + } + } + + s, err := loadState() + if err != nil { + fatal("%v", err) + } + if !s.Logs { + fmt.Fprintln(os.Stderr, "logs not enabled (run: rodney start --logs)") + os.Exit(1) + } + browser, err := connectBrowser(s) + if err != nil { + fatal("%v", err) + } + page, err := getActivePage(browser, s) + if err != nil { + fatal("%v", err) + } + + logFile := filepath.Join(stateDir(), "logs", string(page.TargetID)+".ndjson") + + if _, err := os.Stat(logFile); os.IsNotExist(err) { + fmt.Fprintln(os.Stderr, "no console log recorded for this page yet") + os.Exit(0) + } + + if followMode { + fmt.Fprintln(os.Stderr, "Streaming console logs (Ctrl+C to stop)...") + tailLogFile(logFile, limitN, jsonOutput) + return + } + + // Snapshot mode: stream the file to avoid loading it all into memory. + if limitN > 0 { + // Ring buffer: O(limitN) memory regardless of file size. + ring := make([]string, limitN) + count := 0 + scanLogFile(logFile, func(line string) { + ring[count%limitN] = line + count++ + }) + start, n := 0, count + if count > limitN { + start = count % limitN + n = limitN + } + for i := 0; i < n; i++ { + printNDJSONLine(ring[(start+i)%limitN], jsonOutput) + } + } else { + scanLogFile(logFile, func(line string) { + printNDJSONLine(line, jsonOutput) + }) + } +} + +// scanLogFile opens logFile and calls fn for each non-empty line using a +// streaming bufio.Scanner — no whole-file read into memory. +func scanLogFile(logFile string, fn func(string)) { + f, err := os.Open(logFile) + if err != nil { + return + } + defer f.Close() + scanner := bufio.NewScanner(f) + for scanner.Scan() { + if line := scanner.Text(); line != "" { + fn(line) + } + } +} + +// printNDJSONLine prints a single NDJSON log line. +// In JSON mode it prints verbatim; otherwise it formats as "[level] text". +func printNDJSONLine(line string, jsonOutput bool) { + if jsonOutput { + fmt.Println(line) + return + } + var obj struct { + Level string `json:"level"` + Text string `json:"text"` + } + if err := json.Unmarshal([]byte(line), &obj); err == nil { + fmt.Printf("[%s] %s\n", obj.Level, obj.Text) + } +} + +// tailLogFile follows a log file, printing new lines as they are appended. +// If limitN > 0, prints the last N existing lines first, then follows new content. +// If limitN <= 0, seeks to the end immediately and only shows new entries. +func tailLogFile(logFile string, limitN int, jsonOutput bool) { + f, err := os.Open(logFile) + if err != nil { + fatal("failed to open log file: %v", err) + } + defer f.Close() + + if limitN > 0 { + // Ring buffer: stream last N lines without loading the whole file. + ring := make([]string, limitN) + count := 0 + scanner := bufio.NewScanner(f) + for scanner.Scan() { + if line := scanner.Text(); line != "" { + ring[count%limitN] = line + count++ + } + } + start, n := 0, count + if count > limitN { + start = count % limitN + n = limitN + } + for i := 0; i < n; i++ { + printNDJSONLine(ring[(start+i)%limitN], jsonOutput) + } + } + // Seek to end to tail only new content (scanner may have over-read into + // a bufio buffer, but explicit SeekEnd corrects the OS file position). + f.Seek(0, io.SeekEnd) + + sigCh := make(chan os.Signal, 1) + signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) + + buf := make([]byte, 4096) + var partial string + for { + select { + case <-sigCh: + return + default: + } + n, _ := f.Read(buf) + if n > 0 { + partial += string(buf[:n]) + for { + idx := strings.Index(partial, "\n") + if idx < 0 { + break + } + line := partial[:idx] + partial = partial[idx+1:] + if line != "" { + printNDJSONLine(line, jsonOutput) + } + } + } else { + time.Sleep(50 * time.Millisecond) + } + } +} + +func makeConsoleEntry(e *proto.RuntimeConsoleAPICalled) consoleEntry { + entry := consoleEntry{ + level: consoleTypeToLevel(e.Type), + source: "javascript", + text: formatConsoleArgs(e.Args), + timestamp: float64(e.Timestamp), + } + if e.StackTrace != nil && len(e.StackTrace.CallFrames) > 0 { + frame := e.StackTrace.CallFrames[0] + entry.url = frame.URL + line := frame.LineNumber + entry.line = &line + } + return entry +} + +// marshalConsoleEntry serializes a consoleEntry to a JSON line for the NDJSON log file. +func marshalConsoleEntry(entry consoleEntry) string { + ts := time.UnixMilli(int64(entry.timestamp)).UTC() + obj := map[string]interface{}{ + "level": entry.level, + "source": entry.source, + "text": entry.text, + "timestamp": ts.Format("2006-01-02T15:04:05.000Z07:00"), + } + if entry.url != "" { + obj["url"] = entry.url + } + if entry.line != nil { + obj["line"] = *entry.line + } + data, _ := json.Marshal(obj) + return string(data) +} + + // --- Accessibility commands --- func cmdAXTree(args []string) { @@ -1834,6 +2202,119 @@ func formatAXNodeDetailJSON(node *proto.AccessibilityAXNode) string { return string(data) } +// --- Console logger infrastructure --- + +// cmdInternalLogger is a hidden subcommand: rodney _logger +// It connects to the running Chrome instance, enables target discovery, and +// immediately subscribes to console events on each page as it is created. +func cmdInternalLogger(args []string) { + if len(args) < 2 { + fatal("usage: rodney _logger ") + } + debugURL := args[0] + logsDir := args[1] + + browser := rod.New().ControlURL(debugURL).MustConnect() + os.MkdirAll(logsDir, 0755) + + var mu sync.Mutex + tracking := map[proto.TargetTargetID]bool{} + + // subscribeToPage marks the target as tracked and starts trackPage in a + // goroutine. It looks up the *rod.Page by target ID; retries briefly in + // case GetTargets lags slightly behind the TargetCreated event. + subscribeToPage := func(targetID proto.TargetTargetID) { + mu.Lock() + already := tracking[targetID] + if !already { + tracking[targetID] = true + } + mu.Unlock() + if already { + return + } + go func() { + for i := 0; i < 10; i++ { + pages, _ := browser.Pages() + for _, p := range pages { + if p.TargetID == targetID { + trackPage(p, logsDir) + return + } + } + time.Sleep(10 * time.Millisecond) + } + }() + } + + // TargetSetDiscoverTargets causes Chrome to fire TargetTargetCreated for + // all existing targets immediately, and for every new target thereafter. + // Set up the listener first so we don't miss events. + wait := browser.EachEvent(func(e *proto.TargetTargetCreated) bool { + if e.TargetInfo.Type == "page" { + subscribeToPage(e.TargetInfo.TargetID) + } + return false + }) + proto.TargetSetDiscoverTargets{Discover: true}.Call(browser) + go wait() + + sigCh := make(chan os.Signal, 1) + signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) + <-sigCh +} + +// trackPage subscribes to console events for a single page and writes them to +// a per-page NDJSON file. Blocks until the page is closed or context cancelled. +// +// The log file is opened *after* RuntimeEnable returns (which blocks until +// Chrome acks the command). This means the file's creation on disk is an exact +// signal that Chrome is ready to send events — waitForLogger relies on this. +func trackPage(page *rod.Page, logsDir string) { + logFile := filepath.Join(logsDir, string(page.TargetID)+".ndjson") + + // Register the listener before enabling so no events are missed. + // f starts nil; callback skips writes until f is set below. + var f *os.File + wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { + if f != nil { + fmt.Fprintln(f, marshalConsoleEntry(makeConsoleEntry(e))) + f.Sync() + } + return false + }) + + // Enable runtime; blocks until Chrome acknowledges. + if err := (proto.RuntimeEnable{}).Call(page); err != nil { + return + } + + // Open the log file now. Its appearance on disk is the ready signal + // consumed by waitForLogger in cmdOpen/cmdNewPage. + var err error + f, err = os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + if err != nil { + return + } + defer f.Close() + + wait() // blocks until page closed or context cancelled; f is non-nil +} + +// waitForLogger polls until _logger has subscribed to page and called +// RuntimeEnable (signalled by the log file appearing on disk), or until a +// 500ms timeout expires. Called before navigating a freshly-created blank page. +func waitForLogger(page *rod.Page) { + logFile := filepath.Join(stateDir(), "logs", string(page.TargetID)+".ndjson") + deadline := time.Now().Add(500 * time.Millisecond) + for time.Now().Before(deadline) { + if _, err := os.Stat(logFile); err == nil { + return + } + time.Sleep(5 * time.Millisecond) + } +} + // --- Auth proxy for environments with authenticated HTTP proxies --- // detectProxy checks for HTTPS_PROXY/HTTP_PROXY with credentials. diff --git a/main_test.go b/main_test.go index 79ee87c..9e72301 100644 --- a/main_test.go +++ b/main_test.go @@ -11,6 +11,7 @@ import ( "os" "path/filepath" "strings" + "sync" "testing" "time" @@ -51,6 +52,7 @@ func TestMain(m *testing.M) { mux.HandleFunc("/download", handleDownload) mux.HandleFunc("/testfile.txt", handleTestFile) mux.HandleFunc("/empty", handleEmpty) + mux.HandleFunc("/logs", handleLogs) server := httptest.NewServer(mux) env = &testEnv{browser: browser, server: server} @@ -150,6 +152,21 @@ func handleEmpty(w http.ResponseWriter, r *http.Request) { `)) } +func handleLogs(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "text/html") + w.Write([]byte(` + +Logs Test Page + + + +`)) +} + // --- Helper: navigate to a fixture and return the page --- func navigateTo(t *testing.T, path string) *rod.Page { @@ -1148,3 +1165,167 @@ func TestInsecureFlag_WithSelfSignedCert(t *testing.T) { } }) } + +// ===================== +// logs command tests +// ===================== + +// collectConsoleMsgs enables the Runtime domain, emits js, collects up to +// maxCount events (or waits timeout), and returns the collected entries. +// It does NOT use page.Context() wrapping to avoid event-routing issues. +func collectConsoleMsgs(page *rod.Page, js string, maxCount int, timeout time.Duration) (texts []string, levels []string) { + var mu sync.Mutex + done := make(chan struct{}) + var once sync.Once + closeDone := func() { once.Do(func() { close(done) }) } + + wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { + mu.Lock() + texts = append(texts, formatConsoleArgs(e.Args)) + levels = append(levels, consoleTypeToLevel(e.Type)) + n := len(texts) + mu.Unlock() + if n >= maxCount { + closeDone() + return true // stop + } + return false + }) + + (proto.RuntimeEnable{}).Call(page) //nolint + page.MustEval(js) + + go func() { + wait() + closeDone() + }() + + select { + case <-done: + case <-time.After(timeout): + } + return +} + +func TestLogs_SnapshotCapture(t *testing.T) { + page := navigateTo(t, "/") + + texts, _ := collectConsoleMsgs(page, `() => { + console.log("info message from logs test"); + console.warn("warning message from logs test"); + console.error("error message from logs test"); + }`, 3, 3*time.Second) + + if len(texts) < 3 { + t.Fatalf("expected at least 3 log entries, got %d: %v", len(texts), texts) + } + + found := false + for _, text := range texts { + if strings.Contains(text, "info message from logs test") { + found = true + break + } + } + if !found { + t.Errorf("expected 'info message from logs test' in entries, got: %v", texts) + } +} + +func TestLogs_ConsoleTypes(t *testing.T) { + page := navigateTo(t, "/") + + _, levels := collectConsoleMsgs(page, `() => { + console.warn("warning entry for level test"); + console.error("error entry for level test"); + }`, 2, 3*time.Second) + + levelSet := make(map[string]bool) + for _, l := range levels { + levelSet[l] = true + } + + if !levelSet["warning"] { + t.Errorf("expected a warning-level entry, got levels: %v", levels) + } + if !levelSet["error"] { + t.Errorf("expected an error-level entry, got levels: %v", levels) + } +} + + +func TestLogs_FormatLogLevel(t *testing.T) { + tests := []struct { + level proto.LogLogEntryLevel + expected string + }{ + {proto.LogLogEntryLevelVerbose, "verbose"}, + {proto.LogLogEntryLevelInfo, "info"}, + {proto.LogLogEntryLevelWarning, "warning"}, + {proto.LogLogEntryLevelError, "error"}, + {proto.LogLogEntryLevel("custom"), "custom"}, + } + for _, tt := range tests { + got := formatLogLevel(tt.level) + if got != tt.expected { + t.Errorf("formatLogLevel(%q) = %q, want %q", tt.level, got, tt.expected) + } + } +} + +func TestLogs_ConsoleTypeToLevel(t *testing.T) { + tests := []struct { + ct proto.RuntimeConsoleAPICalledType + expected string + }{ + {proto.RuntimeConsoleAPICalledTypeDebug, "verbose"}, + {proto.RuntimeConsoleAPICalledTypeLog, "info"}, + {proto.RuntimeConsoleAPICalledTypeInfo, "info"}, + {proto.RuntimeConsoleAPICalledTypeWarning, "warning"}, + {proto.RuntimeConsoleAPICalledTypeError, "error"}, + {proto.RuntimeConsoleAPICalledTypeAssert, "error"}, + {proto.RuntimeConsoleAPICalledTypeDir, "info"}, + } + for _, tt := range tests { + got := consoleTypeToLevel(tt.ct) + if got != tt.expected { + t.Errorf("consoleTypeToLevel(%q) = %q, want %q", tt.ct, got, tt.expected) + } + } +} + +func TestLogs_ScanLogFile(t *testing.T) { + dir := t.TempDir() + logFile := filepath.Join(dir, "test.ndjson") + + content := `{"level":"info","source":"javascript","text":"hello","timestamp":"2024-01-01T12:00:00.000Z"} +{"level":"warning","source":"javascript","text":"world","timestamp":"2024-01-01T12:00:01.000Z"} +` + if err := os.WriteFile(logFile, []byte(content), 0644); err != nil { + t.Fatalf("failed to write log file: %v", err) + } + + var lines []string + scanLogFile(logFile, func(line string) { lines = append(lines, line) }) + if len(lines) != 2 { + t.Fatalf("expected 2 lines, got %d: %v", len(lines), lines) + } + + var obj struct { + Level string `json:"level"` + Text string `json:"text"` + } + if err := json.Unmarshal([]byte(lines[0]), &obj); err != nil { + t.Fatalf("failed to unmarshal line 0: %v", err) + } + if obj.Level != "info" || obj.Text != "hello" { + t.Errorf("line 0: got level=%q text=%q, want level=%q text=%q", obj.Level, obj.Text, "info", "hello") + } + + if err := json.Unmarshal([]byte(lines[1]), &obj); err != nil { + t.Fatalf("failed to unmarshal line 1: %v", err) + } + if obj.Level != "warning" || obj.Text != "world" { + t.Errorf("line 1: got level=%q text=%q, want level=%q text=%q", obj.Level, obj.Text, "warning", "world") + } +} diff --git a/notes/cdp-console-logs.md b/notes/cdp-console-logs.md new file mode 100644 index 0000000..298c03b --- /dev/null +++ b/notes/cdp-console-logs.md @@ -0,0 +1,135 @@ +# CDP console log capture — findings + +Research and empirical testing done while implementing `rodney logs`. + +## The three CDP mechanisms + +### 1. `Runtime.consoleAPICalled` (Runtime domain) + +- Fires for every `console.log/warn/error/debug/info/...` call made by JavaScript + running in the page, including calls made via `Runtime.evaluate` +- **Live only** — no replay of past events +- When `Runtime.enable` is called in a new CDP session, Chrome does *not* replay + previous `consoleAPICalled` events to that session +- This is what rodney uses for all console capture + +### 2. `Log.entryAdded` (Log domain) + +- Fires for **browser-generated** log entries: network errors, CSP violations, + mixed-content warnings, deprecation notices, intervention messages, etc. +- Does **not** fire for JavaScript `console.*` API calls (those go exclusively + to `Runtime.consoleAPICalled`) +- `Log.enable` does replay buffered browser-level entries to new sessions + +### 3. `Console.messageAdded` (Console domain — deprecated) + +- The older, deprecated predecessor to the Runtime + Log split +- Replays collected messages on `Console.enable`, per the CDP spec +- In practice (Chrome ~124+) empirically found to replay 0 messages +- Playwright never uses this domain + +## Key discovery: `Runtime.consoleAPICalled` IS broadcast cross-session + +Empirically confirmed: `Runtime.consoleAPICalled` events are broadcast to **all** +CDP sessions that have called `Runtime.enable` on the same target, regardless of +which session triggered the event. This includes events triggered by +`Runtime.evaluate`. + +This was confirmed by observing double-writes to the NDJSON log file when both +a `_logger` subprocess and an in-process EachEvent handler were listening +simultaneously — both received the same event. + +Consequence: the background `_logger` subprocess **can** capture console calls +made through `rodney js`, as long as it has called `Runtime.enable` before those +calls happen. + +## Timing constraint: inline scripts race against subscription + +`Runtime.consoleAPICalled` is live-only — events fired before a session calls +`Runtime.enable` are not replayed. This creates a race for pages that call +`console.*` synchronously in inline scripts: + +```html + +``` + +If the `_logger` process is polling for new pages (100ms intervals), it will +almost always miss inline-script console calls because the page loads before +`_logger` subscribes. + +## Current implementation: `_logger` subprocess with `Target.targetCreated` + +`rodney start --logs` spawns a `_logger` subprocess immediately. It uses +`Target.setDiscoverTargets` + `EachEvent(TargetTargetCreated)` to detect new +pages the moment Chrome creates their target — microseconds after creation, +before navigation begins. + +To close the remaining race for inline scripts, `cmdOpen` and `cmdNewPage` +use a blank-page-first strategy when `--logs` is active: + +1. Create a blank page (`browser.MustPage("")`) — triggers `TargetTargetCreated` + in `_logger` immediately +2. `_logger` calls `RuntimeEnable` on the blank page; `RuntimeEnable` is a + synchronous CDP call that blocks until Chrome acknowledges — after it returns, + Chrome will send events for any subsequent console call on this target +3. `_logger`'s `trackPage` opens the `.ndjson` log file *after* `RuntimeEnable` + returns — the file's appearance on disk is an exact ready signal +4. `cmdOpen` polls (`waitForLogger`) for the log file to appear (5ms intervals, + 500ms timeout) — typically resolves in ~10–15ms +5. `cmdOpen` navigates to the real URL — `RuntimeEnable` persists across + same-target navigations, so all inline scripts are captured + +`rodney logs` requires `rodney start --logs`; it errors with a helpful message +otherwise. + +### What `_logger` captures + +| Source | Captured | +|--------|----------| +| Inline `