refactor: change test reporter output (#4371)

This commit changes output of default test reporter to resemble output from Rust test runner;
first the name of running test is printed with "...", then after test has run result is printed on the same line.

* Split "Deno.TestEvent.Result" into "TestStart" and "TestEnd";
* changes TestReporter interface to support both events; 

Co-authored-by: Ryan Dahl <ry@tinyclouds.org>

cli/js/lib.deno.ns.d.ts

@@ -56,7 +56,8 @@ declare namespace Deno {
 
   export enum TestEvent {
     Start = "start",
-    Result = "result",
+    TestStart = "testStart",
+    TestEnd = "testEnd",
     End = "end"
   }
 
@@ -65,8 +66,13 @@ declare namespace Deno {
     tests: number;
   }
 
-  interface TestEventResult {
+  interface TestEventTestStart {
-    kind: TestEvent.Result;
+    kind: TestEvent.TestStart;
+    name: string;
+  }
+
+  interface TestEventTestEnd {
+    kind: TestEvent.TestEnd;
     result: TestResult;
   }
 
@@ -79,14 +85,16 @@ declare namespace Deno {
 
   interface TestReporter {
     start(event: TestEventStart): Promise<void>;
-    result(event: TestEventResult): Promise<void>;
+    testStart(msg: TestEventTestStart): Promise<void>;
+    testEnd(msg: TestEventTestEnd): Promise<void>;
     end(event: TestEventEnd): Promise<void>;
   }
 
   export class ConsoleTestReporter implements TestReporter {
     constructor();
     start(event: TestEventStart): Promise<void>;
-    result(event: TestEventResult): Promise<void>;
+    testStart(msg: TestEventTestStart): Promise<void>;
+    testEnd(msg: TestEventTestEnd): Promise<void>;
     end(event: TestEventEnd): Promise<void>;
   }
 

cli/js/testing.ts

@@ -1,12 +1,13 @@
 // Copyright 2018-2020 the Deno authors. All rights reserved. MIT license.
-import { bgRed, gray, green, italic, red, yellow } from "./colors.ts";
+import { gray, green, italic, red, yellow } from "./colors.ts";
 import { exit } from "./ops/os.ts";
-import { Console } from "./web/console.ts";
+import { Console, stringifyArgs } from "./web/console.ts";
+import { stdout } from "./files.ts";
+import { TextEncoder } from "./web/text_encoding.ts";
 
 const RED_FAILED = red("FAILED");
-const GREEN_OK = green("OK");
+const GREEN_OK = green("ok");
 const YELLOW_SKIPPED = yellow("SKIPPED");
-const RED_BG_FAIL = bgRed(" FAIL ");
 const disabledConsole = new Console((_x: string, _isErr?: boolean): void => {});
 
 function formatDuration(time = 0): string {
@@ -87,13 +88,14 @@ enum TestStatus {
 interface TestResult {
   name: string;
   status: TestStatus;
-  duration?: number;
+  duration: number;
   error?: Error;
 }
 
 export enum TestEvent {
   Start = "start",
-  Result = "result",
+  TestStart = "testStart",
+  TestEnd = "testEnd",
   End = "end"
 }
 
@@ -102,8 +104,13 @@ interface TestEventStart {
   tests: number;
 }
 
-interface TestEventResult {
+interface TestEventTestStart {
-  kind: TestEvent.Result;
+  kind: TestEvent.TestStart;
+  name: string;
+}
+
+interface TestEventTestEnd {
+  kind: TestEvent.TestEnd;
   result: TestResult;
 }
 
@@ -136,7 +143,7 @@ class TestApi {
   }
 
   async *[Symbol.asyncIterator](): AsyncIterator<
-    TestEventStart | TestEventResult | TestEventEnd
+    TestEventStart | TestEventTestStart | TestEventTestEnd | TestEventEnd
   > {
     yield {
       kind: TestEvent.Start,
@@ -146,7 +153,8 @@ class TestApi {
     const results: TestResult[] = [];
     const suiteStart = +new Date();
     for (const { name, fn, skip } of this.testsToRun) {
-      const result: Partial<TestResult> = { name };
+      const result: Partial<TestResult> = { name, duration: 0 };
+      yield { kind: TestEvent.TestStart, name };
       if (skip) {
         result.status = TestStatus.Skipped;
         this.stats.ignored++;
@@ -154,17 +162,17 @@ class TestApi {
         const start = +new Date();
         try {
           await fn();
-          result.duration = +new Date() - start;
           result.status = TestStatus.Passed;
           this.stats.passed++;
         } catch (err) {
-          result.duration = +new Date() - start;
           result.status = TestStatus.Failed;
           result.error = err;
           this.stats.failed++;
+        } finally {
+          result.duration = +new Date() - start;
         }
       }
-      yield { kind: TestEvent.Result, result: result as TestResult };
+      yield { kind: TestEvent.TestEnd, result: result as TestResult };
       results.push(result as TestResult);
       if (this.failFast && result.error != null) {
         break;
@@ -211,46 +219,78 @@ function createFilterFn(
 
 interface TestReporter {
   start(msg: TestEventStart): Promise<void>;
-  result(msg: TestEventResult): Promise<void>;
+  testStart(msg: TestEventTestStart): Promise<void>;
+  testEnd(msg: TestEventTestEnd): Promise<void>;
   end(msg: TestEventEnd): Promise<void>;
 }
 
 export class ConsoleTestReporter implements TestReporter {
-  private console: Console;
+  private encoder: TextEncoder;
+
   constructor() {
-    this.console = globalThis.console as Console;
+    this.encoder = new TextEncoder();
+  }
+
+  private log(msg: string, noNewLine = false): void {
+    if (!noNewLine) {
+      msg += "\n";
+    }
+
+    // Using `stdout` here because it doesn't force new lines
+    // compared to `console.log`; `core.print` on the other hand
+    // is line-buffered and doesn't output message without newline
+    stdout.writeSync(this.encoder.encode(msg));
   }
 
   async start(event: TestEventStart): Promise<void> {
-    this.console.log(`running ${event.tests} tests`);
+    this.log(`running ${event.tests} tests`);
   }
 
-  async result(event: TestEventResult): Promise<void> {
+  async testStart(event: TestEventTestStart): Promise<void> {
+    const { name } = event;
+
+    this.log(`test ${name} ... `, true);
+  }
+
+  async testEnd(event: TestEventTestEnd): Promise<void> {
     const { result } = event;
 
     switch (result.status) {
       case TestStatus.Passed:
-        this.console.log(
+        this.log(`${GREEN_OK} ${formatDuration(result.duration)}`);
-          `${GREEN_OK}      ${result.name} ${formatDuration(result.duration!)}`
-        );
         break;
       case TestStatus.Failed:
-        this.console.log(
+        this.log(`${RED_FAILED} ${formatDuration(result.duration)}`);
-          `${RED_FAILED}  ${result.name} ${formatDuration(result.duration!)}`
-        );
-        this.console.log(result.error!);
         break;
       case TestStatus.Skipped:
-        this.console.log(`${YELLOW_SKIPPED} ${result.name}`);
+        this.log(`${YELLOW_SKIPPED} ${formatDuration(result.duration)}`);
         break;
     }
   }
 
   async end(event: TestEventEnd): Promise<void> {
-    const { stats, duration } = event;
+    const { stats, duration, results } = event;
     // Attempting to match the output of Rust's test runner.
-    this.console.log(
+    const failedTests = results.filter(r => r.error);
-      `\ntest result: ${stats.failed ? RED_BG_FAIL : GREEN_OK} ` +
+
+    if (failedTests.length > 0) {
+      this.log(`\nfailures:\n`);
+
+      for (const result of failedTests) {
+        this.log(`${result.name}`);
+        this.log(`${stringifyArgs([result.error!])}`);
+        this.log("");
+      }
+
+      this.log(`failures:\n`);
+
+      for (const result of failedTests) {
+        this.log(`\t${result.name}`);
+      }
+    }
+
+    this.log(
+      `\ntest result: ${stats.failed ? RED_FAILED : GREEN_OK}. ` +
         `${stats.passed} passed; ${stats.failed} failed; ` +
         `${stats.ignored} ignored; ${stats.measured} measured; ` +
         `${stats.filtered} filtered out ` +
@@ -293,8 +333,11 @@ export async function runTests({
       case TestEvent.Start:
         await reporter.start(testMsg);
         continue;
-      case TestEvent.Result:
+      case TestEvent.TestStart:
-        await reporter.result(testMsg);
+        await reporter.testStart(testMsg);
+        continue;
+      case TestEvent.TestEnd:
+        await reporter.testEnd(testMsg);
         continue;
       case TestEvent.End:
         endMsg = testMsg;

cli/js/tests/README.md

@@ -47,48 +47,32 @@ Runner discoveres required permissions combinations by loading
 
 There are three ways to run `unit_test_runner.ts`:
 
-- run tests matching current process permissions
-
 ```
-// run tests that don't require any permissions
+# Run all tests. Spawns worker processes for each discovered permission
-target/debug/deno unit_test_runner.ts
+# combination:
+target/debug/deno -A cli/js/tests/unit_test_runner.ts --master
 
-// run tests with "net" permission
+# By default all output of worker processes is discarded; for debug purposes
-target/debug/deno --allow-net unit_test_runner.ts
+# the --verbose flag preserves output from the worker
+target/debug/deno -A cli/js/tests/unit_test_runner.ts --master --verbose
 
-target/debug/deno --allow-net --allow-read unit_test_runner.ts
+# Run subset of tests that don't require any permissions
+target/debug/deno cli/js/tests/unit_test_runner.ts
+
+# Run subset tests that require "net" and "read" permissions
+target/debug/deno --allow-net --allow-read cli/js/tests/unit_test_runner.ts
+
+# "worker" mode communicates with parent using TCP socket on provided address;
+# after initial setup drops permissions to specified set. It shouldn't be used
+# directly, only be "master" process.
+target/debug/deno -A cli/js/tests/unit_test_runner.ts --worker --addr=127.0.0.1:4500 --perms=net,write,run
+
+# Run specific tests
+target/debug/deno --allow-net cli/js/tests/unit_test_runner.ts -- netTcpListenClose
 ```
 
-- run all tests - "master" mode, that spawns worker processes for each
+### Http server
-  discovered permission combination:
 
-```
+`tools/http_server.py` is required to run when one's running unit tests. During
-target/debug/deno -A unit_test_runner.ts --master
+CI it's spawned automatically, but if you want to run tests manually make sure
-```
+that server is spawned otherwise there'll be cascade of test failures.
-
-By default all output of worker processes is discarded; for debug purposes
-`--verbose` flag can be provided to preserve output from worker
-
-```
-target/debug/deno -A unit_test_runner.ts --master --verbose
-```
-
-- "worker" mode; communicates with parent using TCP socket on provided address;
-  after initial setup drops permissions to specified set. It shouldn't be used
-  directly, only be "master" process.
-
-```
-target/debug/deno -A unit_test_runner.ts --worker --addr=127.0.0.1:4500 --perms=net,write,run
-```
-
-### Filtering
-
-Runner supports basic test filtering by name:
-
-```
-target/debug/deno unit_test_runner.ts -- netAccept
-
-target/debug/deno -A unit_test_runner.ts --master -- netAccept
-```
-
-Filter string must be specified after "--" argument

cli/js/tests/test_util.ts

@@ -92,10 +92,6 @@ export async function registerUnitTests(): Promise<void> {
   const processPerms = await getProcessPermissions();
 
   for (const unitTestDefinition of REGISTERED_UNIT_TESTS) {
-    if (unitTestDefinition.skip) {
-      continue;
-    }
-
     if (!permissionsMatch(processPerms, unitTestDefinition.perms)) {
       continue;
     }
@@ -172,10 +168,8 @@ interface UnitTestOptions {
   perms?: UnitTestPermissions;
 }
 
-interface UnitTestDefinition {
+interface UnitTestDefinition extends Deno.TestDefinition {
-  name: string;
+  skip: boolean;
-  fn: Deno.TestFunction;
-  skip?: boolean;
   perms: Permissions;
 }
 
@@ -210,10 +204,6 @@ export function unitTest(
     assert(name, "Missing test function name");
   }
 
-  if (options.skip) {
-    return;
-  }
-
   const normalizedPerms = normalizeTestPermissions(options.perms || {});
   registerPermCombination(normalizedPerms);
 
@@ -262,7 +252,11 @@ export class SocketReporter implements Deno.TestReporter {
     await this.write(msg);
   }
 
-  async result(msg: Deno.TestEventResult): Promise<void> {
+  async testStart(msg: Deno.TestEventTestStart): Promise<void> {
+    await this.write(msg);
+  }
+
+  async testEnd(msg: Deno.TestEventTestEnd): Promise<void> {
     // eslint-disable-next-line @typescript-eslint/no-explicit-any
     const serializedMsg: any = { ...msg };
 

cli/js/tests/unit_test_runner.ts

@@ -17,6 +17,7 @@ interface PermissionSetTestResult {
   stats: Deno.TestStats;
   permsStr: string;
   duration: number;
+  results: Deno.TestResult[];
 }
 
 const PERMISSIONS: Deno.PermissionName[] = [
@@ -144,17 +145,18 @@ async function runTestsForPermissionSet(
         expectedPassedTests = msg.tests;
         await reporter.start(msg);
         continue;
-      }
+      } else if (msg.kind === Deno.TestEvent.TestStart) {
-
+        await reporter.testStart(msg);
-      if (msg.kind === Deno.TestEvent.Result) {
-        await reporter.result(msg);
         continue;
-      }
+      } else if (msg.kind === Deno.TestEvent.TestEnd) {
-
+        await reporter.testEnd(msg);
+        continue;
+      } else {
         endEvent = msg;
         await reporter.end(msg);
         break;
       }
+    }
   } catch (e) {
     hasThrown = true;
     err = e;
@@ -183,14 +185,16 @@ async function runTestsForPermissionSet(
 
   workerProcess.close();
 
-  const passed = expectedPassedTests === endEvent.stats.passed;
+  const passed =
+    expectedPassedTests === endEvent.stats.passed + endEvent.stats.ignored;
 
   return {
     perms,
     passed,
     permsStr: permsFmt,
     duration: endEvent.duration,
-    stats: endEvent.stats
+    stats: endEvent.stats,
+    results: endEvent.results
   };
 }
 
@@ -225,13 +229,13 @@ async function masterRunnerMain(
   let testsPassed = true;
 
   for (const testResult of testResults) {
-    const { permsStr, stats, duration } = testResult;
+    const { permsStr, stats, duration, results } = testResult;
     console.log(`Summary for ${permsStr}`);
     await consoleReporter.end({
       kind: Deno.TestEvent.End,
       stats,
       duration,
-      results: []
+      results
     });
     testsPassed = testsPassed && testResult.passed;
   }

cli/tests/057_revoke_permissions.out

@@ -1,10 +1,10 @@
 running 7 tests
-OK      runGranted [WILDCARD]
+test runGranted ... ok [WILDCARD]
-OK      readGranted [WILDCARD]
+test readGranted ... ok [WILDCARD]
-OK      writeGranted [WILDCARD]
+test writeGranted ... ok [WILDCARD]
-OK      netGranted [WILDCARD]
+test netGranted ... ok [WILDCARD]
-OK      envGranted [WILDCARD]
+test envGranted ... ok [WILDCARD]
-OK      pluginGranted [WILDCARD]
+test pluginGranted ... ok [WILDCARD]
-OK      hrtimeGranted [WILDCARD]
+test hrtimeGranted ... ok [WILDCARD]
 
-test result: OK 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out [WILDCARD]
+test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out [WILDCARD]

cli/tests/compiler_api_test.out

@@ -1,15 +1,16 @@
 running 12 tests
-OK      compilerApiCompileSources [WILDCARD]
+test compilerApiCompileSources ... ok [WILDCARD]
-OK      compilerApiCompileNoSources [WILDCARD]
+test compilerApiCompileNoSources ... ok [WILDCARD]
-OK      compilerApiCompileOptions [WILDCARD]
+test compilerApiCompileOptions ... ok [WILDCARD]
-OK      compilerApiCompileLib [WILDCARD]
+test compilerApiCompileLib ... ok [WILDCARD]
-OK      compilerApiCompileTypes [WILDCARD]
+test compilerApiCompileTypes ... ok [WILDCARD]
-OK      transpileOnlyApi [WILDCARD]
+test transpileOnlyApi ... ok [WILDCARD]
-OK      transpileOnlyApiConfig [WILDCARD]
+test transpileOnlyApiConfig ... ok [WILDCARD]
-OK      bundleApiSources [WILDCARD]
+test bundleApiSources ... ok [WILDCARD]
-OK      bundleApiNoSources [WILDCARD]
+test bundleApiNoSources ... ok [WILDCARD]
-OK      bundleApiConfig [WILDCARD]
+test bundleApiConfig ... ok [WILDCARD]
-OK      bundleApiJsModules [WILDCARD]
+test bundleApiJsModules ... ok [WILDCARD]
-OK      diagnosticsTest [WILDCARD]
+test diagnosticsTest ... ok [WILDCARD]
+
+test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out [WILDCARD]
 
-test result: OK 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out [WILDCARD]

cli/tests/workers_test.out

@@ -1,7 +1,7 @@
 running 4 tests
-OK      workersBasic [WILDCARD]
+test workersBasic ... ok [WILDCARD]
-OK      nestedWorker [WILDCARD]
+test nestedWorker ... ok [WILDCARD]
-OK      workerThrowsWhenExecuting [WILDCARD]
+test workerThrowsWhenExecuting ... ok [WILDCARD]
-OK      workerCanUseFetch [WILDCARD]
+test workerCanUseFetch ... ok [WILDCARD]
 
-test result: OK 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out [WILDCARD]
+test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out [WILDCARD]