[ftr] capture test output rather any try to only log on failure

packages/kbn-dev-utils/index.d.ts

@@ -21,6 +21,11 @@ import { Readable } from 'stream';
 
 type LogLevel = 'silent' | 'error' | 'warning' | 'info' | 'debug' | 'verbose';
 
+export interface Interceptor {
+  bypass: ToolingLog;
+  detach: () => void;
+}
+
 export class ToolingLog extends Readable {
   public verbose(...args: any[]): void;
   public debug(...args: any[]): void;
@@ -32,6 +37,7 @@ export class ToolingLog extends Readable {
   public indent(spaces: number): void;
   public getLevel(): LogLevel;
   public setLevel(level: LogLevel): void;
+  public interceptWrites(handler: (chunk) => void): Interceptor;
 }
 
 export function createToolingLog(level?: LogLevel): ToolingLog;

packages/kbn-dev-utils/src/tooling_log/tooling_log.js

@@ -94,9 +94,46 @@ export function createToolingLog(initialLogLevelName = 'silent') {
           const indent = !indentString
             ? ''
             : indentString.slice(0, -1) + (i === 0 && line[0] === '-' ? '└' : '│');
-          super.write(`${indent}${subLineIndent}${line}\n`);
+          const chunk = `${indent}${subLineIndent}${line}\n`;
+
+          if (this._interceptor) {
+            this._interceptor._handler(chunk);
+          } else {
+            super.write(chunk);
+          }
         });
     }
+
+    /**
+     * Define a function to intercept ToolingLog writes so they can be consumed
+     * in some other way.
+     *
+     * @param {(chunk: string)=>void} handler
+     * @returns {Interceptor}
+     */
+    interceptWrites(handler) {
+      if (this._interceptor) {
+        throw new Error('ToolingLog interceptor already registered');
+      }
+
+      this._interceptor = {
+        _handler: handler,
+        bypass: new Proxy(this, {
+          get: (target, prop, receiver) => {
+            if (prop === '_interceptor') {
+              return undefined;
+            }
+
+            return Reflect.get(this, prop, receiver);
+          },
+        }),
+        detach: () => {
+          this._interceptor = undefined;
+        },
+      };
+
+      return this._interceptor;
+    }
   }
 
   return new ToolingLog();

src/dev/mocha/junit_report_generation.js

@@ -120,6 +120,9 @@ export function setupJUnitReportGeneration(runner, options = {}) {
 
     [...results, ...skippedResults].forEach(result => {
       const el = addTestcaseEl(result.node);
+      el.ele('system-out').dat(
+        result.node.capturedLoggingOutput || ''
+      );
 
       if (result.failed) {
         el.ele('failure').dat(inspect(result.error));

src/functional_test_runner/lib/mocha/reporter/reporter.js

@@ -19,6 +19,7 @@
 
 import { format } from 'util';
 
+import dedent from 'dedent';
 import Mocha from 'mocha';
 
 import { setupJUnitReportGeneration } from '../../../../dev';
@@ -27,6 +28,16 @@ import * as symbols from './symbols';
 import { ms } from './ms';
 import { writeEpilogue } from './write_epilogue';
 
+const interceptedLogCache = new WeakMap();
+
+// recursively walk up from a suite to collect the intercepted logs
+// for a suite and all its parents
+function getAllSuiteLogs(suite) {
+  const history = suite.parent ? getAllSuiteLogs(suite.parent) : '';
+  const ownLogs = interceptedLogCache.get(suite) || '';
+  return history + ownLogs;
+}
+
 export function MochaReporterProvider({ getService }) {
   const log = getService('log');
   const config = getService('config');
@@ -56,10 +67,33 @@ export function MochaReporterProvider({ getService }) {
 
     onStart = () => {
       log.write('');
+
+      this._logInterceptor = log.interceptWrites(chunk => {
+
+        // if the current runnable is a beforeEach hook then
+        // `runner.suite` is set to the suite that defined the
+        // hook, rather than the suite executing, so instead we
+        // grab the suite from the test, but that's only available
+        // when we are doing something test specific, so for global
+        // hooks we fallback to `runner.suite`
+        const currentSuite = this.runner.test
+          ? this.runner.test.parent
+          : this.runner.suite;
+
+        const cache = interceptedLogCache.get(currentSuite) || '';
+        interceptedLogCache.set(currentSuite, cache + chunk);
+      });
+
+      this._logInterceptor.bypass.warning('Test log output is being captured and will only be reported on failure');
+    }
+
+    _writeToBothLogs(msg) {
+      log.write(msg);
+      this._logInterceptor.bypass.write(msg);
     }
 
     onHookStart = hook => {
-      log.write('-> ' + colors.suite(hook.title));
+      log.write(`-> ${colors.suite(hook.title)}`);
       log.indent(2);
     }
 
@@ -69,15 +103,15 @@ export function MochaReporterProvider({ getService }) {
 
     onSuiteStart = suite => {
       if (!suite.root) {
-        log.write('-: ' + colors.suite(suite.title));
+        this._writeToBothLogs('-: ' + colors.suite(suite.title));
       }
 
       log.indent(2);
     }
 
     onSuiteEnd = () => {
       if (log.indent(-2) === '') {
-        log.write();
+        this._writeToBothLogs();
       }
     }
 
@@ -91,19 +125,24 @@ export function MochaReporterProvider({ getService }) {
     }
 
     onPending = test => {
-      log.write('-> ' + colors.pending(test.title));
+      this._writeToBothLogs('-> ' + colors.pending(test.title));
       log.indent(2);
     }
 
     onPass = test => {
-
       let time = '';
       if (test.speed !== 'fast') {
         time = colors.speed(test.speed, ` (${ms(test.duration)})`);
       }
 
       const pass = colors.pass(`${symbols.ok} pass`);
       log.write(`- ${pass} ${time}`);
+
+      this._logInterceptor.bypass.write(
+        `-> ${colors.pass(symbols.ok)} ${test.title} ${time}`
+      );
+
+      test.capturedLoggingOutput = getAllSuiteLogs(test.parent);
     }
 
     onFail = test => {
@@ -123,28 +162,28 @@ export function MochaReporterProvider({ getService }) {
         console.log = realLog;
       }
 
-      log.indent(-2);
-      log.write(
-        `- ${symbols.err} ` +
-        colors.fail(`fail: "${test.fullTitle()}"`) +
+      const formattedOutput = output
+        // split the Base.list output into lines
+        .split('\n')
+        //  drop the first two lines, 1 is empty, and 2 is the test title
+        .slice(2)
+        // move all right of the leading ansi color codes left of the code
+        .map(line => line.replace(/^\s*((?:\u001b\[.+?m)+)(\s+)/, '$2$1'))
+        // join the lines back together
+        .join('\n');
+
+      this._writeToBothLogs(
+        `- ${colors.fail(`${symbols.err} fail: "${test.fullTitle()}"`)}` +
         '\n' +
-        output
-          .split('\n')
-          .slice(2) // drop the first two lines, (empty + test title)
-          .map(line => {
-            // move leading colors behind leading spaces
-            return line.replace(/^((?:\[.+m)+)(\s+)/, '$2$1');
-          })
-          .map(line => {
-            // shrink mocha's indentation
-            return line.replace(/^\s{5,5}/, ' ');
-          })
-          .join('\n')
+        dedent(formattedOutput)
       );
-      log.indent(2);
+
+      test.capturedLoggingOutput = getAllSuiteLogs(test.parent);
     }
 
     onEnd = () => {
+      this._logInterceptor.detach();
+      this._logInterceptor = null;
       writeEpilogue(log, this.stats);
     }
   };