Implement t.log() (#1452)

There are times when you wish to include comments in your tests that will be shown in the context of the test result, and not streamed to `stdout` like `console.log` statements are.

Fixes #420.

Author: nowells

lib/assert.js

@@ -64,6 +64,7 @@ function wrapAssertions(callbacks) {
 	const pass = callbacks.pass;
 	const pending = callbacks.pending;
 	const fail = callbacks.fail;
+	const log = callbacks.log;
 
 	const noop = () => {};
 	const makeRethrow = reason => () => {
@@ -110,6 +111,10 @@ function wrapAssertions(callbacks) {
 			}
 		},
 
+		log(text) {
+			log(this, text);
+		},
+
 		deepEqual(actual, expected, message) {
 			const result = concordance.compare(actual, expected, concordanceOptions);
 			if (result.pass) {

lib/colors.js

@@ -2,6 +2,7 @@
 const chalk = require('chalk');
 
 module.exports = {
+	log: chalk.gray,
 	title: chalk.bold.white,
 	error: chalk.red,
 	skip: chalk.yellow,

lib/reporters/mini.js

@@ -5,6 +5,7 @@ const lastLineTracker = require('last-line-stream/tracker');
 const plur = require('plur');
 const spinners = require('cli-spinners');
 const chalk = require('chalk');
+const figures = require('figures');
 const cliTruncate = require('cli-truncate');
 const cross = require('figures').cross;
 const indentString = require('indent-string');
@@ -163,6 +164,21 @@ class MiniReporter {
 				}
 
 				status += '  ' + colors.title(test.title) + '\n';
+
+				if (test.logs) {
+					test.logs.forEach(log => {
+						const logLines = indentString(colors.log(log), 6);
+						const logLinesWithLeadingFigure = logLines.replace(
+							/^ {6}/,
+							`    ${colors.information(figures.info)} `
+						);
+
+						status += logLinesWithLeadingFigure + '\n';
+					});
+
+					status += '\n';
+				}
+
 				if (test.error.source) {
 					status += '  ' + colors.errorSource(test.error.source.file + ':' + test.error.source.line) + '\n';
 

lib/reporters/tap.js

@@ -49,7 +49,7 @@ class TapReporter {
 		return 'TAP version 13';
 	}
 	test(test) {
-		let output;
+		const output = [];
 
 		let directive = '';
 		const passed = test.todo ? 'not ok' : 'ok';
@@ -62,17 +62,29 @@ class TapReporter {
 
 		const title = stripAnsi(test.title);
 
+		const appendLogs = () => {
+			if (test.logs) {
+				test.logs.forEach(log => {
+					const logLines = indentString(log, 4);
+					const logLinesWithLeadingFigure = logLines.replace(
+						/^ {4}/,
+						'  * '
+					);
+
+					output.push(logLinesWithLeadingFigure);
+				});
+			}
+		};
+
+		output.push(`# ${title}`);
+
 		if (test.error) {
-			output = [
-				'# ' + title,
-				format('not ok %d - %s', ++this.i, title),
-				dumpError(test.error, true)
-			];
+			output.push(format('not ok %d - %s', ++this.i, title));
+			appendLogs();
+			output.push(dumpError(test.error, true));
 		} else {
-			output = [
-				`# ${title}`,
-				format('%s %d - %s %s', passed, ++this.i, title, directive).trim()
-			];
+			output.push(format('%s %d - %s %s', passed, ++this.i, title, directive).trim());
+			appendLogs();
 		}
 
 		return output.join('\n');

lib/reporters/verbose.js

@@ -24,29 +24,38 @@ class VerboseReporter {
 		return '';
 	}
 	test(test, runStatus) {
+		const lines = [];
 		if (test.error) {
-			return '  ' + colors.error(figures.cross) + ' ' + test.title + ' ' + colors.error(test.error.message);
-		}
-
-		if (test.todo) {
-			return '  ' + colors.todo('- ' + test.title);
+			lines.push('  ' + colors.error(figures.cross) + ' ' + test.title + ' ' + colors.error(test.error.message));
+		} else if (test.todo) {
+			lines.push('  ' + colors.todo('- ' + test.title));
 		} else if (test.skip) {
-			return '  ' + colors.skip('- ' + test.title);
-		}
+			lines.push('  ' + colors.skip('- ' + test.title));
+		} else if (test.failing) {
+			lines.push('  ' + colors.error(figures.tick) + ' ' + colors.error(test.title));
+		} else if (runStatus.fileCount === 1 && runStatus.testCount === 1 && test.title === '[anonymous]') {
+			// No output
+		} else {
+			// Display duration only over a threshold
+			const threshold = 100;
+			const duration = test.duration > threshold ? colors.duration(' (' + prettyMs(test.duration) + ')') : '';
 
-		if (test.failing) {
-			return '  ' + colors.error(figures.tick) + ' ' + colors.error(test.title);
+			lines.push('  ' + colors.pass(figures.tick) + ' ' + test.title + duration);
 		}
 
-		if (runStatus.fileCount === 1 && runStatus.testCount === 1 && test.title === '[anonymous]') {
-			return undefined;
-		}
+		if (test.logs) {
+			test.logs.forEach(log => {
+				const logLines = indentString(colors.log(log), 6);
+				const logLinesWithLeadingFigure = logLines.replace(
+					/^ {6}/,
+					`    ${colors.information(figures.info)} `
+				);
 
-		// Display duration only over a threshold
-		const threshold = 100;
-		const duration = test.duration > threshold ? colors.duration(' (' + prettyMs(test.duration) + ')') : '';
+				lines.push(logLinesWithLeadingFigure);
+			});
+		}
 
-		return '  ' + colors.pass(figures.tick) + ' ' + test.title + duration;
+		return lines.length > 0 ? lines.join('\n') : undefined;
 	}
 	unhandledError(err) {
 		if (err.type === 'exception' && err.name === 'AvaError') {
@@ -104,6 +113,21 @@ class VerboseReporter {
 				}
 
 				output += '  ' + colors.title(test.title) + '\n';
+
+				if (test.logs) {
+					test.logs.forEach(log => {
+						const logLines = indentString(colors.log(log), 6);
+						const logLinesWithLeadingFigure = logLines.replace(
+							/^ {6}/,
+							`    ${colors.information(figures.info)} `
+						);
+
+						output += logLinesWithLeadingFigure + '\n';
+					});
+
+					output += '\n';
+				}
+
 				if (test.error.source) {
 					output += '  ' + colors.errorSource(test.error.source.file + ':' + test.error.source.line) + '\n';
 

lib/runner.js

@@ -130,6 +130,7 @@ class Runner extends EventEmitter {
 	addTestResult(result) {
 		const test = result.result;
 		const props = {
+			logs: test.logs,
 			duration: test.duration,
 			title: test.title,
 			error: result.reason,

lib/test.js

@@ -78,6 +78,10 @@ class ExecutionContext {
 
 {
 	const assertions = assert.wrapAssertions({
+		log(executionContext, text) {
+			executionContext._test.addLog(text);
+		},
+
 		pass(executionContext) {
 			executionContext._test.countPassedAssertion();
 		},
@@ -108,6 +112,7 @@ class Test {
 		this.metadata = options.metadata;
 		this.onResult = options.onResult;
 		this.title = options.title;
+		this.logs = [];
 
 		this.snapshotInvocationCount = 0;
 		this.compareWithSnapshot = assertionOptions => {
@@ -175,6 +180,10 @@ class Test {
 		this.assertCount++;
 	}
 
+	addLog(text) {
+		this.logs.push(text);
+	}
+
 	addPendingAssertion(promise) {
 		if (this.finishing) {
 			this.saveFirstError(new Error('Assertion passed, but test has already finished'));

readme.md

@@ -875,6 +875,10 @@ Plan how many assertion there are in the test. The test will fail if the actual
 
 End the test. Only works with `test.cb()`.
 
+###### `t.log(message)`
+
+Print a log message contextually alongside the test result instead of immediately printing it to `stdout` like `console.log`.
+
 ## Assertions
 
 Assertions are mixed into the [execution object](#t) provided to each test implementation:

test/reporters/mini.js

@@ -2,6 +2,7 @@
 const indentString = require('indent-string');
 const tempWrite = require('temp-write');
 const flatten = require('arr-flatten');
+const figures = require('figures');
 const chalk = require('chalk');
 const sinon = require('sinon');
 const test = require('tap').test;
@@ -934,3 +935,56 @@ test('result when no-color flag is set', t => {
 	t.is(output, expectedOutput);
 	t.end();
 });
+
+test('results with errors and logs', t => {
+	const err1 = new Error('failure one');
+	err1.stack = beautifyStack(err1.stack);
+	const err1Path = tempWrite.sync('a();');
+	err1.source = source(err1Path);
+	err1.avaAssertionError = true;
+	err1.statements = [];
+	err1.values = [
+		{label: 'actual:', formatted: JSON.stringify('abc') + '\n'},
+		{label: 'expected:', formatted: JSON.stringify('abd') + '\n'}
+	];
+
+	const reporter = miniReporter();
+	reporter.failCount = 1;
+
+	const runStatus = {
+		errors: [{
+			title: 'failed one',
+			logs: ['log from a failed test\nwith a newline', 'another log from failed test'],
+			error: err1
+		}]
+	};
+
+	const output = reporter.finish(runStatus);
+	compareLineOutput(t, output, flatten([
+		'',
+		'  ' + chalk.red('1 failed'),
+		'',
+		'  ' + chalk.bold.white('failed one'),
+		'    ' + chalk.magenta(figures.info) + ' ' + chalk.gray('log from a failed test'),
+		'      ' + chalk.gray('with a newline'),
+		'    ' + chalk.magenta(figures.info) + ' ' + chalk.gray('another log from failed test'),
+		'',
+		'  ' + chalk.grey(`${err1.source.file}:${err1.source.line}`),
+		'',
+		indentString(codeExcerpt(err1.source), 2).split('\n'),
+		'',
+		/failure one/,
+		'',
+		'  actual:',
+		'',
+		'  "abc"',
+		'',
+		'  expected:',
+		'',
+		'  "abd"',
+		'',
+		stackLineRegex, compareLineOutput.SKIP_UNTIL_EMPTY_LINE,
+		''
+	]));
+	t.end();
+});

test/reporters/tap.js

@@ -266,3 +266,51 @@ test('stdout and stderr should call process.stderr.write', t => {
 	t.is(stub.callCount, 2);
 	t.end();
 });
+
+test('successful test with logs', t => {
+	const reporter = new TapReporter();
+
+	const actualOutput = reporter.test({
+		title: 'passing',
+		logs: ['log message 1\nwith a newline', 'log message 2']
+	});
+
+	const expectedOutput = [
+		'# passing',
+		'ok 1 - passing',
+		'  * log message 1',
+		'    with a newline',
+		'  * log message 2'
+	].join('\n');
+
+	t.is(actualOutput, expectedOutput);
+	t.end();
+});
+
+test('failing test with logs', t => {
+	const reporter = new TapReporter();
+
+	const actualOutput = reporter.test({
+		title: 'failing',
+		error: {
+			name: 'AssertionError',
+			message: 'false == true'
+		},
+		logs: ['log message 1\nwith a newline', 'log message 2']
+	});
+
+	const expectedOutput = [
+		'# failing',
+		'not ok 1 - failing',
+		'  * log message 1',
+		'    with a newline',
+		'  * log message 2',
+		'  ---',
+		'    name: AssertionError',
+		'    message: false == true',
+		'  ...'
+	].join('\n');
+
+	t.is(actualOutput, expectedOutput);
+	t.end();
+});