Huge times to navigate to test page with `browser.get('url')`

pmenichelli commented 1 year ago

System

Version: 32.2 and 32.1
Platform: Centos 8
Firefox: 107.0.1
Selenium: Selenium Grid 4.8.0

Testcase

When running a simple test, selenium seems to be hanging sometimes when navigating to the test page. This happens in our CI where we run the Hub and the Node on different servers with Centos 8. I'm also able to reproduce this locally with a container (hub runs on the container and node on my host Mac)

It seems that browser.get() takes a huge time to load the page.

This does not always happen, but from every 10 times I run the test locally (I pass the --benchmark=10 flag) at least one of them takes a huge time to load.

The only interesting thing I noticed from the trace log is that when it does take too long, the console gets stuck at this message:

1676475367827   Marionette  TRACE   [11] Received event DOMContentLoaded for https://example.test/test/widget/

Then it usually hangs there for like 300 seconds and after that the test continues normally.

I'm not providing the HTML test page that I use cause I feel this is already a lot of info, but in case you need it I can provide it, it's a very simple test page with an iframe, no application framework or anything special.

Test:

import os

from selenium import webdriver
from selenium.webdriver.common.keys import Keys
from selenium.webdriver.common.by import By
from selenium.webdriver.firefox.options import Options as FirefoxOptions
from testtools import TestCase

class GeckoBugTest(TestCase):
    def test_browse_widget_page(self):
        # Set Firefox options
        browser_options = FirefoxOptions()
        firefox_prefs = {
            "permissions.default.microphone": 1,
            "permissions.default.camera": 1,
            "media.navigator.streams.fake": 1
        }
        for key, value in firefox_prefs.items():
            browser_options.set_preference(key, value)

        browser_options.log.level = "trace"

        # Get a driver instance
        driver = webdriver.Remote(
            command_executor="http://<selenium hub address>,
            options=browser_options,
        )

        # Navigate to the page
        with CodeTimer('>>> navigating to test page...'):
            driver.get("https://example.test/geckodriver_bug.html")

        title = driver.find_element(By.ID, "title")
        self.assertEqual(title.text, "Widget test page")
        driver.close()

import timeit

class CodeTimer:
    def __init__(self, name=None):
        self.name = " '"  + name + "'" if name else ''

    def __enter__(self):
        self.start = timeit.default_timer()

    def __exit__(self, exc_type, exc_value, traceback):
        self.took = (timeit.default_timer() - self.start) * 1000.0
        print('>>> Navigation finished, took: ' + str(self.took) + ' ms')

#>>> Navigation finished, took: 653.3095860213507 ms
#>>> Navigation finished, took: 523.6317339877132 ms
#>>> Navigation finished, took: 556.7021780007053 ms
#>>> Navigation finished, took: 325405.6838050019 ms    <--- too long
#>>> Navigation finished, took: 550.3500399936456 ms
#>>> Navigation finished, took: 454.90353400236927 ms
#>>> Navigation finished, took: 460.6272779928986 ms
#>>> Navigation finished, took: 441.08089798828587 ms
#>>> Navigation finished, took: 406.7903950053733 ms
#>>> Navigation finished, took: 325300.6978199992 ms     <--- too long

Stacktrace

In the trace log I see a couple of stack traces like this one. Not sure if it's relevant.

16:35:50.902 WARN [SeleniumSpanExporter$1.lambda$export$1] - Unable to execute request: java.util.concurrent.TimeoutException
Build info: version: '4.8.0', revision: '267030adea'
System info: os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '11.5', java.version: '11.0.11'
Driver info: driver.version: unknown
16:35:50.902 WARN [SeleniumSpanExporter$1.lambda$export$1] - org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException
Build info: version: '4.8.0', revision: '267030adea'
System info: os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '11.5', java.version: '11.0.11'
Driver info: driver.version: unknown
    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:65)
    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:99)
    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:127)
    at org.openqa.selenium.grid.node.local.LocalNode.executeWebDriverCommand(LocalNode.java:470)
    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:245)
    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:59)
    ... 32 more

1676475350902   webdriver::server   DEBUG   <- 500 Internal Server Error {"value":{"error":"timeout","message":"TimedPromise timed out after 300000 ms","stacktrace":"Rem ... rome://remote/content/shared/webdriver/Errors.sys.mjs:471:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:212:19\n"}}

Trace-level log

trace-level-log.txt

pmenichelli commented 1 year ago

The closest I found was this issue and I tried upgrading to Java 11 plus forcing selenium to use the builtin HTTP client but that didn't solve the issue.

whimboo commented 1 year ago

The problem here seems to be that the test page never finishes loading and as such no load event is received by Marionette` which would mark the navigation as done. @pmenichelli when you are running the test do you actually see the Firefox window or is it all in headless mode?

One thing you might wanna try is to run some network logging eg with wireshark on the same machine where Firefox runs. Maybe that indicates a problem. Otherwise the Firefox profiler could be used while the test is running and the log uploaded for investigation.

whimboo commented 1 year ago

No response from the reporter. Closing.

mozilla / geckodriver