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.
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 timestamps *****
*******************************************************************
[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?
