search

SeleniumHQ / docker-selenium

Provides a simple way to run Selenium Grid with Chrome, Firefox, and Edge using Docker, making it easier to perform browser automation
http://www.selenium.dev/docker-selenium/
Other
7.96k stars 2.51k forks source link

Failed to create a session #1375

Closed akmalff closed 3 years ago

akmalff commented 3 years ago

🐛 Bug Report

I'm running a selenium docker in aws instances and recently just switch to selenium 4.0 docker and keep getting this error

Failed to connect to webdriver after 4 tries: Message: Could not start a new session. New session request timed out
Build info: version: '4.0.0-rc-1', revision: 'ea41b757bd'
System info: host: 'ec608ad8170b', ip: '172.17.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '4.4.0-1128-aws', java.version: '11.0.11'
Driver info: driver.version: unknown
Stacktrace:
    at org.openqa.selenium.grid.sessionqueue.local.LocalNewSessionQueue.addToQueue (LocalNewSessionQueue.java:198)
    at org.openqa.selenium.grid.sessionqueue.NewSessionQueue.lambda$new$0 (NewSessionQueue.java:68)
    at org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle (Route.java:192)
    at org.openqa.selenium.remote.http.Route.execute (Route.java:68)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle (Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute (Route.java:68)
    at org.openqa.selenium.grid.sessionqueue.NewSessionQueue.execute (NewSessionQueue.java:120)
    at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute (SpanWrappedHttpHandler.java:86)
    at org.openqa.selenium.remote.http.Filter$1.execute (Filter.java:64)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle (Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute (Route.java:68)
    at org.openqa.selenium.grid.router.Router.execute (Router.java:91)
    at org.openqa.selenium.grid.web.EnsureSpecCompliantResponseHeaders.lambda$apply$0 (EnsureSpecCompliantResponseHeaders.java:34)
    at org.openqa.selenium.remote.http.Filter$1.execute (Filter.java:64)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle (Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute (Route.java:68)
    at org.openqa.selenium.remote.http.Route$NestedRoute.handle (Route.java:270)
    at org.openqa.selenium.remote.http.Route.execute (Route.java:68)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle (Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute (Route.java:68)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle (Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute (Route.java:68)
    at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0 (AddWebDriverSpecHeaders.java:35)
    at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0 (ErrorFilter.java:44)
    at org.openqa.selenium.remote.http.Filter$1.execute (Filter.java:64)
    at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0 (ErrorFilter.java:44)
    at org.openqa.selenium.remote.http.Filter$1.execute (Filter.java:64)
    at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0 (SeleniumHandler.java:44)
    at java.util.concurrent.Executors$RunnableAdapter.call (Executors.java:515)
    at java.util.concurrent.FutureTask.run (FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
    at java.lang.Thread.run (Thread.java:829)

Environment

here's what inside my docker-compose.yml standalone-chromium: image: selenium/standalone-chrome:4.0.0-rc-1-prerelease-20210823 restart: always volumes:

diemol commented 3 years ago

How can I reproduce the issue?

ghost commented 3 years ago

I too am getting this issue with selenium/standalone-chrome:4.0.0-rc-1-prerelease-20210804. I'm using the php webdriver package.

This is the code I'm using.

$capabilities = DesiredCapabilities::chrome();

$options = new ChromeOptions();
$options->addExtensions([
    base_path() . '/extensions/' . env('EXTENSION_FILENAME')
]);

$capabilities->setCapability(ChromeOptions::CAPABILITY, $options);

$driver = RemoteWebDriver::create($this->serverUrl, $capabilities);

$driver->get($this->scrapeUrl . $word);

$result = $this->handleScrape($driver);

$driver->quit();

At random I get the same error as @akmalff. To fix this issue I restart my docker container. But this is just a temporary fix... Even without the extension I get the error.

diemol commented 3 years ago

Can you please share the logs?

ghost commented 3 years ago

@diemol If it happens again I will.

ghost commented 3 years ago

This is the selenium log I'm getting:

18:03:24.106 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:03:24.329 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 96c914718cadc3d5c2085388a1f0634a, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.tRC64r}, goog:chromeOptions: {debuggerAddress: localhost:43689}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:03:28.712 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: 96c914718cadc3d5c2085388a1f0634a
18:03:31.627 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 25795
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:03:34.104 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:03:34.428 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 330088913564d0fa552559d387ec530d, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.Wkrrzw}, goog:chromeOptions: {debuggerAddress: localhost:40963}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:03:38.881 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: 330088913564d0fa552559d387ec530d
18:03:41.627 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 5076
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:03:44.053 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:03:44.221 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: fb2db2d9ae5703cb12f29b90cefddaab, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.vOeeNE}, goog:chromeOptions: {debuggerAddress: localhost:34161}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:03:47.223 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: fb2db2d9ae5703cb12f29b90cefddaab
18:03:51.628 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 24897
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:03:54.032 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:03:54.309 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 212ece93268b160f35621f6b05f5e279, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.7GFjzL}, goog:chromeOptions: {debuggerAddress: localhost:38639}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:03:57.732 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: 212ece93268b160f35621f6b05f5e279
18:04:01.628 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 11419
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:04:04.219 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:04:04.411 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: db7464fdcd465a4b688e9b9f20d6808c, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.IWdWkP}, goog:chromeOptions: {debuggerAddress: localhost:37267}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:04:11.168 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: db7464fdcd465a4b688e9b9f20d6808c
18:04:16.629 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 10742
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:04:19.024 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:04:19.332 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 4847d182836be8dc48e37344ba990e11, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.0peghe}, goog:chromeOptions: {debuggerAddress: localhost:38777}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:04:22.580 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: 4847d182836be8dc48e37344ba990e11
18:04:26.629 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 30027
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:04:29.031 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:04:29.333 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 2c10a7b8cd863061c398942007de3d5a, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.MLolvd}, goog:chromeOptions: {debuggerAddress: localhost:46657}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:04:32.624 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: 2c10a7b8cd863061c398942007de3d5a
18:04:36.630 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 22072
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:04:39.033 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:04:39.214 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 122b2b3ec2597de8180d221998d87327, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.i1uX0i}, goog:chromeOptions: {debuggerAddress: localhost:35169}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:04:42.743 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local session map, Id: 122b2b3ec2597de8180d221998d87327
18:04:46.631 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 4574
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
18:04:49.370 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
18:04:49.474 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 7aef96e3a525d7aca9d7360444c97d19, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 92.0.4515.131, chrome: {chromedriverVersion: 92.0.4515.107 (87a818b10553..., userDataDir: /tmp/.com.google.Chrome.36xcai}, goog:chromeOptions: {debuggerAddress: localhost:41589}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://10.244.88.5:4444/sessi..., se:cdpVersion: 92.0.4515.131, se:vnc: ws://10.244.88.5:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://localhost:7900/websockify, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:virtualAuthenticators: true}
18:07:49.478 WARN [SpanWrappedHttpHandler.execute] - Unable to execute request: java.util.concurrent.TimeoutException
Build info: version: '4.0.0-rc-1', revision: 'c498dad8c5'
System info: host: 'wk-caas-ad5a06697dc54e2ca7b1102d6359a19f-7a5ce74618958843eafb19', ip: '10.244.88.5', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-1113-azure', java.version: '11.0.11'
Driver info: driver.version: unknown
org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException
Build info: version: '4.0.0-rc-1', revision: 'c498dad8c5'
System info: host: 'wk-caas-ad5a06697dc54e2ca7b1102d6359a19f-7a5ce74618958843eafb19', ip: '10.244.88.5', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-1113-azure', java.version: '11.0.11'
Driver info: driver.version: unknown
    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:72)
    at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)
    at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)
    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.execute(NettyHttpHandler.java:51)
    at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)
    at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)
    at org.openqa.selenium.remote.http.netty.NettyClient.execute(NettyClient.java:116)
    at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)
    at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:100)
    at org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)
    at org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:123)
    at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:385)
    at org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)
    at org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)
    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
    at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:86)
    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
    at org.openqa.selenium.grid.node.Node.execute(Node.java:240)
    at org.openqa.selenium.grid.web.CombinedHandler.execute(CombinedHandler.java:59)
    at org.openqa.selenium.grid.web.RoutableHttpClientFactory$1.execute(RoutableHttpClientFactory.java:66)
    at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:100)
    at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:110)
    at org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)
    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
    at org.openqa.selenium.grid.router.Router.execute(Router.java:91)
    at org.openqa.selenium.grid.web.EnsureSpecCompliantResponseHeaders.lambda$apply$0(EnsureSpecCompliantResponseHeaders.java:34)
    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
    at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
    at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
    at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)
    at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
    at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
    at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
    at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)
    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)
Caused by: java.util.concurrent.TimeoutException
    at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886)
    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021)
    at org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:206)
    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:66)
    ... 45 more
18:07:49.479 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "176d8a822070f1bd7d167dc58478fe9c","eventTime": 1630260469478175605,"eventName": "exception","attributes": {"exception.message": "Unable to execute request: java.util.concurrent.TimeoutException\nBuild info: version: '4.0.0-rc-1', revision: 'c498dad8c5'\nSystem info: host: 'wk-caas-ad5a06697dc54e2ca7b1102d6359a19f-7a5ce74618958843eafb19', ip: '10.244.88.5', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-1113-azure', java.version: '11.0.11'\nDriver info: driver.version: unknown","exception.stacktrace": "org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException\nBuild info: version: '4.0.0-rc-1', revision: 'c498dad8c5'\nSystem info: host: 'wk-caas-ad5a06697dc54e2ca7b1102d6359a19f-7a5ce74618958843eafb19', ip: '10.244.88.5', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-1113-azure', java.version: '11.0.11'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:72)\n\tat org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)\n\tat org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.execute(NettyHttpHandler.java:51)\n\tat org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)\n\tat org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)\n\tat org.openqa.selenium.remote.http.netty.NettyClient.execute(NettyClient.java:116)\n\tat org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:100)\n\tat org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)\n\tat org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:123)\n\tat org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:385)\n\tat org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)\n\tat org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:86)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.grid.node.Node.execute(Node.java:240)\n\tat org.openqa.selenium.grid.web.CombinedHandler.execute(CombinedHandler.java:59)\n\tat org.openqa.selenium.grid.web.RoutableHttpClientFactory$1.execute(RoutableHttpClientFactory.java:66)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:100)\n\tat org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:110)\n\tat org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.grid.router.Router.execute(Router.java:91)\n\tat org.openqa.selenium.grid.web.EnsureSpecCompliantResponseHeaders.lambda$apply$0(EnsureSpecCompliantResponseHeaders.java:34)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)\n\tat java.base\u002fjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)\n\tat java.base\u002fjava.util.concurrent.FutureTask.run(FutureTask.java:264)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base\u002fjava.lang.Thread.run(Thread.java:829)\nCaused by: java.util.concurrent.TimeoutException\n\tat java.base\u002fjava.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886)\n\tat java.base\u002fjava.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021)\n\tat org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:206)\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:66)\n\t... 45 more\n","exception.type": "org.openqa.selenium.TimeoutException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "127.0.0.1:4444","http.method": "POST","http.request_content_length": "62","http.scheme": "HTTP","http.target": "\u002fsession\u002f7aef96e3a525d7aca9d7360444c97d19\u002furl"}}

18:07:49.480 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "176d8a822070f1bd7d167dc58478fe9c","eventTime": 1630260469480205512,"eventName": "exception","attributes": {"exception.message": "Unable to execute request for an existing session: java.util.concurrent.TimeoutException\nBuild info: version: '4.0.0-rc-1', revision: 'c498dad8c5'\nSystem info: host: 'wk-caas-ad5a06697dc54e2ca7b1102d6359a19f-7a5ce74618958843eafb19', ip: '10.244.88.5', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-1113-azure', java.version: '11.0.11'\nDriver info: driver.version: unknown","exception.stacktrace": "org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException\nBuild info: version: '4.0.0-rc-1', revision: 'c498dad8c5'\nSystem info: host: 'wk-caas-ad5a06697dc54e2ca7b1102d6359a19f-7a5ce74618958843eafb19', ip: '10.244.88.5', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-1113-azure', java.version: '11.0.11'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:72)\n\tat org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)\n\tat org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.execute(NettyHttpHandler.java:51)\n\tat org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)\n\tat org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)\n\tat org.openqa.selenium.remote.http.netty.NettyClient.execute(NettyClient.java:116)\n\tat org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:100)\n\tat org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)\n\tat org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:123)\n\tat org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:385)\n\tat org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)\n\tat org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:86)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.grid.node.Node.execute(Node.java:240)\n\tat org.openqa.selenium.grid.web.CombinedHandler.execute(CombinedHandler.java:59)\n\tat org.openqa.selenium.grid.web.RoutableHttpClientFactory$1.execute(RoutableHttpClientFactory.java:66)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:100)\n\tat org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:110)\n\tat org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.grid.router.Router.execute(Router.java:91)\n\tat org.openqa.selenium.grid.web.EnsureSpecCompliantResponseHeaders.lambda$apply$0(EnsureSpecCompliantResponseHeaders.java:34)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\n\tat org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\n\tat org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)\n\tat java.base\u002fjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)\n\tat java.base\u002fjava.util.concurrent.FutureTask.run(FutureTask.java:264)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base\u002fjava.lang.Thread.run(Thread.java:829)\nCaused by: java.util.concurrent.TimeoutException\n\tat java.base\u002fjava.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886)\n\tat java.base\u002fjava.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021)\n\tat org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:206)\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:66)\n\t... 45 more\n","exception.type": "org.openqa.selenium.TimeoutException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.router.HandleSession","http.host": "127.0.0.1:4444","http.method": "POST","http.request_content_length": "62","http.scheme": "HTTP","http.target": "\u002fsession\u002f7aef96e3a525d7aca9d7360444c97d19\u002furl","session.id": "7aef96e3a525d7aca9d7360444c97d19"}}

And this is the PHP log I'm getting:

[2021-08-29 18:08:52] local.ERROR: Curl error thrown for http POST to /session with params: {"capabilities":{"firstMatch":[{"browserName":"chrome","goog:chromeOptions":{"exten$

Operation timed out after 30000 milliseconds with 0 bytes received {"exception":"[object] (Facebook\\WebDriver\\Exception\\WebDriverCurlException(code: 0): Curl error thrown f$

Operation timed out after 30000 milliseconds with 0 bytes received at /api/vendor/php-webdriver/webdriver/lib/Remote/HttpCommandExecutor.php:332)

Hope you can help me out. If you need any more information, let me know!

diemol commented 3 years ago

Was this working before? What happens if you use ChromeDriver directly without Grid?

ghost commented 3 years ago

No, never worked properly. Can you elaborate? I'm not very familiar with selenium.

JMoravec commented 3 years ago

Hi, I'm also seeing this when using the grid in k8s. I can't seem to track it down to anything specific, as with retry logic on test failures, the tests successfully run. I have similar logs to zipper11 in the router pod, while the other grid pods don't have anything I noticed that was useful. I also didn't notice any unique logs in the chrome nodes in case it was a bad pod that was causing the failures. They all have similar logs:

2021-08-31 14:49:45,368 INFO Included extra file "/etc/supervisor/conf.d/selenium.conf" during parsing
2021-08-31 14:49:45,369 INFO supervisord started with pid 9
2021-08-31 14:49:46,372 INFO spawned: 'xvfb' with pid 11
2021-08-31 14:49:46,374 INFO spawned: 'vnc' with pid 12
2021-08-31 14:49:46,375 INFO spawned: 'novnc' with pid 13
2021-08-31 14:49:46,376 INFO spawned: 'selenium-node' with pid 14
2021-08-31 14:49:46,389 INFO success: xvfb entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2021-08-31 14:49:46,390 INFO success: vnc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2021-08-31 14:49:46,390 INFO success: novnc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2021-08-31 14:49:46,390 INFO success: selenium-node entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Configuring server...
Setting up SE_NODE_HOST...
Setting up SE_NODE_PORT...
Setting up SE_NODE_GRID_URL...
Selenium Grid Node configuration: 
[events]
publish = "tcp://selenium-event-bus:4442"
subscribe = "tcp://selenium-event-bus:4443"

[node]
session-timeout = "300"
override-max-sessions = false
detect-drivers = false
max-sessions = 1

[[node.driver-configuration]]
name = "chrome"
stereotype = '{"browserName": "chrome", "browserVersion": "92.0", "platformName": "Linux"}'
max-sessions = 1

Starting Selenium Grid Node...
14:49:47.359 INFO [LoggingOptions.configureLogEncoding] - Using the system default encoding
14:49:47.364 INFO [OpenTelemetryTracer.createTracer] - Using OpenTelemetry for tracing
14:49:47.558 INFO [UnboundZmqEventBus.<init>] - Connecting to tcp://selenium-event-bus:4442 and tcp://selenium-event-bus:4443
14:49:47.656 INFO [UnboundZmqEventBus.<init>] - Sockets created
14:49:48.658 INFO [UnboundZmqEventBus.<init>] - Event bus ready
14:49:48.845 INFO [NodeServer.createHandlers] - Reporting self as: http://10.217.85.187:5555
14:49:48.860 INFO [NodeOptions.getSessionFactories] - Detected 1 available processors
14:49:48.951 INFO [NodeOptions.report] - Adding chrome for {"browserVersion": "92.0","browserName": "chrome","platformName": "Linux","se:vncEnabled": true} 1 times
14:49:48.959 INFO [Node.<init>] - Binding additional locator mechanisms: name, id
14:49:49.279 INFO [NodeServer$1.start] - Starting registration process for node id 98e8454e-cdc4-4868-9c11-ed9d6eb858a5
14:49:49.280 INFO [NodeServer.execute] - Started Selenium node 4.0.0-rc-1 (revision ea41b757bd): http://10.217.85.187:5555
14:49:49.282 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
14:49:49.493 INFO [NodeServer.lambda$createHandlers$2] - Node has been added
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on[ 1630421681.500][SEVEREp]o:r tb i9n8d5(7)
Only  lfoacialle dc:o nCnaencntoito nass sairgen  arlelqouweesdt.e
Pleads ea dsderee shst t(p9s9:)/
/chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
14:54:42.272 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 30589
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
[1630421991.191][SEVERE]: bind() failed: Cannot assign requested address (99)
14:59:51.453 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 17096
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
[1630422322.277][SEVERE]: bind() failed: Cannot assign requested address (99)
15:05:22.449 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 23935
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
[1630422653.484][SEVERE]: bind() failed: Cannot assign requested address (99)
15:10:53.658 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 25255
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
[1630422984.484][SEVERE]: binCd() failed: Cannot assign requested addhrreosmse D(r9i9v)e
r was started successfully.
15:16:24.661 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 31822
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
[1630423114.540][SEVERE]: bind() failed: Cannot assign requested address (99)
15:18:34.746 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
Starting ChromeDriver 92.0.4515.107 (87a818b10553a07434ea9e2b6dccf3cbe7895134-refs/branch-heads/4515@{#1634}) on port 4784
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
[1630423274.643][SEVERE]: bind() failed: Cannot assign requested address (99)
15:21:14.853 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
ghost commented 3 years ago

Here are some extra logs I found when selenium stopped working properly again. No idea if they are any use to the maintainers.

15:07:18.157 INFO [LocalDistributor$NewSessionRunnable.handleNewSessionRequest] - Retrying
15:07:18.158 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
15:07:18.158 INFO [LocalDistributor.newSession] - Unable to find slot for request 1ba48b81-853c-4598-9cd5-4cc2dc00e37f. May retry: Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}} 
15:07:18.159 INFO [LocalDistributor.newSession] - Unable to find slot for request 1ba48b81-853c-4598-9cd5-4cc2dc00e37f. May retry: Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY} 
15:07:18.159 INFO [LocalDistributor$NewSessionRunnable.handleNewSessionRequest] - Retrying
15:07:18.160 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
15:07:18.160 INFO [LocalDistributor.newSession] - Unable to find slot for request 362c3bd7-cf4a-499e-ae89-ee1e46262f0b. May retry: Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}} 
15:07:18.161 INFO [LocalDistributor.newSession] - Unable to find slot for request 362c3bd7-cf4a-499e-ae89-ee1e46262f0b. May retry: Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY} 
15:07:18.161 INFO [LocalDistributor$NewSessionRunnable.handleNewSessionRequest] - Retrying
15:07:18.162 INFO [LocalDistributor.newSession] - Session request received by the distributor: 
 [Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}}, Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY}]
15:07:18.162 INFO [LocalDistributor.newSession] - Unable to find slot for request 6ce59fd8-c216-4dbb-a49e-bc5d9e8c2a69. May retry: Capabilities {browserName: chrome, goog:chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}} 
15:07:18.162 INFO [LocalDistributor.newSession] - Unable to find slot for request 6ce59fd8-c216-4dbb-a49e-bc5d9e8c2a69. May retry: Capabilities {browserName: chrome, chromeOptions: {extensions: [Q3IyNAMAAAAdBQAAEqwECqYCMII...]}, platform: ANY} 
15:07:18.163 INFO [LocalDistributor$NewSessionRunnable.handleNewSessionRequest] - Retrying
15:08:09.101 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "cda0b7ec6636daaf1ab18e464b471267","eventTime": 1630422489100611457,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.sessionqueue.local.LocalNewSessionQueue","http.host": "127.0.0.1:4444","http.method": "POST","http.request_content_length": "7638671","http.scheme": "HTTP","http.status_code": 500,"http.target": "\u002fsession"}}

15:08:51.719 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "b36bd4b9282cf2eda9e42d9f772f5233","eventTime": 1630422531718829354,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.sessionqueue.local.LocalNewSessionQueue","http.host": "127.0.0.1:4444","http.method": "POST","http.request_content_length": "7638671","http.scheme": "HTTP","http.status_code": 500,"http.target": "\u002fsession"}}

15:09:34.348 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "03af0b5d2ac4148ecc53b8785466514d","eventTime": 1630422574348233845,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.sessionqueue.local.LocalNewSessionQueue","http.host": "127.0.0.1:4444","http.method": "POST","http.request_content_length": "7638671","http.scheme": "HTTP","http.status_code": 500,"http.target": "\u002fsession"}}

15:10:16.991 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "b709072496f330c4db0690f3d038ef19","eventTime": 1630422616990011253,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.sessionqueue.local.LocalNewSessionQueue","http.host": "127.0.0.1:4444","http.method": "POST","http.request_content_length": "7638671","http.scheme": "HTTP","http.status_code": 500,"http.target": "\u002fsession"}}
JMoravec commented 3 years ago

After a lot of running tests yesterday, I think I possibly found out more info: How I was running tests was scaling up the chrome nodes to some number (50 in my case), and immediately running tests against the hub. I assumed that the grid would not allow nodes that weren't ready to get new sessions, but this doesn't seem to be the case (as in, the timeout exception appears to be happening when tests try to run against a node that is not completely running/ready yet).

To help test this and possibly work around it, I added two things:

  1. A readinessProbe for the chrome node: 
    readinessProbe:
exec:
    command:
        - /bin/sh
        - -c
        - curl -ssL http://localhost:5555/status | jq -r 'value.ready' | grep -q "true" || exit 1
  2. Wait until the replicas are completly ready before running tests: kubectl scale deployment --replicas 50 selenium-chrome-node-deployment

This seems to have dropped the amount of times I see the TimoutException completely, although I'd still like to not have to wait for the scale to be done before running tests. I'd like to see the hub not schedule new sessions until nodes were completely ready.

Hopefully that helps narrow down where the issue is!

JMoravec commented 3 years ago

I spoke too soon 🤦 I'm unfortunately still seeing some timeout exceptions with ^, although it does seem to be less than before

diemol commented 3 years ago

Would it be possible to get a GitHub repo to reproduce this issue? Does it only happen in Kubernetes or also with Docker?

ghost commented 3 years ago

It happens on my local machine with Docker, but also on Azure container instances. The thing is, it does not happen immediately. I have no repo that I can share at the moment. But using the plain image and PHP code I posted a few days back you should be able to reproduce the issue. Let the code run for an hour and you should get the error (at least, I get them).

diemol commented 3 years ago

But using the plain image and PHP code I posted a few days back you should be able to reproduce the issue.

This is a bit ambiguous, and I have never used the PHP bindings. So it'd be helpful to get something I can clone and run to reproduce this.

Let the code run for an hour and you should get the error (at least, I get them).

I do not understand what this means. What code should run for an hour?

Again, I am not familiar with the php bindings, but I am willing to troubleshoot this if I get a repo I can clone to reproduce the issue.

ghost commented 3 years ago

Ok. If I have some free time next week I can create a repo for you.

Reproducing aint really hard because it always happens within one hour of constantly doing something with the selenium grid. I use selenium for webscraping, so I'm getting these errors within one hour of webscraping. I hope this makes more sense of what I meant with "Let the code run for an hour".

ghost commented 3 years ago

@diemol I saw issue https://github.com/SeleniumHQ/docker-selenium/issues/1377 today. Used the latest version release 4.0.0-rc-1-20210902 and increased the connection and request timeout. Seems the scraper is running for over two hours without any issues. I'll monitor and keep you posted.

Tbh, I don't know which one did had any effect.

Edit: I still see the error I posted earlier with Driver info: driver.version: unknown, but the scraping process does not crash anymore. Earlier I kept getting Operation timed out after 30000 milliseconds with 0 bytes right after the Driver Info error.

diemol commented 3 years ago

@zipper11, if things are working better for you and no GitHub repo has been provided, I think I will close this issue for now.

If you bump into the issue and can provide a way to reproduce it, I'd be happy to reopen and troubleshoot.

github-actions[bot] commented 3 years ago

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.