[🐛 Bug]: Fulfil request with body of 12166 characters or more throws exception: Unhandled exception. System.InvalidOperationException: A command response was not received: Fetch.fulfillRequest

arnonax-tr commented 1 year ago

What happened?

When using the DevTools to send a fake response (using Network.ContinueRequestWithResponse) with a body of 12166 characters or more, over Selenium Grid, the following exception is thrown:

Exit code is -532462766 (Unhandled exception. System.InvalidOperationException: A command response was not received: Fetch.fulfillRequest
   at OpenQA.Selenium.DevTools.DevToolsSession.SendCommand(String commandName, JToken commandParameters, CancellationToken cancellationToken, Nullable`1 millisecondsTimeout, Boolean throwExceptionIfResponseNotReceived)
   at OpenQA.Selenium.DevTools.DevToolsSession.SendCommand[TCommand,TCommandResponse](TCommand command, CancellationToken cancellationToken, Nullable`1 millisecondsTimeout, Boolean throwExceptionIfResponseNotReceived)
   at OpenQA.Selenium.DevTools.V85.Fetch.FetchAdapter.FulfillRequest(FulfillRequestCommandSettings command, CancellationToken cancellationToken, Nullable`1 millisecondsTimeout, Boolean throwExceptionIfResponseNotReceived)
   at OpenQA.Selenium.DevTools.V85.V85Network.ContinueRequestWithResponse(HttpRequestData requestData, HttpResponseData responseData)
   at TestProject1.DevToolsBug.OnPausedRequest(Object sender, RequestPausedEventArgs e) 
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__128_1(Object state)
   at System.Threading.QueueUserWorkItemCallback.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart())

Using local chrome it works fine, and using the grid with a smaller body (i.e. 12165 chars or less) it also works.

How can we reproduce the issue?

using OpenQA.Selenium;
using OpenQA.Selenium.Chrome;
using OpenQA.Selenium.DevTools.V85;
using OpenQA.Selenium.DevTools.V85.Fetch;
using OpenQA.Selenium.DevTools.V85.Network;
using OpenQA.Selenium.Remote;
using OpenQA.Selenium.Support.Extensions;
using OpenQA.Selenium.Support.UI;
using EnableCommandSettings = OpenQA.Selenium.DevTools.V85.Fetch.EnableCommandSettings;
using RequestPattern = OpenQA.Selenium.DevTools.V85.Fetch.RequestPattern;
using RequestPausedEventArgs = OpenQA.Selenium.DevTools.RequestPausedEventArgs;

namespace TestProject1;

internal class DevToolsBug
{
    private V85Network _network;
    // Note: changing the length of the response body to 12165 or less makes the problem go away
    private readonly string _responseBody = GetResponseBody(12166);

    private static string GetResponseBody(int length)
    {
        return new string('x', length);
    }

    private const string Html = @"
<html>
<head>
<script>
function fetchFromFakeRoute() {
    fetch('/fakeRoute')
        .then(response => response.text())
        .then(text => document.getElementById('result').innerText = text);
}
</script>
</head>
<body>
<button id='btn' onclick='fetchFromFakeRoute()'>Click me</button>
<div id='result'></div>
</body>
";

    [Test]
    public void ReproduceDevToolsBug()
    {
        // With local ChromeDriver it works:
        // using var driver = new ChromeDriver();

        // But with remote it doesn't:
        var gridUrl = TestContext.Parameters["gridUrl"] ?? throw new Exception("Please set gridUrl through *.runsettings or command line arguments: https://learn.microsoft.com/en-us/visualstudio/test/configure-unit-tests-by-using-a-dot-runsettings-file?view=vs-2022#testrunparameters");
        using var driver = new RemoteWebDriver(new Uri(gridUrl), new ChromeOptions());

        driver.Url = "https://www.google.com";

        using var devToolsSession = driver.GetDevToolsSession(85);
        var fetch = new FetchAdapter(devToolsSession);
        var networkAdapter = new NetworkAdapter(devToolsSession);
        var network = new V85Network(networkAdapter, fetch);

        // TODO: check if the problem reproduces without listening to Responses
        var enableCommandSettings = new EnableCommandSettings
        {
            Patterns = new RequestPattern[]
            {
                new()
                {
                    RequestStage = RequestStage.Request,
                    UrlPattern = "*"
                },
            }
        };
        fetch.Enable(enableCommandSettings);

        _network = network;
        _network.RequestPaused += OnPausedRequest;

        LoadHtml(driver, Html);

        var btn = driver.FindElement(By.Id("btn"));
        btn.Click();

        var result = driver.FindElement(By.Id("result"));

        new WebDriverWait(driver, TimeSpan.FromSeconds(5))
            .Until(_ => result.Text == _responseBody);
    }

    private async void OnPausedRequest(object? sender, RequestPausedEventArgs e)
    {
        if (e.RequestData.Url.EndsWith("/fakeRoute"))
        {
            await _network.ContinueRequestWithResponse(
                e.RequestData,
                new HttpResponseData
                {
                    StatusCode = 200,
                    Body = _responseBody,
                    RequestId = e.RequestId
                });
        }
    }

    private static void LoadHtml(IWebDriver driver, string html)
    {
        driver.ExecuteJavaScript($"document.write(\"{html.Replace("\r", " ").Replace("\n", " ")}\")");
    }
}

Relevant log output

Note: Currently I don't have access to the Grid's log and my DevOps person is on vacation. If it's relevant, When he'll come back I'll reproduce it again and ask him to send me the relevant logs.

Operating System

Client: Windows 10, Grid: AKS

Selenium version

Client: 4.10, Grid: 4.9.1 (revision eb2032df7f)

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

Chrome v.113.0

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

ChromeDriver 114.0.5735.9000 - relevant only when running locally, where the issue doesn't happen

Are you using Selenium Grid?

4.9.1 (revision eb2032df7f)

github-actions[bot] commented 1 year ago

@arnonax-tr, 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!

titusfortner commented 1 year ago

So v85 is for using with Firefox. Can you try specifying the version number that matches your version of Chrome?

arnonax-tr commented 1 year ago

I tried also using 113 and I get the same results. (BTW, I'm normally using 85 so I won't have to change the code every few weeks. We have many projects that use Selenium and updating all of them for every new release of Chrome is a real headache. But that's for another issue...)

arnonax-tr commented 1 year ago

Any update on this?

PS: I suggest to add also a "grid" label to this issue, as it happens only when using Selenium Grid.

titusfortner commented 1 year ago

I'm not the right person to investigate BiDi + Grid issues, but I wanted to make clear that Chrome makes changes with each release, so there is no guarantee things will work if the versions do not match.

arnonax-tr commented 1 year ago

Which versions do not match? If you refer to the fact that my version of ChromeDriver is 114 while the version of Chrome that's installed on the grid is 113, then it's irrelevant, because the version of ChromeDriver is only relevant when running locally, not through the grid (I mentioned it in the description of the issue just to emphasize that locally it works correctly. The issue happens only with the grid).

diemol commented 1 year ago

Are you using the Java 11 HTTP client in Grid? A few improvements came for 4.10.0, I think.

arnonax-tr commented 1 year ago

I'm not sure I understand what you mean. My client (binding) is dotnet, not Java. If this is not what you mean, can you please tell me how can I tell whether I'm using Java 11 HTTP client in the Grid?

diemol commented 1 year ago

I know you are using C# on the client side, but the Grid is Java and that is why I am asking. https://www.selenium.dev/blog/2022/using-java11-httpclient/

arnonax-tr commented 1 year ago

Thanks for the clarification. I tried not to upgrade my grid hub and node to 4.10.0, and the problem still exists. I also found the logs of the node and it contains an error that may be related:

11:19:18.441 INFO [NodeOptions.getSessionFactories] - Detected 3 available processors
11:19:18.442 WARN [NodeOptions.getSessionFactories] - Overriding max recommended number of 3 concurrent sessions. Session stability and reliability might suffer!
11:19:18.443 WARN [NodeOptions.getSessionFactories] - One browser session is recommended per available processor. Safari is always limited to 1 session per host.
11:19:18.443 WARN [NodeOptions.getSessionFactories] - Overriding this value for Internet Explorer is not recommended. Issues related to parallel testing with Internet Explored won't be accepted.
11:19:18.443 WARN [NodeOptions.getSessionFactories] - Double check if enabling 'override-max-sessions' is really needed
11:19:18.488 INFO [NodeOptions.report] - Adding chrome for {"browserName": "chrome","browserVersion": "114.0","platformName": "linux","se:noVncPort": 7900,"se:vncEnabled": true} 2 times (Host)
11:19:18.508 INFO [Node.<init>] - Binding additional locator mechanisms: relative
11:19:18.701 INFO [NodeServer$1.start] - Starting registration process for Node http://10.140.196.43:5555
11:19:18.702 INFO [NodeServer.execute] - Started Selenium node 4.10.0 (revision c14d967899): http://10.140.196.43:5555
11:19:18.712 INFO [NodeServer$1.lambda$start$1] - Sending registration event...
11:19:18.873 INFO [NodeServer.lambda$createHandlers$2] - Node has been added
11:20:06.191 INFO [DriverService$Builder.getLogOutput] - Driver logs no longer sent to console by default; https://www.selenium.dev/documentation/webdriver/drivers/service/#setting-log-output
11:20:07.084 INFO [LocalNode.newSession] - Session created by the Node. Id: 1de9a84e86b314c941f2f1f19b753826, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 114.0.5735.133, chrome: {chromedriverVersion: 114.0.5735.90 (386bc09e8f │
11:20:07.951 INFO [ProxyNodeWebsockets.createWsEndPoint] - Establishing connection to ws://localhost:41243/devtools/browser/7e27ca1e-8b45-4f1f-81b7-0045be66d588
11:20:09.590 WARN [DefaultChannelPipeline.onUnhandledInboundException] - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.lang.IllegalStateException: expected a continuation frame
    at org.openqa.selenium.netty.server.MessageInboundConverter.channelRead0(MessageInboundConverter.java:99)
    at org.openqa.selenium.netty.server.MessageInboundConverter.channelRead0(MessageInboundConverter.java:38)
    at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
    at org.openqa.selenium.netty.server.WebSocketUpgradeHandler.handleWebSocketFrame(WebSocketUpgradeHandler.java:165)
    at org.openqa.selenium.netty.server.WebSocketUpgradeHandler.channelRead(WebSocketUpgradeHandler.java:96)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
    at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
    at io.netty.handler.codec.http.HttpServerKeepAliveHandler.channelRead(HttpServerKeepAliveHandler.java:64)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
    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.base/java.lang.Thread.run(Thread.java:829)

diemol commented 1 year ago

OK, you are using the docker images, that is information we did not know. So you are using the Java 11 client. Can you share how the containers are started?

dimash-tr commented 1 year ago

Hi, We are using helm chart to deploy hub and chrome. hub-deployment copy.txt chrome-deployment copy.txt values_automationNS copy.txt

arnonax-tr commented 1 year ago

BTW, I thought to try the same scenario from a different binding (e.g. Python), in order to check if the problem is specific to .net or not. But then I realized that the APIs of the DevTools is pretty different between the different languages and I don't know how to translate my code to another language. If you can help me translate the above C# code to other language then I can try it.

arnonax-tr commented 1 year ago

FWIW, I tried to run a local grid (both as standalone, and as hub+node configuration), and the issue does not reproduce. So it's probably related to docker indeed.

diemol commented 1 year ago

That is what I wanted to try. However, did you use the Java 11 HTTP client when running locally? Next thing to try is to run the containers locally. The idea is to isolate the environment where this happens.

arnonax-tr commented 1 year ago

That is what I wanted to try. However, did you use the Java 11 HTTP client when running locally? Next thing to try is to run the containers locally. The idea is to isolate the environment where this happens.

Yes, I used Java 11 (Selenium 4.10.0) when running locally.

titusfortner commented 1 year ago

It isn't enough to just use Java 11, you have to require a library and add a system property. Please read https://www.selenium.dev/blog/2022/using-java11-httpclient/

arnonax-tr commented 1 year ago

I tried now locally using Java 11 (using the command java -jar selenium-server-4.10.0.jar --ext selenium-http-jdk-client-4.10.0.jar standalone) and it also works. But I don't think that it tells us much as locally it always worked...

diemol commented 1 year ago

I have not had time these days to triage this. But please run the docker images locally and let us know if it works or not. Because if it works locally with the Docker images, then it is a configuration in the Kubernetes cluster.

arnonax-tr commented 1 year ago

I tried now with local docker container (selenium/standalone-chrome) and it also passed. I don't know if this image uses Java 11 HttpClient or not, but I used it as is and it worked (just had to set --grid-url http://localhost:4444/ using SE_OPTS env. var) Do you have any idea what else can I check in order to diagnose this problem?

diemol commented 1 year ago

Yes, then the problem is on your Kubernetes configuration, as something is not letting the whole blob be sent to the container. The images work well, as they all use the Java 11 HTTP Client.

Please check with your cluster admin.

github-actions[bot] commented 10 months ago

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

SeleniumHQ / selenium