[🐛 Bug]: invalid session id: Unable to find session with ID

[amardeep2006]

What happened?

We are using selenium Grid 4.29.0 with Keda 2.16.1 and Chart version 0.40.0 on Kubernetes.
Autoscaling is enabled as Jobs.
We are observing failures in many tests (not all) where session is created but we are seeing the error in test script logs
invalid session id: Unable to find session with ID: 427d46161959df87e81f2a18e97af223

When I searched for the session id in logs we found that node with this session id was set to draining within same milliseconds as session was created.I am not sure if this can cause issues or this is an expected behavior ?

However the pod was terminated after 4 minutes 46 seconds.

Here are the logs for both hub and node chrome where I see a clear gap of 4 min 46 seconds.

Command used to start Selenium Grid with Docker (or Kubernetes)

Helm chart version 0.40.0

Relevant log output

node chrome logs

2025-02-27 06:59:53,037 WARN stopped: selenium-node (terminated by SIGTERM)
06:59:53.036 INFO [LocalNode.stopAllSessions] - Trying to stop all running sessions before shutting down...
2025-02-27 06:59:52,033 INFO waiting for xvfb, vnc, novnc, selenium-node to die
2025-02-27 06:59:52,033 WARN received SIGTERM indicating exit request
Trapped SIGTERM/SIGINT/x so shutting down supervisord...
{"log-message":"Draining Node, configured sessions value (1) has been reached.","method":"checkSessionCount","log-level":"INFO","log-time-utc":"2025-02-27T06:55:01.736Z","log-name":"org.openqa.selenium.grid.node.local.LocalNode","log-time-local":"2025-02-27T06:55:01.736Z","class":"LocalNode"}
06:55:01.736 INFO [LocalNode.checkSessionCount] - Draining Node, configured sessions value (1) has been reached.
{"log-message":"Session created by the Node. Id: 427d46161959df87e81f2a18e97af223, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 133.0.6943.126, chrome: {chromedriverVersion: 133.0.6943.126 (cffa127ce7b..., userDataDir: /tmp/.org.chromium.Chromium...}, fedcm:accounts: true, goog:chromeOptions: {debuggerAddress: localhost:37441}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: any, proxy: Proxy(), se:bidiEnabled: false, se:cdp: wss://mercer-selgrid-np-eme..., se:cdpVersion: 133.0.6943.126, se:containerName: mercer-selgrid-selenium-nod..., se:downloadsEnabled: true, se:noVncPort: 7900, se:vnc: wss://myorg-selgrid-np-eme..., se:vncEnabled: true, se:vncLocalAddress: ws://10.42.225.202:7900, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:extension:minPinLength: true, webauthn:extension:prf: true, webauthn:virtualAuthenticators: true}","method":"newSession","log-level":"INFO","log-time-utc":"2025-02-27T06:55:01.733Z","log-name":"org.openqa.selenium.grid.node.local.LocalNode","log-time-local":"2025-02-27T06:55:01.733Z","class":"LocalNode"}
06:55:01.733 INFO [LocalNode.newSession] - Session created by the Node. Id: 427d46161959df87e81f2a18e97af223, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 133.0.6943.126, chrome: {chromedriverVersion: 133.0.6943.126 (cffa127ce7b..., userDataDir: /tmp/.org.chromium.Chromium...}, fedcm:accounts: true, goog:chromeOptions: {debuggerAddress: localhost:37441}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: any, proxy: Proxy(), se:bidiEnabled: false, se:cdp: wss://myorg-selgrid-np-eme..., se:cdpVersion: 133.0.6943.126, se:containerName: myorg-selgrid-selenium-nod..., se:downloadsEnabled: true, se:noVncPort: 7900, se:vnc: wss://myorg-selgrid-np-eme..., se:vncEnabled: true, se:vncLocalAddress: ws://10.42.225.202:7900, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:extension:minPinLength: true, webauthn:extension:prf: true, webauthn:virtualAuthenticators: true}
{"log-message":"Node has been added","method":"lambda$createHandlers$2","log-level":"INFO","log-time-utc":"2025-02-27T06:55:01.038Z","log-name":"org.openqa.selenium.grid.node.httpd.NodeServer","log-time-local":"2025-02-27T06:55:01.038Z","class":"NodeServer"}
06:55:01.038 INFO [NodeServer.lambda$createHandlers$2] - Node has been added
{"log-message":"Sending registration event...","method":"lambda$start$2","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.82Z","log-name":"org.openqa.selenium.grid.node.httpd.NodeServer","log-time-local":"2025-02-27T06:55:00.82Z","class":"NodeServer$2"}
06:55:00.820 INFO [NodeServer$2.lambda$start$2] - Sending registration event...
{"log-message":"Started Selenium node 4.29.0 (revision 18ae989): http://10.42.225.202:5555","method":"execute","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.814Z","log-name":"org.openqa.selenium.grid.node.httpd.NodeServer","log-time-local":"2025-02-27T06:55:00.814Z","class":"NodeServer"}
06:55:00.814 INFO [NodeServer.execute] - Started Selenium node 4.29.0 (revision 18ae989): http://10.42.225.202:5555
{"log-message":"Starting registration process for Node http://10.42.225.202:5555","method":"start","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.813Z","log-name":"org.openqa.selenium.grid.node.httpd.NodeServer","log-time-local":"2025-02-27T06:55:00.813Z","class":"NodeServer$2"}
06:55:00.813 INFO [NodeServer$2.start] - Starting registration process for Node http://10.42.225.202:5555
{"log-message":"Binding additional locator mechanisms: relative","method":"<init>","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.694Z","log-name":"org.openqa.selenium.grid.node.Node","log-time-local":"2025-02-27T06:55:00.694Z","class":"Node"}
06:55:00.694 INFO [Node.<init>] - Binding additional locator mechanisms: relative
{"log-message":"Adding chrome for {\"browserName\": \"chrome\",\"browserVersion\": \"\",\"container:hostname\": \"myorg-selgrid-selenium-node-chrome-cf575-zjbxf\",\"goog:chromeOptions\": {\"binary\": \"\\u002fusr\\u002fbin\\u002fgoogle-chrome\"},\"platformName\": \"any\",\"se:containerName\": \"myorg-selgrid-selenium-node-chrome-cf575-zjbxf\",\"se:downloadsEnabled\": true,\"se:noVncPort\": 7900,\"se:vncEnabled\": true} 1 times","method":"report","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.647Z","log-name":"org.openqa.selenium.grid.node.config.NodeOptions","log-time-local":"2025-02-27T06:55:00.647Z","class":"NodeOptions"}
06:55:00.647 INFO [NodeOptions.report] - Adding chrome for {"browserName": "chrome","browserVersion": "","container:hostname": "myorg-selgrid-selenium-node-chrome-cf575-zjbxf","goog:chromeOptions": {"binary": "\u002fusr\u002fbin\u002fgoogle-chrome"},"platformName": "any","se:containerName": "myorg-selgrid-selenium-node-chrome-cf575-zjbxf","se:downloadsEnabled": true,"se:noVncPort": 7900,"se:vncEnabled": true} 1 times
{"log-message":"Detected {0} available processors","method":"getSessionFactories","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.618Z","log-name":"org.openqa.selenium.grid.node.config.NodeOptions","log-time-local":"2025-02-27T06:55:00.618Z","class":"NodeOptions"}
06:55:00.618 INFO [NodeOptions.getSessionFactories] - Detected 2 available processors
{"log-message":"Using null tracer","method":"getTracer","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.607Z","log-name":"org.openqa.selenium.grid.log.LoggingOptions","log-time-local":"2025-02-27T06:55:00.607Z","class":"LoggingOptions"}
06:55:00.607 INFO [LoggingOptions.getTracer] - Using null tracer
{"log-message":"Reporting self as: http://10.42.225.202:5555","method":"createHandlers","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.604Z","log-name":"org.openqa.selenium.grid.node.httpd.NodeServer","log-time-local":"2025-02-27T06:55:00.604Z","class":"NodeServer"}
06:55:00.604 INFO [NodeServer.createHandlers] - Reporting self as: http://10.42.225.202:5555
{"log-message":"Event bus ready","method":"<init>","log-level":"INFO","log-time-utc":"2025-02-27T06:55:00.494Z","log-name":"org.openqa.selenium.events.zeromq.UnboundZmqEventBus","log-time-local":"2025-02-27T06:55:00.494Z","class":"UnboundZmqEventBus"}
06:55:00.494 INFO [UnboundZmqEventBus.<init>] - Event bus ready
2025-02-27 06:54:59,684 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2025-02-27 06:54:59,684 INFO success: vnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2025-02-27 06:54:59,684 INFO success: xvfb entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
{"log-message":"Sockets created","method":"<init>","log-level":"INFO","log-time-utc":"2025-02-27T06:54:59.492Z","log-name":"org.openqa.selenium.events.zeromq.UnboundZmqEventBus","log-time-local":"2025-02-27T06:54:59.492Z","class":"UnboundZmqEventBus"}
06:54:59.492 INFO [UnboundZmqEventBus.<init>] - Sockets created
{"log-message":"Connecting to tcp://myorg-selgrid-selenium-hub:4442 and tcp://myorg-selgrid-selenium-hub:4443","method":"<init>","log-level":"INFO","log-time-utc":"2025-02-27T06:54:59.439Z","log-name":"org.openqa.selenium.events.zeromq.UnboundZmqEventBus","log-time-local":"2025-02-27T06:54:59.439Z","class":"UnboundZmqEventBus"}
06:54:59.439 INFO [UnboundZmqEventBus.<init>] - Connecting to tcp://myorg-selgrid-selenium-hub:4442 and tcp://myorg-selgrid-selenium-hub:4443
{"log-message":"Using null tracer","method":"getTracer","log-level":"INFO","log-time-utc":"2025-02-27T06:54:59.417Z","log-name":"org.openqa.selenium.grid.log.LoggingOptions","log-time-local":"2025-02-27T06:54:59.417Z","class":"LoggingOptions"}
06:54:59.417 INFO [LoggingOptions.getTracer] - Using null tracer
{"log-message":"Using the system default encoding","method":"configureLogEncoding","log-level":"INFO","log-time-utc":"2025-02-27T06:54:59.393Z","log-name":"","log-time-local":"2025-02-27T06:54:59.393Z","class":"LoggingOptions"}
06:54:59.393 INFO [LoggingOptions.configureLogEncoding] - Using the system default encoding
06:54:59.390 INFO [LoggingOptions.configureLogEncoding] - Using the system default encoding
Using JAVA_OPTS: -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/selenium/logs -XX:+UseG1GC -XX:MaxGCPauseMillis=1000 -XX:MaxRAMPercentage=50 -Dwebdriver.remote.enableTracing=false -Dwebdriver.httpclient.version=HTTP_1_1
Starting Selenium Grid Node...
max-sessions = 1
stereotype = '{"browserName": "chrome", "browserVersion": "", "platformName": "", "goog:chromeOptions": {"binary": "/usr/bin/google-chrome"}, "se:containerName": "myorg-selgrid-selenium-node-chrome-cf575-zjbxf", "container:hostname": "myorg-selgrid-selenium-node-chrome-cf575-zjbxf"}'
display-name = "chrome"
[[node.driver-configuration]]
max-sessions = 1
drain-after-session-count = 1
detect-drivers = false
override-max-sessions = false
session-timeout = 300
grid-url = "https://myselgri.url.org"
[node]
port = "5555"
host = "10.42.225.202"
[server]
subscribe = "tcp://myorg-selgrid-selenium-hub:4443"
publish = "tcp://myorg-selgrid-selenium-hub:4442"
[events]
Selenium Grid Node configuration:
Appending Selenium option: --config /opt/selenium/config.toml
Appending Selenium option: --bind-host false
Tracing is disabled
Appending Selenium option: --tracing false
Generating Selenium Config
Appending Selenium option: --structured-logs true
Appending Selenium option: --http-logs false
Appending Selenium option: --log-level INFO
Appending Selenium option: --heartbeat-period 30
Appending Selenium option: --register-shutdown-on-failure
Appending Selenium option: --register-cycle 5
Appending Selenium option: --register-period 120
Appending Selenium option: --enable-managed-downloads true
2025-02-27 06:54:58,668 INFO success: selenium-node entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2025-02-27 06:54:58,664 INFO spawned: 'selenium-node' with pid 24
2025-02-27 06:54:58,663 INFO spawned: 'novnc' with pid 23
2025-02-27 06:54:58,660 INFO spawned: 'vnc' with pid 22
2025-02-27 06:54:58,659 INFO spawned: 'xvfb' with pid 21
2025-02-27 06:54:57,656 INFO supervisord started with pid 20
2025-02-27 06:54:57,656 INFO RPC interface 'supervisor' initialized
2025-02-27 06:54:57,654 INFO Included extra file "/etc/supervisor/conf.d/uploader.conf" during parsing
2025-02-27 06:54:57,653 INFO Included extra file "/etc/supervisor/conf.d/selenium.conf" during parsing
2025-02-27 06:54:57,653 INFO Included extra file "/etc/supervisor/conf.d/recorder.conf" during parsing
2025-02-27 06:54:57,653 INFO Included extra file "/etc/supervisor/conf.d/chrome-cleanup.conf" during parsing

Operating System

EKS 1.28

Docker Selenium version (image tag)

4.29.0

Selenium Grid chart version (chart version)

0.40.0

[github-actions]

@amardeep2006, 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!

[amardeep2006]

Update: This looks like a common pattern across all nodes which are gracefully drained as well. I am trying out SE_NODE_SESSION_TIMEOUT and will share results.
At the same time I have asked teams to check the test scripts for any errors/issue/scenarios that may causing inactivity and ending up session timeout on grid.

[VietND96]

Yes, you can try to increase the SE_NODE_SESSION_TIMEOUT. Between 4.28 - 4.29, there were improvements in timeout to make its behavior work correctly.

[amardeep2006]

Thanks @VietND96 This issue can be closed as we have identified the transaction causing issue. Not an issue on grid.

[amardeep2006]

Adding additional info based on my detailed analysis of this issue.

1. This was happening for few test cases only so we decided to run the test locally on laptop and monitor compute usage and response times.
2. We identifies that one particular page was taking too much of time and RAM to load. The RAM usage went upto 3 GB locally.
3. When we compared this on kubernetes we had set the RAM limit of 2 GB on pods.
4. It was possible that because of RAM constraints on pods, browser was crashing on selenium grid pod.
5. Since the browser was crashed, test scripts were simply waiting and causing session timeouts on grid.
6. We increased the RAM limits to 4 GB and saw improvements.
7. Also told application team to fix the issue in the application page to make it fast and less resource extensive.

One may think we should have got out of memory error instead of Error Code 9 but my hypothesis says out of memory error is caused when we cross 4 GB of memory limit. If browser is starved of RAM it may be throwing a generic Error code 9.

[VietND96]

Regarding issue container consume too much memory, it could be related to #2706. It was enabled by default.
I just updated it to enable by env var flag only. Probably the next image tag will be better

[amardeep2006]

@VietND96 I doubt that . Based on my knowledge -XX:+HeapDumpOnOutOfMemoryError flag does not introduce performance or security problems in run time. The flag is checked only after OutOfMemoryError has happened on Java process.

[VietND96]

Yes, I guess it could use in-memory to cache all dump data during the runtime, once OOM it will throw out. However, I am not sure about this theory, wait for them to try new image tag and feedback.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.