Chrome/karma is started before the webpack dev server is ready to serve

[arobinson]

🐞 Bug report

Command (mark with an x)

• new
• build
• serve
• test
• e2e
• generate
• add
• update
• lint
• extract-i18n
• run
• config
• help
• version
• doc

Is this a regression?

Yes, the previous version in which this bug was not present was: ....

No, AFAIK, this has always been present

Description

A clear and concise description of the problem...

There is this issue in Karma: karma-runner/karma#3745

What happens is that Angular CLI is starting karma and the webpack dev server at the same time. On large Angular projects, like ours, Angular + webpack is very slow (1-2 minutes to start ng serve for example, separate issue we really need to address somehow).

What seems to occur is that chrome (or ChromeHeadless) gives up trying to load the page (it would see the problem that the server is not responding). Karma then kills the browser and restarts it (triggering issue karma-runner/karma#3745). Eventually the webpack dev server starts responding, and the tests run. Once the tests complete, the coverage report (and potentially other reporters) fail to write their reports.

While there is a bug in Karma that needs to be fixed, it does not seem to make sense to start the test framework until the webpack dev server is ready to serve the application. When it is ready, we see the Browser application bundle generation complete printed to the terminal.

Ideally karma would be started after a 200 HTTP response could be obtained from the webpack dev server

🔬 Minimal Reproduction

Only thing that is required is to run ng test on an Angular project. The problem to reproduce is that the application has to have enough code to cause webpack dev server to be too slow to start before chrome gives up loading the page.

🔥 Exception or Error

🌍 Your Environment

Angular CLI: 13.1.2
Node: 14.17.1
Package Manager: npm 6.14.13
OS: darwin x64

Angular: 13.1.1
... animations, common, compiler, compiler-cli, core, forms
... language-service, platform-browser, platform-browser-dynamic
... router

Package                         Version
---------------------------------------------------------
@angular-devkit/architect       0.1301.2
@angular-devkit/build-angular   13.1.2
@angular-devkit/core            13.1.2
@angular-devkit/schematics      13.1.2
@angular/cli                    13.1.2
@ngtools/webpack                13.1.2
@schematics/angular             13.1.2
ng-packagr                      13.1.2
rxjs                            6.6.7
typescript                      4.5.4
webpack                         5.65.0

Anything else relevant?

[alan-agius4]

In this case you can configure and increase Karma's captureTimeout option. This option represents the maximum boot-up time allowed for a browser to start and connect which by default is 60_000ms.

In the Angular CLI, Karma is initialized prior to Webpack. The rational for this is that Webpack needs to run in Karma context in order for it to notify Karma about file changes and complication errors.

[arobinson]

The problem is not Karma waiting long enough, the problem is that chrome itself gives up. Karma has a bug as mentioned that many reports will not work when this happens. As a result, changing any timeouts has no effect on the issue. This is currently really breaking us as all our code coverage metrics in our branch builds for PRs fail due to no coverage reports being generated.

That is why we are requesting that karma not be started until after the webpack has started.

I'd LOVE to get rid of webpack since it is extremely slow, but this would be a temporary fix

[alan-agius4]

@arobinson,

I am a bit confused when you say Chrome itself gives up, the logs in karma-runner/karma#3745 (pasted below), show that actually Karma terminated Chrome because the capture timeout has elapsed (Chrome has not captured in 120000 ms, killing.).

START:
 12 01 2022 20:32:01.145:INFO [karma-server]: Karma v6.3.9 server started at http://localhost:9876/
 12 01 2022 20:32:01.145:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
 12 01 2022 20:32:01.152:INFO [launcher]: Starting browser Chrome
 12 01 2022 20:34:01.547:WARN [launcher]: Chrome has not captured in 120000 ms, killing.
 12 01 2022 20:34:04.784:WARN [launcher]: Chrome was not killed in 2000 ms, sending SIGKILL.
 12 01 2022 20:34:13.076:INFO [launcher]: Trying to start Chrome again (1/2).
 ✔ Browser application bundle generation complete.

I tried to replicate this locally and I did a couple of things.

I firstly forcefully slowed down the build to take 500_000 ms (8.33333333 mins), and I started getting ChromeHeadless has not captured in 60000 ms, killing error message and the test failed due to retries limit.

I then, increased the captureTimeout to 300_000 ms (5 mins), and I saw the below logs

ng t --code-coverage
⠙ Generating browser application bundles (phase: setup)...
14 01 2022 14:26:01.437:INFO [karma-server]: Karma v6.3.11 server started at http://127.0.0.1:9876/
14 01 2022 14:26:01.439:INFO [launcher]: Launching browsers Chrome with concurrency unlimited
14 01 2022 14:26:01.462:INFO [launcher]: Starting browser Chrome
✔ Browser application bundle generation complete.
14 01 2022 14:31:01.452:WARN [launcher]: Chrome has not captured in 300000 ms, killing.
14 01 2022 14:31:01.473:INFO [launcher]: Trying to start Chrome again (1/2).
14 01 2022 14:34:24.735:INFO [Chrome 97.0.4692.71 (Mac OS 10.15.7)]: Connected on socket Dy1k5mK-qbhvm-vhAAAB with id 91452449

Based on the comments this should have not have generated a coverage report, but in my case it did 😑.

Then, I tried to increase captureTimeout to 600_000 ms (10 mins) which is greater than the 8 mins that the build takes.

ng t --code-coverage
⠙ Generating browser application bundles (phase: setup)...
14 01 2022 12:15:46.349:INFO [karma-server]: Karma v6.3.11 server started at http://127.0.0.1:9876/
14 01 2022 12:15:46.350:INFO [launcher]: Launching browsers Chrome with concurrency unlimited
14 01 2022 12:15:46.360:INFO [launcher]: Starting browser Chrome
✔ Browser application bundle generation complete.
14 01 2022 12:24:11.163:INFO [Chrome 97.0.4692.71 (Mac OS 10.15.7)]: Connected on socket sJB3ecLXT8gOlIXkAAAB with id 28198237
Chrome Headless 97.0.4692.71 (Mac OS 10.15.7): Executed 3 of 3 SUCCESS (0.132 secs / 0.108 secs)
TOTAL: 3 SUCCESS

In the later case, from the logs we see that Chrome was not killed and again the coverage report was generated.

[arobinson]

I'll try tweaking our karma settings and see if that helps and I'll report back.

[arobinson]

Increasing the timeout just makes it longer before chrome is killed.

The process just "hangs" here now until the timeout is reached:

 11:25:37  Running unit tests
11:25:40  - Generating browser application bundles (phase: setup)...
11:25:43  Test results are being saved to: /tmp/workspace/Client/nw-client-sonar-pull-request/development/nw-client/client-source/test-results
11:25:43  14 01 2022 18:25:43.240:INFO [karma-server]: Writing browser console to file: /tmp/workspace/Client/nw-client-sonar-pull-request/development/nw-client/client-source/test-results/console.log
11:25:43  
11:25:43  START:
11:25:43  14 01 2022 18:25:43.261:INFO [karma-server]: Karma v6.3.9 server started at http://localhost:9876/
11:25:43  14 01 2022 18:25:43.262:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
11:25:43  14 01 2022 18:25:43.269:INFO [launcher]: Starting browser Chrome
11:29:19  ✔ Browser application bundle generation complete.

As mentioned, I believe the issue to be that chrome gave up trying to load the page since webpack is such a slow beast.

As you can see, webpack is taking 216 seconds to bring up the server.

[arobinson]

11 minutes in and the test still have not started, so increasing the timeout is making the issue worse, not better, unfortunately:

11:25:37  Running unit tests
11:25:40  - Generating browser application bundles (phase: setup)...
11:25:43  Test results are being saved to: /tmp/workspace/Client/nw-client-sonar-pull-request/development/nw-client/client-source/test-results
11:25:43  14 01 2022 18:25:43.240:INFO [karma-server]: Writing browser console to file: /tmp/workspace/Client/nw-client-sonar-pull-request/development/nw-client/client-source/test-results/console.log
11:25:43  
11:25:43  START:
11:25:43  14 01 2022 18:25:43.261:INFO [karma-server]: Karma v6.3.9 server started at http://localhost:9876/
11:25:43  14 01 2022 18:25:43.262:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
11:25:43  14 01 2022 18:25:43.269:INFO [launcher]: Starting browser Chrome
11:29:19  ✔ Browser application bundle generation complete.
11:35:56  14 01 2022 18:35:43.271:WARN [launcher]: Chrome has not captured in 600000 ms, killing.
11:35:56  14 01 2022 18:35:43.304:INFO [launcher]: Trying to start Chrome again (1/2).
11:35:56  14 01 2022 18:35:43.693:INFO [Chrome Headless 92.0.4515.159 (Linux x86_64)]: Connected on socket SttuODUtr-pfY8a7AAAB with id 39733937
11:36:22  14 01 2022 18:36:21.169:WARN [Chrome Headless 92.0.4515.159 (Linux x86_64)]: Disconnected (0 times) reconnect failed before timeout of 7500ms (ping timeout)
11:36:22  Chrome Headless 92.0.4515.159 (Linux x86_64) ERROR
11:36:22    Disconnected reconnect failed before timeout of 7500ms (ping timeout)
11:36:22  Chrome Headless 92.0.4515.159 (Linux x86_64) ERROR
11:36:22    Disconnected reconnect failed before timeout of 7500ms (ping timeout)
11:36:22  14 01 2022 18:36:21.173:INFO [karma-server]: Restarting Chrome Headless 92.0.4515.159 (Linux x86_64) (1 of 5 attempts)
11:36:22  14 01 2022 18:36:22.621:INFO [Chrome Headless 92.0.4515.159 (Linux x86_64)]: Disconnected browser returned on socket Fi9_tK7cfD_BqojkAAAF with id 39733937.

[alan-agius4]

Can you please share your karma configuration?

[arobinson]

Let it go for a long time, and it eventually started the tests:

11:54:54  START:
11:54:54  14 01 2022 18:54:53.719:INFO [karma-server]: Karma v6.3.9 server started at http://localhost:9876/
11:54:54  14 01 2022 18:54:53.719:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
11:54:54  14 01 2022 18:54:53.727:INFO [launcher]: Starting browser Chrome
11:58:30  ✔ Browser application bundle generation complete.
12:05:07  14 01 2022 19:04:53.728:WARN [launcher]: Chrome has not captured in 600000 ms, killing.
12:05:07  14 01 2022 19:04:53.768:INFO [launcher]: Trying to start Chrome again (1/2).
12:05:07  14 01 2022 19:04:54.289:INFO [Chrome Headless 92.0.4515.159 (Linux x86_64)]: Connected on socket SJ87vV8RTTKYvPVgAAAB with id 66991885
12:05:33    AppComponent Test Suite

karma.coverage.ts:

import { all as merge } from 'deepmerge';
import * as karma from 'karma';
import * as karmaCoverage from 'karma-coverage';
import * as path from 'path';
import { buildKarmaConfig, getLogDirectory } from './karma';

// Karma configuration file, see link for more information
// https://karma-runner.github.io/1.0/config/configuration-file.html

module.exports = function (config: karma.Config): void {
  // With source maps and coverage enabled, we may have browser timeouts, so increase the numbers to prevent this
  const coverageSettings: any = {
    captureTimeout: 600000
  };

  const logDir = getLogDirectory();
  const projectDirectory = path.normalize(path.join(logDir, '..', '..'));

  const customConfig = merge([
    buildKarmaConfig(config, { nwOptions: {}, customConfiguration: coverageSettings, reporters: ['coverage'] }),
    <Partial<karma.Config>>{
      plugins: [karmaCoverage],
      coverageReporter: {
        type: 'html',
        dir: path.join(logDir, 'coverage'),
        subdir: '.',
        reporters: [
          { type: 'html', subdir: '.', includeAllSources: true },
          { type: 'lcov', projectRoot: projectDirectory }
        ]
      }
    }
  ]);

  config.set(customConfig);
};

and karma.ts:

import { all as merge } from 'deepmerge';
import * as fs from 'fs';
import * as karma from 'karma';
import * as karmaChromeLauncher from 'karma-chrome-launcher';
import * as karmaJasmine from 'karma-jasmine';
import * as karmaJasmineHtmlReporter from 'karma-jasmine-html-reporter';
import * as karmaJunitReporter from 'karma-junit-reporter';
import * as karmaMochaReporter from 'karma-mocha-reporter';
import * as karmaParallel from 'karma-parallel';
import * as path from 'path';

export interface NwKarmaOptions {
  username?: string;
  password?: string;
  parallel?: boolean;
}

export interface NwKarmaConfig {
  customConfiguration: Partial<karma.ConfigOptions>;
  nwOptions: NwKarmaOptions;
  reporters?: Array<string>;
}

export const getLogDirectory = (): string => {
  const logDir = path.join(__filename, '../../../test-results');
  if (!fs.existsSync(logDir)) {
    fs.mkdirSync(logDir, { recursive: true });
  }
  return logDir;
};

export const buildKarmaConfig = (config: karma.Config, nwConfig: NwKarmaConfig): karma.ConfigOptions => {
  const username = process.env.TEST_USERNAME || nwConfig.nwOptions.username;
  const password = process.env.TEST_PASSWORD || nwConfig.nwOptions.password;

  const logDir = getLogDirectory();
  // eslint-disable-next-line no-console
  console.log('Test results are being saved to: %s', logDir);

  const frameworks = ['jasmine', '@angular-devkit/build-angular'];
  const reporters: Array<string> = ['junit'];
  const plugins = [];

  if (nwConfig.nwOptions.parallel) {
    frameworks.unshift('parallel');
    reporters.push('progress');
    plugins.push(karmaParallel);
  } else {
    reporters.push('kjhtml', 'mocha');
    plugins.push(karmaMochaReporter, karmaJasmineHtmlReporter);
  }

  if (nwConfig.reporters) {
    reporters.push(...nwConfig.reporters);
  }

  const karmaConfig = merge([
    <Partial<karma.ConfigOptions>>{
      basePath: './',
      frameworks: frameworks,
      plugins: [karmaJasmine, karmaChromeLauncher, '@angular-devkit/build-angular/plugins/karma', karmaJunitReporter, ...plugins],
      client: {
        clearContext: false, // Leave Jasmine Spec Runner output visible in browser
        args: [username, password],
        jasmine: { random: false }
      },
      browserConsoleLogOptions: {
        level: 'debug',
        format: '%b %t: %m',
        terminal: false,
        path: path.join(logDir, 'console.log')
      },
      mochaReporter: {
        ignoreSkipped: true
      },
      jasmineHtmlReporter: {
        suppressAll: true // Removes the duplicated traces
      },
      junitReporter: {
        outputDir: path.join(logDir, 'junit'), // Results will be saved as $outputDir/$browserName.xml
        suite: 'core', // Suite will become the package name attribute in xml testsuite element
        useBrowserName: true, // Add browser name to report and classes names
        nameFormatter: undefined, // Function (browser, result) to customize the name attribute in xml testcase element
        classNameFormatter: undefined, // Function (browser, result) to customize the classname attribute in xml testcase element
        properties: {} // Key value pair of properties to add to the <properties> section of the report
      },
      reporters: reporters,
      port: 9876,
      colors: true,
      logLevel: config.LOG_INFO,
      autoWatch: true,
      browsers: ['ChromeHeadless'],
      customLaunchers: {
        ChromeCanaryHeadless: {
          base: 'ChromeCanary',
          flags: ['--no-sandbox', '--headless', '--disable-gpu', '--remote-debugging-port=9225']
        },
        ChromeHeadless: {
          base: 'Chrome',
          flags: ['--no-sandbox', '--headless', '--disable-web-security', '--remote-debugging-port=9225']
        }
      },
      singleRun: true,
      restartOnFileChange: false
    },
    nwConfig.customConfiguration
  ]);

  return karmaConfig;
};

[alan-agius4]

Looking at output again and I noticed is that after the bundle generation is complete at 11:58:30 Karma launcher outputted Chrome has not captured at 12:05:07 that is almost 7 mins of waiting for something.

11:54:54  START:
11:54:54  14 01 2022 18:54:53.719:INFO [karma-server]: Karma v6.3.9 server started at http://localhost:9876/
11:54:54  14 01 2022 18:54:53.719:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
11:54:54  14 01 2022 18:54:53.727:INFO [launcher]: Starting browser Chrome
11:58:30  ✔ Browser application bundle generation complete.
12:05:07  14 01 2022 19:04:53.728:WARN [launcher]: Chrome has not captured in 600000 ms, killing.

From the logs of a previous post I also noticed some ping timeouts and these are all post the bundle is generated and Karma server is read to take on requests.

11:25:43  14 01 2022 18:25:43.269:INFO [launcher]: Starting browser Chrome
11:29:19  ✔ Browser application bundle generation complete.
11:35:56  14 01 2022 18:35:43.271:WARN [launcher]: Chrome has not captured in 600000 ms, killing.
11:35:56  14 01 2022 18:35:43.304:INFO [launcher]: Trying to start Chrome again (1/2).
11:35:56  14 01 2022 18:35:43.693:INFO [Chrome Headless 92.0.4515.159 (Linux x86_64)]: Connected on socket SttuODUtr-pfY8a7AAAB with id 39733937
11:36:22  14 01 2022 18:36:21.169:WARN [Chrome Headless 92.0.4515.159 (Linux x86_64)]: Disconnected (0 times) reconnect failed before timeout of 7500ms (ping timeout)

I wonder if bundle sizes and the fact that coverage is enabled (which incurs additional XHR requests) are actually overloading the Karma dev-server.

I did try your config locally, but I was still unable to replicate the issue when I slow down the build to 500_000ms (8.333 minutes), Chrome was not killed.

⠙ Generating browser application bundles (phase: setup)...19 01 2022 09:58:49.444:INFO [karma-server]: Karma v6.3.11 server started at http://localhost:9876/
19 01 2022 09:58:49.444:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
19 01 2022 09:58:49.450:INFO [launcher]: Starting browser Chrome
✔ Browser application bundle generation complete.
19 01 2022 10:07:12.416:INFO [Chrome Headless 97.0.4692.71 (Mac OS 10.15.7)]: Connected on socket viFjYq-s4aaU79DkAAAB with id 96898333
Finished in 0.143 secs / 0.127 secs @ 10:07:12 GMT+0100 (Central European Standard Time)

---

Forgot to mention this in my previous post, but for Karma, we actually don't use webpack-dev-server. We use Karma's own dev-server, so the setup is more of Karma invokes Webpack to generate the bundle. Karma waits for Webpack to finish generating the bundle prior to doing any requests, such requests will be redirect to Webpack through an additional middleware.

I do see ways to run Webpack and wait for it to finish prior to invoking Karma, but this would likely require a number of major changes.

---

Does this happen in local environments or only in CI?, Do you have caching disabled?

[alan-agius4]

Has this been addressed through karma-runner/karma-coverage#434 (comment)?