fix(child process proxy): OutOfMemory detection (#1635)

Make sure out `OutOfMemory` detection works as expected. This fixes a race condition in which the detection didn't work correctly, and an unexpected error was assumed. See #1634

packages/core/src/child-proxy/ChildProcessProxy.ts

@@ -34,7 +34,8 @@ export default class ChildProcessProxy<T> implements Disposable {
   private currentError: ChildProcessCrashedError | undefined;
   private readonly workerTasks: Task<void>[] = [];
   private readonly log = getLogger(ChildProcessProxy.name);
-  private readonly stdoutAndStderrBuilder = new StringBuilder();
+  private readonly stdoutBuilder = new StringBuilder();
+  private readonly stderrBuilder = new StringBuilder();
   private isDisposed = false;
 
   private constructor(requirePath: string, requireName: string, loggingContext: LoggingClientContext, options: StrykerOptions, additionalInjectableValues: unknown, workingDirectory: string) {
@@ -52,10 +53,8 @@ export default class ChildProcessProxy<T> implements Disposable {
     });
     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);
+    // Listen to `close`, not `exit`, see https://github.com/stryker-mutator/stryker/issues/1634
+    this.worker.on('close', this.handleUnexpectedExit);
     this.worker.on('error', this.handleError);
     this.proxy = this.initProxy();
   }
@@ -141,20 +140,20 @@ export default class ChildProcessProxy<T> implements Disposable {
   }
 
   private listenToStdoutAndStderr() {
-    const handleData = (data: Buffer | string) => {
+    const handleData = (builder: StringBuilder) => (data: Buffer | string) => {
       const output = data.toString();
-      this.stdoutAndStderrBuilder.append(output);
+      builder.append(output);
       if (this.log.isTraceEnabled()) {
         this.log.trace(output);
       }
     };
 
     if (this.worker.stdout) {
-      this.worker.stdout.on('data', handleData);
+      this.worker.stdout.on('data', handleData(this.stdoutBuilder));
     }
 
     if (this.worker.stderr) {
-      this.worker.stderr.on('data', handleData);
+      this.worker.stderr.on('data', handleData(this.stderrBuilder));
     }
   }
 
@@ -164,9 +163,9 @@ export default class ChildProcessProxy<T> implements Disposable {
       .forEach(task => task.reject(error));
   }
 
-  private handleUnexpectedExit(code: number, signal: string) {
+  private readonly handleUnexpectedExit = (code: number, signal: string) => {
     this.isDisposed = true;
-    const output = this.stdoutAndStderrBuilder.toString();
+    const output = StringBuilder.concat(this.stderrBuilder, this.stdoutBuilder);
 
     if (processOutOfMemory()) {
       this.currentError = new OutOfMemoryError(this.worker.pid, code);
@@ -192,7 +191,7 @@ export default class ChildProcessProxy<T> implements Disposable {
     }
   }
 
-  private handleError(error: Error) {
+  private readonly 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));

packages/core/src/utils/StringBuilder.ts

@@ -1,4 +1,4 @@
-import * as os from 'os';
+import { EOL } from 'os';
 
 const DEFAULT_MAX_SIZE = 2048;
 
@@ -17,6 +17,12 @@ export default class StringBuilder {
   }
 
   public toString() {
-    return this.strings.join(os.EOL);
+    return this.strings.join('');
+  }
+
+  public static concat(...builders: StringBuilder[]): string {
+    return builders.map(b => b.toString())
+      .filter(Boolean)
+      .join(EOL);
   }
 }

packages/core/test/unit/child-proxy/ChildProcessProxy.spec.ts

@@ -87,44 +87,53 @@ describe(ChildProcessProxy.name, () => {
       expect(childProcessMock.listeners('message')).lengthOf(1);
     });
 
-    it('should listen for exit calls', () => {
+    it('should listen for close calls', () => {
       createSut();
-      expect(childProcessMock.listeners('exit')).lengthOf(1);
+      expect(childProcessMock.listeners('close')).lengthOf(1);
     });
   });
 
-  describe('on exit', () => {
+  describe('on close', () => {
     beforeEach(() => {
       sut = createSut();
     });
 
     it('should log stdout and stderr on warning', () => {
-      childProcessMock.stderr.emit('data', 'foo');
       childProcessMock.stdout.emit('data', 'bar');
-      actExit(23, 'SIGTERM');
+      childProcessMock.stderr.emit('data', 'foo');
+      actClose(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');
+      actClose(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 log stdout and stderr in correct order', () => {
+      childProcessMock.stdout.emit('data', 'foo');
+      childProcessMock.stderr.emit('data', 'baz');
+      childProcessMock.stdout.emit('data', 'bar');
+      actClose(23, 'SIGTERM');
+      expect(logMock.warn).calledWith(`Child process [pid ${childProcessMock.pid}] exited unexpectedly with exit code 23 (SIGTERM). Last part of stdout and stderr was:${os.EOL
+      }\tbaz${os.EOL}\tfoobar`);
+    });
+
     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);
+      actClose(646);
       return expect(actualPromise).rejectedWith(expectedError);
     });
 
     it('should reject any new calls immediately', () => {
-      actExit(646);
+      actClose(646);
       return expect(sut.proxy.say('')).rejected;
     });
 
-    function actExit(code = 1, signal = 'SIGINT') {
-      childProcessMock.emit('exit', code, signal);
+    function actClose(code = 1, signal = 'SIGINT') {
+      childProcessMock.emit('close', code, signal);
     }
   });
 
@@ -186,7 +195,7 @@ describe(ChildProcessProxy.name, () => {
     });
 
     it('should not do anything if the process already exited', async () => {
-      childProcessMock.emit('exit', 1);
+      childProcessMock.emit('close', 1);
       await actDispose();
       expect(killStub).not.called;
       expect(childProcessMock.send).calledOnce; // init

packages/core/test/unit/utils/StringBuilder.spec.ts

@@ -4,30 +4,58 @@ 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`);
-  });
+  describe('toString', () => {
+
+    it('should append strings without separator when `toString()` is called', () => {
+      const sut = new StringBuilder();
+      sut.append('1');
+      sut.append('2');
+      sut.append('3');
+      expect(sut.toString()).eq(`123`);
+    });
+
+    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).lengthOf(DEFAULT_MAX_CHARACTERS);
+      const expectedLastPart = '...expected';
+      expect(result.substr(result.length - expectedLastPart.length)).eq(expectedLastPart);
+    });
 
-  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);
+    });
   });
 
-  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);
+  describe('concat', () => {
+    it('should concatenate multiple string builders with new lines', () => {
+      const stringBuilders = [
+        new StringBuilder(),
+        new StringBuilder()
+      ];
+      stringBuilders[0].append('foo');
+      stringBuilders[0].append('bar');
+      stringBuilders[1].append('baz');
+      expect(StringBuilder.concat(...stringBuilders)).eq(`foobar${EOL}baz`);
+    });
+    it('should remove empty builders', () => {
+      const stringBuilders = [
+        new StringBuilder(),
+        new StringBuilder(),
+        new StringBuilder()
+      ];
+      stringBuilders[0].append('foo');
+      stringBuilders[0].append('bar');
+      stringBuilders[2].append('baz');
+      expect(StringBuilder.concat(...stringBuilders)).eq(`foobar${EOL}baz`);
+    });
   });
 });