ChromeDriver randomly "freezes" for 70-90 seconds, causing tests to timeout

[Uri Goldstein]

Hello All,

Perhaps someone can help me figure out why the below is happening and fix it?

Given:

• All the below are on Windows 10 / Server 2012 R2
  
• Selenium .Net (C#) tests (Selenium.WebDriver nuget v3.141.0, .Net Framework v4.8)
• ChromeDriver 78.0.3904.70
• Google Chrome Version 78.0.3904.97 (Official Build) (64-bit)
• Tests run automatically by Azure DevOps Server (installed on-prem)

When:

Seemingly randomly once every few hours (one out of every few dozens of tests runs)

Then:

ChromeDriver logs seem to show it freezing for ~70-90 seconds and then resuming. Please see log snippet quoted below.
Test-side (C#) driver class times out after 60 seconds of ChromeDriver inactivity and fails the test.

These "freezes" occur at random times, in random parts of the test suite. Sometime following a ClickElement command, sometimes following a Navigate command. 

Please note:

The line where the freeze occurs seems to always be similar to this:

[1580975930.724][DEBUG]: DevTools WebSocket Command: Runtime.evaluate (id=265) 3DF35569FFFA4540EA485ED9C4383B72 {
   "expression": "1"

C# timeout exception looks like this:

'OpenQA.Selenium.WebDriverException : The HTTP request to the remote WebDriver server for URL http://localhost:25890/session/8ae62a10147ba1c9c0bc8f0ae6e47eed/element/fbd0ddbd-c198-4aa8-b05a-8a1d40766d83/click timed out after 60 seconds.
  ----> System.Net.WebException : The operation has timed out'.
 Stack trace:
   at OpenQA.Selenium.Remote.HttpCommandExecutor.MakeHttpRequest(HttpRequestInfo requestInfo)
   at OpenQA.Selenium.Remote.HttpCommandExecutor.Execute(Command commandToExecute)
   at OpenQA.Selenium.Remote.DriverServiceCommandExecutor.Execute(Command commandToExecute)
   at OpenQA.Selenium.Remote.RemoteWebDriver.Execute(String driverCommandToExecute, Dictionary`2 parameters)
   at OpenQA.Selenium.Remote.RemoteWebElement.Execute(String commandToExecute, Dictionary`2 parameters)
   at OpenQA.Selenium.Remote.RemoteWebElement.Click()
   ...

Log snippet from ChromeDriver:

[1580975930.723][INFO]: Waiting for pending navigations...
[1580975930.723][DEBUG]: DevTools WebSocket Event: Page.frameScheduledNavigation 3DF35569FFFA4540EA485ED9C4383B72 {
   "delay": 0,
   "frameId": "3DF35569FFFA4540EA485ED9C4383B72",
   "reason": "formSubmissionPost",
   "url": "https://site-under-test/some-page"
}
[1580975930.724][DEBUG]: DevTools WebSocket Event: Page.frameRequestedNavigation 3DF35569FFFA4540EA485ED9C4383B72 {
   "frameId": "3DF35569FFFA4540EA485ED9C4383B72",
   "reason": "formSubmissionPost",
   "url": "https://site-under-test/some-page"
}
[1580975930.724][DEBUG]: DevTools WebSocket Event: Page.frameStartedLoading 3DF35569FFFA4540EA485ED9C4383B72 {
   "frameId": "3DF35569FFFA4540EA485ED9C4383B72"
}
[1580975930.724][DEBUG]: DevTools WebSocket Event: Page.frameClearedScheduledNavigation 3DF35569FFFA4540EA485ED9C4383B72 {
   "frameId": "3DF35569FFFA4540EA485ED9C4383B72"
}
[1580975930.724][DEBUG]: DevTools WebSocket Command: Runtime.evaluate (id=265) 3DF35569FFFA4540EA485ED9C4383B72 {
   "expression": "1"
} 

******************************************************************
***** The line above is the one that freezes. Note timestamp *****
******************************************************************
  
[1580976006.271][DEBUG]: DevTools WebSocket Event: Runtime.executionContextDestroyed 3DF35569FFFA4540EA485ED9C4383B72 {
   "executionContextId": 5
}
[1580976006.271][DEBUG]: DevTools WebSocket Event: Runtime.executionContextsCleared 3DF35569FFFA4540EA485ED9C4383B72 {

}
[1580976006.271][DEBUG]: DevTools WebSocket Event: Page.frameNavigated 3DF35569FFFA4540EA485ED9C4383B72 {
   "frame": {
      "id": "3DF35569FFFA4540EA485ED9C4383B72",
      "loaderId": "29E7B61049A044FA7CE34819B5BFA9B3",
      "mimeType": "text/html",
      "securityOrigin": "https://site-under-test",
      "url": "https://site-under-test/some-page"
   }
}
[1580976006.271][DEBUG]: DevTools WebSocket Event: Runtime.executionContextCreated 3DF35569FFFA4540EA485ED9C4383B72 {
   "context": {
      "auxData": {
         "frameId": "3DF35569FFFA4540EA485ED9C4383B72",
         "isDefault": true,
         "type": "default"
      },
      "id": 6,
      "name": "",
      "origin": "https://site-under-test"
   }
}
[1580976006.271][DEBUG]: DevTools WebSocket Event: DOM.documentUpdated 3DF35569FFFA4540EA485ED9C4383B72 {

}
[1580976006.271][DEBUG]: DevTools WebSocket Command: DOM.getDocument (id=266) 3DF35569FFFA4540EA485ED9C4383B72 {

}
[1580976006.272][DEBUG]: DevTools WebSocket Response: Runtime.evaluate (id=265) 3DF35569FFFA4540EA485ED9C4383B72 {
   "result": {
      "description": "1",
      "type": "number",
      "value": 1
   }
}

How can I further investigate what the cause of the "freeze" is and fix it?


Thanks,
urig

[T Crichton]

We're not sure what is causing this or if it is Chrome or ChromeDriver that is freezing. The interval in the log is at a point in the ChromeDriver code when it is listening on a WebSocket for communication from Chrome.

Please try the following:

1) Look in the system event log to see if there are any relevant events at the time that the freeze occurred.

2) Please download the ProcMon from Microsoft: https://docs.microsoft.com/en-us/sysinternals/downloads/procmon and both Chrome and ChromeDriver during the freeze.

We've seen similar freezes in our continuous builds, and are experimenting with forcing a Chrome crash when this occurs to see what is happening in the Chrome side. This requires starting a second ChromeDriver pointing to the same ChromeInstance; I can give you more information if the logs and monitoring don't help.

[Uri Goldstein]

Hi,

I just wanted to say thank you for the detailed response and helpful suggestions.

I've not see anything meaningful in the machine event log and catching the issue when it happens is difficult as it occurs randomly. My current approach is to move the CI agent to a clean, isolated VM to see if interference with other chromedriver.exe / chrome.exe instances is the source. If it isn't I would love to ask for the instructions to crash chrome for diags.

Thanks again,

Uri G.

[T Crichton]

We added the crash in the release tests, which don't use Selenium. That made some of these steps easier. I'll try to translate that to Selenium, but I haven't tried this:

Chrome needs to be started with 2 additional environment variables: CHROME_HEADLESS=1 and BREAKPAD_DUMP_LOCATION=some writable folder. If you run in Linux, you can set this by adding ChromeOptions.MinidumpPath. That will be available for Windows starting with version 82.

Next you need a second ChromeDriver pointing to the same instance of Chrome.

You need the debuggerAddress used by the original Chrome instance. I don't think Selenium exposes that, so you would have to find it in the verbose log file. It's part of the RESPONSE InitSession entry:

      "goog:chromeOptions": {

         "debuggerAddress": "localhost:46837"

      },

You should also be able to pick a port, by adding the argument --remote-debugging-port=<port> when starting Chrome.

The new ChromeDriver needs to run with ChromeOptions.DebuggerAddress set the the value found or set above. Several other options won't work at all in this new Chrome so don't set more than that.

The command needed is:

driver.ExecuteChromeCommand("Page.crash", new Dictionary<string, object>());

This won't work if the freeze is during initSession. It will throw an exception from Selenium, because ChromeDriver won't be able to process the post-command cleanup once the page crashes. But check the exception, because Chrome can refuse the request, which will also generate an exception. If the message contains "session deleted because of page crash", it worked as expected. The crash report should be in BREAKPAD_DUMP_LOCATION. 

[Uri Goldstein]

Hi Tricia,

Big thanks to you for the details of how to debug browser freezes. I really appreciate your help.

Do I understand correctly the process is manual? In my case, running in a CI server (Azure DevOps Pipelines) I don't think I can execute it manually in the right time. I can RDP into the agent running the test but I don't think I can detect the freeze and respond in time before timing out.

If I may ask another question - The .net ChromeDriver class times out after 60 seconds of not hearing back from chromedriver.exe. Is there any way I can extend the length of this timeout? I've tried setting the PageLoad timeout to no avail.

Cheers,

Uri

[T Crichton]

Hi Uri,

It doesn't have to be manual. Our tests catch a timeout and then create the new driver and request a crash. But our tests use our own python based client, not Selenium's. That lets us read the InitSession Response to capture the debugger address. If you can specify remote-debugging-port when starting your tests, the port will be known. Host is usually localhost.

There are constructors that take a commandTimeout parameter:

public ChromeDriver(string chromeDriverDirectory, ChromeOptions options, TimeSpan commandTimeout)

public ChromeDriver(ChromeDriverService service, ChromeOptions options, TimeSpan commandTimeout)

I'm not sure what version of Selenium includes them.

-Tricia

[Uri Goldstein]

Hello and thanks again Tricia,

I've followed your (very clear) instructions and I've come up with this bit of code to crash Chrome on demand from C#:

    // Start primary driver

    var options = new ChromeOptions {  MinidumpPath = @"C:\dev\git\urig\SeleniumLogs\SeleniumLogs\" };
    options.AddArguments("--headless");
    var driver = new ChromeDriver(options);
    driver.Navigate().GoToUrl("https://www.google.com/");

    // Get Chrome debugger address

    var capability = driver.Capabilities["goog:chromeOptions"] as Dictionary<string, object>;
    var debuggerAddress = capability?["debuggerAddress"]?.ToString();

    // Start a second driver pointed to debugger address

    var crashOptions = new ChromeOptions
    {
        DebuggerAddress = debuggerAddress
    };
    crashOptions.AddArguments("--headless");
    var crashDriver = new ChromeDriver(crashOptions);

    // Crash Chrome via second driver

    try
    {
        crashDriver.ExecuteChromeCommand("Page.crash", new Dictionary<string, object>());
    }
    catch (Exception ex)
    {
        Console.WriteLine($"ERROR: {ex}");
    }
    finally
    {
        driver.Quit();
        crashDriver.Quit();
    }

On top of setting MinidumpPath in code I've also set the BREAKPAD_DUMP_LOCATION system variable on my Windows machine.

The code successfully crashes Chrome but I've not seen any dump files created. Might you know why?

Maybe it's because I'm indeed getting this exception when calling ExecuteChromeCommand()?

    unknown error: session deleted because of page crash
    from unknown error: cannot determine loading status
    from tab crashed

Thanks,

urig

[T Crichton]

Hi Uri,

Nice find retrieving the debuggerAddress from Selenium. I didn't know it was there; that's good to know.

You don't mention setting environment variable  CHROME_HEADLESS=1. That bypasses the default behavior which tries to upload the dump file somewhere.  This is different than the headless switch for Chrome, which is not required to generate the dump.

-Tricia

[Uri Goldstein]

Thanks again Tricia :)

Indeed I didn't set CHROME_HEADLESS=1. I did set it now but to no avail.

Both with and without "--headless" as an argument, I'm still not finding a dump file.

What should the filename look like, BTW?

Thanks,

Uri

[T Crichton]

Hi Uri,

Oops, I missed a step..

You also need the chrome argument --enable-crash-reporter-for-testing.

On Windows, the dump would be something like:

reports\4a82d081-f069-4a77-9bf9-6ee037a44d41.dmp

with reports being a directory under the one specified by BREAKPAD_DUMP_LOCATION.

-Tricia