test: collect stdout/stderr in tests (#3615)

test-runner/src/reporter.ts

@@ -21,6 +21,8 @@ export interface Reporter {
   onBegin(config: RunnerConfig, suite: Suite): void;
   onTest(test: Test): void;
   onPending(test: Test): void;
+  onStdOut(test: Test, chunk: string | Buffer);
+  onStdErr(test: Test, chunk: string | Buffer);
   onPass(test: Test): void;
   onFail(test: Test): void;
   onEnd(): void;

test-runner/src/reporters/base.ts

@@ -58,6 +58,16 @@ export class BaseReporter implements Reporter  {
     this.pending.push(test);
   }
 
+  onStdOut(test: Test, chunk: string | Buffer) {
+    if (!this.config.quiet)
+      process.stdout.write(chunk);
+  }
+
+  onStdErr(test: Test, chunk: string | Buffer) {
+    if (!this.config.quiet)
+      process.stderr.write(chunk);
+  }
+
   onPass(test: Test) {
     this.passes.push(test);
   }
@@ -96,34 +106,40 @@ export class BaseReporter implements Reporter  {
 
   private _printFailures(failures: Test[]) {
     failures.forEach((failure, index) => {
-      const relativePath = path.relative(process.cwd(), failure.file);
-      const header = `  ${index +1}. ${terminalLink(relativePath, `file://${os.hostname()}${failure.file}`)} › ${failure.title}`;
-      console.log(colors.bold(colors.red(header)));
-      const stack = failure.error.stack;
-      if (stack) {
-        console.log('');
-        const messageLocation = failure.error.stack.indexOf(failure.error.message);
-        const preamble = failure.error.stack.substring(0, messageLocation + failure.error.message.length);
-        console.log(indent(preamble, '    '));
-        const position = positionInFile(stack, failure.file);
-        if (position) {
-          const source = fs.readFileSync(failure.file, 'utf8');
-          console.log('');
-          console.log(indent(codeFrameColumns(source, {
-              start: position,
-            },
-            { highlightCode: true}
-          ), '    '));
-        }
-        console.log('');
-        console.log(indent(colors.dim(stack.substring(preamble.length + 1)), '    '));
-      } else {
-        console.log('');
-        console.log(indent(String(failure.error), '    '));
-      }
-      console.log('');
+      console.log(this.formatFailure(failure, index + 1));
     });
   }
+
+  formatFailure(failure: Test, index?: number): string {
+    const tokens: string[] = [];
+    const relativePath = path.relative(process.cwd(), failure.file);
+    const header = `  ${index ? index + ')' : ''} ${terminalLink(relativePath, `file://${os.hostname()}${failure.file}`)} › ${failure.title}`;
+    tokens.push(colors.bold(colors.red(header)));
+    const stack = failure.error.stack;
+    if (stack) {
+      tokens.push('');
+      const messageLocation = failure.error.stack.indexOf(failure.error.message);
+      const preamble = failure.error.stack.substring(0, messageLocation + failure.error.message.length);
+      tokens.push(indent(preamble, '    '));
+      const position = positionInFile(stack, failure.file);
+      if (position) {
+        const source = fs.readFileSync(failure.file, 'utf8');
+        tokens.push('');
+        tokens.push(indent(codeFrameColumns(source, {
+            start: position,
+          },
+          { highlightCode: true}
+        ), '    '));
+      }
+      tokens.push('');
+      tokens.push(indent(colors.dim(stack.substring(preamble.length + 1)), '    '));
+    } else {
+      tokens.push('');
+      tokens.push(indent(String(failure.error), '    '));
+    }
+    tokens.push('');
+    return tokens.join('\n');
+  }
 }
 
 function indent(lines: string, tab: string) {

test-runner/src/reporters/json.ts

@@ -54,9 +54,18 @@ class JSONReporter extends BaseReporter {
       slow: test.slow,
       duration: test.duration,
       timeout: test.timeout,
-      error: test.error
+      error: test.error,
+      stdout: test.stdout.map(s => stdioEntry(s)),
+      stderr: test.stderr.map(s => stdioEntry(s)),
+      data: test.data
     };
   }
 }
 
+function stdioEntry(s: string | Buffer): any {
+  if (typeof s === 'string')
+    return { text: s };
+  return { buffer: s.toString('base64') }
+}
+
 export default JSONReporter;

test-runner/src/reporters/multiplexer.ts

@@ -40,6 +40,16 @@ export class Multiplexer implements Reporter {
       reporter.onPending(test);
   }
 
+  onStdOut(test: Test, chunk: string | Buffer) {
+    for (const reporter of this._reporters)
+      reporter.onStdOut(test, chunk);    
+  }
+
+  onStdErr(test: Test, chunk: string | Buffer) {
+    for (const reporter of this._reporters)
+      reporter.onStdErr(test, chunk);    
+  }
+
   onPass(test: Test) {
     for (const reporter of this._reporters)
       reporter.onPass(test);

test-runner/src/reporters/pytest.ts

@@ -88,12 +88,22 @@ class PytestReporter extends BaseReporter {
     super.onPending(test);
     this._append(test, colors.yellow('∘'));
     this._progress.push('S');
+    this._throttler.schedule();
+  }
+
+  onStdOut(test: Test, chunk: string | Buffer) {
+    this._repaint(chunk);
+  }
+
+  onStdErr(test: Test, chunk: string | Buffer) {
+    this._repaint(chunk);
   }
 
   onPass(test: Test) {
     super.onPass(test);
     this._append(test, colors.green('✓'));
     this._progress.push('P');
+    this._throttler.schedule();
   }
 
   onFail(test: Test) {
@@ -103,13 +113,7 @@ class PytestReporter extends BaseReporter {
     row.failed = true;
     this._failed = true;
     this._progress.push('F');
-  }
-
-  onEnd() {
-    super.onEnd();
-    this._repaint();
-    if (this._failed)
-      this.epilogue();
+    this._repaint(this.formatFailure(test) + '\n');
   }
 
   private _append(test: Test, s: string): Row {
@@ -118,11 +122,10 @@ class PytestReporter extends BaseReporter {
     row.track.push(s);
     if (row.track.length === row.total)
       row.finishTime = Date.now();
-    this._throttler.schedule();
     return row;
   }
 
-  private _repaint() {
+  private _repaint(prependChunk?: string | Buffer) {
     const rowList = [...this._rows.values()];
     const running = rowList.filter(r => r.startTime && !r.finishTime);
     const finished = rowList.filter(r => r.finishTime).sort((a, b) => b.finishTime - a.finishTime);
@@ -160,6 +163,8 @@ class PytestReporter extends BaseReporter {
     lines.push('');
 
     process.stdout.write((cursorPrevLine + eraseLine).repeat(this._visibleRows + statusRows));
+    if (prependChunk)
+      process.stdout.write(prependChunk);
     process.stdout.write(lines.join('\n'));
   }
 

test-runner/src/runner.ts

@@ -20,7 +20,7 @@ import path from 'path';
 import { EventEmitter } from 'events';
 import { lookupRegistrations, FixturePool } from './fixtures';
 import { Suite, Test } from './test';
-import { TestRunnerEntry } from './testRunner';
+import { TestRunnerEntry, SerializedTest } from './testRunner';
 import { RunnerConfig } from './runnerConfig';
 import { Reporter } from './reporter';
 
@@ -160,13 +160,19 @@ export class Runner {
     });
     worker.on('fail', params => {
       ++this.stats.failures;
-      const out = worker.takeOut();
-      if (out.length)
-        params.test.error.stack += '\n\x1b[33mstdout: ' + out.join('\n') + '\x1b[0m';
-      const err = worker.takeErr();
-      if (err.length)
-        params.test.error.stack += '\n\x1b[33mstderr: ' + err.join('\n') + '\x1b[0m';
-        this._reporter.onFail(this._updateTest(params.test));
+      this._reporter.onFail(this._updateTest(params.test));
+    });
+    worker.on('stdout', params => {
+      const chunk = chunkFromParams(params);
+      const test = this._testById.get(params.testId);
+      test.stdout.push(chunk);
+      this._reporter.onStdOut(test, chunk);
+    });
+    worker.on('stderr', params => {
+      const chunk = chunkFromParams(params);
+      const test = this._testById.get(params.testId);
+      test.stderr.push(chunk);
+      this._reporter.onStdErr(test, chunk);
     });
     worker.on('exit', () => {
       this._workers.delete(worker);
@@ -182,10 +188,11 @@ export class Runner {
     this._createWorker();
   }
 
-  _updateTest(serialized) {
+  _updateTest(serialized: SerializedTest): Test {
     const test = this._testById.get(serialized.id);
     test.duration = serialized.duration;
     test.error = serialized.error;
+    test.data = serialized.data;
     return test;
   }
 
@@ -238,20 +245,6 @@ class OopWorker extends Worker {
       const { method, params } = message;
       this.emit(method, params);
     });
-    this.stdout = [];
-    this.stderr = [];
-    this.on('stdout', params => {
-      const chunk = chunkFromParams(params);
-      if (!runner._config.quiet)
-        process.stdout.write(chunk);
-      this.stdout.push(chunk);
-    });
-    this.on('stderr', params => {
-      const chunk = chunkFromParams(params);
-      if (!runner._config.quiet)
-        process.stderr.write(chunk);
-      this.stderr.push(chunk);
-    });
   }
 
   async init() {
@@ -267,18 +260,6 @@ class OopWorker extends Worker {
   stop() {
     this.process.send({ method: 'stop' });
   }
-
-  takeOut() {
-    const result = this.stdout;
-    this.stdout = [];
-    return result;
-  }
-
-  takeErr() {
-    const result = this.stderr;
-    this.stderr = [];
-    return result;
-  }
 }
 
 class InProcessWorker extends Worker {
@@ -298,7 +279,7 @@ class InProcessWorker extends Worker {
     delete require.cache[entry.file];
     const { TestRunner } = require('./testRunner');
     const testRunner = new TestRunner(entry, this.runner._config, 0);
-    for (const event of ['test', 'pending', 'pass', 'fail', 'done'])
+    for (const event of ['test', 'pending', 'pass', 'fail', 'done', 'stdout', 'stderr'])
       testRunner.on(event, this.emit.bind(this, event));
     testRunner.run();
   }
@@ -307,19 +288,11 @@ class InProcessWorker extends Worker {
     await this.fixturePool.teardownScope('worker');
     this.emit('exit');
   }
-
-  takeOut() {
-    return [];
-  }
-
-  takeErr() {
-    return [];
-  }
 }
 
-function chunkFromParams(params: string | { buffer: string }): string | Buffer {
-  if (typeof params === 'string')
-    return params;
+function chunkFromParams(params: { testId: string, buffer?: string, text?: string }): string | Buffer {
+  if (typeof params.text === 'string')
+    return params.text;
   return Buffer.from(params.buffer, 'base64');
 }
 

test-runner/src/test.ts

@@ -27,6 +27,9 @@ export class Test {
   timeout = 0;
   fn: Function;
   error: any;
+  stdout: (string | Buffer)[] = [];
+  stderr: (string | Buffer)[] = [];
+  data: any = {};
 
   _ordinal: number;
   _overriddenFn: Function;

test-runner/src/testRunner.ts

@@ -20,6 +20,7 @@ import { setCurrentTestFile } from './expect';
 import { Test, Suite, Configuration, serializeError } from './test';
 import { spec } from './spec';
 import { RunnerConfig } from './runnerConfig';
+import * as util from 'util';
 
 export const fixturePool = new FixturePool<RunnerConfig>();
 
@@ -31,6 +32,21 @@ export type TestRunnerEntry = {
   hash: string;
 };
 
+function chunkToParams(chunk: Buffer | string):  { text?: string, buffer?: string } {
+  if (chunk instanceof Buffer)
+    return { buffer: chunk.toString('base64') };
+  if (typeof chunk !== 'string')
+    return { text: util.inspect(chunk) };
+  return { text: chunk };
+}
+
+export type SerializedTest = {
+  id: string,
+  error: any,
+  duration: number,
+  data: any[]
+};
+
 export class TestRunner extends EventEmitter {
   private _currentOrdinal = -1;
   private _failedWithError: any | undefined;
@@ -75,6 +91,14 @@ export class TestRunner extends EventEmitter {
     this._reportDone();
   }
 
+  stdout(chunk: string | Buffer) {
+    this.emit('stdout', { testId: this._testId(), ...chunkToParams(chunk) })
+  }
+
+  stderr(chunk: string | Buffer) {
+    this.emit('stderr', { testId: this._testId(), ...chunkToParams(chunk) })
+  }
+
   async run() {
     setParameters(this._parsedGeneratorConfiguration);
 
@@ -130,14 +154,12 @@ export class TestRunner extends EventEmitter {
       test._startTime = Date.now();
       if (!this._trialRun)
         await this._testWrapper(test)();
-      this.emit('pass', { test: this._serializeTest() });
+      this.emit('pass', { test: this._serializeTest(true) });
       await this._runHooks(test.suite, 'afterEach', 'after');
     } catch (error) {
       test.error = serializeError(error);
       this._failedWithError = test.error;
-      this.emit('fail', {
-        test: this._serializeTest(),
-      });
+      this.emit('fail', { test: this._serializeTest(true) });
     }
     this._test = null;
   }
@@ -169,11 +191,16 @@ export class TestRunner extends EventEmitter {
     return fixturePool.wrapTestCallback(test.fn, timeout, { ...this._config }, test);
   }
 
-  private _serializeTest() {
+  private _testId() {
+    return `${this._test._ordinal}@${this._configuredFile}`;
+  }
+
+  private _serializeTest(full = false): SerializedTest {
     return {
-      id: `${this._test._ordinal}@${this._configuredFile}`,
+      id: this._testId(),
       error: this._test.error,
       duration: Date.now() - this._test._startTime,
+      data: full ? this._test.data : undefined
     };
   }
 }

test-runner/src/worker.ts

@@ -16,27 +16,20 @@
 
 import { initializeImageMatcher } from './expect';
 import { TestRunner, fixturePool } from './testRunner';
-import * as util from 'util';
 
 let closed = false;
 
 sendMessageToParent('ready');
 
-function chunkToParams(chunk) {
-  if (chunk instanceof Buffer)
-    return { buffer: chunk.toString('base64') };
-  if (typeof chunk !== 'string')
-    return util.inspect(chunk);
-  return chunk;
-}
-
 process.stdout.write = chunk => {
-  sendMessageToParent('stdout', chunkToParams(chunk));
+  if (testRunner && !closed)
+    testRunner.stdout(chunk);
   return true;
 };
 
 process.stderr.write = chunk => {
-  sendMessageToParent('stderr', chunkToParams(chunk));
+  if (testRunner && !closed)
+    testRunner.stderr(chunk);
   return true;
 };
 
@@ -69,7 +62,7 @@ process.on('message', async message => {
   }
   if (message.method === 'run') {
     testRunner = new TestRunner(message.params.entry, message.params.config, workerId);
-    for (const event of ['test', 'pending', 'pass', 'fail', 'done'])
+    for (const event of ['test', 'pending', 'pass', 'fail', 'done', 'stdout', 'stderr'])
       testRunner.on(event, sendMessageToParent.bind(null, event));
     await testRunner.run();
     testRunner = null;

test-runner/test/assets/stdio.js

@@ -0,0 +1,24 @@
+/**
+ * Copyright (c) Microsoft Corporation.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+require('../../..');
+
+it('stdio', () => {
+  process.stdout.write('stdout text');
+  process.stdout.write(Buffer.from('stdout buffer'));
+  process.stderr.write('stderr text');
+  process.stderr.write(Buffer.from('stderr buffer'));
+});

test-runner/test/assets/test-data-visible-in-fixture.js

@@ -0,0 +1,30 @@
+/**
+ * Copyright (c) Microsoft Corporation.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+const { registerFixture } = require('../../');
+const fs = require('fs');
+const path = require('path');
+
+registerFixture('postProcess', async ({}, runTest, config, test) => {
+  await runTest('');
+  test.data['myname'] = 'myvalue';
+});
+
+it('ensure fixture handles test error', async ({ postProcess }) => {
+  console.log('console.log');
+  console.error('console.error');
+  expect(true).toBe(false);
+});

test-runner/test/exit-code.spec.ts

@@ -44,6 +44,16 @@ it('should access error in fixture', async() => {
   expect(data.message).toContain('Object.is equality');
 });
 
+it('should access data in fixture', async() => {
+  const result = await runTest('test-data-visible-in-fixture.js');
+  expect(result.exitCode).toBe(1);
+  const data = JSON.parse(fs.readFileSync(path.join(__dirname, 'test-results', 'results.json')).toString());
+  const test = data.suites[0].tests[0];
+  expect(test.data).toEqual({ 'myname': 'myvalue' });
+  expect(test.stdout).toEqual([{ text: 'console.log\n' }]);
+  expect(test.stderr).toEqual([{ text: 'console.error\n' }]);
+});
+
 it('should handle worker fixture timeout', async() => {
   const result = await runTest('worker-fixture-timeout.js', 1000);
   expect(result.exitCode).toBe(1);
@@ -56,6 +66,16 @@ it('should handle worker fixture error', async() => {
   expect(result.output).toContain('Worker failed');
 });
 
+it('should collect stdio', async() => {
+  const result = await runTest('stdio.js');
+  expect(result.exitCode).toBe(0);
+  const data = JSON.parse(fs.readFileSync(path.join(__dirname, 'test-results', 'results.json')).toString());
+  const test = data.suites[0].tests[0];
+  const { stdout, stderr } = test;
+  expect(stdout).toEqual([{ text: 'stdout text' }, { buffer: Buffer.from('stdout buffer').toString('base64') }]);
+  expect(stderr).toEqual([{ text: 'stderr text' }, { buffer: Buffer.from('stderr buffer').toString('base64') }]);
+});
+
 async function runTest(filePath: string, timeout = 10000) {
   const outputDir = path.join(__dirname, 'test-results')
   await removeFolderAsync(outputDir).catch(e => {});
@@ -64,8 +84,14 @@ async function runTest(filePath: string, timeout = 10000) {
     path.join(__dirname, '..', 'cli.js'),
     path.join(__dirname, 'assets', filePath),
     '--output=' + outputDir,
-    '--timeout=' + timeout
-  ]);
+    '--timeout=' + timeout,
+    '--reporter=dot,json'
+  ], {
+    env: {
+      ...process.env,
+      PWRUNNER_JSON_REPORT: path.join(__dirname, 'test-results', 'results.json'),
+    }
+  });
   const passed = (/(\d+) passed/.exec(output.toString()) || [])[1];
   const failed = (/(\d+) failed/.exec(output.toString()) || [])[1];
   return {