[ftr] capture test output and only log on failure (#21903)

This is an attempt to write a log capture integration for the functional test runner that will collect all log output written during a test, prevent it from being written to stdout to lower the amount of work Jenkins master has to do and include the entire log output for each test in the junit report. I'm slightly concerned about the amount of memory we'll be using to store a copy of the logs for each test, but streaming the XML report isn’t easy and there doesn’t seem to be a library out there to help. If we decide it’s torally necessary we might be able to figure it out.

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"