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