From c0182bf3625bf9291c558456d8f9670f5c9ae675 Mon Sep 17 00:00:00 2001 From: spalger Date: Sat, 11 Aug 2018 11:40:33 -0700 Subject: [PATCH] [ftr] capture test output rather any try to only log on failure --- packages/kbn-dev-utils/index.d.ts | 6 ++ .../src/tooling_log/tooling_log.js | 39 ++++++++- src/dev/mocha/junit_report_generation.js | 3 + .../lib/mocha/reporter/reporter.js | 83 ++++++++++++++----- 4 files changed, 108 insertions(+), 23 deletions(-) diff --git a/packages/kbn-dev-utils/index.d.ts b/packages/kbn-dev-utils/index.d.ts index efd26bfea07b6f1..02584b84727b9d7 100644 --- a/packages/kbn-dev-utils/index.d.ts +++ b/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; diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log.js index d306dcfe76a5d6a..98d4c5ed18be1ce 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log.js +++ b/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(); diff --git a/src/dev/mocha/junit_report_generation.js b/src/dev/mocha/junit_report_generation.js index 5572d4287a241ff..6955a36acee7460 100644 --- a/src/dev/mocha/junit_report_generation.js +++ b/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)); diff --git a/src/functional_test_runner/lib/mocha/reporter/reporter.js b/src/functional_test_runner/lib/mocha/reporter/reporter.js index efced410ab937ab..a593bda4de81992 100644 --- a/src/functional_test_runner/lib/mocha/reporter/reporter.js +++ b/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,7 +103,7 @@ export function MochaReporterProvider({ getService }) { onSuiteStart = suite => { if (!suite.root) { - log.write('-: ' + colors.suite(suite.title)); + this._writeToBothLogs('-: ' + colors.suite(suite.title)); } log.indent(2); @@ -77,7 +111,7 @@ export function MochaReporterProvider({ getService }) { onSuiteEnd = () => { if (log.indent(-2) === '') { - log.write(); + this._writeToBothLogs(); } } @@ -91,12 +125,11 @@ 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)})`); @@ -104,6 +137,12 @@ export function MochaReporterProvider({ getService }) { 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); } };