Improve watch logging (#737)

* display current time when mini & verbose reporters finish

I'm using toLocaleTimeString() which works even back to Node.js 0.10. Forcing a
24-hour clock because we're geeks.

* watcher: restart logger on subsequent runs

The CLI starts the logger so the watcher shouldn't reset it on its first run.
Restart the logger after resetting, this allows the mini reporter to render its
spinner.

* better api.run stub in watcher test

Return an object for the runStatus, add assertions to verify this object is
passed to logger.finish()

* assert that r/rs reruns all tests

* clear mini reporter in watch mode

Clear the mini reporter unless the previous run had failures, or "r\n" was
entered on stdin.

* consistent empty lines in finish output

Always print two empty lines before each error/rejection/exception when the mini
and verbose reporters finish. Remove trailing whitespace from stack traces.
Always print an empty line after the finish output.

Add a test helper to more easily compare line output, with useful debug
information. At the moment this new helper is only used for failing tests.

* print line if reporter was not be cleared

Watch mode won't clear the mini reporter if there were errors, or "r\n" was
entered on stdin. The verbose reporter can't be cleared at all. To improve the
separation between multiple test runs, write a horizontal line when starting a
new test run and the reporter was not cleared.

* remove debug output from cli test

Author: novemberborn

lib/logger.js

@@ -50,6 +50,23 @@ Logger.prototype.finish = function (runStatus) {
 	this.write(this.reporter.finish(runStatus), runStatus);
 };
 
+Logger.prototype.section = function () {
+	if (!this.reporter.section) {
+		return;
+	}
+
+	this.write(this.reporter.section());
+};
+
+Logger.prototype.clear = function () {
+	if (!this.reporter.clear) {
+		return false;
+	}
+
+	this.write(this.reporter.clear());
+	return true;
+};
+
 Logger.prototype.write = function (str, runStatus) {
 	if (typeof str === 'undefined') {
 		return;

lib/reporters/mini.js

@@ -7,6 +7,7 @@ var spinners = require('cli-spinners');
 var chalk = require('chalk');
 var cliTruncate = require('cli-truncate');
 var cross = require('figures').cross;
+var repeating = require('repeating');
 var colors = require('../colors');
 
 chalk.enabled = true;
@@ -113,32 +114,26 @@ MiniReporter.prototype.unhandledError = function (err) {
 	}
 };
 
-MiniReporter.prototype.reportCounts = function () {
-	var status = '';
+MiniReporter.prototype.reportCounts = function (time) {
+	var lines = [
+		this.passCount > 0 ? '\n   ' + colors.pass(this.passCount, 'passed') : '',
+		this.failCount > 0 ? '\n   ' + colors.error(this.failCount, 'failed') : '',
+		this.skipCount > 0 ? '\n   ' + colors.skip(this.skipCount, 'skipped') : '',
+		this.todoCount > 0 ? '\n   ' + colors.todo(this.todoCount, 'todo') : ''
+	].filter(Boolean);
 
-	if (this.passCount > 0) {
-		status += '\n   ' + colors.pass(this.passCount, 'passed');
+	if (time && lines.length > 0) {
+		lines[0] += ' ' + time;
 	}
 
-	if (this.failCount > 0) {
-		status += '\n   ' + colors.error(this.failCount, 'failed');
-	}
-
-	if (this.skipCount > 0) {
-		status += '\n   ' + colors.skip(this.skipCount, 'skipped');
-	}
-
-	if (this.todoCount > 0) {
-		status += '\n   ' + colors.todo(this.todoCount, 'todo');
-	}
-
-	return status;
+	return lines.join('');
 };
 
 MiniReporter.prototype.finish = function (runStatus) {
 	this.clearInterval();
 
-	var status = this.reportCounts();
+	var time = chalk.gray.dim('[' + new Date().toLocaleTimeString('en-US', {hour12: false}) + ']');
+	var status = this.reportCounts(time);
 
 	if (this.rejectionCount > 0) {
 		status += '\n   ' + colors.error(this.rejectionCount, plur('rejection', this.rejectionCount));
@@ -162,12 +157,12 @@ MiniReporter.prototype.finish = function (runStatus) {
 			var description;
 
 			if (test.error) {
-				description = '  ' + test.error.message + '\n  ' + stripFirstLine(test.error.stack);
+				description = '   ' + test.error.message + '\n  ' + stripFirstLine(test.error.stack).trimRight();
 			} else {
 				description = JSON.stringify(test);
 			}
 
-			status += '\n\n  ' + colors.error(i + '.', title) + '\n';
+			status += '\n\n\n   ' + colors.error(i + '.', title) + '\n';
 			status += colors.stack(description);
 		});
 	}
@@ -181,22 +176,26 @@ MiniReporter.prototype.finish = function (runStatus) {
 			i++;
 
 			if (err.type === 'exception' && err.name === 'AvaError') {
-				status += '\n\n  ' + colors.error(cross + ' ' + err.message) + '\n';
+				status += '\n\n\n   ' + colors.error(cross + ' ' + err.message);
 			} else {
 				var title = err.type === 'rejection' ? 'Unhandled Rejection' : 'Uncaught Exception';
-				var description = err.stack ? err.stack : JSON.stringify(err);
+				var description = err.stack ? err.stack.trimRight() : JSON.stringify(err);
 
-				status += '\n\n  ' + colors.error(i + '.', title) + '\n';
-				status += '  ' + colors.stack(description);
+				status += '\n\n\n   ' + colors.error(i + '.', title) + '\n';
+				status += '   ' + colors.stack(description);
 			}
 		});
 	}
 
-	if (this.failCount === 0 && this.rejectionCount === 0 && this.exceptionCount === 0) {
-		status += '\n';
-	}
+	return status + '\n';
+};
+
+MiniReporter.prototype.section = function () {
+	return '\n' + chalk.gray.dim(repeating('\u2500', process.stdout.columns || 80));
+};
 
-	return status;
+MiniReporter.prototype.clear = function () {
+	return '';
 };
 
 MiniReporter.prototype.write = function (str) {

lib/reporters/verbose.js

@@ -1,7 +1,9 @@
 'use strict';
 var prettyMs = require('pretty-ms');
 var figures = require('figures');
+var chalk = require('chalk');
 var plur = require('plur');
+var repeating = require('repeating');
 var colors = require('../colors');
 
 Object.keys(colors).forEach(function (key) {
@@ -68,31 +70,22 @@ VerboseReporter.prototype.unhandledError = function (err) {
 VerboseReporter.prototype.finish = function (runStatus) {
 	var output = '\n';
 
-	if (runStatus.failCount > 0) {
-		output += '  ' + colors.error(runStatus.failCount, plur('test', runStatus.failCount), 'failed') + '\n';
-	} else {
-		output += '  ' + colors.pass(runStatus.passCount, plur('test', runStatus.passCount), 'passed') + '\n';
-	}
-
-	if (runStatus.skipCount > 0) {
-		output += '  ' + colors.skip(runStatus.skipCount, plur('test', runStatus.skipCount), 'skipped') + '\n';
-	}
-
-	if (runStatus.todoCount > 0) {
-		output += '  ' + colors.todo(runStatus.todoCount, plur('test', runStatus.todoCount), 'todo') + '\n';
-	}
-
-	if (runStatus.rejectionCount > 0) {
-		output += '  ' + colors.error(runStatus.rejectionCount, 'unhandled', plur('rejection', runStatus.rejectionCount)) + '\n';
-	}
-
-	if (runStatus.exceptionCount > 0) {
-		output += '  ' + colors.error(runStatus.exceptionCount, 'uncaught', plur('exception', runStatus.exceptionCount)) + '\n';
+	var lines = [
+		runStatus.failCount > 0 ?
+			'  ' + colors.error(runStatus.failCount, plur('test', runStatus.failCount), 'failed') :
+			'  ' + colors.pass(runStatus.passCount, plur('test', runStatus.passCount), 'passed'),
+		runStatus.skipCount > 0 ? '  ' + colors.skip(runStatus.skipCount, plur('test', runStatus.skipCount), 'skipped') : '',
+		runStatus.todoCount > 0 ? '  ' + colors.todo(runStatus.todoCount, plur('test', runStatus.todoCount), 'todo') : '',
+		runStatus.rejectionCount > 0 ? '  ' + colors.error(runStatus.rejectionCount, 'unhandled', plur('rejection', runStatus.rejectionCount)) : '',
+		runStatus.exceptionCount > 0 ? '  ' + colors.error(runStatus.exceptionCount, 'uncaught', plur('exception', runStatus.exceptionCount)) : ''
+	].filter(Boolean);
+
+	if (lines.length > 0) {
+		lines[0] += ' ' + chalk.gray.dim('[' + new Date().toLocaleTimeString('en-US', {hour12: false}) + ']');
+		output += lines.join('\n');
 	}
 
 	if (runStatus.failCount > 0) {
-		output += '\n';
-
 		var i = 0;
 
 		runStatus.tests.forEach(function (test) {
@@ -102,12 +95,17 @@ VerboseReporter.prototype.finish = function (runStatus) {
 
 			i++;
 
-			output += '  ' + colors.error(i + '.', test.title) + '\n';
-			output += '  ' + colors.stack(test.error.stack) + '\n';
+			output += '\n\n\n  ' + colors.error(i + '.', test.title) + '\n';
+			var stack = test.error.stack ? test.error.stack.trimRight() : '';
+			output += '  ' + colors.stack(stack);
 		});
 	}
 
-	return output;
+	return output + '\n';
+};
+
+VerboseReporter.prototype.section = function () {
+	return chalk.gray.dim(repeating('\u2500', process.stdout.columns || 80));
 };
 
 VerboseReporter.prototype.write = function (str) {

lib/watcher.js

@@ -43,8 +43,23 @@ function Watcher(logger, api, files, sources) {
 	this.debouncer = new Debouncer(this);
 
 	this.isTest = makeTestMatcher(files, AvaFiles.defaultExcludePatterns());
+
+	var isFirstRun = true;
+	this.clearLogOnNextRun = true;
 	this.run = function (specificFiles) {
-		logger.reset();
+		if (isFirstRun) {
+			isFirstRun = false;
+		} else {
+			var cleared = this.clearLogOnNextRun && logger.clear();
+			if (!cleared) {
+				logger.reset();
+				logger.section();
+			}
+			this.clearLogOnNextRun = true;
+
+			logger.reset();
+			logger.start();
+		}
 
 		var runOnlyExclusive = false;
 
@@ -63,10 +78,12 @@ function Watcher(logger, api, files, sources) {
 			}
 		}
 
+		var self = this;
 		this.busy = api.run(specificFiles || files, {
 			runOnlyExclusive: runOnlyExclusive
 		}).then(function (runStatus) {
 			logger.finish(runStatus);
+			self.clearLogOnNextRun = self.clearLogOnNextRun && runStatus.failCount === 0;
 		}, rethrowAsync);
 	};
 
@@ -182,6 +199,7 @@ Watcher.prototype.observeStdin = function (stdin) {
 			// Cancel the debouncer again, it might have restarted while waiting for
 			// the busy promise to fulfil.
 			self.debouncer.cancel();
+			self.clearLogOnNextRun = false;
 			self.rerunAll();
 		});
 	});

package.json

@@ -129,6 +129,7 @@
     "power-assert-formatter": "^1.3.0",
     "power-assert-renderers": "^0.1.0",
     "pretty-ms": "^2.0.0",
+    "repeating": "^2.0.0",
     "require-precompiled": "^0.1.0",
     "resolve-cwd": "^1.0.0",
     "set-immediate-shim": "^1.0.1",

test/cli.js

@@ -235,7 +235,7 @@ if (hasChokidar) {
 			t.is(err.code, 1);
 			t.match(stderr, 'The TAP reporter is not available when using watch mode.');
 			t.end();
-		}).stderr.pipe(process.stderr);
+		});
 	});
 
 	['--watch', '-w'].forEach(function (watchFlag) {
@@ -245,7 +245,7 @@ if (hasChokidar) {
 					t.is(err.code, 1);
 					t.match(stderr, 'The TAP reporter is not available when using watch mode.');
 					t.end();
-				}).stderr.pipe(process.stderr);
+				});
 			});
 		});
 	});

test/helper/compare-line-output.js

@@ -0,0 +1,27 @@
+'use strict';
+var SKIP_UNTIL_EMPTY_LINE = {};
+
+function compareLineOutput(t, actual, lineExpectations) {
+	var actualLines = actual.split('\n');
+
+	var expectationIndex = 0;
+	var lineIndex = 0;
+	while (lineIndex < actualLines.length && expectationIndex < lineExpectations.length) {
+		var line = actualLines[lineIndex++];
+		var expected = lineExpectations[expectationIndex++];
+		if (expected === SKIP_UNTIL_EMPTY_LINE) {
+			lineIndex = actualLines.indexOf('', lineIndex);
+			continue;
+		}
+
+		if (typeof expected === 'string') {
+			// Assertion titles use 1-based line indexes
+			t.is(line, expected, 'line ' + lineIndex + ' ≪' + line + '≫ is ≪' + expected + '≫');
+		} else {
+			t.match(line, expected, 'line ' + lineIndex + ' ≪' + line + '≫ matches ' + expected);
+		}
+	}
+}
+
+module.exports = compareLineOutput;
+compareLineOutput.SKIP_UNTIL_EMPTY_LINE = SKIP_UNTIL_EMPTY_LINE;

test/logger.js

@@ -45,6 +45,56 @@ test('only write if reset is supported by reporter', function (t) {
 	t.end();
 });
 
+test('only call section if supported by reporter', function (t) {
+	var tapReporter = tap();
+	var logger = new Logger(tapReporter);
+	tapReporter.section = undefined;
+	logger.section();
+	t.end();
+});
+
+test('only write if section is supported by reporter', function (t) {
+	var tapReporter = tap();
+	var logger = new Logger(tapReporter);
+	tapReporter.section = undefined;
+	logger.write = t.fail;
+	logger.section();
+	t.end();
+});
+
+test('only call clear if supported by reporter', function (t) {
+	var tapReporter = tap();
+	var logger = new Logger(tapReporter);
+	tapReporter.clear = undefined;
+	logger.clear();
+	t.end();
+});
+
+test('only write if clear is supported by reporter', function (t) {
+	var tapReporter = tap();
+	var logger = new Logger(tapReporter);
+	tapReporter.clear = undefined;
+	logger.write = t.fail;
+	logger.clear();
+	t.end();
+});
+
+test('return false if clear is not supported by reporter', function (t) {
+	var tapReporter = tap();
+	var logger = new Logger(tapReporter);
+	tapReporter.clear = undefined;
+	t.false(logger.clear());
+	t.end();
+});
+
+test('return true if clear is supported by reporter', function (t) {
+	var tapReporter = tap();
+	var logger = new Logger(tapReporter);
+	tapReporter.clear = function () {};
+	t.true(logger.clear());
+	t.end();
+});
+
 test('writes the reporter reset result', function (t) {
 	var tapReporter = tap();
 	var logger = new Logger(tapReporter);