From 98df9adfdc0dbe94e9a2f267ed104dffe72ace9b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Wed, 18 Feb 2026 21:04:00 +0100 Subject: [PATCH 1/9] Add `rodney logs` command for capturing browser console output Adds `rodney logs [-f] [-n N] [--json]` to capture JavaScript console messages (log/warn/error/debug) from the active Chrome tab via CDP Runtime.consoleAPICalled. Snapshot mode (default) collects events for 100ms then exits; follow mode (-f) streams until Ctrl+C. Uses the Runtime domain rather than the Log domain because headless Chrome does not reliably deliver Log.entryAdded events for JavaScript console calls. Also avoids page.Context() wrapping for EachEvent listeners, which creates a detached copy with a separate event publisher. Co-Authored-By: Claude Sonnet 4.6 --- README.md | 18 +++++ help.txt | 3 + main.go | 225 +++++++++++++++++++++++++++++++++++++++++++++++++++ main_test.go | 144 +++++++++++++++++++++++++++++++++ 4 files changed, 390 insertions(+) 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..c5fbfe9 100644 --- a/main.go +++ b/main.go @@ -15,6 +15,7 @@ import ( "path/filepath" "strconv" "strings" + "sync" "syscall" "time" @@ -269,6 +270,8 @@ func main() { cmdVisible(args) case "assert": cmdAssert(args) + case "logs": + cmdLogs(args) case "ax-tree": cmdAXTree(args) case "ax-find": @@ -1493,6 +1496,228 @@ 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) + } + browser, err := connectBrowser(s) + if err != nil { + fatal("%v", err) + } + page, err := getActivePage(browser, s) + if err != nil { + fatal("%v", err) + } + + if followMode { + // Follow mode: print entries as they arrive, block until signal. + fmt.Fprintln(os.Stderr, "Streaming console logs (Ctrl+C to stop)...") + + // Track how many buffered entries were already printed (for -n handling) + // before streaming starts. Since Runtime domain has no buffered replay, + // we collect a brief snapshot first, then stream. + var mu sync.Mutex + var snapshot []consoleEntry + + page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { + entry := makeConsoleEntry(e) + mu.Lock() + snapshot = append(snapshot, entry) + mu.Unlock() + return false + }) + + if err := (proto.RuntimeEnable{}).Call(page); err != nil { + fatal("failed to enable Runtime domain: %v", err) + } + + sigCh := make(chan os.Signal, 1) + signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) + <-sigCh + + mu.Lock() + collected := snapshot + mu.Unlock() + + if limitN > 0 && len(collected) > limitN { + collected = collected[len(collected)-limitN:] + } + for _, entry := range collected { + printLogEntry(entry, jsonOutput) + } + return + } + + // Snapshot mode: collect events for a brief window then print. + var mu sync.Mutex + var entries []consoleEntry + + page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { + entry := makeConsoleEntry(e) + mu.Lock() + entries = append(entries, entry) + mu.Unlock() + return false + }) + + if err := (proto.RuntimeEnable{}).Call(page); err != nil { + fatal("failed to enable Runtime domain: %v", err) + } + + time.Sleep(100 * time.Millisecond) + + mu.Lock() + snapshot := entries + mu.Unlock() + + if limitN > 0 && len(snapshot) > limitN { + snapshot = snapshot[len(snapshot)-limitN:] + } + + for _, entry := range snapshot { + printLogEntry(entry, jsonOutput) + } +} + +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 +} + // --- Accessibility commands --- func cmdAXTree(args []string) { diff --git a/main_test.go b/main_test.go index 79ee87c..3f8fd5c 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,130 @@ 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) + } + } +} From 454e11f14d2acbc8601b3ec292d70aa15d3efe93 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Wed, 18 Feb 2026 21:08:53 +0100 Subject: [PATCH 2/9] Fix logs -f: print entries immediately instead of buffering until Ctrl+C Co-Authored-By: Claude Sonnet 4.6 --- main.go | 24 ++---------------------- 1 file changed, 2 insertions(+), 22 deletions(-) diff --git a/main.go b/main.go index c5fbfe9..74f7f02 100644 --- a/main.go +++ b/main.go @@ -1633,20 +1633,11 @@ func cmdLogs(args []string) { } if followMode { - // Follow mode: print entries as they arrive, block until signal. + // Follow mode: print each entry immediately as it arrives. fmt.Fprintln(os.Stderr, "Streaming console logs (Ctrl+C to stop)...") - // Track how many buffered entries were already printed (for -n handling) - // before streaming starts. Since Runtime domain has no buffered replay, - // we collect a brief snapshot first, then stream. - var mu sync.Mutex - var snapshot []consoleEntry - page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { - entry := makeConsoleEntry(e) - mu.Lock() - snapshot = append(snapshot, entry) - mu.Unlock() + printLogEntry(makeConsoleEntry(e), jsonOutput) return false }) @@ -1657,17 +1648,6 @@ func cmdLogs(args []string) { sigCh := make(chan os.Signal, 1) signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) <-sigCh - - mu.Lock() - collected := snapshot - mu.Unlock() - - if limitN > 0 && len(collected) > limitN { - collected = collected[len(collected)-limitN:] - } - for _, entry := range collected { - printLogEntry(entry, jsonOutput) - } return } From e7a3bb9949dc05472506ffc0985edb0c96b2dbd5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Thu, 19 Feb 2026 09:44:43 +0100 Subject: [PATCH 3/9] Rewrite `rodney logs` to use file-backed NDJSON log captured in-process MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Each `rodney js` invocation now captures Runtime.consoleAPICalled events within its own CDP session (the only session that receives evaluate-triggered console calls) and appends them as NDJSON to /logs/.ndjson. `rodney logs` reads that file directly; `rodney logs -f` tails it. The background _logger subprocess approach was removed — it couldn't capture `rodney js` console output due to Chrome's cross-session CDP limitation, so it added complexity without covering the primary use case. Co-Authored-By: Claude Sonnet 4.6 --- main.go | 178 +++++++++++++++++++++++++++++++------- main_test.go | 50 +++++++++++ notes/cdp-console-logs.md | 157 +++++++++++++++++++++++++++++++++ 3 files changed, 352 insertions(+), 33 deletions(-) create mode 100644 notes/cdp-console-logs.md diff --git a/main.go b/main.go index 74f7f02..94a7830 100644 --- a/main.go +++ b/main.go @@ -15,7 +15,6 @@ import ( "path/filepath" "strconv" "strings" - "sync" "syscall" "time" @@ -724,9 +723,32 @@ func cmdJS(args []string) { expr := strings.Join(args, " ") _, _, page := withPage() + // Capture console.* events in-process and append to the per-page NDJSON log file. + // Chrome does not broadcast Runtime.consoleAPICalled cross-session, so we must + // capture them here within the same CDP session as the evaluate call. + logsDir := filepath.Join(stateDir(), "logs") + os.MkdirAll(logsDir, 0755) + logFile := filepath.Join(logsDir, string(page.TargetID)+".ndjson") + logF, _ := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + if logF != nil { + wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { + fmt.Fprintln(logF, marshalConsoleEntry(makeConsoleEntry(e))) + logF.Sync() + return false + }) + (proto.RuntimeEnable{}).Call(page) + go wait() + } + // Wrap bare expressions in a function js := fmt.Sprintf(`() => { return (%s); }`, expr) result, err := page.Eval(js) + + if logF != nil { + time.Sleep(50 * time.Millisecond) // let the EachEvent goroutine flush queued events + logF.Close() + } + if err != nil { fatal("JS error: %v", err) } @@ -1632,54 +1654,124 @@ func cmdLogs(args []string) { 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 { - // Follow mode: print each entry immediately as it arrives. fmt.Fprintln(os.Stderr, "Streaming console logs (Ctrl+C to stop)...") + tailLogFile(logFile, limitN, jsonOutput) + return + } - page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { - printLogEntry(makeConsoleEntry(e), jsonOutput) - return false - }) + // Snapshot mode: read NDJSON file + lines := readLogLines(logFile) + if limitN > 0 && len(lines) > limitN { + lines = lines[len(lines)-limitN:] + } + for _, line := range lines { + printNDJSONLine(line, jsonOutput) + } +} - if err := (proto.RuntimeEnable{}).Call(page); err != nil { - fatal("failed to enable Runtime domain: %v", err) +// readLogLines reads an NDJSON log file and returns non-empty lines. +func readLogLines(logFile string) []string { + data, err := os.ReadFile(logFile) + if err != nil { + return nil + } + var lines []string + for _, line := range strings.Split(string(data), "\n") { + if line != "" { + lines = append(lines, line) } + } + return lines +} - sigCh := make(chan os.Signal, 1) - signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) - <-sigCh +// 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) + } +} - // Snapshot mode: collect events for a brief window then print. - var mu sync.Mutex - var entries []consoleEntry - - page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { - entry := makeConsoleEntry(e) - mu.Lock() - entries = append(entries, entry) - mu.Unlock() - return false - }) - - if err := (proto.RuntimeEnable{}).Call(page); err != nil { - fatal("failed to enable Runtime domain: %v", err) +// 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() - time.Sleep(100 * time.Millisecond) + if limitN > 0 { + // Read current content, print last N lines, then seek to end + data, _ := io.ReadAll(f) + lines := readNDJSONLines(string(data)) + if len(lines) > limitN { + lines = lines[len(lines)-limitN:] + } + for _, line := range lines { + printNDJSONLine(line, jsonOutput) + } + } + // Seek to end to tail only new content + f.Seek(0, io.SeekEnd) - mu.Lock() - snapshot := entries - mu.Unlock() + sigCh := make(chan os.Signal, 1) + signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) - if limitN > 0 && len(snapshot) > limitN { - snapshot = snapshot[len(snapshot)-limitN:] + 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) + } } +} - for _, entry := range snapshot { - printLogEntry(entry, jsonOutput) +// readNDJSONLines splits a string into non-empty lines. +func readNDJSONLines(content string) []string { + var lines []string + for _, line := range strings.Split(content, "\n") { + if line != "" { + lines = append(lines, line) + } } + return lines } func makeConsoleEntry(e *proto.RuntimeConsoleAPICalled) consoleEntry { @@ -1698,6 +1790,26 @@ func makeConsoleEntry(e *proto.RuntimeConsoleAPICalled) consoleEntry { 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) { diff --git a/main_test.go b/main_test.go index 3f8fd5c..aace76a 100644 --- a/main_test.go +++ b/main_test.go @@ -1253,6 +1253,7 @@ func TestLogs_ConsoleTypes(t *testing.T) { } } + func TestLogs_FormatLogLevel(t *testing.T) { tests := []struct { level proto.LogLogEntryLevel @@ -1292,3 +1293,52 @@ func TestLogs_ConsoleTypeToLevel(t *testing.T) { } } } + +func TestLogs_ReadLogLines(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) + } + + lines := readLogLines(logFile) + 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") + } + + // Verify -n slicing works correctly + if len(lines) > 1 { + tail := lines[len(lines)-1:] + if len(tail) != 1 { + t.Errorf("tail slice expected 1 line, got %d", len(tail)) + } + if err := json.Unmarshal([]byte(tail[0]), &obj); err != nil { + t.Fatalf("failed to unmarshal tail line: %v", err) + } + if obj.Level != "warning" || obj.Text != "world" { + t.Errorf("tail: 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..c534135 --- /dev/null +++ b/notes/cdp-console-logs.md @@ -0,0 +1,157 @@ +# 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 cross-session replay +- 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 **follow mode** (`rodney logs -f`) and what + Playwright uses for `page.on('console')` + +### 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 +- This is what rodney uses for **snapshot mode** (`rodney logs`) + +### 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, consistent + with the Log domain behaviour above +- Playwright never uses this domain + +## Why `rodney js "console.log(...)"` doesn't appear in `rodney logs` + +Each `rodney` invocation is a **separate OS process with a separate CDP session**. + +When `rodney js "console.log('hello')"` runs: +1. A new CDP session is opened +2. `Runtime.evaluate` is called — `console.log` fires +3. The session disconnects + +When `rodney logs` runs next: +1. A new CDP session is opened +2. `Runtime.enable` is called +3. Chrome does **not** replay the previous session's `consoleAPICalled` events + +There is no CDP mechanism that makes cross-session `console.*` replay possible. +We tested and confirmed: `Runtime.disable` + `Runtime.enable`, `Log.enable`, and +`Console.enable` all return 0 events for messages produced by a prior session's +`Runtime.evaluate`. + +## How Playwright avoids this problem + +Playwright maintains a **persistent CDP connection** for the entire test/automation +lifetime. `page.on('console')` hooks into `Runtime.consoleAPICalled` on that +same persistent session, so it captures every `console.*` call — including those +from `page.evaluate(...)` — because they all happen within the same session. + +Relevant detail from Playwright source (`crPage.ts`): when `Runtime.enable` is +first called, Chrome *does* replay the last ~1000 console messages with +`executionContextId = 0`. Playwright explicitly **drops** these replays because +(a) the original execution context is gone so args can't be inspected, and +(b) they arrive before user listeners are registered anyway. + +```typescript +// crPage.ts – FrameSession._onConsoleAPI +if (event.executionContextId === 0) { + // DevTools protocol stores the last 1000 console messages… + // Ignore these messages since there's no execution context we can use. + return; +} +``` + +## Considered workaround: JS interceptor + +We briefly implemented a `window.__rodney_logs` buffer — `rodney logs` would +inject an override of `console.*` that stores entries in `window.__rodney_logs`, +and subsequent invocations would read and clear that buffer. + +This worked but was rejected because: +- It mutates the page's JavaScript environment +- It only captures messages after the first `rodney logs` invocation +- It feels wrong for a debugging tool to modify what it observes + +## Key discovery: `Runtime.consoleAPICalled` is NOT broadcast cross-session + +Empirically confirmed: when Session A calls `Runtime.evaluate` and the evaluated +code calls `console.log`, Chrome delivers the `Runtime.consoleAPICalled` event +**only to Session A**. A separate Session B with `Runtime.enable` active on the +same page target does **not** receive the event. + +This means the background `_logger` approach (which connects via its own CDP +session) **cannot capture `console.log` calls made through `rodney js`**. + +Page-native console calls (inline scripts, timers, event handlers — anything +that runs outside of `Runtime.evaluate`) *are* broadcast to all sessions with +Runtime enabled. So the logger does capture those, just not CDP-evaluate events. + +Test used to confirm (simplified): +```go +// Session A: registers EachEvent + RuntimeEnable, blocks waiting for events +// Session B: calls page.MustEval(`() => { console.log("cross-session-test") }`) +// Result: Session A receives nothing → timeout +``` + +## Considered alternative: Chrome `--enable-logging` file + +Chrome supports `--enable-logging --log-level=0` which writes all JavaScript +`console.*` calls to `/chrome_debug.log`, regardless of which CDP +session triggered them. This solves the cross-session problem entirely. + +Log line format: +``` +[PID:TID:DATE:INFO:CONSOLE(N)] "message text", source: https://example.com (42) +``` + +Empirically confirmed (Chrome ~128): +- Captures `console.log`, `console.warn`, `console.error` from inline scripts ✓ +- Captures `console.log` fired via `Runtime.evaluate` in a separate session ✓ +- All levels (`log`, `warn`, `error`) map to `INFO:CONSOLE` — **no severity info** ✗ +- Single file for the entire browser session — not scoped per page ✗ + (URL in the `source:` field enables filtering, but adds complexity) +- Requires baking `--enable-logging` into `rodney start` ✗ + +Rejected because losing level info (`[info]`/`[warning]`/`[error]`) is a +meaningful regression, and the per-page scoping would need extra work. +Preserved here as a viable fallback if the current approach proves insufficient. + +## Current implementation (in-process capture in `cmdJS`) + +The background `_logger` subprocess approach was implemented and then removed. +It was unnecessary because the primary use case — capturing `console.*` calls +made via `rodney js` — cannot be served by a separate CDP session anyway (see +"Key discovery" above). Page-native console events between CLI invocations are +not a common enough use case to justify the complexity. + +Instead, `rodney js` captures console events **in-process**, within the same CDP +session that runs the `Runtime.evaluate` call: + +1. Before evaluating, open (or create) `/logs/.ndjson` +2. Register an `EachEvent` handler for `Runtime.consoleAPICalled` +3. Enable the Runtime domain and start the event loop (`go wait()`) +4. Evaluate the JS expression +5. Sleep 50 ms to let the event goroutine flush any queued events +6. Close the log file + +`rodney logs` reads the NDJSON file directly — no CDP session required. + +| Mode | Mechanism | What it captures | +|------|-----------|-----------------| +| `rodney logs` | Read NDJSON file | All `console.*` calls made via `rodney js` | +| `rodney logs -f` | Tail NDJSON file | Same, plus new entries as they arrive | +| `rodney logs -n N` | Read last N lines from NDJSON file | Last N `console.*` calls | + +Log files live at `/logs/.ndjson` and persist until the +state directory is cleaned up manually or a new session is started. From 8d699422a5cfbf071bb16c5960db757315b50e18 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Thu, 19 Feb 2026 10:20:00 +0100 Subject: [PATCH 4/9] Restore _logger subprocess with --logs feature flag + stderr console output - Add `Logs` and `LoggerPID` fields to State struct - Add `--logs` flag to `rodney start`; gates logger infrastructure - Restore `rodney _logger ` hidden subcommand that polls browser.Pages() every 100ms and writes page-native console events to per-page NDJSON files - Add `startBrowserLogger(s)` called from `cmdOpen`; spawns one _logger process, stores PID in state, idempotent via signal(0) check - Add `setupConsoleCapture(s, page)` helper used by `cmdJS` and `cmdAssert`: always prints Runtime.consoleAPICalled events to stderr; also appends to .ndjson when --logs is enabled - `cmdStop` now SIGTERMs LoggerPID before removing state - `cmdLogs` exits with a helpful error when logs are not enabled Co-Authored-By: Claude Sonnet 4.6 --- main.go | 172 ++++++++++++++++++++++++++++++++++++++++++++++++-------- 1 file changed, 147 insertions(+), 25 deletions(-) diff --git a/main.go b/main.go index 94a7830..5af8224 100644 --- a/main.go +++ b/main.go @@ -82,8 +82,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 +191,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": @@ -322,12 +326,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]) } } @@ -419,6 +426,7 @@ func cmdStart(args []string) { DataDir: dataDir, ProxyPID: proxyPID, ProxyPort: proxyPort, + Logs: enableLogs, } if err := saveState(state); err != nil { @@ -500,6 +508,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") } @@ -564,6 +578,7 @@ func cmdOpen(args []string) { } } page.MustWaitLoad() + startBrowserLogger(s) info, _ := page.Info() if info != nil { fmt.Println(info.Title) @@ -721,33 +736,18 @@ func cmdJS(args []string) { fatal("usage: rodney js ") } expr := strings.Join(args, " ") - _, _, page := withPage() + s, _, page := withPage() - // Capture console.* events in-process and append to the per-page NDJSON log file. - // Chrome does not broadcast Runtime.consoleAPICalled cross-session, so we must - // capture them here within the same CDP session as the evaluate call. - logsDir := filepath.Join(stateDir(), "logs") - os.MkdirAll(logsDir, 0755) - logFile := filepath.Join(logsDir, string(page.TargetID)+".ndjson") - logF, _ := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) - if logF != nil { - wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { - fmt.Fprintln(logF, marshalConsoleEntry(makeConsoleEntry(e))) - logF.Sync() - return false - }) - (proto.RuntimeEnable{}).Call(page) - go wait() - } + // Capture console.* events: always prints to stderr; also writes to NDJSON if --logs enabled. + // Chrome does not broadcast Runtime.consoleAPICalled cross-session for evaluate calls, + // so we must capture them here within the same CDP session. + cleanup := setupConsoleCapture(s, page) // Wrap bare expressions in a function js := fmt.Sprintf(`() => { return (%s); }`, expr) result, err := page.Eval(js) - if logF != nil { - time.Sleep(50 * time.Millisecond) // let the EachEvent goroutine flush queued events - logF.Close() - } + cleanup() if err != nil { fatal("JS error: %v", err) @@ -1466,10 +1466,12 @@ func cmdAssert(args []string) { fatal("usage: rodney assert [expected] [--message msg]") } - _, _, page := withPage() + s, _, page := withPage() + cleanup := setupConsoleCapture(s, page) js := fmt.Sprintf(`() => { return (%s); }`, expr) result, err := page.Eval(js) + cleanup() if err != nil { fatal("JS error: %v", err) } @@ -1645,6 +1647,10 @@ func cmdLogs(args []string) { 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) @@ -2151,6 +2157,122 @@ func formatAXNodeDetailJSON(node *proto.AccessibilityAXNode) string { return string(data) } +// --- Console logger infrastructure --- + +// setupConsoleCapture registers a Runtime.consoleAPICalled listener on the page. +// Events are always printed to stderr. If s.Logs is true, they are also appended +// to the per-page NDJSON log file. Returns a cleanup func that waits 50ms for +// in-flight events to flush and then closes the log file (if open). +func setupConsoleCapture(s *State, page *rod.Page) func() { + var logF *os.File + if s.Logs { + logsDir := filepath.Join(stateDir(), "logs") + os.MkdirAll(logsDir, 0755) + logFile := filepath.Join(logsDir, string(page.TargetID)+".ndjson") + logF, _ = os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + } + wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { + entry := makeConsoleEntry(e) + fmt.Fprintf(os.Stderr, "[%s] %s\n", entry.level, entry.text) + if logF != nil { + fmt.Fprintln(logF, marshalConsoleEntry(entry)) + logF.Sync() + } + return false + }) + (proto.RuntimeEnable{}).Call(page) + go wait() + return func() { + time.Sleep(50 * time.Millisecond) // let EachEvent goroutine flush queued events + if logF != nil { + logF.Close() + } + } +} + +// startBrowserLogger spawns a single `rodney _logger` subprocess that stays connected +// to CDP and writes Runtime.consoleAPICalled events for all pages to NDJSON files. +// No-op if s.Logs is false or if the logger is already alive. +func startBrowserLogger(s *State) { + if !s.Logs { + return + } + // Idempotency: skip if a logger with the stored PID is still running. + if s.LoggerPID > 0 { + if proc, err := os.FindProcess(s.LoggerPID); err == nil { + if proc.Signal(syscall.Signal(0)) == nil { + return // already alive + } + } + } + logsDir := filepath.Join(stateDir(), "logs") + os.MkdirAll(logsDir, 0755) + exe, _ := os.Executable() + cmd := exec.Command(exe, "_logger", s.DebugURL, logsDir) + setSysProcAttr(cmd) + if err := cmd.Start(); err != nil { + fmt.Fprintf(os.Stderr, "warning: failed to start logger: %v\n", err) + return + } + s.LoggerPID = cmd.Process.Pid + cmd.Process.Release() + saveState(s) +} + +// cmdInternalLogger is a hidden subcommand: rodney _logger +// It connects to the running Chrome instance and tracks all pages, writing +// Runtime.consoleAPICalled events to per-page NDJSON files in logsDir. +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) + + tracking := map[proto.TargetTargetID]bool{} + sigCh := make(chan os.Signal, 1) + signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) + + ticker := time.NewTicker(100 * time.Millisecond) + defer ticker.Stop() + for { + select { + case <-sigCh: + return + case <-ticker.C: + pages, _ := browser.Pages() + for _, page := range pages { + if !tracking[page.TargetID] { + tracking[page.TargetID] = true + go trackPage(page, logsDir) + } + } + } + } +} + +// 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. +func trackPage(page *rod.Page, logsDir string) { + logFile := filepath.Join(logsDir, string(page.TargetID)+".ndjson") + f, err := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + if err != nil { + return + } + defer f.Close() + + wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { + fmt.Fprintln(f, marshalConsoleEntry(makeConsoleEntry(e))) + f.Sync() + return false + }) + (proto.RuntimeEnable{}).Call(page) + wait() // blocks until page closed or context cancelled +} + // --- Auth proxy for environments with authenticated HTTP proxies --- // detectProxy checks for HTTPS_PROXY/HTTP_PROXY with credentials. From fc160cc771548579bb10108735bd3fe16fa360d0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Thu, 19 Feb 2026 10:26:36 +0100 Subject: [PATCH 5/9] Fix double logging: setupConsoleCapture only writes to stderr MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Chrome broadcasts Runtime.consoleAPICalled to all CDP sessions, so both the _logger subprocess and the in-process EachEvent listener in cmdJS/cmdAssert were writing the same event to the NDJSON file. Fix by removing file writes from setupConsoleCapture — it now only prints to stderr. The _logger subprocess is the sole writer of NDJSON log files. Co-Authored-By: Claude Sonnet 4.6 --- main.go | 21 +++------------------ 1 file changed, 3 insertions(+), 18 deletions(-) diff --git a/main.go b/main.go index 5af8224..e4e8dfc 100644 --- a/main.go +++ b/main.go @@ -2159,34 +2159,19 @@ func formatAXNodeDetailJSON(node *proto.AccessibilityAXNode) string { // --- Console logger infrastructure --- -// setupConsoleCapture registers a Runtime.consoleAPICalled listener on the page. -// Events are always printed to stderr. If s.Logs is true, they are also appended -// to the per-page NDJSON log file. Returns a cleanup func that waits 50ms for -// in-flight events to flush and then closes the log file (if open). +// setupConsoleCapture registers a Runtime.consoleAPICalled listener on the page +// and prints events to stderr. File writing is handled exclusively by the _logger +// subprocess to avoid double-writing (Chrome broadcasts events to all CDP sessions). func setupConsoleCapture(s *State, page *rod.Page) func() { - var logF *os.File - if s.Logs { - logsDir := filepath.Join(stateDir(), "logs") - os.MkdirAll(logsDir, 0755) - logFile := filepath.Join(logsDir, string(page.TargetID)+".ndjson") - logF, _ = os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) - } wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { entry := makeConsoleEntry(e) fmt.Fprintf(os.Stderr, "[%s] %s\n", entry.level, entry.text) - if logF != nil { - fmt.Fprintln(logF, marshalConsoleEntry(entry)) - logF.Sync() - } return false }) (proto.RuntimeEnable{}).Call(page) go wait() return func() { time.Sleep(50 * time.Millisecond) // let EachEvent goroutine flush queued events - if logF != nil { - logF.Close() - } } } From f5a01f925ffc5455e6bcdded6ec18eccc5a2f92c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Thu, 19 Feb 2026 10:34:33 +0100 Subject: [PATCH 6/9] Simplify: remove setupConsoleCapture, let _logger handle all console events Chrome broadcasts Runtime.consoleAPICalled to all CDP sessions regardless of whether events were triggered by page-native code or Runtime.evaluate, so the _logger subprocess captures everything. No in-process capture in cmdJS/cmdAssert is needed. Remove setupConsoleCapture and revert those commands to plain withPage(). Co-Authored-By: Claude Sonnet 4.6 --- main.go | 29 ++--------------------------- 1 file changed, 2 insertions(+), 27 deletions(-) diff --git a/main.go b/main.go index e4e8dfc..85d3336 100644 --- a/main.go +++ b/main.go @@ -736,19 +736,12 @@ func cmdJS(args []string) { fatal("usage: rodney js ") } expr := strings.Join(args, " ") - s, _, page := withPage() - - // Capture console.* events: always prints to stderr; also writes to NDJSON if --logs enabled. - // Chrome does not broadcast Runtime.consoleAPICalled cross-session for evaluate calls, - // so we must capture them here within the same CDP session. - cleanup := setupConsoleCapture(s, page) + _, _, page := withPage() // Wrap bare expressions in a function js := fmt.Sprintf(`() => { return (%s); }`, expr) result, err := page.Eval(js) - cleanup() - if err != nil { fatal("JS error: %v", err) } @@ -1466,12 +1459,10 @@ func cmdAssert(args []string) { fatal("usage: rodney assert [expected] [--message msg]") } - s, _, page := withPage() + _, _, page := withPage() - cleanup := setupConsoleCapture(s, page) js := fmt.Sprintf(`() => { return (%s); }`, expr) result, err := page.Eval(js) - cleanup() if err != nil { fatal("JS error: %v", err) } @@ -2159,22 +2150,6 @@ func formatAXNodeDetailJSON(node *proto.AccessibilityAXNode) string { // --- Console logger infrastructure --- -// setupConsoleCapture registers a Runtime.consoleAPICalled listener on the page -// and prints events to stderr. File writing is handled exclusively by the _logger -// subprocess to avoid double-writing (Chrome broadcasts events to all CDP sessions). -func setupConsoleCapture(s *State, page *rod.Page) func() { - wait := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { - entry := makeConsoleEntry(e) - fmt.Fprintf(os.Stderr, "[%s] %s\n", entry.level, entry.text) - return false - }) - (proto.RuntimeEnable{}).Call(page) - go wait() - return func() { - time.Sleep(50 * time.Millisecond) // let EachEvent goroutine flush queued events - } -} - // startBrowserLogger spawns a single `rodney _logger` subprocess that stays connected // to CDP and writes Runtime.consoleAPICalled events for all pages to NDJSON files. // No-op if s.Logs is false or if the logger is already alive. From 8484d1b4d05cf4e8391853eedabe95c8a8e86580 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Thu, 19 Feb 2026 10:49:00 +0100 Subject: [PATCH 7/9] Replace _logger polling with TargetTargetCreated events; start on cmdStart - cmdInternalLogger now uses Target.setDiscoverTargets + EachEvent on TargetTargetCreated instead of polling every 100ms. Chrome fires the event the moment a page target is created, giving _logger near-zero reaction time. - _logger is spawned in cmdStart (not cmdOpen), so it is already connected and listening before any page is opened. - cmdOpen and cmdNewPage create a blank page first when s.Logs is true, sleep 100ms for _logger to subscribe and call RuntimeEnable, then navigate to the real URL. RuntimeEnable persists across same-target navigations, so all inline scripts on the real URL are captured. Co-Authored-By: Claude Sonnet 4.6 --- main.go | 87 ++++++++++++++++++++++++++++++++++++++++++++------------- 1 file changed, 68 insertions(+), 19 deletions(-) diff --git a/main.go b/main.go index 85d3336..eb4e933 100644 --- a/main.go +++ b/main.go @@ -12,6 +12,7 @@ import ( "os" "os/exec" "os/signal" + "sync" "path/filepath" "strconv" "strings" @@ -433,6 +434,8 @@ func cmdStart(args []string) { fatal("failed to save state: %v", err) } + startBrowserLogger(state) + fmt.Printf("Chrome started (PID %d)\n", pid) fmt.Printf("Debug URL: %s\n", debugURL) } @@ -565,7 +568,19 @@ 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. 100ms is ample time for the subprocess round-trips. + page = browser.MustPage("") + time.Sleep(100 * time.Millisecond) + if err := page.Navigate(url); err != nil { + fatal("navigation failed: %v", err) + } + } else { + page = browser.MustPage(url) + } s.ActivePage = 0 saveState(s) } else { @@ -578,7 +593,6 @@ func cmdOpen(args []string) { } } page.MustWaitLoad() - startBrowserLogger(s) info, _ := page.Info() if info != nil { fmt.Println(info.Title) @@ -1290,7 +1304,17 @@ func cmdNewPage(args []string) { var page *rod.Page if url != "" { - page = browser.MustPage(url) + if s.Logs { + // Same blank-page-first strategy as cmdOpen: let _logger subscribe and + // call RuntimeEnable before the real URL's scripts execute. + page = browser.MustPage("") + time.Sleep(100 * time.Millisecond) + if err := page.Navigate(url); err != nil { + fatal("navigation failed: %v", err) + } + } else { + page = browser.MustPage(url) + } page.MustWaitLoad() } else { page = browser.MustPage("") @@ -2180,8 +2204,8 @@ func startBrowserLogger(s *State) { } // cmdInternalLogger is a hidden subcommand: rodney _logger -// It connects to the running Chrome instance and tracks all pages, writing -// Runtime.consoleAPICalled events to per-page NDJSON files in logsDir. +// 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 ") @@ -2192,26 +2216,51 @@ func cmdInternalLogger(args []string) { browser := rod.New().ControlURL(debugURL).MustConnect() os.MkdirAll(logsDir, 0755) + var mu sync.Mutex tracking := map[proto.TargetTargetID]bool{} - sigCh := make(chan os.Signal, 1) - signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM) - ticker := time.NewTicker(100 * time.Millisecond) - defer ticker.Stop() - for { - select { - case <-sigCh: + // 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 - case <-ticker.C: - pages, _ := browser.Pages() - for _, page := range pages { - if !tracking[page.TargetID] { - tracking[page.TargetID] = true - go trackPage(page, logsDir) + } + 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 From 45b1b1ff3f1e88615d6891d0997fb02bf18048b8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Sk=C3=B6ld?= Date: Thu, 19 Feb 2026 10:57:16 +0100 Subject: [PATCH 8/9] Remove fixed sleep; sync via log file; inline logger spawn into cmdStart - trackPage now opens the log file *after* RuntimeEnable returns (which blocks until Chrome acks). The file's appearance on disk is an exact ready signal that Chrome will send events for any subsequent console call. - cmdOpen and cmdNewPage replace time.Sleep(100ms) with waitForLogger(), which polls for the log file in 5ms increments (500ms timeout). Resolves in ~10-15ms in practice instead of always waiting 100ms. - Logger subprocess is now spawned inline in cmdStart (like the _proxy helper) rather than via a separate startBrowserLogger function. - LoggerPID is set directly in the initial State struct, eliminating the second saveState call. - Update notes/cdp-console-logs.md: correct the cross-session broadcast finding (events ARE broadcast to all sessions), document the current _logger architecture and blank-page-first strategy, and remove the now-deleted in-process capture approach. Co-Authored-By: Claude Sonnet 4.6 --- main.go | 106 +++++++++++--------- notes/cdp-console-logs.md | 200 +++++++++++++++++--------------------- 2 files changed, 151 insertions(+), 155 deletions(-) diff --git a/main.go b/main.go index eb4e933..18b27bf 100644 --- a/main.go +++ b/main.go @@ -420,6 +420,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, @@ -428,14 +444,13 @@ func cmdStart(args []string) { ProxyPID: proxyPID, ProxyPort: proxyPort, Logs: enableLogs, + LoggerPID: loggerPID, } if err := saveState(state); err != nil { fatal("failed to save state: %v", err) } - startBrowserLogger(state) - fmt.Printf("Chrome started (PID %d)\n", pid) fmt.Printf("Debug URL: %s\n", debugURL) } @@ -572,9 +587,10 @@ func cmdOpen(args []string) { // 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. 100ms is ample time for the subprocess round-trips. + // captured. Poll for the log file: trackPage creates it only after + // RuntimeEnable returns, so its existence is an exact ready signal. page = browser.MustPage("") - time.Sleep(100 * time.Millisecond) + waitForLogger(page) if err := page.Navigate(url); err != nil { fatal("navigation failed: %v", err) } @@ -1305,10 +1321,9 @@ func cmdNewPage(args []string) { var page *rod.Page if url != "" { if s.Logs { - // Same blank-page-first strategy as cmdOpen: let _logger subscribe and - // call RuntimeEnable before the real URL's scripts execute. + // Same blank-page-first strategy as cmdOpen. page = browser.MustPage("") - time.Sleep(100 * time.Millisecond) + waitForLogger(page) if err := page.Navigate(url); err != nil { fatal("navigation failed: %v", err) } @@ -2174,35 +2189,6 @@ func formatAXNodeDetailJSON(node *proto.AccessibilityAXNode) string { // --- Console logger infrastructure --- -// startBrowserLogger spawns a single `rodney _logger` subprocess that stays connected -// to CDP and writes Runtime.consoleAPICalled events for all pages to NDJSON files. -// No-op if s.Logs is false or if the logger is already alive. -func startBrowserLogger(s *State) { - if !s.Logs { - return - } - // Idempotency: skip if a logger with the stored PID is still running. - if s.LoggerPID > 0 { - if proc, err := os.FindProcess(s.LoggerPID); err == nil { - if proc.Signal(syscall.Signal(0)) == nil { - return // already alive - } - } - } - logsDir := filepath.Join(stateDir(), "logs") - os.MkdirAll(logsDir, 0755) - exe, _ := os.Executable() - cmd := exec.Command(exe, "_logger", s.DebugURL, logsDir) - setSysProcAttr(cmd) - if err := cmd.Start(); err != nil { - fmt.Fprintf(os.Stderr, "warning: failed to start logger: %v\n", err) - return - } - s.LoggerPID = cmd.Process.Pid - cmd.Process.Release() - saveState(s) -} - // 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. @@ -2265,21 +2251,53 @@ func cmdInternalLogger(args []string) { // 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") - f, err := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + + // 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 := page.EachEvent(func(e *proto.RuntimeConsoleAPICalled) bool { - fmt.Fprintln(f, marshalConsoleEntry(makeConsoleEntry(e))) - f.Sync() - return false - }) - (proto.RuntimeEnable{}).Call(page) - wait() // blocks until page closed or context cancelled + 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 --- diff --git a/notes/cdp-console-logs.md b/notes/cdp-console-logs.md index c534135..298c03b 100644 --- a/notes/cdp-console-logs.md +++ b/notes/cdp-console-logs.md @@ -8,11 +8,10 @@ Research and empirical testing done while implementing `rodney logs`. - 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 cross-session replay +- **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 **follow mode** (`rodney logs -f`) and what - Playwright uses for `page.on('console')` +- This is what rodney uses for all console capture ### 2. `Log.entryAdded` (Log domain) @@ -21,137 +20,116 @@ Research and empirical testing done while implementing `rodney logs`. - 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 -- This is what rodney uses for **snapshot mode** (`rodney logs`) ### 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, consistent - with the Log domain behaviour above +- In practice (Chrome ~124+) empirically found to replay 0 messages - Playwright never uses this domain -## Why `rodney js "console.log(...)"` doesn't appear in `rodney logs` +## Key discovery: `Runtime.consoleAPICalled` IS broadcast cross-session -Each `rodney` invocation is a **separate OS process with a separate CDP 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`. -When `rodney js "console.log('hello')"` runs: -1. A new CDP session is opened -2. `Runtime.evaluate` is called — `console.log` fires -3. The session disconnects +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. -When `rodney logs` runs next: -1. A new CDP session is opened -2. `Runtime.enable` is called -3. Chrome does **not** replay the previous session's `consoleAPICalled` events +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. -There is no CDP mechanism that makes cross-session `console.*` replay possible. -We tested and confirmed: `Runtime.disable` + `Runtime.enable`, `Log.enable`, and -`Console.enable` all return 0 events for messages produced by a prior session's -`Runtime.evaluate`. +## Timing constraint: inline scripts race against subscription -## How Playwright avoids this problem - -Playwright maintains a **persistent CDP connection** for the entire test/automation -lifetime. `page.on('console')` hooks into `Runtime.consoleAPICalled` on that -same persistent session, so it captures every `console.*` call — including those -from `page.evaluate(...)` — because they all happen within the same session. - -Relevant detail from Playwright source (`crPage.ts`): when `Runtime.enable` is -first called, Chrome *does* replay the last ~1000 console messages with -`executionContextId = 0`. Playwright explicitly **drops** these replays because -(a) the original execution context is gone so args can't be inspected, and -(b) they arrive before user listeners are registered anyway. - -```typescript -// crPage.ts – FrameSession._onConsoleAPI -if (event.executionContextId === 0) { - // DevTools protocol stores the last 1000 console messages… - // Ignore these messages since there's no execution context we can use. - return; -} +`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 + ``` -## Considered workaround: JS interceptor +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. -We briefly implemented a `window.__rodney_logs` buffer — `rodney logs` would -inject an override of `console.*` that stores entries in `window.__rodney_logs`, -and subsequent invocations would read and clear that buffer. +## Current implementation: `_logger` subprocess with `Target.targetCreated` -This worked but was rejected because: -- It mutates the page's JavaScript environment -- It only captures messages after the first `rodney logs` invocation -- It feels wrong for a debugging tool to modify what it observes +`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. -## Key discovery: `Runtime.consoleAPICalled` is NOT broadcast cross-session +To close the remaining race for inline scripts, `cmdOpen` and `cmdNewPage` +use a blank-page-first strategy when `--logs` is active: -Empirically confirmed: when Session A calls `Runtime.evaluate` and the evaluated -code calls `console.log`, Chrome delivers the `Runtime.consoleAPICalled` event -**only to Session A**. A separate Session B with `Runtime.enable` active on the -same page target does **not** receive the event. +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 -This means the background `_logger` approach (which connects via its own CDP -session) **cannot capture `console.log` calls made through `rodney js`**. +`rodney logs` requires `rodney start --logs`; it errors with a helpful message +otherwise. -Page-native console calls (inline scripts, timers, event handlers — anything -that runs outside of `Runtime.evaluate`) *are* broadcast to all sessions with -Runtime enabled. So the logger does capture those, just not CDP-evaluate events. +### What `_logger` captures -Test used to confirm (simplified): -```go -// Session A: registers EachEvent + RuntimeEnable, blocks waiting for events -// Session B: calls page.MustEval(`() => { console.log("cross-session-test") }`) -// Result: Session A receives nothing → timeout -``` +| Source | Captured | +|--------|----------| +| Inline `