LibTest/io/WebSocket/* tests are flaky

[alexmarkov]

Examples of the flaky failures:

/=========================================================================================\
| co19/LibTest/io/WebSocket/addStream_A01_t04 broke (Pass -> RuntimeError, expected Pass) |
\=========================================================================================/

--- Command "vm" (took 02.000300s):
set DART_CONFIGURATION=ReleaseIA32 & set DART_SUPPRESS_WER=1 & set DART_CRASHPAD_HANDLER=C:\b\s\w\ir\out\ReleaseIA32\crashpad_handler.exe & out\ReleaseIA32\dart.exe --sound-null-safety -Dtest_runner.configuration=vm-win-release-ia32 --ignore-unrecognized-flags --packages=C:\b\s\w\ir\.dart_tool\package_config.json C:\b\s\w\ir\tests\co19\src\LibTest\io\WebSocket\addStream_A01_t04.dart

exit code:
255

stdout:
unittest-suite-wait-for-done
unittest-suite-success

stderr:
Unhandled exception:
Exception: Fatal: asyncStart() was called even though we are done with testing.. This is most likely a bug in your test.
#0      asyncStart (file:///C:/b/s/w/ir/tests/co19/src/Utils/async_utils.dart:49:5)
#1      AsyncExpect.data (file:///C:/b/s/w/ir/tests/co19/src/Utils/async_utils.dart:195:5)
#2      main.<anonymous closure>.<anonymous closure> (file:///C:/b/s/w/ir/tests/co19/src/LibTest/io/WebSocket/addStream_A01_t04.dart:34:62)
#3      Future._propagateToListeners.handleValueCallback (dart:async/future_impl.dart:951:45)
#4      Future._propagateToListeners (dart:async/future_impl.dart:980:13)
#5      Future._completeWithValue (dart:async/future_impl.dart:723:5)
#6      Future._asyncCompleteWithValue.<anonymous closure> (dart:async/future_impl.dart:807:7)
#7      _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
#8      _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)
#9      _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:128:13)
#10     _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:195:5)

--- Re-run this test:
python3 tools/test.py -n vm-win-release-ia32 co19/LibTest/io/WebSocket/addStream_A01_t04


/===================================================================================\
| co19/LibTest/io/WebSocket/add_A01_t03 broke (Pass -> RuntimeError, expected Pass) |
\===================================================================================/

--- Command "vm" (took 01.000898s):
set DART_CONFIGURATION=ReleaseIA32 & set DART_SUPPRESS_WER=1 & set DART_CRASHPAD_HANDLER=C:\b\s\w\ir\out\ReleaseIA32\crashpad_handler.exe & out\ReleaseIA32\dart.exe --sound-null-safety -Dtest_runner.configuration=vm-win-release-ia32 --ignore-unrecognized-flags --packages=C:\b\s\w\ir\.dart_tool\package_config.json C:\b\s\w\ir\tests\co19\src\LibTest\io\WebSocket\add_A01_t03.dart

exit code:
255

stdout:
unittest-suite-wait-for-done
unittest-suite-success

stderr:
Unhandled exception:
Exception: Fatal: asyncStart() was called even though we are done with testing.. This is most likely a bug in your test.
#0      asyncStart (file:///C:/b/s/w/ir/tests/co19/src/Utils/async_utils.dart:49:5)
#1      AsyncExpect.data (file:///C:/b/s/w/ir/tests/co19/src/Utils/async_utils.dart:195:5)
#2      main.<anonymous closure>.<anonymous closure> (file:///C:/b/s/w/ir/tests/co19/src/LibTest/io/WebSocket/add_A01_t03.dart:24:41)
#3      Future._propagateToListeners.handleValueCallback (dart:async/future_impl.dart:951:45)
#4      Future._propagateToListeners (dart:async/future_impl.dart:980:13)
#5      Future._completeWithValue (dart:async/future_impl.dart:723:5)
#6      Future._asyncCompleteWithValue.<anonymous closure> (dart:async/future_impl.dart:807:7)
#7      _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
#8      _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)
#9      _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:128:13)
#10     _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:195:5)

--- Re-run this test:
python3 tools/test.py -n vm-win-release-ia32 co19/LibTest/io/WebSocket/add_A01_t03


/===========================================================================================\
| co19/LibTest/io/WebSocket/closeReason_A01_t01 broke (Pass -> RuntimeError, expected Pass) |
\===========================================================================================/

--- Command "vm" (took 02.000303s):
set DART_CONFIGURATION=ReleaseIA32 & set DART_SUPPRESS_WER=1 & set DART_CRASHPAD_HANDLER=C:\b\s\w\ir\out\ReleaseIA32\crashpad_handler.exe & out\ReleaseIA32\dart.exe --sound-null-safety -Dtest_runner.configuration=vm-win-release-ia32 --ignore-unrecognized-flags --packages=C:\b\s\w\ir\.dart_tool\package_config.json C:\b\s\w\ir\tests\co19\src\LibTest\io\WebSocket\closeReason_A01_t01.dart

exit code:
255

stderr:
Unhandled exception:
Expect.equals(expected: <>, actual: <null>) fails.
#0      _fail (file:///C:/b/s/w/ir/tests/co19/src/Utils/expect.dart:18:5)
#1      Expect.equals (file:///C:/b/s/w/ir/tests/co19/src/Utils/expect_common.dart:15:7)
#2      main.<anonymous closure>.<anonymous closure>.<anonymous closure> (file:///C:/b/s/w/ir/tests/co19/src/LibTest/io/WebSocket/closeReason_A01_t01.dart:31:16)
#3      Future._propagateToListeners.handleValueCallback (dart:async/future_impl.dart:951:45)
#4      Future._propagateToListeners (dart:async/future_impl.dart:980:13)
#5      Future._completeWithValue (dart:async/future_impl.dart:723:5)
#6      Future._asyncCompleteWithValue.<anonymous closure> (dart:async/future_impl.dart:807:7)
#7      _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
#8      _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)
#9      _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:128:13)
#10     _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:195:5)

--- Re-run this test:
python3 tools/test.py -n vm-win-release-ia32 co19/LibTest/io/WebSocket/closeReason_A01_t01

Investigated flakiness in LibTest/io/WebSocket/add_A01_t03.dart. It is flaky because HttpServer may handle outstanding data after client test is completed and asyncTest issued the last asyncEnd but server is not closed until cleanup callback is executed:

co19/Utils/async_utils.dart

Lines 120 to 131 in 5198824

	void asyncTest<T>(Future test(T? value), {required Future<T> setup(),
	required void cleanup(T? value)}) {
	asyncStart();
	Future<T?> setupFuture = setup();
	setupFuture.then((T? setupValue) {
	test(setupValue)
	.then((_) => asyncEnd())
	.whenComplete(() {
	cleanup(setupValue);
	});
	});
	}

While handling the outstanding data, HttpServer would call AsyncExpect.data:

co19/LibTest/io/WebSocket/add_A01_t03.dart

Line 24 in 5198824

(WebSocket ws) => AsyncExpect.data(["Hello"], ws)),

AsyncExpect.data calls asyncStart which would fail at this time because the last asyncEnd was already called.

This particular flakiness can be fixed by adding extra asyncStart/asyncEnd pair into asyncTest, something along the lines:

diff --git a/Utils/async_utils.dart b/Utils/async_utils.dart
index 1c011d356..6a2b7a3e5 100644
--- a/Utils/async_utils.dart
+++ b/Utils/async_utils.dart
@@ -119,13 +119,14 @@ class Sync2<T> {
 /// [test] is completed. [cleanup] is always called, regardless of test status.
 void asyncTest<T>(Future test(T? value), {required Future<T> setup(),
     required void cleanup(T? value)}) {
-  asyncStart();
+  asyncStart(2);
   Future<T?> setupFuture = setup();
   setupFuture.then((T? setupValue) {
     test(setupValue)
       .then((_) => asyncEnd())
       .whenComplete(() {
         cleanup(setupValue);
+        asyncEnd();
     });
   });
 }

[sgrekhov]

@alexmarkov thank you for the investigation! I think that adding asyncEnd() after cleanup() is a very good solution. Implemented. #3074