chutzpah icon indicating copy to clipboard operation
chutzpah copied to clipboard

Occasional "Error: Timeout occurred when executing test file" under vstest.console.exe

Open M0ns1gn0r opened this issue 2 years ago • 0 comments

I occasionally get Error: Timeout occurred when executing test file on the build machine which runs the tests via vstest.console.exe. I can't really find the pattern, it's very sporadic, therefore I enabled tracing in the Chutzpah.json:

{
  "Engine": "Chrome",
  "EngineOptions": {
    "ChromeBrowserPath": "C:\\Program Files\\Google\\Chrome\\Application\\chrome.exe"
  },
  "EnableTracing": true
}

Here are log excerpts from a successful and a failing run.

Successful run

vstest.console.exe Information: 0 : Time:11:32:38.4929608; Thread:8; Message:Invoking headless browser on test harness 'C:\_agents\<redacted>\_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html' for file 'C:\_agents\<redacted>\RestoringCursorPositionTests.js'
vstest.console.exe Information: 0 : Time:11:32:38.5179625; Thread:8; Message:Started headless browser: <path_to_Chutzpah.4.4.12>\Node\x86\node.exe with PID: 5576 using args:  "<path_to_Chutzpah.4.4.12>\ChutzpahJSRunners\Chrome\qunitRunner.js" "http://localhost:9876/_agents/<redacted>/_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html" execution 10000 True False "C:\Program Files\Google\Chrome\Application\chrome.exe" "" ""
vstest.console.exe Information: 0 : Time:11:32:40.6261499; Thread:10; Message:Phantom Log - Using Chrome Install : C:\Program Files\Google\Chrome\Application\chrome.exe
vstest.console.exe Information: 0 : Time:11:32:40.6431518; Thread:10; Message:Phantom Log - puppeteer browser args: ["--disable-web-security","--no-sandbox"]
vstest.console.exe Information: 0 : Time:11:32:42.5073186; Thread:10; Message:Phantom Log - Resource Received: http://localhost:9876/_agents/<redacted>/_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html
vstest.console.exe Information: 0 : Time:11:32:42.5573229; Thread:10; Message:Phantom Log - isQunitLoaded
vstest.console.exe Information: 0 : Time:11:32:42.6563311; Thread:10; Message:Phantom Log - Resource Received: http://localhost:9876/_agents/<redacted>/TargetEditor.css?sha=5cb878ddd5a62ea6ef9e128e2d834cab766009a7
vstest.console.exe Information: 0 : Time:11:32:42.6713315; Thread:10; Message:Phantom Log - Resource Received: http://localhost:9876/__chutzpah__/chutzpah_boot.js?sha=6befcd00fd543581d2a8ac76e852d5909901f326
vstest.console.exe Information: 0 : Time:11:32:42.6973347; Thread:10; Message:Phantom Log - isQunitLoaded
vstest.console.exe Information: 0 : Time:11:32:42.8493485; Thread:10; Message:Phantom Log - Resource Received: http://localhost:9876/__chutzpah__/QUnit/v1/qunit.css?sha=59fa172bfe0e043feb694fbff923fd3d221c0026
vstest.console.exe Information: 0 : Time:11:32:42.9043536; Thread:10; Message:Phantom Log - Resource Received: http://localhost:9876/_agents/<redacted>/Utils/preInit.js?sha=9b6369360c4ada3815cbdaa2d503b72af48ce370
...many similar lines skipped...
vstest.console.exe Information: 0 : Time:11:32:47.3227469; Thread:8; Message:Test harness 'C:\_agents\<redacted>\_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html' for file 'C:\_agents\<redacted>\RestoringCursorPositionTests.js' finished with 35 passed, 0 failed and 0 errors
vstest.console.exe Information: 0 : Time:11:32:47.3447504; Thread:8; Message:Finished running headless browser on test harness 'C:\_agents\<redacted>\_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html' for file 'C:\_agents\<redacted>\RestoringCursorPositionTests.js'
vstest.console.exe Information: 0 : Time:11:32:47.3627507; Thread:8; Message:Finished test run for C:\_agents\<redacted>\RestoringCursorPositionTests.js in Execution mode

Failed run

vstest.console.exe Information: 0 : Time:12:23:43.1363162; Thread:8; Message:Invoking headless browser on test harness 'C:\_agents\<redacted>\_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html' for file 'C:\_agents\<redacted>\RestoringCursorPositionTests.js'
vstest.console.exe Information: 0 : Time:12:23:43.8383799; Thread:8; Message:Started headless browser: <path_to_Chutzpah.4.4.12>\Node\x86\node.exe with PID: 1792 using args:  "<path_to_Chutzpah.4.4.12>\ChutzpahJSRunners\Chrome\qunitRunner.js" "http://localhost:9876/_agents/<redacted>/_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html" execution 10000 True False "C:\Program Files\Google\Chrome\Application\chrome.exe" "" ""
vstest.console.exe Information: 0 : Time:12:23:46.5776240; Thread:6; Message:Phantom Log - Using Chrome Install : C:\Program Files\Google\Chrome\Application\chrome.exe
vstest.console.exe Information: 0 : Time:12:23:46.6176283; Thread:6; Message:Phantom Log - puppeteer browser args: ["--disable-web-security","--no-sandbox"]
vstest.console.exe Error: 0 : Time:12:23:57.1475751; Thread:8; Message:Test file 'C:\_agents\<redacted>\RestoringCursorPositionTests.js' timed out after running for 10502.9452 milliseconds
vstest.console.exe Information: 0 : Time:12:23:57.1985723; Thread:8; Message:Ended headless browser: <path_to_Chutzpah.4.4.12>\Node\x86\node.exe with PID: 1792 using args:  "<path_to_Chutzpah.4.4.12>\ChutzpahJSRunners\Chrome\qunitRunner.js" "http://localhost:9876/_agents/<redacted>/_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html" execution 10000 True False "C:\Program Files\Google\Chrome\Application\chrome.exe" "" ""
vstest.console.exe Error: 0 : Time:12:23:57.2395754; Thread:8; Message:Headless browser returned with an error: Timeout occurred when executing test file
vstest.console.exe Information: 0 : Time:12:23:57.2875808; Thread:8; Message:Test harness 'C:\_agents\<redacted>\_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html' for file 'C:\_agents\<redacted>\RestoringCursorPositionTests.js' finished with 0 passed, 0 failed and 1 errors
vstest.console.exe Information: 0 : Time:12:23:57.3205833; Thread:8; Message:Finished running headless browser on test harness 'C:\_agents\<redacted>\_Chutzpah.87ef6c34eb5ec093d62ffa993dcf1e82baa79268.test.html' for file 'C:\_agents\<redacted>\RestoringCursorPositionTests.js'
vstest.console.exe Information: 0 : Time:12:23:57.3595865; Thread:8; Message:Finished test run for C:\_agents\<redacted>\RestoringCursorPositionTests.js in Execution mode

Basically, there are no Resource Received: http://... entries in the failed run log. Looks like the harness didn't even start to load. Are there any ideas on what other diagnostics I could perform?

P.S. I had to clean-up and simplify the logs to paste them here publicly. I can provide the full logs if needed.

M0ns1gn0r avatar Jun 23 '22 11:06 M0ns1gn0r