Azure Pipeline "ChromeHeadless have not captured in 60000 ms, killing.", works on second t-CodePudding

I am experiencing intermittent build failures with ng test that I think have to do with instances of ChromeHeadless hanging out after failing to properly connect. My Azure pipeline always chirps with one ChromeHeadless have not captured in 60000 ms, killing. (like this question) but then will run the unit tests just fine. The tests will pass about half the time the build goes green. The other half I get a node nonzero exit code error.

Command: ng test --code-coverage --browsers=ChromeHeadless --watch=false

Success Log:

2021-11-15T22:59:09.9297050Z > ng test --code-coverage --browsers=ChromeHeadless --watch=false
2021-11-15T22:59:09.9297547Z 
2021-11-15T22:59:09.9298696Z 15 11 2021 22:55:02.738:WARN [karma-server]: Passing raw CLI options to `new Server(config, done)` is deprecated. Use `parseConfig(configFilePath, cliOptions, {promiseConfig: true, throwErrors: true})` to prepare a processed `Config` instance and pass that as the `config` argument instead.
2021-11-15T22:59:09.9300540Z 15 11 2021 22:55:53.494:INFO [karma-server]: Karma v6.3.4 server started at http://localhost:9876/
2021-11-15T22:59:09.9302562Z 15 11 2021 22:55:53.495:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
2021-11-15T22:59:09.9305118Z 15 11 2021 22:55:53.501:INFO [launcher]: Starting browser ChromeHeadless
2021-11-15T22:59:09.9306242Z 15 11 2021 22:56:53.528:WARN [launcher]: ChromeHeadless have not captured in 60000 ms, killing.
2021-11-15T22:59:09.9307283Z 15 11 2021 22:56:56.344:INFO [launcher]: Trying to start ChromeHeadless again (1/2).
2021-11-15T22:59:09.9308355Z 15 11 2021 22:57:08.714:INFO [Chrome Headless 95.0.4638.69 (Windows 10)]: Connected on socket 7GsL_H9cLK7nNS-0AAAB with id 24622884
2021-11-15T22:59:09.9309742Z Chrome Headless 95.0.4638.69 (Windows 10): Executed 0 of 5191[32m SUCCESS[39m (0 secs / 0 secs)
2021-11-15T22:59:09.9311289Z [1A[2KChrome Headless 95.0.4638.69 (Windows 10): Executed 1 of 5191[32m SUCCESS[39m (0 secs / 0.09 secs)

...snip a bunch of test lines...

2021-11-15T22:59:10.4682949Z [1A[2KChrome Headless 95.0.4638.69 (Windows 10): Executed 5191 of 5191[32m SUCCESS[39m (1 min 48.797 secs / 40.407 secs)
2021-11-15T22:59:10.4683432Z [32mTOTAL: 5191 SUCCESS[39m
2021-11-15T22:59:10.4683751Z TOTAL: 5191 SUCCESS
2021-11-15T22:59:10.4685421Z ##[debug]rm -rf D:\a\1\npm\1808514.npmrc
2021-11-15T22:59:10.4686006Z ##[debug]removing file D:\a\1\npm\1808514.npmrc
2021-11-15T22:59:10.4687970Z ##[debug]Agent.BuildDirectory=D:\a\1
2021-11-15T22:59:10.4688686Z ##[debug]rm -rf D:\a\1\npm
2021-11-15T22:59:10.4690143Z ##[debug]removing directory D:\a\1\npm
2021-11-15T22:59:10.4694691Z ##[section]Finishing: Running Unit Tests

Failure log:

2021-11-15T23:00:13.5726081Z > ng test --code-coverage --browsers=ChromeHeadless --watch=false
2021-11-15T23:00:13.5726931Z 
2021-11-15T23:00:13.5728815Z 15 11 2021 22:55:00.157:WARN [karma-server]: Passing raw CLI options to `new Server(config, done)` is deprecated. Use `parseConfig(configFilePath, cliOptions, {promiseConfig: true, throwErrors: true})` to prepare a processed `Config` instance and pass that as the `config` argument instead.
2021-11-15T23:00:13.5731137Z 15 11 2021 22:56:23.079:INFO [karma-server]: Karma v6.3.4 server started at http://localhost:9876/
2021-11-15T23:00:13.5733401Z 15 11 2021 22:56:23.081:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
2021-11-15T23:00:13.5735288Z 15 11 2021 22:56:23.087:INFO [launcher]: Starting browser ChromeHeadless
2021-11-15T23:00:13.5736548Z 15 11 2021 22:57:24.479:WARN [launcher]: ChromeHeadless have not captured in 60000 ms, killing.
2021-11-15T23:00:13.5737814Z 15 11 2021 22:57:34.284:INFO [launcher]: Trying to start ChromeHeadless again (1/2).
2021-11-15T23:00:13.5739190Z 15 11 2021 22:58:00.870:INFO [Chrome Headless 95.0.4638.69 (Windows 10)]: Connected on socket C0MkTPwSkT-fXggHAAAB with id 78277967
2021-11-15T23:00:13.5740882Z Chrome Headless 95.0.4638.69 (Windows 10): Executed 0 of 5191[32m SUCCESS[39m (0 secs / 0 secs)
2021-11-15T23:00:13.5743230Z [1A[2KChrome Headless 95.0.4638.69 (Windows 10): Executed 1 of 5191[32m SUCCESS[39m (0 secs / 0.103 secs)

...snip a bunch of test lines...

2021-11-15T23:00:14.2929797Z [1A[2KChrome Headless 95.0.4638.69 (Windows 10): Executed 5191 of 5191[32m SUCCESS[39m (0 secs / 48.607 secs)
2021-11-15T23:00:14.2930731Z 15 11 2021 23:00:12.864:WARN [Chrome Headless 95.0.4638.69 (Windows 10)]: Disconnected (0 times) reconnect failed before timeout of 2000ms (ping timeout)
2021-11-15T23:00:14.2931733Z [1A[2K[31mChrome Headless 95.0.4638.69 (Windows 10) ERROR[39m
2021-11-15T23:00:14.2932881Z   Disconnected reconnect failed before timeout of 2000ms (ping timeout)
2021-11-15T23:00:14.2933725Z Chrome Headless 95.0.4638.69 (Windows 10): Executed 5191 of 5191[31m DISCONNECTED[39m (2 mins 1.613 secs / 48.607 secs)
2021-11-15T23:00:14.2934480Z Chrome Headless 95.0.4638.69 (Windows 10) ERROR
2021-11-15T23:00:14.2935136Z   Disconnected reconnect failed before timeout of 2000ms (ping timeout)
2021-11-15T23:00:14.2935937Z [1A[2KChrome Headless 95.0.4638.69 (Windows 10): Executed 5191 of 5191[31m DISCONNECTED[39m (2 mins 1.613 secs / 48.607 secs)

... snip some config output...

2021-11-15T23:00:14.3395972Z ##[debug]pattern: '*-debug.log'
2021-11-15T23:00:14.3396710Z ##[debug]findPath: 'C:\npm\cache\_logs'
2021-11-15T23:00:14.3397422Z ##[debug]statOnly: 'false'
2021-11-15T23:00:14.3398156Z ##[debug]findPath: 'C:\npm\cache\_logs'
2021-11-15T23:00:14.3399116Z ##[debug]findOptions.allowBrokenSymbolicLinks: 'false'
2021-11-15T23:00:14.3399977Z ##[debug]findOptions.followSpecifiedSymbolicLink: 'true'
2021-11-15T23:00:14.3400817Z ##[debug]findOptions.followSymbolicLinks: 'true'
2021-11-15T23:00:14.3401559Z ##[debug]0 results
2021-11-15T23:00:14.3402490Z ##[debug]found 0 paths
2021-11-15T23:00:14.3404014Z ##[debug]applying include pattern
2021-11-15T23:00:14.3405865Z ##[debug]adjustedPattern: 'C:\npm\cache\_logs\*-debug.log'
2021-11-15T23:00:14.3407657Z ##[debug]0 matches
2021-11-15T23:00:14.3409050Z ##[debug]0 final results
2021-11-15T23:00:14.3410115Z ##[debug]Trying debug log location: D:\a\1\s\npm-debug.log
2021-11-15T23:00:14.3457007Z ##[warning]Couldn't find a debug log in the cache or working directory
2021-11-15T23:00:14.3478105Z ##[debug]Processed: ##vso[task.issue type=warning;]Couldn't find a debug log in the cache or working directory
2021-11-15T23:00:14.3479818Z ##[debug]Agent.BuildDirectory=D:\a\1
2021-11-15T23:00:14.3480813Z ##[debug]rm -rf D:\a\1\npm
2021-11-15T23:00:14.3482353Z ##[debug]removing directory D:\a\1\npm
2021-11-15T23:00:14.3483408Z ##[debug]task result: Failed
2021-11-15T23:00:14.3485013Z ##[error]Error: Npm failed with return code: 1
2021-11-15T23:00:14.3486527Z ##[debug]Processed: ##vso[task.issue type=error;]Error: Npm failed with return code: 1
2021-11-15T23:00:14.3496428Z ##[debug]Processed: ##vso[task.complete result=Failed;]Error: Npm failed with return code: 1
2021-11-15T23:00:14.3500802Z ##[section]Finishing: Running Unit Tests

What I THINK Is going on is that multiple instances of the unit tests are being spun off due to the error at the top and then we've got a race condition: sometimes the "disconnected" unit tests finish first and the build stays green. Sometimes the second "live" set finishes first and when the "disconnected" one tries to terminate and clean up it discovers the logs folder is deleted or something and errors out with code 1. I'm stumped on how to verify that hypothesis though. I tried setting karma's retryLimit to 1 (default is 2) but that doesn't seem to impact the initial startup.

CodePudding user response：

I'm noticing that in both cases you are seeing ChromeHeadless have not captured in issue. In the success it took about 1 min 15 sec before it started up. I'm going to make a few assumptions

you have quite a bit of code being compiled to run
you're using the agent in the pipeline (which I want to say is not overly powerful)

The good news is that karma has a captureTimeout that defaults to 60,000. I believe if you add this setting to karma.conf and double it you will give time for chrome to handle all of the tests you're making it load.

You may have a second issue where you possibly have a test that is so intense that chrome sometimes stops responding for longer than browserDisconnectTimeout.