Print tests that were pending when a timeout occurs

In `--verbose` mode, print tests that were pending when a timeout occurs. See also #583.

api.js

@@ -74,7 +74,7 @@ class Api extends Emittery {
 					worker.exit();
 				}
 
-				runStatus.emitStateChange({type: 'timeout', period: timeout});
+				runStatus.emitStateChange({type: 'timeout', period: timeout, timedOutWorkerFiles});
 			}, timeout);
 		} else {
 			restartTimer = Object.assign(() => {}, {cancel() {}});
@@ -212,7 +212,6 @@ class Api extends Emittery {
 								worker.promise.then(() => { // eslint-disable-line max-nested-callbacks
 									pendingWorkers.delete(worker);
 								});
-
 								restartTimer();
 
 								return worker.promise;

lib/reporters/verbose.js

@@ -70,6 +70,7 @@ class VerboseReporter {
 		this.failures = [];
 		this.filesWithMissingAvaImports = new Set();
 		this.knownFailures = [];
+		this.runningTestFiles = new Map();
 		this.lastLineIsEmpty = false;
 		this.matching = false;
 		this.prefixTitle = (testFile, title) => title;
@@ -103,7 +104,7 @@ class VerboseReporter {
 
 		switch (evt.type) {
 			case 'declared-test':
-				// Ignore
+				this.addTestRunning(evt.testFile, evt.title);
 				break;
 			case 'hook-failed':
 				this.failures.push(evt);
@@ -135,17 +136,19 @@ class VerboseReporter {
 				this.stats = evt.stats;
 				break;
 			case 'test-failed':
+				this.removeTestRunning(evt.testFile, evt.title);
 				this.failures.push(evt);
 				this.writeTestSummary(evt);
 				break;
 			case 'test-passed':
+				this.removeTestRunning(evt.testFile, evt.title);
 				if (evt.knownFailing) {
 					this.knownFailures.push(evt);
 				}
 				this.writeTestSummary(evt);
 				break;
 			case 'timeout':
-				this.lineWriter.writeLine(colors.error(`${figures.cross} Exited because no new tests completed within the last ${evt.period}ms of inactivity`));
+				this.writeTimeoutSummary(evt);
 				break;
 			case 'uncaught-exception':
 				this.lineWriter.ensureEmptyLine();
@@ -245,6 +248,42 @@ class VerboseReporter {
 		}
 	}
 
+	addTestRunning(file, title) {
+		if (!this.runningTestFiles.has(file)) {
+			this.runningTestFiles.set(file, new Set());
+		}
+		this.runningTestFiles.get(file).add(title);
+	}
+
+	removeTestRunning(file, title) {
+		const byFile = this.runningTestFiles.get(file);
+		if (byFile) {
+			byFile.delete(title);
+		}
+	}
+
+	writeTimeoutSummary(evt) {
+		this.lineWriter.writeLine(colors.error(`\n${figures.cross} Exited because no new tests completed within the last ${evt.period}ms of inactivity`));
+		let wroteTrailingSeparator = false;
+
+		for (const timedOutFile of evt.timedOutWorkerFiles) {
+			const byFile = this.runningTestFiles.get(timedOutFile);
+			if (byFile) {
+				this.runningTestFiles.delete(timedOutFile);
+
+				if (!wroteTrailingSeparator) {
+					this.lineWriter.writeLine('');
+				}
+				this.lineWriter.writeLine(`${byFile.size} tests still running in ${timedOutFile}:\n`);
+				for (const title of byFile) {
+					this.lineWriter.writeLine(`${figures.circleDotted} ${this.prefixTitle(timedOutFile, title)}`);
+				}
+				this.lineWriter.writeLine('');
+				wroteTrailingSeparator = true;
+			}
+		}
+	}
+
 	writeLogs(evt) {
 		if (evt.logs) {
 			for (const log of evt.logs) {

test/fixture/report/timeoutinmultiplefiles/a.js

@@ -0,0 +1,12 @@
+import test from '../../../..';
+
+test('a passes', t => t.pass());
+
+test.cb('a slow', t => {
+	setTimeout(t.end, 5000);
+});
+test.cb('a slow two', t => {
+	setTimeout(t.end, 5000);
+});
+
+test('a passes two', t => t.pass());

test/fixture/report/timeoutinmultiplefiles/b.js

@@ -0,0 +1,15 @@
+import test from '../../../..';
+
+test('b passes', t => t.pass());
+
+test.cb('b slow', t => {
+	setTimeout(t.end, 5000);
+});
+test.cb('b slow two', t => {
+	setTimeout(t.end, 5000);
+});
+test.cb('b slow three', t => {
+	setTimeout(t.end, 5000);
+});
+
+test('b passes two', t => t.pass());

test/fixture/report/timeoutinmultiplefiles/package.json

@@ -0,0 +1 @@
+{}

test/fixture/report/timeoutinsinglefile/a.js

@@ -0,0 +1,12 @@
+import test from '../../../..';
+
+test('passes', t => t.pass());
+
+test.cb('slow', t => {
+	setTimeout(t.end, 5000);
+});
+test.cb('slow two', t => {
+	setTimeout(t.end, 5000);
+});
+
+test('passes two', t => t.pass());

test/fixture/report/timeoutinsinglefile/package.json

@@ -0,0 +1 @@
+{}

test/helper/fix-reporter-env.js

@@ -10,7 +10,7 @@ const fixColors = () => {
 
 module.exports = () => {
 	// Fix timestamps.
-	lolex.install({
+	const clock = lolex.install({
 		now: new Date(2014, 11, 19, 17, 19, 12, 200).getTime(),
 		toFake: [
 			'Date'
@@ -22,6 +22,12 @@ module.exports = () => {
 
 	fixColors();
 	require('../../lib/chalk').set({enabled: true, level: 3});
+
+	return {
+		restoreClock() {
+			clock.uninstall();
+		}
+	};
 };
 
 module.exports.onlyColors = fixColors;

test/helper/report.js

@@ -97,7 +97,7 @@ const run = (type, reporter) => {
 		babelConfig: {testOptions: {}},
 		resolveTestsFrom: projectDir,
 		projectDir,
-		timeout: undefined,
+		timeout: type.startsWith('timeout') ? '1000ms' : undefined,
 		concurrency: 1,
 		updateSnapshots: false,
 		snapshotDir: false,
@@ -139,6 +139,8 @@ exports.regular = reporter => run('regular', reporter);
 exports.failFast = reporter => run('failFast', reporter);
 exports.failFast2 = reporter => run('failFast2', reporter);
 exports.only = reporter => run('only', reporter);
+exports.timeoutInSingleFile = reporter => run('timeoutInSingleFile', reporter);
+exports.timeoutInMultipleFiles = reporter => run('timeoutInMultipleFiles', reporter);
 exports.watch = reporter => run('watch', reporter);
 exports.typescript = reporter => run('typescript', reporter);
 exports.edgeCases = reporter => run('edge-cases', reporter);

test/reporters/verbose.js

@@ -1,9 +1,9 @@
 'use strict';
 require('../helper/report').captureStdIOReliability();
-require('../helper/fix-reporter-env')();
 
 const path = require('path');
 const test = require('tap').test;
+const {restoreClock} = require('../helper/fix-reporter-env')();
 const TTYStream = require('../helper/tty-stream');
 const report = require('../helper/report');
 const VerboseReporter = require('../../lib/reporters/verbose');
@@ -38,3 +38,11 @@ test('verbose reporter - only run', run('only'));
 test('verbose reporter - watch mode run', run('watch'));
 test('verbose reporter - typescript', run('typescript', [report.sanitizers.lineEndings]));
 test('verbose reporter - edge cases', run('edgeCases'));
+
+test('verbose reporter - timeout', t => {
+	restoreClock();
+
+	t.test('single file run', run('timeoutInSingleFile'));
+	t.test('multiple files run', run('timeoutInMultipleFiles'));
+	t.end();
+});

test/reporters/verbose.timeoutinmultiplefiles.log

@@ -0,0 +1,33 @@
+
+---tty-stream-chunk-separator
+  ✔ a › a passes
+---tty-stream-chunk-separator
+  ✔ a › a passes two
+---tty-stream-chunk-separator
+  
+  ✖ Exited because no new tests completed within the last 1000ms of inactivity
+
+  2 tests still running in ~/test/fixture/report/timeoutinmultiplefiles/a.js:
+
+  ◌ a › a slow
+  ◌ a › a slow two
+
+---tty-stream-chunk-separator
+  ✔ b › b passes
+---tty-stream-chunk-separator
+  ✔ b › b passes two
+---tty-stream-chunk-separator
+  
+  ✖ Exited because no new tests completed within the last 1000ms of inactivity
+
+  3 tests still running in ~/test/fixture/report/timeoutinmultiplefiles/b.js:
+
+  ◌ b › b slow
+  ◌ b › b slow two
+  ◌ b › b slow three
+
+---tty-stream-chunk-separator
+
+  4 tests passed
+
+---tty-stream-chunk-separator

test/reporters/verbose.timeoutinsinglefile.log

@@ -0,0 +1,19 @@
+
+---tty-stream-chunk-separator
+  ✔ passes
+---tty-stream-chunk-separator
+  ✔ passes two
+---tty-stream-chunk-separator
+  
+  ✖ Exited because no new tests completed within the last 1000ms of inactivity
+
+  2 tests still running in ~/test/fixture/report/timeoutinsinglefile/a.js:
+
+  ◌ slow
+  ◌ slow two
+
+---tty-stream-chunk-separator
+
+  2 tests passed
+
+---tty-stream-chunk-separator