[ftr] capture test output and only log on failure

package.json

@@ -315,6 +315,7 @@
     "postcss": "^7.0.2",
     "prettier": "^1.14.0",
     "proxyquire": "1.7.11",
+    "regenerate": "^1.4.0",
     "simple-git": "1.37.0",
     "sinon": "^5.0.7",
     "strip-ansi": "^3.0.1",

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

@@ -18,4 +18,4 @@
  */
 
 export { withProcRunner } from './proc_runner';
-export { ToolingLog, pickLevelFromFlags } from './tooling_log';
+export { ToolingLog, ToolingLogTextWriter, pickLevelFromFlags } from './tooling_log';

src/dev/mocha/__tests__/junit_report_generation.js

@@ -93,7 +93,8 @@ describe('dev/mocha/junit report generation', () => {
         classname: sharedClassname,
         name: 'SUITE works',
         time: testPass.$.time,
-      }
+      },
+      'system-out': testPass['system-out']
     });
 
     expect(testFail.$.time).to.match(DURATION_REGEX);
@@ -104,6 +105,7 @@ describe('dev/mocha/junit report generation', () => {
         name: 'SUITE fails',
         time: testFail.$.time,
       },
+      'system-out': testFail['system-out'],
       failure: [
         testFail.failure[0]
       ]
@@ -118,6 +120,7 @@ describe('dev/mocha/junit report generation', () => {
         name: 'SUITE SUB_SUITE "before each" hook: fail hook for "never runs"',
         time: beforeEachFail.$.time,
       },
+      'system-out': testFail['system-out'],
       failure: [
         beforeEachFail.failure[0]
       ]
@@ -128,6 +131,7 @@ describe('dev/mocha/junit report generation', () => {
         classname: sharedClassname,
         name: 'SUITE SUB_SUITE never runs',
       },
+      'system-out': testFail['system-out'],
       skipped: ['']
     });
   });

src/dev/mocha/junit_report_generation.js

@@ -23,6 +23,27 @@ import { inspect } from 'util';
 
 import mkdirp from 'mkdirp';
 import xmlBuilder from 'xmlbuilder';
+import stripAnsi from 'strip-ansi';
+import regenerate from 'regenerate';
+
+import { getSnapshotOfRunnableLogs } from './log_cache';
+
+// create a regular expression using regenerate() that selects any character that is explicitly allowed by https://www.w3.org/TR/xml/#NT-Char
+const validXmlCharsRE = new RegExp(
+  `(?:${
+    regenerate()
+      .add(0x9, 0xA, 0xD)
+      .addRange(0x20, 0xD7FF)
+      .addRange(0xE000, 0xFFFD)
+      .addRange(0x10000, 0x10FFFF)
+      .toString()
+  })*`,
+  'g'
+);
+
+function escapeCdata(string) {
+  return stripAnsi(string).match(validXmlCharsRE).join('');
+}
 
 export function setupJUnitReportGeneration(runner, options = {}) {
   const {
@@ -120,9 +141,12 @@ export function setupJUnitReportGeneration(runner, options = {}) {
 
     [...results, ...skippedResults].forEach(result => {
       const el = addTestcaseEl(result.node);
+      el.ele('system-out').dat(
+        escapeCdata(getSnapshotOfRunnableLogs(result.node) || '')
+      );
 
       if (result.failed) {
-        el.ele('failure').dat(inspect(result.error));
+        el.ele('failure').dat(escapeCdata(inspect(result.error)));
         return;
       }
 

src/dev/mocha/log_cache.js

@@ -0,0 +1,62 @@
+/*
+ * Licensed to Elasticsearch B.V. under one or more contributor
+ * license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright
+ * ownership. Elasticsearch B.V. licenses this file to you 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 cachedSuiteLogs = new WeakMap();
+const cachesRunnableLogs = new WeakMap();
+
+/**
+ * Add a chunk of log output to the cached
+ * output for a suite
+ * @param {Mocha.Suite} suite
+ * @param {string} chunk
+ */
+export function recordLog(suite, chunk) {
+  const cache = cachedSuiteLogs.get(suite) || '';
+  cachedSuiteLogs.set(suite, cache + chunk);
+}
+
+/**
+ * Recursively walk up from a runnable to collect
+ * the cached log for its suite and all its parents
+ * @param {Mocha.Suite} suite
+ */
+function getCurrentCachedSuiteLogs(suite) {
+  const history = suite.parent ? getCurrentCachedSuiteLogs(suite.parent) : '';
+  const ownLogs = cachedSuiteLogs.get(suite) || '';
+  return history + ownLogs;
+}
+
+/**
+ * Snapshot the logs from this runnable's suite at this point,
+ * as the suite logs will get updated to include output from
+ * subsequent runnables
+ * @param {Mocha.Runnable} runnable
+ */
+export function snapshotLogsForRunnable(runnable) {
+  cachesRunnableLogs.set(runnable, getCurrentCachedSuiteLogs(runnable.parent));
+}
+
+/**
+ * Get the suite logs as they were when the logs for this runnable
+ * were snapshotted
+ * @param {Mocha.Runnable} runnable
+ */
+export function getSnapshotOfRunnableLogs(runnable) {
+  return cachesRunnableLogs.get(runnable);
+}

src/functional_test_runner/__tests__/fixtures/failure_hooks/config.js

@@ -42,6 +42,9 @@ export default function () {
             log.info('testHookFailureAfterDelay %s %s', err.message, test.fullTitle());
           });
       }
+    },
+    mochaReporter: {
+      captureLogOutput: false
     }
   };
 }

src/functional_test_runner/lib/config/schema.js

@@ -96,6 +96,10 @@ export const schema = Joi.object().keys({
     rootDirectory: Joi.string(),
   }).default(),
 
+  mochaReporter: Joi.object().keys({
+    captureLogOutput: Joi.boolean().default(!!process.env.CI),
+  }).default(),
+
   users: Joi.object().pattern(
     ID_PATTERN,
     Joi.object().keys({

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

@@ -20,16 +20,19 @@
 import { format } from 'util';
 
 import Mocha from 'mocha';
+import { ToolingLogTextWriter } from '@kbn/dev-utils';
 
 import { setupJUnitReportGeneration } from '../../../../dev';
 import * as colors from './colors';
 import * as symbols from './symbols';
 import { ms } from './ms';
 import { writeEpilogue } from './write_epilogue';
+import { recordLog, snapshotLogsForRunnable } from '../../../../dev/mocha/log_cache';
 
 export function MochaReporterProvider({ getService }) {
   const log = getService('log');
   const config = getService('config');
+  let originalLogWriters;
 
   return class MochaReporter extends Mocha.reporters.Base {
     constructor(runner, options) {
@@ -55,11 +58,40 @@ export function MochaReporterProvider({ getService }) {
     }
 
     onStart = () => {
+      if (config.get('mochaReporter.captureLogOutput')) {
+        log.warning('debug logs are being captured, only error logs will be written to the console');
+        originalLogWriters = log.getWriters();
+        log.setWriters([
+          new ToolingLogTextWriter({
+            level: 'error',
+            writeTo: process.stdout
+          }),
+          new ToolingLogTextWriter({
+            level: 'debug',
+            writeTo: {
+              write: (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;
+
+                recordLog(currentSuite, chunk);
+              }
+            }
+          })
+        ]);
+      }
+
       log.write('');
     }
 
     onHookStart = hook => {
-      log.write('-> ' + colors.suite(hook.title));
+      log.write(`-> ${colors.suite(hook.title)}`);
       log.indent(2);
     }
 
@@ -76,7 +108,7 @@ export function MochaReporterProvider({ getService }) {
     }
 
     onSuiteEnd = () => {
-      if (log.indent(-2) === '') {
+      if (log.indent(-2) === 0) {
         log.write();
       }
     }
@@ -86,7 +118,8 @@ export function MochaReporterProvider({ getService }) {
       log.indent(2);
     }
 
-    onTestEnd = () => {
+    onTestEnd = (test) => {
+      snapshotLogsForRunnable(test);
       log.indent(-2);
     }
 
@@ -96,7 +129,6 @@ export function MochaReporterProvider({ getService }) {
     }
 
     onPass = test => {
-
       let time = '';
       if (test.speed !== 'fast') {
         time = colors.speed(test.speed, ` (${ms(test.duration)})`);
@@ -106,7 +138,7 @@ export function MochaReporterProvider({ getService }) {
       log.write(`- ${pass} ${time}`);
     }
 
-    onFail = test => {
+    onFail = runnable => {
       // NOTE: this is super gross
       //
       //  - I started by trying to extract the Base.list() logic from mocha
@@ -118,14 +150,13 @@ export function MochaReporterProvider({ getService }) {
       const realLog = console.log;
       console.log = (...args) => output += `${format(...args)}\n`;
       try {
-        Mocha.reporters.Base.list([test]);
+        Mocha.reporters.Base.list([runnable]);
       } finally {
         console.log = realLog;
       }
 
       log.write(
-        `- ${symbols.err} ` +
-        colors.fail(`fail: "${test.fullTitle()}"`) +
+        `- ${colors.fail(`${symbols.err} fail: "${runnable.fullTitle()}"`)}` +
         '\n' +
         output
           .split('\n')
@@ -136,9 +167,17 @@ export function MochaReporterProvider({ getService }) {
           .map(line => ` ${line}`)
           .join('\n')
       );
+
+      // failed hooks trigger the `onFail(runnable)` callback, so we snapshot the logs for
+      // them here. Tests will re-capture the snapshot in `onTestEnd()`
+      snapshotLogsForRunnable(runnable);
     }
 
     onEnd = () => {
+      if (originalLogWriters) {
+        log.setWriters(originalLogWriters);
+      }
+
       writeEpilogue(log, this.stats);
     }
   };

yarn.lock

@@ -11346,6 +11346,10 @@ regenerate@^1.2.1:
   version "1.3.3"
   resolved "https://registry.yarnpkg.com/regenerate/-/regenerate-1.3.3.tgz#0c336d3980553d755c39b586ae3b20aa49c82b7f"
 
+regenerate@^1.4.0:
+  version "1.4.0"
+  resolved "https://registry.yarnpkg.com/regenerate/-/regenerate-1.4.0.tgz#4a856ec4b56e4077c557589cae85e7a4c8869a11"
+
 regenerator-runtime@^0.10.0:
   version "0.10.5"
   resolved "https://registry.yarnpkg.com/regenerator-runtime/-/regenerator-runtime-0.10.5.tgz#336c3efc1220adcedda2c9fab67b5a7955a33658"