From d240bdd85d14cf3067e1f8baf244822be0a2db74 Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Tue, 23 Oct 2018 18:46:35 +0100 Subject: [PATCH 01/11] feat(NA): first version to add logs to the functional test runner when running on dev. --- .../src/tooling_log/tooling_log_text_writer.js | 7 ++++--- src/functional_test_runner/cli.js | 3 ++- tasks/functional_test_runner.js | 1 + 3 files changed, 7 insertions(+), 4 deletions(-) diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js index fa0db28687432..437a30ad71a20 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js @@ -18,9 +18,8 @@ */ import { format } from 'util'; - import { magentaBright, yellow, red, blue, green, dim } from 'chalk'; - +import moment from 'moment'; import { parseLogLevel } from './log_levels'; const PREFIX_INDENT = ' '.repeat(6); @@ -53,6 +52,7 @@ export class ToolingLogTextWriter { constructor(config) { this.level = parseLogLevel(config.level); this.writeTo = config.writeTo; + this.includeTimestamp = config.includeTimestamp || false; if (!this.writeTo || typeof this.writeTo.write !== 'function') { throw new Error( @@ -68,6 +68,7 @@ export class ToolingLogTextWriter { const txt = type === 'error' ? stringifyError(args[0]) : format(...args); const prefix = MSG_PREFIXES[type] || ''; + const timestamp = (this.includeTimestamp && ` ${moment().format('HH:mm:ss')} `) || ''; (prefix + txt).split('\n').forEach((line, i) => { let lineIndent = ''; @@ -84,7 +85,7 @@ export class ToolingLogTextWriter { lineIndent += PREFIX_INDENT; } - this.writeTo.write(`${lineIndent}${line}\n`); + this.writeTo.write(`${lineIndent}${timestamp}${line}\n`); }); return true; diff --git a/src/functional_test_runner/cli.js b/src/functional_test_runner/cli.js index 10e096da777c3..0d8026b1904fb 100644 --- a/src/functional_test_runner/cli.js +++ b/src/functional_test_runner/cli.js @@ -57,7 +57,8 @@ if (cmd.verbose) logLevel = 'verbose'; const log = new ToolingLog({ level: logLevel, - writeTo: process.stdout + writeTo: process.stdout, + includeTimestamp: cmd.debug }); const functionalTestRunner = createFunctionalTestRunner({ diff --git a/tasks/functional_test_runner.js b/tasks/functional_test_runner.js index 91c49e090ed58..89c637bafb270 100644 --- a/tasks/functional_test_runner.js +++ b/tasks/functional_test_runner.js @@ -31,6 +31,7 @@ export default function (grunt) { const log = new ToolingLog({ level: logLevel, writeTo: process.stdout, + includeTimestamp: grunt.option('debug') || grunt.option('verbose') }); const functionalTestRunner = createFunctionalTestRunner({ From 42db995b0e95482b85bd9aab45009800dfd9952c Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Tue, 23 Oct 2018 22:24:06 +0100 Subject: [PATCH 02/11] fix(NA): change timestamp position. --- .../kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js index 437a30ad71a20..3924de9ab0561 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js @@ -85,7 +85,7 @@ export class ToolingLogTextWriter { lineIndent += PREFIX_INDENT; } - this.writeTo.write(`${lineIndent}${timestamp}${line}\n`); + this.writeTo.write(`${timestamp}${lineIndent}${line}\n`); }); return true; From a5f1a5f8d4b677adaac4896c8ee475b56a1ba219 Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 03:43:14 +0100 Subject: [PATCH 03/11] test(NA): add unit test for tooling log text writer with timestamp. --- .../tooling_log_text_writer.test.js.snap | 9 ++++++ .../tooling_log_text_writer.test.js | 30 +++++++++++++++++++ 2 files changed, 39 insertions(+) diff --git a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap index 76c018fdb3661..76074cd18d0c6 100644 --- a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap +++ b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap @@ -9,6 +9,15 @@ exports[`formats %s patterns and indents multi-line messages correctly 1`] = ` " `; +exports[`formats log line with timestamp 1`] = ` +" 02:02:02 02:02:02 02:02:02 02:02:02 02:02:02 02:02:02 │ succ foo bar + 02:02:02 │ { foo: { bar: { '1': [Array] } }, + 02:02:02 │ bar: { bar: { '1': [Array] } } } + 02:02:02 │ + 02:02:02 │ Infinity +" +`; + exports[`level:debug/type:debug snapshots: is written 1`] = `true`; exports[`level:debug/type:debug snapshots: output 1`] = ` diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js index ed859757c0e76..cef7207013f32 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js @@ -18,6 +18,11 @@ */ import { ToolingLogTextWriter } from './tooling_log_text_writer'; +import moment from 'moment'; + +jest.mock('moment', () => () => ({ + format: jest.fn().mockImplementation(() => ' 02:02:02 '), +})); it('throws error if created with invalid level', () => { expect( @@ -96,3 +101,28 @@ it('formats %s patterns and indents multi-line messages correctly', () => { const output = write.mock.calls.reduce((acc, chunk) => `${acc}${chunk}`, ''); expect(output).toMatchSnapshot(); }); + +it('formats log line with timestamp', () => { + const write = jest.fn(); + const writer = new ToolingLogTextWriter({ + level: 'debug', + writeTo: { + write, + }, + includeTimestamp: true, + }); + + writer.write({ + type: 'success', + indent: 10, + args: [ + '%s\n%O\n\n%d', + 'foo bar', + { foo: { bar: { 1: [1, 2, 3] } }, bar: { bar: { 1: [1, 2, 3] } } }, + Infinity, + ], + }); + + const output = write.mock.calls.reduce((acc, chunk) => `${moment().format()}${acc}${chunk}`, ''); + expect(output).toMatchSnapshot(); +}); From 6bee1a1c949fc507e87c8b1958115eb7bed6bd3f Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 04:02:41 +0100 Subject: [PATCH 04/11] test(NA): update test and snapshots --- .../tooling_log_text_writer.test.js.snap | 164 +----------------- .../tooling_log_text_writer.test.js | 3 +- 2 files changed, 2 insertions(+), 165 deletions(-) diff --git a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap index 76074cd18d0c6..16cef8ad53ecc 100644 --- a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap +++ b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap @@ -10,7 +10,7 @@ exports[`formats %s patterns and indents multi-line messages correctly 1`] = ` `; exports[`formats log line with timestamp 1`] = ` -" 02:02:02 02:02:02 02:02:02 02:02:02 02:02:02 02:02:02 │ succ foo bar +" 02:02:02 │ succ foo bar 02:02:02 │ { foo: { bar: { '1': [Array] } }, 02:02:02 │ bar: { bar: { '1': [Array] } } } 02:02:02 │ @@ -18,168 +18,6 @@ exports[`formats log line with timestamp 1`] = ` " `; -exports[`level:debug/type:debug snapshots: is written 1`] = `true`; - -exports[`level:debug/type:debug snapshots: output 1`] = ` -" debg foo -" -`; - -exports[`level:debug/type:error snapshots: is written 1`] = `true`; - -exports[`level:debug/type:error snapshots: output 1`] = ` -"ERROR foo -" -`; - -exports[`level:debug/type:info snapshots: is written 1`] = `true`; - -exports[`level:debug/type:info snapshots: output 1`] = ` -" info foo -" -`; - -exports[`level:debug/type:success snapshots: is written 1`] = `true`; - -exports[`level:debug/type:success snapshots: output 1`] = ` -" succ foo -" -`; - -exports[`level:debug/type:verbose snapshots: is written 1`] = `false`; - -exports[`level:debug/type:warning snapshots: is written 1`] = `true`; - -exports[`level:debug/type:warning snapshots: output 1`] = ` -" warn foo -" -`; - -exports[`level:error/type:debug snapshots: is written 1`] = `false`; - -exports[`level:error/type:error snapshots: is written 1`] = `true`; - -exports[`level:error/type:error snapshots: output 1`] = ` -"ERROR foo -" -`; - -exports[`level:error/type:info snapshots: is written 1`] = `false`; - -exports[`level:error/type:success snapshots: is written 1`] = `false`; - -exports[`level:error/type:verbose snapshots: is written 1`] = `false`; - -exports[`level:error/type:warning snapshots: is written 1`] = `false`; - -exports[`level:info/type:debug snapshots: is written 1`] = `false`; - -exports[`level:info/type:error snapshots: is written 1`] = `true`; - -exports[`level:info/type:error snapshots: output 1`] = ` -"ERROR foo -" -`; - -exports[`level:info/type:info snapshots: is written 1`] = `true`; - -exports[`level:info/type:info snapshots: output 1`] = ` -" info foo -" -`; - -exports[`level:info/type:success snapshots: is written 1`] = `true`; - -exports[`level:info/type:success snapshots: output 1`] = ` -" succ foo -" -`; - -exports[`level:info/type:verbose snapshots: is written 1`] = `false`; - -exports[`level:info/type:warning snapshots: is written 1`] = `true`; - -exports[`level:info/type:warning snapshots: output 1`] = ` -" warn foo -" -`; - -exports[`level:silent/type:debug snapshots: is written 1`] = `false`; - -exports[`level:silent/type:error snapshots: is written 1`] = `false`; - -exports[`level:silent/type:info snapshots: is written 1`] = `false`; - -exports[`level:silent/type:success snapshots: is written 1`] = `false`; - -exports[`level:silent/type:verbose snapshots: is written 1`] = `false`; - -exports[`level:silent/type:warning snapshots: is written 1`] = `false`; - -exports[`level:verbose/type:debug snapshots: is written 1`] = `true`; - -exports[`level:verbose/type:debug snapshots: output 1`] = ` -" debg foo -" -`; - -exports[`level:verbose/type:error snapshots: is written 1`] = `true`; - -exports[`level:verbose/type:error snapshots: output 1`] = ` -"ERROR foo -" -`; - -exports[`level:verbose/type:info snapshots: is written 1`] = `true`; - -exports[`level:verbose/type:info snapshots: output 1`] = ` -" info foo -" -`; - -exports[`level:verbose/type:success snapshots: is written 1`] = `true`; - -exports[`level:verbose/type:success snapshots: output 1`] = ` -" succ foo -" -`; - -exports[`level:verbose/type:verbose snapshots: is written 1`] = `true`; - -exports[`level:verbose/type:verbose snapshots: output 1`] = ` -" sill foo -" -`; - -exports[`level:verbose/type:warning snapshots: is written 1`] = `true`; - -exports[`level:verbose/type:warning snapshots: output 1`] = ` -" warn foo -" -`; - -exports[`level:warning/type:debug snapshots: is written 1`] = `false`; - -exports[`level:warning/type:error snapshots: is written 1`] = `true`; - -exports[`level:warning/type:error snapshots: output 1`] = ` -"ERROR foo -" -`; - -exports[`level:warning/type:info snapshots: is written 1`] = `false`; - -exports[`level:warning/type:success snapshots: is written 1`] = `false`; - -exports[`level:warning/type:verbose snapshots: is written 1`] = `false`; - -exports[`level:warning/type:warning snapshots: is written 1`] = `true`; - -exports[`level:warning/type:warning snapshots: output 1`] = ` -" warn foo -" -`; - exports[`throws error if created with invalid level 1`] = `"Invalid log level \\"foo\\" (expected one of silent,error,warning,info,debug,verbose)"`; exports[`throws error if writeTo config is not defined or doesn't have a write method 1`] = `"ToolingLogTextWriter requires the \`writeTo\` option be set to a stream (like process.stdout)"`; diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js index cef7207013f32..5ae79d6860f71 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js @@ -18,7 +18,6 @@ */ import { ToolingLogTextWriter } from './tooling_log_text_writer'; -import moment from 'moment'; jest.mock('moment', () => () => ({ format: jest.fn().mockImplementation(() => ' 02:02:02 '), @@ -123,6 +122,6 @@ it('formats log line with timestamp', () => { ], }); - const output = write.mock.calls.reduce((acc, chunk) => `${moment().format()}${acc}${chunk}`, ''); + const output = write.mock.calls.reduce((acc, chunk) => `${acc}${chunk}`, ''); expect(output).toMatchSnapshot(); }); From 52ec91945fe7d615d790e70c184c1c4e33e9a869 Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 16:52:54 +0100 Subject: [PATCH 05/11] fix(NA): only apply timestamp logs for the jenkins test reports. --- src/functional_test_runner/cli.js | 3 +-- src/functional_test_runner/lib/mocha/reporter/reporter.js | 6 ++++-- tasks/functional_test_runner.js | 3 +-- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/src/functional_test_runner/cli.js b/src/functional_test_runner/cli.js index 0d8026b1904fb..10e096da777c3 100644 --- a/src/functional_test_runner/cli.js +++ b/src/functional_test_runner/cli.js @@ -57,8 +57,7 @@ if (cmd.verbose) logLevel = 'verbose'; const log = new ToolingLog({ level: logLevel, - writeTo: process.stdout, - includeTimestamp: cmd.debug + writeTo: process.stdout }); const functionalTestRunner = createFunctionalTestRunner({ diff --git a/src/functional_test_runner/lib/mocha/reporter/reporter.js b/src/functional_test_runner/lib/mocha/reporter/reporter.js index 39c69f914e43f..9817ad5b033e0 100644 --- a/src/functional_test_runner/lib/mocha/reporter/reporter.js +++ b/src/functional_test_runner/lib/mocha/reporter/reporter.js @@ -64,7 +64,8 @@ export function MochaReporterProvider({ getService }) { log.setWriters([ new ToolingLogTextWriter({ level: 'error', - writeTo: process.stdout + writeTo: process.stdout, + includeTimestamp: true }), new ToolingLogTextWriter({ level: 'debug', @@ -82,7 +83,8 @@ export function MochaReporterProvider({ getService }) { recordLog(currentSuite, chunk); } - } + }, + includeTimestamp: true }) ]); } diff --git a/tasks/functional_test_runner.js b/tasks/functional_test_runner.js index 89c637bafb270..234e2fcb0303d 100644 --- a/tasks/functional_test_runner.js +++ b/tasks/functional_test_runner.js @@ -30,8 +30,7 @@ export default function (grunt) { const log = new ToolingLog({ level: logLevel, - writeTo: process.stdout, - includeTimestamp: grunt.option('debug') || grunt.option('verbose') + writeTo: process.stdout }); const functionalTestRunner = createFunctionalTestRunner({ From 83c680785eb3b98b8f49513da21f9dd580cabce8 Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 16:59:32 +0100 Subject: [PATCH 06/11] test(NA): update jest snapshots correctly. --- .../tooling_log_text_writer.test.js.snap | 162 ++++++++++++++++++ tasks/functional_test_runner.js | 2 +- 2 files changed, 163 insertions(+), 1 deletion(-) diff --git a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap index 16cef8ad53ecc..c807fed20a470 100644 --- a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap +++ b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap @@ -18,6 +18,168 @@ exports[`formats log line with timestamp 1`] = ` " `; +exports[`level:debug/type:debug snapshots: is written 1`] = `true`; + +exports[`level:debug/type:debug snapshots: output 1`] = ` +" debg foo +" +`; + +exports[`level:debug/type:error snapshots: is written 1`] = `true`; + +exports[`level:debug/type:error snapshots: output 1`] = ` +"ERROR foo +" +`; + +exports[`level:debug/type:info snapshots: is written 1`] = `true`; + +exports[`level:debug/type:info snapshots: output 1`] = ` +" info foo +" +`; + +exports[`level:debug/type:success snapshots: is written 1`] = `true`; + +exports[`level:debug/type:success snapshots: output 1`] = ` +" succ foo +" +`; + +exports[`level:debug/type:verbose snapshots: is written 1`] = `false`; + +exports[`level:debug/type:warning snapshots: is written 1`] = `true`; + +exports[`level:debug/type:warning snapshots: output 1`] = ` +" warn foo +" +`; + +exports[`level:error/type:debug snapshots: is written 1`] = `false`; + +exports[`level:error/type:error snapshots: is written 1`] = `true`; + +exports[`level:error/type:error snapshots: output 1`] = ` +"ERROR foo +" +`; + +exports[`level:error/type:info snapshots: is written 1`] = `false`; + +exports[`level:error/type:success snapshots: is written 1`] = `false`; + +exports[`level:error/type:verbose snapshots: is written 1`] = `false`; + +exports[`level:error/type:warning snapshots: is written 1`] = `false`; + +exports[`level:info/type:debug snapshots: is written 1`] = `false`; + +exports[`level:info/type:error snapshots: is written 1`] = `true`; + +exports[`level:info/type:error snapshots: output 1`] = ` +"ERROR foo +" +`; + +exports[`level:info/type:info snapshots: is written 1`] = `true`; + +exports[`level:info/type:info snapshots: output 1`] = ` +" info foo +" +`; + +exports[`level:info/type:success snapshots: is written 1`] = `true`; + +exports[`level:info/type:success snapshots: output 1`] = ` +" succ foo +" +`; + +exports[`level:info/type:verbose snapshots: is written 1`] = `false`; + +exports[`level:info/type:warning snapshots: is written 1`] = `true`; + +exports[`level:info/type:warning snapshots: output 1`] = ` +" warn foo +" +`; + +exports[`level:silent/type:debug snapshots: is written 1`] = `false`; + +exports[`level:silent/type:error snapshots: is written 1`] = `false`; + +exports[`level:silent/type:info snapshots: is written 1`] = `false`; + +exports[`level:silent/type:success snapshots: is written 1`] = `false`; + +exports[`level:silent/type:verbose snapshots: is written 1`] = `false`; + +exports[`level:silent/type:warning snapshots: is written 1`] = `false`; + +exports[`level:verbose/type:debug snapshots: is written 1`] = `true`; + +exports[`level:verbose/type:debug snapshots: output 1`] = ` +" debg foo +" +`; + +exports[`level:verbose/type:error snapshots: is written 1`] = `true`; + +exports[`level:verbose/type:error snapshots: output 1`] = ` +"ERROR foo +" +`; + +exports[`level:verbose/type:info snapshots: is written 1`] = `true`; + +exports[`level:verbose/type:info snapshots: output 1`] = ` +" info foo +" +`; + +exports[`level:verbose/type:success snapshots: is written 1`] = `true`; + +exports[`level:verbose/type:success snapshots: output 1`] = ` +" succ foo +" +`; + +exports[`level:verbose/type:verbose snapshots: is written 1`] = `true`; + +exports[`level:verbose/type:verbose snapshots: output 1`] = ` +" sill foo +" +`; + +exports[`level:verbose/type:warning snapshots: is written 1`] = `true`; + +exports[`level:verbose/type:warning snapshots: output 1`] = ` +" warn foo +" +`; + +exports[`level:warning/type:debug snapshots: is written 1`] = `false`; + +exports[`level:warning/type:error snapshots: is written 1`] = `true`; + +exports[`level:warning/type:error snapshots: output 1`] = ` +"ERROR foo +" +`; + +exports[`level:warning/type:info snapshots: is written 1`] = `false`; + +exports[`level:warning/type:success snapshots: is written 1`] = `false`; + +exports[`level:warning/type:verbose snapshots: is written 1`] = `false`; + +exports[`level:warning/type:warning snapshots: is written 1`] = `true`; + +exports[`level:warning/type:warning snapshots: output 1`] = ` +" warn foo +" +`; + exports[`throws error if created with invalid level 1`] = `"Invalid log level \\"foo\\" (expected one of silent,error,warning,info,debug,verbose)"`; exports[`throws error if writeTo config is not defined or doesn't have a write method 1`] = `"ToolingLogTextWriter requires the \`writeTo\` option be set to a stream (like process.stdout)"`; diff --git a/tasks/functional_test_runner.js b/tasks/functional_test_runner.js index 234e2fcb0303d..91c49e090ed58 100644 --- a/tasks/functional_test_runner.js +++ b/tasks/functional_test_runner.js @@ -30,7 +30,7 @@ export default function (grunt) { const log = new ToolingLog({ level: logLevel, - writeTo: process.stdout + writeTo: process.stdout, }); const functionalTestRunner = createFunctionalTestRunner({ From ceb51e8a7f2b1651ac4665744103afa00675ceb4 Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 18:18:35 +0100 Subject: [PATCH 07/11] fix(NA): only add timestamp for the test results cached chunk logs. --- .../tooling_log_text_writer.test.js.snap | 9 ------ .../tooling_log/tooling_log_text_writer.js | 5 +--- .../tooling_log_text_writer.test.js | 29 ------------------- .../lib/mocha/reporter/reporter.js | 13 +++++---- tasks/test.js | 14 ++++----- 5 files changed, 16 insertions(+), 54 deletions(-) diff --git a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap index c807fed20a470..76c018fdb3661 100644 --- a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap +++ b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.js.snap @@ -9,15 +9,6 @@ exports[`formats %s patterns and indents multi-line messages correctly 1`] = ` " `; -exports[`formats log line with timestamp 1`] = ` -" 02:02:02 │ succ foo bar - 02:02:02 │ { foo: { bar: { '1': [Array] } }, - 02:02:02 │ bar: { bar: { '1': [Array] } } } - 02:02:02 │ - 02:02:02 │ Infinity -" -`; - exports[`level:debug/type:debug snapshots: is written 1`] = `true`; exports[`level:debug/type:debug snapshots: output 1`] = ` diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js index 3924de9ab0561..fb37062b255bc 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js @@ -19,7 +19,6 @@ import { format } from 'util'; import { magentaBright, yellow, red, blue, green, dim } from 'chalk'; -import moment from 'moment'; import { parseLogLevel } from './log_levels'; const PREFIX_INDENT = ' '.repeat(6); @@ -52,7 +51,6 @@ export class ToolingLogTextWriter { constructor(config) { this.level = parseLogLevel(config.level); this.writeTo = config.writeTo; - this.includeTimestamp = config.includeTimestamp || false; if (!this.writeTo || typeof this.writeTo.write !== 'function') { throw new Error( @@ -68,7 +66,6 @@ export class ToolingLogTextWriter { const txt = type === 'error' ? stringifyError(args[0]) : format(...args); const prefix = MSG_PREFIXES[type] || ''; - const timestamp = (this.includeTimestamp && ` ${moment().format('HH:mm:ss')} `) || ''; (prefix + txt).split('\n').forEach((line, i) => { let lineIndent = ''; @@ -85,7 +82,7 @@ export class ToolingLogTextWriter { lineIndent += PREFIX_INDENT; } - this.writeTo.write(`${timestamp}${lineIndent}${line}\n`); + this.writeTo.write(`${lineIndent}${line}\n`); }); return true; diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js index 5ae79d6860f71..ed859757c0e76 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.js @@ -19,10 +19,6 @@ import { ToolingLogTextWriter } from './tooling_log_text_writer'; -jest.mock('moment', () => () => ({ - format: jest.fn().mockImplementation(() => ' 02:02:02 '), -})); - it('throws error if created with invalid level', () => { expect( () => @@ -100,28 +96,3 @@ it('formats %s patterns and indents multi-line messages correctly', () => { const output = write.mock.calls.reduce((acc, chunk) => `${acc}${chunk}`, ''); expect(output).toMatchSnapshot(); }); - -it('formats log line with timestamp', () => { - const write = jest.fn(); - const writer = new ToolingLogTextWriter({ - level: 'debug', - writeTo: { - write, - }, - includeTimestamp: true, - }); - - writer.write({ - type: 'success', - indent: 10, - args: [ - '%s\n%O\n\n%d', - 'foo bar', - { foo: { bar: { 1: [1, 2, 3] } }, bar: { bar: { 1: [1, 2, 3] } } }, - Infinity, - ], - }); - - const output = write.mock.calls.reduce((acc, chunk) => `${acc}${chunk}`, ''); - expect(output).toMatchSnapshot(); -}); diff --git a/src/functional_test_runner/lib/mocha/reporter/reporter.js b/src/functional_test_runner/lib/mocha/reporter/reporter.js index 9817ad5b033e0..29165bc737fa2 100644 --- a/src/functional_test_runner/lib/mocha/reporter/reporter.js +++ b/src/functional_test_runner/lib/mocha/reporter/reporter.js @@ -21,6 +21,7 @@ import { format } from 'util'; import Mocha from 'mocha'; import { ToolingLogTextWriter } from '@kbn/dev-utils'; +import moment from 'moment'; import { setupJUnitReportGeneration } from '../../../../dev'; import * as colors from './colors'; @@ -64,8 +65,7 @@ export function MochaReporterProvider({ getService }) { log.setWriters([ new ToolingLogTextWriter({ level: 'error', - writeTo: process.stdout, - includeTimestamp: true + writeTo: process.stdout }), new ToolingLogTextWriter({ level: 'debug', @@ -81,10 +81,13 @@ export function MochaReporterProvider({ getService }) { ? this.runner.test.parent : this.runner.suite; - recordLog(currentSuite, chunk); + // We are registering the current time in order to extend the + // current chunk with it so we can have the test results + // log lines with that information + const currentTime = `${moment().format('HH:mm:ss')}`; + recordLog(currentSuite, `${currentTime} ${chunk}`); } - }, - includeTimestamp: true + } }) ]); } diff --git a/tasks/test.js b/tasks/test.js index b0abce01554a1..9e7e90a964964 100644 --- a/tasks/test.js +++ b/tasks/test.js @@ -48,13 +48,13 @@ module.exports = function (grunt) { grunt.registerTask('test:coverage', ['run:testCoverageServer', 'karma:coverage']); grunt.registerTask('test:quick', [ - 'checkPlugins', - 'test:server', - 'run:functionalTests', - 'test:jest', - 'test:jest_integration', - 'test:projects', - 'test:browser', + // 'checkPlugins', + // 'test:server', + // 'run:functionalTests', + // 'test:jest', + // 'test:jest_integration', + // 'test:projects', + // 'test:browser', 'run:apiIntegrationTests', ]); From e40c144f214b026ca166fdb8d6f742ff17c5f639 Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 18:19:51 +0100 Subject: [PATCH 08/11] fix(NA): rollback bad changes. --- .../src/tooling_log/tooling_log_text_writer.js | 2 ++ tasks/test.js | 14 +++++++------- 2 files changed, 9 insertions(+), 7 deletions(-) diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js index fb37062b255bc..fa0db28687432 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.js @@ -18,7 +18,9 @@ */ import { format } from 'util'; + import { magentaBright, yellow, red, blue, green, dim } from 'chalk'; + import { parseLogLevel } from './log_levels'; const PREFIX_INDENT = ' '.repeat(6); diff --git a/tasks/test.js b/tasks/test.js index 9e7e90a964964..b0abce01554a1 100644 --- a/tasks/test.js +++ b/tasks/test.js @@ -48,13 +48,13 @@ module.exports = function (grunt) { grunt.registerTask('test:coverage', ['run:testCoverageServer', 'karma:coverage']); grunt.registerTask('test:quick', [ - // 'checkPlugins', - // 'test:server', - // 'run:functionalTests', - // 'test:jest', - // 'test:jest_integration', - // 'test:projects', - // 'test:browser', + 'checkPlugins', + 'test:server', + 'run:functionalTests', + 'test:jest', + 'test:jest_integration', + 'test:projects', + 'test:browser', 'run:apiIntegrationTests', ]); From e5fb174a1c2e292e686c62327749c6496e3f7cff Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 18:30:22 +0100 Subject: [PATCH 09/11] refact(NA): change comments on code to be more clear with the purpose. --- src/functional_test_runner/lib/mocha/reporter/reporter.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/functional_test_runner/lib/mocha/reporter/reporter.js b/src/functional_test_runner/lib/mocha/reporter/reporter.js index 29165bc737fa2..0c3cf3e058024 100644 --- a/src/functional_test_runner/lib/mocha/reporter/reporter.js +++ b/src/functional_test_runner/lib/mocha/reporter/reporter.js @@ -81,9 +81,9 @@ export function MochaReporterProvider({ getService }) { ? this.runner.test.parent : this.runner.suite; - // We are registering the current time in order to extend the - // current chunk with it so we can have the test results - // log lines with that information + // We are registering the current time in order to be able + // to extend the log chunk with it so we can have the test + // results log lines labeled with such info const currentTime = `${moment().format('HH:mm:ss')}`; recordLog(currentSuite, `${currentTime} ${chunk}`); } From 391f2128d408ef076893b86228d04508ce6bfc5c Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 19:24:39 +0100 Subject: [PATCH 10/11] refact(NA): rename chunk to line. --- src/functional_test_runner/lib/mocha/reporter/reporter.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/functional_test_runner/lib/mocha/reporter/reporter.js b/src/functional_test_runner/lib/mocha/reporter/reporter.js index 0c3cf3e058024..891ff2da51f3a 100644 --- a/src/functional_test_runner/lib/mocha/reporter/reporter.js +++ b/src/functional_test_runner/lib/mocha/reporter/reporter.js @@ -70,7 +70,7 @@ export function MochaReporterProvider({ getService }) { new ToolingLogTextWriter({ level: 'debug', writeTo: { - write: (chunk) => { + write: (line) => { // 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 @@ -82,10 +82,10 @@ export function MochaReporterProvider({ getService }) { : this.runner.suite; // We are registering the current time in order to be able - // to extend the log chunk with it so we can have the test + // to extend the log line with it so we can have the test // results log lines labeled with such info const currentTime = `${moment().format('HH:mm:ss')}`; - recordLog(currentSuite, `${currentTime} ${chunk}`); + recordLog(currentSuite, `${currentTime} ${line}`); } } }) From 824ebac0b5acf284cc6d7226cc1e74def311ac0f Mon Sep 17 00:00:00 2001 From: Tiago Costa Date: Wed, 24 Oct 2018 21:43:06 +0100 Subject: [PATCH 11/11] feat(NA): log the relative time info since the start time of the task instead of the absolute time. --- .../lib/mocha/reporter/reporter.js | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/src/functional_test_runner/lib/mocha/reporter/reporter.js b/src/functional_test_runner/lib/mocha/reporter/reporter.js index 891ff2da51f3a..1df3fc8b6bf18 100644 --- a/src/functional_test_runner/lib/mocha/reporter/reporter.js +++ b/src/functional_test_runner/lib/mocha/reporter/reporter.js @@ -34,6 +34,7 @@ export function MochaReporterProvider({ getService }) { const log = getService('log'); const config = getService('config'); let originalLogWriters; + let reporterCaptureStartTime; return class MochaReporter extends Mocha.reporters.Base { constructor(runner, options) { @@ -61,7 +62,10 @@ 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'); + + reporterCaptureStartTime = moment(); originalLogWriters = log.getWriters(); + log.setWriters([ new ToolingLogTextWriter({ level: 'error', @@ -81,11 +85,14 @@ export function MochaReporterProvider({ getService }) { ? this.runner.test.parent : this.runner.suite; - // We are registering the current time in order to be able - // to extend the log line with it so we can have the test - // results log lines labeled with such info - const currentTime = `${moment().format('HH:mm:ss')}`; - recordLog(currentSuite, `${currentTime} ${line}`); + // We are computing the difference between the time when this + // reporter has started and the time when each line are being + // logged in order to be able to label the test results log lines + // with this relative time information + const diffTimeSinceStart = moment().diff(reporterCaptureStartTime); + const readableDiffTimeSinceStart = `[${moment(diffTimeSinceStart).format('HH:mm:ss')}] `; + + recordLog(currentSuite, `${readableDiffTimeSinceStart} ${line}`); } } })