From 80b044a94cbad39528219e6008cb2c4911593143 Mon Sep 17 00:00:00 2001 From: Nico Jansen Date: Thu, 2 Aug 2018 20:45:44 +0200 Subject: [PATCH] feat(child process): Make all child processes silent (#1039) Make all test runner and transpiler child processes silent. The standard out and standard error (stdout and stderr) are now only visible when `loglevel: 'trace'`. If a child process crashes, the last 10 messages received are logged as warning. This is also a refactoring of the way we spawn child processes. Instead of having 2 similar implementations (one for transpiler and one for test runners), they are both consolidated in one coherent `ChildProcessProxy` abstraction. Also clean up the test runner decorator pattern. Timeouts and retries are now implemented only once. Recognizing that the child process crashed is done by validating that the error is an instance of `ChildProcessCrashedError`. No process specifics other than the name of the error is known from the outside. The `Task` class is also refactored. Instead of relying on a custom implementation, it uses the `Promise.race` method for timeout functionality. Fixes #1038 #976 --- packages/stryker/.vscode/settings.json | 20 +- packages/stryker/src/Sandbox.ts | 4 +- .../child-proxy/ChildProcessCrashedError.ts | 15 ++ .../src/child-proxy/ChildProcessProxy.ts | 198 ++++++++++++++---- .../child-proxy/ChildProcessProxyWorker.ts | 116 ++++++---- .../src/child-proxy/OutOfMemoryError.ts | 11 + .../src/child-proxy/messageProtocol.ts | 11 +- .../IsolatedTestRunnerAdapter.ts | 180 ---------------- .../IsolatedTestRunnerAdapterWorker.ts | 155 -------------- .../src/isolated-runner/MessageProtocol.ts | 37 ---- .../src/isolated-runner/RetryDecorator.ts | 55 ----- .../src/isolated-runner/TimeoutDecorator.ts | 45 ---- .../ChildProcessTestRunnerDecorator.ts | 56 +++++ .../ChildProcessTestRunnerWorker.ts | 41 ++++ .../ResilientTestRunnerFactory.ts | 4 +- .../stryker/src/test-runner/RetryDecorator.ts | 38 ++++ .../TestRunnerDecorator.ts | 0 .../src/test-runner/TimeoutDecorator.ts | 35 ++++ .../src/transpiler/MutantTranspiler.ts | 5 +- packages/stryker/src/utils/StringBuilder.ts | 22 ++ packages/stryker/src/utils/StrykerError.ts | 2 +- packages/stryker/src/utils/Task.ts | 47 ++--- packages/stryker/src/utils/objectUtils.ts | 12 +- packages/stryker/stryker.conf.js | 6 +- .../stryker/test/helpers/LoggingServer.ts | 4 + .../child-proxy/ChildProcessProxy.it.ts | 88 ++++++-- .../test/integration/child-proxy/Echo.ts | 26 ++- .../AdditionalTestRunners.ts | 11 +- .../ResilientTestRunnerFactory.it.ts | 80 +++---- packages/stryker/test/unit/SandboxPoolSpec.ts | 7 +- packages/stryker/test/unit/SandboxSpec.ts | 4 +- .../unit/child-proxy/ChildProcessProxySpec.ts | 183 +++++++++++++--- .../child-proxy/ChildProcessWorkerSpec.ts | 82 ++++++-- .../test/unit/child-proxy/HelloClass.ts | 4 + .../IsolatedTestRunnerAdapterSpec.ts | 178 ---------------- .../isolated-runner/RetryDecoratorSpec.ts | 83 -------- .../ChildProcessTestRunnerDecoratorSpec.ts | 95 +++++++++ .../unit/test-runner/RetryDecoratorSpec.ts | 86 ++++++++ .../TestRunnerDecoratorSpec.ts | 2 +- .../TimeoutDecoratorSpec.ts | 10 +- .../unit/transpiler/MutantTranspilerSpec.ts | 7 +- .../test/unit/utils/StringBuilderSpec.ts | 33 +++ tsconfig.json | 3 +- 43 files changed, 1103 insertions(+), 998 deletions(-) create mode 100644 packages/stryker/src/child-proxy/ChildProcessCrashedError.ts create mode 100644 packages/stryker/src/child-proxy/OutOfMemoryError.ts delete mode 100644 packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapter.ts delete mode 100644 packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapterWorker.ts delete mode 100644 packages/stryker/src/isolated-runner/MessageProtocol.ts delete mode 100644 packages/stryker/src/isolated-runner/RetryDecorator.ts delete mode 100644 packages/stryker/src/isolated-runner/TimeoutDecorator.ts create mode 100644 packages/stryker/src/test-runner/ChildProcessTestRunnerDecorator.ts create mode 100644 packages/stryker/src/test-runner/ChildProcessTestRunnerWorker.ts rename packages/stryker/src/{isolated-runner => test-runner}/ResilientTestRunnerFactory.ts (69%) create mode 100644 packages/stryker/src/test-runner/RetryDecorator.ts rename packages/stryker/src/{isolated-runner => test-runner}/TestRunnerDecorator.ts (100%) create mode 100644 packages/stryker/src/test-runner/TimeoutDecorator.ts create mode 100644 packages/stryker/src/utils/StringBuilder.ts rename packages/stryker/test/integration/{isolated-runner => test-runner}/AdditionalTestRunners.ts (93%) rename packages/stryker/test/integration/{isolated-runner => test-runner}/ResilientTestRunnerFactory.it.ts (69%) delete mode 100644 packages/stryker/test/unit/isolated-runner/IsolatedTestRunnerAdapterSpec.ts delete mode 100644 packages/stryker/test/unit/isolated-runner/RetryDecoratorSpec.ts create mode 100644 packages/stryker/test/unit/test-runner/ChildProcessTestRunnerDecoratorSpec.ts create mode 100644 packages/stryker/test/unit/test-runner/RetryDecoratorSpec.ts rename packages/stryker/test/unit/{isolated-runner => test-runner}/TestRunnerDecoratorSpec.ts (91%) rename packages/stryker/test/unit/{isolated-runner => test-runner}/TimeoutDecoratorSpec.ts (89%) create mode 100644 packages/stryker/test/unit/utils/StringBuilderSpec.ts diff --git a/packages/stryker/.vscode/settings.json b/packages/stryker/.vscode/settings.json index 8f0f977b69..75776c1ebe 100644 --- a/packages/stryker/.vscode/settings.json +++ b/packages/stryker/.vscode/settings.json @@ -1,15 +1,13 @@ { - "files": { - "exclude": { - ".git": "", - ".tscache": "", - "**/*.js": { - "when": "$(basename).ts" - }, - "**/*.d.ts": true, - "**/*.map": { - "when": "$(basename)" - } + "files.exclude": { + ".git": true, + ".tscache": true, + "**/*.js": { + "when": "$(basename).ts" + }, + "**/*.d.ts": true, + "**/*.map": { + "when": "$(basename)" } } } \ No newline at end of file diff --git a/packages/stryker/src/Sandbox.ts b/packages/stryker/src/Sandbox.ts index ee92e5fe24..818730b150 100644 --- a/packages/stryker/src/Sandbox.ts +++ b/packages/stryker/src/Sandbox.ts @@ -6,8 +6,8 @@ import { RunResult, RunnerOptions } from 'stryker-api/test_runner'; import { File } from 'stryker-api/core'; import { TestFramework } from 'stryker-api/test_framework'; import { wrapInClosure, normalizeWhiteSpaces } from './utils/objectUtils'; -import TestRunnerDecorator from './isolated-runner/TestRunnerDecorator'; -import ResilientTestRunnerFactory from './isolated-runner/ResilientTestRunnerFactory'; +import TestRunnerDecorator from './test-runner/TestRunnerDecorator'; +import ResilientTestRunnerFactory from './test-runner/ResilientTestRunnerFactory'; import { TempFolder } from './utils/TempFolder'; import { writeFile, findNodeModules, symlinkJunction } from './utils/fileUtils'; import TestableMutant, { TestSelectionResult } from './TestableMutant'; diff --git a/packages/stryker/src/child-proxy/ChildProcessCrashedError.ts b/packages/stryker/src/child-proxy/ChildProcessCrashedError.ts new file mode 100644 index 0000000000..c7591e19d3 --- /dev/null +++ b/packages/stryker/src/child-proxy/ChildProcessCrashedError.ts @@ -0,0 +1,15 @@ +import StrykerError from '../utils/StrykerError'; + +export default class ChildProcessCrashedError extends StrykerError { + constructor( + public readonly pid: number, + message: string, + public readonly exitCode?: number, + public readonly signal?: string, + innerError?: Error) { + super(message, innerError); + Error.captureStackTrace(this, ChildProcessCrashedError); + // TS recommendation: https://github.com/Microsoft/TypeScript/wiki/Breaking-Changes#extending-built-ins-like-error-array-and-map-may-no-longer-work + Object.setPrototypeOf(this, ChildProcessCrashedError.prototype); + } +} \ No newline at end of file diff --git a/packages/stryker/src/child-proxy/ChildProcessProxy.ts b/packages/stryker/src/child-proxy/ChildProcessProxy.ts index e5fd08ca90..9bedf101b5 100644 --- a/packages/stryker/src/child-proxy/ChildProcessProxy.ts +++ b/packages/stryker/src/child-proxy/ChildProcessProxy.ts @@ -1,80 +1,114 @@ +import * as os from 'os'; import { fork, ChildProcess } from 'child_process'; import { File } from 'stryker-api/core'; import { getLogger } from 'stryker-api/logging'; import { WorkerMessage, WorkerMessageKind, ParentMessage, autoStart, ParentMessageKind } from './messageProtocol'; -import { serialize, deserialize } from '../utils/objectUtils'; -import Task from '../utils/Task'; +import { serialize, deserialize, kill, isErrnoException, padLeft } from '../utils/objectUtils'; +import { Task, ExpirableTask } from '../utils/Task'; import LoggingClientContext from '../logging/LoggingClientContext'; +import ChildProcessCrashedError from './ChildProcessCrashedError'; +import OutOfMemoryError from './OutOfMemoryError'; +import StringBuilder from '../utils/StringBuilder'; -export type ChildProxy = { - [K in keyof T]: (...args: any[]) => Promise; +interface Func { + (...args: TS): R; +} +interface PromisifiedFunc { + (...args: TS): Promise; +} +interface Constructor { + new (...args: TS): T; +} +export type Promisified = { + [K in keyof T]: T[K] extends PromisifiedFunc ? T[K] : T[K] extends Func ? PromisifiedFunc : () => Promise; }; +const BROKEN_PIPE_ERROR_CODE = 'EPIPE'; +const IPC_CHANNEL_CLOSED_ERROR_CODE = 'ERR_IPC_CHANNEL_CLOSED'; +const TIMEOUT_FOR_DISPOSE = 2000; + export default class ChildProcessProxy { - readonly proxy: ChildProxy = {} as ChildProxy; + readonly proxy: Promisified; private worker: ChildProcess; private initTask: Task; - private disposeTask: Task; + private disposeTask: ExpirableTask | undefined; + private currentError: ChildProcessCrashedError | undefined; private workerTasks: Task[] = []; private log = getLogger(ChildProcessProxy.name); + private stdoutAndStderrBuilder = new StringBuilder(); + private isDisposed = false; - private constructor(requirePath: string, loggingContext: LoggingClientContext, plugins: string[], private constructorFunction: { new(...params: any[]): T }, constructorParams: any[]) { - this.worker = fork(require.resolve('./ChildProcessProxyWorker'), [autoStart], { silent: false, execArgv: [] }); + private constructor(requirePath: string, loggingContext: LoggingClientContext, plugins: string[], workingDirectory: string, constructorParams: any[]) { + this.worker = fork(require.resolve('./ChildProcessProxyWorker'), [autoStart], { silent: true, execArgv: [] }); this.initTask = new Task(); + this.log.debug('Starting %s in child process %s', requirePath, this.worker.pid); this.send({ kind: WorkerMessageKind.Init, loggingContext, plugins, requirePath, - constructorArgs: constructorParams + constructorArgs: constructorParams, + workingDirectory }); - this.listenToWorkerMessages(); - this.initProxy(); + this.listenForMessages(); + this.listenToStdoutAndStderr(); + // This is important! Be sure to bind to `this` + this.handleUnexpectedExit = this.handleUnexpectedExit.bind(this); + this.handleError = this.handleError.bind(this); + this.worker.on('exit', this.handleUnexpectedExit); + this.worker.on('error', this.handleError); + this.proxy = this.initProxy(); } /** * Creates a proxy where each function of the object created using the constructorFunction arg is ran inside of a child process */ - static create(requirePath: string, loggingContext: LoggingClientContext, plugins: string[], constructorFunction: { new(arg: P1): T }, arg: P1): ChildProcessProxy; - /** - * Creates a proxy where each function of the object created using the constructorFunction arg is ran inside of a child process - */ - static create(requirePath: string, loggingContext: LoggingClientContext, plugins: string[], constructorFunction: { new(arg: P1, arg2: P2): T }, arg1: P1, arg2: P2): ChildProcessProxy; - /** - * Creates a proxy where each function of the object created using the constructorFunction arg is ran inside of a child process - */ - static create(requirePath: string, loggingContext: LoggingClientContext, plugins: string[], constructorFunction: { new(...params: any[]): T }, ...constructorArgs: any[]) { - return new ChildProcessProxy(requirePath, loggingContext, plugins, constructorFunction, constructorArgs); + static create(requirePath: string, loggingContext: LoggingClientContext, plugins: string[], workingDirectory: string, _: Constructor, ...constructorArgs: TS): + ChildProcessProxy { + return new ChildProcessProxy(requirePath, loggingContext, plugins, workingDirectory, constructorArgs); } private send(message: WorkerMessage) { this.worker.send(serialize(message)); } - private initProxy() { - Object.keys(this.constructorFunction.prototype).forEach(methodName => { - this.proxyMethod(methodName as keyof T); + private initProxy(): Promisified { + // This proxy is a genuine javascript `Proxy` class + // More info: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy + const self = this; + return new Proxy({} as Promisified, { + get(_, propertyKey) { + if (typeof propertyKey === 'string') { + return self.forward(propertyKey); + } else { + return undefined; + } + } }); } - private proxyMethod(methodName: any) { - this.proxy[(methodName as keyof T)] = (...args: any[]) => { - const workerTask = new Task(); - this.initTask.promise.then(() => { + private forward(methodName: string) { + return (...args: any[]) => { + if (this.currentError) { + return Promise.reject(this.currentError); + } else { + const workerTask = new Task(); const correlationId = this.workerTasks.push(workerTask) - 1; - this.send({ - kind: WorkerMessageKind.Work, - correlationId, - methodName, - args + this.initTask.promise.then(() => { + this.send({ + kind: WorkerMessageKind.Call, + correlationId, + methodName, + args + }); }); - }); - return workerTask.promise; + return workerTask.promise; + } }; } - private listenToWorkerMessages() { + private listenForMessages() { this.worker.on('message', (serializedMessage: string) => { const message: ParentMessage = deserialize(serializedMessage, [File]); switch (message.kind) { @@ -83,12 +117,16 @@ export default class ChildProcessProxy { break; case ParentMessageKind.Result: this.workerTasks[message.correlationId].resolve(message.result); + delete this.workerTasks[message.correlationId]; break; case ParentMessageKind.Rejection: this.workerTasks[message.correlationId].reject(new Error(message.error)); + delete this.workerTasks[message.correlationId]; break; case ParentMessageKind.DisposeCompleted: - this.disposeTask.resolve(undefined); + if (this.disposeTask) { + this.disposeTask.resolve(undefined); + } break; default: this.logUnidentifiedMessage(message); @@ -97,12 +135,88 @@ export default class ChildProcessProxy { }); } + private listenToStdoutAndStderr() { + const handleData = (data: Buffer | string) => { + const output = data.toString(); + this.stdoutAndStderrBuilder.append(output); + if (this.log.isTraceEnabled()) { + this.log.trace(output); + } + }; + + if (this.worker.stdout) { + this.worker.stdout.on('data', handleData); + } + + if (this.worker.stderr) { + this.worker.stderr.on('data', handleData); + } + } + + private reportError(error: Error) { + this.workerTasks + .filter(task => !task.isCompleted) + .forEach(task => task.reject(error)); + } + + private handleUnexpectedExit(code: number, signal: string) { + this.isDisposed = true; + const output = this.stdoutAndStderrBuilder.toString(); + + if (processOutOfMemory()) { + this.currentError = new OutOfMemoryError(this.worker.pid, code); + this.log.warn(`Child process [pid ${this.currentError.pid}] ran out of memory. Stdout and stderr are logged on debug level.`); + this.log.debug(stdoutAndStderr()); + } else { + this.currentError = new ChildProcessCrashedError(this.worker.pid, `Child process [pid ${this.worker.pid}] exited unexpectedly with exit code ${code} (${signal || 'without signal'}). ${stdoutAndStderr()}`, code, signal); + this.log.warn(this.currentError.message, this.currentError); + } + + this.reportError(this.currentError); + + function processOutOfMemory() { + return output.indexOf('JavaScript heap out of memory') >= 0; + } + + function stdoutAndStderr() { + if (output.length) { + return `Last part of stdout and stderr was:${os.EOL}${padLeft(output)}`; + } else { + return 'Stdout and stderr were empty.'; + } + } + } + + private handleError(error: Error) { + if (this.innerProcessIsCrashed(error)) { + this.log.warn(`Child process [pid ${this.worker.pid}] has crashed. See other warning messages for more info.`, error); + this.reportError(new ChildProcessCrashedError(this.worker.pid, `Child process [pid ${this.worker.pid}] has crashed`, undefined, undefined, error)); + } else { + this.reportError(error); + } + } + + private innerProcessIsCrashed(error: any) { + return isErrnoException(error) && (error.code === BROKEN_PIPE_ERROR_CODE || error.code === IPC_CHANNEL_CLOSED_ERROR_CODE); + } + public dispose(): Promise { - this.disposeTask = new Task(); - this.send({ kind: WorkerMessageKind.Dispose }); - return this.disposeTask.promise - .then(() => this.worker.kill()) - .catch(() => this.worker.kill()); + this.worker.removeListener('exit', this.handleUnexpectedExit); + if (this.isDisposed) { + return Promise.resolve(); + } else { + this.log.debug('Disposing of worker process %s', this.worker.pid); + const killWorker = () => { + this.log.debug('Kill %s', this.worker.pid); + kill(this.worker.pid); + this.isDisposed = true; + }; + this.disposeTask = new ExpirableTask(TIMEOUT_FOR_DISPOSE); + this.send({ kind: WorkerMessageKind.Dispose }); + return this.disposeTask.promise + .then(killWorker) + .catch(killWorker); + } } private logUnidentifiedMessage(message: never) { diff --git a/packages/stryker/src/child-proxy/ChildProcessProxyWorker.ts b/packages/stryker/src/child-proxy/ChildProcessProxyWorker.ts index d7a8d8c981..bd4b3243a3 100644 --- a/packages/stryker/src/child-proxy/ChildProcessProxyWorker.ts +++ b/packages/stryker/src/child-proxy/ChildProcessProxyWorker.ts @@ -1,7 +1,8 @@ +import * as path from 'path'; import { getLogger, Logger } from 'stryker-api/logging'; import { File } from 'stryker-api/core'; import { serialize, deserialize, errorToString } from '../utils/objectUtils'; -import { WorkerMessage, WorkerMessageKind, ParentMessage, autoStart, ParentMessageKind } from './messageProtocol'; +import { WorkerMessage, WorkerMessageKind, ParentMessage, autoStart, ParentMessageKind, CallMessage } from './messageProtocol'; import PluginLoader from '../PluginLoader'; import LogConfigurator from '../logging/LogConfigurator'; @@ -12,7 +13,9 @@ export default class ChildProcessProxyWorker { realSubject: any; constructor() { - this.listenToParent(); + // Make sure to bind the methods in order to ensure the `this` pointer + this.handleMessage = this.handleMessage.bind(this); + process.on('message', this.handleMessage); } private send(value: ParentMessage) { @@ -21,48 +24,58 @@ export default class ChildProcessProxyWorker { } } - private listenToParent() { - - const handler = (serializedMessage: string) => { - const message = deserialize(serializedMessage, [File]); - switch (message.kind) { - case WorkerMessageKind.Init: - LogConfigurator.configureChildProcess(message.loggingContext); - this.log = getLogger(ChildProcessProxyWorker.name); - new PluginLoader(message.plugins).load(); - const RealSubjectClass = require(message.requirePath).default; - this.realSubject = new RealSubjectClass(...message.constructorArgs); - this.send({ kind: ParentMessageKind.Initialized }); - this.removeAnyAdditionalMessageListeners(handler); - break; - case WorkerMessageKind.Work: - new Promise(resolve => resolve(this.realSubject[message.methodName](...message.args))) - .then(result => { - this.send({ - kind: ParentMessageKind.Result, - correlationId: message.correlationId, - result - }); - }).catch(error => { - this.send({ - kind: ParentMessageKind.Rejection, - error: errorToString(error), - correlationId: message.correlationId - }); + private handleMessage(serializedMessage: string) { + const message = deserialize(serializedMessage, [File]); + switch (message.kind) { + case WorkerMessageKind.Init: + LogConfigurator.configureChildProcess(message.loggingContext); + this.log = getLogger(ChildProcessProxyWorker.name); + this.handlePromiseRejections(); + new PluginLoader(message.plugins).load(); + const RealSubjectClass = require(message.requirePath).default; + const workingDir = path.resolve(message.workingDirectory); + if (process.cwd() !== workingDir) { + this.log.debug(`Changing current working directory for this process to ${workingDir}`); + process.chdir(workingDir); + } + this.realSubject = new RealSubjectClass(...message.constructorArgs); + this.send({ kind: ParentMessageKind.Initialized }); + this.removeAnyAdditionalMessageListeners(this.handleMessage); + break; + case WorkerMessageKind.Call: + new Promise(resolve => resolve(this.doCall(message))) + .then(result => { + this.send({ + kind: ParentMessageKind.Result, + correlationId: message.correlationId, + result }); - this.removeAnyAdditionalMessageListeners(handler); - break; - case WorkerMessageKind.Dispose: - const sendCompleted = () => { - this.send({ kind: ParentMessageKind.DisposeCompleted }); - }; - LogConfigurator.shutdown() - .then(sendCompleted) - .catch(sendCompleted); - break; - } - }; - process.on('message', handler); + }).catch(error => { + this.send({ + kind: ParentMessageKind.Rejection, + error: errorToString(error), + correlationId: message.correlationId + }); + }); + this.removeAnyAdditionalMessageListeners(this.handleMessage); + break; + case WorkerMessageKind.Dispose: + const sendCompleted = () => { + this.send({ kind: ParentMessageKind.DisposeCompleted }); + }; + LogConfigurator.shutdown() + .then(sendCompleted) + .catch(sendCompleted); + break; + } + } + + private doCall(message: CallMessage): {} | PromiseLike<{}> | undefined { + if (typeof this.realSubject[message.methodName] === 'function') { + return this.realSubject[message.methodName](...message.args); + } else { + return this.realSubject[message.methodName]; + } } /** @@ -79,6 +92,23 @@ export default class ChildProcessProxyWorker { } }); } + + /** + * During mutation testing, it's to be expected that promise rejections are not handled synchronously anymore (or not at all) + * Let's handle those events so future versions of node don't crash + * See issue 350: https://github.com/stryker-mutator/stryker/issues/350 + */ + private handlePromiseRejections() { + const unhandledRejections: Promise[] = []; + process.on('unhandledRejection', (reason, promise) => { + const unhandledPromiseId = unhandledRejections.push(promise); + this.log.debug(`UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: ${unhandledPromiseId}): ${reason}`); + }); + process.on('rejectionHandled', (promise) => { + const unhandledPromiseId = unhandledRejections.indexOf(promise) + 1; + this.log.debug(`PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: ${unhandledPromiseId})`); + }); + } } // Prevent side effects for merely requiring the file diff --git a/packages/stryker/src/child-proxy/OutOfMemoryError.ts b/packages/stryker/src/child-proxy/OutOfMemoryError.ts new file mode 100644 index 0000000000..2bdbe14163 --- /dev/null +++ b/packages/stryker/src/child-proxy/OutOfMemoryError.ts @@ -0,0 +1,11 @@ +import ChildProcessCrashedError from './ChildProcessCrashedError'; + +export default class OutOfMemoryError extends ChildProcessCrashedError { + constructor(pid: number, exitCode: number) { + super(pid, `Process ${pid} ran out of memory`, exitCode); + this.message = `Process `; + Error.captureStackTrace(this, OutOfMemoryError); + // TS recommendation: https://github.com/Microsoft/TypeScript/wiki/Breaking-Changes#extending-built-ins-like-error-array-and-map-may-no-longer-work + Object.setPrototypeOf(this, OutOfMemoryError.prototype); + } +} \ No newline at end of file diff --git a/packages/stryker/src/child-proxy/messageProtocol.ts b/packages/stryker/src/child-proxy/messageProtocol.ts index b93669aec5..9272fdec37 100644 --- a/packages/stryker/src/child-proxy/messageProtocol.ts +++ b/packages/stryker/src/child-proxy/messageProtocol.ts @@ -2,7 +2,7 @@ import LoggingClientContext from '../logging/LoggingClientContext'; export enum WorkerMessageKind { 'Init', - 'Work', + 'Call', 'Dispose' } @@ -13,7 +13,7 @@ export enum ParentMessageKind { 'DisposeCompleted' } -export type WorkerMessage = InitMessage | WorkMessage | { kind: WorkerMessageKind.Dispose }; +export type WorkerMessage = InitMessage | CallMessage | DisposeMessage; export type ParentMessage = WorkResult | { kind: ParentMessageKind.Initialized | ParentMessageKind.DisposeCompleted } | RejectionResult; // Make this an unlikely command line argument @@ -24,10 +24,13 @@ export interface InitMessage { kind: WorkerMessageKind.Init; loggingContext: LoggingClientContext; plugins: string[]; + workingDirectory: string; requirePath: string; constructorArgs: any[]; } +export interface DisposeMessage { kind: WorkerMessageKind.Dispose; } + export interface WorkResult { kind: ParentMessageKind.Result; correlationId: number; @@ -40,9 +43,9 @@ export interface RejectionResult { error: string; } -export interface WorkMessage { +export interface CallMessage { correlationId: number; - kind: WorkerMessageKind.Work; + kind: WorkerMessageKind.Call; args: any[]; methodName: string; } diff --git a/packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapter.ts b/packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapter.ts deleted file mode 100644 index 0f73744b0f..0000000000 --- a/packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapter.ts +++ /dev/null @@ -1,180 +0,0 @@ -import { EventEmitter } from 'events'; -import { getLogger } from 'stryker-api/logging'; -import * as _ from 'lodash'; -import { fork, ChildProcess } from 'child_process'; -import { TestRunner, RunResult, RunOptions, RunnerOptions } from 'stryker-api/test_runner'; -import { serialize, kill } from '../utils/objectUtils'; -import { AdapterMessage, WorkerMessage } from './MessageProtocol'; -import Task from '../utils/Task'; -import StrykerError from '../utils/StrykerError'; -import LoggingClientContext from '../logging/LoggingClientContext'; - -const MAX_WAIT_FOR_DISPOSE = 2000; - -class InitTask extends Task { - readonly kind = 'init'; -} -class DisposeTask extends Task { - readonly kind = 'dispose'; -} -class RunTask extends Task { - readonly kind = 'run'; -} -type WorkerTask = InitTask | DisposeTask | RunTask; - - -/** - * Runs the given test runner in a child process and forwards reports about test results - * Also implements timeout-mechanism (on timeout, restart the child runner and report timeout) - */ -export default class TestRunnerChildProcessAdapter extends EventEmitter implements TestRunner { - - private readonly log = getLogger(TestRunnerChildProcessAdapter.name); - private workerProcess: ChildProcess; - private currentTask: WorkerTask; - private lastMessagesQueue: string[] = []; - - constructor(private realTestRunnerName: string, private options: RunnerOptions, private sandboxWorkingDirectory: string, private loggingContext: LoggingClientContext) { - super(); - this.startWorker(); - } - - private startWorker() { - // Remove --debug-brk from process arguments. - // When debugging, it will try to reuse the same debug port, which will be taken by the main process. - let execArgv = _.clone(process.execArgv); - _.remove(execArgv, arg => arg.substr(0, 11) === '--debug-brk'); - this.workerProcess = fork(`${__dirname}/IsolatedTestRunnerAdapterWorker`, [], { silent: true, execArgv: [] }); - this.sendStartCommand(); - this.listenToWorkerProcess(); - } - - private listenToWorkerProcess() { - - if (this.workerProcess.stdout) { - let traceEnabled = this.log.isTraceEnabled(); - this.workerProcess.stdout.on('data', (data: Buffer) => { - const msg = data.toString(); - - this.lastMessagesQueue.push(msg); - if (this.lastMessagesQueue.length > 10) { - this.lastMessagesQueue.shift(); - } - - if (traceEnabled) { - this.log.trace(msg); - } - }); - } - - if (this.workerProcess.stderr) { - this.workerProcess.stderr.on('data', (data: any) => { - this.log.error(data.toString()); - }); - } - - this.workerProcess.on('message', (message: WorkerMessage) => { - switch (message.kind) { - case 'result': - if (this.currentTask.kind === 'run') { - this.currentTask.resolve(message.result); - } else { - this.logReceivedUnexpectedMessageWarning(message); - } - break; - case 'initDone': - if (this.currentTask.kind === 'init') { - if (message.errorMessage) { - this.currentTask.reject(message.errorMessage); - } else { - this.currentTask.resolve(undefined); - } - } else { - this.logReceivedUnexpectedMessageWarning(message); - } - break; - case 'disposeDone': - if (this.currentTask.kind === 'dispose') { - this.currentTask.resolve(undefined); - } else { - this.logReceivedUnexpectedMessageWarning(message); - } - break; - default: - this.logReceivedMessageWarning(message); - break; - } - }); - - this.workerProcess.on('exit', (code: number | null, signal: string) => { - if (code !== 0 && code !== null) { - this.log.error(`Child process exited with non-zero exit code ${code}. Last 10 message from the child process were: \r\n${this.lastMessagesQueue.map(msg => `\t${msg}`).join('\r\n')}`); - if (this.currentTask) { - this.currentTask.reject(new StrykerError(`Test runner child process exited with non-zero exit code ${code}`)); - } - } - }); - } - - private logReceivedUnexpectedMessageWarning(message: WorkerMessage) { - this.log.warn(`Received unexpected message from test runner worker process: "${message.kind}" while current task is ${this.currentTask.kind}. Ignoring this message.`); - } - - private logReceivedMessageWarning(message: never) { - this.log.error(`Retrieved unrecognized message from child process: ${JSON.stringify(message)}`); - } - - init(): Promise { - this.currentTask = new InitTask(); - this.sendInitCommand(); - return this.currentTask.promise; - } - - run(options: RunOptions): Promise { - this.currentTask = new RunTask(); - this.sendRunCommand(options); - return this.currentTask.promise; - } - - dispose(): Promise { - this.currentTask = new DisposeTask(MAX_WAIT_FOR_DISPOSE); - this.sendDisposeCommand(); - return this.currentTask.promise - .then(() => kill(this.workerProcess.pid)); - } - - private sendRunCommand(options: RunOptions) { - this.send({ - kind: 'run', - runOptions: options - }); - } - - private send(message: AdapterMessage) { - try { - // Serialize message before sending to preserve all javascript, including regex's and functions - // See https://github.com/stryker-mutator/stryker/issues/143 - this.workerProcess.send(serialize(message)); - } catch (error) { - this.currentTask.reject(error); - } - } - - private sendStartCommand() { - this.send({ - kind: 'start', - runnerName: this.realTestRunnerName, - runnerOptions: this.options, - sandboxWorkingDirectory: this.sandboxWorkingDirectory, - loggingContext: this.loggingContext - }); - } - - private sendInitCommand() { - this.send({ kind: 'init' }); - } - - private sendDisposeCommand() { - this.send({ kind: 'dispose' }); - } -} \ No newline at end of file diff --git a/packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapterWorker.ts b/packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapterWorker.ts deleted file mode 100644 index 8a21099ed7..0000000000 --- a/packages/stryker/src/isolated-runner/IsolatedTestRunnerAdapterWorker.ts +++ /dev/null @@ -1,155 +0,0 @@ -import { AdapterMessage, RunMessage, StartMessage, WorkerMessage, InitDoneMessage } from './MessageProtocol'; -import { TestRunner, RunStatus, TestRunnerFactory, RunResult } from 'stryker-api/test_runner'; -import PluginLoader from '../PluginLoader'; -import { getLogger, Logger } from 'stryker-api/logging'; -import { deserialize, errorToString } from '../utils/objectUtils'; -import LogConfigurator from '../logging/LogConfigurator'; - -class IsolatedTestRunnerAdapterWorker { - - private log: Logger; - private underlyingTestRunner: TestRunner; - - constructor() { - this.handlePromiseRejections(); - this.listenToMessages(); - } - - private listenToMessages() { - process.on('message', (serializedMessage: string) => { - const message = deserialize(serializedMessage); - switch (message.kind) { - case 'start': - this.start(message); - break; - case 'run': - this.run(message); - break; - case 'init': - this.init(); - break; - case 'dispose': - const sendDisposeDone = this.sendDisposeDone.bind(this); - this.dispose().then(sendDisposeDone, sendDisposeDone); - break; - default: - this.logReceivedMessageWarning(message); - } - }); - } - - /** - * During mutation testing, it's to be expected that promise rejections are not handled synchronously anymore (or not at all) - * Let's handle those events so future versions of node don't crash - * See issue 350: https://github.com/stryker-mutator/stryker/issues/350 - */ - private handlePromiseRejections() { - const unhandledRejections: Promise[] = []; - process.on('unhandledRejection', (reason, promise) => { - const unhandledPromiseId = unhandledRejections.push(promise); - this.log.debug(`UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: ${unhandledPromiseId}): ${reason}`); - }); - process.on('rejectionHandled', (promise) => { - const unhandledPromiseId = unhandledRejections.indexOf(promise) + 1; - this.log.debug(`PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: ${unhandledPromiseId})`); - }); - } - - private logReceivedMessageWarning(message: never) { - this.log.warn('Received unsupported message: {}', JSON.stringify(message)); - } - - start(message: StartMessage) { - LogConfigurator.configureChildProcess(message.loggingContext); - this.log = getLogger(IsolatedTestRunnerAdapterWorker.name); - this.loadPlugins(message.runnerOptions.strykerOptions.plugins || []); - this.log.debug(`Changing current working directory for this process to ${message.sandboxWorkingDirectory}`); - process.chdir(message.sandboxWorkingDirectory); - this.underlyingTestRunner = TestRunnerFactory.instance().create(message.runnerName, message.runnerOptions); - } - - async init() { - if (this.underlyingTestRunner.init) { - try { - await this.underlyingTestRunner.init(); - } catch (err) { - this.sendInitDone(errorToString(err)); - } - } - this.sendInitDone(); - } - - sendInitDone(errorMessage: string | null = null) { - const message: InitDoneMessage = { kind: 'initDone', errorMessage }; - if (process.send) { - process.send(message); - } - } - - async dispose() { - try { - if (this.underlyingTestRunner.dispose) { - await this.underlyingTestRunner.dispose(); - } - } finally { - await LogConfigurator.shutdown(); - } - } - - sendDisposeDone() { - this.send({ kind: 'disposeDone' }); - } - - async run(body: RunMessage) { - try { - let res = await this.underlyingTestRunner.run(body.runOptions); - this.reportResult(res); - } catch (error) { - this.reportErrorResult(error); - } - } - - private send(message: WorkerMessage) { - if (process.send) { - process.send(message); - } - } - - private loadPlugins(plugins: string[]) { - new PluginLoader(plugins).load(); - } - - private reportResult(result: RunResult) { - // If the test runner didn't report on coverage, let's try to do it ourselves. - if (!result.coverage) { - result.coverage = (Function('return this'))().__coverage__; - } - if (result.errorMessages) { - // errorMessages should be a string[] - // Just in case the test runner implementer forgot to convert `Error`s to string, we will do it here - // https://github.com/stryker-mutator/stryker/issues/141 - result.errorMessages = result.errorMessages.map(errorToString); - } - this.send({ - kind: 'result', - result - }); - } - - private reportErrorResult(error: any) { - const runResult: RunResult = { - tests: [], - status: RunStatus.Error, - }; - if (error) { - if (Array.isArray(error)) { - runResult.errorMessages = error.map((e: any) => e); - } else { - runResult.errorMessages = [error]; - } - } - this.reportResult(runResult); - } -} - -new IsolatedTestRunnerAdapterWorker(); \ No newline at end of file diff --git a/packages/stryker/src/isolated-runner/MessageProtocol.ts b/packages/stryker/src/isolated-runner/MessageProtocol.ts deleted file mode 100644 index 05e6ae31d5..0000000000 --- a/packages/stryker/src/isolated-runner/MessageProtocol.ts +++ /dev/null @@ -1,37 +0,0 @@ -import { RunResult, RunnerOptions } from 'stryker-api/test_runner'; -import { RunOptions } from 'stryker-api/test_runner'; -import LoggingClientContext from '../logging/LoggingClientContext'; - -export type AdapterMessage = RunMessage | StartMessage | EmptyAdapterMessage; -export type WorkerMessage = ResultMessage | EmptyWorkerMessage | InitDoneMessage; - -export interface ResultMessage { - kind: 'result'; - result: RunResult; -} - -export interface RunMessage { - kind: 'run'; - runOptions: RunOptions; -} - -export interface StartMessage { - kind: 'start'; - runnerName: string; - runnerOptions: RunnerOptions; - sandboxWorkingDirectory: string; - loggingContext: LoggingClientContext; -} - -export interface InitDoneMessage { - kind: 'initDone'; - errorMessage: string | null; -} - -export interface EmptyAdapterMessage { - kind: 'init' | 'dispose'; -} - -export interface EmptyWorkerMessage { - kind: 'disposeDone'; -} \ No newline at end of file diff --git a/packages/stryker/src/isolated-runner/RetryDecorator.ts b/packages/stryker/src/isolated-runner/RetryDecorator.ts deleted file mode 100644 index 23c848e1f9..0000000000 --- a/packages/stryker/src/isolated-runner/RetryDecorator.ts +++ /dev/null @@ -1,55 +0,0 @@ -import { RunOptions, RunResult, RunStatus } from 'stryker-api/test_runner'; -import { isErrnoException, errorToString } from '../utils/objectUtils'; -import TestRunnerDecorator from './TestRunnerDecorator'; -import Task from '../utils/Task'; - -const BROKEN_PIPE_ERROR_CODE = 'EPIPE'; -const ERROR_MESSAGE = 'Test runner crashed. Tried twice to restart it without any luck. Last time the error message was: '; - -/** - * Wraps a test runner and implements the retry functionality. - */ -export default class RetryDecorator extends TestRunnerDecorator { - private currentRunTask: Task; - - run(options: RunOptions): Promise { - this.currentRunTask = new Task(); - this.tryRun(options); - return this.currentRunTask.promise; - } - - dispose(): Promise { - return super.dispose().catch(err => { - if (this.innerProcessIsCrashed(err)) { - return null; - } else { - // Oops, not intended to catch this one. Pass through - throw err; - } - }); - } - - private innerProcessIsCrashed(error: any) { - return isErrnoException(error) && error.code === BROKEN_PIPE_ERROR_CODE; - } - - private async tryRun(options: RunOptions, attemptsLeft = 2, lastError?: any) { - if (attemptsLeft > 0) { - try { - let result = await this.innerRunner.run(options); - this.currentRunTask.resolve(result); - } catch (error) { - await this.recover(); - await this.tryRun(options, attemptsLeft - 1, error); - } - } else { - await this.recover(); - this.currentRunTask.resolve({ status: RunStatus.Error, errorMessages: [ERROR_MESSAGE + errorToString(lastError)], tests: [] }); - } - } - - private recover(): Promise { - this.createInnerRunner(); - return this.init(); - } -} diff --git a/packages/stryker/src/isolated-runner/TimeoutDecorator.ts b/packages/stryker/src/isolated-runner/TimeoutDecorator.ts deleted file mode 100644 index d72f044c86..0000000000 --- a/packages/stryker/src/isolated-runner/TimeoutDecorator.ts +++ /dev/null @@ -1,45 +0,0 @@ -import { RunOptions, RunResult, RunStatus } from 'stryker-api/test_runner'; -import { isPromise } from '../utils/objectUtils'; -import Task from '../utils/Task'; -import TestRunnerDecorator from './TestRunnerDecorator'; -import { getLogger } from 'stryker-api/logging'; - -const MAX_WAIT_FOR_DISPOSE = 2500; - -/** - * Wraps a test runner and implements the timeout functionality. - */ -export default class TimeoutDecorator extends TestRunnerDecorator { - - private readonly log = getLogger(TimeoutDecorator.name); - - run(options: RunOptions): Promise { - this.log.debug('Starting timeout timer (%s ms) for a test run', options.timeout); - const runTask = new Task(options.timeout, () => this.handleTimeout()); - runTask.chainTo(super.run(options)); - return runTask.promise; - } - - dispose(): Promise { - return this.proxy(() => super.dispose(), MAX_WAIT_FOR_DISPOSE); - } - - private proxy(action?: () => Promise | void, timeoutMs?: number): Promise { - if (action) { - const maybePromise = action(); - if (isPromise(maybePromise)) { - const task = new Task(timeoutMs); - task.chainTo(maybePromise); - return task.promise; - } - } - return Promise.resolve(); - } - - private handleTimeout(): Promise { - return this.dispose() - .then(() => this.createInnerRunner()) - .then(() => this.init()) - .then(() => ({ status: RunStatus.Timeout, tests: [] })); - } -} \ No newline at end of file diff --git a/packages/stryker/src/test-runner/ChildProcessTestRunnerDecorator.ts b/packages/stryker/src/test-runner/ChildProcessTestRunnerDecorator.ts new file mode 100644 index 0000000000..e122b733cd --- /dev/null +++ b/packages/stryker/src/test-runner/ChildProcessTestRunnerDecorator.ts @@ -0,0 +1,56 @@ +import { TestRunner, RunResult, RunOptions, RunnerOptions } from 'stryker-api/test_runner'; +import LoggingClientContext from '../logging/LoggingClientContext'; +import ChildProcessProxy from '../child-proxy/ChildProcessProxy'; +import ChildProcessTestRunnerWorker from './ChildProcessTestRunnerWorker'; +import { sleep } from '../utils/objectUtils'; +import ChildProcessCrashedError from '../child-proxy/ChildProcessCrashedError'; + +const MAX_WAIT_FOR_DISPOSE = 2000; + +/** + * Runs the given test runner in a child process and forwards reports about test results + * Also implements timeout-mechanism (on timeout, restart the child runner and report timeout) + */ +export default class ChildProcessTestRunnerDecorator implements TestRunner { + + private readonly worker: ChildProcessProxy; + + constructor(realTestRunnerName: string, + options: RunnerOptions, + sandboxWorkingDirectory: string, + loggingContext: LoggingClientContext) { + this.worker = ChildProcessProxy.create( + require.resolve('./ChildProcessTestRunnerWorker.js'), + loggingContext, + options.strykerOptions.plugins || [], + sandboxWorkingDirectory, + ChildProcessTestRunnerWorker, realTestRunnerName, options); + } + + init(): Promise { + return this.worker.proxy.init(); + } + + run(options: RunOptions): Promise { + return this.worker.proxy.run(options); + } + + async dispose(): Promise { + + await Promise.race([ + // First let the inner test runner dispose + this.worker.proxy.dispose().catch(error => { + // It's OK if the child process is already down. + if (!(error instanceof ChildProcessCrashedError)) { + throw error; + } + }), + + // ... but don't wait forever on that + sleep(MAX_WAIT_FOR_DISPOSE) + ]); + + // After that, dispose the child process itself + await this.worker.dispose(); + } +} \ No newline at end of file diff --git a/packages/stryker/src/test-runner/ChildProcessTestRunnerWorker.ts b/packages/stryker/src/test-runner/ChildProcessTestRunnerWorker.ts new file mode 100644 index 0000000000..0a88343f2d --- /dev/null +++ b/packages/stryker/src/test-runner/ChildProcessTestRunnerWorker.ts @@ -0,0 +1,41 @@ +import { TestRunner, TestRunnerFactory, RunnerOptions, RunOptions } from 'stryker-api/test_runner'; +import { errorToString } from '../utils/objectUtils'; + +/** + * + */ +export default class ChildProcessTestRunnerWorker implements TestRunner { + + private underlyingTestRunner: TestRunner; + + constructor(realTestRunnerName: string, options: RunnerOptions) { + this.underlyingTestRunner = TestRunnerFactory.instance().create(realTestRunnerName, options); + } + + async init(): Promise { + if (this.underlyingTestRunner.init) { + await this.underlyingTestRunner.init(); + } + } + + async dispose() { + if (this.underlyingTestRunner.dispose) { + await this.underlyingTestRunner.dispose(); + } + } + + async run(options: RunOptions) { + const result = await this.underlyingTestRunner.run(options); + // If the test runner didn't report on coverage, let's try to do it ourselves. + if (!result.coverage) { + result.coverage = (global as any).__coverage__; + } + if (result.errorMessages) { + // errorMessages should be a string[] + // Just in case the test runner implementer forgot to convert `Error`s to string, we will do it here + // https://github.com/stryker-mutator/stryker/issues/141 + result.errorMessages = result.errorMessages.map(errorToString); + } + return result; + } +} \ No newline at end of file diff --git a/packages/stryker/src/isolated-runner/ResilientTestRunnerFactory.ts b/packages/stryker/src/test-runner/ResilientTestRunnerFactory.ts similarity index 69% rename from packages/stryker/src/isolated-runner/ResilientTestRunnerFactory.ts rename to packages/stryker/src/test-runner/ResilientTestRunnerFactory.ts index 711e27361a..aa2984d068 100644 --- a/packages/stryker/src/isolated-runner/ResilientTestRunnerFactory.ts +++ b/packages/stryker/src/test-runner/ResilientTestRunnerFactory.ts @@ -1,4 +1,4 @@ -import IsolatedTestRunnerAdapter from './IsolatedTestRunnerAdapter'; +import ChildProcessTestRunnerDecorator from './ChildProcessTestRunnerDecorator'; import TimeoutDecorator from './TimeoutDecorator'; import RetryDecorator from './RetryDecorator'; import TestRunnerDecorator from './TestRunnerDecorator'; @@ -9,6 +9,6 @@ import { RunnerOptions } from 'stryker-api/test_runner'; export default { create(testRunnerName: string, settings: RunnerOptions, sandboxWorkingDirectory: string, loggingContext: LoggingClientContext): TestRunnerDecorator { return new RetryDecorator(() => - new TimeoutDecorator(() => new IsolatedTestRunnerAdapter(testRunnerName, settings, sandboxWorkingDirectory, loggingContext))); + new TimeoutDecorator(() => new ChildProcessTestRunnerDecorator(testRunnerName, settings, sandboxWorkingDirectory, loggingContext))); } }; \ No newline at end of file diff --git a/packages/stryker/src/test-runner/RetryDecorator.ts b/packages/stryker/src/test-runner/RetryDecorator.ts new file mode 100644 index 0000000000..62c359686a --- /dev/null +++ b/packages/stryker/src/test-runner/RetryDecorator.ts @@ -0,0 +1,38 @@ +import { RunOptions, RunResult, RunStatus } from 'stryker-api/test_runner'; +import TestRunnerDecorator from './TestRunnerDecorator'; +import { errorToString } from '../utils/objectUtils'; +import OutOfMemoryError from '../child-proxy/OutOfMemoryError'; +import { getLogger } from 'stryker-api/logging'; + +const ERROR_MESSAGE = 'Test runner crashed. Tried twice to restart it without any luck. Last time the error message was: '; + +/** + * Wraps a test runner and implements the retry functionality. + */ +export default class RetryDecorator extends TestRunnerDecorator { + + log = getLogger(RetryDecorator.name); + + async run(options: RunOptions, attemptsLeft = 2, lastError?: Error): Promise { + if (attemptsLeft > 0) { + try { + return await this.innerRunner.run(options); + } catch (error) { + if (error instanceof OutOfMemoryError) { + this.log.info('Test runner process [%s] ran out of memory. You probably have a memory leak in your tests. Don\'t worry, Stryker will restart the process, but you might want to investigate this later, because this decreases performance.', error.pid); + } + await this.recover(); + return this.run(options, attemptsLeft - 1, error); + } + } else { + await this.recover(); + return { status: RunStatus.Error, errorMessages: [ERROR_MESSAGE + errorToString(lastError)], tests: [] }; + } + } + + private async recover(): Promise { + await this.dispose(); + this.createInnerRunner(); + return this.init(); + } +} diff --git a/packages/stryker/src/isolated-runner/TestRunnerDecorator.ts b/packages/stryker/src/test-runner/TestRunnerDecorator.ts similarity index 100% rename from packages/stryker/src/isolated-runner/TestRunnerDecorator.ts rename to packages/stryker/src/test-runner/TestRunnerDecorator.ts diff --git a/packages/stryker/src/test-runner/TimeoutDecorator.ts b/packages/stryker/src/test-runner/TimeoutDecorator.ts new file mode 100644 index 0000000000..9819e9ea24 --- /dev/null +++ b/packages/stryker/src/test-runner/TimeoutDecorator.ts @@ -0,0 +1,35 @@ +import { RunOptions, RunResult, RunStatus } from 'stryker-api/test_runner'; +import TestRunnerDecorator from './TestRunnerDecorator'; +import { getLogger } from 'stryker-api/logging'; +import { sleep } from '../utils/objectUtils'; + +const TIMEOUT_EXPIRED = 'timeout_expired'; + +/** + * Wraps a test runner and implements the timeout functionality. + */ +export default class TimeoutDecorator extends TestRunnerDecorator { + + private readonly log = getLogger(TimeoutDecorator.name); + + async run(options: RunOptions): Promise { + this.log.debug('Starting timeout timer (%s ms) for a test run', options.timeout); + const result = await Promise.race([super.run(options), timeout()]); + if (result === TIMEOUT_EXPIRED) { + return this.handleTimeout(); + } else { + return result; + } + function timeout() { + return sleep(options.timeout).then<'timeout_expired'>(() => TIMEOUT_EXPIRED); + } + } + + private handleTimeout(): Promise { + this.log.debug('Timeout expired, restarting the process and reporting timeout'); + return this.dispose() + .then(() => this.createInnerRunner()) + .then(() => this.init()) + .then(() => ({ status: RunStatus.Timeout, tests: [] })); + } +} \ No newline at end of file diff --git a/packages/stryker/src/transpiler/MutantTranspiler.ts b/packages/stryker/src/transpiler/MutantTranspiler.ts index 18892af347..3831c76200 100644 --- a/packages/stryker/src/transpiler/MutantTranspiler.ts +++ b/packages/stryker/src/transpiler/MutantTranspiler.ts @@ -4,7 +4,7 @@ import TranspilerFacade from './TranspilerFacade'; import TestableMutant from '../TestableMutant'; import { File } from 'stryker-api/core'; import SourceFile from '../SourceFile'; -import ChildProcessProxy, { ChildProxy } from '../child-proxy/ChildProcessProxy'; +import ChildProcessProxy, { Promisified } from '../child-proxy/ChildProcessProxy'; import { TranspilerOptions } from 'stryker-api/transpile'; import TranspiledMutant from '../TranspiledMutant'; import TranspileResult from './TranspileResult'; @@ -14,7 +14,7 @@ import LoggingClientContext from '../logging/LoggingClientContext'; export default class MutantTranspiler { private transpilerChildProcess: ChildProcessProxy | undefined; - private proxy: ChildProxy; + private proxy: Promisified; private currentMutatedFile: SourceFile; private unMutatedFiles: ReadonlyArray; @@ -30,6 +30,7 @@ export default class MutantTranspiler { require.resolve('./TranspilerFacade'), loggingContext, config.plugins, + process.cwd(), TranspilerFacade, transpilerOptions ); diff --git a/packages/stryker/src/utils/StringBuilder.ts b/packages/stryker/src/utils/StringBuilder.ts new file mode 100644 index 0000000000..fc323e5e2a --- /dev/null +++ b/packages/stryker/src/utils/StringBuilder.ts @@ -0,0 +1,22 @@ +import * as os from 'os'; + +const DEFAULT_MAX_SIZE = 2048; + +export default class StringBuilder { + private currentLength = 0; + private strings: string[] = []; + private readonly maxSize = DEFAULT_MAX_SIZE; + + append(str: string) { + this.strings.push(str); + this.currentLength += str.length; + while (this.currentLength > this.maxSize && this.strings.length > 1) { + const popped = this.strings.shift() as string; + this.currentLength -= popped.length; + } + } + + toString() { + return this.strings.join(os.EOL); + } +} \ No newline at end of file diff --git a/packages/stryker/src/utils/StrykerError.ts b/packages/stryker/src/utils/StrykerError.ts index 20e7972568..c6d4ad31db 100644 --- a/packages/stryker/src/utils/StrykerError.ts +++ b/packages/stryker/src/utils/StrykerError.ts @@ -1,7 +1,7 @@ import { errorToString } from './objectUtils'; export default class StrykerError extends Error { - constructor(message: string, innerError?: Error) { + constructor(message: string, readonly innerError?: Error) { super(`${message}${innerError ? `. Inner error: ${errorToString(innerError)}` : ''}`); Error.captureStackTrace(this, StrykerError); // TS recommendation: https://github.com/Microsoft/TypeScript/wiki/Breaking-Changes#extending-built-ins-like-error-array-and-map-may-no-longer-work diff --git a/packages/stryker/src/utils/Task.ts b/packages/stryker/src/utils/Task.ts index 4e7cae239d..a66ec1337c 100644 --- a/packages/stryker/src/utils/Task.ts +++ b/packages/stryker/src/utils/Task.ts @@ -1,59 +1,48 @@ +import { sleep } from './objectUtils'; /** * Wraps a promise in a Task api for convenience. */ -export default class Task { +export class Task { - private _promise: Promise; + protected _promise: Promise; private resolveFn: (value?: T | PromiseLike) => void; private rejectFn: (reason: any) => void; - private _isResolved = false; - private timeout: NodeJS.Timer; + private _isCompleted = false; - constructor(timeoutMs?: number, private timeoutHandler?: () => PromiseLike) { + constructor() { this._promise = new Promise((resolve, reject) => { this.resolveFn = resolve; this.rejectFn = reject; }); - if (timeoutMs) { - this.timeout = setTimeout(() => this.handleTimeout(), timeoutMs); - } - } - - get isResolved() { - return this._isResolved; } get promise() { return this._promise; } - handleTimeout() { - if (this.timeoutHandler) { - this.timeoutHandler().then(val => this.resolve(val)); - } else { - this.resolve(undefined); - } - } - - chainTo(promise: Promise) { - promise.then(value => this.resolve(value), reason => this.reject(reason)); + get isCompleted() { + return this._isCompleted; } resolve(result: undefined | T | PromiseLike) { - this.resolveTimeout(); + this._isCompleted = true; this.resolveFn(result); } reject(reason: any) { - this.resolveTimeout(); + this._isCompleted = true; this.rejectFn(reason); } +} - private resolveTimeout() { - if (this.timeout) { - clearTimeout(this.timeout); - } - this._isResolved = true; +/** + * A task that can expire after the given time. + * If that happens, the inner promise is resolved + */ +export class ExpirableTask extends Task { + constructor(timeoutMS: number) { + super(); + this._promise = Promise.race([this._promise, sleep(timeoutMS)]); } } \ No newline at end of file diff --git a/packages/stryker/src/utils/objectUtils.ts b/packages/stryker/src/utils/objectUtils.ts index 4bd520d8c8..d47e967242 100644 --- a/packages/stryker/src/utils/objectUtils.ts +++ b/packages/stryker/src/utils/objectUtils.ts @@ -93,11 +93,21 @@ export function kill(pid: number): Promise { res(); } }); - + function canIgnore(code: number | undefined) { // https://docs.microsoft.com/en-us/windows/desktop/Debug/system-error-codes--0-499- // these error codes mean the program is _already_ closed. return code === 255 || code === 128; } }); +} + +export function sleep(ms: number): Promise { + return new Promise(res => { + setTimeout(res, ms); + }); +} + +export function padLeft(input: string): string { + return input.split('\n').map(str => '\t' + str).join('\n'); } \ No newline at end of file diff --git a/packages/stryker/stryker.conf.js b/packages/stryker/stryker.conf.js index e50fe48a8e..c88830dd97 100644 --- a/packages/stryker/stryker.conf.js +++ b/packages/stryker/stryker.conf.js @@ -11,7 +11,8 @@ module.exports = function (config) { 'package.json', 'src/**/*.ts', '!src/**/*.d.ts', - 'test/**/*.ts', + 'test/helpers/**/*.ts', + 'test/unit/**/*.ts', '!test/**/*.d.ts' ], symlinkNodeModules: false, @@ -44,12 +45,13 @@ module.exports = function (config) { testFramework: 'mocha', testRunner: 'mocha', reporter: ['progress', 'html', 'clear-text', 'event-recorder', 'dashboard'], - maxConcurrentTestRunners: 5, + maxConcurrentTestRunners: 4, thresholds: { high: 80, low: 60, break: null }, + fileLogLevel: 'trace', logLevel: 'info', plugins: [ require.resolve('../stryker-mocha-runner/src/index'), diff --git a/packages/stryker/test/helpers/LoggingServer.ts b/packages/stryker/test/helpers/LoggingServer.ts index dc1e3dfdff..e20e69eed2 100644 --- a/packages/stryker/test/helpers/LoggingServer.ts +++ b/packages/stryker/test/helpers/LoggingServer.ts @@ -17,6 +17,10 @@ export default class LoggingServer { const loggingEvents: log4js.LoggingEvent[] = logEventStrings.map(logEventString => JSON.parse(logEventString)); loggingEvents.forEach(event => this.subscriber && this.subscriber.next(event)); }); + socket.on('error', () => { + // A client connection was killed unexpectedly. + // This happens during integration tests, this is safe to ignore (log4js does that as well) + }); }); this.server.listen(this.port); diff --git a/packages/stryker/test/integration/child-proxy/ChildProcessProxy.it.ts b/packages/stryker/test/integration/child-proxy/ChildProcessProxy.it.ts index 43abe6b0c2..b892c01887 100644 --- a/packages/stryker/test/integration/child-proxy/ChildProcessProxy.it.ts +++ b/packages/stryker/test/integration/child-proxy/ChildProcessProxy.it.ts @@ -1,37 +1,58 @@ +import * as path from 'path'; +import * as getPort from 'get-port'; +import * as log4js from 'log4js'; import { expect } from 'chai'; +import { File, LogLevel } from 'stryker-api/core'; +import { Logger } from 'stryker-api/logging'; import Echo from './Echo'; import ChildProcessProxy from '../../../src/child-proxy/ChildProcessProxy'; -import { File, LogLevel } from 'stryker-api/core'; -import * as log4js from 'log4js'; -import * as getPort from 'get-port'; -import Task from '../../../src/utils/Task'; +import { Task } from '../../../src/utils/Task'; import LoggingServer from '../../helpers/LoggingServer'; +import { filter } from 'rxjs/operators'; +import { Mock } from '../../helpers/producers'; +import currentLogMock from '../../helpers/logMock'; +import { sleep } from '../../../src/utils/objectUtils'; +import OutOfMemoryError from '../../../src/child-proxy/OutOfMemoryError'; +import ChildProcessCrashedError from '../../../src/child-proxy/ChildProcessCrashedError'; describe('ChildProcessProxy', function () { this.timeout(15000); let sut: ChildProcessProxy; let loggingServer: LoggingServer; + let log: Mock; + const echoName = 'The Echo Server'; + const workingDir = '..'; beforeEach(async () => { const port = await getPort(); + log = currentLogMock(); loggingServer = new LoggingServer(port); - sut = ChildProcessProxy.create(require.resolve('./Echo'), { port, level: LogLevel.Debug }, [], Echo, 'World'); + sut = ChildProcessProxy.create(require.resolve('./Echo'), { port, level: LogLevel.Debug }, [], workingDir, Echo, echoName); }); afterEach(async () => { - await sut.dispose(); - await loggingServer.dispose(); + try { + await sut.dispose(); + await loggingServer.dispose(); + } catch (error) { + console.error(error); + } }); it('should be able to get direct result', async () => { const actual = await sut.proxy.say('hello'); - expect(actual).eq('World: hello'); + expect(actual).eq(`${echoName}: hello`); }); it('should be able to get delayed result', async () => { const actual = await sut.proxy.sayDelayed('hello', 2); - expect(actual).eq('World: hello (2 ms)'); + expect(actual).eq(`${echoName}: hello (2 ms)`); + }); + + it('should set the current working directory', async () => { + const actual = await sut.proxy.cwd(); + expect(actual).eq(path.resolve(workingDir)); }); it('should be able to receive files', async () => { @@ -45,29 +66,62 @@ describe('ChildProcessProxy', function () { expect(actual.name).eq('foobar.txt'); }); - it('should be able to receive a promise rejection', () => { - return expect(sut.proxy.reject('Foobar error')).rejectedWith('Foobar error'); + it('should be able to receive a promise rejection', async () => { + await expect(sut.proxy.reject('Foobar error')).rejectedWith('Foobar error'); + }); + + it('should be able to receive public properties as promised', () => { + return expect(sut.proxy.name()).eventually.eq(echoName); }); it('should be able to log on debug when LogLevel.Debug is allowed', async () => { - const firstLogEventTask = new Task(); - loggingServer.event$.subscribe(firstLogEventTask.resolve.bind(firstLogEventTask)); + const logEventTask = new Task(); + loggingServer.event$.pipe( + filter(event => event.categoryName === Echo.name) + ).subscribe(logEventTask.resolve.bind(logEventTask)); sut.proxy.debug('test message'); - const log = await firstLogEventTask.promise; + const log = await logEventTask.promise; expect(log.categoryName).eq(Echo.name); expect(log.data).deep.eq(['test message']); }); it('should not log on trace if LogLevel.Debug is allowed as min log level', async () => { - const firstLogEventTask = new Task(); - loggingServer.event$.subscribe(firstLogEventTask.resolve.bind(firstLogEventTask)); + const logEventTask = new Task(); + loggingServer.event$.pipe( + filter(event => event.categoryName === Echo.name) + ).subscribe(logEventTask.resolve.bind(logEventTask)); sut.proxy.trace('foo'); sut.proxy.debug('bar'); - const log = await firstLogEventTask.promise; + const log = await logEventTask.promise; expect(log.categoryName).eq(Echo.name); expect(log.data).deep.eq(['bar']); expect(toLogLevel(log.level)).eq(LogLevel.Debug); }); + + it('should reject when the child process exits', () => { + return expect(sut.proxy.exit(42)).rejectedWith(ChildProcessCrashedError); + }); + + it('should log stdout and stderr on warning when a child process crashed', async () => { + await sut.proxy.stdout('stdout message'); + await sut.proxy.stderr('stderr message'); + // Give nodejs the chance to flush the stdout and stderr buffers + await sleep(10); + await expect(sut.proxy.exit(12)).rejected; + const call = log.warn.getCall(0); + expect(call.args[0]).matches(/Child process \[pid \d+\] exited unexpectedly with exit code 12 \(without signal\)\. Last part of stdout and stderr was/g); + expect(call.args[0]).includes('stdout message'); + expect(call.args[0]).includes('stderr message'); + }); + + it('should immediately reject any subsequent calls when the child process exits', async () => { + await expect(sut.proxy.exit(1)).rejected; + await expect(sut.proxy.say('something')).rejectedWith(ChildProcessCrashedError); + }); + + it('should throw an OutOfMemoryError if the process went out-of-memory', async () => { + await expect(sut.proxy.memoryLeak()).rejectedWith(OutOfMemoryError); + }); }); function toLogLevel(level: log4js.Level) { diff --git a/packages/stryker/test/integration/child-proxy/Echo.ts b/packages/stryker/test/integration/child-proxy/Echo.ts index 71abd62a25..ca85eab647 100644 --- a/packages/stryker/test/integration/child-proxy/Echo.ts +++ b/packages/stryker/test/integration/child-proxy/Echo.ts @@ -5,7 +5,7 @@ export default class Echo { private logger = getLogger(Echo.name); - constructor(private name: string) { + constructor(public name: string) { } @@ -25,10 +25,19 @@ export default class Echo { return file.textContent; } + exit(code: number) { + process.exit(code); + return new Promise(res => {/*never resolve*/ }); + } + readFile() { return new File('foobar.txt', 'hello foobar'); } + cwd() { + return process.cwd(); + } + debug(message: string) { this.logger.debug(message); } @@ -40,4 +49,19 @@ export default class Echo { reject(error: string) { return Promise.reject(new Error(error)); } + + stdout(...args: string[]) { + args.forEach(arg => console.log(arg)); + } + + stderr(...args: string[]) { + args.forEach(arg => console.error(arg)); + } + + memoryLeak() { + const arr: number[] = []; + while (true) { + arr.push(1); + } + } } \ No newline at end of file diff --git a/packages/stryker/test/integration/isolated-runner/AdditionalTestRunners.ts b/packages/stryker/test/integration/test-runner/AdditionalTestRunners.ts similarity index 93% rename from packages/stryker/test/integration/isolated-runner/AdditionalTestRunners.ts rename to packages/stryker/test/integration/test-runner/AdditionalTestRunners.ts index 303a9afe37..3dc85cb3a4 100644 --- a/packages/stryker/test/integration/isolated-runner/AdditionalTestRunners.ts +++ b/packages/stryker/test/integration/test-runner/AdditionalTestRunners.ts @@ -11,13 +11,20 @@ class CoverageReportingTestRunner implements TestRunner { class TimeBombTestRunner implements TestRunner { constructor() { // Setting a time bomb after 100 ms - setTimeout(() => process.exit(), 100); + setTimeout(() => process.exit(), 500); } run() { return Promise.resolve({ status: RunStatus.Complete, tests: [] }); } } +class ProximityMineTestRunner implements TestRunner { + run() { + process.exit(42); + return Promise.resolve({ status: RunStatus.Complete, tests: [] }); + } +} + class DirectResolvedTestRunner implements TestRunner { run() { (global as any).__coverage__ = 'coverageObject'; @@ -39,7 +46,6 @@ class DiscoverRegexTestRunner implements TestRunner { } } - class ErroredTestRunner implements TestRunner { run() { @@ -129,5 +135,6 @@ TestRunnerFactory.instance().register('discover-regex', DiscoverRegexTestRunner) TestRunnerFactory.instance().register('direct-resolved', DirectResolvedTestRunner); TestRunnerFactory.instance().register('coverage-reporting', CoverageReportingTestRunner); TestRunnerFactory.instance().register('time-bomb', TimeBombTestRunner); +TestRunnerFactory.instance().register('proximity-mine', ProximityMineTestRunner); TestRunnerFactory.instance().register('async-promise-rejection-handler', AsyncronousPromiseRejectionHandlerTestRunner); TestRunnerFactory.instance().register('reject-init', RejectInitRunner); \ No newline at end of file diff --git a/packages/stryker/test/integration/isolated-runner/ResilientTestRunnerFactory.it.ts b/packages/stryker/test/integration/test-runner/ResilientTestRunnerFactory.it.ts similarity index 69% rename from packages/stryker/test/integration/isolated-runner/ResilientTestRunnerFactory.it.ts rename to packages/stryker/test/integration/test-runner/ResilientTestRunnerFactory.it.ts index f8248a2a0d..f9b6ad424f 100644 --- a/packages/stryker/test/integration/isolated-runner/ResilientTestRunnerFactory.it.ts +++ b/packages/stryker/test/integration/test-runner/ResilientTestRunnerFactory.it.ts @@ -3,18 +3,13 @@ import { expect } from 'chai'; import * as getPort from 'get-port'; import { RunStatus, RunnerOptions } from 'stryker-api/test_runner'; import * as log4js from 'log4js'; -import ResilientTestRunnerFactory from '../../../src/isolated-runner/ResilientTestRunnerFactory'; -import TestRunnerDecorator from '../../../src/isolated-runner/TestRunnerDecorator'; +import ResilientTestRunnerFactory from '../../../src/test-runner/ResilientTestRunnerFactory'; +import TestRunnerDecorator from '../../../src/test-runner/TestRunnerDecorator'; import { LogLevel } from 'stryker-api/core'; import LoggingServer from '../../helpers/LoggingServer'; import LoggingClientContext from '../../../src/logging/LoggingClientContext'; import { toArray } from 'rxjs/operators'; - -function sleep(ms: number) { - return new Promise(res => { - setTimeout(res, ms); - }); -} +import { sleep } from '../../../src/utils/objectUtils'; describe('ResilientTestRunnerFactory integration', function () { @@ -22,7 +17,7 @@ describe('ResilientTestRunnerFactory integration', function () { let sut: TestRunnerDecorator; let options: RunnerOptions; - const sandboxWorkingDirectory = path.resolve('./test/integration/isolated-runner'); + const sandboxWorkingDirectory = path.resolve('./test/integration/test-runner'); let loggingContext: LoggingClientContext; let loggingServer: LoggingServer; @@ -35,7 +30,7 @@ describe('ResilientTestRunnerFactory integration', function () { loggingContext = { port, level: LogLevel.Trace }; options = { strykerOptions: { - plugins: ['../../test/integration/isolated-runner/AdditionalTestRunners'], + plugins: [require.resolve('./AdditionalTestRunners')], testRunner: 'karma', testFramework: 'jasmine', port: 0, @@ -54,8 +49,13 @@ describe('ResilientTestRunnerFactory integration', function () { await loggingServer.dispose(); }); - function arrangeSut(name: string): TestRunnerDecorator { - return sut = ResilientTestRunnerFactory.create(name, options, sandboxWorkingDirectory, loggingContext); + function createSut(name: string) { + sut = ResilientTestRunnerFactory.create(name, options, sandboxWorkingDirectory, loggingContext); + } + + function arrangeSut(name: string): Promise { + createSut(name); + return sut.init(); } function actRun(timeout = 4000) { @@ -63,47 +63,44 @@ describe('ResilientTestRunnerFactory integration', function () { } it('should be able to receive a regex', async () => { - arrangeSut('discover-regex'); + await arrangeSut('discover-regex'); const result = await actRun(); expect(result.status).eq(RunStatus.Complete); }); it('should pass along the coverage result from the test runner behind', async () => { - arrangeSut('coverage-reporting'); + await arrangeSut('coverage-reporting'); const result = await actRun(); expect(result.coverage).eq('realCoverage'); }); it('should pass along the run result', async () => { - arrangeSut('direct-resolved'); + await arrangeSut('direct-resolved'); const result = await actRun(); expect(result.status).eq(RunStatus.Complete); }); it('should try to report coverage from the global scope, even when the test runner behind does not', async () => { - arrangeSut('direct-resolved'); + await arrangeSut('direct-resolved'); const result = await actRun(); expect(result.coverage).eq('coverageObject'); }); it('should resolve in a timeout if the test runner never resolves', async () => { - sut = arrangeSut('never-resolved'); - await sut.init(); + await arrangeSut('never-resolved'); const result = await actRun(1000); expect(RunStatus[result.status]).eq(RunStatus[RunStatus.Timeout]); }); it('should be able to recover from a timeout by creating a new child process', async () => { - sut = arrangeSut('never-resolved'); - await sut.init(); + await arrangeSut('never-resolved'); await actRun(1000); // first timeout const result = await actRun(1000); expect(RunStatus[result.status]).eq(RunStatus[RunStatus.Timeout]); }); it('should convert any `Error` objects to string', async () => { - sut = arrangeSut('errored'); - await sut.init(); + await arrangeSut('errored'); const result = await actRun(1000); expect(RunStatus[result.status]).to.be.eq(RunStatus[RunStatus.Error]); expect(result.errorMessages).to.have.length(1); @@ -111,50 +108,57 @@ describe('ResilientTestRunnerFactory integration', function () { }); it('should run only after initialization, even when it is slow', async () => { - sut = arrangeSut('slow-init-dispose'); - await sut.init(); + await arrangeSut('slow-init-dispose'); const result = await actRun(1000); expect(RunStatus[result.status]).eq(RunStatus[RunStatus.Complete]); }); it('should be able to run twice in quick succession', async () => { - arrangeSut('direct-resolved'); - await actRun(); + await arrangeSut('direct-resolved'); const result = await actRun(); expect(RunStatus[result.status]).eq(RunStatus[RunStatus.Complete]); }); - it('should reject when `init` of test runner behind rejects', () => { - sut = arrangeSut('reject-init'); - return expect(sut.init()).rejectedWith('Init was rejected'); + it('should reject when `init` of test runner behind rejects', async () => { + createSut('reject-init'); + await expect(sut.init()).rejectedWith('Init was rejected'); }); it('should change the current working directory to the sandbox directory', async () => { - arrangeSut('verify-working-folder'); + await arrangeSut('verify-working-folder'); const result = await actRun(); expect(result.errorMessages).undefined; }); - it('should be able to recover from any crash', async () => { - // time-bomb will crash after 100 ms - arrangeSut('time-bomb'); - await sleep(101); + it('should be able to recover from an async crash', async () => { + // time-bomb will crash after 500 ms + await arrangeSut('time-bomb'); + await sleep(550); const result = await actRun(); expect(RunStatus[result.status]).eq(RunStatus[RunStatus.Complete]); expect(result.errorMessages).undefined; }); + + it('should report if a crash happens twice', async () => { + await arrangeSut('proximity-mine'); + const result = await actRun(); + expect(RunStatus[result.status]).eq(RunStatus[RunStatus.Error]); + expect(result.errorMessages).property('0').contains('Test runner crashed'); + }); it('should handle asynchronously handled promise rejections from the underlying test runner', async () => { const logEvents = loggingServer.event$.pipe(toArray()).toPromise(); - sut = arrangeSut('async-promise-rejection-handler'); - await sut.init(); + await arrangeSut('async-promise-rejection-handler'); await actRun(); await sut.dispose(); alreadyDisposed = true; await loggingServer.dispose(); const actualLogEvents = await logEvents; - expect(actualLogEvents.find(logEvent => - log4js.levels.DEBUG.isEqualTo(logEvent.level) && logEvent.data.toString().indexOf('UnhandledPromiseRejectionWarning: Unhandled promise rejection') > -1)).ok; + expect( + actualLogEvents.find(logEvent => + log4js.levels.DEBUG.isEqualTo(logEvent.level) + && logEvent.data.toString().indexOf('UnhandledPromiseRejectionWarning: Unhandled promise rejection') > -1) + ).ok; }); }); diff --git a/packages/stryker/test/unit/SandboxPoolSpec.ts b/packages/stryker/test/unit/SandboxPoolSpec.ts index 694fe0ce68..6984ce3b8a 100644 --- a/packages/stryker/test/unit/SandboxPoolSpec.ts +++ b/packages/stryker/test/unit/SandboxPoolSpec.ts @@ -6,10 +6,11 @@ import { File, LogLevel } from 'stryker-api/core'; import { TestFramework } from 'stryker-api/test_framework'; import Sandbox from '../../src/Sandbox'; import SandboxPool from '../../src/SandboxPool'; -import Task from '../../src/utils/Task'; +import { Task } from '../../src/utils/Task'; import '../helpers/globals'; import { Mock, config, file, mock, testFramework } from '../helpers/producers'; import LoggingClientContext from '../../src/logging/LoggingClientContext'; +import { sleep } from '../../src/utils/objectUtils'; const OVERHEAD_TIME_MS = 42; const LOGGING_CONTEXT: LoggingClientContext = Object.freeze({ @@ -117,8 +118,6 @@ describe('SandboxPool', () => { }); function tick() { - return new Promise(res => { - setTimeout(res, 0); - }); + return sleep(0); } diff --git a/packages/stryker/test/unit/SandboxSpec.ts b/packages/stryker/test/unit/SandboxSpec.ts index ebbaec40d6..2b06285b27 100644 --- a/packages/stryker/test/unit/SandboxSpec.ts +++ b/packages/stryker/test/unit/SandboxSpec.ts @@ -9,7 +9,7 @@ import { File, LogLevel } from 'stryker-api/core'; import { wrapInClosure, normalizeWhiteSpaces } from '../../src/utils/objectUtils'; import Sandbox from '../../src/Sandbox'; import { TempFolder } from '../../src/utils/TempFolder'; -import ResilientTestRunnerFactory from '../../src/isolated-runner/ResilientTestRunnerFactory'; +import ResilientTestRunnerFactory from '../../src/test-runner/ResilientTestRunnerFactory'; import TestableMutant, { TestSelectionResult } from '../../src/TestableMutant'; import { mutant as createMutant, testResult, Mock, createFileAlreadyExistsError } from '../helpers/producers'; import SourceFile from '../../src/SourceFile'; @@ -17,7 +17,7 @@ import '../helpers/globals'; import TranspiledMutant from '../../src/TranspiledMutant'; import * as fileUtils from '../../src/utils/fileUtils'; import currentLogMock from '../helpers/logMock'; -import TestRunnerDecorator from '../../src/isolated-runner/TestRunnerDecorator'; +import TestRunnerDecorator from '../../src/test-runner/TestRunnerDecorator'; import LoggingClientContext from '../../src/logging/LoggingClientContext'; import { RunnerOptions } from 'stryker-api/test_runner'; diff --git a/packages/stryker/test/unit/child-proxy/ChildProcessProxySpec.ts b/packages/stryker/test/unit/child-proxy/ChildProcessProxySpec.ts index 7d02507055..ce964fd27f 100644 --- a/packages/stryker/test/unit/child-proxy/ChildProcessProxySpec.ts +++ b/packages/stryker/test/unit/child-proxy/ChildProcessProxySpec.ts @@ -1,40 +1,59 @@ +import * as os from 'os'; import { expect } from 'chai'; import * as childProcess from 'child_process'; import ChildProcessProxy from '../../../src/child-proxy/ChildProcessProxy'; -import { autoStart, InitMessage, WorkerMessageKind, ParentMessage, WorkerMessage, ParentMessageKind } from '../../../src/child-proxy/messageProtocol'; +import { autoStart, InitMessage, WorkerMessageKind, ParentMessage, WorkerMessage, ParentMessageKind, DisposeMessage } from '../../../src/child-proxy/messageProtocol'; import { serialize } from '../../../src/utils/objectUtils'; import HelloClass from './HelloClass'; import LoggingClientContext from '../../../src/logging/LoggingClientContext'; import { LogLevel } from 'stryker-api/core'; +import * as objectUtils from '../../../src/utils/objectUtils'; +import { EventEmitter } from 'events'; +import { Logger } from 'stryker-api/logging'; +import { Mock } from '../../helpers/producers'; +import currentLogMock from '../../helpers/logMock'; const LOGGING_CONTEXT: LoggingClientContext = Object.freeze({ port: 4200, level: LogLevel.Fatal }); +class ChildProcessMock extends EventEmitter { + send = sandbox.stub(); + stderr = new EventEmitter(); + stdout = new EventEmitter(); + pid = 4648; +} + describe('ChildProcessProxy', () => { let sut: ChildProcessProxy; let forkStub: sinon.SinonStub; - let childProcessMock: { - send: sinon.SinonStub; - on: sinon.SinonStub; - }; + let childProcessMock: ChildProcessMock; + let killStub: sinon.SinonStub; + let logMock: Mock; + let clock: sinon.SinonFakeTimers; beforeEach(() => { + clock = sandbox.useFakeTimers(); + childProcessMock = new ChildProcessMock(); forkStub = sandbox.stub(childProcess, 'fork'); - childProcessMock = { - send: sandbox.stub(), - on: sandbox.stub() - }; + killStub = sandbox.stub(objectUtils, 'kill'); forkStub.returns(childProcessMock); + logMock = currentLogMock(); + }); + + afterEach(() => { + childProcessMock.removeAllListeners(); + childProcessMock.stderr.removeAllListeners(); + childProcessMock.stdout.removeAllListeners(); }); - describe('create', () => { + describe('constructor', () => { it('should create child process', () => { - ChildProcessProxy.create('foobar', LOGGING_CONTEXT, ['examplePlugin', 'secondExamplePlugin'], HelloClass, 'something'); - expect(forkStub).calledWith(require.resolve('../../../src/child-proxy/ChildProcessProxyWorker'), [autoStart], { silent: false, execArgv: [] }); + sut = createSut(); + expect(forkStub).calledWith(require.resolve('../../../src/child-proxy/ChildProcessProxyWorker'), [autoStart], { silent: true, execArgv: [] }); }); it('should send init message to child process', () => { @@ -43,29 +62,76 @@ describe('ChildProcessProxy', () => { loggingContext: LOGGING_CONTEXT, plugins: ['examplePlugin', 'secondExamplePlugin'], requirePath: 'foobar', - constructorArgs: ['something'] + constructorArgs: ['something'], + workingDirectory: 'workingDirectory' }; // Act - ChildProcessProxy.create('foobar', LOGGING_CONTEXT, ['examplePlugin', 'secondExamplePlugin'], HelloClass, 'something'); + createSut({ + arg: expectedMessage.constructorArgs[0], + loggingContext: LOGGING_CONTEXT, + plugins: expectedMessage.plugins, + workingDir: expectedMessage.workingDirectory, + requirePath: expectedMessage.requirePath + }); + ChildProcessProxy.create(expectedMessage.requirePath, LOGGING_CONTEXT, expectedMessage.plugins, + expectedMessage.workingDirectory, HelloClass, expectedMessage.constructorArgs[0]); // Assert expect(childProcessMock.send).calledWith(serialize(expectedMessage)); }); it('should listen to worker process', () => { - ChildProcessProxy.create('foobar', LOGGING_CONTEXT, [], HelloClass, ''); - expect(childProcessMock.on).calledWith('message'); + createSut(); + expect(childProcessMock.listeners('message')).lengthOf(1); + }); + + it('should listen for exit calls', () => { + createSut(); + expect(childProcessMock.listeners('exit')).lengthOf(1); + }); + }); + + describe('on exit', () => { + beforeEach(() => { + sut = createSut(); }); + + it('should log stdout and stderr on warning', () => { + childProcessMock.stderr.emit('data', 'foo'); + childProcessMock.stdout.emit('data', 'bar'); + actExit(23, 'SIGTERM'); + expect(logMock.warn).calledWithMatch(`Child process [pid ${childProcessMock.pid}] exited unexpectedly with exit code 23 (SIGTERM). Last part of stdout and stderr was:${os.EOL + }\tfoo${os.EOL}\tbar`); + }); + + it('should log that no stdout was available when stdout and stderr are empty', () => { + actExit(23, 'SIGTERM'); + expect(logMock.warn).calledWith(`Child process [pid ${childProcessMock.pid}] exited unexpectedly with exit code 23 (SIGTERM). Stdout and stderr were empty.`); + }); + + it('should reject any outstanding worker promises with the error', () => { + const expectedError = 'Child process [pid 4648] exited unexpectedly with exit code 646 (SIGINT).'; + const actualPromise = sut.proxy.say('test'); + actExit(646); + return expect(actualPromise).rejectedWith(expectedError); + }); + + it('should reject any new calls immediately', () => { + actExit(646); + return expect(sut.proxy.say('')).rejected; + }); + + function actExit(code = 1, signal = 'SIGINT') { + childProcessMock.emit('exit', code, signal); + } }); describe('when calling methods', () => { beforeEach(() => { - sut = ChildProcessProxy.create('', LOGGING_CONTEXT, [], HelloClass, ''); - const initDoneResult: ParentMessage = { kind: ParentMessageKind.Initialized }; - const msg = serialize(initDoneResult); - childProcessMock.on.callArgWith(1, [msg]); + sut = createSut(); + receiveMessage({ kind: ParentMessageKind.Initialized }); }); it('should proxy the message', async () => { @@ -76,26 +142,87 @@ describe('ChildProcessProxy', () => { result: 'ack' }; const expectedWorkerMessage: WorkerMessage = { - kind: WorkerMessageKind.Work, + kind: WorkerMessageKind.Call, correlationId: 0, - methodName: 'sayHello', + methodName: 'say', args: ['echo'] }; // Act - const delayedEcho = sut.proxy.sayHello('echo'); - await tick(); - childProcessMock.on.callArgWith(1, [serialize(workerResponse)]); // resolve the promise + const delayedEcho = sut.proxy.say('echo'); + clock.tick(0); + receiveMessage(workerResponse); const result: string = await delayedEcho; // Assert expect(result).eq('ack'); expect(childProcessMock.send).calledWith(serialize(expectedWorkerMessage)); }); + }); + + describe('dispose', () => { + + beforeEach(() => { + sut = createSut(); + }); + + it('should send a dispose message', async () => { + await actDispose(); + const expectedWorkerMessage: DisposeMessage = { kind: WorkerMessageKind.Dispose }; + expect(childProcessMock.send).calledWith(serialize(expectedWorkerMessage)); + }); + + it('should kill the child process', async () => { + await actDispose(); + expect(killStub).calledWith(childProcessMock.pid); + }); + + it('should not do anything if already disposed', async () => { + await actDispose(); + await actDispose(); + expect(killStub).calledOnce; + expect(childProcessMock.send).calledTwice; // 1 init, 1 dispose + }); + + it('should not do anything if the process already exited', async () => { + childProcessMock.emit('exit', 1); + await actDispose(); + expect(killStub).not.called; + expect(childProcessMock.send).calledOnce; // init + }); + + it('should only wait for max 2 seconds before going ahead and killing the child process anyway', async () => { + const disposePromise = sut.dispose(); + clock.tick(2000); + await disposePromise; + expect(killStub).called; + }); + + async function actDispose() { + const disposePromise = sut.dispose(); + receiveMessage({ kind: ParentMessageKind.DisposeCompleted }); + await disposePromise; + } }); - function tick() { - return new Promise(res => setTimeout(res, 0)); + function receiveMessage(workerResponse: ParentMessage) { + childProcessMock.emit('message', serialize(workerResponse)); } -}); \ No newline at end of file +}); + +function createSut(overrides: { + requirePath?: string; + loggingContext?: LoggingClientContext; + plugins?: string[]; + workingDir?: string; + arg?: string; +} = {}): ChildProcessProxy { + return ChildProcessProxy.create( + overrides.requirePath || 'foobar', + overrides.loggingContext || LOGGING_CONTEXT, + overrides.plugins || ['examplePlugin', 'secondExamplePlugin'], + overrides.workingDir || 'workingDir', + HelloClass, + overrides.arg || 'someArg'); +} diff --git a/packages/stryker/test/unit/child-proxy/ChildProcessWorkerSpec.ts b/packages/stryker/test/unit/child-proxy/ChildProcessWorkerSpec.ts index b4791db94c..e860cadfcb 100644 --- a/packages/stryker/test/unit/child-proxy/ChildProcessWorkerSpec.ts +++ b/packages/stryker/test/unit/child-proxy/ChildProcessWorkerSpec.ts @@ -1,13 +1,16 @@ +import * as path from 'path'; import ChildProcessProxyWorker from '../../../src/child-proxy/ChildProcessProxyWorker'; import { expect } from 'chai'; import { serialize } from '../../../src/utils/objectUtils'; -import { WorkerMessage, WorkerMessageKind, ParentMessage, WorkResult, WorkMessage, ParentMessageKind } from '../../../src/child-proxy/messageProtocol'; +import { WorkerMessage, WorkerMessageKind, ParentMessage, WorkResult, CallMessage, ParentMessageKind, InitMessage } from '../../../src/child-proxy/messageProtocol'; import PluginLoader, * as pluginLoader from '../../../src/PluginLoader'; import { Mock, mock } from '../../helpers/producers'; import HelloClass from './HelloClass'; import LogConfigurator from '../../../src/logging/LogConfigurator'; import { LogLevel } from 'stryker-api/core'; import LoggingClientContext from '../../../src/logging/LoggingClientContext'; +import { Logger } from 'stryker-api/logging'; +import currentLogMock from '../../helpers/logMock'; const LOGGING_CONTEXT: LoggingClientContext = Object.freeze({ port: 4200, level: LogLevel.Fatal }); @@ -18,12 +21,16 @@ describe('ChildProcessProxyWorker', () => { let processListenersStub: sinon.SinonStub; let configureChildProcessStub: sinon.SinonStub; let processRemoveListenerStub: sinon.SinonStub; + let processChdirStub: sinon.SinonStub; + let logMock: Mock; let pluginLoaderMock: Mock; let originalProcessSend: undefined | NodeJS.MessageListener; let processes: NodeJS.MessageListener[]; + const workingDir = 'working dir'; beforeEach(() => { processes = []; + logMock = currentLogMock(); processOnStub = sandbox.stub(process, 'on'); processListenersStub = sandbox.stub(process, 'listeners'); processListenersStub.returns(processes); @@ -32,6 +39,7 @@ describe('ChildProcessProxyWorker', () => { // process.send is normally undefined originalProcessSend = process.send; process.send = processSendStub; + processChdirStub = sandbox.stub(process, 'chdir'); configureChildProcessStub = sandbox.stub(LogConfigurator, 'configureChildProcess'); pluginLoaderMock = mock(PluginLoader); sandbox.stub(pluginLoader, 'default').returns(pluginLoaderMock); @@ -49,7 +57,7 @@ describe('ChildProcessProxyWorker', () => { describe('after init message', () => { let sut: ChildProcessProxyWorker; - let initMessage: WorkerMessage; + let initMessage: InitMessage; beforeEach(() => { sut = new ChildProcessProxyWorker(); @@ -58,19 +66,34 @@ describe('ChildProcessProxyWorker', () => { loggingContext: LOGGING_CONTEXT, constructorArgs: ['FooBarName'], plugins: ['fooPlugin', 'barPlugin'], - requirePath: require.resolve('./HelloClass') + requirePath: require.resolve('./HelloClass'), + workingDirectory: workingDir }; }); it('should create the correct real instance', () => { - processOnStub.callArgWith(1, [serialize(initMessage)]); + processOnMessage(initMessage); expect(sut.realSubject).instanceOf(HelloClass); const actual = sut.realSubject as HelloClass; expect(actual.name).eq('FooBarName'); }); + it('should change the current working directory', () => { + processOnMessage(initMessage); + const fullWorkingDir = path.resolve(workingDir); + expect(logMock.debug).calledWith(`Changing current working directory for this process to ${fullWorkingDir}`); + expect(processChdirStub).calledWith(fullWorkingDir); + }); + + it('should not change the current working directory if it didn\'t change', () => { + initMessage.workingDirectory = process.cwd(); + processOnMessage(initMessage); + expect(logMock.debug).not.called; + expect(processChdirStub).not.called; + }); + it('should send "init_done"', async () => { - processOnStub.callArgWith(1, [serialize(initMessage)]); + processOnMessage(initMessage); const expectedWorkerResponse: ParentMessage = { kind: ParentMessageKind.Initialized }; await tick(); // make sure promise is resolved expect(processSendStub).calledWith(serialize(expectedWorkerResponse)); @@ -82,7 +105,7 @@ describe('ChildProcessProxyWorker', () => { processes.push(noop); // Act - processOnStub.callArgWith(1, [serialize(initMessage)]); + processOnMessage(initMessage); await tick(); // make sure promise is resolved // Assert @@ -95,27 +118,40 @@ describe('ChildProcessProxyWorker', () => { }); it('should load plugins', () => { - processOnStub.callArgWith(1, serialize(initMessage)); + processOnMessage(initMessage); expect(pluginLoader.default).calledWithNew; expect(pluginLoader.default).calledWith(['fooPlugin', 'barPlugin']); expect(pluginLoaderMock.load).called; }); + + it('should handle unhandledRejection events', () => { + processOnMessage(initMessage); + const error = new Error('foobar'); + processOnStub.withArgs('unhandledRejection').callArgWith(1, error); + expect(logMock.debug).calledWith(`UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): ${error}`); + }); + + it('should handle rejectionHandled events', () => { + processOnMessage(initMessage); + processOnStub.withArgs('rejectionHandled').callArgWith(1); + expect(logMock.debug).calledWith('PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 0)'); + }); describe('on worker message', () => { - async function actAndAssert(workerMessage: WorkMessage, expectedResult: WorkResult) { + async function actAndAssert(workerMessage: CallMessage, expectedResult: WorkResult) { // Act - processOnStub.callArgWith(1, serialize(initMessage)); - processOnStub.callArgWith(1, serialize(workerMessage)); + processOnMessage(initMessage); + processOnMessage(workerMessage); await tick(); // Assert expect(processSendStub).calledWith(serialize(expectedResult)); } - async function actAndAssertRejection(workerMessage: WorkMessage, expectedError: string) { + async function actAndAssertRejection(workerMessage: CallMessage, expectedError: string) { // Act - processOnStub.callArgWith(1, serialize(initMessage)); - processOnStub.callArgWith(1, serialize(workerMessage)); + processOnMessage(initMessage); + processOnMessage(workerMessage); await tick(); // Assert expect(processSendStub).calledWithMatch(`"correlationId": ${workerMessage.correlationId.toString()}`); @@ -126,7 +162,7 @@ describe('ChildProcessProxyWorker', () => { it('should send the result', async () => { // Arrange const workerMessage: WorkerMessage = { - kind: WorkerMessageKind.Work, + kind: WorkerMessageKind.Call, correlationId: 32, args: [], methodName: 'sayHello' @@ -143,7 +179,7 @@ describe('ChildProcessProxyWorker', () => { it('should send a rejection', async () => { // Arrange const workerMessage: WorkerMessage = { - kind: WorkerMessageKind.Work, + kind: WorkerMessageKind.Call, correlationId: 32, args: [], methodName: 'reject' @@ -151,10 +187,10 @@ describe('ChildProcessProxyWorker', () => { await actAndAssertRejection(workerMessage, 'Rejected'); }); - it('should send a thrown synchronous error as rejection', async () => { + it('should send a thrown synchronous error as rejection', async () => { // Arrange const workerMessage: WorkerMessage = { - kind: WorkerMessageKind.Work, + kind: WorkerMessageKind.Call, correlationId: 32, args: ['foo bar'], methodName: 'throw' @@ -165,7 +201,7 @@ describe('ChildProcessProxyWorker', () => { it('should use correct arguments', async () => { // Arrange const workerMessage: WorkerMessage = { - kind: WorkerMessageKind.Work, + kind: WorkerMessageKind.Call, correlationId: 32, args: ['foo', 'bar', 'chair'], methodName: 'say' @@ -182,7 +218,7 @@ describe('ChildProcessProxyWorker', () => { it('should work with promises from real class', async () => { // Arrange const workerMessage: WorkerMessage = { - kind: WorkerMessageKind.Work, + kind: WorkerMessageKind.Call, correlationId: 32, args: [], methodName: 'sayDelayed' @@ -198,8 +234,16 @@ describe('ChildProcessProxyWorker', () => { }); }); + + function processOnMessage(message: WorkerMessage) { + processOnStub + .withArgs('message') + .callArgWith(1, [serialize(message)]); + } + }); + function tick() { return new Promise(res => setTimeout(res, 0)); } \ No newline at end of file diff --git a/packages/stryker/test/unit/child-proxy/HelloClass.ts b/packages/stryker/test/unit/child-proxy/HelloClass.ts index 05e895ecdb..600786ae3f 100644 --- a/packages/stryker/test/unit/child-proxy/HelloClass.ts +++ b/packages/stryker/test/unit/child-proxy/HelloClass.ts @@ -11,6 +11,10 @@ export default class HelloClass { return `hello ${things.join(' and ')}`; } + sum(a: number, b: number) { + return a + b; + } + reject() { return Promise.reject(new Error('Rejected')); } diff --git a/packages/stryker/test/unit/isolated-runner/IsolatedTestRunnerAdapterSpec.ts b/packages/stryker/test/unit/isolated-runner/IsolatedTestRunnerAdapterSpec.ts deleted file mode 100644 index 5a49298bee..0000000000 --- a/packages/stryker/test/unit/isolated-runner/IsolatedTestRunnerAdapterSpec.ts +++ /dev/null @@ -1,178 +0,0 @@ -import { EmptyAdapterMessage } from './../../../src/isolated-runner/MessageProtocol'; -import * as path from 'path'; -import * as child_process from 'child_process'; -import * as _ from 'lodash'; -import * as sinon from 'sinon'; -import { expect } from 'chai'; -import { RunResult, RunStatus, RunnerOptions } from 'stryker-api/test_runner'; -import IsolatedTestRunnerAdapter from '../../../src/isolated-runner/IsolatedTestRunnerAdapter'; -import { WorkerMessage, RunMessage, ResultMessage } from '../../../src/isolated-runner/MessageProtocol'; -import * as objectUtils from '../../../src/utils/objectUtils'; -import { LogLevel } from 'stryker-api/core'; - -describe('IsolatedTestRunnerAdapter', () => { - let sut: IsolatedTestRunnerAdapter; - let sinonSandbox: sinon.SinonSandbox; - let clock: sinon.SinonFakeTimers; - let killStub: sinon.SinonStub; - let fakeChildProcess: { - kill: sinon.SinonStub; - send: sinon.SinonStub; - on: sinon.SinonStub; - pid: number; - }; - let runnerOptions: RunnerOptions; - - beforeEach(() => { - runnerOptions = { - fileNames: [], - port: 42, - strykerOptions: {} - }; - sinonSandbox = sinon.createSandbox(); - fakeChildProcess = { - kill: sinon.stub(), - send: sinon.stub(), - on: sinon.stub(), - pid: 42 - }; - killStub = sinonSandbox.stub(objectUtils, 'kill'); - sinonSandbox.stub(child_process, 'fork').returns(fakeChildProcess); - clock = sinon.useFakeTimers(); - }); - - describe('when constructed', () => { - - beforeEach(() => { - sut = new IsolatedTestRunnerAdapter('realRunner', runnerOptions, 'a working directory', { port: 4200, level: LogLevel.Fatal }); - }); - - it('should spawn a child process', () => { - let expectedWorkerProcessPath = path.resolve(__dirname + '/../../../src/isolated-runner/') + '/IsolatedTestRunnerAdapterWorker'; - let expectedExecArgv = _.clone(process.execArgv); - _.remove(expectedExecArgv, arg => arg.substr(0, 11) === '--debug-brk'); - expect(child_process.fork).to.have.been.calledWith(expectedWorkerProcessPath, [], { execArgv: expectedExecArgv, silent: true }); - expect(fakeChildProcess.on).to.have.been.calledWith('message'); - }); - - describe('init', () => { - - let initPromise: Promise; - - function arrangeAct() { - initPromise = sut.init(); - clock.tick(500); - receiveResultMessage(); - } - - it('should call "init" on child process', () => { - arrangeAct(); - const expectedMessage: EmptyAdapterMessage = { kind: 'init' }; - expect(fakeChildProcess.send).to.have.been.calledWith(objectUtils.serialize(expectedMessage)); - }); - - - it(' "initDone"', () => { - arrangeAct(); - receiveMessage({ kind: 'initDone', errorMessage: null }); - return expect(initPromise).to.eventually.eq(undefined); - }); - - it('should reject any exceptions', () => { - fakeChildProcess.send.throws(new Error('some error')); - arrangeAct(); - return expect(initPromise).to.be.rejectedWith('some error'); - }); - }); - - describe('run(options)', () => { - const runOptions: { timeout: 2000 } = { timeout: 2000 }; - let runPromise: Promise; - - function act() { - runPromise = sut.run(runOptions); - } - - it('should send run-message to worker', () => { - act(); - const expectedMessage: RunMessage = { - kind: 'run', - runOptions - }; - expect(fakeChildProcess.send).to.have.been.calledWith(objectUtils.serialize(expectedMessage)); - }); - - it('should proxy run response', () => { - const expectedResult: RunResult = { - status: RunStatus.Error, - errorMessages: ['OK, only used for unit testing'], - tests: [] - }; - act(); - receiveMessage({ kind: 'result', result: expectedResult }); - expect(runPromise).to.eventually.be.eq(expectedResult); - }); - - it('should reject any exceptions', () => { - fakeChildProcess.send.throws(new Error('some error')); - act(); - return expect(runPromise).to.be.rejectedWith('some error'); - }); - }); - - describe('dispose()', () => { - - it('should send `dispose` to worker process', () => { - sut.dispose(); - return expect(fakeChildProcess.send).to.have.been.calledWith(objectUtils.serialize({ kind: 'dispose' })); - }); - - describe('and child process responds to dispose', () => { - beforeEach(() => { - const promise = sut.dispose(); - receiveMessage({ kind: 'disposeDone' }); - return promise; - }); - - it('should kill the child process', () => { - expect(killStub).to.have.been.calledWith(42); - }); - }); - - describe('and a timeout occurred', () => { - - beforeEach(() => { - // Wait for worker process takes 2000 ms - const promise = sut.dispose(); - clock.tick(2000); - return promise; - }); - - it('should kill the child process', () => { - expect(killStub).to.have.been.calledWith(42); - }); - }); - }); - it('should reject any exceptions', () => { - fakeChildProcess.send.throws(new Error('some error')); - return expect(sut.run({ timeout: 24 })).to.be.rejectedWith('some error'); - }); - }); - - const receiveResultMessage = () => { - const message: ResultMessage = { kind: 'result', result: { status: RunStatus.Complete, tests: [] } }; - receiveMessage(message); - return message; - }; - - const receiveMessage = (message: WorkerMessage) => { - const callback: (message: WorkerMessage) => void = fakeChildProcess.on.getCall(0).args[1]; - callback(message); - return message; - }; - - afterEach(() => { - clock.restore(); - sinonSandbox.restore(); - }); -}); \ No newline at end of file diff --git a/packages/stryker/test/unit/isolated-runner/RetryDecoratorSpec.ts b/packages/stryker/test/unit/isolated-runner/RetryDecoratorSpec.ts deleted file mode 100644 index 4740930413..0000000000 --- a/packages/stryker/test/unit/isolated-runner/RetryDecoratorSpec.ts +++ /dev/null @@ -1,83 +0,0 @@ -import { expect } from 'chai'; -import { RunResult, RunStatus } from 'stryker-api/test_runner'; -import RetryDecorator from '../../../src/isolated-runner/RetryDecorator'; -import TestRunnerMock from '../../helpers/TestRunnerMock'; -import { errorToString } from '../../../src/utils/objectUtils'; -import TestRunnerDecorator from '../../../src/isolated-runner/TestRunnerDecorator'; - -describe('RetryDecorator', () => { - let sut: RetryDecorator; - let testRunner1: TestRunnerMock; - let testRunner2: TestRunnerMock; - let testRunner3: TestRunnerMock; - let testRunner4: TestRunnerMock; - let availableTestRunners: TestRunnerMock[]; - const options = { timeout: 2 }; - const expectedResult = 'something'; - const brokenPipeError: NodeJS.ErrnoException = { - name: '', - code: 'EPIPE', - message: 'Intended error for testing' - }; - - beforeEach(() => { - testRunner1 = new TestRunnerMock(); - testRunner2 = new TestRunnerMock(); - testRunner3 = new TestRunnerMock(); - testRunner4 = new TestRunnerMock(); - availableTestRunners = [testRunner1, testRunner2, testRunner3, testRunner4]; - sut = new RetryDecorator(() => availableTestRunners.shift()); - }); - - describe('init', () => { - it('should not be overridden', () => { - expect(sut.init).to.be.eq(TestRunnerDecorator.prototype.init); - }); - }); - - describe('dispose', () => { - it('should pass through when resolved', () => { - testRunner1.dispose.resolves(null); - return expect(sut.dispose()).to.eventually.eq(null); - }); - - it('should swallow rejections when inner process crashed', () => { - testRunner1.dispose.rejects(brokenPipeError); - return expect(sut.dispose()).to.eventually.not.be.ok; - }); - - it('should pass through non-crash related rejections', () => { - testRunner1.dispose.rejects(new Error('someError')); - return expect(sut.dispose()).to.be.rejectedWith('someError'); - }); - }); - - describe('run', () => { - it('should pass through resolved values', () => { - testRunner1.run.resolves(expectedResult); - const result = sut.run(options); - expect(testRunner1.run).to.have.been.calledWith(options); - return expect(result).to.eventually.eq(expectedResult); - }); - - it('should retry on a new test runner if a reject appears', () => { - testRunner1.run.rejects(new Error('Error')); - testRunner2.run.resolves(expectedResult); - return expect(sut.run(options)).to.eventually.eq(expectedResult); - }); - - it('should retry at most 1 times before rejecting', () => { - const finalError = new Error('Error'); - - testRunner1.run.rejects(new Error('Error')); - testRunner2.run.rejects(finalError); - - return sut.run(options).then((runResult: RunResult) => { - expect(runResult.status).to.be.eq(RunStatus.Error); - expect(runResult.errorMessages).to.be.deep.eq(['Test runner crashed. Tried twice to restart it without any luck. Last time the error message was: ' - + errorToString(finalError)]); - expect(availableTestRunners).to.have.lengthOf(0); - }); - }); - }); -}); \ No newline at end of file diff --git a/packages/stryker/test/unit/test-runner/ChildProcessTestRunnerDecoratorSpec.ts b/packages/stryker/test/unit/test-runner/ChildProcessTestRunnerDecoratorSpec.ts new file mode 100644 index 0000000000..b4ed5513b6 --- /dev/null +++ b/packages/stryker/test/unit/test-runner/ChildProcessTestRunnerDecoratorSpec.ts @@ -0,0 +1,95 @@ +import * as sinon from 'sinon'; +import { expect } from 'chai'; +import { RunnerOptions, RunOptions } from 'stryker-api/test_runner'; +import { LogLevel } from 'stryker-api/core'; +import ChildProcessTestRunnerDecorator from '../../../src/test-runner/ChildProcessTestRunnerDecorator'; +import { Mock, mock } from '../../helpers/producers'; +import ChildProcessProxy from '../../../src/child-proxy/ChildProcessProxy'; +import LoggingClientContext from '../../../src/logging/LoggingClientContext'; +import ChildProcessTestRunnerWorker from '../../../src/test-runner/ChildProcessTestRunnerWorker'; +import TestRunnerDecorator from '../../../src/test-runner/TestRunnerDecorator'; +import { Task } from '../../../src/utils/Task'; +import ChildProcessCrashedError from '../../../src/child-proxy/ChildProcessCrashedError'; + +describe(ChildProcessTestRunnerDecorator.name, () => { + let sut: ChildProcessTestRunnerDecorator; + let runnerOptions: RunnerOptions; + let childProcessProxyMock: { + proxy: Mock; + dispose: sinon.SinonStub; + }; + let childProcessProxyCreateStub: sinon.SinonStub; + let loggingContext: LoggingClientContext; + let clock: sinon.SinonFakeTimers; + + beforeEach(() => { + clock = sandbox.useFakeTimers(); + childProcessProxyMock = { + proxy: mock(TestRunnerDecorator), + dispose: sandbox.stub() + }; + childProcessProxyCreateStub = sandbox.stub(ChildProcessProxy, 'create'); + childProcessProxyCreateStub.returns(childProcessProxyMock); + runnerOptions = { + fileNames: [], + port: 42, + strykerOptions: { + plugins: ['foo-plugin', 'bar-plugin'] + } + }; + loggingContext = { port: 4200, level: LogLevel.Fatal }; + sut = new ChildProcessTestRunnerDecorator('realRunner', runnerOptions, 'a working directory', loggingContext); + }); + + it('should create the child process proxy', () => { + expect(childProcessProxyCreateStub).calledWith( + require.resolve('../../../src/test-runner/ChildProcessTestRunnerWorker.js'), + loggingContext, + ['foo-plugin', 'bar-plugin'], + 'a working directory', + ChildProcessTestRunnerWorker, + 'realRunner', runnerOptions + ); + }); + + it('should forward `init` calls', () => { + childProcessProxyMock.proxy.init.resolves(42); + return expect(sut.init()).eventually.eq(42); + }); + + it('should forward `run` calls', async () => { + childProcessProxyMock.proxy.run.resolves(42); + const runOptions: RunOptions = { + timeout: 234 + }; + await expect(sut.run(runOptions)).eventually.eq(42); + expect(childProcessProxyMock.proxy.run).calledWith(runOptions); + }); + + describe('dispose', () => { + + it('should dispose the test runner before disposing the child process itself on `dispose`', async () => { + childProcessProxyMock.proxy.dispose.resolves(); + await sut.dispose(); + expect(childProcessProxyMock.proxy.dispose) + .calledBefore(childProcessProxyMock.dispose); + }); + + it('should not reject when the child process is down', async () => { + childProcessProxyMock.proxy.dispose.rejects(new ChildProcessCrashedError(1, '1')); + await sut.dispose(); + expect(childProcessProxyMock.dispose).called; + }); + + it('should only wait 2 seconds for the test runner to be disposed', async () => { + const testRunnerDisposeTask = new Task(); + childProcessProxyMock.proxy.dispose.returns(testRunnerDisposeTask.promise); + const disposePromise = sut.dispose(); + clock.tick(2001); + await disposePromise; + expect(childProcessProxyMock.dispose).called; + testRunnerDisposeTask.resolve(undefined); + }); + + }); +}); \ No newline at end of file diff --git a/packages/stryker/test/unit/test-runner/RetryDecoratorSpec.ts b/packages/stryker/test/unit/test-runner/RetryDecoratorSpec.ts new file mode 100644 index 0000000000..d52528bb04 --- /dev/null +++ b/packages/stryker/test/unit/test-runner/RetryDecoratorSpec.ts @@ -0,0 +1,86 @@ +import { expect } from 'chai'; +import { RunStatus } from 'stryker-api/test_runner'; +import RetryDecorator from '../../../src/test-runner/RetryDecorator'; +import TestRunnerMock from '../../helpers/TestRunnerMock'; +import { errorToString } from '../../../src/utils/objectUtils'; +import TestRunnerDecorator from '../../../src/test-runner/TestRunnerDecorator'; +import ChildProcessCrashedError from '../../../src/child-proxy/ChildProcessCrashedError'; +import OutOfMemoryError from '../../../src/child-proxy/OutOfMemoryError'; +import { Logger } from 'stryker-api/logging'; +import { Mock } from '../../helpers/producers'; +import currentLogMock from '../../helpers/logMock'; + +describe('RetryDecorator', () => { + let sut: RetryDecorator; + let testRunner1: TestRunnerMock; + let testRunner2: TestRunnerMock; + let availableTestRunners: TestRunnerMock[]; + let logMock: Mock; + const options = { timeout: 2 }; + const expectedResult = 'something'; + const crashedError = new ChildProcessCrashedError(42, ''); + + beforeEach(() => { + testRunner1 = new TestRunnerMock(); + testRunner2 = new TestRunnerMock(); + logMock = currentLogMock(); + availableTestRunners = [testRunner1, testRunner2]; + sut = new RetryDecorator(() => availableTestRunners.shift() || new TestRunnerMock()); + }); + + it('should not override `init`', () => { + expect(sut.init).to.be.eq(TestRunnerDecorator.prototype.init); + }); + + it('should not override `dispose`', () => { + expect(sut.dispose).to.be.eq(TestRunnerDecorator.prototype.dispose); + }); + + describe('run', () => { + it('should pass through resolved values', () => { + testRunner1.run.resolves(expectedResult); + const result = sut.run(options); + expect(testRunner1.run).to.have.been.calledWith(options); + return expect(result).to.eventually.eq(expectedResult); + }); + + it('should retry on a new test runner if a run is rejected', () => { + testRunner1.run.rejects(new Error('Error')); + testRunner2.run.resolves(expectedResult); + return expect(sut.run(options)).to.eventually.eq(expectedResult); + }); + + it('should retry if a `ChildProcessCrashedError` occurred reject appears', () => { + testRunner1.run.rejects(crashedError); + testRunner2.run.resolves(expectedResult); + return expect(sut.run(options)).to.eventually.eq(expectedResult); + }); + + it('should log and retry when an `OutOfMemoryError` occurred.', async () => { + testRunner1.run.rejects(new OutOfMemoryError(123, 123)); + testRunner2.run.resolves(expectedResult); + await expect(sut.run(options)).to.eventually.eq(expectedResult); + expect(logMock.info).calledWith('Test runner process [%s] ran out of memory. You probably have a memory leak in your tests. Don\'t worry, Stryker will restart the process, but you might want to investigate this later, because this decreases performance.', 123); + }); + + it('should dispose a test runner when it rejected, before creating a new one', async () => { + testRunner1.run.rejects(crashedError); + testRunner2.run.resolves(expectedResult); + await sut.run(options); + expect(testRunner1.dispose).calledBefore(testRunner2.init); + }); + + it('should retry at most 1 times before rejecting', async () => { + const finalError = new Error('foo'); + + testRunner1.run.rejects(new Error('bar')); + testRunner2.run.rejects(finalError); + + const runResult = await sut.run(options); + expect(runResult.status).to.be.eq(RunStatus.Error); + expect(runResult.errorMessages).to.be.deep.eq(['Test runner crashed. Tried twice to restart it without any luck. Last time the error message was: ' + + errorToString(finalError)]); + expect(availableTestRunners).to.have.lengthOf(0); + }); + }); +}); \ No newline at end of file diff --git a/packages/stryker/test/unit/isolated-runner/TestRunnerDecoratorSpec.ts b/packages/stryker/test/unit/test-runner/TestRunnerDecoratorSpec.ts similarity index 91% rename from packages/stryker/test/unit/isolated-runner/TestRunnerDecoratorSpec.ts rename to packages/stryker/test/unit/test-runner/TestRunnerDecoratorSpec.ts index 5813b4a5fa..468c194976 100644 --- a/packages/stryker/test/unit/isolated-runner/TestRunnerDecoratorSpec.ts +++ b/packages/stryker/test/unit/test-runner/TestRunnerDecoratorSpec.ts @@ -1,5 +1,5 @@ import { expect } from 'chai'; -import TestRunnerDecorator from '../../../src/isolated-runner/TestRunnerDecorator'; +import TestRunnerDecorator from '../../../src/test-runner/TestRunnerDecorator'; import TestRunnerMock from '../../helpers/TestRunnerMock'; describe('TestRunnerDecorator', () => { diff --git a/packages/stryker/test/unit/isolated-runner/TimeoutDecoratorSpec.ts b/packages/stryker/test/unit/test-runner/TimeoutDecoratorSpec.ts similarity index 89% rename from packages/stryker/test/unit/isolated-runner/TimeoutDecoratorSpec.ts rename to packages/stryker/test/unit/test-runner/TimeoutDecoratorSpec.ts index 8917b30aab..fcd7493640 100644 --- a/packages/stryker/test/unit/isolated-runner/TimeoutDecoratorSpec.ts +++ b/packages/stryker/test/unit/test-runner/TimeoutDecoratorSpec.ts @@ -1,7 +1,7 @@ import * as sinon from 'sinon'; import { expect } from 'chai'; import { RunStatus } from 'stryker-api/test_runner'; -import TimeoutDecorator from '../../../src/isolated-runner/TimeoutDecorator'; +import TimeoutDecorator from '../../../src/test-runner/TimeoutDecorator'; import { isPromise } from '../../../src/utils/objectUtils'; import TestRunnerMock from '../../helpers/TestRunnerMock'; @@ -58,14 +58,6 @@ describe('TimeoutDecorator', () => { describe('dispose', () => { itShouldProxyRequestsForMethod('dispose'); - - it('should wait no longer then 2500 ms', () => { - testRunner1.dispose.returns(new Promise(res => { })); - const disposePromise = sut.dispose(); - clock.tick(2500); - const p = expect(disposePromise).to.eventually.be.eq(undefined); - return p; - }); }); describe('run', () => { diff --git a/packages/stryker/test/unit/transpiler/MutantTranspilerSpec.ts b/packages/stryker/test/unit/transpiler/MutantTranspilerSpec.ts index c0fd4186ad..2d274128a6 100644 --- a/packages/stryker/test/unit/transpiler/MutantTranspilerSpec.ts +++ b/packages/stryker/test/unit/transpiler/MutantTranspilerSpec.ts @@ -6,7 +6,7 @@ import ChildProcessProxy from '../../../src/child-proxy/ChildProcessProxy'; import MutantTranspiler from '../../../src/transpiler/MutantTranspiler'; import TranspileResult from '../../../src/transpiler/TranspileResult'; import TranspilerFacade, * as transpilerFacade from '../../../src/transpiler/TranspilerFacade'; -import { errorToString } from '../../../src/utils/objectUtils'; +import { errorToString, sleep } from '../../../src/utils/objectUtils'; import '../../helpers/globals'; import { Mock, config, file, mock, testableMutant } from '../../helpers/producers'; import LoggingClientContext from '../../../src/logging/LoggingClientContext'; @@ -44,6 +44,7 @@ describe('MutantTranspiler', () => { require.resolve('../../../src/transpiler/TranspilerFacade'), LOGGING_CONTEXT, ['plugin1'], + process.cwd(), TranspilerFacade, { config: expectedConfig, produceSourceMaps: false } ); @@ -156,9 +157,7 @@ describe('MutantTranspiler', () => { ]; expect(actualResults).deep.eq(expectedResults); }); - const nextTick = () => new Promise(res => { - setTimeout(res, 0); - }); + const nextTick = () => sleep(0); }); }); diff --git a/packages/stryker/test/unit/utils/StringBuilderSpec.ts b/packages/stryker/test/unit/utils/StringBuilderSpec.ts new file mode 100644 index 0000000000..3b887fb28c --- /dev/null +++ b/packages/stryker/test/unit/utils/StringBuilderSpec.ts @@ -0,0 +1,33 @@ +import { expect } from 'chai'; +import { EOL } from 'os'; +import StringBuilder from '../../../src/utils/StringBuilder'; + +describe(StringBuilder.name, () => { + + it('should append strings with new lines when `toString()` is called', () => { + const sut = new StringBuilder(); + sut.append('1'); + sut.append('2'); + sut.append('3'); + expect(sut.toString()).eq(`1${EOL}2${EOL}3`); + }); + + const DEFAULT_MAX_CHARACTERS = 2048; + it(`should append a to maximum of ${DEFAULT_MAX_CHARACTERS} characters by default`, () => { + const sut = new StringBuilder(); + for (let i = 0; i < DEFAULT_MAX_CHARACTERS; i++) { + sut.append('.'); + } + sut.append('expected'); + const result = sut.toString(); + expect(result.replace(new RegExp(EOL, 'g'), '')).lengthOf(DEFAULT_MAX_CHARACTERS); + expect(result.endsWith(`.${EOL}.${EOL}.${EOL}expected`)).ok; + }); + + it('should not split the last string, even if it exceeds the max characters', () => { + const input = new Array(DEFAULT_MAX_CHARACTERS + 1).fill('.').join(''); + const sut = new StringBuilder(); + sut.append(input); + expect(sut.toString()).eq(input); + }); +}); \ No newline at end of file diff --git a/tsconfig.json b/tsconfig.json index 38781d60c3..15a7eac702 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -18,7 +18,8 @@ "es2015.promise", "es2015.core", "es2015.symbol", - "es2015.symbol.wellknown" + "es2015.symbol.wellknown", + "es2015.proxy" ] } } \ No newline at end of file