[🐛 Bug]: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read:

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.98k stars 2.51k forks source link

[🐛 Bug]: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read: #1507

Closed mghantous closed 2 years ago

mghantous commented 2 years ago

What happened?

We have a python / django test suite that runs about 60 tests in serial against a standalone-chrome and also against standalone-firefox. Usually somewhere in the middle of the run, but varying on the specific test, we encounter an exception that is org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read:. The stack trace is almost identical for firefox and chrome other than the System Info (IP and host name), so I have attached one in the log output. The selenium python package and standalone images we use are both on the latest available tags (selenium==4.1.0 and 4.1.2-20220208 respectively).

Command used to start Selenium Grid with Docker

We start via docker-compose with standalone firefox and chrome images. The relevant compose sections:

  firefox:
    image: selenium/standalone-firefox:${SELENIUM_TAG:-4.1.2-20220208}
    shm_size: 2gb
    environment:
      - START_XVFB=${START_XVFB:-false}

  chrome:
    image: selenium/standalone-chrome:${SELENIUM_TAG:-4.1.2-20220208}
    shm_size: 2gb
    environment:
      - START_XVFB=${START_XVFB:-false}
      # Cannot bind to ipv6 on docker for linux. See https://stackoverflow.com/a/57328161/2112497
      - JAVA_OPTS=-Dwebdriver.chrome.whitelistedIps=

Relevant log output

org.openqa.selenium.json.JsonException: Unable to parse:
    at org.openqa.selenium.json.Json.toType(Json.java:57)
    at org.openqa.selenium.json.Json.toType(Json.java:50)
    at org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandler.java:113)
    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:72)
    at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
    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$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.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: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read:
Build info: version: '4.1.2', revision: '9a5a329c5a'
System info: host: 'ecba5910c3b1', ip: '172.18.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '5.4.0-97-generic', java.version: '11.0.13'
Driver info: driver.version: unknown
    at org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)
    at org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)
    at org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)
    at org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145)
    at org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)
    at org.openqa.selenium.json.Json.toType(Json.java:71)
    at org.openqa.selenium.json.Json.toType(Json.java:55)
    ... 35 more

Operating System

Ubuntu 20.04

Docker Selenium version (tag)

4.1.2-20220208

diemol commented 2 years ago

How can I reproduce the issue?

indrekj commented 2 years ago

We're encountering the same thing. I have no reliable way to reproduce it though.

indrekj commented 2 years ago

If it helps then this happens with 4.1.0 (and 4.1.2) for us as well:

15:55:14       Selenium::WebDriver::Error::UnknownError:
15:55:14         Expected to read a START_MAP but instead have: END. Last 0 characters read: 
15:55:14         Build info: version: '4.1.0', revision: 'aea69daa1c'
15:55:14         System info: host: 'beta-monitoring-dff87366-8287-4ca3-bcfd-092b2526c15d-4dzb-wsx0j', ip: '10.2.127.116', os.name: 'Linux', os.arch: 'amd64', os.version: '5.4.172-90.336.amzn2.x86_64', java.version: '11.0.11'
15:55:14         Driver info: driver.version: unknown

chinzzz commented 2 years ago

I also encountered the issue. Test runs fine in 20 to 25 threads but running on 30 threads (or more) will result to about 50% of the tests getting the mentioned error. The higher the number of threads, the higher the percentage of the error.

thkwalter commented 2 years ago

We also see this issue with selenium-server-4.1.2. The problem is not reproducible. But all failing tests have two things in common:

The client-side stacktrace shows the following lines (java bindings 4.1.2):

at org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51)
at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:558)
at org.openqa.selenium.remote.ElementLocation$ElementFinder$2.findElements(ElementLocation.java:179)
at org.openqa.selenium.remote.ElementLocation.findElements(ElementLocation.java:102)

Another warning is logged before and/or after the log message containing the server-side exception. This warning is logged for the same session id and contains the http status code 404:

eventName: HTTP request execution complete
attributes: 
    http.flavor: 1
    http.handler_class: org.openqa.selenium.remote.http.Route$PredicatedRoute
    http.host: xxx
    http.method: POST
    http.request_content_length: yyy
    http.scheme: HTTP
    http.status_code: 404
    http.target: \u002fsession\u002fada9755d04e47dc8938ea8008b214324\u002fexecute\u002fsync
    http.user_agent: selenium\u002f4.1.2 (java unix)

diemol commented 2 years ago

I've had a look at the comments but sadly I've got not clue on how to reproduce this. Is this still happening in 4.1.3?

mghantous commented 2 years ago

Yes, still happening on 4.1.3

chrome_1               | 2022-04-11T15:56:06.218687658Z 15:56:06.218 INFO [LocalDistributor.newSession] - Session created by the distributor. Id: 43e21e36cc481382130f3670adbf9b05, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 100.0.4896.75, chrome: {chromedriverVersion: 100.0.4896.60 (6a5d10861ce8..., userDataDir: /tmp/.com.google.Chrome.DDSm8a}, goog:chromeOptions: {debuggerAddress: localhost:37813}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:cdp: ws://172.18.0.4:4444/sessio..., se:cdpVersion: 100.0.4896.75, 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}
chrome_1               | 2022-04-11T15:56:28.730011666Z 15:56:28.729 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "571a4e5092c697880a6857b42316f3b8","eventTime": 1649692588724185395,"eventName": "exception","attributes": {"exception.message": "Unable to execute request for an existing session: Unable to parse: ","exception.stacktrace": "org.openqa.selenium.json.JsonException: Unable to parse: \n\tat org.openqa.selenium.json.Json.toType(Json.java:57)\n\tat org.openqa.selenium.json.Json.toType(Json.java:50)\n\tat org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandler.java:113)\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:72)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)\n\tat org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:121)\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$NestedRoute.handle(Route.java:270)\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.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: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read: \nBuild info: version: '4.1.3', revision: '7b1ebf28ef'\nSystem info: host: '83ee97fd6958', ip: '172.18.0.4', os.name: 'Linux', os.arch: 'amd64', os.version: '5.4.0-107-generic', java.version: '11.0.14.1'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)\n\tat org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)\n\tat org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)\n\tat org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145)\n\tat org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)\n\tat org.openqa.selenium.json.Json.toType(Json.java:71)\n\tat org.openqa.selenium.json.Json.toType(Json.java:55)\n\t... 35 more\n","exception.type": "org.openqa.selenium.json.JsonException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.router.HandleSession","http.host": "chrome:4444","http.method": "POST","http.request_content_length": "60","http.scheme": "HTTP","http.target": "\u002fsession\u002f43e21e36cc481382130f3670adbf9b05\u002felement","http.user_agent": "selenium\u002f4.1.3 (python linux)","session.id": "43e21e36cc481382130f3670adbf9b05"}}

Let me try to format that stack trace multi-line

  org.openqa.selenium.json.JsonException: Unable to parse: 
    at org.openqa.selenium.json.Json.toType(Json.java:57)
    at org.openqa.selenium.json.Json.toType(Json.java:50)
    at org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandler.java:113)
    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:72)
    at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
    at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:121)
    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$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.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: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read: 
Build info: version: '4.1.3', revision: '7b1ebf28ef'
System info: host: '83ee97fd6958', ip: '172.18.0.4', os.name: 'Linux', os.arch: 'amd64', os.version: '5.4.0-107-generic', java.version: '11.0.14.1'
Driver info: driver.version: unknown
    at org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)
    at org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)
    at org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)
    at org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145)
    at org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)
    at org.openqa.selenium.json.Json.toType(Json.java:71)
    at org.openqa.selenium.json.Json.toType(Json.java:55)
    ... 35 more

diemol commented 2 years ago

Sadly the stacktrace is not giving us enough information to reproduce it. Would it be possible to get some tests that reproduce this? It is completely ok if I need to run them a few times and for a while to get this happening.

chinzzz commented 2 years ago

Hi @diemol, just wondering if you tried this scenario: Available nodes = 30 Thread count = 40 (or any count as long as thread count > available nodes) This is one of the scenarios where I can consistently replicate the issue. The first batch seems to run properly but as the list in the queue grows, the error count grow as well.

diemol commented 2 years ago

@chinzzz can you share the commands you are using to start the Grid?

martenbohlin commented 2 years ago

Hi, I just want to report that we see the same issue with version 4.1.3. It fails on random places when running our suit of tests that takes ~1h to run but I have not been able to reproduce it with a simple example. Our tests run just fine on 3.141.59.

Is there any debugloggin or something like that we could enable in order to find the source of this issue?

diemol commented 2 years ago

@martenbohlin it'd be great to get a way to reproduce the issue.

You can also share the full logs by enabling debug level: SE_OPTS=--log-level FINE

tinez commented 2 years ago

Hi, we're suffering from the same problem in ovirt-system-tests. Sometimes it's a JsonException, sometimes a TimeoutException, sometimes the Expected to read a START_MAP... thingy.

I've tried 4.0.0, 4.1.2, 4.1.4 both in a grid setup and with standalone nodes - it doesn't seem to matter. What does seem to matter is that recently we've moved the selenium containers from a physical host to a more restricted VM (2 vcpus, 2048M RAM) and it started to fail much more often since then.

If that's any help, here are FINE logs from a standalone chrome container. The stack trace was:

Stacktrace:
java.lang.RuntimeException: Unable to execute request for an existing session: java.util.concurrent.TimeoutException
Build info: version: '4.0.0', revision: '3a21814679'
System info: host: 'aa9a96dc77c4', ip: '10.0.2.100', os.name: 'Linux', os.arch: 'amd64', os.version: '4.18.0-383.el8.x86_64', java.version: '11.0.11'
Driver info: driver.version: unknown
        at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:139)
        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)
        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:119)
        at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)
        at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
        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:388)
        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:72)
        at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
        at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:110)
        ... 22 more

I could describe a solution which would allow you to reproduce this, but it's definitely not trivial (i.e. you'd need a dedicated, physical host capable of doing virtualization).

Any help will be greatly appreciated, thanks!

amyreit commented 2 years ago

I get this same issue fairly frequently in a variety of locations in my code. To make it more simple - this is not a grid issue. I use the standalone firefox 4.1.2. I've seen the behavior since 4.0 and it has not improved. It's not something that is easily reproducible but it happens in our continuous test at least once a day. My stacks look like this -

Build info: version: '4.1.2', revision: '9a5a329c5a'
System info: host: 'ebcprh01886620-n.fyre.ibm.com', ip: '10.51.19.197', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-167-generic', java.version: '11.0.14.1'
Driver info: driver.version: RemoteWebDriver
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.createException(W3CHttpResponseCodec.java:200)
at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:133)
at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:53)
at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:184)
at org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51)
at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:558)
at org.openqa.selenium.remote.ElementLocation$ElementFinder$2.findElement(ElementLocation.java:162)
at org.openqa.selenium.remote.ElementLocation.findElement(ElementLocation.java:60)
at org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:382)
at org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:374)
at org.openqa.selenium.support.ui.ExpectedConditions$7.apply(ExpectedConditions.java:197)
at org.openqa.selenium.support.ui.ExpectedConditions$7.apply(ExpectedConditions.java:193)
at org.openqa.selenium.support.ui.FluentWait.until(FluentWait.java:208)

diemol commented 2 years ago

@tinez the log does not show the exception related to this issue. Do you have a log that shows that and ideally a way to reproduce it?

@amyreit is there a way you can share the complete logs?

Folks, if you just share the last piece of the log there is absolutely no way we can understand how the Grid got to that point.

cocorossello commented 2 years ago

I can also see this error in 4.1.4 happening always in each build, sadly I can't give a reproducer. The first suspicious log in the grid is:

07:09:50.435 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "9f4b393d2e704ff3437e305a5551cc65","eventTime": 1651993790435123807,"eventName": "exception","attributes": {"exception.message": "Unable to execute request for an existing session: Unable to parse: ","exc
eption.stacktrace": "org.openqa.selenium.json.JsonException: Unable to parse: \n\tat org.openqa.selenium.json.Json.toType(Json.java:57)\n\tat org.openqa.selenium.json.Json.toType(Json.java:50)\n\tat org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandle
r.java:113)\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.ex
ecute(CombinedHandler.java:59)\n\tat org.openqa.selenium.grid.web.RoutableHttpClientFactory$1.execute(RoutableHttpClientFactory.java:72)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)\n\tat org.openqa.selenium.grid.router.HandleSess
ion.execute(HandleSession.java:122)\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.selen
ium.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.seleni
um.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(ThreadPool
Executor.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: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have
: END. Last 0 characters read: \nBuild info: version: '4.1.4', revision: '535d840ee2'\nSystem info: host: '72e53d629620', ip: '172.19.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.0-1005-azure', java.version: '11.0.15'\nDriver info: driver.version: unknown\n\tat
org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)\n\tat org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)\n\tat org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)\n\tat org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoerce
r$6(JsonTypeCoercer.java:145)\n\tat org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)\n\tat org.openqa.selenium.json.Json.toType(Json.java:71)\n\tat org.openqa.selenium.json.Json.toType(Json.java:55)\n\t... 31 more\n","exception.type": "org.openqa.selen
ium.json.JsonException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.router.HandleSession","http.host": "development-selenium.travelc.internal:4444","http.method": "POST","http.request_content_length": "59","http.scheme": "HTTP","http.target": "\u002fsessio
n\u002f70f5920659faf12b7d09bcfd8d700bb6\u002felement","http.user_agent": "selenium\u002f4.1.3 (java unix)","session.id": "70f5920659faf12b7d09bcfd8d700bb6"}}

Right before this one I can see these logs:


07:09:49.435 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "9f1d03c7412156479a30552651341df0","eventTime": 1651993789434909509,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Ro
ute$PredicatedRoute","http.host": "development-selenium.travelc.internal:4444","http.method": "POST","http.request_content_length": "48780","http.scheme": "HTTP","http.status_code": 404,"http.target": "\u002fsession\u002f347e8607f391badc6c818044aed6b6a1\u002fexecute\u002fsync"
,"http.user_agent": "selenium\u002f4.1.3 (java unix)"}}

07:09:49.448 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "45ab6ed4b71210ef653e543e3b730be8","eventTime": 1651993789447925704,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Ro
ute$PredicatedRoute","http.host": "development-selenium.travelc.internal:4444","http.method": "GET","http.scheme": "HTTP","http.status_code": 404,"http.target": "\u002fsession\u002f347e8607f391badc6c818044aed6b6a1\u002felement\u002f3ee249c2-9a03-47d7-8eef-a97d1227d972\u002ftex
t","http.user_agent": "selenium\u002f4.1.3 (java unix)"}}

07:09:49.457 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "2c6e4c285ea6c97c4d42199adb8645bb","eventTime": 1651993789456438910,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Ro
ute$PredicatedRoute","http.host": "development-selenium.travelc.internal:4444","http.method": "GET","http.scheme": "HTTP","http.status_code": 404,"http.target": "\u002fsession\u002f347e8607f391badc6c818044aed6b6a1\u002felement\u002f3ee249c2-9a03-47d7-8eef-a97d1227d972\u002fnam
e","http.user_agent": "selenium\u002f4.1.3 (java unix)"}}

Logs from the client side are not really relevant, I can see that any command is affected... createSession, findElements...

tinez commented 2 years ago

@diemol Please see my repo for the updated stacktrace and standalone chrome logs.

As for the reproducibility - I had a ~85% success rate on my own server on Friday and today I got nothing... but we still see these issues in our CI infrastructure.

amyreit commented 2 years ago

It happens in many different places but here is one - trying to verify that icon is correct on the screen -

org.openqa.selenium.WebDriverException: Expected to read a START_MAP but instead have: END. Last 0 characters read: 
Build info: version: '4.1.2', revision: '9a5a329c5a'
System info: host: '2a897ed656a0', ip: '172.17.0.5', os.name: 'Linux', os.arch: 'amd64', os.version: '5.4.0-99-generic', java.version: '11.0.13'
Driver info: driver.version: unknown
Build info: version: '4.1.2', revision: '9a5a329c5a'
System info: host: 'ebcprh01886620-n.fyre.ibm.com', ip: '10.51.19.197', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-167-generic', java.version: '11.0.14.1'
Driver info: org.openqa.selenium.remote.RemoteWebDriver
Command: [d9fb091a-a96b-447f-ae30-9bc9fc2948d1, findElement {using=id, value=collectionView-applications-card-app3(clusterA)newCard-cardIcon}]
Capabilities {acceptInsecureCerts: true, browserName: firefox, browserVersion: 96.0.3, javascriptEnabled: true, moz:accessibilityChecks: false, moz:buildID: 20220126154723, moz:debuggerAddress: localhost:49647, moz:firefoxOptions: {}, moz:geckodriverVersion: 0.30.0, moz:headless: false, moz:processID: 158, moz:profile: /tmp/rust_mozprofileNEAdzb, moz:shutdownTimeout: 60000, moz:useNonSpecCompliantPointerOrigin: false, moz:webdriverClick: true, pageLoadStrategy: normal, platform: LINUX, platformName: LINUX, platformVersion: 5.4.0-99-generic, proxy: Proxy(), se:cdp: ws://172.17.0.5:4444/sessio..., se:cdpVersion: 85.0, se:vnc: ws://172.17.0.5:4444/sessio..., se:vncEnabled: true, se:vncLocalAddress: ws://172.17.0.5:7900, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify}
Session ID: d9fb091a-a96b-447f-ae30-9bc9fc2948d1
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
    at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.createException(W3CHttpResponseCodec.java:200)
    at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:133)
    at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:53)
    at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:184)
    at org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51)
    at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:558)
    at org.openqa.selenium.remote.ElementLocation$ElementFinder$2.findElement(ElementLocation.java:162)
    at org.openqa.selenium.remote.ElementLocation.findElement(ElementLocation.java:60)
    at org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:382)
    at org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:374)
    at org.openqa.selenium.support.ui.ExpectedConditions$7.apply(ExpectedConditions.java:197)
    at org.openqa.selenium.support.ui.ExpectedConditions$7.apply(ExpectedConditions.java:193)
    at org.openqa.selenium.support.ui.FluentWait.until(FluentWait.java:208)
    at com.ibm.ws.ui.fat.selenium.tests.AbstractUITest.waitForVisibilityOfElementLocatedBy(AbstractUITest.java:2134)
    at com.ibm.ws.ui.fat.selenium.tests.AbstractUITest.waitAndVerifyAttributeValueBy(AbstractUITest.java:2852)
    at com.ibm.ws.ui.fat.selenium.tests.AbstractUITest.waitAndVerifyAttributeValueBy(AbstractUITest.java:2806)
    at com.ibm.ws.ui.fat.selenium.tests.AbstractUITest.waitAndVerifyAttributeValueBy(AbstractUITest.java:2781)
    at com.ibm.ws.ui.fat.selenium.tests.AbstractUITest.waitAndVerifyAttributeValueById(AbstractUITest.java:2690)
    at com.ibm.ws.ui.fat.selenium.tests.AbstractUITest.waitAndVerifyAttributeValueById(AbstractUITest.java:2652)
    at com.ibm.ws.ui.fat.selenium.tests.AbstractUITest.verifySVG(AbstractUITest.java:3117)
    at com.ibm.ws.ui.fat.selenium.tests.explore.ExploreAbstractUITest.confirmAppCardInfo(ExploreAbstractUITest.java:1564)
    at com.ibm.ws.ui.tool.explore.fat.gui.nd.rw.tests.PartiallyRunningTest.appCardStarted(PartiallyRunningTest.java:239)
    at com.ibm.ws.ui.tool.explore.fat.gui.nd.rw.tests.PartiallyRunningTest.confirmAppCardData(PartiallyRunningTest.java:177)
    at com.ibm.ws.ui.tool.explore.fat.gui.nd.rw.tests.PartiallyRunningTest.appsResourceFilterTest(PartiallyRunningTest.java:121)
    at com.ibm.ws.ui.tool.explore.fat.gui.nd.rw.tests.PartiallyRunningTest.appsViewTest(PartiallyRunningTest.java:77)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47)
    at org.junit.rules.RunRules.evaluate(RunRules.java:18)
    at componenttest.custom.junit.runner.FATRunner$1.evaluate(FATRunner.java:197)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47)
    at org.junit.rules.RunRules.evaluate(RunRules.java:18)
    at componenttest.custom.junit.runner.FATRunner$2.evaluate(FATRunner.java:318)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
    at componenttest.custom.junit.runner.FATRunner.run(FATRunner.java:171)
    at org.junit.runners.Suite.runChild(Suite.java:128)
    at org.junit.runners.Suite.runChild(Suite.java:24)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:47)
    at org.junit.rules.RunRules.evaluate(RunRules.java:18)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
    at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
    at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:520)
    at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1060)
    at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:911)
[05/05/2022 15:01:44:969 PDT] 001 FATRunner                      evaluate                       I exiting com.ibm.ws.ui.tool.explore.fat.gui.nd.rw.tests.PartiallyRunningTest.appsViewTest

mschwehl commented 2 years ago

Maybe this helps, we run version 4.1.4 and have the start-map issue as well in the selenium-hub. I cannot reproduce

06:39:12.031 WARN [SpanWrappedHttpHandler.execute] - Unable to execute request: Expected to read a START_MAP but instead have: END. Last 0 characters read:

Tue, May 10 2022 8:39:12 am | Build info: version: '4.1.4', revision: '535d840ee2'
Tue, May 10 2022 8:39:12 am | System info: host: 'selenium-hub-99d55b447-v8zt4', ip: '10.42.4.114', os.name: 'Linux', os.arch: 'amd64', os.version: '4.1.12-124.57.1.el7uek.x86_64', java.version: '11.0.15'
Tue, May 10 2022 8:39:12 am | Driver info: driver.version: unknown
Tue, May 10 2022 8:39:12 am | org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read:
Tue, May 10 2022 8:39:12 am | Build info: version: '4.1.4', revision: '535d840ee2'
Tue, May 10 2022 8:39:12 am | System info: host: 'selenium-hub-99d55b447-v8zt4', ip: '10.42.4.114', os.name: 'Linux', os.arch: 'amd64', os.version: '4.1.12-124.57.1.el7uek.x86_64', java.version: '11.0.15'
Tue, May 10 2022 8:39:12 am | Driver info: driver.version: unknown
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.NewSessionPayload.getOss(NewSessionPayload.java:304)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.NewSessionPayload.<init>(NewSessionPayload.java:97)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.NewSessionPayload.create(NewSessionPayload.java:76)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.grid.data.SessionRequest.<init>(SessionRequest.java:65)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.grid.sessionqueue.NewSessionQueue.lambda$new$0(NewSessionQueue.java:66)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle(Route.java:192)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.grid.sessionqueue.NewSessionQueue.execute(NewSessionQueue.java:120)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:86)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.grid.router.Router.execute(Router.java:91)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.grid.web.EnsureSpecCompliantResponseHeaders.lambda$apply$0(EnsureSpecCompliantResponseHeaders.java:34)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Route.execute(Route.java:68)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)
Tue, May 10 2022 8:39:12 am | at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)
Tue, May 10 2022 8:39:12 am | at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Tue, May 10 2022 8:39:12 am | at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Tue, May 10 2022 8:39:12 am | at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Tue, May 10 2022 8:39:12 am | at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Tue, May 10 2022 8:39:12 am | at java.base/java.lang.Thread.run(Thread.java:829)
Tue, May 10 2022 8:39:12 am | 06:39:12.031 WARN [SeleniumSpanExporter$1.lambda$export$0] - {"traceId": "8a20faa1ef02d639f48c423710757d73","eventTime": 1652164752031002739,"eventName": "exception","attributes": {"exception.message": "Unable to execute request: Expected to read a START_MAP but instead have: END. Last 0 characters read: \nBuild info: version: '4.1.4', revision: '535d840ee2'\nSystem info: host: 'selenium-hub-99d55b447-v8zt4', ip: '10.42.4.114', os.name: 'Linux', os.arch: 'amd64', os.version: '4.1.12-124.57.1.el7uek.x86_64', java.version: '11.0.15'\nDriver info: driver.version: unknown","exception.stacktrace": "org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read: \nBuild info: version: '4.1.4', revision: '535d840ee2'\nSystem info: host: 'selenium-hub-99d55b447-v8zt4', ip: '10.42.4.114', os.name: 'Linux', os.arch: 'amd64', os.version: '4.1.12-124.57.1.el7uek.x86_64', java.version: '11.0.15'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)\n\tat org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)\n\tat org.openqa.selenium.remote.NewSessionPayload.getOss(NewSessionPayload.java:304)\n\tat org.openqa.selenium.remote.NewSessionPayload.\u003cinit>(NewSessionPayload.java:97)\n\tat org.openqa.selenium.remote.NewSessionPayload.create(NewSessionPayload.java:76)\n\tat org.openqa.selenium.grid.data.SessionRequest.\u003cinit>(SessionRequest.java:65)\n\tat org.openqa.selenium.grid.sessionqueue.NewSessionQueue.lambda$new$0(NewSessionQueue.java:66)\n\tat org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle(Route.java:192)\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.sessionqueue.NewSessionQueue.execute(NewSessionQueue.java:120)\n\tat org.openqa.selenium.remote.tracing.SpanWrappe
  | dHttpHandler.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.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)\n","exception.type": "org.openqa.selenium.json.JsonException","http.client_ip": "21.136.8.27","http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.sessionqueue.local.LocalNewSessionQueue","http.host": "selenium.bamf.intern","http.method": "POST","http.requ
  | est_content_length": "835","http.scheme": "HTTP","http.target": "\u002fsession","http.user_agent": "selenium\u002f3.141.5 (java unix)"}}
Tue, May 10 2022 8:39:12 am |  
Tue, May 10 2022 8:47:17 am | Trapped SIGTERM/SIGINT/x so shutting down supervisord...
Tue, May 10 2022 8:47:18 am | 2022-05-10 06:47:18,589 WARN received SIGTERM indicating exit request
Tue, May 10 2022 8:47:18 am | 2022-05-10 06:47:18,589 INFO waiting for selenium-grid-hub to die
Tue, May 10 2022 8:47:19 am | 2022-05-10 06:47:19,592 INFO stopped: selenium-grid-hub (terminated by SIGTERM)
Tue, May 10 2022 8:47:19 am | Shutdown complete

diemol commented 2 years ago

This exception is thrown when the data that needs to be processed does not come in a properly formed JSON object. Which could be because of sync issues in the test, or the capabilities are incorrect, many different reasons. In short, the exception is correct.

From the stacktraces shared, I see it happens:

At org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandler.java:113) because the contents of the request are empty.
Mostly when finding elements
One case in org.openqa.selenium.remote.NewSessionPayload.getOss(NewSessionPayload.java:304).

To continue the research, could you please share the test case where the exception happens? Even if it only happens every now and then.

kmcrawford commented 2 years ago

@diemol I also am having this same issue. The only way I can get my unresponsive grid back is to delete the router pod. Which is strange b/c the healthcheck should detect the unresponsive system and delete the pod.

diemol commented 2 years ago

@kmcrawford can you share the stacktrace, please?

osdamv commented 2 years ago

My 2 cents, currently I am working from home, My internet connection losses a lot of packets, this is just an issue for activities such as online gaming, video streaming is fine. Interestingly, looks like selenium grid is packages dropped sensitive. since I run test executions from my home, Selenium grid complains a lot about this, however from my company offices everything works fine.

My recommendation, check from where you are executing your tests, try to avoid ssh proxies, the executing program should be in the same data center ideally

As how to replicate, I think it should be possible simulating this problem: https://stackoverflow.com/questions/614795/simulate-delayed-and-dropped-packets-on-linux

KupchinskiyVasiliy commented 2 years ago

We are experience the same problem when running tests in multiple parallel threads. Were able to reproduce with 4.0.0 and with the latest version - 4.1.4

We attempted to fix problem ourselves, below are results of our research (we used 4.0.0):

Removed single threaded executor: https://github.com/SeleniumHQ/selenium/blob/trunk/java/src/org/openqa/selenium/netty/server/RequestConverter.java#L63 (I found that this is bottleneck in case when Netty configured to have multiple worker threads)
Use FileBackedOutputStream instead of PipedInputStream/PipedOutputStream (not sure that this is affected on target result).
Call ctx.fireChannelRead only after receive LastHttpContent instance.

These changes reduced START_MAP errors to less than 20 out of 1700 tests from 100-200 with out of the box implementation.

4.0.0 based patch is attached at https://gist.github.com/KupchinskiyVasiliy/af89e0fdf77fe06040708a3a3034bbf5

cocorossello commented 2 years ago

Just tested with latest version 4.2.2-20220609 and I still can see the same error.

In client side:

org.openqa.selenium.SessionNotCreatedException: Could not start a new session. Response code 500. Message: Expected to read a START_MAP but instead have: END. Last 0 characters read: 
Build info: version: '4.2.2', revision: '683ccb65d6'
System info: host: '2a3b30186f59', ip: '172.19.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.0-1010-azure', java.version: '11.0.15'
Driver info: driver.version: unknown
Build info: version: '4.2.2', revision: '683ccb65d6'
System info: host: '515f0eef1232', ip: '172.20.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.0-1005-azure', java.version: '18.0.1'
Driver info: com.tr2.test.endtoend.selenium.base.IgnoreFirstConnectExceptionRemoteWebDriver
Command: [null, newSession {capabilities=[Capabilities {browserName: chrome, goog:chromeOptions: {args: [--window-size=1280,1280, --user-agent='Mozilla/5.0 (..., --disable-translate, --disable-extensions, --disable-background-networ..., --safebrowsing-disable-auto..., --disable-sync, --metrics-recording-only, --disable-default-apps, autoplay-policy=no-user-ges..., --disable-notifications, --disable-permissions-api, --ignore-certificate-errors, --force-prefers-reduced-motion, --headless, --headless, --use-gl=swiftshader, --disable-background-networ..., --disable-background-timer-..., --disable-backgrounding-occ..., --disable-breakpad, --disable-client-side-phish..., --disable-component-extensi..., --disable-default-apps, --disable-features=TranslateUI, --disable-hang-monitor, --disable-ipc-flooding-prot..., --disable-popup-blocking, --disable-prompt-on-repost, --disable-renderer-backgrou..., --disable-sync, --force-color-profile=srgb, --metrics-recording-only, --no-first-run, --password-store=basic, --use-mock-keychain, --hide-scrollbars, --mute-audio, --blink-settings=imagesEnab...], excludeSwitches: [enable-automation, load-extension], extensions: [], prefs: {intl.accept_languages: en-US,en,es}}, goog:loggingPrefs: org.openqa.selenium.logging...}], desiredCapabilities=Capabilities {browserName: chrome, goog:chromeOptions: {args: [--window-size=1280,1280, --user-agent='Mozilla/5.0 (..., --disable-translate, --disable-extensions, --disable-background-networ..., --safebrowsing-disable-auto..., --disable-sync, --metrics-recording-only, --disable-default-apps, autoplay-policy=no-user-ges..., --disable-notifications, --disable-permissions-api, --ignore-certificate-errors, --force-prefers-reduced-motion, --headless, --headless, --use-gl=swiftshader, --disable-background-networ..., --disable-background-timer-..., --disable-backgrounding-occ..., --disable-breakpad, --disable-client-side-phish..., --disable-component-extensi..., --disable-default-apps, --disable-features=TranslateUI, --disable-hang-monitor, --disable-ipc-flooding-prot..., --disable-popup-blocking, --disable-prompt-on-repost, --disable-renderer-backgrou..., --disable-sync, --force-color-profile=srgb, --metrics-recording-only, --no-first-run, --password-store=basic, --use-mock-keychain, --hide-scrollbars, --mute-audio, --blink-settings=imagesEnab...], excludeSwitches: [enable-automation, load-extension], extensions: [], prefs: {intl.accept_languages: en-US,en,es}}, goog:loggingPrefs: org.openqa.selenium.logging...}}]
Capabilities {}
    at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:144)
    at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:102)
    at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:67)
    at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:156)
    at org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51)
    at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:588)
    at com.tr2.test.endtoend.selenium.base.IgnoreFirstConnectExceptionRemoteWebDriver.execute(IgnoreFirstConnectExceptionRemoteWebDriver.java:28)
    at org.openqa.selenium.remote.RemoteWebDriver.startSession(RemoteWebDriver.java:283)

In the docker container side:

15:41:06.473 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "c44b03b8398aa79eafc38fff9a4e8a9d","eventTime": 1655134866473410678,"eventName": "exception","attributes": {"exception.message": "Unable to execute request for an existing session: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed","exception.stacktrace": "java.io.UncheckedIOException: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:73)\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:49)\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:98)\n\tat org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)\n\tat org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)\n\tat org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:125)\n\tat org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:447)\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:72)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)\n\tat org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:122)\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$NestedRoute.handle(Route.java:270)\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.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: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed\n\tat org.asynchttpclient.exception.RemotelyClosedException.INSTANCE(Unknown Source)\n","exception.type": "java.io.UncheckedIOException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.router.HandleSession","http.host": "selenium-spot.travelc.internal:4444","http.method": "POST","http.request_content_length": "68","http.scheme": "HTTP","http.target": "\u002fsession\u002fd8778d3279f1c53db071e5c39f86736e\u002fexecute\u002fsync","http.user_agent": "selenium\u002f4.2.2 (java unix)","session.id": "d8778d3279f1c53db071e5c39f86736e"}}

15:41:06.482 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local Session Map, Id: d8778d3279f1c53db071e5c39f86736e
15:41:06.483 INFO [GridModel.release] - Releasing slot for session id d8778d3279f1c53db071e5c39f86736e
15:41:06.483 INFO [SessionSlot.stop] - Stopping session d8778d3279f1c53db071e5c39f86736e
15:41:06.586 WARN [SpanWrappedHttpHandler.execute] - Unable to execute request: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed
java.io.UncheckedIOException: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed
        at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:73)
        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:49)
        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:98)
        at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)
        at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
        at org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)
        at org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:125)
        at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:447)
        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:72)
        at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
        at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:122)
        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$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.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: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed
        at org.asynchttpclient.exception.RemotelyClosedException.INSTANCE(Unknown Source)
15:41:06.586 WARN [SeleniumSpanExporter$1.lambda$export$1] - Unable to execute request: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed

awaterme commented 2 years ago

We have the same issue, selenium 4.2.2.

Could this be concurrency related maybe due to timeouts and waits? Although being discouraged we are using both, implicit and explicit waits. Additionally we are initializing firefox driver with this capabilities:

FirefoxOptions opt = new FirefoxOptions();
Map<String, Integer> timeouts = new HashMap<>();
timeouts.put("implicit", 3 * 1000);
opt.setCapability("timeouts", timeouts);

sl45sms commented 2 years ago

I've got the same error randomly on the same line, however. print(column.find_element(By.TAG_NAME,'span').text, end=',')

So by add a little delay under the above line (time.sleep(0.1)) seems to works for me.... I don't know if I'm just lucky, but I was able to finish the scrap.

Traceback (most recent call last):
  File "/usr/src/app/./scraper.py", line 37, in <module>
    print(column.find_element(By.TAG_NAME,'span').text, end=',')
  File "/usr/local/lib/python3.10/site-packages/selenium/webdriver/remote/webelement.py", line 419, in find_element
    return self._execute(Command.FIND_CHILD_ELEMENT,
  File "/usr/local/lib/python3.10/site-packages/selenium/webdriver/remote/webelement.py", line 396, in _execute
    return self._parent.execute(command, params)
  File "/usr/local/lib/python3.10/site-packages/selenium/webdriver/remote/webdriver.py", line 435, in execute
    self.error_handler.check_response(response)
  File "/usr/local/lib/python3.10/site-packages/selenium/webdriver/remote/errorhandler.py", line 247, in check_response
    raise exception_class(message, screen, stacktrace)
selenium.common.exceptions.WebDriverException: Message: Expected to read a START_MAP but instead have: END. Last 0 characters read: 
Build info: version: '4.3.0', revision: 'a4995e2c09*'
System info: host: '0347ee78d194', ip: '172.17.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '5.4.0-104-generic', java.version: '11.0.15'
Driver info: driver.version: unknown
Stacktrace:
org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read: 
Build info: version: '4.3.0', revision: 'a4995e2c09*'
System info: host: '0347ee78d194', ip: '172.17.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '5.4.0-104-generic', java.version: '11.0.15'
Driver info: driver.version: unknown
        at org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)
        at org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)
        at org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)
        at org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145)
        at org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)
        at org.openqa.selenium.json.Json.toType(Json.java:71)
        at org.openqa.selenium.json.Json.toType(Json.java:55)
        at org.openqa.selenium.json.Json.toType(Json.java:50)
        at org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandler.java:113)
        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:72)
        at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
        at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:122)
        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$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.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)

AndreasPetersen commented 2 years ago

Getting this with 4.4.0. We're running 12 tests concurrently against Selenium Grid (4.4.0-20220812). Two of the tests received this error.

Client error:

Caused by: org.openqa.selenium.json.JsonException: Unable to parse: 400 Bad Request
    at app//org.openqa.selenium.json.Json.toType(Json.java:57)
    at app//org.openqa.selenium.json.Json.toType(Json.java:50)
    at app//org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:99)
    at app//org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:53)
    at app//org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:184)
    at app//org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51)
    at app//org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:547)
    at app//org.openqa.selenium.remote.RemoteWebElement.execute(RemoteWebElement.java:257)
    at app//org.openqa.selenium.remote.RemoteWebElement.getRect(RemoteWebElement.java:349)
    at app//dk.b.w.selenium.core.WebCore.waitForElementToStopMoving(WebCore.java:477)
    at app//dk.b.w.selenium.core.WebCore.waitForElementToStopMoving(WebCore.java:467)
    at app//dk.b.w.selenium.core.WebCore.waitForElementToStopMoving(WebCore.java:462)
    at app//dk.b.w.selenium.r.rc.clickMainAddButton(rc.java:478)
    at app//dk.b.w.selenium.r.v.initAddItem(v.java:123)
    at app//dk.b.w.selenium.r.v.addAccount(v.java:49)
    at app//dk.b.w.selenium.r.v.addOwnAccount(v.java:33)
    at app//dk.b.w.selenium.e2e.AdvisoryDraftTest.advisorCannotManipulateWhenNoBankConsent(AdvisoryDraftTest.java:407)
    at java.base@11.0.11/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base@11.0.11/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base@11.0.11/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base@11.0.11/java.lang.reflect.Method.invoke(Method.java:566)
    at app//org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:725)
    at app//org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at app//org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
    at app//org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
    at app//org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
    at app//org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
    at app//org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at app//org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
    at app//org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
    at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:214)
    ... 34 more
Caused by: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: NUMBER. Last 0 characters read: 
Build info: version: '4.4.0', revision: 'e5c75ed026a'
System info: host: 'jdk11-builder-2z9nn-5b6km', ip: '10.13.128.23', os.name: 'Linux', os.arch: 'amd64', os.version: '3.10.0-1160.71.1.el7.x86_64', java.version: '11.0.11'
Driver info: driver.version: RemoteWebDriver
    at app//org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)
    at app//org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)
    at app//org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)
    at app//org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145)
    at app//org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)
    at app//org.openqa.selenium.json.Json.toType(Json.java:71)
    at app//org.openqa.selenium.json.Json.toType(Json.java:55)
    ... 69 more

I have the following error on a Selenium Chrome Node on Selenium Grid:

07:01:06.085 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "4da48901e33452daa28a9d3ac17243f0","eventTime": 1662361266082704089,"eventName": "exception","attributes": {"exception.message": "Unable to execute request: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed","exception.stacktrace": "java.io.UncheckedIOException: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:73)\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:49)\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:98)\n\tat org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)\n\tat org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)\n\tat org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:125)\n\tat org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:448)\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.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: org.asynchttpclient.exception.RemotelyClosedException: Remotely closed\n\tat org.asynchttpclient.exception.RemotelyClosedException.INSTANCE(Unknown Source)\n","exception.type": "java.io.UncheckedIOException","http.client_ip": "10.197.103.126","http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "selenium-hub-wea-staging.apps.c02u.paastools.bdunet.dk","http.method": "POST","http.request_content_length": "50","http.scheme": "HTTP","http.target": "\u002fsession\u002f673c880280f4448821cb7e2f6c01a74b\u002felement\u002f92cbbcde-5e60-4d5b-860a-e3c05cdbfb33\u002fclick","http.user_agent": "selenium\u002f4.4.0 (java unix)"}}

awaterme commented 2 years ago

Same problem here, with selenium 4.4.0, running as standalone server in combination with firefox. Log file with some context: selenium.log

efranken commented 2 years ago

I was just able to reproduce this twice by having no nodes connected, passing in tests to make a queue, then adding a node after a few minutes. Failures with the error in the title occur, and the node that launches immediately gets a blank browser that just sits at the address "Data:," if in chrome.

In the wild, this occurs during a test run that hits a queue. There will be multiple browsers that hang, open to the address of "Data;." (if Chrome) and tests will fail with org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read:. The test will report failed, but the node will hang at the "Data:," address for about 10 minutes if running chrome. If firefox, same thing, just a blank browser. It seems each test coming out of the queue will hang like this, meaning less nodes are available as more come in and enter the hung state.

We previously ran Selenium 3 without this issue, however if a test was in the queue too long it would simply fail with "Failed all retries to get a browser session".

The setup is a fully distributed model (router, distributor with event bus, session map, session queue) on different VMs. The nodes are effectively ran as provided by docker-selenium, however each one has Chrome+Edge+Firefox. Autoscaling is used to scale the number of nodes. Nodes and each grid component are on v4.4.0.

I'm wondering if this is a case of:

no nodes available
test is sent to router
node request for test goes queue
because no nodes are available, eventually test times out and marks itself as failed
request remains in queue, eventually node becomes available
node request takes a browser, but does not receive any instruction as test has already failed

Curious if anyone shares a similar deployment or can reproduce the issue in the same way.

vinoth959 commented 2 years ago

I face the same issue too..

Selenium 4.4.0 with both chrome 106 version on selenium grid 4.4.0 hosted on windows server..

2022-10-05 09:36:10:010 [ERROR] Thread18 :org.openqa.selenium.json.JsonException: Unable to parse: 400 Bad Request at org.openqa.selenium.json.Json.toType(Json.java:57) at org.openqa.selenium.json.Json.toType(Json.java:50) at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:99) at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:53) at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:184) at org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51) at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:547) at org.openqa.selenium.remote.RemoteWebElement.execute(RemoteWebElement.java:257) at org.openqa.selenium.remote.RemoteWebElement.isDisplayed(RemoteWebElement.java:313) at org.openqa.selenium.support.ui.ExpectedConditions.elementIfVisible(ExpectedConditions.java:307) at org.openqa.selenium.support.ui.ExpectedConditions.access$000(ExpectedConditions.java:40) at org.openqa.selenium.support.ui.ExpectedConditions$10.apply(ExpectedConditions.java:293) at org.openqa.selenium.support.ui.ExpectedConditions$10.apply(ExpectedConditions.java:290) at org.openqa.selenium.support.ui.FluentWait.until(FluentWait.java:208) at com.Helper.ObjectLoader.waitForElementToBeVisible(ObjectLoader.java:225) at com.Helper.ObjectLoader.LoadObject(ObjectLoader.java:485) at BDD.POMClass.ACMP.ClinicalReview.navigateToClinicalReviewTabandSetStatus(ClinicalReview.java:462) at BDD.StepDefinitions.ACMP.ACMPLogin.ApprovePX(ACMPLogin.java:141) at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at io.cucumber.java.Invoker.doInvoke(Invoker.java:66) at io.cucumber.java.Invoker.invokeStatic(Invoker.java:80) at io.cucumber.java.AbstractGlueDefinition.invokeMethod(AbstractGlueDefinition.java:45) at io.cucumber.java.JavaStepDefinition.execute(JavaStepDefinition.java:29) at io.cucumber.core.runner.CoreStepDefinition.execute(CoreStepDefinition.java:66) at io.cucumber.core.runner.PickleStepDefinitionMatch.runStep(PickleStepDefinitionMatch.java:63) at io.cucumber.core.runner.ExecutionMode$1.execute(ExecutionMode.java:10) at io.cucumber.core.runner.TestStep.executeStep(TestStep.java:92) at io.cucumber.core.runner.TestStep.run(TestStep.java:64) at io.cucumber.core.runner.PickleStepTestStep.run(PickleStepTestStep.java:51) at io.cucumber.core.runner.TestCase.run(TestCase.java:104) at io.cucumber.core.runner.Runner.runPickle(Runner.java:73) at io.cucumber.core.runtime.Runtime.lambda$execute$5(Runtime.java:110) at io.cucumber.core.runtime.Runtime$$Lambda$410/204775627.accept(Unknown Source) at io.cucumber.core.runtime.CucumberExecutionContext.runTestCase(CucumberExecutionContext.java:117) at io.cucumber.core.runtime.Runtime.lambda$execute$6(Runtime.java:110) at io.cucumber.core.runtime.Runtime$$Lambda$409/1328984436.run(Unknown Source) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at io.cucumber.core.runtime.Runtime$SameThreadExecutorService.execute(Runtime.java:233) at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112) at io.cucumber.core.runtime.Runtime.lambda$run$2(Runtime.java:86) at io.cucumber.core.runtime.Runtime$$Lambda$408/348365146.apply(Unknown Source) at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) at java.util.stream.SliceOps$1$1.accept(SliceOps.java:204) at java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1351) at java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:126) at java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:529) at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:516) at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:502) at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499) at io.cucumber.core.runtime.Runtime.run(Runtime.java:87) at io.cucumber.core.cli.Main.run(Main.java:92) at com.TestRunner.CucumberRunner.CucumberRun(CucumberRunner.java:67) at com.TestRunner.CucumberRunner.run(CucumberRunner.java:174) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: NUMBER. Last 0 characters read: Build info: version: '4.4.0', revision: 'e5c75ed026a' System info: host: '----------------', ip: '----------------', os.name: 'Windows 8.1', os.arch: 'amd64', os.version: '6.3', java.version: '1.8.0_45' Driver info: driver.version: RemoteWebDriver at org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307) at org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229) at org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64) at org.openqa.selenium.json.MapCoercer$$Lambda$685/1648702237.apply(Unknown Source) at org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145) at org.openqa.selenium.json.JsonTypeCoercer$$Lambda$687/1371348507.apply(Unknown Source) at org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127) at org.openqa.selenium.json.Json.toType(Json.java:71) at org.openqa.selenium.json.Json.toType(Json.java:55) ... 60 more

vinoth959 commented 2 years ago

Logs from Node:

09:36:09.719 INFO [ProxyNodeWebsockets.createWsEndPoint] - Establishing connection to ws://localhost:33749/devtools/browser/c283fd24-4dc4-4d0f-9329-5da67dee047d 09:36:12.343 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "4baa280bae40ef8acc42fa9c7334bced","eventTime": 1664976972343035702,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "-----------:----","http.method": "POST","http.request_content_length": "61","http.scheme": "HTTP","http.status_code": 500,"http.target": "\u002fsession\u002f09e2b1de528e58292a8bc919102060d1\u002fexecute\u002fsync","http.user_agent": "selenium\u002f4.4.0 (java windows)"}}

09:36:12.578 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "8c6bd393577ae4dbbcf940f3d74cebe2","eventTime": 1664976972577039372,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "-----------:----","http.method": "GET","http.scheme": "HTTP","http.status_code": 404,"http.target": "\u002fsession\u002f0df347dc37dcfcfaacfa67cb4628420c\u002falert\u002ftext","http.user_agent": "selenium\u002f4.4.0 (java windows)"}}

09:36:12.695 INFO [SessionSlot.stop] - Stopping session 268eac0def291fffae80884932e32924 09:36:12.968 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "6c661bfdb2250034ba45fe03d74f9aac","eventTime": 1664976972967474081,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "-----------:----","http.method": "POST","http.request_content_length": "61","http.scheme": "HTTP","http.status_code": 500,"http.target": "\u002fsession\u002f6e86e37c0e5a4c77556f63ce084a21b2\u002fexecute\u002fsync","http.user_agent": "selenium\u002f4.4.0 (java windows)"}}

09:36:13.016 INFO [SessionSlot.stop] - Stopping session dd63a93ea6f4d646304379a77eac2060 09:36:13.101 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "ccb6c1dc5ef66fd3f4ae58c5f4b354ae","eventTime": 1664976973100850941,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "-----------:----","http.method": "GET","http.scheme": "HTTP","http.status_code": 404,"http.target": "\u002fsession\u002f0df347dc37dcfcfaacfa67cb4628420c\u002falert\u002ftext","http.user_agent": "selenium\u002f4.4.0 (java windows)"}}

09:36:13.715 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "c95745749ebfbbfd89af87e5682d359c","eventTime": 1664976973714861907,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "-----------:----","http.method": "GET","http.scheme": "HTTP","http.status_code": 404,"http.target": "\u002fsession\u002f0df347dc37dcfcfaacfa67cb4628420c\u002falert\u002ftext","http.user_agent": "selenium\u002f4.4.0 (java windows)"}}

09:36:15.367 WARN [SpanWrappedHttpHandler.execute] - Unable to execute request: java.net.ConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 java.io.UncheckedIOException: java.net.ConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:73) 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:49) 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:98) at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55) at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92) at org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75) at org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:125) at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:448) 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.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:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.ConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 at org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:179) at org.asynchttpclient.netty.channel.NettyChannelConnector$1.onFailure(NettyChannelConnector.java:108) at org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:28) at org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:20) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609) at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:321) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:337) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:710) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ... 1 more Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 Caused by: java.net.ConnectException: Connection refused: no further information at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:716) at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:710) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748) 09:36:15.367 WARN [SeleniumSpanExporter$1.lambda$export$1] - Unable to execute request: java.net.ConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 09:36:15.367 WARN [SeleniumSpanExporter$1.lambda$export$1] - java.io.UncheckedIOException: java.net.ConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:73) 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:49) 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:98) at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55) at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92) at org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75) at org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:125) at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:448) 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.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:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.ConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 at org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:179) at org.asynchttpclient.netty.channel.NettyChannelConnector$1.onFailure(NettyChannelConnector.java:108) at org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:28) at org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:20) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609) at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:321) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:337) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:710) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ... 1 more Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: no further information: localhost/0:0:0:0:0:0:0:1:59130 Caused by: java.net.ConnectException: Connection refused: no further information at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:716) at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:710) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748)

09:36:15.369 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "b77b3f13142ac2e83f2fc16f28093e21","eventTime": 1664976975362384703,"eventName": "exception","attributes": {"exception.message": "Unable to execute request: java.net.ConnectException: Connection refused: no further information: localhost\u002f0:0:0:0:0:0:0:1:59130","exception.stacktrace": "java.io.UncheckedIOException: java.net.ConnectException: Connection refused: no further information: localhost\u002f0:0:0:0:0:0:0:1:59130\r\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:73)\r\n\tat org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)\r\n\tat org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)\r\n\tat org.openqa.selenium.remote.http.netty.NettyHttpHandler.execute(NettyHttpHandler.java:49)\r\n\tat org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)\r\n\tat org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:56)\r\n\tat org.openqa.selenium.remote.http.netty.NettyClient.execute(NettyClient.java:98)\r\n\tat org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:55)\r\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)\r\n\tat org.openqa.selenium.grid.node.ProtocolConvertingSession.execute(ProtocolConvertingSession.java:75)\r\n\tat org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:125)\r\n\tat org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:448)\r\n\tat org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)\r\n\tat org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:373)\r\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\r\n\tat org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:86)\r\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\r\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\r\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\r\n\tat org.openqa.selenium.grid.node.Node.execute(Node.java:240)\r\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:336)\r\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:68)\r\n\tat org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)\r\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\r\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\r\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\r\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:64)\r\n\tat org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)\r\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\r\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\r\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\r\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\r\n\tat java.lang.Thread.run(Thread.java:748)\r\nCaused by: java.net.ConnectException: Connection refused: no further information: localhost\u002f0:0:0:0:0:0:0:1:59130\r\n\tat org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:179)\r\n\tat org.asynchttpclient.netty.channel.NettyChannelConnector$1.onFailure(NettyChannelConnector.java:108)\r\n\tat org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:28)\r\n\tat org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:20)\r\n\tat io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)\r\n\tat io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571)\r\n\tat io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550)\r\n\tat io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)\r\n\tat io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)\r\n\tat io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609)\r\n\tat io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117)\r\n\tat io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:321)\r\n\tat io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:337)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:710)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)\r\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)\r\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\r\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\r\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\r\n\t... 1 more\r\nCaused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: no further information: localhost\u002f0:0:0:0:0:0:0:1:59130\r\nCaused by: java.net.ConnectException: Connection refused: no further information\r\n\tat sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)\r\n\tat sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:716)\r\n\tat io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337)\r\n\tat io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:710)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)\r\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)\r\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\r\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\r\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\r\n\tat java.lang.Thread.run(Thread.java:748)\r\n","exception.type": "java.io.UncheckedIOException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "-----------:----","http.method": "POST","http.request_content_length": "48780","http.scheme": "HTTP","http.target": "\u002fsession\u002fde9ebab3d386bea45b232ceb05654915\u002fexecute\u002fsync","http.user_agent": "selenium\u002f4.4.0 (java windows)"}}

andrewnicols commented 2 years ago

I've just seen this on a selenium/standalone-chrome:latest image with chrome 106.

I don't have any more logging yet, but I've just configured one of our test instance jobs to run with SE_OPTS set to loge at level fine. I'll kick off some more jobs and see if I can reproduce. This will take a number of hours per job and will generate some pretty extensive log files so I'll see if I can identify the problem area once I get a failure.

andrewnicols commented 2 years ago

Well that didn't take long. I deliberately under-resourced a job and hit this pretty quickly, but no real additional information that I can see. Here's the entire log excerpt from the start of the node, until the failed test:

jenkins@worker13:~$ docker logs -f selenium5455fee0bd02f3d65
2022-10-28 14:03:23,317 INFO Included extra file "/etc/supervisor/conf.d/selenium.conf" during parsing
2022-10-28 14:03:23,319 INFO RPC interface 'supervisor' initialized
2022-10-28 14:03:23,319 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2022-10-28 14:03:23,320 INFO supervisord started with pid 8
2022-10-28 14:03:24,322 INFO spawned: 'xvfb' with pid 10
2022-10-28 14:03:24,324 INFO spawned: 'vnc' with pid 11
2022-10-28 14:03:24,325 INFO spawned: 'novnc' with pid 12
2022-10-28 14:03:24,327 INFO spawned: 'selenium-standalone' with pid 13
Setting up SE_NODE_GRID_URL...
2022-10-28 14:03:24,335 INFO success: xvfb entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2022-10-28 14:03:24,335 INFO success: vnc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2022-10-28 14:03:24,335 INFO success: novnc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2022-10-28 14:03:24,335 INFO success: selenium-standalone entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Selenium Grid Standalone configuration:
[network]
relax-checks = true

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

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

Starting Selenium Grid Standalone...
14:03:25.012 INFO [LoggingOptions.configureLogEncoding] - Using the system default encoding
14:03:25.020 INFO [OpenTelemetryTracer.createTracer] - Using OpenTelemetry for tracing
14:03:25.966 INFO [NodeOptions.getSessionFactories] - Detected 12 available processors
14:03:26.033 INFO [NodeOptions.report] - Adding chrome for {"browserVersion": "106.0","se:noVncPort": 7900,"browserName": "chrome","platformName": "LINUX","se:vncEnabled": true} 1 times
14:03:26.049 INFO [Node.<init>] - Binding additional locator mechanisms: name, relative, id
14:03:26.089 INFO [GridModel.setAvailability] - Switching Node 7497e6c9-cd86-4628-b136-dee5682c68ce (uri: http://172.23.0.14:4444) from DOWN to UP
14:03:26.090 INFO [LocalDistributor.add] - Added node 7497e6c9-cd86-4628-b136-dee5682c68ce at http://172.23.0.14:4444. Health check every 120s
14:03:26.254 INFO [Standalone.execute] - Started Selenium Standalone 4.5.3 (revision 4b786a1e430): http://172.23.0.14:4444
14:05:33.510 INFO [LocalDistributor.newSession] - Session request received by the Distributor:
 [Capabilities {browserName: chrome, chromeOptions: {args: [disable-web-security, headless, no-gpu, no-sandbox, unlimited-storage]}, platform: ANY}, Capabilities {browserName: chrome, goog:chromeOptions: {args: [disable-web-security, headless, no-gpu, no-sandbox, unlimited-storage]}}]
Starting ChromeDriver 106.0.5249.61 (511755355844955cd3e264779baf0dd38212a4d0-refs/branch-heads/5249@{#569}) on port 3933
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully.
[1666965933.637][SEVERE]: bind() failed: Cannot assign requested address (99)
14:05:34.600 WARN [ProtocolHandshake.createSession] - Support for Legacy Capabilities is deprecated; You are sending the following invalid capabilities: [chromeOptions, platform]; Please update to W3C Syntax: https://www.selenium.dev/blog/2022/legacy-protocol-support/
14:05:34.655 INFO [LocalNode.newSession] - Session created by the Node. Id: 263510a41e4f79c41db3f9cfe09657e4, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 106.0.5249.119, chrome: {chromedriverVersion: 106.0.5249.61 (511755355844..., userDataDir: /tmp/.com.google.Chrome.I41vH8}, goog:chromeOptions: {debuggerAddress: localhost:33817}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: ANY, proxy: Proxy(), se:cdp: http://localhost:33817, se:cdpVersion: 106.0.5249.119, se:vncEnabled: true, se:vncLocalAddress: ws://172.23.0.14: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:virtualAuthenticators: true}
14:05:34.668 INFO [LocalDistributor.newSession] - Session created by the Distributor. Id: 263510a41e4f79c41db3f9cfe09657e4
 Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 106.0.5249.119, chrome: {chromedriverVersion: 106.0.5249.61 (511755355844..., userDataDir: /tmp/.com.google.Chrome.I41vH8}, chromeOptions: {args: [disable-web-security, headless, no-gpu, no-sandbox, unlimited-storage]}, goog:chromeOptions: {debuggerAddress: localhost:33817}, networkConnectionEnabled: false, pageLoadStrategy: normal, platform: ANY, platformName: ANY, proxy: Proxy(), se:bidiEnabled: false, se:cdp: ws://172.23.0.14:4444/sessi..., se:cdpVersion: 106.0.5249.119, se:vnc: ws://172.23.0.14:4444/sessi..., se:vncEnabled: true, se:vncLocalAddress: ws://172.23.0.14: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:virtualAuthenticators: true}
14:05:49.800 WARN [SeleniumSpanExporter$1.lambda$export$1] - Unable to execute request for an existing session: Unable to parse:
14:05:49.801 WARN [SeleniumSpanExporter$1.lambda$export$1] - org.openqa.selenium.json.JsonException: Unable to parse:
    at org.openqa.selenium.json.Json.toType(Json.java:57)
    at org.openqa.selenium.json.Json.toType(Json.java:50)
    at org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandler.java:119)
    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:72)
    at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)
    at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:122)
    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$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.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: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read:
Build info: version: '4.5.3', revision: '4b786a1e430'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.0-48-generic', java.version: '11.0.16'
Driver info: driver.version: unknown
    at org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)
    at org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)
    at org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)
    at org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145)
    at org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)
    at org.openqa.selenium.json.Json.toType(Json.java:71)
    at org.openqa.selenium.json.Json.toType(Json.java:55)
    ... 35 more

14:05:49.801 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "d7cdfaf4741ae99709b779936a06243d","eventTime": 1666965949800072784,"eventName": "exception","attributes": {"exception.message": "Unable to execute request for an existing session: Unable to parse: ","exception.stacktrace": "org.openqa.selenium.json.JsonException: Unable to parse: \n\tat org.openqa.selenium.json.Json.toType(Json.java:57)\n\tat org.openqa.selenium.json.Json.toType(Json.java:50)\n\tat org.openqa.selenium.grid.node.CustomLocatorHandler.execute(CustomLocatorHandler.java:119)\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:72)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:92)\n\tat org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:122)\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$NestedRoute.handle(Route.java:270)\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.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: org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read: \nBuild info: version: '4.5.3', revision: '4b786a1e430'\nSystem info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.0-48-generic', java.version: '11.0.16'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.json.JsonInput.expect(JsonInput.java:307)\n\tat org.openqa.selenium.json.JsonInput.beginObject(JsonInput.java:229)\n\tat org.openqa.selenium.json.MapCoercer.lambda$apply$1(MapCoercer.java:64)\n\tat org.openqa.selenium.json.JsonTypeCoercer.lambda$buildCoercer$6(JsonTypeCoercer.java:145)\n\tat org.openqa.selenium.json.JsonTypeCoercer.coerce(JsonTypeCoercer.java:127)\n\tat org.openqa.selenium.json.Json.toType(Json.java:71)\n\tat org.openqa.selenium.json.Json.toType(Json.java:55)\n\t... 35 more\n","exception.type": "org.openqa.selenium.json.JsonException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.router.HandleSession","http.host": "selenium5455fee0bd02f3d65:4444","http.method": "POST","http.request_content_length": "4556","http.scheme": "HTTP","http.target": "\u002fsession\u002f263510a41e4f79c41db3f9cfe09657e4\u002felement","session.id": "263510a41e4f79c41db3f9cfe09657e4"}}

14:05:50.036 INFO [LocalSessionMap.lambda$new$0] - Deleted session from local Session Map, Id: 263510a41e4f79c41db3f9cfe09657e4
14:05:50.036 INFO [GridModel.release] - Releasing slot for session id 263510a41e4f79c41db3f9cfe09657e4
14:05:50.037 INFO [SessionSlot.stop] - Stopping session 263510a41e4f79c41db3f9cfe09657e4

Frustratingly it doesn't actually spit out the details of the response that failed to be parsed as JSON.

@diemol , is there anything I can do to get the failed response content?

My hunch is that this is related to system load as we don't see it on every run.

andrewnicols commented 2 years ago

Frustratingly I can't see an easy way to add the chrome verbose logging options to chromedriver from Selenium - that is these options: https://chromedriver.chromium.org/logging

There is --driver-configuration described in https://www.selenium.dev/documentation/grid/configuration/cli_options/, but I'm not sure of the params required to have that log to stdout

JulienBreton commented 2 years ago

@andrewnicols maybe https://github.com/SeleniumHQ/docker-selenium/issues/1507#issuecomment-1295052462 is related to https://github.com/SeleniumHQ/selenium/issues/11156

andrewnicols commented 2 years ago

I don’t believe so @JulienBreton because the json parse failure always accompanies the start_map error and is inconsistently seen.

I suspect that chrome driver is returning an invalid response under load, and this is the result.

To investigate further we need the chrome driver verbose logs. I’ll attempt to build an image with a modified chromedriver wrapper to set the verbose option for testing next week

joerg1985 commented 2 years ago

I think this is the bug from #11156, if it hits you while the id locator is translated to a css locator (CustomLocatorHandler) the error message is "org.openqa.selenium.json.JsonException: Expected to read a START_MAP but instead have: END. Last 0 characters read:"

Abhijith2893 commented 2 years ago

We are also running into this issue and are curious to know if anyone has the following scenario. We have a problem with our security scanning software breaking the grid (#1646). Due to this, we restart the router in the distributed model or the hub in the hub/node model after the security scan to bring the grid back up. After doing the restart we see the error described in this post on some of the nodes. Wondering if anyone else has such restarts in place or if this issue is happening otherwise as well.

pajon commented 2 years ago

Hi guys, this issue has something with request body as @KupchinskiyVasiliy mention. In my issue report https://github.com/SeleniumHQ/selenium/issues/11188 i mention, that one line of code can fix temporarily (this don't fix the root cause) the issue.

I rebuild latest version (4.5.3) with the fix and available images can be found in my docker hub repo if you want test it.

krmahadevan commented 2 years ago

Frustratingly I can't see an easy way to add the chrome verbose logging options to chromedriver from Selenium - that is these options: https://chromedriver.chromium.org/logging

@andrewnicols - Have you tried setting the log levels via org.openqa.selenium.chrome.ChromeOptions#setLogLevel and pass this chrome options

Here's a sample

import java.net.MalformedURLException;
import java.net.URL;
import java.util.logging.Level;
import org.openqa.selenium.chrome.ChromeDriverLogLevel;
import org.openqa.selenium.chrome.ChromeOptions;
import org.openqa.selenium.logging.LogType;
import org.openqa.selenium.logging.LoggingPreferences;
import org.openqa.selenium.logging.Logs;
import org.openqa.selenium.remote.RemoteWebDriver;

public class RunLocallyTestCase {

  public static void main(String[] args) throws MalformedURLException {
    RemoteWebDriver driver = null;

    try {
      LoggingPreferences prefs = new LoggingPreferences();
      prefs.enable(LogType.DRIVER, Level.FINEST);
      URL url = new URL("http://localhost:4444");
      ChromeOptions options = new ChromeOptions();
      options.setCapability(ChromeOptions.LOGGING_PREFS, prefs);
      options.setLogLevel(ChromeDriverLogLevel.DEBUG);
      driver = new RemoteWebDriver(url, options);
      driver.get("https://www.selenium.dev/");
      System.err.println("Title: " + driver.getTitle());
      final Logs logs = driver.manage().logs();
      logs.get(LogType.DRIVER).forEach(entry -> System.err.println(entry.toJson()));
    } finally {
      if (driver != null) {
        driver.quit();
      }
    }
  }
}

There is --driver-configuration described in https://www.selenium.dev/documentation/grid/configuration/cli_options/, but I'm not sure of the params required to have that log to stdout

I believe that you don't need this since you can pass in the chromedriver's log levels via the capabilities itself.

Perhaps you can try this and share some more additional information pertaining to this defect so that we can get it fixed ?

andrewnicols commented 2 years ago

@krmahadevan,

We're a PHP app but Java commands gave me a few clues to get there.

Here's an excerpt of the logs from just before the failure.

The-activity-results-block-displays-students-in-separate-groups-scores_I-set-the-following-fields-to-these-values-_112.driver.json.log

In this case we're selecting an option from a select. I'm not sure of the specifics of how that happens because the driver abstracts some of that away, but I can find out.

The response looks correct and valid JSON, and the driver is returning something so I wonder if could well be #11156 in our case.

Do we know when there will be a new release containing this fix?

diemol commented 2 years ago

4.6.0 will contain the fix for https://github.com/SeleniumHQ/selenium/issues/11156, which should come out in a couple of days.

pajon commented 2 years ago

Thank you @diemol and @joerg1985 👍 It solved all issues for me (4.5.3 + cherry-picked commit). The issue was introduced from 4.0 version so all versions before 4.6 are basically unstable. I think it would be very helpfull to backport commit or notice users about the issue from previous verions

cocorossello commented 2 years ago

I've just tried 4.6.0 and I can confirm that we are not hitting this error anymore!

deejgregor commented 2 years ago

Confirmed that 4.6.0 fixed our issues, as well. Thanks!

diemol commented 2 years ago

Thank you for the feedback, I will close this as a result.

MamunC commented 1 year ago

Seeing this issue in 4.8.1. Anyone having this problem with the new release?

DeepKandey commented 1 year ago

I am also facing the same exception with Selenium 4.9.1. When I try to hit the curl POST command inside the hub, it throws this error. curl -X POST HTTP://selenium-hub:4444/graphql

bchhabra commented 1 year ago

Still the same issue on

4.10.0