unknown unhandled Node error (big repo, lots of mutants) #4577

Open michahell opened 9 months ago

Summary

We are getting an Unhandled 'error' event Node.js error when running Stryker-mutator in our GitLab pipeline.

This is our pipeline build log, with some env secrets removed: kvk-stryker-raw-GL-job-output-modified.txt

We are adding stryker-mutator to our Angular 16 frontend repo, size of about 500k sloc.

Locally on my M1 macbook I can easily run stryker without memory or unhandled issues, which I did, to build up an incremental file of about 60MB (~31.000 mutants) by running 'subsets' of folders through stryker. This is how we do that:

import { execSync } from 'child_process';
import fs from 'fs';

const dir = process.argv[2];
if (!fs.existsSync(dir)) {
  throw new Error('Directory does not exist');
}

const command = `npm run stryker -- --ignorePatterns src/**/*.spec.ts,!${dir}/**/*.spec.ts,dist,coverage,scripts,devops,.angular,graphql-mock-server --mutate ${dir}/**/*.ts,!src/**/*.spec.ts,!src/test.ts,!src/environments/*.ts`;
execSync(command, { stdio: 'inherit' });

and using:

npm run stryker-subset "src/app/modules/hr-inzien" -- --logLevel trace

When I run stryker with concurrency:2 I can see that the test runner child process can spike to ~3,5GB memory and also the stryker process itself can spike to ~1,5GB.
We want to ideally also test static mutants so that's turned on.
The number of remaining mutants to test in the pipeline job is only 43, but still the Stryker command explodes with an unhandled Node.Js error :(
My assumption this far was that it was memory related, and initially the job exploded with explicit OOM errors.
I don't know what the current error means, since that information is lacking.
We don't yet expose stryker.log as a pipeline artefact, but that is something that I can change.

Stryker config

from build log:

[36m12:46:27 (29) DEBUG ConfigReader[39m Loading config from stryker.conf.json
[36m12:46:27 (29) DEBUG ConfigReader[39m Loaded config: {
  "$schema": "./node_modules/@stryker-mutator/core/schema/stryker-schema.json",
  "_comment": "This config was generated using a preset. Please see website for more information: https://stryker-mutator.io/docs/stryker-js/guides/angular",
  "mutate": [
    "src/**/*.ts",
    "!src/**/*.spec.ts",
    "!src/test.ts",
    "!src/environments/*.ts"
  ],
  "testRunner": "karma",
  "commandRunner": {
    "command": "npm test"
  },
  "karma": {
    "configFile": "src/karma.conf.cjs",
    "projectType": "angular-cli",
    "config": {
      "browsers": [
        "ChromeHeadlessCI"
      ]
    }
  },
  "reporters": [
    "progress",
    "clear-text",
    "html"
  ],
  "htmlReporter": {
    "fileName": "reports/stryker.html"
  },
  "concurrency": 2,
  "concurrency_comment": "Recommended to use about half of your available cores when running stryker with angular",
  "coverageAnalysis": "perTest",
  "checkers": [
    "typescript"
  ],
  "tsconfigFile": "tsconfig.json",
  "disableTypeChecks": "src/**/*.ts",
  "cleanTempDir": "always",
  "dryRunOnly": false,
  "ignorePatterns": [
    ".angular",
    ".idea ",
    ".husky",
    "coverage",
    "devops",
    "dist",
    "docs",
    "graphql-mock-server",
    "reports",
    "scripts"
  ],
  "ignoreStatic": false,
  "logLevel": "debug",
  "incremental": true,
  "incrementalFile": "stryker/stryker-incremental.json",
  "fileLogLevel": "trace",
  "maxTestRunnerReuse": 20,
  "allowConsoleColors": true,
  "checkerNodeArgs": [],
  "clearTextReporter": {
    "allowColor": true,
    "allowEmojis": false,
    "logTests": true,
    "maxTestsToLog": 3
  },
  "dashboard": {
    "baseUrl": "https://dashboard.stryker-mutator.io/api/reports",
    "reportType": "full"
  },
  "eventReporter": {
    "baseDir": "reports/mutation/events"
  },
  "force": false,
  "inPlace": false,
  "maxConcurrentTestRunners": 9007199254740991,
  "mutator": {
    "plugins": null,
    "excludedMutations": []
  },
  "plugins": [
    "@stryker-mutator/*"
  ],
  "appendPlugins": [],
  "jsonReporter": {
    "fileName": "reports/mutation/mutation.json"
  },
  "symlinkNodeModules": true,
  "tempDirName": ".stryker-tmp",
  "testRunnerNodeArgs": [],
  "thresholds": {
    "high": 80,
    "low": 60,
    "break": null
  },
  "timeoutFactor": 1.5,
  "timeoutMS": 5000,
  "dryRunTimeoutMinutes": 5,
  "warnings": true,
  "disableBail": false,
  "allowEmpty": false
}

Test runner config

karma.conf.cjs

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

/**
 * @remarks To enable parallel processing.
 *
 * 1. frameworks: ['parallel', 'jasmine', '@angular-devkit/build-angular'],
 * 2. require('karma-parallel')
 * 3. parallelOptions: {
 *      shardStrategy: 'round-robin',
 *      concurrency: 1,
 *    }
 */

module.exports = function (config) {
  config.set({
    basePath: '',
    frameworks: ['jasmine', '@angular-devkit/build-angular'],
    plugins: [
      'karma-jasmine',
      'karma-chrome-launcher',
      'karma-coverage',
      'karma-spec-reporter',
      '@angular-devkit/build-angular/plugins/karma',
      'karma-mocha-reporter',
      'karma-jasmine-order-reporter',
    ],
    preprocessors: {
      'src/**/*.ts': ['coverage'],
    },
    client: {
      clearContext: false,
      jasmine: {
        verboseDeprecations: true,
        random: process.env.FLAKY_TESTING || false,
      },
    },
    browserConsoleLogOptions: {
      level: 'log',
    },
    coverageReporter: {
      reporters: [
        { type: 'html', dir: require('path').join(__dirname, '../dist/dwp-coverage') },
        {
          type: 'lcovonly',
          dir: require('path').join(__dirname, '../dist/dwp-coverage'),
          subdir: '.',
        },
      ],
    },
    angularCli: {
      environment: 'dev',
      sourceMap: true,
    },
    // https://www.npmjs.com/package/karma-spec-reporter
    specReporter: {
      maxLogLines: -1, // limit number of lines logged per test, max total = 999 unless set to -1
      suppressErrorSummary: false, // do not print error summary
      suppressFailed: false, // do not print information about failed tests
      suppressPassed: true, // do not print information about passed tests
      suppressSkipped: true, // do not print information about skipped tests
      showSpecTiming: true, // print the time elapsed for each spec
      failFast: false, // test would finish with error when a first fail occurs.
    },
    // https://www.npmjs.com/package/karma-mocha-reporter
    mochaReporter: {
      output: 'full',
      colors: {
        success: 'green',
        info: 'blue',
        warning: 'yellow',
        error: 'bgRed',
      },
      symbols: {
        success: '+',
        info: '#',
        warning: '!',
        error: 'x',
      },
      ignoreSkipped: 'true',
    },
    reporters: ['coverage', 'mocha', 'jasmine-order'],
    port: 9877,
    colors: true,
    logLevel: config.LOG_INFO,
    autoWatch: true,
    reportSlowerThan: 100,
    browsers: ['ChromeHeadlessNoSandbox'],
    browserDisconnectTimeout: 60000,
    browserNoActivityTimeout: 60000,
    failOnEmptyTestSuite: true, // delete if no empty test specs are available.
    customLaunchers: {
      ChromeDebugging: {
        base: 'Chrome',
        flags: ['--remote-debugging-port=9222'],
        debug: true,
      },
      ChromeHeadlessNoSandbox: {
        base: 'ChromeHeadless',
        flags: [
          '--no-sandbox',
          '--disable-setuid-sandbox',
          '--disable-gpu',
          '--remote-debugging-port=9222',
        ],
      },
      ChromeHeadlessCI: {
        base: 'ChromeHeadless',
        flags: [
          '--no-sandbox',
          '--remote-debugging-port=9222',
          '--enable-logging',
          '--v=1',
          '--disable-background-timer-throttling',
          '--disable-renderer-backgrounding',
          '--proxy-bypass-list=*',
          "--proxy-server='direct://'",
        ],
      },
    },
    singleRun: true,
  });
};

Stryker environment

❯ npm ls | grep stryker
├── @stryker-mutator/core@7.1.1
├── @stryker-mutator/karma-runner@7.1.1
├── @stryker-mutator/typescript-checker@7.1.1

Test runner environment

karma:

❯ npm ls | grep karma
├── @stryker-mutator/karma-runner@7.1.1
├── karma-chrome-launcher@3.2.0
├── karma-cli@2.0.0
├── karma-coverage@2.2.1
├── karma-jasmine-order-reporter@1.1.0
├── karma-jasmine@5.1.0
├── karma-mocha-reporter@2.2.5
├── karma-spec-reporter@0.0.36
├── karma@6.4.2

and jasmine:

❯ npm ls | grep jasmine
├── @types/jasmine@5.1.1
├── jasmine-core@5.0.1
├── jasmine-marbles@0.9.2
├── jasmine-spec-reporter@7.0.0
├── jasmine@5.0.2
├── karma-jasmine-order-reporter@1.1.0
├── karma-jasmine@5.1.0

test command

ng test --no-watch --browsers ChromeHeadlessCI

Your Environment

software	version(s)
node	v18.17.1
npm	9.6.7
Operating System	OSX (Sonoma 14.1.1) and linux (ubunt, not entirely sure which version, could investigate later)

Add stryker.log

This I don't have unfortunately, since stryker is being run in our pipeline and stryker.log is currently not an artifact. I can make it so and update this issue in the future

Hi @michahell thanks for opening this issue 🙋‍♂️. Also thanks for sharing your build server logs, it is crucial in figuring out what is wrong.

I'm pretty sure the cause here is #2448, an older issue that sometimes seems to pop up.

Stryker uses tree-kill to kill worker processes (checkers, test runners) when they're done. This ensures no dangling browsers, web servers, etc are running and accumulating during mutation testing (for example, killing karma might cause your chrome browser to keep running on linux-based systems). However, in rare circumstances, it seems that dependencies of tree-kill are not installed. For example, ps seems to be missing on your build server.

I've created a small test project to verify that tree-kill works (or indeed, doesn't work). Could you try to run it on your build server? Cloning it and running npm start should do the trick.

https://github.com/nicojs/tree-kill-test

Hello @nicojs !

Thanks for your elaborate response and explanation. For speed (not having to create a separate repo + build pipeline) I've included tree-kill as an explicit dependency in our project and made my branch only execute the node script ISO stryker, this is the result locally on my machine:

❯ node stryker/tree-kill-test.mjs
child process exited with code 1, signal null
Child process killed

and this in our pipeline:

$ node stryker/tree-kill-test.mjs
child process exited with code 1, signal null
node:events:495
      throw er; // Unhandled 'error' event
      ^
Error: spawn ps ENOENT
    at ChildProcess._handle.onexit (node:internal/child_process:284:19)
    at onErrorNT (node:internal/child_process:477:16)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
Emitted 'error' event on ChildProcess instance at:
    at ChildProcess._handle.onexit (node:internal/child_process:290:12)
    at onErrorNT (node:internal/child_process:477:16)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
  errno: -2,
  code: 'ENOENT',
  syscall: 'spawn ps',
  path: 'ps',
  spawnargs: [ '-o', 'pid', '--no-headers', '--ppid', 27 ]
}
Node.js v18.18.2
Cleaning up project directory and file based variables
00:01
ERROR: Job failed: exit code 1

It seems like this is indeed the culprit. I'm going to try to install the ps command in the build base-image that we're using with apt-get update + apt-get install procps and see if that remedies it.

will report back after!

Thanks, I hope that works. Looking through the tree-kill code it seems that ps is the only dependency for linux.

I'll also re-open #2448, since that is the cause. I think the best thing to do when tree-kill fails is to perform a 'normal' childProcess.kill.

after installing procps on our build image, the tree-kill test code now does the same as on my local machine:

$ node stryker/tree-kill-test.mjs
child process exited with code 1, signal null
Child process killed

I'll try running Stryker-mutator again to see if --maxTestRunnerReuse 20 is going to save us :)

stryker-mutator seems to now keep chugging on in our pipeline! We now have a working baseline, we can increment --maxTestRunnerReuse 20 to see when memory pressure becomes too large 👍

stryker-mutator / stryker-js

unknown unhandled Node error (big repo, lots of mutants) #4577