[🐛 Bug]: Distributor Failing to Register Nodes due to Exception in EventListener

[johnbartels]

What happened?

Deployment Details:
Type: Fully Distributed
Node - 4.19.0
Distributor - 4.21.0
Router - 4.21.0
Smap - 4.21.0
Squeue - 4.21.0

Selelenium 4 Grid was running ~smoothly (for several days) and I then started receiving reports of SessionNotCreatedExceptions. I then looked in NewRelic and saw that the Queue was rather large and there were no running tests. Node Logs indicated that the registration event was being sent over and over.

16:22:46.554 INFO [NodeServer.execute] - Started Selenium node 4.19.0 (revision 5f9cec8): http://10.28.177.94:5555
16:22:46.584 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:22:56.593 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:23:06.600 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:23:16.604 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:23:26.608 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:23:36.614 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:23:46.619 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:23:56.623 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:24:06.630 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:24:16.634 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:24:26.638 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:24:36.642 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
16:24:46.556 INFO [NodeServer$1.lambda$start$1] - Sending registration event...

Distributor Logs indicated that the Nodes did not have the sessiontimeout set

How can we reproduce the issue?

I am not entirely sure how to reproduce as the distributor is complaining that a configuration setting is not set (but is clearly located both in the config.toml file and as an argument in the java process running on the node container).

Relevant log output

Log from Distributor (4.21):

17:37:45.983 WARN [UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2] - Caught exception from listener: org.openqa.selenium.events.EventListener@65ab8c00
java.lang.IllegalArgumentException: Session timeout must be set
	at org.openqa.selenium.internal.Require.positive(Require.java:99)
	at org.openqa.selenium.grid.node.Node.<init>(Node.java:129)
	at org.openqa.selenium.grid.node.remote.RemoteNode.<init>(RemoteNode.java:91)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.register(LocalDistributor.java:317)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.lambda$new$4(LocalDistributor.java:211)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:42)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:24)
	at org.openqa.selenium.events.zeromq.UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2(UnboundZmqEventBus.java:319)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)

Log from Node:

docker exec node ps aux | grep java
seluser    172  0.5  3.9 3597236 155940 ?      Sl   16:22   0:23 java -Dwebdriver.chrome.driver=/usr/bin/chromedriver -Dwebdriver.edge.driver=/usr/bin/msedgedriver -Dwebdriver.gecko.driver=/usr/bin/geckodriver -jar /opt/selenium/selenium-server.jar node --bind-host false --config /opt/selenium/config.toml --log-level CONFIG --session-timeout 600 --heartbeat-period 30
[root@selenium4-node-linux-10-28-177-94 inin]# docker exec node cat /opt/selenium/config.toml
[events]
publish = "tcp://selenium4-distributor-internal-ip.devdomain.com:4442"  
subscribe = "tcp://selenium4-distributor-internal-ip.devdomain.com:4443"

[server]
host = "10.28.177.94"
[node]
session-timeout = 600
override-max-sessions = false
detect-drivers = false
drain-after-session-count = 1
enable-managed-downloads = true
max-sessions = 1

[[node.driver-configuration]]
display-name = "chrome"
stereotype = '{"browserName": "chrome", "browserVersion": "124.0", "platformName": "Linux", "goog:chromeOptions": {"binary": "/usr/bin/google-chrome"}}'
max-sessions = 1
    
[[node.driver-configuration]]
display-name = "firefox"
stereotype = '{"browserName": "firefox", "browserVersion": "126.0", "platformName": "Linux"}'
max-sessions = 1
    
[[node.driver-configuration]]
display-name = "edge"
stereotype = '{"browserName": "MicrosoftEdge", "browserVersion": "125.0", "platformName": "Linux"}'
max-sessions = 1

Operating System

Amazon Linux 2

Selenium version

Java 4.21.0

What are the browser(s) and version(s) where you see this issue?

n/a

What are the browser driver(s) and version(s) where you see this issue?

n/a

Are you using Selenium Grid?

Yes - 4.0

[github-actions]

@johnbartels, thank you for creating this issue. We will troubleshoot it as soon as we can.

---

Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

[joerg1985]

@johnbartels you should use the same selenium version for all components. Usually it does work mixing versions but in this case the 4.21.0 grid components expect a field not provided by the 4.19.0 node.

[johnbartels]

@joerg1985 Thank you for the quick response and assistance in understanding why this issue occurred. I would ask that similar breaking changes be called out in future release notes. I would also state that there is typically an expectation that a new version is at least compatible with the previous version, and previous versions of Selenium supported multiple versions of chrome etc. I would also state that it was possible to add the new config files without removing the old ones which would have prevented this breaking change.

I believe this was the related change:
SeleniumHQ/docker-selenium#2343

[johnbartels]

@joerg1985 I updated my nodes to 4.21.0-20240517 and I am still seeing the "Session timeout must be set" traces from the distributor

[joerg1985]

@johnbartels there is a open ticket regarding the versioning, addressing this #13349

I don't think this is related to the config, it should fallback to a valid value.
This field is send by the node to the distributor while registering with the current value.

Perhaps there is somewhere a old node running and connecting to the distributor?
Does one of the nodes still print Sending registration event again and again?
Could you stop this node and check the exceptions are gone.
If none of your nodes does print the Sending registration event stop all nodes and to see if the exceptions stop.

[johnbartels]

There are no old nodes connected to the distributor (I can check grid status, but my nodes are in an ASG and when the old ASG is terminated, all old nodes are terminated). The nodes that were built with version 4.21.0-20240517 no longer have the repeated "Sending registration event..." traces, but I am still seeing the "java.lang.IllegalArgumentException: Session timeout must be set" from the distributor. I also use a centralized logging solution (Sumo) and typically have ~150 nodes running tens of thousands of tests daily. Node containers are terminated after a single session, and thus the new node will register and we see this trace on the distributor. If I were to deploy this change to our production grid, we'd be seeing tens of thousands of these stack traces every day. I will scale down to one node and run some tests to see if any behavior changes occur.

[johnbartels]

I scaled my nodes down to '1', and saw the following:

Node Logs:

Starting Selenium Grid Node...
2024-10-08 18:52:15,883 INFO success: xvfb entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-10-08 18:52:15,891 INFO success: vnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-10-08 18:52:15,891 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
18:52:16.507 INFO [LoggingOptions.configureLogEncoding] - Using the system default encoding
18:52:16.516 INFO [OpenTelemetryTracer.createTracer] - Using OpenTelemetry for tracing
18:52:16.774 INFO [UnboundZmqEventBus.<init>] - Connecting to tcp://selenium4-distributor-internal-ip. devdomain.com:4442 and tcp://selenium4-distributor-internal-ip. devdomain.com:4443
18:52:16.965 INFO [UnboundZmqEventBus.<init>] - Sockets created
18:52:17.974 INFO [UnboundZmqEventBus.<init>] - Event bus ready
18:52:18.148 INFO [NodeServer.createHandlers] - Reporting self as: http://10.28.178.184:5555
18:52:18.188 INFO [NodeOptions.getSessionFactories] - Detected 2 available processors
18:52:18.267 INFO [NodeOptions.report] - Adding chrome for {"browserName": "chrome","browserVersion": "125.0","goog:chromeOptions": {"binary": "\u002fusr\u002fbin\u002fgoogle-chrome"},"platformName": "linux","se:downloadsEnabled": true,"se:noVncPort": 7900,"se:vncEnabled": true} 1 times
18:52:18.271 INFO [NodeOptions.report] - Adding firefox for {"browserName": "firefox","browserVersion": "130.0","platformName": "linux","se:downloadsEnabled": true,"se:noVncPort": 7900,"se:vncEnabled": true} 1 times
18:52:18.273 INFO [NodeOptions.report] - Adding edge for {"browserName": "MicrosoftEdge","browserVersion": "128.0","platformName": "linux","se:downloadsEnabled": true,"se:noVncPort": 7900,"se:vncEnabled": true} 1 times
18:52:18.316 INFO [Node.<init>] - Binding additional locator mechanisms: relative
18:52:18.567 INFO [NodeServer$1.start] - Starting registration process for Node http://10.28.178.184:5555
18:52:18.571 INFO [NodeServer.execute] - Started Selenium node 4.21.0 (revision 79ed462ef4): http://10.28.178.184:5555
18:52:18.634 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
18:52:18.960 INFO [NodeServer.lambda$createHandlers$2] - Node has been added

Distributor Logs:

18:52:18.945 INFO [GridModel.setAvailability] - Switching Node 49639489-531d-48d9-856d-7566f9eee5da (uri: http://10.28.178.184:5555) from DOWN to UP
18:52:18.945 INFO [LocalDistributor.add] - Added node 49639489-531d-48d9-856d-7566f9eee5da at http://10.28.178.184:5555. Health check every 120s
18:52:23.229 WARN [UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2] - Caught exception from listener: org.openqa.selenium.events.EventListener@753dcdee
java.lang.IllegalArgumentException: Session timeout must be set
	at org.openqa.selenium.internal.Require.positive(Require.java:99)
	at org.openqa.selenium.grid.node.Node.<init>(Node.java:129)
	at org.openqa.selenium.grid.node.remote.RemoteNode.<init>(RemoteNode.java:91)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.register(LocalDistributor.java:317)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.lambda$new$4(LocalDistributor.java:211)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:42)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:24)
	at org.openqa.selenium.events.zeromq.UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2(UnboundZmqEventBus.java:319)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
18:53:23.212 WARN [UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2] - Caught exception from listener: org.openqa.selenium.events.EventListener@753dcdee
java.lang.IllegalArgumentException: Session timeout must be set
	at org.openqa.selenium.internal.Require.positive(Require.java:99)
	at org.openqa.selenium.grid.node.Node.<init>(Node.java:129)
	at org.openqa.selenium.grid.node.remote.RemoteNode.<init>(RemoteNode.java:91)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.register(LocalDistributor.java:317)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.lambda$new$4(LocalDistributor.java:211)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:42)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:24)
	at org.openqa.selenium.events.zeromq.UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2(UnboundZmqEventBus.java:319)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
18:54:23.196 WARN [UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2] - Caught exception from listener: org.openqa.selenium.events.EventListener@753dcdee
java.lang.IllegalArgumentException: Session timeout must be set
	at org.openqa.selenium.internal.Require.positive(Require.java:99)
	at org.openqa.selenium.grid.node.Node.<init>(Node.java:129)
	at org.openqa.selenium.grid.node.remote.RemoteNode.<init>(RemoteNode.java:91)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.register(LocalDistributor.java:317)
	at org.openqa.selenium.grid.distributor.local.LocalDistributor.lambda$new$4(LocalDistributor.java:211)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:42)
	at org.openqa.selenium.events.EventListener.accept(EventListener.java:24)
	at org.openqa.selenium.events.zeromq.UnboundZmqEventBus$PollingRunnable.lambda$notifyListeners$2(UnboundZmqEventBus.java:319)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
	```
	At first it seemed like this stack traces only occurred when the node registered initially, but after scaling down to just one node, it is apparent that it also occurs every minute thereafter.

[joerg1985]

And scaling down to zero does stop it? The question might be strage, but this might indicate the distributor might send the event.

[johnbartels]

Scaling down to zero did not stop this trace. I scaled down to 0 nodes (verified by hitting the /status endpoint) and then waited a minute, saw a new trace pop up in the logs. I then waited 5 more minutes and was able to see that the stack trace with the "Session timeout must be set" message occurred every minute (even with 0 nodes).

[johnbartels]

I added the "--session-request-timeout" argument to my distributor's service file, and the process that was spawned has the following args/values:

java -jar selenium4.jar distributor --sessions http://selenium4-smap-internal-ip.devdomain.com:5556 --sessionqueue http://selenium4-squeue-internal-ip.devdomain.com:5559 --bind-bus true --healthcheck-interval 120 --session-request-timeout 600 --log /var/log/selenium/distributorControllerLogs.log --log-level INFO

However, the stack trace with the message "Session timeout must be set" was still present

[joerg1985]

It is very strange, the issue is still present without a node trying to register. I had a look at the code an the only way to trigger this error is to send a NodeHeartBeatEvent or a NodeStatusEvent without the field set.

Could you try to start with a different DNS name and IP just to get sure nothing else does connect to the distributor.