Improve asynchronous test failures and async_minitest.

There's a bundle of improvements here:

- Show the stack trace of the failure when a test using async_minitest
  fails. The trade-off is that it now only reports the first failure.
  Collecting all of them didn't play nice with the stack trace
  deobfuscation the test runner does.

- Report the group and name of the test that failed when known.

- Fix as many double-reporting test result bugs as I could find. Also,
  in case that still happens, don't spew out a pile of useless JSON.

- Correctly wait for a test to complete even if it schedules its own
  asynchronous operations without returning futures.

- Generally simplify and clean some stuff up.

Change-Id: Ie020ae0b80a11764c455cf0ce24dfea09ca0adce
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/138903
Reviewed-by: Srujan Gaddam <[email protected]>
Reviewed-by: Sigmund Cherem <[email protected]>
Commit-Queue: Bob Nystrom <[email protected]>

Author: munificent

pkg/async_helper/lib/async_helper.dart

@@ -6,8 +6,7 @@
 /// If a test is asynchronous, it needs to notify the testing driver
 /// about this (otherwise tests may get reported as passing [after main()
 /// finished] even if the asynchronous operations fail).
-/// Tests which can't use the unittest framework should use the helper functions
-/// in this library.
+///
 /// This library provides four methods
 ///  - asyncStart(): Needs to be called before an asynchronous operation is
 ///                  scheduled.

pkg/async_helper/lib/async_minitest.dart

@@ -6,8 +6,9 @@
 /// unittest/test API used by the language and core library.
 ///
 /// Compared with `minitest.dart`, this library supports and expects
-/// asynchronous tests. It uses a `Zone` per test to collect errors in the
-/// correct test.
+/// asynchronous tests. It uses a `Zone` per test to associate a test name with
+/// the failure.
+///
 /// It does not support `setUp` or `tearDown` methods,
 /// and matchers are severely restricted.
 ///
@@ -42,17 +43,18 @@ void group(String name, body()) {
 
 void test(String name, body()) {
   var oldName = _pushName(name);
-  var test = new _Test(_currentName)..asyncWait();
-  var result =
-      runZoned(body, zoneValues: {_testToken: test}, onError: test.fail);
+
+  asyncStart();
+  var result = runZoned(body, zoneValues: {_testToken: _currentName});
   if (result is Future) {
     result.then((_) {
-      test.asyncDone();
-    }, onError: test.fail);
+      asyncEnd();
+    });
   } else {
     // Ensure all tests get to be set up first.
-    scheduleMicrotask(test.asyncDone);
+    scheduleMicrotask(asyncEnd);
   }
+
   _popName(oldName);
 }
 
@@ -69,85 +71,84 @@ void expect(dynamic value, dynamic matcher, {String reason}) {
 }
 
 R Function() expectAsync0<R>(R Function() f, {int count = 1}) {
-  var test = _currentTest..asyncWait(count);
+  asyncStart(count);
   return () {
     var result = f();
-    test.asyncDone();
+    asyncEnd();
     return result;
   };
 }
 
 R Function(A) expectAsync1<R, A>(R Function(A) f, {int count = 1}) {
-  var test = _currentTest..asyncWait(count);
+  asyncStart(count);
   return (A a) {
     var result = f(a);
-    test.asyncDone();
+    asyncEnd();
     return result;
   };
 }
 
 R Function(A, B) expectAsync2<R, A, B>(R Function(A, B) f, {int count = 1}) {
-  var test = _currentTest..asyncWait(count);
+  asyncStart(count);
   return (A a, B b) {
     var result = f(a, b);
-    test.asyncDone();
+    asyncEnd();
     return result;
   };
 }
 
 dynamic expectAsync(Function f, {int count = 1}) {
   var f2 = f; // Avoid type-promoting f, we want dynamic invocations.
-  var test = _currentTest;
   if (f2 is Function(Null, Null, Null, Null, Null)) {
-    test.asyncWait(count);
+    asyncStart(count);
     return ([a, b, c, d, e]) {
       var result = f(a, b, c, d, e);
-      test.asyncDone();
+      asyncEnd();
       return result;
     };
   }
   if (f2 is Function(Null, Null, Null, Null)) {
-    test.asyncWait(count);
+    asyncStart(count);
     return ([a, b, c, d]) {
       var result = f(a, b, c, d);
-      test.asyncDone();
+      asyncEnd();
       return result;
     };
   }
   if (f2 is Function(Null, Null, Null)) {
-    test.asyncWait(count);
+    asyncStart(count);
     return ([a, b, c]) {
       var result = f(a, b, c);
-      test.asyncDone();
+      asyncEnd();
       return result;
     };
   }
   if (f2 is Function(Null, Null)) {
-    test.asyncWait(count);
+    asyncStart(count);
     return ([a, b]) {
       var result = f(a, b);
-      test.asyncDone();
+      asyncEnd();
       return result;
     };
   }
   if (f2 is Function(Null)) {
-    test.asyncWait(count);
+    asyncStart(count);
     return ([a]) {
       var result = f(a);
-      test.asyncDone();
+      asyncEnd();
       return result;
     };
   }
   if (f2 is Function()) {
-    test.asyncWait(count);
+    asyncStart(count);
     return () {
       var result = f();
-      test.asyncDone();
+      asyncEnd();
       return result;
     };
   }
   throw new UnsupportedError(
-      "expectAsync only accepts up to five arguemnt functions");
+      "expectAsync only accepts up to five argument functions");
 }
 
 // Matchers
@@ -212,13 +213,13 @@ bool isStateError(dynamic o) {
 
 void _checkThrow<T>(dynamic v, void onError(error)) {
   if (v is Future) {
-    var test = _currentTest..asyncWait();
+    asyncStart();
     v.then((_) {
       Expect.fail("Did not throw");
     }, onError: (e, s) {
       if (e is! T) throw e;
       if (onError != null) onError(e);
-      test.asyncDone();
+      asyncEnd();
     });
     return;
   }
@@ -251,20 +252,18 @@ Matcher throwsA(matcher) => (dynamic o) {
 Matcher completion(matcher) => (dynamic o) {
       Expect.type<Future>(o);
       Future future = o;
-      _currentTest.asyncWait();
+      asyncStart();
       future.then((value) {
         expect(value, matcher);
-        _currentTest.asyncDone();
+        asyncEnd();
       });
     };
 
 void completes(dynamic o) {
   Expect.type<Future>(o);
   Future future = o;
-  _currentTest.asyncWait();
-  future.then((_) {
-    _currentTest.asyncDone();
-  });
+  asyncStart();
+  future.then(asyncSuccess);
 }
 
 void isMap(dynamic o) {
@@ -297,12 +296,21 @@ String fail(String message) {
   Expect.fail("$message");
 }
 
-// Internal helpers.
+/// Key for zone value holding current test name.
+final _testToken = Object();
+
+bool _initializedTestNameCallback = false;
 
-// The current combined name of the nesting [group] or [test].
+/// The current combined name of the nesting [group] or [test].
 String _currentName = null;
 
 String _pushName(String newName) {
+  // Look up the current test name from the zone created for the test.
+  if (!_initializedTestNameCallback) {
+    ExpectException.setTestNameCallback(() => Zone.current[_testToken]);
+    _initializedTestNameCallback = true;
+  }
+
   var oldName = _currentName;
   if (oldName == null) {
     _currentName = newName;
@@ -315,73 +323,3 @@ String _pushName(String newName) {
 void _popName(String oldName) {
   _currentName = oldName;
 }
-
-// Key for zone value holding current test object.
-final Object _testToken = new Object();
-
-_Test get _currentTest =>
-    Zone.current[_testToken] ?? (throw new StateError("Not inside test!"));
-
-class _Test {
-  static int activeTests = 0;
-  static int failedTests = 0;
-
-  final String name;
-  bool completed = false;
-  bool failed = false;
-  int asyncExpected = 0;
-  _Test(this.name) {
-    activeTests++;
-  }
-
-  void asyncWait([int n = 1]) {
-    if (completed) {
-      print("ERROR: $name: New operations started after completion."
-          "${StackTrace.current}");
-    } else if (asyncExpected == 0) {
-      asyncStart(); // Matched by asyncEnd in [_complete];
-    }
-    asyncExpected += n;
-  }
-
-  void asyncDone() {
-    if (asyncExpected == 0) {
-      print("ERROR: $name: More asyncEnds than asyncStarts.\n"
-          "${StackTrace.current}");
-    } else {
-      asyncExpected--;
-      if (asyncExpected == 0 && !completed) {
-        print("SUCCESS: $name");
-        _complete();
-      }
-    }
-  }
-
-  void fail(Object error, StackTrace stack) {
-    if (!completed) {
-      failed = true;
-      failedTests++;
-      print("FAILURE: $name: $error\n$stack");
-      _complete();
-    } else {
-      if (!failed) {
-        failed = true;
-        failedTests++;
-      }
-      print("FAILURE: $name: (after completion) $error\n$stack");
-    }
-  }
-
-  void _complete() {
-    assert(!completed);
-    completed = true;
-    activeTests--;
-    if (failedTests == 0) {
-      asyncEnd();
-    } else if (activeTests == 0) {
-      Zone.root.scheduleMicrotask(() {
-        Expect.fail("$failedTests tests failed");
-      });
-    }
-  }
-}

pkg/expect/lib/expect.dart

@@ -690,9 +690,29 @@ bool _identical(a, b) => identical(a, b);
 ///
 /// Always recognized by [Expect.throws] as an unexpected error.
 class ExpectException {
+  /// Call this to provide a function that associates a test name with this
+  /// failure.
+  ///
+  /// Used by async_helper/async_minitest.dart to inject logic to bind the
+  /// `group()` and `test()` name strings to a test failure.
+  static void setTestNameCallback(String Function() getName) {
+    _getTestName = getName;
+  }
+
+  // TODO(rnystrom): Type this `String Function()?` once this library doesn't
+  // need to be NNBD-agnostic.
+  static dynamic _getTestName;
+
   final String message;
-  ExpectException(this.message);
-  String toString() => message;
+  final String name;
+
+  ExpectException(this.message)
+      : name = (_getTestName == null) ? null : _getTestName();
+
+  String toString() {
+    if (name != null) return 'In test "$name" $message';
+    return message;
+  }
 }
 
 /// Is true iff type assertions are enabled.

pkg/test_runner/lib/src/browser.dart

@@ -218,32 +218,17 @@ requirejs(["$testName", "dart_sdk", "async_helper"],
     return lines.join("\\n");
   };
 
-  let pendingCallbacks = 0;
-  let waitForDone = false, isDone = false;
-
   sdk.dart.addAsyncCallback = function() {
-    pendingCallbacks++;
-    if (!waitForDone) {
-      // When the first callback is added, signal that test_controller.js
-      // should wait until done.
-      waitForDone = true;
-      dartPrint('unittest-suite-wait-for-done');
-    }
+    async_helper.async_helper.asyncStart();
   };
 
   sdk.dart.removeAsyncCallback = function() {
-    if (--pendingCallbacks <= 0) {
-      // We might be done with async callbacks. Schedule a task to check.
-      // Note: can't use a Promise here, because the unhandled rejection event
-      // is fired as a task, rather than a microtask. `setTimeout` will create a
-      // task, giving an unhandled promise reject time to fire before this does.
-      setTimeout(() => {
-        if (pendingCallbacks <= 0 && !isDone) {
-          isDone = true;
-          dartPrint('unittest-suite-done');
-        }
-      }, 0);
-    }
+    // removeAsyncCallback() is called *before* the async operation is
+    // performed, but we don't want to report the test as being done until
+    // after that operation completes, so wait for that callback to run.
+    setTimeout(() => {
+      async_helper.async_helper.asyncEnd();
+    }, 0);
   };
 
   if ($isNnbd) {

pkg/test_runner/lib/src/browser_controller.dart

@@ -1120,10 +1120,7 @@ class BrowserTestRunner {
 
     DebugLogger.warning("Double reporting tests:");
     for (var id in doubleReportingOutputs.keys) {
-      DebugLogger.warning("${testCache[id]}, output: ");
-      DebugLogger.warning("${doubleReportingOutputs[id]}");
-      DebugLogger.warning("");
-      DebugLogger.warning("");
+      DebugLogger.warning("${testCache[id]}");
     }
   }