diff --git a/src/common/internal/logging/log_message.ts b/src/common/internal/logging/log_message.ts index ee006cdeb3ae..d92180437169 100644 --- a/src/common/internal/logging/log_message.ts +++ b/src/common/internal/logging/log_message.ts @@ -4,6 +4,7 @@ import { extractImportantStackTrace } from '../stack.js'; export class LogMessageWithStack extends Error { readonly extra: unknown; + private showStar: boolean = true; private stackHiddenMessage: string | undefined = undefined; constructor(name: string, ex: Error | ErrorWithExtra) { @@ -16,19 +17,20 @@ export class LogMessageWithStack extends Error { } } - /** Set a flag so the stack is not printed in toJSON(). */ - setStackHidden(stackHiddenMessage: string) { - this.stackHiddenMessage ??= stackHiddenMessage; + /** Set a flag so the stack is not printed in toJSON(), and important messages are starred. */ + setPrintOptions(showStar: boolean, stackHiddenMessage: string) { + this.showStar = showStar; + this.stackHiddenMessage = stackHiddenMessage; } toJSON(): string { - let m = this.name; + let m = (this.showStar ? '☆ ' : ' ') + this.name; if (this.message) m += ': ' + this.message; if (this.stack) { if (this.stackHiddenMessage === undefined) { m += '\n' + extractImportantStackTrace(this); } else if (this.stackHiddenMessage) { - m += `\n at (elided: ${this.stackHiddenMessage})`; + m += `\n at (elided: ${this.stackHiddenMessage})`; } } return m; diff --git a/src/common/internal/logging/test_case_recorder.ts b/src/common/internal/logging/test_case_recorder.ts index f5c3252b5c7d..4091ddd1f53a 100644 --- a/src/common/internal/logging/test_case_recorder.ts +++ b/src/common/internal/logging/test_case_recorder.ts @@ -18,7 +18,13 @@ enum LogSeverity { const kMaxLogStacks = 2; const kMinSeverityForStack = LogSeverity.Warn; -function logSeverityToString(status: LogSeverity): Status { +function logSeverityToString(severity: LogSeverity): string { + return ['NotRun', 'Skip', 'Pass', 'Warn', 'ExpectFailed', 'ValidationFailed', 'ThrewException'][ + severity + ]; +} + +function logSeverityToStatus(status: LogSeverity): Status { switch (status) { case LogSeverity.NotRun: return 'notrun'; @@ -42,11 +48,10 @@ export class TestCaseRecorder { private finalCaseStatus = LogSeverity.NotRun; private hideStacksBelowSeverity = kMinSeverityForStack; private startTime = -1; + private preambleLog?: LogMessageWithStack; private logs: LogMessageWithStack[] = []; private logLinesAtCurrentSeverity = 0; private debugging = false; - /** Used to dedup log messages which have identical stacks. */ - private messagesForPreviouslySeenStacks = new Map(); constructor(result: LiveTestCaseResult, debugging: boolean) { this.result = result; @@ -72,7 +77,7 @@ export class TestCaseRecorder { } // Convert numeric enum back to string (but expose 'exception' as 'fail') - this.result.status = logSeverityToString(this.finalCaseStatus); + this.result.status = logSeverityToStatus(this.finalCaseStatus); this.result.logs = this.logs; } @@ -146,6 +151,18 @@ export class TestCaseRecorder { this.logImpl(LogSeverity.ThrewException, 'EXCEPTION', ex); } + private updatePreamble() { + if (this.preambleLog === undefined) { + const preambleError = new Error(); + preambleError.stack = undefined; + this.preambleLog = new LogMessageWithStack('SUMMARY', preambleError); + this.logs.unshift(this.preambleLog); + } + this.preambleLog.message = `highest severity is ☆ ${logSeverityToString( + this.hideStacksBelowSeverity + )}`; + } + private logImpl(level: LogSeverity, name: string, baseException: unknown): void { assert(baseException instanceof Error, 'test threw a non-Error object'); globalTestConfig.testHeartbeatCallback(); @@ -158,25 +175,26 @@ export class TestCaseRecorder { this.finalCaseStatus = Math.max(this.finalCaseStatus, level); } - // setFirstLineOnly for all logs except `kMaxLogStacks` stacks at the highest severity + // Hide stack for all logs except `kMaxLogStacks` stacks at the highest severity if (level > this.hideStacksBelowSeverity) { this.logLinesAtCurrentSeverity = 0; this.hideStacksBelowSeverity = level; + this.updatePreamble(); - // Go back and setFirstLineOnly for everything of a lower log level + // Go back and hide stack for everything of a lower log level for (const log of this.logs) { - log.setStackHidden('below max severity'); + log.setPrintOptions(false, 'below max severity'); } } if (level === this.hideStacksBelowSeverity) { this.logLinesAtCurrentSeverity++; + if (this.logLinesAtCurrentSeverity > kMaxLogStacks) { + logMessage.setPrintOptions(true, `only ${kMaxLogStacks} shown`); + } } else if (level < kMinSeverityForStack) { - logMessage.setStackHidden(''); + logMessage.setPrintOptions(false, ''); } else if (level < this.hideStacksBelowSeverity) { - logMessage.setStackHidden('below max severity'); - } - if (this.logLinesAtCurrentSeverity > kMaxLogStacks) { - logMessage.setStackHidden(`only ${kMaxLogStacks} shown`); + logMessage.setPrintOptions(false, 'below max severity'); } this.logs.push(logMessage); diff --git a/src/demo/a/b/c.spec.ts b/src/demo/a/b/c.spec.ts index 0ee8f4c182a0..ce68152265b7 100644 --- a/src/demo/a/b/c.spec.ts +++ b/src/demo/a/b/c.spec.ts @@ -1,7 +1,6 @@ export const description = 'Description for c.spec.ts'; import { makeTestGroup } from '../../../common/framework/test_group.js'; -import { unreachable } from '../../../common/util/util.js'; import { UnitTest } from '../../../unittests/unit_test.js'; export const g = makeTestGroup(UnitTest); @@ -32,49 +31,3 @@ g.test('deep_case_tree') .combine('z', [1, 2]) ) .fn(() => {}); - -g.test('statuses,debug').fn(t => { - t.debug('debug'); -}); - -g.test('statuses,skip').fn(t => { - t.skip('skip'); -}); - -g.test('statuses,warn').fn(t => { - t.warn('warn'); -}); - -g.test('statuses,fail').fn(t => { - t.fail('fail'); -}); - -g.test('statuses,throw').fn(() => { - unreachable('unreachable'); -}); - -g.test('multiple_same_stack').fn(t => { - for (let i = 0; i < 3; ++i) { - t.fail( - i === 2 - ? 'this should appear after deduplicated line' - : 'this should be "seen 2 times with identical stack"' - ); - } -}); - -g.test('multiple_same_level').fn(t => { - t.fail('this should print a stack'); - t.fail('this should print a stack'); - t.fail('this should not print a stack'); -}); - -g.test('lower_levels_hidden,before').fn(t => { - t.warn('warn - this should not print a stack'); - t.fail('fail'); -}); - -g.test('lower_levels_hidden,after').fn(t => { - t.fail('fail'); - t.warn('warn - this should not print a stack'); -}); diff --git a/src/demo/logs.spec.ts b/src/demo/logs.spec.ts new file mode 100644 index 000000000000..801cd3d0f928 --- /dev/null +++ b/src/demo/logs.spec.ts @@ -0,0 +1,82 @@ +export const description = 'Demos of how log levels show up in log outputs'; + +import { makeTestGroup } from '../common/framework/test_group.js'; +import { unreachable } from '../common/util/util.js'; +import { UnitTest } from '../unittests/unit_test.js'; + +export const g = makeTestGroup(UnitTest); + +g.test('statuses,debug').fn(t => { + t.debug('debug'); +}); + +g.test('statuses,skip').fn(t => { + t.skip('skip'); +}); + +g.test('statuses,warn').fn(t => { + t.warn('warn'); +}); + +g.test('statuses,fail').fn(t => { + t.fail('fail'); +}); + +g.test('statuses,throw').fn(() => { + unreachable('unreachable'); +}); + +g.test('multiple_same_level').fn(t => { + t.fail('this should print a stack'); + t.fail('this should print a stack'); + t.fail('this should not print a stack'); +}); + +g.test('multiple_lower_level').fn(t => { + t.fail('this should print a stack'); + t.fail('this should print a stack'); + t.fail('this should not print a stack'); + t.warn('this should not print a stack'); + t.warn('this should not print a stack'); + t.warn('this should not print a stack'); +}); + +g.test('lower_levels_hidden,before').fn(t => { + t.warn('warn - this should not print a stack'); + t.fail('fail'); +}); + +g.test('lower_levels_hidden,after').fn(t => { + t.fail('fail'); + t.warn('warn - this should not print a stack'); +}); + +g.test('exception_over_validation').fn(t => { + t.rec.validationFailed(new Error('first, but lower priority - stack should be elided')); + t.rec.threw(new Error('second, but higher priority - stack should be shown')); + t.rec.validationFailed(new Error('third, lower priority - stack should be elided')); +}); + +g.test('validation_over_expectation').fn(t => { + t.rec.expectationFailed(new Error('first, but lower priority - stack should be elided')); + t.rec.validationFailed(new Error('second, but higher priority - stack should be shown')); + t.rec.expectationFailed(new Error('third, lower priority - stack should be elided')); +}); + +g.test('expectation_over_warn').fn(t => { + t.rec.warn(new Error('first, but lower priority - stack should be elided')); + t.rec.expectationFailed(new Error('second, but higher priority - stack should be shown')); + t.rec.warn(new Error('third, lower priority - stack should be elided')); +}); + +g.test('warn_over_skip').fn(t => { + t.rec.skipped(new Error('stacks are never shown for this level')); + t.rec.warn(new Error('second, but higher priority - stack should be shown')); + t.rec.skipped(new Error('stacks are never shown for this level')); +}); + +g.test('skip_over_info').fn(t => { + t.rec.info(new Error('stacks are never shown for this level')); + t.rec.skipped(new Error('stacks are never shown for this level')); + t.rec.info(new Error('stacks are never shown for this level')); +}); diff --git a/src/unittests/loaders_and_trees.spec.ts b/src/unittests/loaders_and_trees.spec.ts index a22c06e66979..dc693063342b 100644 --- a/src/unittests/loaders_and_trees.spec.ts +++ b/src/unittests/loaders_and_trees.spec.ts @@ -287,7 +287,7 @@ g.test('end2end').fn(async t => { new TestQuerySingleCase('suite2', ['foof'], ['blah'], {}), [], 'pass', - logs => objectEquals(logs, ['"DEBUG: OK"']) + logs => objectEquals(logs, ['" DEBUG: OK"']) ); await runTestcase( t, @@ -297,7 +297,7 @@ g.test('end2end').fn(async t => { new TestQuerySingleCase('suite2', ['foof'], ['bleh'], { a: 1 }), [], 'pass', - logs => objectEquals(logs, ['"DEBUG: OK"', '"DEBUG: OK"']) + logs => objectEquals(logs, ['" DEBUG: OK"', '" DEBUG: OK"']) ); await runTestcase( t, @@ -308,9 +308,9 @@ g.test('end2end').fn(async t => { [], 'fail', logs => - logs.length === 1 && - logs[0].startsWith('"EXPECTATION FAILED: goodbye\\n') && - logs[0].indexOf('loaders_and_trees.spec.') !== -1 + logs.length === 2 && + logs[1].startsWith('"☆ EXPECTATION FAILED: goodbye\\n') && + logs[1].indexOf('loaders_and_trees.spec.') !== -1 ); }); @@ -334,7 +334,7 @@ g.test('expectations,single_case').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['zed'], { a: 1, b: 2 }), zedExpectationsSkipA1B2, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); await runTestcase( @@ -413,7 +413,7 @@ g.test('expectations,multi_case').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['zed'], { a: 1, b: 3 }), zedExpectationsSkipB3, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); }); @@ -436,7 +436,7 @@ g.test('expectations,multi_case_all').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['zed'], { a: 1, b: 2 }), zedExpectationsSkipA1, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); await runTestcase( @@ -447,7 +447,7 @@ g.test('expectations,multi_case_all').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['zed'], { a: 1, b: 3 }), zedExpectationsSkipA1, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); }); @@ -470,7 +470,7 @@ g.test('expectations,multi_case_none').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['zed'], { a: 1, b: 2 }), zedExpectationsSkipZed, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); await runTestcase( @@ -481,7 +481,7 @@ g.test('expectations,multi_case_none').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['zed'], { a: 1, b: 3 }), zedExpectationsSkipZed, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); }); @@ -505,7 +505,7 @@ g.test('expectations,multi_test').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['wye'], {}), expectationsSkipAllInBaz, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); await runTestcase( @@ -516,7 +516,7 @@ g.test('expectations,multi_test').fn(async t => { new TestQuerySingleCase('suite1', ['baz'], ['zed'], { a: 1, b: 2 }), expectationsSkipAllInBaz, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); }); @@ -575,7 +575,7 @@ g.test('expectations,multi_file').fn(async t => { new TestQuerySingleCase('suite1', ['foo'], ['hello'], {}), expectationsSkipAll, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); await runTestcase( @@ -586,7 +586,7 @@ g.test('expectations,multi_file').fn(async t => { new TestQuerySingleCase('suite1', ['bar', 'buzz', 'buzz'], ['zap'], {}), expectationsSkipAll, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); }); @@ -610,7 +610,7 @@ g.test('expectations,catches_failure').fn(async t => { new TestQuerySingleCase('suite2', ['foof'], ['blah'], {}), expectedFailures, 'pass', - logs => objectEquals(logs, ['"DEBUG: OK"']) + logs => objectEquals(logs, ['" DEBUG: OK"']) ); // Status is passed, but failure is logged. @@ -622,7 +622,7 @@ g.test('expectations,catches_failure').fn(async t => { new TestQuerySingleCase('suite2', ['foof'], ['bluh', 'a'], {}), expectedFailures, 'pass', - logs => logs.length === 1 && logs[0].startsWith('"EXPECTATION FAILED: goodbye\\n') + logs => logs.length === 2 && logs[1].startsWith('"☆ EXPECTATION FAILED: goodbye\\n') ); }); @@ -649,7 +649,7 @@ g.test('expectations,skip_dominates_failure').fn(async t => { new TestQuerySingleCase('suite2', ['foof'], ['bluh', 'a'], {}), expectedFailures, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); }); @@ -676,7 +676,7 @@ g.test('expectations,skip_inside_failure').fn(async t => { new TestQuerySingleCase('suite2', ['foof'], ['blah'], {}), expectedFailures, 'skip', - logs => logs.length === 1 && logs[0].startsWith('"SKIP: Skipped by expectations"') + logs => logs.length === 1 && logs[0].startsWith('" SKIP: Skipped by expectations"') ); await runTestcase( @@ -687,7 +687,10 @@ g.test('expectations,skip_inside_failure').fn(async t => { new TestQuerySingleCase('suite2', ['foof'], ['bluh', 'a'], {}), expectedFailures, 'pass', - logs => logs.length === 1 && logs[0].startsWith('"EXPECTATION FAILED: goodbye\\n') + logs => + logs.length === 2 && + logs[0] === '" SUMMARY: highest severity is ☆ ExpectFailed"' && + logs[1].startsWith('"☆ EXPECTATION FAILED: goodbye\\n') ); }); diff --git a/src/unittests/logger.spec.ts b/src/unittests/logger.spec.ts index abc27e28767a..cb3887ff1e8c 100644 --- a/src/unittests/logger.spec.ts +++ b/src/unittests/logger.spec.ts @@ -149,8 +149,8 @@ g.test('fail,threw').fn(t => { g.test('debug') .paramsSimple([ - { debug: true, _logsCount: 5 }, // - { debug: false, _logsCount: 3 }, + { debug: true, _logsCount: 6 }, // + { debug: false, _logsCount: 4 }, ]) .fn(t => { const { debug, _logsCount } = t.params;