[Fix] Blocking tests exceeding the test timeout fail

Change the `timeoutAfter` handler to _also_ fail if a blocking test's
runtime duration exceeds the timeout. Use a boolean flag `timedOut` to
avoid double failures in the event of a race condition.

Test the new functionality with both the `timeout` option and the
`timeoutAfter` assertion.

Author: ericcornelissen

lib/test.js

@@ -189,13 +189,25 @@ Test.prototype.plan = function plan(n) {
 Test.prototype.timeoutAfter = function timeoutAfter(ms) {
 	if (!ms) { throw new Error('timeoutAfter requires a timespan'); }
 	var self = this;
+	var startTime = Date.now();
+	var timedOut = false;
 	var timeout = safeSetTimeout(function () {
+		if (timedOut) { return; }
+		timedOut = true;
 		self.fail(self.name + ' timed out after ' + ms + 'ms');
 		self.end();
 	}, ms);
 	this.once('end', function () {
 		safeClearTimeout(timeout);
 	});
+	this.once('end', function () {
+		if (timedOut) { return; }
+		timedOut = true;
+		var duration = Date.now() - startTime;
+		if (duration > ms) {
+			self.fail(self.name + ' timed out after ' + duration + 'ms');
+		}
+	});
 };
 
 Test.prototype.end = function end(err) {

test/timeout.js

@@ -1,17 +1,65 @@
 'use strict';
 
-var test = require('../');
+var tape = require('../');
+var tap = require('tap');
+var concat = require('concat-stream');
+
+var stripFullStack = require('./common').stripFullStack;
+
 var ran = 0;
 
-test('timeout', function (t) {
-	t.pass('this should run');
-	ran++;
-	setTimeout(function () {
+tap.test('timeout with multiple tests', function (tt) {
+	tt.plan(0);
+
+	var test = tape.createHarness();
+
+	test('timeout', function (t) {
+		t.pass('this should run');
+		ran++;
+		setTimeout(function () {
+			t.end();
+		}, 100);
+	});
+
+	test('should still run', { timeout: 50 }, function (t) {
+		t.equal(ran, 1);
 		t.end();
-	}, 100);
+	});
 });
 
-test('should still run', { timeout: 50 }, function (t) {
-	t.equal(ran, 1);
-	t.end();
+tap.test('timeout with blocking', function (tt) {
+	tt.plan(1);
+
+	var test = tape.createHarness();
+
+	test.createStream().pipe(concat({ encoding: 'string' }, function (rows) {
+		tt.same(stripFullStack(rows), [
+			'TAP version 13',
+			'# timeout',
+			'not ok 1 timeout timed out after 2ms',
+			'  ---',
+			'    operator: fail',
+			'    at: Test.<anonymous> ($TEST/timeout.js:$LINE:$COL)',
+			'    stack: |-',
+			'      Error: timeout timed out after 2ms',
+			'          [... stack stripped ...]',
+			'          at Test.<anonymous> ($TEST/timeout.js:$LINE:$COL)',
+			'          [... stack stripped ...]',
+			'  ...',
+			'',
+			'1..1',
+			'# tests 1',
+			'# pass  0',
+			'# fail  1',
+			''
+		]);
+	}));
+
+	test('timeout', { timeout: 1 }, function (t) {
+		var start = Date.now();
+		while (Date.now() < start + 2) {
+			// Busy-wait to block the event loop
+		}
+		t.end();
+	});
 });

test/timeoutAfter.js

@@ -97,3 +97,41 @@ tap.test('timeoutAfter with Promises', { skip: typeof Promise === 'undefined' },
 		});
 	});
 });
+
+tap.test('timeoutAfter with blocking', function (tt) {
+	tt.plan(1);
+
+	var test = tape.createHarness();
+
+	test.createStream().pipe(concat({ encoding: 'string' }, function (rows) {
+		tt.same(stripFullStack(rows), [
+			'TAP version 13',
+			'# timeoutAfter',
+			'not ok 1 timeoutAfter timed out after 2ms',
+			'  ---',
+			'    operator: fail',
+			'    at: Test.<anonymous> ($TEST/timeoutAfter.js:$LINE:$COL)',
+			'    stack: |-',
+			'      Error: timeoutAfter timed out after 2ms',
+			'          [... stack stripped ...]',
+			'          at Test.<anonymous> ($TEST/timeoutAfter.js:$LINE:$COL)',
+			'          [... stack stripped ...]',
+			'  ...',
+			'',
+			'1..1',
+			'# tests 1',
+			'# pass  0',
+			'# fail  1',
+			''
+		]);
+	}));
+
+	test('timeoutAfter', function (t) {
+		t.timeoutAfter(1);
+		var start = Date.now();
+		while (Date.now() < start + 2) {
+			// Busy-wait to block the event loop
+		}
+		t.end();
+	});
+});