Skip to content

[rb] render WebSocket debug log lines lazily - #18033

Merged
titusfortner merged 2 commits into
SeleniumHQ:trunkfrom
ikraamg:rb-websocket-lazy-debug-frames
Sep 15, 2026
Merged

titusfortner merged 2 commits into
SeleniumHQ:trunkfrom
ikraamg:rb-websocket-lazy-debug-frames

Conversation

@ikraamg

@ikraamg ikraamg commented Sep 14, 2026

Copy link
Copy Markdown
Contributor

🔗 Related Issues

None filed; the reproduction below shows the cost directly.

💥 What does this PR do?

WebSocketConnection#send_cmd and #process_frame build the "WebSocket -> …" / "WebSocket <- …" strings before calling WebDriver.logger.debug, so every frame pays a deep Hash#inspect even though the logger discards the line at its default level. A BiDi session gets one frame per network event, so a page with many assets renders each of them for nothing.

This passes the frame to the logger as a block instead. Logger#debug already documents the block as "appended to the end of the provided template" and discard_or_log only yields once the level check has passed, so output at debug level is unchanged.

Standalone reproduction against selenium-webdriver 4.48.0 on Ruby 4.0.6, feeding a 4.3 KB network.responseCompleted frame through process_frame 5,000 times at the default logger level:

unpatched: 5000 frames, 75 µs/frame, Hash#to_s calls: 5000 (nothing logged)
patched:   5000 frames, 10 µs/frame, Hash#to_s calls: 0
at debug level the patched line still logs: DEBUG Selenium [:ws] WebSocket <-  {"id" => 7, "result" => {"ok" => true}}

On a production Firefox BiDi worker (rbspy, 90 s, 100 Hz), the Hash#inspect under process_frame was about 3% of on-CPU time on the listener thread; after this change it no longer appears.

Reproduction script
require 'selenium-webdriver'
require 'json'
require 'benchmark'

frame = JSON.generate('type' => 'event', 'method' => 'network.responseCompleted',
                      'params' => { 'request' => { 'headers' => 12.times.map { |i| { 'name' => "x-#{i}", 'value' => { 'type' => 'string', 'value' => 'v' * 40 } } } },
                                    'response' => { 'headers' => 20.times.map { |i| { 'name' => "h#{i}", 'value' => { 'type' => 'string', 'value' => 'w' * 60 } } } } })
conn = Selenium::WebDriver::WebSocketConnection.allocate
conn.instance_variable_set(:@messages_mtx, Mutex.new)
renders = 0
Hash.prepend(Module.new { define_method(:to_s) { renders += 1; super() } })
n = 5_000
t = Benchmark.realtime { n.times { conn.send(:process_frame, frame) } }
puts "#{(t * 1e6 / n).round} µs/frame, Hash#to_s calls: #{renders}, logger level #{Selenium::WebDriver.logger.level}"

🔧 Implementation Notes

The alternative was return msg unless WebDriver.logger.debug?-style guards at each call site, but the logger's block form exists for exactly this and keeps the id: :ws filtering in one place. The three new unit examples use described_class.allocate like the rest of the spec; two of them fail on trunk.

🤖 AI assistance

  • No substantial AI assistance used
  • AI assisted (complete below)
    • Tool(s): Claude Code
    • What was generated: the two-line change, the unit spec examples, and the reproduction script
    • I reviewed all AI output and can explain the change

💡 Additional Considerations

None. No public API or .rbs change.

🔄 Types of changes

  • Bug fix (backwards compatible)

WebSocketConnection#send_cmd and #process_frame build the
"WebSocket -> ..." and "WebSocket <- ..." strings before handing
them to WebDriver.logger.debug, so every frame pays a deep
Hash#inspect even though the logger discards the line at its
default level. A BiDi session receives one frame per network
event, so a page with many assets renders each of them for
nothing; profiling a Firefox BiDi worker showed the inspect at
about 3% of on-CPU time.

Pass the frame to the logger as a block instead. Logger#debug
already documents the block as appended to the message and only
yields once the level check has passed, so the output at debug
level is unchanged.
@qodo-code-review

Copy link
Copy Markdown
Contributor

Qodo reviews are paused for this user.

Troubleshooting steps vary by plan Learn more →

On a Teams plan?
Reviews resume once this user has a paid seat and their Git account is linked in Qodo.
Link Git account →

Using GitHub Enterprise Server, GitLab Self-Managed, or Bitbucket Data Center?
These require an Enterprise plan - Contact us
Contact us →

@selenium-ci selenium-ci added the C-rb Ruby Bindings label Sep 14, 2026
@titusfortner

Copy link
Copy Markdown
Member

/agentic_review

@qodo-code-review

qodo-code-review Bot commented Sep 15, 2026 •

Copy link
Copy Markdown
Contributor

Code Review by Qodo

🐞 Bugs (1) 📘 Rule violations (0) 📜 Skill insights (0)

Grey Divider


Remediation recommended

1. WebSocket debug lines gain an extra gap 🐞 Bug ◔ Observability
Description
The new calls pass WebSocket -> and WebSocket <- as the logger message while supplying the
payload through a block. discard_or_log appends one space after the message and another before the
yielded value, so enabled WebSocket debug output contains two spaces before every frame payload
instead of the single space emitted previously.
Code

rb/lib/selenium/webdriver/common/websocket_connection.rb[108]

+        WebDriver.logger.debug('WebSocket ->', id: :ws) { data.to_s[...MAX_LOG_MESSAGE_SIZE] }
Evidence
The old calls interpolate a message containing one space after the arrow before truncation. The new
calls provide a message ending at the arrow, while the logger implementation appends a space at line
236 and another before the yielded block value at line 237, producing two spaces. The logger's own
documentation describes the block as appended to the template, and the PR's stated goal says debug
output is unchanged, which this formatting change contradicts.

rb/lib/selenium/webdriver/common/websocket_connection.rb[108-108]
rb/lib/selenium/webdriver/common/websocket_connection.rb[203-203]
rb/lib/selenium/webdriver/common/logger.rb[236-237]

Agent prompt
The issue below was found during a code review. Follow the provided context and guidance below and implement a solution

## Issue description
The lazy WebSocket debug calls pass the frame payload through a logger block. The logger implementation appends a trailing space to the template and then prepends another space before the block result, producing two spaces between `WebSocket ->`/`WebSocket <-` and the payload. This changes the established debug output format and can disrupt exact-string log consumers.

## Fix Focus Areas
- rb/lib/selenium/webdriver/common/websocket_connection.rb[108-108]
- rb/lib/selenium/webdriver/common/websocket_connection.rb[203-203]
- rb/lib/selenium/webdriver/common/logger.rb[236-237]

## Recommended Fix
Adjust the lazy logging composition so the rendered output retains exactly one separator between the WebSocket direction marker and the payload, while preserving lazy evaluation and the existing log filtering behavior. Add or update unit coverage to assert the complete emitted message at debug level.

ⓘ Copy this prompt and use it to remediate the issue with your preferred AI generation tools


Grey Divider

Context sources
Review mode: 🚀 Fast: This is a small, localized runtime optimization with straightforward logger-block semantics and focused unit coverage, outside high-risk areas.

Grey Divider

Tip of the day
💡 Did you know, you can reply 'qodo' on any finding to push back, ask questions, or dig deeper

More tips ↗ | Customize Qodo ↗ | Qodo docs ↗

Grey Divider

Qodo Logo

Comment thread rb/lib/selenium/webdriver/common/websocket_connection.rb
@qodo-code-review

qodo-code-review Bot commented Sep 15, 2026 •

Copy link
Copy Markdown
Contributor

No code changes since the last review — review skipped

Qodo Logo

@titusfortner
titusfortner merged commit 6c63e70 into SeleniumHQ:trunk Sep 15, 2026
1 check passed
@titusfortner

Copy link
Copy Markdown
Member

@ikraamg thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

C-rb Ruby Bindings

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants