search

SeleniumHQ / selenium

A browser automation framework and ecosystem.
https://selenium.dev
Apache License 2.0
30.65k stars 8.18k forks source link

[🐛 Bug]: Timeout set to 16 minutes, but always fails with timeout after 9 minutes #14446

Open codex70 opened 2 months ago

codex70 commented 2 months ago

What happened?

This is similar to the problem at https://github.com/SeleniumHQ/selenium/issues/9314. I am trying to test a report which takes around 12 minutes to run. I am using selenium hub in docker with google browser. The tests are run using TestNG and Cucumber.

Originally I was seeing the same 3 minute timeout as described in the other issue, but I've implemented the code shown in the page, and now see a different timeout issue after 9 minutes (it is always exactly 9 minutes). The timeout also seems to block the driver from quitting and stopping for a significant amount of time (around a further 13 minutes). After this, I need to restart the docker container in order to connect again to the remote web driver.

How can we reproduce the issue?

Run selenium in docker with docker compose:
version: "3"
services:
  chrome:
    image: selenium/node-chrome:latest
    shm_size: 2gb
    depends_on:
      - selenium-hub
    environment:
      - SE_EVENT_BUS_HOST=selenium-hub
      - SE_EVENT_BUS_PUBLISH_PORT=4442
      - SE_EVENT_BUS_SUBSCRIBE_PORT=4443

  edge:
    image: selenium/node-edge:latest
    shm_size: 2gb
    depends_on:
      - selenium-hub
    environment:
      - SE_EVENT_BUS_HOST=selenium-hub
      - SE_EVENT_BUS_PUBLISH_PORT=4442
      - SE_EVENT_BUS_SUBSCRIBE_PORT=4443

  firefox:
    image: selenium/node-firefox:latest
    shm_size: 2gb
    depends_on:
      - selenium-hub
    environment:
      - SE_EVENT_BUS_HOST=selenium-hub
      - SE_EVENT_BUS_PUBLISH_PORT=4442
      - SE_EVENT_BUS_SUBSCRIBE_PORT=4443

  selenium-hub:
    image: selenium/hub:latest
    container_name: selenium-hub
    ports:
      - "4442:4442"
      - "4443:4443"
      - "4444:4444"

Create the "SetTimeout" class:
/**
 * Reference: https://github.com/SeleniumHQ/selenium/issues/9314
 */
public class SetTimeout {

    public static final Duration clientTimeout = Duration.ofMinutes(16);
    public static final Duration defaultTimeout = Duration.ofMillis(960000);
    ChromeDriverService chromeDriverService;

    private static ChromeOptions getChromeOptions() {
        ChromeOptions options = new ChromeOptions();

        //remove unexepectedalertexceptions
        options.addArguments("--unexpectedAlertBehaviour=dismiss", "--silent", "--blink-settings=imagesEnabled=false", "--disable-blink-features", "--disable-blink-features=AutomationControlled", "--disable-gpu", "--no-sandbox", "--window-size=1920,1200", "--ignore-certificate-errors", "--disable-application-cache");

        // no downloads
        Map<String, Object> chromePrefs = new HashMap<String, Object>();
        chromePrefs.put("download_restrictions", 3);
        options.setExperimentalOption("prefs", chromePrefs);
        return options;
    }

    public ChromeDriverService getChromeDriverService() {
        return chromeDriverService;
    }

    public RemoteWebDriver createDriver(URL url) throws Exception {

        RemoteWebDriver driver;

        ChromeOptions options = getChromeOptions();

        LoggingPreferences logPrefs = new LoggingPreferences();
        logPrefs.enable(LogType.PERFORMANCE, Level.ALL);
        options.setCapability("goog:loggingPrefs", logPrefs);
        options.setPageLoadStrategy(PageLoadStrategy.EAGER);

        chromeDriverService = new ChromeDriverService.Builder().withLogOutput(System.out).build();
        chromeDriverService.start();

        ClientConfig config = ClientConfig.defaultConfig().connectionTimeout(clientTimeout)
                .readTimeout(clientTimeout).baseUrl(url);
        Tracer tracer = OpenTelemetryTracer.getInstance();
        CommandExecutor executor = new HttpCommandExecutor(
                buildChromiumCommandMappings("goog"),
                config,
                new TracedHttpClient.Factory(tracer, HttpClient.Factory.createDefault()));

        driver = new RemoteWebDriver(executor, options);

        //Inject Core Web Vitals scripts
        Map<String, Object> parameters = new HashMap<String, Object>();
        parameters.put("source", "var vitalsCLS = 'unset';\n" +
                "function logCLS({value}) {\n" +
                "  \tvitalsCLS = value.toString();\n" +
                "  \tconsole.log('CLS: ' + vitalsCLS);\n" +
                "}\n" +
                "\n" +
                "var vitalsFID = 'unset';\n" +
                "function logFID({value}) {\n" +
                "  \tvitalsFID = value.toString();\n" +
                "  \tconsole.log('FID: ' + vitalsFID);\n" +
                "}\n" +
                "\n" +
                "var vitalsLCP = 'unset';\n" +
                "function logLCP({value}) {\n" +
                "  \tvitalsLCP = value.toString();\n" +
                "  \tconsole.log('LCP: ' + vitalsLCP);\n" +
                "}\n" +
                "\n" +
                "window.onload = function() {\n" +
                "\t\n" +
                "\tvar script = document.createElement('script');\n" +
                "\tscript.src = 'https://unpkg.com/web-vitals';\n" +
                "  \tscript.onload = function() {\n" +
                "  \t\n" +
                "    // When loading `web-vitals` using a classic script, all the public\n" +
                "    // methods can be found on the `webVitals` global namespace.\n" +
                "\twebVitals.getCLS(logCLS, true); \n" +
                "    webVitals.getFID(logFID, true); \n" +
                "    webVitals.getLCP(logLCP, true); \n" +
                "  \n" +
                "  }\n" +
                "\n" +
                "  document.body.appendChild(script);\n" +
                "\n" +
                "} ");

        Command addScriptCommand = new Command(driver.getSessionId(), ChromiumDriverCommand.EXECUTE_CDP_COMMAND, ImmutableMap.of("cmd", "Page.addScriptToEvaluateOnNewDocument", "params", parameters));
        driver.getCommandExecutor().execute(addScriptCommand);

        //Stop any unwanted downloading of *.pdf *.crdownload et al. files
        parameters = new HashMap<String, Object>();
        parameters.put("behavior", "deny");

        Command setDownloadBehaviorCommand = new Command(driver.getSessionId(), ChromiumDriverCommand.EXECUTE_CDP_COMMAND, ImmutableMap.of("cmd", "Browser.setDownloadBehavior", "params", parameters));
        driver.getCommandExecutor().execute(setDownloadBehaviorCommand);
        // driver.executeCdpCommand("Browser.setDownloadBehavior", parameters);

        WebDriver.Timeouts pageLoadTimeout = driver.manage().timeouts().pageLoadTimeout(defaultTimeout);
        System.out.println(pageLoadTimeout.getPageLoadTimeout().toMillis());
        WebDriver.Timeouts scriptTimeout = driver.manage().timeouts().scriptTimeout(defaultTimeout);
        System.out.println(scriptTimeout.getScriptTimeout().toMillis());

        return driver;

    }

    private Map<String, CommandInfo> buildChromiumCommandMappings(String vendorKeyword) {
        String sessionPrefix = "/session/:sessionId/";
        String chromiumPrefix = sessionPrefix + "chromium";
        String vendorPrefix = sessionPrefix + vendorKeyword;

        HashMap<String, CommandInfo> mappings = new HashMap<>();

        mappings.put(ChromiumDriverCommand.LAUNCH_APP,
                new CommandInfo(chromiumPrefix + "/launch_app", HttpMethod.POST));

        String networkConditions = chromiumPrefix + "/network_conditions";
        mappings.put(ChromiumDriverCommand.GET_NETWORK_CONDITIONS,
                new CommandInfo(networkConditions, HttpMethod.GET));
        mappings.put(ChromiumDriverCommand.SET_NETWORK_CONDITIONS,
                new CommandInfo(networkConditions, HttpMethod.POST));
        mappings.put(ChromiumDriverCommand.DELETE_NETWORK_CONDITIONS,
                new CommandInfo(networkConditions, HttpMethod.DELETE));

        mappings.put(ChromiumDriverCommand.EXECUTE_CDP_COMMAND,
                new CommandInfo(vendorPrefix + "/cdp/execute", HttpMethod.POST));

        // Cast / Media Router APIs
        String cast = vendorPrefix + "/cast";
        mappings.put(ChromiumDriverCommand.GET_CAST_SINKS,
                new CommandInfo(cast + "/get_sinks", HttpMethod.GET));
        mappings.put(ChromiumDriverCommand.SET_CAST_SINK_TO_USE,
                new CommandInfo(cast + "/set_sink_to_use", HttpMethod.POST));
        mappings.put(ChromiumDriverCommand.START_CAST_TAB_MIRRORING,
                new CommandInfo(cast + "/start_tab_mirroring", HttpMethod.POST));
        mappings.put(ChromiumDriverCommand.GET_CAST_ISSUE_MESSAGE,
                new CommandInfo(cast + "/get_issue_message", HttpMethod.GET));
        mappings.put(ChromiumDriverCommand.STOP_CASTING,
                new CommandInfo(cast + "/stop_casting", HttpMethod.POST));

        mappings.put(ChromiumDriverCommand.SET_PERMISSION,
                new CommandInfo(sessionPrefix + "/permissions", HttpMethod.POST));

        return unmodifiableMap(mappings);
    }

    static final class ChromiumDriverCommand {
        static final String LAUNCH_APP = "launchApp";
        static final String GET_NETWORK_CONDITIONS = "getNetworkConditions";
        static final String SET_NETWORK_CONDITIONS = "setNetworkConditions";
        static final String DELETE_NETWORK_CONDITIONS = "deleteNetworkConditions";
        static final String EXECUTE_CDP_COMMAND = "executeCdpCommand";
        // Cast Media Router APIs
        static final String GET_CAST_SINKS = "getCastSinks";
        static final String SET_CAST_SINK_TO_USE = "selectCastSink";
        static final String START_CAST_TAB_MIRRORING = "startCastTabMirroring";
        static final String GET_CAST_ISSUE_MESSAGE = "getCastIssueMessage";
        static final String STOP_CASTING = "stopCasting";
        static final String SET_PERMISSION = "setPermission";

        private ChromiumDriverCommand() {
        }
    }

}

// Run the following:

import io.cucumber.testng.AbstractTestNGCucumberTests;
import io.cucumber.testng.CucumberOptions;
import org.testng.annotations.Test;

@CucumberOptions(tags = "",
        features = {"src/test/resources/features/simplelogin.feature"},
        glue = {"cucumber.definition.simplelogin"},
        plugin = { "io.qameta.allure.cucumber7jvm.AllureCucumber7Jvm"})
@Test(groups = {"Login", "Regression"})
public class SimpleLoginStepsRunner extends AbstractTestNGCucumberTests {

}

// With the steps class
import io.cucumber.java.After;
import io.cucumber.java.Before;
import io.cucumber.java.Scenario;
import io.cucumber.java.en.Given;
import io.cucumber.java.en.Then;
import io.cucumber.java.en.When;
import org.openqa.selenium.By;
import org.openqa.selenium.WebElement;
import org.openqa.selenium.remote.RemoteWebDriver;

import java.net.URL;

public class SimpleLoginSteps {
    SetTimeout setTimeout;
    RemoteWebDriver driver;

    @Before
    public void setUp() throws Exception {
        setTimeout = new SetTimeout();
        driver = setTimeout.createDriver(new URL("http://localhost:4444/wd/hub"));
    }

    /**
     * Open my application.
     */
    @Given("I go to the website")
    public void openMyApplication() {
        driver.get(System.getProperty("url"));
    }

    /**
     * Add username.
     */
    @When("I log in using an appropriate user")
    public void addUsername() {
        WebElement usernameTextBox = driver.findElement(By.name("username"));
        usernameTextBox.sendKeys(System.getProperty("username"));

        WebElement passwordTextBox = driver.findElement(By.name("password"));
        passwordTextBox.sendKeys(System.getProperty("password"));

        driver.findElement(By.cssSelector("input[type='submit']")).click();
    }

    /**
     * Open my application.
     */
    @Then("I go to the page {string}")
    public void openMyApplication(String url) {
        long timer = System.currentTimeMillis();
        try {
            driver.get(url);
            System.out.println(driver.getTitle());
        } catch (Exception e) {
            System.out.println("Chrome Driver thread timed out: " + (System.currentTimeMillis() - timer));
            throw e;
        }
    }

    @After
    public void tearDown(Scenario scenario) {
        driver.quit();
        setTimeout.getChromeDriverService().stop();
    }
}

// using the feature file:
Feature: Login

  @login @RegressionTest
  Scenario: Login with valid username and password
    Given I go to the website
    When I log in using an appropriate user
    Then I go to the page "MY LONG RUNNING URL"

Relevant log output

In the tests I get the following logs:
------------------------------------------
Starting ChromeDriver 128.0.6613.84 (606aa55c7d687518d34b55accc5a71ea0bd28727-refs/branch-heads/6613@{#1335}) on port 32549
Only local connections are allowed.
Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
ChromeDriver was started successfully on port 32549.
Aug 27, 2024 7:28:08 PM org.openqa.selenium.remote.tracing.opentelemetry.OpenTelemetryTracer createTracer
INFO: Using OpenTelemetry for tracing
960000
960000
Chrome Driver thread timed out: 580644

Unable to execute request for an existing session: java.net.http.HttpTimeoutException: request timed out
Build info: version: '4.23.1', revision: '656257d8e9'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'
Driver info: driver.version: unknown
Build info: version: '4.23.1', revision: '656257d8e9'
System info: os.name: 'Windows 11', os.arch: 'amd64', os.version: '10.0', java.version: '17.0.11'
Driver info: org.openqa.selenium.remote.RemoteWebDriver
Command: [e800b7e2502019a519d0a2750a6e1f0a, get {url=MY LONG RUNNING URL}]
Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 127.0.6533.99, chrome: {chromedriverVersion: 127.0.6533.99 (f31af5097d90..., userDataDir: /tmp/.org.chromium.Chromium...}, fedcm:accounts: true, goog:chromeOptions: {debuggerAddress: localhost:40251}, goog:loggingPrefs: {performance: ALL}, networkConnectionEnabled: false, pageLoadStrategy: eager, platformName: linux, proxy: Proxy(), se:bidiEnabled: false, se:cdp: ws://172.26.0.3:4444/sessio..., se:cdpVersion: 127.0.6533.99, se:vnc: ws://172.26.0.3:4444/sessio..., se:vncEnabled: true, se:vncLocalAddress: ws://172.26.0.3:7900, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:extension:minPinLength: true, webauthn:extension:prf: true, webauthn:virtualAuthenticators: true}
Session ID: e800b7e2502019a519d0a2750a6e1f0a
org.openqa.selenium.WebDriverException: Unable to execute request for an existing session: java.net.http.HttpTimeoutException: request timed out
Build info: version: '4.23.1', revision: '656257d8e9'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'
Driver info: driver.version: unknown
Build info: version: '4.23.1', revision: '656257d8e9'
System info: os.name: 'Windows 11', os.arch: 'amd64', os.version: '10.0', java.version: '17.0.11'
Driver info: org.openqa.selenium.remote.RemoteWebDriver
Command: [e800b7e2502019a519d0a2750a6e1f0a, get {url=MY LONG RUNNING URL}]
Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 127.0.6533.99, chrome: {chromedriverVersion: 127.0.6533.99 (f31af5097d90..., userDataDir: /tmp/.org.chromium.Chromium...}, fedcm:accounts: true, goog:chromeOptions: {debuggerAddress: localhost:40251}, goog:loggingPrefs: {performance: ALL}, networkConnectionEnabled: false, pageLoadStrategy: eager, platformName: linux, proxy: Proxy(), se:bidiEnabled: false, se:cdp: ws://172.26.0.3:4444/sessio..., se:cdpVersion: 127.0.6533.99, se:vnc: ws://172.26.0.3:4444/sessio..., se:vncEnabled: true, se:vncLocalAddress: ws://172.26.0.3:7900, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:extension:minPinLength: true, webauthn:extension:prf: true, webauthn:virtualAuthenticators: true}
Session ID: e800b7e2502019a519d0a2750a6e1f0a
    at java.base@17.0.11/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at java.base@17.0.11/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
    at java.base@17.0.11/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.base@17.0.11/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
    at java.base@17.0.11/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
    at app//org.openqa.selenium.remote.ErrorCodec.decode(ErrorCodec.java:167)
    at app//org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:138)
    at app//org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:50)
    at app//org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:190)
    at app//org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:545)
    at app//org.openqa.selenium.remote.RemoteWebDriver.get(RemoteWebDriver.java:313)
    at app//cucumber.definition.simplelogin.SimpleLoginSteps.openMyApplication(SimpleLoginSteps.java:55)

-------------------------------------------
and in the docker chrome container I get
-------------------------------------------
2024-08-27T17:33:17.583271379Z 17:33:17.581 WARN [SpanWrappedHttpHandler.execute] - Unable to execute request: java.net.http.HttpTimeoutException: request timed out
2024-08-27T17:33:17.583362830Z Build info: version: '4.23.1', revision: '656257d8e9'
2024-08-27T17:33:17.583365926Z System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'
2024-08-27T17:33:17.583367843Z Driver info: driver.version: unknown
2024-08-27T17:33:17.583369746Z org.openqa.selenium.TimeoutException: java.net.http.HttpTimeoutException: request timed out
2024-08-27T17:33:17.583389755Z Build info: version: '4.23.1', revision: '656257d8e9'
2024-08-27T17:33:17.583391534Z System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'
2024-08-27T17:33:17.583393274Z Driver info: driver.version: unknown
2024-08-27T17:33:17.583394835Z  at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute0(JdkHttpClient.java:408)
2024-08-27T17:33:17.583397103Z  at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)
2024-08-27T17:33:17.583398796Z  at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:55)
2024-08-27T17:33:17.583400462Z  at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute(JdkHttpClient.java:374)
2024-08-27T17:33:17.583402168Z  at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:54)
2024-08-27T17:33:17.583403871Z  at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:90)
2024-08-27T17:33:17.583405504Z  at org.openqa.selenium.grid.node.DefaultActiveSession.execute(DefaultActiveSession.java:62)
2024-08-27T17:33:17.583407184Z  at org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:126)
2024-08-27T17:33:17.583408941Z  at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:633)
2024-08-27T17:33:17.583410627Z  at org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)
2024-08-27T17:33:17.583412273Z  at org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:397)
2024-08-27T17:33:17.583413882Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-27T17:33:17.583415568Z  at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:87)
2024-08-27T17:33:17.583417329Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-27T17:33:17.583418972Z  at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
2024-08-27T17:33:17.583420658Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-27T17:33:17.583423838Z  at org.openqa.selenium.grid.node.Node.execute(Node.java:270)
2024-08-27T17:33:17.583425794Z  at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
2024-08-27T17:33:17.583428975Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-27T17:33:17.583430656Z  at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)
2024-08-27T17:33:17.583432424Z  at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
2024-08-27T17:33:17.583433980Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-27T17:33:17.583435612Z  at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
2024-08-27T17:33:17.583437317Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-27T17:33:17.583441737Z  at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)
2024-08-27T17:33:17.583443440Z  at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
2024-08-27T17:33:17.583445036Z  at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-08-27T17:33:17.583446583Z  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2024-08-27T17:33:17.583448186Z  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2024-08-27T17:33:17.583449924Z  at java.base/java.lang.Thread.run(Thread.java:840)
2024-08-27T17:33:17.583451625Z Caused by: java.net.http.HttpTimeoutException: request timed out
2024-08-27T17:33:17.583453267Z  at java.net.http/jdk.internal.net.http.ResponseTimerEvent.handle(ResponseTimerEvent.java:63)
2024-08-27T17:33:17.583454896Z  at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1270)
2024-08-27T17:33:17.583456546Z  at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:899)
2024-08-27T17:33:17.587865063Z 17:33:17.586 WARN [SeleniumSpanExporter$1.lambda$export$1] - org.openqa.selenium.TimeoutException: java.net.http.HttpTimeoutException: request timed out
2024-08-27T17:33:17.587929517Z Build info: version: '4.23.1', revision: '656257d8e9'
2024-08-27T17:33:17.587933065Z System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'
2024-08-27T17:33:17.587935151Z Driver info: driver.version: unknown
2024-08-27T17:33:17.587936944Z  at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute0(JdkHttpClient.java:408)
2024-08-27T17:33:17.587939829Z  at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)
2024-08-27T17:33:17.587941573Z  at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:55)
2024-08-27T17:33:17.587943219Z  at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute(JdkHttpClient.java:374)
2024-08-27T17:33:17.587944860Z  at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:54)
2024-08-27T17:33:17.587946657Z  at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:90)
2024-08-27T17:33:17.587948532Z  at org.openqa.selenium.grid.node.DefaultActiveSession.execute(DefaultActiveSession.java:62)
2024-08-27T17:33:17.587950758Z  at org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:126)
2024-08-27T17:33:17.587953095Z  at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:633)
2024-08-27T17:33:17.587955327Z  at org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)
2024-08-27T17:33:17.587957096Z  at org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:397)
2024-08-27T17:33:17.587975412Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-27T17:33:17.587977400Z  at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:87)
2024-08-27T17:33:17.587979220Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-27T17:33:17.587980922Z  at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
2024-08-27T17:33:17.587983219Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-27T17:33:17.587984920Z  at org.openqa.selenium.grid.node.Node.execute(Node.java:270)
2024-08-27T17:33:17.587986495Z  at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
2024-08-27T17:33:17.587988217Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-27T17:33:17.587990033Z  at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)
2024-08-27T17:33:17.587993506Z  at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
2024-08-27T17:33:17.587995776Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-27T17:33:17.587997885Z  at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
2024-08-27T17:33:17.587999839Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-27T17:33:17.588001537Z  at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)
2024-08-27T17:33:17.588004141Z  at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
2024-08-27T17:33:17.588005894Z  at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-08-27T17:33:17.588008061Z  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2024-08-27T17:33:17.588009845Z  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2024-08-27T17:33:17.588011806Z  at java.base/java.lang.Thread.run(Thread.java:840)
2024-08-27T17:33:17.588014298Z Caused by: java.net.http.HttpTimeoutException: request timed out
2024-08-27T17:33:17.588015992Z  at java.net.http/jdk.internal.net.http.ResponseTimerEvent.handle(ResponseTimerEvent.java:63)
2024-08-27T17:33:17.588017753Z  at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1270)
2024-08-27T17:33:17.588019445Z  at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:899)
2024-08-27T17:33:17.588021489Z 
2024-08-27T17:33:17.588023095Z 17:33:17.587 WARN [SeleniumSpanExporter$1.lambda$export$1] - Unable to execute request: java.net.http.HttpTimeoutException: request timed out
2024-08-27T17:33:17.588024939Z Build info: version: '4.23.1', revision: '656257d8e9'
2024-08-27T17:33:17.588026637Z System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'
2024-08-27T17:33:17.588060549Z Driver info: driver.version: unknown
2024-08-27T17:33:17.590522344Z 17:33:17.589 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "5a030d9fbc546faaf7d48716350dfdc0","eventTime": 1724779990762414291,"eventName": "exception","attributes": {"exception.message": "Unable to execute request: java.net.http.HttpTimeoutException: request timed out\nBuild info: version: '4.23.1', revision: '656257d8e9'\nSystem info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'\nDriver info: driver.version: unknown","exception.stacktrace": "org.openqa.selenium.TimeoutException: java.net.http.HttpTimeoutException: request timed out\nBuild info: version: '4.23.1', revision: '656257d8e9'\nSystem info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute0(JdkHttpClient.java:408)\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:55)\n\tat org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute(JdkHttpClient.java:374)\n\tat org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:54)\n\tat org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:90)\n\tat org.openqa.selenium.grid.node.DefaultActiveSession.execute(DefaultActiveSession.java:62)\n\tat org.openqa.selenium.grid.node.local.SessionSlot.execute(SessionSlot.java:126)\n\tat org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:633)\n\tat org.openqa.selenium.grid.node.ForwardWebDriverCommand.execute(ForwardWebDriverCommand.java:35)\n\tat org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:397)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:69)\n\tat org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:87)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:69)\n\tat org.openqa.selenium.grid.node.Node.execute(Node.java:270)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:69)\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:63)\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:63)\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:539)\n\tat java.base\u002fjava.util.concurrent.FutureTask.run(FutureTask.java:264)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n\tat java.base\u002fjava.lang.Thread.run(Thread.java:840)\nCaused by: java.net.http.HttpTimeoutException: request timed out\n\tat java.net.http\u002fjdk.internal.net.http.ResponseTimerEvent.handle(ResponseTimerEvent.java:63)\n\tat java.net.http\u002fjdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1270)\n\tat java.net.http\u002fjdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:899)\n","exception.type": "org.openqa.selenium.TimeoutException","http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "172.26.0.3:5555","http.method": "POST","http.request_content_length": "105","http.scheme": "HTTP","http.target": "\u002fsession\u002fe800b7e2502019a519d0a2750a6e1f0a\u002furl","http.user_agent": "selenium\u002f4.23.1 (java windows)"}}

Operating System

Windows 11 and Docker

Selenium version

Java 4.23.1

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

Chrome Remote

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

Chrome Browser version 127.0.6533.99

Are you using Selenium Grid?

Grid version: 4.23.1

github-actions[bot] commented 2 months ago

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

codex70 commented 2 months ago
image

Here you can clearly see the test failing after exactly 9 minutes, followed by a further 9 minutes to quit and stop the driver in the tear down procedure.

diemol commented 2 months ago

Why are you not setting any timeout on the Grid?

codex70 commented 2 months ago

Why are you not setting any timeout on the Grid?

Because I wasn't aware that was an option, I must have missed that. Will try that now

codex70 commented 2 months ago

OK, I've tried with the following options in the docker compose file, but it hasn't made any difference:

  selenium-hub:
    image: selenium/hub:latest
    container_name: selenium-hub
    ports:
      - "4442:4442"
      - "4443:4443"
      - "4444:4444"
    environment:
      - GRID_TIMEOUT=960000
      - GRID_BROWSER_TIMEOUT=960000
      - SE_NODE_SESSION_TIMEOUT=960000

Are there any other settings for the chrome node container, or anything else that I might be missing?

diemol commented 2 months ago

GRID_TIMEOUT and GRID_BROWSER_TIMEOUT don't exist. Have you checked the docs at https://github.com/SeleniumHQ/docker-selenium?

codex70 commented 2 months ago

Thank you, the example I found must have been out of date.

I have now put:

    environment:
      - SE_NODE_SESSION_TIMEOUT=960000
      - SE_SESSION_REQUEST_TIMEOUT=960000

However this still makes no difference. One thing I did notice was that in the error message I get the following details from the driver, which do not appear to relate to any of the timeouts I have set:

timeouts: {implicit: 0, pageLoad: 300000, script: 30000}

Are there any other settings that I'm missing or have misunderstood?

codex70 commented 2 months ago

If I set the following options, they get passed through to selenium, but it still makes no difference:

        options.setImplicitWaitTimeout(clientTimeout);
        options.setPageLoadTimeout(defaultTimeout);
        options.setScriptTimeout(defaultTimeout);

Whatever settings I change, I still end up with the following errors in the selenium hub docker container:

15:57:10.157 WARN [SeleniumSpanExporter$1.lambda$export$1] - org.openqa.selenium.TimeoutException: java.net.http.HttpTimeoutException: request timed out
2024-08-28T15:57:10.158592962Z Build info: version: '4.23.1', revision: '656257d8e9'
2024-08-28T15:57:10.158596225Z System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.153.1-microsoft-standard-WSL2', java.version: '17.0.12'
2024-08-28T15:57:10.158598760Z Driver info: driver.version: unknown
2024-08-28T15:57:10.158601055Z  at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute0(JdkHttpClient.java:408)
2024-08-28T15:57:10.158604184Z  at org.openqa.selenium.remote.http.RetryRequest.lambda$apply$5(RetryRequest.java:81)
2024-08-28T15:57:10.158606401Z  at dev.failsafe.Functions.lambda$toCtxSupplier$11(Functions.java:243)
2024-08-28T15:57:10.158608620Z  at dev.failsafe.Functions.lambda$get$0(Functions.java:46)
2024-08-28T15:57:10.158610964Z  at dev.failsafe.internal.RetryPolicyExecutor.lambda$apply$0(RetryPolicyExecutor.java:74)
2024-08-28T15:57:10.158613151Z  at dev.failsafe.internal.RetryPolicyExecutor.lambda$apply$0(RetryPolicyExecutor.java:74)
2024-08-28T15:57:10.158626748Z  at dev.failsafe.internal.FallbackExecutor.lambda$apply$0(FallbackExecutor.java:51)
2024-08-28T15:57:10.158629231Z  at dev.failsafe.SyncExecutionImpl.executeSync(SyncExecutionImpl.java:187)
2024-08-28T15:57:10.158631440Z  at dev.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)
2024-08-28T15:57:10.158633684Z  at dev.failsafe.FailsafeExecutor.get(FailsafeExecutor.java:112)
2024-08-28T15:57:10.158635936Z  at org.openqa.selenium.remote.http.RetryRequest.lambda$apply$6(RetryRequest.java:81)
2024-08-28T15:57:10.158638225Z  at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)
2024-08-28T15:57:10.158640589Z  at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:55)
2024-08-28T15:57:10.158642755Z  at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute(JdkHttpClient.java:374)
2024-08-28T15:57:10.158644917Z  at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:54)
2024-08-28T15:57:10.158647114Z  at org.openqa.selenium.grid.web.ReverseProxyHandler.execute(ReverseProxyHandler.java:90)
2024-08-28T15:57:10.158649283Z  at org.openqa.selenium.grid.router.HandleSession.execute(HandleSession.java:181)
2024-08-28T15:57:10.158651434Z  at org.openqa.selenium.remote.http.Route$PredicatedRoute.handle(Route.java:397)
2024-08-28T15:57:10.158653615Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-28T15:57:10.158655807Z  at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
2024-08-28T15:57:10.158658082Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-28T15:57:10.158661594Z  at org.openqa.selenium.grid.router.Router.execute(Router.java:87)
2024-08-28T15:57:10.158663839Z  at org.openqa.selenium.grid.web.EnsureSpecCompliantResponseHeaders.lambda$apply$0(EnsureSpecCompliantResponseHeaders.java:34)
2024-08-28T15:57:10.158666106Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-28T15:57:10.158668245Z  at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
2024-08-28T15:57:10.158670517Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-28T15:57:10.158672718Z  at org.openqa.selenium.remote.http.Route$NestedRoute.handle(Route.java:270)
2024-08-28T15:57:10.158674909Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-28T15:57:10.158677168Z  at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
2024-08-28T15:57:10.158679502Z  at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
2024-08-28T15:57:10.158681929Z  at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)
2024-08-28T15:57:10.158684357Z  at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
2024-08-28T15:57:10.158686538Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-28T15:57:10.158691631Z  at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
2024-08-28T15:57:10.158693866Z  at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
2024-08-28T15:57:10.158695974Z  at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)
2024-08-28T15:57:10.158700042Z  at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
2024-08-28T15:57:10.158702628Z  at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-08-28T15:57:10.158704794Z  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2024-08-28T15:57:10.158706967Z  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2024-08-28T15:57:10.158709164Z  at java.base/java.lang.Thread.run(Thread.java:840)
2024-08-28T15:57:10.158711293Z Caused by: java.net.http.HttpTimeoutException: request timed out
2024-08-28T15:57:10.158713455Z  at java.net.http/jdk.internal.net.http.ResponseTimerEvent.handle(ResponseTimerEvent.java:63)
2024-08-28T15:57:10.158715696Z  at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1270)
2024-08-28T15:57:10.158717958Z  at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:899)

It still consistently fails at 9 minutes, then takes a further 9 minutes to close and stop the driver.

codex70 commented 2 months ago

As a follow up, if I run with standalone chrome instead of going through selenium hub, the above code works as expected and there are no timeouts. It doesn't really solve the problem, but for me, for the time being, this is a work around I can live with.

@diemol, thank you for all your help, I'm not sure if you want me to close this issue, or leave it open?