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

.github/workflows/docker.yml

@@ -5,10 +5,12 @@ on:
       - main
     paths:
       - "docker/**"
+      - "!docker/**/*.md"
       - ".github/workflows/docker.yml"
   pull_request:
     paths:
       - "docker/**"
+      - "!docker/**/*.md"
       - ".github/workflows/docker.yml"
   schedule:
     - cron: "0 6 * * *"

CHANGELOG.md

@@ -3,8 +3,25 @@
 ### Added
 - `keyboard.hold(:shift) { }` holds modifiers for every keyboard and mouse event in the block, e.g. a shift+drag, and
   releases them afterwards. `mouse.move` accepts `modifiers:` like `down` and `up` [#581]
+- `page.console` collects `console.*` calls, browser log entries and uncaught exceptions as `Console::Message`s,
+  `Enumerable` over the last 1000, and `page.on(:console)` yields new ones, also on workers. No more parsing the
+  `:logger` output to get them [cuprite#113]
+- `:logger` accepts a `Logger`: CDP messages and browser output go out at debug level, with `ferrum:protocol` or
+  `ferrum:browser` as program name
+- `FERRUM_LOG` picks what's logged: `*`, `-browser`, CDP method patterns like `Page.*` or `-Network.*`, `0` for nothing
+- Logger output written to a terminal is colored: arrows by kind, bold methods, dimmed times. Files, pipes and
+  `NO_COLOR` keep plain text, `FERRUM_LOG_COLOR=always|never` overrides it
+- `FERRUM_LOG_FORMAT=annotated` puts the command id and method in front of each CDP message and gives responses
+  their command's method and duration, `FERRUM_LOG_FORMAT=json` writes each CDP message as JSON alone
+- Ferrum keeps reading what Chrome writes after startup: it's logged on the `browser` channel, the last 100 lines are in
+  `browser.process.output`
 
 ### Changed
+- The logger cuts any string value over 1024 characters in CDP messages, not just screenshots.
+  `FERRUM_LOG_VALUE_LENGTH` sets the length, `0` keeps them whole. `FERRUM_LOGGING_SCREENSHOTS` is gone
+- `ProcessTimeoutError` is raised as soon as Chrome exits instead of after `:process_timeout`
+- The logger no longer prints `[log] ...` lines for console calls, use `page.on(:console) { |message| puts message }`
+- `FERRUM_DEBUG` is deprecated in favor of `FERRUM_LOG=*`
 - `keyboard.down` and `keyboard.up` raise `ArgumentError` for a modifier such as `:shift` and point to `hold`. `down`
   used to crash with `NoMethodError`, `up` sent an empty keyup event [#581]
 - Behind a proxy with `:user` and `:password`, Ferrum stops continuing intercepted requests once you subscribe to
@@ -17,6 +34,7 @@
   `429 Too Many Requests` for a full remote browser service, and exposes it as `#status`
 
 ### Fixed
+- Every CDP response was scanned for Base64 screenshots to hide from the logger, even with no `:logger` set
 - Headers can be added on a remote browser whose `/json/version` has no `User-Agent`, such as browserless v2, instead of
   failing with `Invalid parameters` [rubycdp/cuprite#300]
 - A `Ferrum::Node` found before a navigation or reload kept its cached CDP node id, which Chrome reuses for the new

docker/DESIGN.md

@@ -176,7 +176,7 @@ under it, which crashpad needs (ferrum#541, #544). Downloads then belong to the
 - `.github/workflows/docker.yml` runs the Go tests, then builds each browser and architecture pair on a native
   runner, never through QEMU, which crashes Chrome (ferrum#270).
   - It runs the Ferrum suite against every image, with `FERRUM_URL` pointing at the driver. Specs tagged
-    `local_browser`, which start their own Chrome, are skipped.
+    `:launch`, which start their own Chrome, are skipped.
   - It merges the architectures into one multi-arch tag by digest. A failed build or suite publishes nothing, so
     `latest` stays where it was.
 - Builds happen on driver changes pushed to `main` and on a daily check for new browser versions: Google's apt

docs/13-javascript.md

@@ -100,3 +100,46 @@ Returns nothing.
 ```ruby
 page.disable_javascript
 ```
+
+## Console
+
+#### console : `Console`
+
+What the DevTools console would show for the page: `console.*` calls, browser log entries (failed resource loads,
+CSP violations, deprecations, ...) and uncaught exceptions. It keeps the last 1000 messages, oldest first, and is
+`Enumerable`, so filter it like any collection.
+
+```ruby
+page.go_to("https://example.com")
+page.console.select(&:error?) # => [#<Ferrum::Console::Message type=:error source=:network ...>]
+page.console.select { |message| message.match?(/deprecated/) }
+page.console.last.text # => "Hello world"
+page.console.clear
+```
+
+`Ferrum::Console::Message` has:
+
+* `type` `Symbol` - `:log`, `:info`, `:warning`, `:error`, `:debug`, `:table`, ... for `console.*` calls, the log
+  entry's level for browser log entries, `:error` for uncaught exceptions
+* `source` `Symbol` - `:console_api`, `:exception`, or the log entry's source such as `:network` or `:security`
+* `text` `String` - the arguments joined by spaces, objects and arrays as JSON
+* `args` `Array` - the `console.*` arguments as Ruby values, objects and arrays built from Chrome's shallow preview
+* `location` `Location` and `stack_trace` `Array<Location>` - `url`, `line`, `column`, `function_name`
+* `timestamp` `Time`
+* `severity` `Symbol` - `:debug`, `:info`, `:warn` or `:error`, the matching `Logger` method
+* `error?`, `warning?`, `match?(pattern)`
+
+#### on(:console)
+
+Calls the block for every new message.
+
+```ruby
+logger = Logger.new($stdout)
+page.on(:console) { |message| logger.public_send(message.severity, message.to_s) }
+```
+
+Fail a test on browser errors:
+
+```ruby
+after { expect(browser.console.select(&:error?)).to be_empty }
+```

docs/2-customization.md

@@ -23,8 +23,8 @@ Ferrum::Browser.new(options)
     * `:extensions` (Array[String | Hash]) - An array of paths to files or JS
       source code to be preloaded into the browser e.g.:
       `["/path/to/script.js", { source: "window.secret = 'top'" }]`
-    * `:logger` (Object responding to `puts`) - When present, debug output is
-      written to this object.
+    * `:logger` (Object responding to `puts`, or a `Logger`) - When present, debug output is
+      written to it, see [Logging](#logging).
     * `:slowmo` (Integer | Float) - Set a delay in seconds to wait before sending command.
       Useful companion of headless option, so that you have time to see changes.
     * `:timeout` (Numeric) - The number of seconds we'll wait for a response when
@@ -60,6 +60,55 @@ Ferrum::Browser.new(options)
     * `:save_path` (String) - Path to save attachments with [Content-Disposition](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Content-Disposition) header.
     * `:env` (Hash) - Environment variables you'd like to pass through to the process
 
+## Logging
+
+With `:logger`, or `FERRUM_LOG` set to print to `$stdout`, Ferrum writes two channels:
+
+* `protocol` - every CDP message sent (`▶`) and received (`◀`). String values longer than 1024 characters, such as
+  Base64 screenshots, are cut; set `FERRUM_LOG_VALUE_LENGTH` to another length, or to `0` to keep them whole.
+* `browser` - what the Chrome process Ferrum launched writes to stdout and stderr.
+
+`FERRUM_LOG` picks what's written, as a comma-separated list:
+
+```sh
+FERRUM_LOG=*                         # everything, what to attach to a bug report
+FERRUM_LOG=*,-browser                # everything but Chrome's output
+FERRUM_LOG=*,-Network.*,-Target.*    # leave out CDP messages whose method matches
+FERRUM_LOG=Page.*,Runtime.evaluate   # only CDP messages whose method matches
+FERRUM_LOG=0                         # nothing, even with :logger
+```
+
+Items with a dot are CDP method patterns, a leading `-` leaves things out and wins over the rest, and a response is
+kept or dropped with the command it answers. Without `FERRUM_LOG`, `:logger` gets everything. `FERRUM_DEBUG` still
+works as `FERRUM_LOG=*`, but is deprecated.
+
+`FERRUM_LOG_FORMAT` picks how CDP messages look. `json` writes each message as JSON alone, one per line and never
+colored, for tools such as `jq`. `annotated` puts the command id and method in front of each CDP message, one line
+each, and gives a response the method of its command and how long the answer took. Params, results and events stay
+whole JSON:
+
+```
+▶ 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
+    ◀ 1.640 Runtime.consoleAPICalled {"type":"warning","args":[{"type":"string","value":"hey"}],…} @4E470240
+```
+
+Without `FERRUM_LOG_FORMAT`, lines look as they always have, `▶ 1.623 {"id":23,"method":"Page.navigate",...}`.
+
+Written to a terminal, lines are colored with the basic ANSI colors, which follow the terminal's light or dark theme:
+arrows are colored by kind (sent, response, error, event), methods are bold and times dimmed. The text stays the
+same, and files, pipes, `StringIO` and `Logger`s get it without colors, as does a terminal when `NO_COLOR` is set.
+`FERRUM_LOG_COLOR=always` or `never` overrides both.
+
+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.
+
+Console messages aren't logged, subscribe to them with [`page.on(:console)`](/docs/ferrum/javascript#console) and
+write them wherever you like.
+
+Chrome's output is also kept when nothing is logged: `browser.process.output.lines` holds its last 100 lines, and
+`ProcessTimeoutError#output` has them when Chrome doesn't start.
+
 ## The crashpad handler
 
 Chrome starts two `chrome_crashpad_handler` processes per browser on Linux. Their only job is to collect and upload

docs/21-workers.md

@@ -82,6 +82,15 @@ worker.network.wait_for_idle
 worker.network.traffic # => [#<Ferrum::Network::Exchange, ...]
 ```
 
+#### console : `Console`
+
+Same API as `page.console` -- see [JavaScript](/docs/ferrum/javascript#console). Collects the worker's own
+`console.*` calls and uncaught exceptions.
+
+```ruby
+worker.console.map(&:text) # => ["from worker"]
+```
+
 #### evaluate / execute / evaluate_async
 
 Same API as on `Page`/`Frame` -- see [JavaScript](/docs/ferrum/javascript). A worker has a single execution context,
@@ -91,10 +100,10 @@ so there's no frame to target.
 worker.evaluate("1 + 1") # => 2
 ```
 
-#### on(:request) / on(:auth)
+#### on(:request) / on(:auth) / on(:console)
 
 Subscribe to the worker's own network interception events, same as `page.on(:request)` -- see the `intercept` method
-in [Network](/docs/ferrum/network).
+in [Network](/docs/ferrum/network), or to its new console messages.
 
 #### close : `Boolean`
 

lib/ferrum/browser.rb

@@ -31,7 +31,7 @@ class Browser
     delegate %i[go_to goto go back forward refresh reload stop wait_for_reload
                 at_css at_xpath css xpath wait_for_selector current_url current_title url title
                 body doctype content=
-                headers cookies network accessibility downloads
+                headers cookies network console accessibility downloads
                 mouse keyboard
                 screenshot pdf mhtml viewport_size device_pixel_ratio
                 start_screencast stop_screencast
@@ -77,8 +77,8 @@ class Browser
     #   An array of paths to files or JS source code to be preloaded into the
     #   browser e.g.: `["/path/to/script.js", { source: "window.secret = 'top'" }]`
     #
-    # @option options [#puts] :logger
-    #   When present, debug output is written to this object.
+    # @option options [#puts, Logger] :logger
+    #   When present, debug output is written to this object, see {Log}.
     #
     # @option options [Integer, Float] :slowmo
     #   Set a delay in seconds to wait before sending a command.

lib/ferrum/browser/options.rb

@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+require "ferrum/log"
+
 module Ferrum
   class Browser
     #
@@ -16,9 +18,10 @@ class Options
       DEFAULT_TIMEOUT = ENV.fetch("FERRUM_DEFAULT_TIMEOUT", 5).to_i
       DEFAULT_PROTOCOL_TIMEOUT = ENV.fetch("FERRUM_PROTOCOL_TIMEOUT", DEFAULT_TIMEOUT).to_i
       PROCESS_TIMEOUT = ENV.fetch("FERRUM_PROCESS_TIMEOUT", 10).to_i
-      DEBUG_MODE = !ENV.fetch("FERRUM_DEBUG", nil).nil?
 
-      attr_reader :window_size, :logger, :ws_max_receive_size,
+      warn "Ferrum: FERRUM_DEBUG is deprecated, use FERRUM_LOG=* instead" if ENV.key?("FERRUM_DEBUG")
+
+      attr_reader :window_size, :logger, :log, :ws_max_receive_size,
                   :js_errors, :base_url, :slowmo, :pending_connection_errors,
                   :url, :ws_url, :env, :process_timeout, :browser_name, :browser_path,
                   :save_path, :proxy, :port, :host, :headless, :incognito, :dockerize, :browser_options,
@@ -51,7 +54,7 @@ def initialize(options = nil)
         @ignore_default_browser_options = @options[:ignore_default_browser_options]
 
         @proxy = validate_proxy(@options[:proxy])
-        @logger = parse_logger(@options[:logger])
+        @logger, @log = parse_logger(@options[:logger])
         @base_url = parse_base_url(@options[:base_url]) if @options[:base_url]
         @url = @options[:url].to_s if @options[:url]
         @ws_url = @options[:ws_url].to_s if @options[:ws_url]
@@ -120,9 +123,13 @@ def to_h
       private
 
       def parse_logger(logger)
-        return logger if logger
+        value = ENV.fetch("FERRUM_LOG") { "*" if ENV.key?("FERRUM_DEBUG") }
+        settings = value ? Log.parse(value) : {}
+        logger ||= $stdout.tap { |s| s.sync = true } if value && settings
+        return [logger, nil] unless logger && settings
 
-        !logger && DEBUG_MODE ? $stdout.tap { |s| s.sync = true } : logger
+        [logger, Log.new(logger, **settings, format: Log.parse_format(ENV.fetch("FERRUM_LOG_FORMAT", nil)),
+                                             color: Log.parse_color(ENV.fetch("FERRUM_LOG_COLOR", nil)))]
       end
 
       def parse_base_url(value)