Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[🐛 Bug]: Random GOAWAY frame received from Selenium Grid #2195

Closed
cezzarez opened this issue Apr 7, 2024 · 10 comments
Closed

[🐛 Bug]: Random GOAWAY frame received from Selenium Grid #2195

cezzarez opened this issue Apr 7, 2024 · 10 comments

Comments

@cezzarez
Copy link

cezzarez commented Apr 7, 2024

What happened?

We have a Selenium Grid setup using KEDA and Selenium Grid helm chart. KEDA v.2.13.0 and Selenium Grid helm chart v.0.28.3.
When we are testing some of the pages we randomly received the:

Caused by: java.io.IOException: /10.251.7.8:35426: GOAWAY received
From Selenium Grid.

The settings we have for Egde node:
SE_NODE_SESSION_TIMEOUT=600 (because first we saw the timeout was reached, but 600 is much more than we need for tests)
SE_SESSION_REQUEST_TIMEOUT=450 (a lot of values tested here, looks like it does not change anything)
SE_JAVA_OPTS=-Dwebdriver.http.factory=jdk-http-client -Djdk.httpclient.websocket.intermediateBufferSize=3000000 (also different values tested for Buffer, but did not see any change for that)
shm size = 4Gi (it was also increase/decreased and I do not see any changes for this param)

In the HUB I even change the Healthcheck interval from 120 to 300 because I though, that maybe it is because of the timeout.

I launch the logs level to ALL and to be honest still nothing special on EDGE or HUB hosts observed.

In the EDGE I can see the error:
09:27:16.633 DEBUG [PlainHttpConnection.close] - [HttpClient-1-SelectorManager] [186s 134ms] PlainHttpConnection(SocketTube(1)) Closing channel: channel registered with selector, key.interestOps=1, sa.interestOps=1
09:27:16.634 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalError] - [HttpClient-1-SelectorManager] [186s 134ms] SocketTube(1) got read error: java.io.IOException: connection closed locally
09:27:16.634 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [186s 134ms] SocketTube(1) leaving read() loop after EOF: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1]
09:27:16.634 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [186s 134ms] SocketTube(1) Read scheduler stopped
09:27:16.634 DEBUG [HttpClientImpl$SelectorAttachment.resetInterestOps] - [HttpClient-1-SelectorManager] [186s 134ms] SelectorAttachment key cancelled for java.nio.channels.SocketChannel[closed]
09:27:16.635 DEBUG [SocketTube$SocketFlowEvent.abort] - [HttpClient-1-SelectorManager] [186s 135ms] SocketTube(1) abort: java.io.IOException: java.nio.channels.CancelledKeyException
09:27:16.635 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [186s 135ms] HttpClientImpl(1) next timeout: 0
09:27:16.635 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [186s 135ms] HttpClientImpl(1) next expired: 0
09:27:16.635 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [186s 135ms] HttpClientImpl(1) Next deadline is 3000
09:27:16.643 DEBUG [UrlChecker.lambda$waitUntilUnavailable$2] - Polling http://localhost:31879/shutdown
09:27:16.643 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:31879/shutdown

But I cannot find anything interesting in the issues here or Stack Overflow about this "part" of logs...

In the HUB logs (ALL level) nothig what could suggest anythig.

So what happened...?
No idea, we run the tests, we see the pod is created, but sometimes (in a very random moment) the GOAWAY frame is received.
It suggest the Selenium is closed, but in logs there is no information what exactly is the problem.
I am now sure it is not because of the memory, timeouts or anything like that, but maybe you as an experts know what could it be?

I want to just add, that sometimes the tests are going well, and are finished with SUCCESS state.

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

It would be just helm install for Selenium Grid helm chart on k8s.
You have to also set the autoscale to true to install KEDA.

Relevant log output

In the EDGE I can see the error: 
09:27:16.633 DEBUG [PlainHttpConnection.close] - [HttpClient-1-SelectorManager] [186s 134ms] PlainHttpConnection(SocketTube(1)) Closing channel: channel registered with selector, key.interestOps=1, sa.interestOps=1
09:27:16.634 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalError] - [HttpClient-1-SelectorManager] [186s 134ms] SocketTube(1) got read error: java.io.IOException: connection closed locally
09:27:16.634 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [186s 134ms] SocketTube(1) leaving read() loop after EOF:  Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1]
09:27:16.634 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [186s 134ms] SocketTube(1) Read scheduler stopped
09:27:16.634 DEBUG [HttpClientImpl$SelectorAttachment.resetInterestOps] - [HttpClient-1-SelectorManager] [186s 134ms] SelectorAttachment key cancelled for java.nio.channels.SocketChannel[closed]
09:27:16.635 DEBUG [SocketTube$SocketFlowEvent.abort] - [HttpClient-1-SelectorManager] [186s 135ms] SocketTube(1) abort: java.io.IOException: java.nio.channels.CancelledKeyException
09:27:16.635 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [186s 135ms] HttpClientImpl(1) next timeout: 0
09:27:16.635 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [186s 135ms] HttpClientImpl(1) next expired: 0
09:27:16.635 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [186s 135ms] HttpClientImpl(1) Next deadline is 3000
09:27:16.643 DEBUG [UrlChecker.lambda$waitUntilUnavailable$2] - Polling http://localhost:31879/shutdown
09:27:16.643 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:31879/shutdown

From Jenkins, where we run the tests I can see randomly:
Caused by: java.io.UncheckedIOException: java.io.IOException: /10.251.7.8:35426: GOAWAY received

Operating System

Kubernetes (EKS)

Docker Selenium version (image tag)

4.18.1-20240224

Selenium Grid chart version (chart version)

0.28.3

Copy link

github-actions bot commented Apr 7, 2024

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


Info for maintainers

Triage this issue by using labels.

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

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

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

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

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

Thank you!

@diemol
Copy link
Member

diemol commented Apr 9, 2024

Why do you need these options?

SE_JAVA_OPTS=-Dwebdriver.http.factory=jdk-http-client -Djdk.httpclient.websocket.intermediateBufferSize=3000000

-Dwebdriver.http.factory=jdk-http-client is the default one since 4.14.

What test script can we use to replicate the issue?

@cezzarez
Copy link
Author

cezzarez commented Apr 9, 2024

Hello @diemol !
Thank you for the reply.
About the options, in the previous versions I was using them, as it was the internal requirement, probably missed the note about the default settings. Just removed them.

About the replication, not sure if it will be possible to do on your site...
Our tests are using internal pages and the source code cannot be shared.

The tests are pretty complex also (they can took some time), but as I mentioned it is for sure not the timeout problem, because the GOAWAY frame is very random.

Haven't you see similar cases before? Maybe you have some hints, what could be the reason of it?

@diemol
Copy link
Member

diemol commented Apr 9, 2024

I've never seen this reported before, so I would not know where to start without a way to reproduce it. Could it be something in your infrastructure?

@kakliniew
Copy link

kakliniew commented Jun 26, 2024

@diemol faced the same issue I guess. I have selenium grid 4.21.0, edge node browser 4.21.0.
When I use serenity 4.0.1 (selenium 4.12.0) tests work correctly, but when I try to upgrade (e.g. 4.1.4 - selenium 4.18.1) then I receive this error after 15s of execution (execution works fine but then suddenly GOAWAY).

I use also io.github.bonigarcia:webdrivermanager.

here something similar: https://stackoverflow.com/questions/75896279/selenium-remote-run-java-io-ioexception-goaway-received

Session ID: <hidden id>
        at app//org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:546)
        at app//org.openqa.selenium.remote.ElementLocation$ElementFinder$2.findElement(ElementLocation.java:165)
        at app//org.openqa.selenium.remote.ElementLocation.findElement(ElementLocation.java:59)
        at app//org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:356)
        at app//org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:350)
        at app//net.thucydides.core.webdriver.WebDriverFacade.findElement(WebDriverFacade.java:259)
        at app//net.serenitybdd.core.pages.WebElementResolverByLocator.resolveForDriver(WebElementResolverByLocator.java:25)
        at app//net.serenitybdd.core.pages.WebElementFacadeImpl.getResolvedElement(WebElementFacadeImpl.java:188)
        at app//net.serenitybdd.core.pages.WebElementFacadeImpl.getElement(WebElementFacadeImpl.java:183)
        at app//net.serenitybdd.core.pages.WebElementExpectations$3.apply(WebElementExpectations.java:63)
        at app//net.serenitybdd.core.pages.WebElementExpectations$3.apply(WebElementExpectations.java:55)
        at app//org.openqa.selenium.support.ui.FluentWait.until(FluentWait.java:203)
        at app//net.serenitybdd.core.pages.WebElementFacadeImpl.waitUntilEnabled(WebElementFacadeImpl.java:1136)
        at app//net.serenitybdd.core.pages.WebElementFacadeImpl.waitUntilElementAvailable(WebElementFacadeImpl.java:908)
        at app//net.serenitybdd.core.pages.WebElementFacadeImpl.click(WebElementFacadeImpl.java:1221)
        at app//net.serenitybdd.core.pages.WebElementFacadeImpl.click(WebElementFacadeImpl.java:1241)
        at <hidden part>

        Caused by:
        java.io.UncheckedIOException: java.io.IOException: /<hidden ip>: GOAWAY received
            at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute0(JdkHttpClient.java:443)
            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:55)
            at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute(JdkHttpClient.java:359)
            at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:54)
            at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:187)
            at org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51)
            at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:519)
            at org.openqa.selenium.remote.ElementLocation$ElementFinder$2.findElement(ElementLocation.java:165)
            at org.openqa.selenium.remote.ElementLocation.findElement(ElementLocation.java:59)
            at org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:356)
            at org.openqa.selenium.remote.RemoteWebDriver.findElement(RemoteWebDriver.java:350)
            at net.thucydides.core.webdriver.WebDriverFacade.findElement(WebDriverFacade.java:259)
            at net.serenitybdd.core.pages.WebElementResolverByLocator.resolveForDriver(WebElementResolverByLocator.java:25)
            at net.serenitybdd.core.pages.WebElementFacadeImpl.getResolvedElement(WebElementFacadeImpl.java:188)
            at net.serenitybdd.core.pages.WebElementFacadeImpl.getElement(WebElementFacadeImpl.java:183)
            at net.serenitybdd.core.pages.WebElementExpectations$3.apply(WebElementExpectations.java:63)
            at net.serenitybdd.core.pages.WebElementExpectations$3.apply(WebElementExpectations.java:55)
            at org.openqa.selenium.support.ui.FluentWait.until(FluentWait.java:203)
            at net.serenitybdd.core.pages.WebElementFacadeImpl.waitUntilEnabled(WebElementFacadeImpl.java:1136)
            at net.serenitybdd.core.pages.WebElementFacadeImpl.waitUntilElementAvailable(WebElementFacadeImpl.java:908)
            at net.serenitybdd.core.pages.WebElementFacadeImpl.click(WebElementFacadeImpl.java:1221)
            at net.serenitybdd.core.pages.WebElementFacadeImpl.click(WebElementFacadeImpl.java:1241)
           <hidden part>
            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 io.cucumber.java.Invoker.doInvoke(Invoker.java:66)
            at io.cucumber.java.Invoker.invoke(Invoker.java:24)
            at io.cucumber.java.AbstractGlueDefinition.invokeMethod(AbstractGlueDefinition.java:47)
            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:84)
            at io.cucumber.core.runner.TestStep.run(TestStep.java:56)
            at io.cucumber.core.runner.PickleStepTestStep.run(PickleStepTestStep.java:51)
            at io.cucumber.core.runner.TestCase.run(TestCase.java:84)
            at io.cucumber.core.runner.Runner.runPickle(Runner.java:75)
            at io.cucumber.junit.PickleRunners$NoStepDescriptions.lambda$run$0(PickleRunners.java:151)
            at io.cucumber.core.runtime.CucumberExecutionContext.lambda$runTestCase$5(CucumberExecutionContext.java:137)
            at io.cucumber.core.runtime.RethrowingThrowableCollector.executeAndThrow(RethrowingThrowableCollector.java:23)
            at io.cucumber.core.runtime.CucumberExecutionContext.runTestCase(CucumberExecutionContext.java:137)
            at io.cucumber.junit.PickleRunners$NoStepDescriptions.run(PickleRunners.java:148)
            at io.cucumber.junit.FeatureRunner.runChild(FeatureRunner.java:144)
            at io.cucumber.junit.FeatureRunner.runChild(FeatureRunner.java:28)
            at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
            at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
            at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
            at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
            at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
            at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
            at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
            at io.cucumber.junit.FeatureRunner.run(FeatureRunner.java:137)
            at io.cucumber.junit.CucumberSerenityBaseRunner.runChild(CucumberSerenityBaseRunner.java:332)
            at io.cucumber.junit.CucumberSerenityBaseRunner.runChild(CucumberSerenityBaseRunner.java:53)
            at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
            at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
            at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
            at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
            at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
            at io.cucumber.junit.CucumberSerenityBaseRunner$RunCucumber.evaluate(CucumberSerenityBaseRunner.java:363)
            at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
            at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
            at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:108)
            at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
            at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:40)
            at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:60)
            at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:52)
            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.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
            at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
            at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
            at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
            at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
            at org.gradle.api.internal.tasks.testing.worker.TestWorker$2.run(TestWorker.java:176)
            at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
            at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
            at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
            at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
            at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:113)
            at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:65)
            at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
            at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)

            Caused by:
            java.io.IOException: /<hidden ip>: GOAWAY received
                at java.net.http/jdk.internal.net.http.Http2Connection.handleGoAway(Http2Connection.java:999)
                at java.net.http/jdk.internal.net.http.Http2Connection.handleConnectionFrame(Http2Connection.java:867)
                at java.net.http/jdk.internal.net.http.Http2Connection.processFrame(Http2Connection.java:738)
                at java.net.http/jdk.internal.net.http.frame.FramesDecoder.decode(FramesDecoder.java:155)
                at java.net.http/jdk.internal.net.http.Http2Connection$FramesController.processReceivedData(Http2Connection.java:232)
                at java.net.http/jdk.internal.net.http.Http2Connection.asyncReceive(Http2Connection.java:663)
                at java.net.http/jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.processQueue(Http2Connection.java:1292)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
                at java.net.http/jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.runOrSchedule(Http2Connection.java:1310

@kakliniew
Copy link

@diemol could you look into this problem?
I removed bonigarcia and saw in logs that after update it doesn't have 'ms:edgeOptions: {args: [--remote-allow-origins=*], extensions: []}}]', but I fixed that, still GOAWAY

@diemol
Copy link
Member

diemol commented Jul 12, 2024

How can I look into it if there is not a way to reproduce it?

@kakliniew
Copy link

@diemol thanks for answer. I thought perhaps the description and stacktrace would be sufficient. I can't share the code, but I will try to create code from scratch to reproduce the error

@VietND96
Copy link
Member

I wrote all the details in #2328. The chart also includes config keys for annotations to disable HTTP/2 if TLS termination is used.

@VietND96 VietND96 added this to the 4.23.0 milestone Jul 27, 2024
Copy link

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

@github-actions github-actions bot locked and limited conversation to collaborators Aug 27, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

4 participants