[Selenium 4] [Grid] Node Registration Lack of Error for No Driver Path Set

[dylanlive]

🐛 Bug Report

Follow up to #8752. When launching Selenium Grid Node, and failing to include the path to a Browser Driver like Chromedriver, the registration will hang indefinitely and not present any error on INFO (or greater) level.

This sent me down a rabbit hole of debugging open ports, etc.

Tested with this version of Grid:
https://github.com/SeleniumHQ/docker-selenium/raw/beta-jars/selenium-server-4.0.0-prerelease-beta-1-02d5e641d5.jar

To Reproduce

1. Unset any browser drivers on path, such as webdriver.chrome.driver
2. Launch with just java -jar selenium-server-4.0.0-prerelease-beta-1-02d5e641d5.jar node --publish-events tcp://IP:4442 --subscribe-events tcp://IP:4443

Compare these two (IPs in example have been modified) Output is a powershell prompt.

Broken (which just hangs on this output):

PS C:\Windows\system32> $hubHost = "1.2.3.4"
PS C:\Windows\system32> java -jar selenium-server-4.0.0-prerelease-beta-1-02d5e641d5.jar node --publish-events tcp://$($hubHost):4442 --subscribe-events tcp://$($hubHost):4443
21:11:38.528 INFO [LogManager$RootLogger.log] - Using the system default encoding
21:11:38.531 INFO [LoggingOptions.createTracer] - Using OpenTelemetry for tracing
21:11:38.671 INFO [UnboundZmqEventBus.<init>] - Connecting to tcp://1.2.3.4:4442 and tcp://1.2.3.4:4443
21:11:38.723 INFO [UnboundZmqEventBus.<init>] - Sockets created
21:11:38.726 INFO [UnboundZmqEventBus.lambda$new$7] - Bus started
21:11:39.029 INFO [NodeServer.createHandlers] - Reporting self as: http://5.6.7.8:5555
21:11:39.110 INFO [Node.<init>] - Binding additional locator mechanisms: name, id
21:11:39.336 INFO [NodeServer$1.start] - Starting registration process for node id 924d7db1-844f-44ec-838c-e5a12592a8fb
21:11:39.337 INFO [NodeServer.execute] - Started Selenium node 4.0.0-beta-1 (revision 02d5e641d5): http://5.6.7.8:5555

Working:

PS C:\Windows\system32> $hubHost = "1.2.3.4"
PS C:\Windows\system32> java -Dwebdriver.chrome.driver=C:\ProgramData\chromedriver_win32\chromedriver.exe -jar selenium-server-4.0.0-prerelease-beta-1-02d5e641d5.jar node --publish-events tcp://$($hubHost):4442 --subscribe-events tcp://$($hubHost):4443
21:15:34.048 INFO [LogManager$RootLogger.log] - Using the system default encoding
21:15:34.050 INFO [LoggingOptions.createTracer] - Using OpenTelemetry for tracing
21:15:34.178 INFO [UnboundZmqEventBus.<init>] - Connecting to tcp://1.2.3.4:4442 and tcp://1.2.3.4:4443
21:15:34.231 INFO [UnboundZmqEventBus.<init>] - Sockets created
21:15:34.233 INFO [UnboundZmqEventBus.lambda$new$7] - Bus started
21:15:34.532 INFO [NodeServer.createHandlers] - Reporting self as: http://5.6.7.8:5555
21:15:34.617 INFO [NodeOptions.report] - Adding Chrome for {"browserName": "chrome"} 4 times
21:15:34.625 INFO [Node.<init>] - Binding additional locator mechanisms: id, name
21:15:34.842 INFO [NodeServer$1.start] - Starting registration process for node id 355ecc3e-ed7b-4f75-b9ec-c6d521ef03b4
21:15:34.843 INFO [NodeServer.execute] - Started Selenium node 4.0.0-beta-1 (revision 02d5e641d5): http://5.6.7.8:5555
21:15:35.953 INFO [NodeServer.lambda$createHandlers$1] - Node has been added

Expected behavior

An error message printed that could give a hint as to why the node never gets added. Perhaps something like:
"No browser driver on path"

Test script or set of commands reproducing this issue

See above (reproduction)

Environment

OS: Windows 10
Browser: Chrome
Browser version: 86.0.4240.75
Browser Driver version: 86.0.4240.22
Language Bindings version: n/a
Selenium Grid version (if applicable): selenium-server-4.0.0-prerelease-beta-1-02d5e641d5.jar

[pujagani]

Thank you for sharing the detailed bug report. I am working on fixing this. @dylanlive Will the logs as depicted in the screenshot below be clear to understand? Appreciate the feedback. In this case, since I am on Macbook, it is detecting the Safari driver ("Discovered 1 driver(s)") but the Node is requesting to add specific driver chrome, which is not present on the system path currently.

[dylanlive]

Hey @pujagani! That might help, but I think it might be looked over. I think the most confusing piece on my side is it says "Starting registration process" and then I never hear anything after that.

I believe in Grid 3, you'd see a loop of messages if there were connectivity problems.

If it's something wrong with the configuration being used, I think I'd expect it to Exit 1 if it's never going to register itself.

Open for feedback from others as well.

[pujagani]

Thank you for providing the feedback! I see your point and it is a valid concern as well. However, Grid 4 relies on the event-bus to communicate among the components. "Starting registration process" means that is has sent an event to the event-bus and it will retry in case the node is not up. When the Hub comes up it listens to the same event-bus and actually registers the node. The logs seen at that time on the Hub are

12:00:39.887 INFO [LocalDistributor.add] - Added node 9a97e169-6528-4be3-8a2b-99fbc78717c1 at http://192.168.29.129:5555.
12:00:40.138 INFO [GridModel.setAvailability] - Switching node 9a97e169-6528-4be3-8a2b-99fbc78717c1 (uri: http://192.168.29.129:5555) from DOWN to UP

The same Node receives node added event and prints the log:

11:58:39.239 INFO [NodeServer.lambda$createHandlers$1] - Node has been added

I will add this to the documentation to avoid any confusion.

In the case of "connectivity" issues here, it would be related to the Event-bus and those errors will be throw/logged.

https://github.com/SeleniumHQ/selenium/blob/trunk/java/server/src/org/openqa/selenium/grid/node/config/NodeOptions.java Diego and Simon have done a good job in identifying and throwing config errors :)

If the config passes any wrong parameters or values, it errors out and the node does not start. Will push the changes for missing drivers bit when adding specific drivers. With the current implementation and the changes, I am thinking it will cover most scenarios. Let me know if I am missing something!

[diemol]

Closed via #9129