Prevent log corruption when using mini reporter. Fixes #392.

This prevents interference between the mini logger and child processes that use `console.log`. The mini reporter previously used logUpdate which deletes lines previously written with the logUpdate API before writing a new one. This caused problems if lines from console.log were written inbetween logUpdate calls. It would delete the users log messages instead of the test status line. To fix this, we store the last written last log line, clear it, write the users log output, then restore the last log line. This keeps the miniReporter output always at the bottom of the log output.

It also fixes an incorrect use of the `child_process` API. We were using the `stdio` option for `child_process.fork`, but that option is ignored (it is honored for just about every other method in that API). See: https://github.com/nodejs/node/blob/7b355c5bb30d7f9b38654fdb50e58dbd1dcd990a/lib/child_process.js#L49-L50

It also adds a set of visual tests which can be run via `npm run visual`. They must be run manually, and should be run as part of our pre-release process.

Author: jamestalmage

api.js

@@ -55,7 +55,13 @@ Api.prototype._runFile = function (file) {
 		.on('stats', this._handleStats)
 		.on('test', this._handleTest)
 		.on('unhandledRejections', this._handleRejections)
-		.on('uncaughtException', this._handleExceptions);
+		.on('uncaughtException', this._handleExceptions)
+		.on('stdout', this._handleOutput.bind(this, 'stdout'))
+		.on('stderr', this._handleOutput.bind(this, 'stderr'));
+};
+
+Api.prototype._handleOutput = function (channel, data) {
+	this.emit(channel, data);
 };
 
 Api.prototype._handleRejections = function (data) {

cli.js

@@ -104,6 +104,9 @@ logger.start();
 api.on('test', logger.test);
 api.on('error', logger.unhandledError);
 
+api.on('stdout', logger.stdout);
+api.on('stderr', logger.stderr);
+
 api.run()
 	.then(function () {
 		logger.finish();

lib/fork.js

@@ -8,12 +8,17 @@ var AvaError = require('./ava-error');
 var send = require('./send');
 
 module.exports = function (file, opts) {
-	opts = objectAssign({file: file}, opts);
+	opts = objectAssign({
+		file: file,
+		tty: process.stdout.isTTY ? {
+			columns: process.stdout.columns,
+			rows: process.stdout.rows
+		} : false
+	}, opts);
 
 	var ps = childProcess.fork(path.join(__dirname, 'test-worker.js'), [JSON.stringify(opts)], {
 		cwd: path.dirname(file),
-		stdio: ['ignore', process.stderr, process.stderr],
-		silent: opts.silent
+		silent: true
 	});
 
 	var relFile = path.relative('.', file);
@@ -77,6 +82,18 @@ module.exports = function (file, opts) {
 		send(ps, 'teardown');
 	});
 
+	ps.stdout.on('data', function (data) {
+		if (!opts.silent) {
+			ps.emit('stdout', data);
+		}
+	});
+
+	ps.stderr.on('data', function (data) {
+		if (!opts.silent) {
+			ps.emit('stderr', data);
+		}
+	});
+
 	promise.on = function () {
 		ps.on.apply(ps, arguments);
 

lib/logger.js

@@ -53,6 +53,22 @@ Logger.prototype.write = function (str) {
 	this.reporter.write(str);
 };
 
+Logger.prototype.stdout = function (data) {
+	if (!this.reporter.stdout) {
+		return;
+	}
+
+	this.reporter.stdout(data);
+};
+
+Logger.prototype.stderr = function (data) {
+	if (!this.reporter.stderr) {
+		return;
+	}
+
+	this.reporter.stderr(data);
+};
+
 Logger.prototype.exit = function (code) {
 	// TODO: figure out why this needs to be here to
 	// correctly flush the output when multiple test files

lib/reporters/mini.js

@@ -1,7 +1,9 @@
 'use strict';
-var logUpdate = require('log-update');
-var colors = require('../colors');
+var cliCursor = require('cli-cursor');
+var lastLineTracker = require('last-line-stream/tracker');
+var StringDecoder = require('string_decoder').StringDecoder;
 var plur = require('plur');
+var colors = require('../colors');
 var beautifyStack = require('../beautify-stack');
 
 function MiniReporter() {
@@ -14,7 +16,11 @@ function MiniReporter() {
 	this.skipCount = 0;
 	this.rejectionCount = 0;
 	this.exceptionCount = 0;
-	this.finished = false;
+	this.currentStatus = '';
+	this.statusLineCount = 0;
+	this.lastLineTracker = lastLineTracker();
+	this.stream = process.stderr;
+	this.stringDecoder = new StringDecoder();
 }
 
 module.exports = MiniReporter;
@@ -24,7 +30,7 @@ MiniReporter.prototype.start = function () {
 };
 
 MiniReporter.prototype.test = function (test) {
-	var status = '\n';
+	var status = '';
 	var title;
 
 	if (test.skip) {
@@ -61,9 +67,7 @@ MiniReporter.prototype.unhandledError = function (err) {
 };
 
 MiniReporter.prototype.finish = function () {
-	this.finished = true;
-
-	var status = '\n';
+	var status = '';
 
 	if (this.passCount > 0) {
 		status += '  ' + colors.pass(this.passCount, 'passed');
@@ -134,9 +138,76 @@ MiniReporter.prototype.finish = function () {
 };
 
 MiniReporter.prototype.write = function (str) {
-	logUpdate.stderr(str);
+	cliCursor.hide();
+	this.currentStatus = str + '\n';
+	this._update();
+	this.statusLineCount = this.currentStatus.split('\n').length;
+};
+
+MiniReporter.prototype.stdout = MiniReporter.prototype.stderr = function (data) {
+	this._update(data);
+};
+
+MiniReporter.prototype._update = function (data) {
+	var str = '';
+	var ct = this.statusLineCount;
+	var columns = process.stdout.columns;
+	var lastLine = this.lastLineTracker.lastLine();
+
+	// Terminals automatically wrap text. We only need the last log line as seen on the screen.
+	lastLine = lastLine.substring(lastLine.length - (lastLine.length % columns));
+
+	// Don't delete the last log line if it's completely empty.
+	if (lastLine.length) {
+		ct++;
+	}
+
+	// Erase the existing status message, plus the last log line.
+	str += eraseLines(ct);
+
+	// Rewrite the last log line.
+	str += lastLine;
 
-	if (this.finished) {
-		logUpdate.stderr.done();
+	if (str.length) {
+		this.stream.write(str);
+	}
+
+	if (data) {
+		// send new log data to the terminal, and update the last line status.
+		this.lastLineTracker.update(this.stringDecoder.write(data));
+		this.stream.write(data);
+	}
+
+	var currentStatus = this.currentStatus;
+	if (currentStatus.length) {
+		lastLine = this.lastLineTracker.lastLine();
+		// We need a newline at the end of the last log line, before the status message.
+		// However, if the last log line is the exact width of the terminal a newline is implied,
+		// and adding a second will cause problems.
+		if (lastLine.length % columns) {
+			currentStatus = '\n' + currentStatus;
+		}
+		// rewrite the status message.
+		this.stream.write(currentStatus);
 	}
 };
+
+// TODO(@jamestalamge): This should be fixed in log-update and ansi-escapes once we are confident it's a good solution.
+var CSI = '\u001b[';
+var ERASE_LINE = CSI + '2K';
+var CURSOR_TO_COLUMN_0 = CSI + '0G';
+var CURSOR_UP = CSI + '1A';
+
+// Returns a string that will erase `count` lines from the end of the terminal.
+function eraseLines(count) {
+	var clear = '';
+
+	for (var i = 0; i < count; i++) {
+		clear += ERASE_LINE + (i < count - 1 ? CURSOR_UP : '');
+	}
+	if (count) {
+		clear += CURSOR_TO_COLUMN_0;
+	}
+
+	return clear;
+}

lib/reporters/tap.js

@@ -78,3 +78,7 @@ TapReporter.prototype.finish = function () {
 TapReporter.prototype.write = function (str) {
 	console.log(str);
 };
+
+TapReporter.prototype.stdout = TapReporter.prototype.stderr = function (data) {
+	process.stderr.write(data);
+};

lib/reporters/verbose.js

@@ -100,3 +100,7 @@ VerboseReporter.prototype.finish = function () {
 VerboseReporter.prototype.write = function (str) {
 	console.error(str);
 };
+
+VerboseReporter.prototype.stdout = VerboseReporter.prototype.stderr = function (data) {
+	process.stderr.write(data);
+};

lib/test-worker.js

@@ -1,12 +1,27 @@
 'use strict';
+var opts = JSON.parse(process.argv[2]);
+var testPath = opts.file;
+
+// Fake TTY support
+if (opts.tty) {
+	process.stdout.isTTY = true;
+	process.stdout.columns = opts.tty.columns || 80;
+	process.stdout.rows = opts.tty.rows;
+	var tty = require('tty');
+	var isatty = tty.isatty;
+	tty.isatty = function (fd) {
+		if (fd === 1 || fd === process.stdout) {
+			return true;
+		}
+		return isatty(fd);
+	};
+}
+
 var path = require('path');
 var fs = require('fs');
 var debug = require('debug')('ava');
 var sourceMapSupport = require('source-map-support');
 
-var opts = JSON.parse(process.argv[2]);
-var testPath = opts.file;
-
 if (debug.enabled) {
 	// Forward the `time-require` `--sorted` flag.
 	// Intended for internal optimization tests only.

package.json

@@ -38,7 +38,8 @@
   },
   "scripts": {
     "test": "xo && nyc --cache --reporter=lcov --reporter=text tap --no-cov --timeout=150 test/*.js test/reporters/*.js",
-    "test-win": "tap --no-cov --reporter=classic --timeout=150 test/*.js test/reporters/*.js"
+    "test-win": "tap --no-cov --reporter=classic --timeout=150 test/*.js test/reporters/*.js",
+    "visual": "node test/visual/run-visual-tests.js"
   },
   "files": [
     "lib",
@@ -87,6 +88,7 @@
     "bluebird": "^3.0.0",
     "caching-transform": "^1.0.0",
     "chalk": "^1.0.0",
+    "cli-cursor": "^1.0.2",
     "co-with-promise": "^4.6.0",
     "commondir": "^1.0.1",
     "convert-source-map": "^1.1.2",
@@ -101,7 +103,7 @@
     "is-generator-fn": "^1.0.0",
     "is-observable": "^0.1.0",
     "is-promise": "^2.1.0",
-    "log-update": "^1.0.2",
+    "last-line-stream": "^1.0.0",
     "loud-rejection": "^1.2.0",
     "max-timeout": "^1.0.0",
     "md5-hex": "^1.2.0",
@@ -127,8 +129,10 @@
     "coveralls": "^2.11.4",
     "delay": "^1.3.0",
     "get-stream": "^1.1.0",
-    "rimraf": "^2.5.0",
+    "inquirer": "^0.11.1",
     "nyc": "^5.1.0",
+    "pify": "^2.3.0",
+    "rimraf": "^2.5.0",
     "signal-exit": "^2.1.2",
     "sinon": "^1.17.2",
     "source-map-fixtures": "^0.4.0",