Skip to content

feat: console messages API, a reworked logger and browser output kept after startup - #658

Merged
route merged 6 commits into
mainfrom
feat/console-messages
Oct 19, 2026
Merged

route merged 6 commits into
mainfrom
feat/console-messages

Conversation

@route

@route route commented Oct 18, 2026 •

Copy link
Copy Markdown
Member

Gives console messages their own API, so nobody has to parse the :logger output to get them (rubycdp/cuprite#113). The logger becomes debug output for Ferrum itself, and Ferrum keeps reading what Chrome writes after startup.

Three feature commits, each can be reviewed on its own, plus two small spec cleanups: an unused helper removed, and the local_browser tag renamed to :launch.

Console

page.console.select(&:error?)
page.console.select { |m| m.match?(/deprecated/) }
page.console.clear
page.on(:console) { |m| logger.public_send(m.severity, m.to_s) }
browser.console # current page
worker.console
  • Ferrum::Console is Enumerable over the last 1000 Console::Messages, built from Runtime.consoleAPICalled, Log.entryAdded and Runtime.exceptionThrown. It skips messages Chrome replays from destroyed contexts and log entries from workers.
  • Console::Message has type, source, text, args, location, stack_trace, timestamp, severity, error?, warning?, match? and to_s. Text, arguments and stack traces are converted from CDP only when read.
  • Breaking: the logger no longer prints [log] ... lines. page.on(:console) { |m| puts m } prints the same text.

Browser output

  • Chrome's stdout and stderr used to be read only until the WebSocket URL appeared, and everything after that was lost. A thread now drains the pipe for as long as Chrome runs, and browser.process.output.lines holds the last 100 lines. Process::Output owns the pipe.
  • The write end is closed right after spawn, so a Chrome that exits during startup raises ProcessTimeoutError immediately instead of after :process_timeout.

Logging

:logger gets two channels: protocol (CDP messages) and browser (Chrome's output). It can be an IO or a Logger; a Logger gets every line at debug level, with ferrum:protocol or ferrum:browser as program name, and nothing is built when its level is higher.

Env Values What it controls
FERRUM_LOG *, protocol, browser, -browser, Page.*, -Network.*, 0 What gets logged; prints to $stdout when there's no :logger
FERRUM_LOG_FORMAT default, json, annotated What CDP lines look like
FERRUM_LOG_VALUE_LENGTH 1024; 0 keeps values whole Maximum length of a string value in a CDP message
FERRUM_LOG_COLOR auto, always, never Color; auto means only on a terminal without NO_COLOR
FERRUM_DEBUG any value Deprecated, works as FERRUM_LOG=* and warns once
  • FERRUM_LOG: items with a dot are CDP method patterns, and a leading - excludes. Exclusions win, and a response is kept or dropped together with its command.
  • Formats:
    • default looks the way the log always has.
    • json writes one message per line as plain JSON, for jq.
    • annotated looks like this:
      ▶ 1.623 #23 Page.navigate {"url":"http://127.0.0.1:5000/console_log"} @4E470240
          ◀ 1.637 #23 Page.navigate 14ms {"frameId":"325D8B09…","loaderId":"64738D2F…"} @4E470240
      
  • Long values: they're cut anywhere in a message, not just screenshots, and the JSON stays valid. This replaces FERRUM_LOGGING_SCREENSHOTS, and without a logger, CDP responses are no longer regex-scanned for screenshots.
  • Colors: written to a terminal, lines are colored with the basic ANSI colors, which work on light and dark themes.
  • Logging never breaks the browser: if formatting or writing a line fails, e.g. a closed IO, Ferrum warns once and skips the line. Messages nested deeper than JSON's default limit of 100 levels, such as large DOM trees, are logged fine.

…er page and worker

page.console is an Enumerable over the last 1000 Console::Messages built from Runtime.consoleAPICalled,
Log.entryAdded and Runtime.exceptionThrown, and page.on(:console) yields new ones. Text, arguments and stack
traces are converted from CDP only when read. The :logger no longer prints console calls, they're handed to the
caller through page.on(:console) instead.

Refs rubycdp/cuprite#113
@Nakilon

Nakilon commented Oct 19, 2026

Copy link
Copy Markdown
Contributor

Oh so that's where the "parsing the log" idea came from, lol, that my coworker copied back in the day.
Deepseek then showed how to capture console prior logging just like this:

    page.driver.browser.on("Runtime.exceptionThrown") do |params|
      p params["exceptionDetails"]["exception"]["description"]
    end
    page.driver.browser.on("Runtime.consoleAPICalled") do |params|
      next if [] == values = params["args"].map{ |_| _["value"] }.reject do |v|
        [
          # any exclusion you wanna have
        ].any?{ |r| r === v }
      end
      p values
    end
    page.driver.browser.on("Log.entryAdded") do |params|
      next if [
        # other exclusions
      ].any?{ |r| r === params["entry"]["text"] }
      p params["entry"]["text"]
    end

Chrome's stdout and stderr were read only until the WebSocket URL showed up and then closed, losing everything Chrome
wrote later. A thread now drains the pipe for as long as the process lives into Process::Output, which keeps the
last 100 lines as browser.process.output. The write end is closed right after spawn, so a Chrome that exits during
startup raises ProcessTimeoutError at once instead of after :process_timeout.
@route
route force-pushed the feat/console-messages branch from 2d8d982 to 4bdc60f Compare October 19, 2026 11:36
@route route changed the title feat(console): collect console messages, log entries and exceptions per page and worker feat: console messages API, a reworked logger and browser output kept after startup Oct 19, 2026
route added 3 commits October 19, 2026 15:55
…rmat CDP messages

The :logger gets two channels, protocol (CDP messages) and browser (Chrome's output), and can be a Logger, which
receives them at debug level as ferrum:protocol and ferrum:browser without building lines its level skips.
FERRUM_LOG picks what's logged: channels, CDP method patterns to keep or leave out (Page.*, -Network.*) and 0 for
nothing; FERRUM_DEBUG still logs everything but is deprecated. FERRUM_LOG_FORMAT=annotated gives responses their
command's method and duration, FERRUM_LOG_FORMAT=json writes messages as JSON alone. Lines are
colored on a terminal (FERRUM_LOG_COLOR, NO_COLOR), and string values over
FERRUM_LOG_VALUE_LENGTH are cut, replacing FERRUM_LOGGING_SCREENSHOTS and the screenshot scrubbing every CDP
response paid for even without a logger.
@route
route force-pushed the feat/console-messages branch from 4bdc60f to 5b1b63f Compare October 19, 2026 13:01
@route
route merged commit 7c46000 into main Oct 19, 2026
14 checks passed
@route
route deleted the feat/console-messages branch October 19, 2026 13:32
route added a commit that referenced this pull request Oct 26, 2026
…JRuby deadlock (#680)

* fix(client): revert nonblocking websocket write that deadlocks on JRuby

This reverts commit 080aadc (#644).

On JRuby IO#readpartial waits in a NIO select while holding the channel's blocking lock, and write_nonblock
and IO.select need that same lock to switch the channel to nonblocking mode. With the reader thread parked
in readpartial, the handshake write never returns and Ferrum::Browser.new hangs forever. Any write after
that waits for the browser to send something first, so the approach can't work on JRuby at all.

Conflicts with the logger rework (#658) are resolved by keeping its logging. The 0.19.0 changelog entry
stays, the history of that release doesn't change.

Fixes #676

* fix(client): write websocket frames from a writer thread

Brings back the protection from #644 in a way that works on JRuby: a browser that stops reading its socket
blocked the sending thread forever while it held the lock every other command needs to be sent.

Callers and the driver now only encode frames and queue them; a writer thread is the only code writing the
socket, with blocking writes, and the reader the only code reading it. No lock is held across socket I/O.
Each queued frame carries its command's deadline and is dropped if that passes before it's written, so a
command behind a large one fails after its own timeout. A chunk the browser takes no data of for
protocol_timeout closes the connection, and the commands still waiting get DeadBrowserError with the reason.

Restores the rest of #644 as well: the command timeout is passed down to the websocket, and a pending
command whose send raised is forgotten.

* test: stop the test server after the suite and pipe the test proxy by hand

On JRuby the process never exited after the suite: Puma was only killed at exit, and killing doesn't
interrupt its reactor's select. The websocket test proxy used IO.copy_stream from two threads on the same
sockets, which hits the same JRuby lock as #676, so browsers behind it timed out.

* chore(ci): run the test suite on JRuby

* fix(context): keep targets in creation order on JRuby

Concurrent::Map is a Hash on CRuby but a hash-ordered Java map on JRuby, so pages, windows(:last) and
workers came back in a different random order per process. Targets are kept in a Concurrent::Hash and
iterated over a snapshot, so a target added by the event thread meanwhile can't break the iteration.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants