diff --git a/.github/workflows/docker.yml b/.github/workflows/docker.yml index b1e8f532..78db5756 100644 --- a/.github/workflows/docker.yml +++ b/.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 * * *" diff --git a/CHANGELOG.md b/CHANGELOG.md index 68b0a0bb..6e820e75 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/docker/DESIGN.md b/docker/DESIGN.md index f1b11901..32625bff 100644 --- a/docker/DESIGN.md +++ b/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 diff --git a/docs/13-javascript.md b/docs/13-javascript.md index ea33d065..6dff564a 100644 --- a/docs/13-javascript.md +++ b/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?) # => [#] +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` - `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 } +``` diff --git a/docs/2-customization.md b/docs/2-customization.md index 602a1604..290fe5ab 100644 --- a/docs/2-customization.md +++ b/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 diff --git a/docs/21-workers.md b/docs/21-workers.md index 835d2bca..7b8d3d10 100644 --- a/docs/21-workers.md +++ b/docs/21-workers.md @@ -82,6 +82,15 @@ worker.network.wait_for_idle worker.network.traffic # => [# ["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` diff --git a/lib/ferrum/browser.rb b/lib/ferrum/browser.rb index f167e000..51886709 100644 --- a/lib/ferrum/browser.rb +++ b/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. diff --git a/lib/ferrum/browser/options.rb b/lib/ferrum/browser/options.rb index 0a6cbec0..8bf17188 100644 --- a/lib/ferrum/browser/options.rb +++ b/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) diff --git a/lib/ferrum/browser/process.rb b/lib/ferrum/browser/process.rb index 49fe24d9..88580239 100644 --- a/lib/ferrum/browser/process.rb +++ b/lib/ferrum/browser/process.rb @@ -8,6 +8,7 @@ require "ferrum/browser/options/base" require "ferrum/browser/options/chrome" require "ferrum/browser/process/killer" +require "ferrum/browser/process/output" require "ferrum/browser/command" require "ferrum/utils/elapsed_time" require "ferrum/utils/platform" @@ -27,6 +28,7 @@ class Process HTTP_SCHEMES = { "ws" => "http", "wss" => "https" }.freeze WS_SCHEMES = { "http" => "ws", "https" => "wss" }.freeze LOCAL_HOSTS = %w[0.0.0.0 :: 127.0.0.1 ::1 localhost].freeze + WS_URL = %r{DevTools listening on (ws://.*[a-zA-Z0-9-]{36})} delegate path: :command @@ -44,16 +46,23 @@ def self.start(*args) attr_reader :host, :port, :ws_url, :pid, :command, :xvfb + # What the browser process wrote to stdout and stderr, empty for a + # browser Ferrum didn't launch. + # + # @return [Output] + attr_reader :output + def initialize(options) @pid = @xvfb = @user_data_dir = nil @requested_host = options.host + @log = options.log + @output = Output.new(@log) if options.ws_url || options.url self.ws_url = options.ws_url || fetch_ws_url(options.url) return end - @logger = options.logger @process_timeout = options.process_timeout @env = Hash(options.env) @@ -71,20 +80,13 @@ def start return if ws_url begin - read_io, write_io = IO.pipe - process_options = { in: File::NULL } - process_options[:pgroup] = true unless Utils::Platform.windows? - process_options[:out] = process_options[:err] = write_io - @xvfb = Xvfb.start(@command.options) if @command.xvfb? - - env = Hash(@xvfb&.to_env).merge(@env) - @pid = ::Process.spawn(env, *@command.to_a, process_options) - ObjectSpace.define_finalizer(self, Killer.finalizer([@pid, @xvfb&.pid], @user_data_dir)) - - parse_ws_url(read_io, @process_timeout) + @output = Output.new(@log) + @output.pipe { |io| spawn_browser(io) } + parse_ws_url + @output.follow ensure - close_io(read_io, write_io) + @output.close unless ws_url end end @@ -138,6 +140,15 @@ def inspect private + def spawn_browser(io) + process_options = { in: File::NULL, out: io, err: io } + process_options[:pgroup] = true unless Utils::Platform.windows? + env = Hash(@xvfb&.to_env).merge(@env) + + @pid = ::Process.spawn(env, *@command.to_a, process_options) + ObjectSpace.define_finalizer(self, Killer.finalizer([@pid, @xvfb&.pid], @user_data_dir)) + end + def sync_stop if @pid Killer.kill(@pid) @@ -145,6 +156,7 @@ def sync_stop @pid = nil end + @output.close remove_user_data_dir if @user_data_dir ObjectSpace.undefine_finalizer(self) nil @@ -160,11 +172,13 @@ def async_stop pid = @pid xvfb_pid = @xvfb&.pid user_data_dir = @user_data_dir + output = @output @pid = @user_data_dir = nil Utils::Thread.spawn do Killer.kill(pid) if pid Killer.kill(xvfb_pid) if xvfb_pid + output.close Killer.remove_directory(user_data_dir) if user_data_dir ObjectSpace.undefine_finalizer(self) end @@ -175,28 +189,11 @@ def remove_user_data_dir @user_data_dir = nil end - def parse_ws_url(read_io, timeout) - output = "" - start = Utils::ElapsedTime.monotonic_time - max_time = start + timeout - regexp = %r{DevTools listening on (ws://.*[a-zA-Z0-9-]{36})} - while (now = Utils::ElapsedTime.monotonic_time) < max_time - begin - output += read_io.read_nonblock(512) - rescue IO::WaitReadable - read_io.wait_readable(max_time - now) - else - if output.match(regexp) - self.ws_url = rewrite_host(output.match(regexp)[1].strip) - break - end - end - end - - return if ws_url + def parse_ws_url + match = @output.wait_for(WS_URL, @process_timeout) + raise ProcessTimeoutError.new(@process_timeout, @output.to_s) unless match - @logger&.puts(output) - raise ProcessTimeoutError.new(timeout, output) + self.ws_url = rewrite_host(match[1].strip) end def ws_url=(url) @@ -211,14 +208,6 @@ def rewrite_host(url) uri.to_s end - def close_io(*ios) - ios.each do |io| - io.close if io && !io.closed? - rescue IOError - raise unless RUBY_ENGINE == "jruby" - end - end - def fetch_ws_url(url) response = ::Net::HTTP.get_response(URI(json_version_url(url).to_s)) status = "#{response.code} #{response.message}" unless response.is_a?(::Net::HTTPSuccess) diff --git a/lib/ferrum/browser/process/output.rb b/lib/ferrum/browser/process/output.rb new file mode 100644 index 00000000..74d85639 --- /dev/null +++ b/lib/ferrum/browser/process/output.rb @@ -0,0 +1,143 @@ +# frozen_string_literal: true + +module Ferrum + class Browser + class Process + # + # What the browser process wrote to stdout and stderr: keeps the last + # {LIMIT} lines and writes each one to the `:browser` log channel. Owns + # the pipe the process writes to, which is read on its own thread for as + # long as the process lives, so it never fills up and blocks the browser. + # + class Output + LIMIT = 100 + DRAIN_TIMEOUT = 0.5 + + def initialize(log = nil) + @log = log + @lines = [] + @partial = String.new(encoding: Encoding::BINARY) + @mutex = Mutex.new + @io = @reader = nil + end + + # + # Opens the pipe and yields its write end, to be given to the process + # as stdout and stderr. The write end is closed here afterwards, so + # reading hits the end of the pipe once the process exits. + # + # @yieldparam [IO] io + # + # @return [void] + # + def pipe + @io, writer = IO.pipe + yield writer + ensure + close_io(writer) + end + + # + # Reads the pipe until the output matches, the process exits or the + # time is up. + # + # @param [Regexp] regexp + # + # @param [Numeric] timeout + # + # @return [MatchData, nil] + # + def wait_for(regexp, timeout) + deadline = Utils::ElapsedTime.monotonic_time + timeout + while (now = Utils::ElapsedTime.monotonic_time) < deadline + begin + self << @io.read_nonblock(512) + rescue IO::WaitReadable + @io.wait_readable(deadline - now) + rescue EOFError + return + else + match = to_s.match(regexp) + return match if match + end + end + end + + # + # Keeps reading the pipe on a new thread until it's closed. + # + # @return [Thread] + # + def follow + @reader = Utils::Thread.spawn do + loop { self << @io.readpartial(4096) } + rescue IOError + self << "\n" unless @partial.empty? + end + end + + # + # Gives the reading thread {DRAIN_TIMEOUT} seconds to take what the + # process wrote last, then closes the pipe. The lines are kept. + # + # @return [void] + # + def close + @reader&.join(DRAIN_TIMEOUT) + close_io(@io) + @io = @reader = nil + end + + # + # Adds a chunk of output, which can end in the middle of a line. + # + # @param [String] chunk + # + # @return [self] + # + def <<(chunk) + lines = @mutex.synchronize do + *complete, @partial = (@partial + chunk.b).split("\n", -1) + complete.map! { |line| utf8(line) } + @lines.concat(complete) + @lines.shift(@lines.size - LIMIT) if @lines.size > LIMIT + complete + end + + lines.each { |line| @log&.browser(line) } + self + end + + # + # The last lines, oldest first. + # + # @return [Array] + # + def lines + @mutex.synchronize { @partial.empty? ? @lines.dup : [*@lines, utf8(@partial)] } + end + + # + # The last lines joined by newlines. + # + # @return [String] + # + def to_s + lines.join("\n") + end + + private + + def utf8(line) + line.dup.force_encoding(Encoding::UTF_8).scrub.delete_suffix("\r") + end + + def close_io(io) + io.close if io && !io.closed? + rescue IOError + raise unless RUBY_ENGINE == "jruby" + end + end + end + end +end diff --git a/lib/ferrum/client.rb b/lib/ferrum/client.rb index 67158d1e..48af6f63 100644 --- a/lib/ferrum/client.rb +++ b/lib/ferrum/client.rb @@ -160,7 +160,7 @@ def initialize(ws_url, options) @ws_url = ws_url @options = options @pendings = Concurrent::Hash.new - @ws = WebSocket.new(ws_url, options.ws_max_receive_size, options.logger) + @ws = WebSocket.new(ws_url, options.ws_max_receive_size, options.log) @subscriber = Subscriber.new start diff --git a/lib/ferrum/client/web_socket.rb b/lib/ferrum/client/web_socket.rb index 0ed40b13..4624e87e 100644 --- a/lib/ferrum/client/web_socket.rb +++ b/lib/ferrum/client/web_socket.rb @@ -15,14 +15,13 @@ class Client class WebSocket WEBSOCKET_BUG_SLEEP = 0.05 DEFAULT_PORTS = { "ws" => 80, "wss" => 443 }.freeze - SKIP_LOGGING_SCREENSHOTS = !ENV["FERRUM_LOGGING_SCREENSHOTS"] ESCAPE_OR_LONE_SURROGATE = /\\u[dD][89abAB]\h{2}\\u[dD][c-fC-F]\h{2}|\\u([dD][89a-fA-F]\h{2})|\\./ attr_reader :url, :messages - def initialize(url, max_receive_size, logger) + def initialize(url, max_receive_size, log) @url = url - @logger = logger + @log = log uri = URI.parse(@url) port = uri.port || DEFAULT_PORTS[uri.scheme] @@ -43,8 +42,6 @@ def initialize(url, max_receive_size, logger) @driver_mutex = Mutex.new @messages = Queue.new - @screenshot_commands = Concurrent::Hash.new if SKIP_LOGGING_SCREENSHOTS - @driver.on(:open, &method(:on_open)) @driver.on(:message, &method(:on_message)) @driver.on(:close, &method(:on_close)) @@ -73,13 +70,7 @@ def on_open(_event) # def on_message(event) data = safely_parse_json(event.data) - output = event.data - if SKIP_LOGGING_SCREENSHOTS && @screenshot_commands[data&.dig("id")] - @screenshot_commands.delete(data&.dig("id")) - output.sub!(/{"data":"[^"]*"}/, %("Set FERRUM_LOGGING_SCREENSHOTS=true to see screenshots in Base64")) - end - - @logger&.puts(" ◀ #{Utils::ElapsedTime.elapsed_time} #{output}\n") + @log&.received(data, event.data, self) # If we couldn't parse JSON data for some reason (parse error or deeply nested object) we # don't push response to @messages. Worse that could happen we raise timeout error due to command didn't return @@ -118,8 +109,6 @@ def on_close(_event) # is closed, since the frame was cut off midway. # def send_message(data, timeout = nil) - @screenshot_commands[data[:id]] = true if SKIP_LOGGING_SCREENSHOTS - json = data.to_json @driver_mutex.synchronize do @write_timeout = timeout @@ -127,7 +116,7 @@ def send_message(data, timeout = nil) ensure @write_timeout = nil end - @logger&.puts("\n\n▶ #{Utils::ElapsedTime.elapsed_time} #{json}") + @log&.sent(data, self) end # diff --git a/lib/ferrum/console.rb b/lib/ferrum/console.rb new file mode 100644 index 00000000..b73f630e --- /dev/null +++ b/lib/ferrum/console.rb @@ -0,0 +1,157 @@ +# frozen_string_literal: true + +require "ferrum/console/message" + +module Ferrum + # + # Collects what the DevTools console would show for a page or worker: + # `console.*` calls, browser log entries and uncaught exceptions, as + # {Console::Message}s. Keeps the last {LIMIT} messages and is `Enumerable` + # over them, oldest first. + # + # @example + # browser.go_to("https://example.com") + # browser.console.select(&:error?) # => [#] + # browser.console.clear + # + class Console + include Enumerable + + LIMIT = 1000 + + def initialize(page) + @page = page + @messages = [] + @listeners = Concurrent::Map.new + @listener_id = Concurrent::AtomicFixnum.new + @mutex = Mutex.new + end + + # + # Yields each collected message, oldest first. + # + # @yieldparam [Message] message + # + # @return [Enumerator, self] + # + def each(&) + return to_enum(:each) { size } unless block_given? + + to_a.each(&) + self + end + + # + # The collected messages, oldest first. + # + # @return [Array] + # + def to_a + @mutex.synchronize { @messages.dup } + end + + # + # The most recent message. + # + # @return [Message, nil] + # + def last + @mutex.synchronize { @messages.last } + end + + # + # Number of collected messages. + # + # @return [Integer] + # + def size + @mutex.synchronize { @messages.size } + end + + # + # Whether no messages were collected. + # + # @return [Boolean] + # + def empty? + size.zero? + end + + # + # Forgets the collected messages. + # + # @return [self] + # + def clear + @mutex.synchronize { @messages.clear } + self + end + + # + # Calls the block for every new message. Prefer `page.on(:console)`. + # + # @yieldparam [Message] message + # + # @return [Integer] + # The listener id, used to remove it via {#off}. + # + def on(&block) + @listener_id.increment.tap { |id| @listeners[id] = block } + end + + # + # Removes a listener added via {#on}. + # + # @param [Integer] id + # + # @return [void] + # + def off(id) + @listeners.delete(id) + end + + # + # Subscribes to the CDP events messages are built from. + # + # @return [void] + # + def subscribe + @page.on("Runtime.consoleAPICalled") do |params| + add(Message.from_console_api(params)) unless replayed?(params) + end + + @page.on("Log.entryAdded") do |params| + entry = params["entry"] + add(Message.from_log_entry(entry)) unless entry["source"] == "worker" + end + + @page.on("Runtime.exceptionThrown") do |params| + add(Message.from_exception(params)) + end + end + + # + # Debug representation of the console. + # + # @return [String] + # + def inspect + "#<#{self.class.name} size=#{size}>" + end + + private + + def replayed?(params) + params["executionContextId"].to_i.zero? + end + + def add(message) + @mutex.synchronize do + @messages << message + @messages.shift if @messages.size > LIMIT + end + + @listeners.each_value { |listener| listener.call(message) } + end + end +end diff --git a/lib/ferrum/console/location.rb b/lib/ferrum/console/location.rb new file mode 100644 index 00000000..bbbe1ce3 --- /dev/null +++ b/lib/ferrum/console/location.rb @@ -0,0 +1,42 @@ +# frozen_string_literal: true + +module Ferrum + class Console + # + # A place in the page's source a {Message} points at: where `console.*` + # was called, an exception was thrown or a resource failed to load. + # Line and column numbers are 1-based. + # + class Location + attr_reader :url, :line, :column, :function_name + + # Builds a location from a CDP `Runtime.CallFrame`, or from the `url` + # and `lineNumber` of a `Log.LogEntry`. CDP numbers lines and columns + # from 0. + # + # @param [Hash{String => Object}] frame + # + # @return [Location] + def self.from_frame(frame) + new(url: frame["url"].to_s, + line: frame["lineNumber"]&.+(1), + column: frame["columnNumber"]&.+(1), + function_name: frame["functionName"].to_s) + end + + def initialize(url:, line: nil, column: nil, function_name: "") + @url = url + @line = line + @column = column + @function_name = function_name + end + + # The location as `url:line:column`, leaving out what's unknown. + # + # @return [String] + def to_s + [url, line, column].compact.join(":") + end + end + end +end diff --git a/lib/ferrum/console/message.rb b/lib/ferrum/console/message.rb new file mode 100644 index 00000000..3651c10e --- /dev/null +++ b/lib/ferrum/console/message.rb @@ -0,0 +1,230 @@ +# frozen_string_literal: true + +require "json" +require "ferrum/console/location" + +module Ferrum + class Console + # + # A message as the DevTools console would show it: a `console.*` call, + # a browser log entry (failed resource loads, CSP violations, + # deprecations, ...) or an uncaught exception. The text, arguments and + # stack trace are only converted from CDP when asked for. + # + class Message + SEVERITIES = { error: :error, assert: :error, warning: :warn, + debug: :debug, verbose: :debug, trace: :debug }.freeze + UNSERIALIZABLE = { "NaN" => Float::NAN, "Infinity" => Float::INFINITY, + "-Infinity" => -Float::INFINITY, "-0" => -0.0 }.freeze + + # What logged the message: `:log`, `:info`, `:warning`, `:error`, + # `:debug`, `:table`, `:trace`, `:assert`, ... for `console.*` calls, + # `:verbose`, `:info`, `:warning` or `:error` for browser log entries + # and `:error` for uncaught exceptions. + # + # @return [Symbol] + attr_reader :type + + # Where the message comes from: `:console_api` for `console.*` calls, + # `:exception` for uncaught exceptions, otherwise the browser log + # entry's source such as `:network`, `:security`, `:violation`, + # `:deprecation` or `:intervention`. + # + # @return [Symbol] + attr_reader :source + + # When the message was logged. + # + # @return [Time] + attr_reader :timestamp + + # Builds a message from `Runtime.consoleAPICalled` params. + # + # @param [Hash{String => Object}] params + # + # @return [Message] + def self.from_console_api(params) + new(type: params["type"], source: "console_api", timestamp: params["timestamp"], + raw_args: params["args"], frames: params.dig("stackTrace", "callFrames")) + end + + # Builds a message from a `Log.entryAdded` entry. + # + # @param [Hash{String => Object}] entry + # + # @return [Message] + def self.from_log_entry(entry) + frames = entry.dig("stackTrace", "callFrames") + frames ||= [entry.slice("url", "lineNumber")] if entry["url"] + new(type: entry["level"], source: entry["source"], timestamp: entry["timestamp"], + raw_text: entry["text"], frames: frames) + end + + # Builds a message from `Runtime.exceptionThrown` params. + # + # @param [Hash{String => Object}] params + # + # @return [Message] + def self.from_exception(params) + details = params["exceptionDetails"] + frames = details.dig("stackTrace", "callFrames") + frames ||= [details.slice("url", "lineNumber", "columnNumber")] + text = [details["text"], details.dig("exception", "description")].compact.uniq.join(" ") + new(type: "error", source: "exception", timestamp: params["timestamp"], raw_text: text, frames: frames) + end + + def initialize(type:, source:, timestamp:, raw_args: nil, raw_text: nil, frames: nil) + @type = underscore(type) + @source = underscore(source) + @timestamp = Time.at(0, timestamp.to_f, :millisecond) + @raw_args = raw_args || [] + @raw_text = raw_text + @frames = frames || [] + end + + # The message text. `console.*` arguments are joined by spaces, with + # objects and arrays rendered as JSON. + # + # @return [String] + def text + @text ||= @raw_text || @raw_args.map { |arg| arg_text(arg) }.join(" ") + end + + # The `console.*` arguments as Ruby values. Strings, numbers, + # booleans and `null` come as they are, `undefined` is `nil`, plain + # objects and arrays are a `Hash` or an `Array` built from Chrome's + # shallow preview, anything else (functions, DOM nodes, errors, ...) is + # its description. Empty for log entries and exceptions. + # + # @return [Array] + def args + @args ||= @raw_args.map { |arg| arg_value(arg) } + end + + # The call stack at the moment the message was logged, innermost frame + # first. Can be empty. + # + # @return [Array] + def stack_trace + @stack_trace ||= @frames.map { |frame| Location.from_frame(frame) } + end + + # Where the message was logged from. + # + # @return [Location, nil] + def location + stack_trace.first + end + + # The {#type} expressed as a `Logger` method name, so a message can be + # passed on with `logger.public_send(message.severity, message)`. + # + # @return [Symbol] + # `:debug`, `:info`, `:warn` or `:error`. + def severity + SEVERITIES.fetch(type, :info) + end + + # Whether the message is an error: `console.error`, a failed + # `console.assert`, an error log entry or an uncaught exception. + # + # @return [Boolean] + def error? + severity == :error + end + + # Whether the message is a warning. + # + # @return [Boolean] + def warning? + severity == :warn + end + + # Whether the message text matches the given pattern. + # + # @param [Regexp, String] pattern + # A regexp matched against the text, or a string checked for inclusion in it. + # + # @return [Boolean] + def match?(pattern) + return text.match?(pattern) if pattern.is_a?(Regexp) + + text.include?(pattern.to_s) + end + + # The message as the logger prints it: `[type] text`, followed by an + # `at function (url:line:column)` line per stack frame. + # + # @return [String] + def to_s + lines = stack_trace.map { |frame| " at #{frame.function_name} (#{frame})" } + ["[#{type}] #{text}", *lines].join("\n") + end + + # Debug representation of the message. + # + # @return [String] + def inspect + "#<#{self.class.name} type=#{type.inspect} source=#{source.inspect} text=#{text.inspect}>" + end + + private + + def underscore(name) + name.to_s.gsub(/(?<=[a-z])(?=[A-Z])|-/, "_").downcase.to_sym + end + + def arg_text(arg) + value = arg_value(arg) + + case value + when String then value + when Hash, Array then JSON.generate(value) + when nil then arg["subtype"] == "null" ? "null" : "undefined" + else arg["description"] || value.to_s + end + end + + def arg_value(arg) + return arg["value"] if arg.key?("value") + return unserializable(arg["unserializableValue"]) if arg.key?("unserializableValue") + return if arg["type"] == "undefined" + + preview_value(arg["preview"]) || arg["description"] + end + + def preview_value(preview) + return unless preview && preview["type"] == "object" + + case preview["subtype"] + when nil then preview["properties"].to_h { |property| [property["name"], property_value(property)] } + when "array" then preview["properties"].map { |property| property_value(property) } + end + end + + def property_value(property) + return preview_value(property["valuePreview"]) || property["value"] if property["valuePreview"] + + value = property["value"] + case property["type"] + when "number" then parse_number(value) + when "bigint" then unserializable(value) + when "boolean" then value == "true" + when "undefined" then nil + when "object" then property["subtype"] == "null" ? nil : value + else value + end + end + + def unserializable(value) + UNSERIALIZABLE.fetch(value) { value.end_with?("n") ? Integer(value.delete_suffix("n")) : value } + end + + def parse_number(value) + return UNSERIALIZABLE[value] if UNSERIALIZABLE.key?(value) + + Integer(value, exception: false) || Float(value, exception: false) || value + end + end + end +end diff --git a/lib/ferrum/interceptable.rb b/lib/ferrum/interceptable.rb index d3fa7f14..9c4581c7 100644 --- a/lib/ferrum/interceptable.rb +++ b/lib/ferrum/interceptable.rb @@ -3,31 +3,39 @@ module Ferrum # Shared by {Page} and {Worker}: subscribes to the CDP events behind the # `:request` (Fetch-domain request interception), `:response` (a request's - # response has fully loaded) and `:auth` (proxy/basic auth challenges) - # pseudo-events, on top of the includer's own `client` and `network`. - # Anything else is passed straight through to `client`. + # response has fully loaded), `:auth` (proxy/basic auth challenges) and + # `:console` (a new console message) pseudo-events, on top of the + # includer's own `client`, `network` and `console`. Anything else is passed + # straight through to `client`. module Interceptable - # Subscribes to a CDP event, or to `:request`/`:response`/`:auth`. + # Subscribes to a CDP event, or to `:request`/`:response`/`:auth`/`:console`. # # @param [Symbol, String] name # - # @yieldparam [Network::InterceptedRequest, Network::Exchange, Network::AuthRequest, Hash] arg + # @yieldparam [Network::InterceptedRequest, Network::Exchange, Network::AuthRequest, Console::Message, Hash] arg # For `:request`, the intercepted {Network::InterceptedRequest}. For # `:response`, the finished {Network::Exchange}. For `:auth`, the - # {Network::AuthRequest} challenge. For any other (raw CDP) event name, - # the event's params `Hash`. + # {Network::AuthRequest} challenge. For `:console`, the new + # {Console::Message}. For any other (raw CDP) event name, the event's + # params `Hash`. # # @yieldparam [Integer] index # This callback's position among all callbacks currently registered for - # the event. + # the event. Not passed for `:console`. # # @yieldparam [Integer] total - # Total number of callbacks currently registered for the event. + # Total number of callbacks currently registered for the event. Not + # passed for `:console`. # # @return [Integer] # The subscription id, used to unsubscribe via {#off}. + # + # @example + # page.on(:console) { |message| warn(message) if message.error? } def on(name, &block) case name + when :console + console.on(&block) when :request client.on("Fetch.requestPaused") do |params, index, total| request = Network::InterceptedRequest.new(client, params) @@ -60,6 +68,8 @@ def on(name, &block) # @return [void] def off(name, id) case name + when :console + console.off(id) when :request client.off("Fetch.requestPaused", id) when :response diff --git a/lib/ferrum/log.rb b/lib/ferrum/log.rb new file mode 100644 index 00000000..28d28e78 --- /dev/null +++ b/lib/ferrum/log.rb @@ -0,0 +1,245 @@ +# frozen_string_literal: true + +require "ferrum/log/paint" +require "ferrum/log/default" +require "ferrum/log/json" +require "ferrum/log/annotated" + +module Ferrum + # + # Writes Ferrum's debug output to the `:logger` given to {Browser.new}, split + # into channels: `:protocol` (CDP messages) and `:browser` (the output of the + # Chrome process Ferrum launched). + # + # The logger can be an IO-like object responding to `puts`, or a `Logger`, + # which gets every line at debug level with `ferrum:` as program + # name. Nothing is built for a disabled channel or a level the `Logger` skips. + # + # `FERRUM_LOG` picks what is written, see {.parse}. `FERRUM_LOG_FORMAT` picks + # how CDP messages look: `json` writes them as JSON alone, see {Json}, and + # `annotated` puts the command id and method in front of each message and + # its response, see {Annotated}. Without it they look as they always have, + # see {Default}. + # + # Written to a terminal, lines are colored with the basic ANSI colors, which + # terminal themes adapt to light and dark backgrounds. Files, pipes and + # `Logger`s get plain text, and so does a terminal when `NO_COLOR` is set. + # `FERRUM_LOG_COLOR=always` or `never` overrides both. + # + # Logging never breaks the browser: an error while formatting or writing a + # line, e.g. a closed IO, is reported once and the line skipped. + # + class Log + include Paint + + CHANNELS = %i[protocol browser].freeze + ALL = %w[* 1 true].freeze + OFF = %w[0 false].freeze + FORMATS = { default: Default, json: Json, annotated: Annotated }.freeze + VALUE_LENGTH = Integer(ENV.fetch("FERRUM_LOG_VALUE_LENGTH", 1024)) + + attr_reader :logger, :channels, :only, :skip + + # Parses `FERRUM_LOG`, a comma-separated list of: + # + # * `*`, `1` or `true` - all channels + # * `protocol`, `browser` - that channel, `-browser` leaves it out + # * `Page.*`, `Runtime.evaluate` - only CDP messages whose method matches, + # which turns `protocol` on + # * `-Network.*` - leaves out CDP messages whose method matches + # + # Without a channel or CDP pattern to log, all channels are logged, so + # `-browser` means everything but the browser output. Exclusions win over + # inclusions, and responses follow the command they answer. `0`, `false` + # or an empty value turn logging off. + # + # @param [String, nil] value + # + # @return [Hash{Symbol => Array}, nil] + # The `channels:`, `only:` and `skip:` for {#initialize}, `nil` when off. + def self.parse(value) + items = value.to_s.split(",").map(&:strip).reject(&:empty?) + return if items.all? { |item| OFF.include?(item) } + + patterns, names = items.partition { |item| item.include?(".") } + skip, only = patterns.partition { |pattern| pattern.start_with?("-") } + removed, added = names.partition { |name| name.start_with?("-") } + + channels = added.flat_map { |name| parse_channel(name) } + channels << :protocol if only.any? + channels = CHANNELS if channels.empty? + channels -= removed.flat_map { |name| parse_channel(name.delete_prefix("-")) } + + { channels: channels.uniq, only: only, skip: skip.map { |pattern| pattern.delete_prefix("-") } } + end + + # Parses one channel item of `FERRUM_LOG`, warning about an unknown one. + # + # @param [String] name + # + # @return [Array] + def self.parse_channel(name) + return CHANNELS if ALL.include?(name) + return [name.to_sym] if CHANNELS.include?(name.to_sym) + + warn "Ferrum: unknown FERRUM_LOG item #{name.inspect} is ignored" + [] + end + + # Parses `FERRUM_LOG_FORMAT`: `json`, `annotated` or `default`, which is + # also what an empty or unknown value means. + # + # @param [String, nil] value + # + # @return [Symbol] + def self.parse_format(value) + format = value.to_s.strip + return :default if format.empty? + return format.to_sym if FORMATS.key?(format.to_sym) + + warn "Ferrum: unknown FERRUM_LOG_FORMAT #{format.inspect}, using default" + :default + end + + # Parses `FERRUM_LOG_COLOR`, anything but `always` or `never` means `:auto`. + # + # @param [String, nil] value + # + # @return [Symbol] + def self.parse_color(value) + %w[always never].include?(value.to_s.strip) ? value.strip.to_sym : :auto + end + + # Encodes a CDP message, or a part of it, as JSON with string values longer + # than {VALUE_LENGTH} shortened, e.g. Base64 screenshots. + # `FERRUM_LOG_VALUE_LENGTH=0` keeps them whole. Messages nest as deep as + # Chrome sends them, e.g. a DOM tree, so there's no nesting limit. + # + # @param [Object] value + # + # @return [String] + def self.dump(value) + JSON.generate(truncate(value), max_nesting: false) + end + + # Shortens string values longer than {VALUE_LENGTH} anywhere in a CDP + # message. + # + # @param [Object] value + # + # @return [Object] + def self.truncate(value) + case value + when Hash then value.transform_values { |item| truncate(item) } + when Array then value.map { |item| truncate(item) } + when String + return value if VALUE_LENGTH.zero? || value.size <= VALUE_LENGTH + + "#{value[0, VALUE_LENGTH]}... (#{value.size - VALUE_LENGTH} more characters)" + else value + end + end + + def initialize(logger, channels: CHANNELS, only: [], skip: [], format: :default, color: :auto) + @logger = logger + @channels = channels + @only = only + @skip = skip + @color = case color + when :always then true + when :never then false + else logger.respond_to?(:tty?) && logger.tty? && ENV.fetch("NO_COLOR", "").empty? + end + @formatter = FORMATS.fetch(format).new(color: @color) + @commands = Concurrent::Map.new if format == :annotated || only.any? || skip.any? + end + + # Whether the channel is written to the logger. + # + # @param [Symbol] channel + # + # @return [Boolean] + def enabled?(channel) + channels.include?(channel) + end + + # Writes a CDP message sent to the browser. + # + # @param [Hash{Symbol => Object}] message + # + # @param [Object] connection + # What the message was sent over, command ids are unique per connection. + # + # @return [void] + def sent(message, connection = nil) + return unless enabled?(:protocol) + + @commands&.[]=([connection, message[:id]], [message[:method], Utils::ElapsedTime.monotonic_time]) + return unless show?(message[:method]) + + write(:protocol) { @formatter.sent(message, Utils::ElapsedTime.elapsed_time) } + end + + # Writes a CDP message received from the browser. + # + # @param [Hash{String => Object}, nil] message + # The parsed message, `nil` when it couldn't be parsed. + # + # @param [String] raw + # The message as received. + # + # @param [Object] connection + # What the message was received over. + # + # @return [void] + def received(message, raw, connection = nil) + return unless enabled?(:protocol) + + command = answered_command(message, connection) + return unless show?(message&.fetch("method", nil) || command&.first) + + write(:protocol) { @formatter.received(message, raw, Utils::ElapsedTime.elapsed_time, command) } + end + + # Writes a line of the browser process output. + # + # @param [String] line + # + # @return [void] + def browser(line) + write(:browser) { line } + end + + private + + def answered_command(message, connection) + return unless @commands && message&.key?("id") + + method, sent_at = @commands.delete([connection, message["id"]]) + [method, Utils::ElapsedTime.monotonic_time - sent_at] if method + end + + def show?(method) + return true unless method + + (only.empty? || matches?(only, method)) && !matches?(skip, method) + end + + def matches?(patterns, method) + patterns.any? { |pattern| File.fnmatch?(pattern, method) } + end + + def write(channel, &block) + return unless enabled?(channel) + + if logger.respond_to?(:debug) + logger.debug("ferrum:#{channel}", &block) + else + logger.puts(block.call) + end + rescue StandardError => e + warn "Ferrum: couldn't write to the logger, #{e.class}: #{e.message}" unless @write_failed + @write_failed = true + end + end +end diff --git a/lib/ferrum/log/annotated.rb b/lib/ferrum/log/annotated.rb new file mode 100644 index 00000000..993b3f2a --- /dev/null +++ b/lib/ferrum/log/annotated.rb @@ -0,0 +1,77 @@ +# frozen_string_literal: true + +require "ferrum/log/paint" + +module Ferrum + class Log + # + # Formats CDP messages one line each, the JSON whole after a header: the + # direction, the elapsed time, the command id and method. Received + # messages are indented under the commands sent. A response also + # names the method of its command and how long the answer took. Picked + # with `FERRUM_LOG_FORMAT=annotated`. + # + class Annotated + include Paint + + def initialize(color: false) + @color = color + end + + # @param [Hash{Symbol => Object}] message + # + # @param [Float] elapsed + # + # @return [String] + def sent(message, elapsed) + line(paint("▶", :cyan), time(elapsed), "##{message[:id]}", paint(message[:method], :bold), + json(message[:params]), session(message[:sessionId])) + end + + # @param [Hash{String => Object}, nil] message + # + # @param [String] raw + # + # @param [Float] elapsed + # + # @param [Array(String, Float), nil] command + # The method of the command this message answers and how long the + # answer took, in seconds. + # + # @return [String] + def received(message, raw, elapsed, command = nil) + return line(" ", paint("◀", :magenta), time(elapsed), raw) unless message + return event(message, elapsed) unless message.key?("id") + + method, duration = command + error = message["error"] + line(" ", paint("◀", error ? :red : :green), time(elapsed), "##{message['id']}", paint(method, :bold), + duration && "#{(duration * 1000).round}ms", json(error || message["result"]), + session(message["sessionId"])) + end + + private + + def event(message, elapsed) + line(" ", paint("◀", :magenta), time(elapsed), paint(message["method"], :bold), json(message["params"]), + session(message["sessionId"])) + end + + def line(*parts) + parts.map(&:to_s).reject(&:empty?).join(" ") + end + + def time(elapsed) + paint(format("%.3f", elapsed), :dim) + end + + def json(value) + Log.dump(value) unless value.nil? || value == {} + end + + def session(id) + paint("@#{id[0, 8]}", :dim) if id + end + end + end +end diff --git a/lib/ferrum/log/default.rb b/lib/ferrum/log/default.rb new file mode 100644 index 00000000..a98039f5 --- /dev/null +++ b/lib/ferrum/log/default.rb @@ -0,0 +1,55 @@ +# frozen_string_literal: true + +require "ferrum/log/paint" + +module Ferrum + class Log + # + # Formats CDP messages as Ferrum always has: the direction, the elapsed + # time and the message as JSON. On a terminal the arrow is colored by + # kind, the time dimmed and the method bold. + # + class Default + include Paint + + def initialize(color: false) + @color = color + end + + # @param [Hash{Symbol => Object}] message + # + # @param [Float] elapsed + # + # @return [String] + def sent(message, elapsed) + "\n\n#{paint('▶', :cyan)} #{paint(elapsed, :dim)} #{payload(message, message[:method])}" + end + + # @param [Hash{String => Object}, nil] message + # + # @param [String] raw + # + # @param [Float] elapsed + # + # @return [String] + def received(message, raw, elapsed, _command = nil) + arrow = if message.nil? || !message.key?("id") then :magenta + elsif message.key?("error") then :red + else :green + end + body = message ? payload(message, message["method"]) : raw + + " #{paint('◀', arrow)} #{paint(elapsed, :dim)} #{body}\n" + end + + private + + def payload(message, method) + json = Log.dump(message) + return json unless method && color? + + json.sub(%("method":"#{method}"), %("method":"#{paint(method, :bold)}")) + end + end + end +end diff --git a/lib/ferrum/log/json.rb b/lib/ferrum/log/json.rb new file mode 100644 index 00000000..5a523382 --- /dev/null +++ b/lib/ferrum/log/json.rb @@ -0,0 +1,32 @@ +# frozen_string_literal: true + +module Ferrum + class Log + # + # Formats CDP messages as JSON alone, one message per line, for tools such + # as `jq`. Commands, responses and events tell apart by their keys: `id` + # and `method`, `id` and `result` or `error`, `method` alone. Never + # colored. Picked with `FERRUM_LOG_FORMAT=json`. + # + class Json + def initialize(**); end + + # @param [Hash{Symbol => Object}] message + # + # @return [String] + def sent(message, _elapsed) + Log.dump(message) + end + + # @param [Hash{String => Object}, nil] message + # + # @param [String] raw + # Written as is when the message couldn't be parsed. + # + # @return [String] + def received(message, raw, _elapsed, _command = nil) + message ? Log.dump(message) : raw + end + end + end +end diff --git a/lib/ferrum/log/paint.rb b/lib/ferrum/log/paint.rb new file mode 100644 index 00000000..b67bd977 --- /dev/null +++ b/lib/ferrum/log/paint.rb @@ -0,0 +1,28 @@ +# frozen_string_literal: true + +module Ferrum + class Log + # + # Wraps text in basic ANSI colors, which terminal themes adapt to light + # and dark backgrounds, when the includer's `@color` is set. + # + module Paint + COLORS = { bold: 1, dim: 2, red: 31, green: 32, yellow: 33, magenta: 35, cyan: 36 }.freeze + + # Whether text gets colored. + # + # @return [Boolean] + def color? + @color + end + + private + + def paint(text, color) + return text.to_s unless color && color? + + "\e[#{COLORS.fetch(color)}m#{text}\e[0m" + end + end + end +end diff --git a/lib/ferrum/page.rb b/lib/ferrum/page.rb index f7d69470..e52a20bb 100644 --- a/lib/ferrum/page.rb +++ b/lib/ferrum/page.rb @@ -8,6 +8,7 @@ require "ferrum/cookies" require "ferrum/dialog" require "ferrum/network" +require "ferrum/console" require "ferrum/accessibility" require "ferrum/interceptable" require "ferrum/downloads" @@ -67,6 +68,11 @@ class Page # @return [Network] attr_reader :network + # Console messages. + # + # @return [Console] + attr_reader :console + # Accessibility object. # # @return [Accessibility] @@ -110,6 +116,7 @@ def initialize(client, context_id:, target_id:, proxy: nil) @headers = Headers.new(self) @cookies = Cookies.new(self) @network = Network.new(self) + @console = Console.new(self) @accessibility = Accessibility.new(self) @tracing = Tracing.new(self) @downloads = Downloads.new(self) @@ -535,16 +542,11 @@ def document_node_id(async: false) def subscribe frames_subscribe network.subscribe + console.subscribe downloads.subscribe on("DOM.documentUpdated") { @document_version += 1 } - if @options.logger - on("Runtime.consoleAPICalled") do |params| - log_console_api(params) - end - end - if @options.js_errors on("Runtime.exceptionThrown") do |params| # FIXME: https://jvns.ca/blog/2015/11/27/why-rubys-timeout-is-dangerous-and-thread-dot-raise-is-terrifying/ @@ -598,16 +600,6 @@ def prepare_page document_node_id end - def log_console_api(params) - message = params.fetch("args", []).filter_map { |arg| arg["value"] || arg["description"] }.join(" ") - @options.logger.puts("[#{params['type']}] #{message}") - - params.dig("stackTrace", "callFrames")&.each do |frame| - location = "#{frame['url']}:#{frame['lineNumber'].to_i + 1}:#{frame['columnNumber'].to_i + 1}" - @options.logger.puts(" at #{frame['functionName']} (#{location})") - end - end - def inject_extensions @options.extensions.each do |extension| # https://github.com/GoogleChrome/puppeteer/issues/1443 diff --git a/lib/ferrum/worker.rb b/lib/ferrum/worker.rb index 0968efa8..fbe3d869 100644 --- a/lib/ferrum/worker.rb +++ b/lib/ferrum/worker.rb @@ -2,6 +2,7 @@ require "ferrum/frame/runtime" require "ferrum/interceptable" +require "ferrum/console" module Ferrum # A dedicated or shared Worker spawned by a page. Unlike {Page} it has no @@ -26,6 +27,7 @@ def initialize(client, target_id:, url:) @page = self @execution_id = Concurrent::MVar.new @network = Network.new(self) + @console = Console.new(self) subscribe prepare @@ -36,6 +38,11 @@ def initialize(client, target_id:, url:) # @return [Network] attr_reader :network + # Console messages. + # + # @return [Console] + attr_reader :console + # How long to wait for CDP responses and JS evaluation to complete. # # @return [Numeric] @@ -88,6 +95,7 @@ def inspect def subscribe network.subscribe + console.subscribe on("Runtime.executionContextCreated") do |params| self.execution_id = params.dig("context", "id") diff --git a/sig/ferrum/browser/options.rbs b/sig/ferrum/browser/options.rbs index 87080fde..240aabb8 100644 --- a/sig/ferrum/browser/options.rbs +++ b/sig/ferrum/browser/options.rbs @@ -15,8 +15,6 @@ module Ferrum PROCESS_TIMEOUT: ::Integer - DEBUG_MODE: bool - attr_reader window_size: ::Array[::Integer] attr_accessor timeout: ::Numeric @@ -25,7 +23,8 @@ module Ferrum attr_accessor default_user_agent: String? - attr_reader logger: (IO | StringIO | nil) + attr_reader logger: untyped + attr_reader log: Log? attr_reader ws_max_receive_size: ::Integer? @@ -90,7 +89,8 @@ module Ferrum @ws_max_receive_size: ::Integer? @ignore_default_browser_options: bool? @proxy: Hash[Symbol, (String | ::Integer)]? - @logger: (IO | nil) + @logger: untyped + @log: Log? @base_url: ::Addressable::URI? @url: String? @ws_url: String? @@ -110,7 +110,7 @@ module Ferrum private - def parse_logger: ((IO | StringIO | bool | nil) logger) -> (IO | StringIO | nil) + def parse_logger: (untyped logger) -> [untyped, Log?] def parse_base_url: (String value) -> ::Addressable::URI end diff --git a/sig/ferrum/browser/process.rbs b/sig/ferrum/browser/process.rbs index 70c9256c..025f9b6c 100644 --- a/sig/ferrum/browser/process.rbs +++ b/sig/ferrum/browser/process.rbs @@ -7,6 +7,8 @@ module Ferrum LOCAL_HOSTS: ::Array[String] + WS_URL: Regexp + attr_reader host: String? attr_reader port: ::Integer? @@ -19,10 +21,13 @@ module Ferrum attr_reader xvfb: Browser::Xvfb? + attr_reader output: Output + @pid: ::Integer? @xvfb: Browser::Xvfb? @user_data_dir: String? - @logger: (IO | nil) + @log: Log? + @output: Output @process_timeout: ::Integer @env: Hash[String, String] @command: Browser::Command? @@ -47,13 +52,15 @@ module Ferrum private + def spawn_browser: (IO io) -> void + def sync_stop: () -> nil def async_stop: () -> Thread def remove_user_data_dir: () -> void - def parse_ws_url: (IO read_io, ::Integer timeout) -> String? + def parse_ws_url: () -> void def ws_url=: (String? url) -> void @@ -61,8 +68,6 @@ module Ferrum def fetch_ws_url: (Addressable::URI | String url) -> String - def close_io: (*IO ios) -> void - def json_version_url: (Addressable::URI | String url) -> Addressable::URI def reachable_ws_url: (String? ws_url, Addressable::URI | String endpoint) -> String? diff --git a/sig/ferrum/browser/process/output.rbs b/sig/ferrum/browser/process/output.rbs new file mode 100644 index 00000000..ff4ff6cd --- /dev/null +++ b/sig/ferrum/browser/process/output.rbs @@ -0,0 +1,39 @@ +module Ferrum + class Browser + class Process + class Output + LIMIT: ::Integer + DRAIN_TIMEOUT: ::Float + + @log: Log? + @lines: Array[String] + @partial: String + @mutex: ::Thread::Mutex + @io: IO? + @reader: ::Thread? + + def initialize: (?Log? log) -> void + + def pipe: () { (IO io) -> void } -> void + + def wait_for: (Regexp regexp, ::Numeric timeout) -> MatchData? + + def follow: () -> ::Thread + + def close: () -> void + + def <<: (String chunk) -> self + + def lines: () -> Array[String] + + def to_s: () -> String + + private + + def utf8: (String line) -> String + + def close_io: (IO? io) -> void + end + end + end +end diff --git a/sig/ferrum/client/web_socket.rbs b/sig/ferrum/client/web_socket.rbs index 69144d46..73c16247 100644 --- a/sig/ferrum/client/web_socket.rbs +++ b/sig/ferrum/client/web_socket.rbs @@ -3,21 +3,19 @@ module Ferrum class WebSocket WEBSOCKET_BUG_SLEEP: Float DEFAULT_PORTS: Hash[String, Integer] - SKIP_LOGGING_SCREENSHOTS: bool attr_reader url: (String | ::Addressable::URI) attr_reader messages: ::Queue @url: String - @logger: untyped + @log: Log? @sock: (::TCPSocket | ::OpenSSL::SSL::SSLSocket) @driver: untyped @messages: ::Queue - @screenshot_commands: ::Concurrent::Hash[Integer, bool]? @thread: ::Thread @write_timeout: ::Numeric? - def initialize: ((String | ::Addressable::URI) url, Integer? max_receive_size, untyped logger) -> void + def initialize: ((String | ::Addressable::URI) url, Integer? max_receive_size, Log? log) -> void def on_open: (untyped event) -> void diff --git a/sig/ferrum/console.rbs b/sig/ferrum/console.rbs new file mode 100644 index 00000000..47d8934a --- /dev/null +++ b/sig/ferrum/console.rbs @@ -0,0 +1,42 @@ +module Ferrum + class Console + include Enumerable[Console::Message] + + LIMIT: ::Integer + + @page: (Page | Worker) + @messages: Array[Console::Message] + @listeners: ::Concurrent::Map[::Integer, ^(Console::Message) -> void] + @listener_id: ::Concurrent::AtomicFixnum + @mutex: ::Thread::Mutex + + def initialize: ((Page | Worker) page) -> void + + def each: () { (Console::Message) -> void } -> self + | () -> ::Enumerator[Console::Message, self] + + def to_a: () -> Array[Console::Message] + + def last: () -> Console::Message? + + def size: () -> ::Integer + + def empty?: () -> bool + + def clear: () -> self + + def on: () { (Console::Message) -> void } -> ::Integer + + def off: (::Integer id) -> void + + def subscribe: () -> void + + def inspect: () -> String + + private + + def replayed?: (Hash[String, untyped] params) -> bool + + def add: (Console::Message message) -> void + end +end diff --git a/sig/ferrum/console/location.rbs b/sig/ferrum/console/location.rbs new file mode 100644 index 00000000..40b894c5 --- /dev/null +++ b/sig/ferrum/console/location.rbs @@ -0,0 +1,21 @@ +module Ferrum + class Console + class Location + attr_reader url: String + attr_reader line: ::Integer? + attr_reader column: ::Integer? + attr_reader function_name: String + + @url: String + @line: ::Integer? + @column: ::Integer? + @function_name: String + + def self.from_frame: (Hash[String, untyped] frame) -> Location + + def initialize: (url: String, ?line: ::Integer?, ?column: ::Integer?, ?function_name: String) -> void + + def to_s: () -> String + end + end +end diff --git a/sig/ferrum/console/message.rbs b/sig/ferrum/console/message.rbs new file mode 100644 index 00000000..60e84857 --- /dev/null +++ b/sig/ferrum/console/message.rbs @@ -0,0 +1,67 @@ +module Ferrum + class Console + class Message + SEVERITIES: Hash[Symbol, Symbol] + UNSERIALIZABLE: Hash[String, ::Float] + + attr_reader type: Symbol + attr_reader source: Symbol + attr_reader timestamp: ::Time + + @type: Symbol + @source: Symbol + @timestamp: ::Time + @raw_args: Array[Hash[String, untyped]] + @raw_text: String? + @frames: Array[Hash[String, untyped]] + @text: String? + @args: Array[untyped]? + @stack_trace: Array[Location]? + + def self.from_console_api: (Hash[String, untyped] params) -> Message + + def self.from_log_entry: (Hash[String, untyped] entry) -> Message + + def self.from_exception: (Hash[String, untyped] params) -> Message + + def initialize: (type: String, source: String, timestamp: ::Numeric?, ?raw_args: Array[Hash[String, untyped]]?, + ?raw_text: String?, ?frames: Array[Hash[String, untyped]]?) -> void + + def text: () -> String + + def args: () -> Array[untyped] + + def stack_trace: () -> Array[Location] + + def location: () -> Location? + + def severity: () -> (:debug | :info | :warn | :error) + + def error?: () -> bool + + def warning?: () -> bool + + def match?: (Regexp | String pattern) -> bool + + def to_s: () -> String + + def inspect: () -> String + + private + + def underscore: (String? name) -> Symbol + + def arg_text: (Hash[String, untyped] arg) -> String + + def arg_value: (Hash[String, untyped] arg) -> untyped + + def preview_value: (Hash[String, untyped]? preview) -> (Hash[String, untyped] | Array[untyped])? + + def property_value: (Hash[String, untyped] property) -> untyped + + def unserializable: (String value) -> (::Float | ::Integer | String) + + def parse_number: (String value) -> (::Float | ::Integer | String) + end + end +end diff --git a/sig/ferrum/interceptable.rbs b/sig/ferrum/interceptable.rbs index bfa5a61b..7271aafa 100644 --- a/sig/ferrum/interceptable.rbs +++ b/sig/ferrum/interceptable.rbs @@ -3,6 +3,7 @@ module Ferrum def on: (:request) { (Network::InterceptedRequest, Integer, Integer) -> void } -> Integer | (:response) { (Network::Exchange, Integer, Integer) -> void } -> Integer | (:auth) { (Network::AuthRequest, Integer, Integer) -> void } -> Integer + | (:console) { (Console::Message) -> void } -> Integer | (Symbol | String name) { (*untyped) -> void } -> Integer def off: (Symbol | String name, Integer id) -> void diff --git a/sig/ferrum/log.rbs b/sig/ferrum/log.rbs new file mode 100644 index 00000000..84b068db --- /dev/null +++ b/sig/ferrum/log.rbs @@ -0,0 +1,57 @@ +module Ferrum + class Log + include Paint + + CHANNELS: Array[Symbol] + ALL: Array[String] + OFF: Array[String] + FORMATS: Hash[Symbol, (singleton(Default) | singleton(Json) | singleton(Annotated))] + VALUE_LENGTH: ::Integer + + attr_reader logger: untyped + attr_reader channels: Array[Symbol] + attr_reader only: Array[String] + attr_reader skip: Array[String] + + @logger: untyped + @channels: Array[Symbol] + @only: Array[String] + @skip: Array[String] + @color: bool + @formatter: (Default | Json | Annotated) + @write_failed: bool? + @commands: ::Concurrent::Map[[untyped, ::Integer], [String, ::Float]]? + + def self.parse: (String? value) -> { channels: Array[Symbol], only: Array[String], skip: Array[String] }? + + def self.parse_channel: (String name) -> Array[Symbol] + + def self.parse_format: (String? value) -> Symbol + + def self.parse_color: (String? value) -> Symbol + + def self.dump: (untyped value) -> String + + def self.truncate: (untyped value) -> untyped + + def initialize: (untyped logger, ?channels: Array[Symbol], ?only: Array[String], ?skip: Array[String], ?format: Symbol, ?color: Symbol) -> void + + def enabled?: (Symbol channel) -> bool + + def sent: (Hash[Symbol, untyped] message, ?untyped connection) -> void + + def received: (Hash[String, untyped]? message, String raw, ?untyped connection) -> void + + def browser: (String line) -> void + + private + + def answered_command: (Hash[String, untyped]? message, untyped connection) -> [String, ::Float]? + + def show?: (String? method) -> bool + + def matches?: (Array[String] patterns, String method) -> bool + + def write: (Symbol channel) { () -> String } -> void + end +end diff --git a/sig/ferrum/log/annotated.rbs b/sig/ferrum/log/annotated.rbs new file mode 100644 index 00000000..daeee8a6 --- /dev/null +++ b/sig/ferrum/log/annotated.rbs @@ -0,0 +1,25 @@ +module Ferrum + class Log + class Annotated + include Paint + + def initialize: (?color: bool) -> void + + def sent: (Hash[Symbol, untyped] message, ::Float elapsed) -> String + + def received: (Hash[String, untyped]? message, String raw, ::Float elapsed, ?[String, ::Float]? command) -> String + + private + + def event: (Hash[String, untyped] message, ::Float elapsed) -> String + + def line: (*untyped parts) -> String + + def time: (::Float elapsed) -> String + + def json: (untyped value) -> String? + + def session: (String? id) -> String? + end + end +end diff --git a/sig/ferrum/log/default.rbs b/sig/ferrum/log/default.rbs new file mode 100644 index 00000000..fdfe820e --- /dev/null +++ b/sig/ferrum/log/default.rbs @@ -0,0 +1,17 @@ +module Ferrum + class Log + class Default + include Paint + + def initialize: (?color: bool) -> void + + def sent: (Hash[Symbol, untyped] message, ::Float elapsed) -> String + + def received: (Hash[String, untyped]? message, String raw, ::Float elapsed, ?[String, ::Float]? _command) -> String + + private + + def payload: (Hash[Symbol | String, untyped] message, String? method) -> String + end + end +end diff --git a/sig/ferrum/log/json.rbs b/sig/ferrum/log/json.rbs new file mode 100644 index 00000000..d36ef122 --- /dev/null +++ b/sig/ferrum/log/json.rbs @@ -0,0 +1,11 @@ +module Ferrum + class Log + class Json + def initialize: (**untyped) -> void + + def sent: (Hash[Symbol, untyped] message, ::Float _elapsed) -> String + + def received: (Hash[String, untyped]? message, String raw, ::Float _elapsed, ?[String, ::Float]? _command) -> String + end + end +end diff --git a/sig/ferrum/log/paint.rbs b/sig/ferrum/log/paint.rbs new file mode 100644 index 00000000..ce0f13d2 --- /dev/null +++ b/sig/ferrum/log/paint.rbs @@ -0,0 +1,15 @@ +module Ferrum + class Log + module Paint + COLORS: Hash[Symbol, ::Integer] + + @color: bool + + def color?: () -> bool + + private + + def paint: (untyped text, Symbol? color) -> String + end + end +end diff --git a/sig/ferrum/page.rbs b/sig/ferrum/page.rbs index 51553300..927c2f4f 100644 --- a/sig/ferrum/page.rbs +++ b/sig/ferrum/page.rbs @@ -19,6 +19,7 @@ module Ferrum attr_reader mouse: Mouse attr_reader keyboard: Keyboard attr_reader network: Network + attr_reader console: Console attr_reader accessibility: Accessibility attr_reader headers: Headers attr_reader cookies: Cookies @@ -38,6 +39,7 @@ module Ferrum @headers: Headers @cookies: Cookies @network: Network + @console: Console @tracing: Page::Tracing @downloads: Downloads @referrer: String? @@ -87,6 +89,7 @@ module Ferrum def command: (String method, ?wait: ::Numeric?, ?slowmoable: bool, ?timeout: ::Numeric?, **untyped) -> Hash[String, untyped] def on: (:dialog) { (Dialog, Integer, Integer) -> void } -> Integer + | (:console) { (Console::Message) -> void } -> Integer | (:request) { (Network::InterceptedRequest, Integer, Integer) -> void } -> Integer | (:response) { (Network::Exchange, Integer, Integer) -> void } -> Integer | (:auth) { (Network::AuthRequest, Integer, Integer) -> void } -> Integer diff --git a/sig/ferrum/worker.rbs b/sig/ferrum/worker.rbs index 675766ad..ae505d47 100644 --- a/sig/ferrum/worker.rbs +++ b/sig/ferrum/worker.rbs @@ -7,6 +7,7 @@ module Ferrum attr_reader target_id: String attr_reader url: String attr_reader network: Network + attr_reader console: Console @client: (Client | SessionClient) @target_id: String @@ -15,6 +16,7 @@ module Ferrum @page: Worker @execution_id: untyped @network: Network + @console: Console def initialize: ((Client | SessionClient) client, target_id: String, url: String) -> void diff --git a/spec/browser/options/chrome_spec.rb b/spec/browser/options/chrome_spec.rb index 66ef043f..4899505f 100644 --- a/spec/browser/options/chrome_spec.rb +++ b/spec/browser/options/chrome_spec.rb @@ -27,7 +27,7 @@ end describe ".version" do - it "returns an executable version", local_browser: true do + it "returns an executable version", :launch do expect(described_class.version).to match(/(Chromium|Chrome)(?: for Testing)? \d/) end end diff --git a/spec/browser/xvfb_spec.rb b/spec/browser/xvfb_spec.rb index 8bd5a51b..0788399d 100644 --- a/spec/browser/xvfb_spec.rb +++ b/spec/browser/xvfb_spec.rb @@ -1,6 +1,6 @@ # frozen_string_literal: true -describe Ferrum::Browser::Xvfb, local_browser: true, skip: !Ferrum::Browser::Binary.find("Xvfb") do +describe Ferrum::Browser::Xvfb, :launch, skip: !Ferrum::Browser::Binary.find("Xvfb") do let(:process) { xvfb_browser.process } let(:xvfb_browser) { Ferrum::Browser.new(default_options.merge(options)) } let(:default_options) { Hash(headless: true, xvfb: true) } diff --git a/spec/browser_spec.rb b/spec/browser_spec.rb index 2c34f71a..2ec9237a 100644 --- a/spec/browser_spec.rb +++ b/spec/browser_spec.rb @@ -1,5 +1,6 @@ # frozen_string_literal: true +require "logger" require "ferrum/proxy" describe Ferrum::Browser do @@ -17,7 +18,7 @@ end end - it "supports custom chrome path", local_browser: true do + it "supports custom chrome path", :launch do original_path = "#{PROJECT_ROOT}/spec/support/chrome_path" File.write(original_path, browser.process.path) @@ -43,18 +44,227 @@ end end - it "supports :logger argument", local_browser: true do - browser = Ferrum::Browser.new(logger: logger) - browser.go_to(base_url("/console_log")) - expect(logger.string).to include("Hello world") - expect(logger.string).to include("[log] Hello world") - expect(logger.string).to include("at window.onload") - expect(logger.string).to include("/console_log") + context ":logger argument" do + it "supports :logger argument", :launch do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + wait_for { logger.string }.to include("Runtime.consoleAPICalled") + expect(logger.string).to include("DevTools listening on") + expect(logger.string).not_to include("[log] Hello world") + ensure + browser&.quit + end + + it "writes to a Logger at debug level", :launch do + browser = Ferrum::Browser.new(logger: Logger.new(logger, level: :debug)) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include("DEBUG -- ferrum:browser: DevTools listening on") + expect(logger.string).to include("DEBUG -- ferrum:protocol: \n\n▶") + ensure + browser&.quit + end + + it "writes nothing to a Logger above debug level", :launch do + browser = Ferrum::Browser.new(logger: Logger.new(logger, level: :info)) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to be_empty + ensure + browser&.quit + end + + it "logs to $stdout with FERRUM_LOG", :launch do + with_env("FERRUM_LOG" => "browser") do + expect do + Ferrum::Browser.new.quit + end.to output(/DevTools listening on/).to_stdout + end + end + + it "logs nothing with FERRUM_LOG=0", :launch do + with_env("FERRUM_LOG" => "0") do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to be_empty + ensure + browser&.quit + end + end + + it "logs everything with the deprecated FERRUM_DEBUG", :launch do + with_env("FERRUM_DEBUG" => "true") do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include("Page.navigate") + expect(logger.string).to include("DevTools listening on") + ensure + browser&.quit + end + end + + it "leaves out the channels excluded in FERRUM_LOG", :launch do + with_env("FERRUM_LOG" => "*,-browser") do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include("Page.navigate") + expect(logger.string).not_to include("DevTools listening on") + ensure + browser&.quit + end + end + + it "logs only CDP messages matching FERRUM_LOG", :launch do + with_env("FERRUM_LOG" => "Page.navigate") do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include(%("method":"Page.navigate")) + expect(logger.string).to match(/"result":\{"frameId":"\h+","loaderId"/) + expect(logger.string).not_to include("Runtime.") + expect(logger.string).not_to include("DevTools listening on") + ensure + browser&.quit + end + end + + it "leaves out CDP messages excluded in FERRUM_LOG", :launch do + with_env("FERRUM_LOG" => "protocol,-Network.*,-Page.navigate") do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + wait_for { logger.string }.to include("Runtime.consoleAPICalled") + expect(logger.string).not_to include("Network.") + expect(logger.string).not_to include("Page.navigate") + expect(logger.string).not_to match(/"result":\{"frameId":"\h+","loaderId"/) + ensure + browser&.quit + end + end + + it "writes CDP messages as JSON alone with FERRUM_LOG_FORMAT=json", :launch do + with_env("FERRUM_LOG" => "protocol", "FERRUM_LOG_FORMAT" => "json") do + def logger.tty? = true + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + messages = logger.string.lines.map { |line| JSON.parse(line) } + expect(messages).to include(a_hash_including("method" => "Page.navigate", "params" => { "url" => base_url("/console_log") })) + expect(messages).to include(a_hash_including("id" => a_kind_of(Integer), "result" => a_hash_including("frameId"))) + ensure + browser&.quit + end + end + + it "annotates CDP messages with FERRUM_LOG_FORMAT=annotated", :launch do + with_env("FERRUM_LOG_FORMAT" => "annotated") do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to match(%r{^▶ \d+\.\d{3} #\d+ Page\.navigate \{"url":"http://[^"]+/console_log"\} @\h{8}$}) + id = logger.string[/▶ \S+ #(\d+) Page\.navigate/, 1] + expect(logger.string).to match(/^ ◀ \d+\.\d{3} ##{id} Page\.navigate \d+ms \{"frameId":"\h+",.+\} @\h{8}$/) + wait_for { logger.string }.to match(/^ ◀ \d+\.\d{3} Runtime\.consoleAPICalled \{"type":"log"/) + ensure + browser&.quit + end + end + + it "colors protocol lines written to a terminal", :launch do + def logger.tty? = true + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include(%("method":"\e[1mPage.navigate\e[0m")) + expect(logger.string).to include("\e[36m▶\e[0m") + ensure + browser&.quit + end + + it "writes plain text when not writing to a terminal", :launch do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include("Page.navigate") + expect(logger.string).not_to include("\e[") + ensure + browser&.quit + end + + it "colors lines written anywhere with FERRUM_LOG_COLOR=always", :launch do + with_env("FERRUM_LOG_COLOR" => "always") do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include("\e[36m▶\e[0m") + ensure + browser&.quit + end + end + + it "writes plain text to a terminal with FERRUM_LOG_COLOR=never", :launch do + with_env("FERRUM_LOG_COLOR" => "never") do + def logger.tty? = true + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + + expect(logger.string).to include("Page.navigate") + expect(logger.string).not_to include("\e[") + ensure + browser&.quit + end + end + + it "keeps the browser working when the logger fails", :launch do + broken = Object.new + def broken.puts(*) = raise(IOError, "closed stream") + browser = nil + + expect do + browser = Ferrum::Browser.new(logger: broken) + browser.go_to(base_url("/console_log")) + end.to output(/couldn't write to the logger, IOError: closed stream/).to_stderr + expect(browser.evaluate("1 + 1")).to eq(2) + ensure + browser&.quit + end + + it "logs CDP messages nested deeper than JSON's default limit", :launch do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/deeply_nested")) + + expect(browser.evaluate(%(document.getElementById("text"))).text).to eq("text") + expect(logger.string).to include("DOM.describeNode") + ensure + browser&.quit + end + + it "shortens long strings in logged CDP messages", :launch, skip: Ferrum::Log::VALUE_LENGTH.zero? do + browser = Ferrum::Browser.new(logger: logger) + browser.go_to(base_url("/console_log")) + screenshot = browser.screenshot(encoding: :base64) + + expect(logger.string).not_to include(screenshot) + expect(logger.string).to include("#{screenshot[0, Ferrum::Log::VALUE_LENGTH]}... (" \ + "#{screenshot.size - Ferrum::Log::VALUE_LENGTH} more characters)") + ensure + browser&.quit + end + end + + it "keeps the output of the browser process", :launch do + browser = Ferrum::Browser.new + + expect(browser.process.output.lines).to include(a_string_starting_with("DevTools listening on")) ensure browser&.quit end - it "supports :ignore_default_browser_options argument", local_browser: true do + it "supports :ignore_default_browser_options argument", :launch do defaults = Ferrum::Browser::Options::Chrome.options.except("mute-audio") browser = Ferrum::Browser.new(ignore_default_browser_options: true, browser_options: defaults.merge("no-sandbox" => nil)) @@ -92,7 +302,7 @@ end context ":extensions argument" do - it "extends the browser's world with files", local_browser: true do + it "extends the browser's world with files", :launch do browser = Ferrum::Browser.new(base_url: base_url, extensions: [File.expand_path("support/geolocation.js", __dir__)]) @@ -113,7 +323,7 @@ browser&.quit end - it "extends the browser's world with source", local_browser: true do + it "extends the browser's world with source", :launch do browser = Ferrum::Browser.new(base_url: base_url, extensions: [{ source: "window.secret = 'top'" }]) @@ -124,7 +334,7 @@ browser&.quit end - it "errors when extension is unavailable", local_browser: true do + it "errors when extension is unavailable", :launch do browser = Ferrum::Browser.new(extensions: [File.expand_path("../support/non_existent.js", __dir__)]) expect { browser.go_to }.to raise_error(Errno::ENOENT) ensure @@ -132,7 +342,7 @@ end end - it "supports :port argument", local_browser: true do + it "supports :port argument", :launch do browser = Ferrum::Browser.new(port: 12_345) browser.go_to(base_url) @@ -141,7 +351,7 @@ browser&.quit end - it "supports :url argument", local_browser: true do + it "supports :url argument", :launch do with_external_browser do |url, _process| browser = Ferrum::Browser.new(url: url) browser.go_to(base_url) @@ -211,7 +421,7 @@ def proxy_tunnel(socket, request, browser_url) upstream&.close end - it "supports :url argument with a query string", local_browser: true do + it "supports :url argument with a query string", :launch do with_external_browser do |url, _process| with_token_authenticated_proxy(url, token: "secret") do |proxy_url| browser = Ferrum::Browser.new(url: proxy_url) @@ -226,7 +436,7 @@ def proxy_tunnel(socket, request, browser_url) end end - it "adds headers when /json/version has no User-Agent", local_browser: true do + it "adds headers when /json/version has no User-Agent", :launch do with_external_browser do |url, _process| with_token_authenticated_proxy(url, token: "secret", json_version: :without_user_agent) do |proxy_url| browser = Ferrum::Browser.new(url: proxy_url, base_url: base_url) @@ -241,7 +451,7 @@ def proxy_tunnel(socket, request, browser_url) end end - it "raises when :url doesn't answer with a websocket url", local_browser: true do + it "raises when :url doesn't answer with a websocket url", :launch do with_external_browser do |url, _process| with_token_authenticated_proxy(url, token: "secret") do |proxy_url| unauthorized = proxy_url.sub("secret", "wrong") @@ -252,7 +462,7 @@ def proxy_tunnel(socket, request, browser_url) end end - it "supports :ws_url argument", local_browser: true do + it "supports :ws_url argument", :launch do with_external_browser do |url, _process| browser = Ferrum::Browser.new(ws_url: web_socket_debugger_url(url)) browser.go_to(base_url) @@ -263,7 +473,7 @@ def proxy_tunnel(socket, request, browser_url) end end - it "supports :ws_url argument without asking /json/version", local_browser: true do + it "supports :ws_url argument without asking /json/version", :launch do with_external_browser do |url, _process| with_token_authenticated_proxy(url, token: "secret", json_version: :missing) do |proxy_url| path = Addressable::URI.parse(web_socket_debugger_url(url)).path @@ -301,7 +511,7 @@ def proxy_tunnel(socket, request, browser_url) after { proxy.stop } context "without authorization" do - it "works without authorization", local_browser: true do + it "works without authorization", :launch do browser = Ferrum::Browser.new( proxy: { host: proxy.host, port: proxy.port } ) @@ -317,7 +527,7 @@ def proxy_tunnel(socket, request, browser_url) context "with authorization" do let(:options) { Hash(user: "user", password: "pa$$") } - it "works with right password", local_browser: true do + it "works with right password", :launch do browser = Ferrum::Browser.new( proxy: { host: proxy.host, port: proxy.port, **options } ) @@ -329,7 +539,7 @@ def proxy_tunnel(socket, request, browser_url) browser&.quit end - it "breaks with wrong password", local_browser: true do + it "breaks with wrong password", :launch do browser = Ferrum::Browser.new( proxy: { host: proxy.host, port: proxy.port, user: "u1", password: "p1" } ) @@ -343,7 +553,7 @@ def proxy_tunnel(socket, request, browser_url) browser&.quit end - it "lets requests be aborted", local_browser: true do + it "lets requests be aborted", :launch do browser = Ferrum::Browser.new( proxy: { host: proxy.host, port: proxy.port, **options } ) @@ -358,7 +568,7 @@ def proxy_tunnel(socket, request, browser_url) browser&.quit end - it "supports blacklist", local_browser: true do + it "supports blacklist", :launch do browser = Ferrum::Browser.new( proxy: { host: proxy.host, port: proxy.port, **options } ) @@ -398,7 +608,7 @@ def proxy_tunnel(socket, request, browser_url) end end - it "supports :pending_connection_errors argument", local_browser: true do + it "supports :pending_connection_errors argument", :launch do browser = Ferrum::Browser.new(base_url: base_url, pending_connection_errors: true, timeout: 0.5) expect { browser.go_to("/really_slow") }.to raise_error(Ferrum::PendingConnectionsError) @@ -436,7 +646,7 @@ def proxy_tunnel(socket, request, browser_url) context "with local path" do let(:save_path) { "spec/tmp" } - it "raises an error", local_browser: true do + it "raises an error", :launch do expect do browser.go_to("/#{filename}") end.to raise_error(Ferrum::Error, "supply absolute path for `:save_path` option") @@ -445,14 +655,14 @@ def proxy_tunnel(socket, request, browser_url) end context "with error on initialize" do - it "stops process if an error is raised during process start", local_browser: true do + it "stops process if an error is raised during process start", :launch do process = Ferrum::Browser::Process.new(Ferrum::Browser::Options.new(process_timeout: 0)) allow(Ferrum::Browser::Process).to receive(:new).and_return(process) expect { Ferrum::Browser.new }.to raise_error(Ferrum::ProcessTimeoutError) expect(process.pid).to be(nil) end - it "stops process if an error is raised during client creation", local_browser: true do + it "stops process if an error is raised during client creation", :launch do process = Ferrum::Browser::Process.new(Ferrum::Browser::Options.new) allow(Ferrum::Browser::Process).to receive(:new).and_return(process) @@ -463,7 +673,7 @@ def proxy_tunnel(socket, request, browser_url) expect(process.pid).to be(nil) end - it "stops process if an error is raised during contexts creation", local_browser: true do + it "stops process if an error is raised during contexts creation", :launch do process = Ferrum::Browser::Process.new(Ferrum::Browser::Options.new) allow(Ferrum::Browser::Process).to receive(:new).and_return(process) @@ -521,14 +731,14 @@ def proxy_tunnel(socket, request, browser_url) end describe "#quit" do - it "stops silently before go_to call", local_browser: true do + it "stops silently before go_to call", :launch do browser = Ferrum::Browser.new expect { browser.quit }.not_to raise_error ensure browser&.quit end - it "supports stopping the session", skip: Ferrum::Utils::Platform.windows?, local_browser: true do + it "supports stopping the session", :launch, skip: Ferrum::Utils::Platform.windows? do browser = Ferrum::Browser.new pid = browser.process.pid @@ -538,7 +748,7 @@ def proxy_tunnel(socket, request, browser_url) expect { Process.kill(0, pid) }.to raise_error(Errno::ESRCH) end - it "returns immediately with wait: false, finishing cleanup once the returned thread is joined", skip: Ferrum::Utils::Platform.windows?, local_browser: true do + it "returns immediately with wait: false, finishing cleanup once the returned thread is joined", :launch, skip: Ferrum::Utils::Platform.windows? do browser = Ferrum::Browser.new pid = browser.process.pid @@ -556,7 +766,7 @@ def proxy_tunnel(socket, request, browser_url) end describe "#restart" do - it "blocks until the old process is confirmed dead before returning", skip: Ferrum::Utils::Platform.windows?, local_browser: true do + it "blocks until the old process is confirmed dead before returning", :launch, skip: Ferrum::Utils::Platform.windows? do browser = Ferrum::Browser.new old_pid = browser.process.pid @@ -629,7 +839,7 @@ def proxy_tunnel(socket, request, browser_url) end describe "#evaluate_on_new_document" do - it "supports evaluation of JavaScript before page loads", local_browser: true do + it "supports evaluation of JavaScript before page loads", :launch do browser = Ferrum::Browser.new(base_url: base_url) browser.evaluate_on_new_document <<~JS @@ -838,7 +1048,7 @@ def proxy_tunnel(socket, request, browser_url) end describe "#debug_url" do - it "parses the devtools frontend url correctly when devtoolsFrontendUrl is relative", local_browser: true do + it "parses the devtools frontend url correctly when devtoolsFrontendUrl is relative", :launch do browser = Ferrum::Browser.new(port: 12_345) uri = instance_double(URI) @@ -848,7 +1058,7 @@ def proxy_tunnel(socket, request, browser_url) expect(browser.send(:debug_url)).to eq("http://127.0.0.1:12345/works") end - it "parses the devtools frontend url correctly when devtoolsFrontendUrl is fully qualified", local_browser: true do + it "parses the devtools frontend url correctly when devtoolsFrontendUrl is fully qualified", :launch do browser = Ferrum::Browser.new(port: 12_346) uri = instance_double(URI) @@ -861,7 +1071,7 @@ def proxy_tunnel(socket, request, browser_url) end end - context "with pty", local_browser: true, if: Ferrum::Utils::Platform.mri? && !Ferrum::Utils::Platform.windows? do + context "with pty", :launch, if: Ferrum::Utils::Platform.mri? && !Ferrum::Utils::Platform.windows? do require "pty" require "timeout" diff --git a/spec/client_spec.rb b/spec/client_spec.rb index b9735129..7c414f1b 100644 --- a/spec/client_spec.rb +++ b/spec/client_spec.rb @@ -17,7 +17,7 @@ def messages remote.client.instance_variable_get(:@ws).messages end - it "releases the commands in flight", local_browser: true do + it "releases the commands in flight", :launch do page = remote.create_page Thread.new do sleep(0.2) @@ -29,7 +29,7 @@ def messages expect(Ferrum::Utils::ElapsedTime.elapsed_time(start)).to be < 5 end - it "fails the commands that follow without waiting", local_browser: true do + it "fails the commands that follow without waiting", :launch do page = remote.create_page messages.close start = Ferrum::Utils::ElapsedTime.monotonic_time @@ -38,7 +38,7 @@ def messages expect(Ferrum::Utils::ElapsedTime.elapsed_time(start)).to be < 1 end - it "closes the socket when the browser dies before answering the close frame", local_browser: true do + it "closes the socket when the browser dies before answering the close frame", :launch do remote.create_page socket = remote.client.instance_variable_get(:@ws).instance_variable_get(:@sock) Process.kill("KILL", -remote.process.pid) @@ -48,7 +48,7 @@ def messages expect(socket).to be_closed end - it "reports an unexpected reader error instead of raising in the main thread", local_browser: true do + it "reports an unexpected reader error instead of raising in the main thread", :launch do page = remote.create_page driver = remote.client.instance_variable_get(:@ws).instance_variable_get(:@driver) allow(driver).to receive(:parse).and_raise(Errno::ETIMEDOUT) @@ -76,7 +76,7 @@ def evaluate_in_background(page, expression) end end - it "gives up on a command the browser doesn't take", local_browser: true do + it "gives up on a command the browser doesn't take", :launch do page = remote.create_page Process.kill("STOP", remote.process.pid) @@ -87,7 +87,7 @@ def evaluate_in_background(page, expression) expect(sender.value.message).to match(/accepted no data for 1s/) end - it "fails the commands waiting to be sent behind it", local_browser: true do + it "fails the commands waiting to be sent behind it", :launch do page = remote.create_page Process.kill("STOP", remote.process.pid) @@ -105,7 +105,7 @@ def evaluate_in_background(page, expression) after { remote.quit } - it "keeps dispatching events when a callback raises", local_browser: true do + it "keeps dispatching events when a callback raises", :launch do page = remote.create_page expect do diff --git a/spec/console_spec.rb b/spec/console_spec.rb new file mode 100644 index 00000000..a8c12ee6 --- /dev/null +++ b/spec/console_spec.rb @@ -0,0 +1,126 @@ +# frozen_string_literal: true + +describe Ferrum::Console do + let(:console) { page.console } + + it "collects console API calls" do + page.go_to("/console_log") + + wait_for { console.size }.to eq(1) + message = console.first + expect(message.type).to eq(:log) + expect(message.source).to eq(:console_api) + expect(message.text).to eq("Hello world") + expect(message.severity).to eq(:info) + expect(message.timestamp).to be_within(60).of(Time.now) + expect(message.location.url).to end_with("/console_log") + expect(message.location.function_name).to eq("window.onload") + expect(message.to_s).to start_with("[log] Hello world\n at window.onload (") + end + + it "converts arguments to Ruby values" do + page.go_to + page.execute(<<~JS) + console.log("text", 1, 1.5, true, null, undefined, NaN, 10n, + { a: 1, b: "x", c: [1, 2] }, [1, "a", null], () => 1) + JS + + wait_for { console.size }.to eq(1) + expect(console.first.args).to match( + ["text", 1, 1.5, true, nil, nil, be_nan, 10, { "a" => 1, "b" => "x", "c" => "Array(2)" }, [1, "a", nil], "() => 1"] + ) + expect(console.first.text).to eq( + %(text 1 1.5 true null undefined NaN 10n {"a":1,"b":"x","c":"Array(2)"} [1,"a",null] () => 1) + ) + end + + it "tells errors and warnings apart" do + page.go_to + page.execute(<<~JS) + console.error("bad") + console.warn("careful") + console.info("fine") + JS + + wait_for { console.size }.to eq(3) + expect(console.select(&:error?).map(&:text)).to eq(["bad"]) + expect(console.select(&:warning?).map(&:text)).to eq(["careful"]) + expect(console.map(&:type)).to eq(%i[error warning info]) + end + + it "collects uncaught exceptions" do + page.go_to + page.execute(%(setTimeout(() => { throw new Error("boom") }))) + + wait_for { console.size }.to eq(1) + message = console.first + expect(message.source).to eq(:exception) + expect(message).to be_error + expect(message.text).to start_with("Uncaught Error: boom") + end + + it "collects browser log entries" do + page.go_to + page.execute(%(document.body.appendChild(document.createElement("img")).src = "/unexist.png")) + + wait_for { console.size }.to eq(1) + message = console.first + expect(message.source).to eq(:network) + expect(message).to be_error + expect(message).to be_match("404") + expect(message.location.url).to end_with("/unexist.png") + end + + it "keeps only the most recent messages" do + page.go_to + page.execute("for (let i = 0; i < #{described_class::LIMIT + 5}; i++) console.log(i)") + + wait_for { console.last&.text }.to eq((described_class::LIMIT + 4).to_s) + expect(console.size).to eq(described_class::LIMIT) + expect(console.first.text).to eq("5") + end + + it "forgets messages on clear" do + page.go_to("/console_log") + wait_for { console.size }.to eq(1) + + console.clear + expect(console).to be_empty + + page.execute(%(console.log("again"))) + wait_for { console.map(&:text) }.to eq(["again"]) + end + + it "is reachable through the browser" do + browser.go_to("/console_log") + + wait_for { browser.console.map(&:text) }.to eq(["Hello world"]) + end + + describe "page.on(:console)" do + it "yields new messages" do + messages = [] + page.on(:console) { |message| messages << message.text } + + page.go_to("/console_log") + page.execute(%(console.warn("later"))) + + wait_for { messages }.to eq(["Hello world", "later"]) + end + + it "stops yielding after page.off(:console)" do + messages = [] + id = page.on(:console) { |message| messages << message.text } + + page.go_to + page.execute(%(console.log("first"))) + wait_for { messages }.to eq(["first"]) + + page.off(:console, id) + page.execute(%(console.log("second"))) + wait_for { console.size }.to eq(2) + + expect(messages).to eq(["first"]) + end + end +end diff --git a/spec/contexts_spec.rb b/spec/contexts_spec.rb index 728128fe..301912fb 100644 --- a/spec/contexts_spec.rb +++ b/spec/contexts_spec.rb @@ -25,7 +25,7 @@ end describe "#default_context" do - it "works in the browser's startup window when it came up with one", local_browser: true do + it "works in the browser's startup window when it came up with one", :launch do with_external_browser(incognito: false) do |url| remote = Ferrum::Browser.new(url: url) @@ -36,7 +36,7 @@ end end - it "creates a context of its own when the browser has no startup window", local_browser: true do + it "creates a context of its own when the browser has no startup window", :launch do with_external_browser do |url| remote = Ferrum::Browser.new(url: url) remote.create_page @@ -51,7 +51,7 @@ end end - it "ignores contexts another client created in the same browser", local_browser: true do + it "ignores contexts another client created in the same browser", :launch do with_external_browser do |url| first = Ferrum::Browser.new(url: url) context = first.contexts.create diff --git a/spec/cookies_spec.rb b/spec/cookies_spec.rb index 6e1b4f86..3319f05f 100644 --- a/spec/cookies_spec.rb +++ b/spec/cookies_spec.rb @@ -217,7 +217,7 @@ expect(browser.body).to include("127.0.0.1") end - it "sets cookies correctly with :domain option when base_url isn't set", local_browser: true do + it "sets cookies correctly with :domain option when base_url isn't set", :launch do browser = Ferrum::Browser.new browser.cookies.set(name: "stealth", value: "123456", domain: "localhost") diff --git a/spec/downloads_spec.rb b/spec/downloads_spec.rb index 7564e37a..46946d71 100644 --- a/spec/downloads_spec.rb +++ b/spec/downloads_spec.rb @@ -71,7 +71,7 @@ end context "with the browser's implicit context" do - it "saves an attachment", local_browser: true do + it "saves an attachment", :launch do with_external_browser(incognito: false) do |url| remote = Ferrum::Browser.new(url: url, base_url: base_url, save_path: save_path) remote_page = remote.create_page diff --git a/spec/frame/runtime_spec.rb b/spec/frame/runtime_spec.rb index 32e238b6..2cdde169 100644 --- a/spec/frame/runtime_spec.rb +++ b/spec/frame/runtime_spec.rb @@ -16,7 +16,7 @@ after { browser.quit } - it "propagates a Javascript error to a ruby exception", local_browser: true do + it "propagates a Javascript error to a ruby exception", :launch do expect do browser.execute(%(throw new Error("zomg"))) end.to raise_error(Ferrum::JavaScriptError) { |e| @@ -24,7 +24,7 @@ } end - it "propagates an asynchronous Javascript error on the page to a ruby exception", local_browser: true do + it "propagates an asynchronous Javascript error on the page to a ruby exception", :launch do expect do browser.execute "setTimeout(function() { omg }, 0)" sleep 0.01 @@ -32,13 +32,13 @@ end.to raise_error(Ferrum::JavaScriptError, /ReferenceError.*omg/) end - it "propagates a synchronous Javascript error on the page to a ruby exception", local_browser: true do + it "propagates a synchronous Javascript error on the page to a ruby exception", :launch do expect do browser.execute "omg" end.to raise_error(Ferrum::JavaScriptError, /ReferenceError.*omg/) end - it "does not re-raise a Javascript error if it is rescued", local_browser: true do + it "does not re-raise a Javascript error if it is rescued", :launch do expect do browser.execute "setTimeout(function() { omg }, 0)" sleep 0.01 @@ -49,11 +49,11 @@ expect(browser.evaluate("1+1")).to eq(2) end - it "propagates a Javascript error during page load to a ruby exception", local_browser: true do + it "propagates a Javascript error during page load to a ruby exception", :launch do expect { browser.go_to("/js_error") }.to raise_error(Ferrum::JavaScriptError) end - it "does not propagate a Javascript error to ruby if error raising disabled", local_browser: true do + it "does not propagate a Javascript error to ruby if error raising disabled", :launch do browser = Ferrum::Browser.new(base_url: base_url, js_errors: false) browser.go_to("/js_error") browser.execute "setTimeout(function() { omg }, 0)" @@ -63,7 +63,7 @@ browser&.quit end - it "does not propagate a Javascript error to ruby if error raising disabled and client restarted", local_browser: true do + it "does not propagate a Javascript error to ruby if error raising disabled and client restarted", :launch do browser = Ferrum::Browser.new(base_url: base_url, js_errors: false) browser.restart browser.go_to("/js_error") diff --git a/spec/page/screenshot_spec.rb b/spec/page/screenshot_spec.rb index 6d48ead9..567ca41d 100644 --- a/spec/page/screenshot_spec.rb +++ b/spec/page/screenshot_spec.rb @@ -489,7 +489,7 @@ def create_screenshot(path:, **options) expect(browser.viewport_size).to eq([1024, 681]) end - it "supports specifying viewport size with an option", local_browser: true do + it "supports specifying viewport size with an option", :launch do browser = Ferrum::Browser.new(window_size: [800, 600]) browser.go_to(base_url) expect(browser.viewport_size).to eq([800, 513]) diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index a724876d..2e68fc15 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -33,7 +33,8 @@ puts "" RSpec.configure do |config| - config.filter_run_excluding local_browser: true if remote_url + # Specs tagged :launch start their own Chrome, so they can't run against a remote browser (FERRUM_URL). + config.filter_run_excluding :launch if remote_url config.wait_timeout = 1 config.wait_delay = 0.2 diff --git a/spec/support/global_helpers.rb b/spec/support/global_helpers.rb index 68ba691c..6cebfc60 100644 --- a/spec/support/global_helpers.rb +++ b/spec/support/global_helpers.rb @@ -65,7 +65,11 @@ def web_socket_debugger_url(url) # nop end - def wait_a_bit(duration = 0.2) - Thread.pass && sleep(duration) + def with_env(env) + original = env.keys.to_h { |name| [name, ENV.fetch(name, nil)] } + ENV.update(env) + yield + ensure + ENV.update(original) if original end end diff --git a/spec/support/no_chrome b/spec/support/no_chrome index 04ad5179..9ea0a91e 100755 --- a/spec/support/no_chrome +++ b/spec/support/no_chrome @@ -1,3 +1,3 @@ #!/bin/bash -exec ls +exec sleep 30 diff --git a/spec/unit/client/web_socket_spec.rb b/spec/unit/client/web_socket_spec.rb index db744ecb..b5d9c010 100644 --- a/spec/unit/client/web_socket_spec.rb +++ b/spec/unit/client/web_socket_spec.rb @@ -34,7 +34,6 @@ def peak_concurrent_writes = @peak.value before do web_socket.instance_variable_set(:@driver, frame_probe) web_socket.instance_variable_set(:@driver_mutex, Mutex.new) - web_socket.instance_variable_set(:@screenshot_commands, Concurrent::Hash.new) end describe "#send_message" do diff --git a/spec/unit/process_spec.rb b/spec/unit/process_spec.rb index abe7560a..30cff906 100644 --- a/spec/unit/process_spec.rb +++ b/spec/unit/process_spec.rb @@ -90,12 +90,12 @@ context "when spawning Chrome itself" do it "uses the requested :host instead of the address Chrome reports" do subject = described_class.new(Ferrum::Browser::Options.new(host: "ferrum.localhost", port: 6001)) - read_io, write_io = IO.pipe - write_io.write("DevTools listening on ws://127.0.0.1:6001/devtools/browser/" \ - "11111111-1111-1111-1111-111111111111\n") - write_io.close + subject.output.pipe do |io| + io.write("DevTools listening on ws://127.0.0.1:6001/devtools/browser/" \ + "11111111-1111-1111-1111-111111111111\n") + end - subject.send(:parse_ws_url, read_io, 1) + subject.send(:parse_ws_url) expect(subject.host).to eq("ferrum.localhost") expect(subject.port).to eq(6001) diff --git a/spec/worker_spec.rb b/spec/worker_spec.rb index 8cb85dbe..9c96fa91 100644 --- a/spec/worker_spec.rb +++ b/spec/worker_spec.rb @@ -33,6 +33,23 @@ def wait_for_target(&block) expect(browser.workers).to contain_exactly(target.worker) expect(target.worker.evaluate("1 + 1")).to eq(2) end + + it "collects its console messages" do + page.go_to + + page.execute <<~JS + new Worker(URL.createObjectURL(new Blob( + ["self.onmessage = () => {}"], + { type: "application/javascript" } + ))) + JS + + worker = wait_for_target(&:worker?).worker + worker.execute(%(console.warn("from worker"))) + + wait_for { worker.console.map(&:text) }.to eq(["from worker"]) + expect(worker.console.first).to be_warning + end end describe "shared workers" do