Output logs for tests that remain pending when AVA exits

Author: kevo1ution

lib/reporters/default.js

@@ -370,8 +370,11 @@ export default class Reporter {
 			}
 
 			this.lineWriter.writeLine(`${testsInFile.size} tests were pending in ${this.relativeFile(file)}\n`);
+			const testTitleToLogs = evt.pendingTestsLogs.get(file);
 			for (const title of testsInFile) {
+				const logs = testTitleToLogs?.get(title);
 				this.lineWriter.writeLine(`${figures.circleDotted} ${this.prefixTitle(file, title)}`);
+				this.writeLogs({logs});
 			}
 
 			this.lineWriter.writeLine('');

lib/run-status.js

@@ -9,6 +9,7 @@ export default class RunStatus extends Emittery {
 		super();
 
 		this.pendingTests = new Map();
+		this.pendingTestsLogs = new Map();
 
 		this.emptyParallelRun = parallelRuns
 			&& parallelRuns.currentFileCount === 0
@@ -60,6 +61,7 @@ export default class RunStatus extends Emittery {
 		});
 
 		this.pendingTests.set(testFile, new Set());
+		this.pendingTestsLogs.set(testFile, new Map());
 		worker.onStateChange(data => this.emitStateChange(data));
 	}
 
@@ -124,22 +126,31 @@ export default class RunStatus extends Emittery {
 				fileStats.remainingTests--;
 				this.removePendingTest(event);
 				break;
+			case 'test-register-log-reference':
+				this.addPendingTestLogs(event);
+				break;
 			case 'timeout':
 				stats.timeouts++;
 				event.pendingTests = this.pendingTests;
+				event.pendingTestsLogs = this.pendingTestsLogs;
 				this.pendingTests = new Map();
+				this.pendingTestsLogs = new Map();
 				for (const testsInFile of event.pendingTests.values()) {
 					stats.timedOutTests += testsInFile.size;
 				}
 
 				break;
 			case 'interrupt':
 				event.pendingTests = this.pendingTests;
+				event.pendingTestsLogs = this.pendingTestsLogs;
 				this.pendingTests = new Map();
+				this.pendingTestsLogs = new Map();
 				break;
 			case 'process-exit':
 				event.pendingTests = this.pendingTests;
+				event.pendingTestsLogs = this.pendingTestsLogs;
 				this.pendingTests = new Map();
+				this.pendingTestsLogs = new Map();
 				break;
 			case 'uncaught-exception':
 				stats.uncaughtExceptions++;
@@ -198,6 +209,10 @@ export default class RunStatus extends Emittery {
 		return 0;
 	}
 
+	addPendingTestLogs(event) {
+		this.pendingTestsLogs.get(event.testFile)?.set(event.title, event.logs);
+	}
+
 	addPendingTest(event) {
 		if (this.pendingTests.has(event.testFile)) {
 			this.pendingTests.get(event.testFile).add(event.title);

lib/runner.js

@@ -358,6 +358,12 @@ export default class Runner extends Emittery {
 				notifyTimeoutUpdate: this.notifyTimeoutUpdate,
 			});
 
+			this.emit('stateChange', {
+				type: 'test-register-log-reference',
+				title: task.title,
+				logs: test.logs,
+			});
+
 			const result = await this.runSingle(test);
 			testOk = result.passed;
 

test-tap/fixture/long-running.cjs

@@ -3,6 +3,7 @@ const delay = require('delay');
 const test = require('../../entrypoints/main.cjs');
 
 test('slow', async t => {
+	t.log('helpful log of a pending test');
 	await delay(5000);
 	t.pass();
 });

test-tap/fixture/report/timeoutcontextlogs/a.cjs

@@ -0,0 +1,20 @@
+const delay = require('delay');
+
+const test = require('../../../../entrypoints/main.cjs');
+
+test('a passes', t => t.pass());
+
+test('a slow', async t => {
+	t.log('this slow test prints useful debug message just text');
+	await delay(15_000);
+	t.log('this never logs because test times out');
+	t.pass();
+});
+test('a slow two', async t => {
+	t.log('another useful debug message', {x: 5});
+	await delay(15_000);
+	t.log('this never logs because test times out');
+	t.pass();
+});
+
+test('a passes two', t => t.pass());

test-tap/fixture/report/timeoutcontextlogs/b.cjs

@@ -0,0 +1,19 @@
+const delay = require('delay');
+
+const test = require('../../../../entrypoints/main.cjs');
+
+test('a passes', t => t.pass());
+
+test('a slow', async t => {
+	t.log('hello world');
+	await delay(15_000);
+	t.log('this never prints due to test time out');
+	t.pass();
+});
+test('a slow two', async t => {
+	await delay(15_000);
+	t.log('this never prints due to test time out');
+	t.pass();
+});
+
+test('a passes two', t => t.pass());

test-tap/fixture/report/timeoutcontextlogs/package.json

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

test-tap/helper/report.js

@@ -126,6 +126,7 @@ exports.only = reporter => run('only', reporter);
 exports.timeoutInSingleFile = reporter => run('timeoutInSingleFile', reporter);
 exports.timeoutInMultipleFiles = reporter => run('timeoutInMultipleFiles', reporter);
 exports.timeoutWithMatch = reporter => run('timeoutWithMatch', reporter, {match: ['*needle*']});
+exports.timeoutContextLogs = reporter => run('timeoutContextLogs', reporter);
 exports.watch = reporter => run('watch', reporter);
 exports.edgeCases = reporter => run('edgeCases', reporter, {
 	filter: [

test-tap/integration/assorted.js

@@ -14,13 +14,15 @@ const __dirname = fileURLToPath(new URL('.', import.meta.url));
 test('timeout', {skip: ciInfo.isCI}, t => {
 	execCli(['long-running.cjs', '-T', '1s'], (error, stdout) => {
 		t.ok(error);
+		t.match(stdout, 'helpful log of a pending test');
 		t.match(stdout, /Timed out/);
 		t.end();
 	});
 });
 
 test('interrupt', {skip: ciInfo.isCI}, t => {
 	const proc = execCli(['long-running.cjs'], (_, stdout) => {
+		t.match(stdout, 'helpful log of a pending test');
 		t.match(stdout, /SIGINT/);
 		t.end();
 	});

test-tap/reporters/default.js

@@ -51,6 +51,7 @@ test(async t => {
 		t.test('single file run', run('timeoutInSingleFile'));
 		t.test('multiple files run', run('timeoutInMultipleFiles'));
 		t.test('single file with only certain tests matched run', run('timeoutWithMatch'));
+		t.test('logs provided during a pending test logged at the end', run('timeoutContextLogs'));
 		t.end();
 	});
 });

test-tap/reporters/default.timeoutcontextlogs.v14.log

@@ -0,0 +1,38 @@
+
+---tty-stream-chunk-separator
+  ✔ a › a passes
+---tty-stream-chunk-separator
+  ✔ a › a passes two
+---tty-stream-chunk-separator
+  
+  ✘ Timed out while running tests
+
+  2 tests were pending in a.cjs
+
+  ◌ a › a slow
+    ℹ this slow test prints useful debug message just text
+  ◌ a › a slow two
+    ℹ another useful debug message {
+        x: 5,
+      }
+
+---tty-stream-chunk-separator
+  ✔ b › a passes
+---tty-stream-chunk-separator
+  ✔ b › a passes two
+---tty-stream-chunk-separator
+  
+  ✘ Timed out while running tests
+
+  2 tests were pending in b.cjs
+
+  ◌ b › a slow
+    ℹ hello world
+  ◌ b › a slow two
+
+---tty-stream-chunk-separator
+  ─
+
+  4 tests passed
+  4 tests remained pending after a timeout
+---tty-stream-chunk-separator

test-tap/reporters/default.timeoutcontextlogs.v16.log

@@ -0,0 +1,38 @@
+
+---tty-stream-chunk-separator
+  ✔ a › a passes
+---tty-stream-chunk-separator
+  ✔ a › a passes two
+---tty-stream-chunk-separator
+  
+  ✘ Timed out while running tests
+
+  2 tests were pending in a.cjs
+
+  ◌ a › a slow
+    ℹ this slow test prints useful debug message just text
+  ◌ a › a slow two
+    ℹ another useful debug message {
+        x: 5,
+      }
+
+---tty-stream-chunk-separator
+  ✔ b › a passes
+---tty-stream-chunk-separator
+  ✔ b › a passes two
+---tty-stream-chunk-separator
+  
+  ✘ Timed out while running tests
+
+  2 tests were pending in b.cjs
+
+  ◌ b › a slow
+    ℹ hello world
+  ◌ b › a slow two
+
+---tty-stream-chunk-separator
+  ─
+
+  4 tests passed
+  4 tests remained pending after a timeout
+---tty-stream-chunk-separator

test-tap/reporters/default.timeoutcontextlogs.v18.log

@@ -0,0 +1,38 @@
+
+---tty-stream-chunk-separator
+  ✔ a › a passes
+---tty-stream-chunk-separator
+  ✔ a › a passes two
+---tty-stream-chunk-separator
+  
+  ✘ Timed out while running tests
+
+  2 tests were pending in a.cjs
+
+  ◌ a › a slow
+    ℹ this slow test prints useful debug message just text
+  ◌ a › a slow two
+    ℹ another useful debug message {
+        x: 5,
+      }
+
+---tty-stream-chunk-separator
+  ✔ b › a passes
+---tty-stream-chunk-separator
+  ✔ b › a passes two
+---tty-stream-chunk-separator
+  
+  ✘ Timed out while running tests
+
+  2 tests were pending in b.cjs
+
+  ◌ b › a slow
+    ℹ hello world
+  ◌ b › a slow two
+
+---tty-stream-chunk-separator
+  ─
+
+  4 tests passed
+  4 tests remained pending after a timeout
+---tty-stream-chunk-separator