Improve watcher e2e test. (#2254)

Author: davidmorgan

pkgs/watcher/lib/src/directory_watcher/linux.dart

@@ -150,6 +150,7 @@ class _LinuxDirectoryWatcher
 
   /// The callback that's run when a batch of changes comes in.
   void _onBatch(List<Event> batch) {
+    logForTesting?.call('_onBatch,$batch');
     var files = <String>{};
     var dirs = <String>{};
     var changed = <String>{};
@@ -281,6 +282,7 @@ class _LinuxDirectoryWatcher
         // Only emit ADD if it hasn't already been emitted due to the file being
         // modified or added after the directory was added.
         if (!_files.contains(entity.path)) {
+          logForTesting?.call('_addSubdir,$path,$entity');
           _files.add(entity.path);
           _emitEvent(ChangeType.ADD, entity.path);
         }
@@ -346,6 +348,8 @@ class _LinuxDirectoryWatcher
   ///
   /// See [_Watch] class comment.
   _Watch _watch(String path) {
+    logForTesting?.call('_Watch._watch,$path');
+
     _watches[path]?.cancel();
     final result = _Watch(path, _cancelWatchesUnderPath);
     _watches[path] = result;
@@ -360,6 +364,8 @@ class _LinuxDirectoryWatcher
 
   /// Cancels all watches under path [path].
   void _cancelWatchesUnderPath(String path) {
+    logForTesting?.call('_Watch.cancelWatchesUnderPath,$path');
+
     // If [path] is the root watch directory do nothing, that's handled when the
     // stream closes.
     if (path == this.path) return;
@@ -397,6 +403,7 @@ class _Watch {
       String path, StreamController<FileSystemEvent> controller) {
     return Directory(path).watch().listen(
       (event) {
+        logForTesting?.call('_Watch._listen,$path,$event');
         if (event is FileSystemDeleteEvent ||
             (event.isDirectory && event is FileSystemMoveEvent)) {
           _cancelWatchesUnderPath(event.path);
@@ -410,6 +417,7 @@ class _Watch {
   }
 
   void cancel() {
+    logForTesting?.call('_Watch.cancel,$path');
     _subscription.cancel();
   }
 }

pkgs/watcher/lib/src/directory_watcher/mac_os.dart

@@ -112,6 +112,8 @@ class _MacOSDirectoryWatcher
 
   /// The callback that's run when [Directory.watch] emits a batch of events.
   void _onBatch(List<Event> batch) {
+    logForTesting?.call('onBatch: $batch');
+
     // If we get a batch of events before we're ready to begin emitting events,
     // it's probable that it's a batch of pre-watcher events (see issue 14373).
     // Ignore those events and re-list the directory.

pkgs/watcher/lib/src/utils.dart

@@ -72,3 +72,6 @@ extension IgnoringError<T> on Stream<T> {
     ));
   }
 }
+
+/// Set to log watcher internals for testing.
+void Function(String)? logForTesting;

pkgs/watcher/test/directory_watcher/client_simulator.dart

@@ -15,27 +15,22 @@ import 'package:watcher/watcher.dart';
 /// lengths on disk.
 class ClientSimulator {
   final Watcher watcher;
-  final void Function(String) printOnFailure;
-
-  /// Events and actions, for logging on failure.
-  final List<String> messages = [];
+  final void Function(String) log;
 
   final Map<String, int> _trackedFileLengths = {};
 
   StreamSubscription<WatchEvent>? _subscription;
   DateTime _lastEventAt = DateTime.now();
 
-  ClientSimulator._({required this.watcher, required this.printOnFailure});
+  ClientSimulator._({required this.watcher, required this.log});
 
   /// Creates a `ClientSimulator` watching with [watcher].
   ///
   /// When returned, it has already read the filesystem state and started
   /// tracking file lengths using watcher events.
   static Future<ClientSimulator> watch(
-      {required Watcher watcher,
-      required void Function(String) printOnFailure}) async {
-    final result =
-        ClientSimulator._(watcher: watcher, printOnFailure: printOnFailure);
+      {required Watcher watcher, required void Function(String) log}) async {
+    final result = ClientSimulator._(watcher: watcher, log: log);
     result._initialRead();
     result._subscription = watcher.events.listen(result._handleEvent);
     await watcher.ready;
@@ -93,7 +88,7 @@ class ClientSimulator {
         if (_trackedFileLengths.containsKey(event.path)) {
           // This happens sometimes, so investigation+fix would be needed
           // if we want to make it an error.
-          printOnFailure('Warning: ADD for tracked path,${event.path}');
+          log('Warning: ADD for tracked path,${event.path}');
         }
         _readFile(event.path);
         break;
@@ -106,7 +101,7 @@ class ClientSimulator {
         if (!_trackedFileLengths.containsKey(event.path)) {
           // This happens sometimes, so investigation+fix would be needed
           // if we want to make it an error.
-          printOnFailure('Warning: REMOVE untracked path: ${event.path}');
+          log('Warning: REMOVE untracked path: ${event.path}');
         }
         _trackedFileLengths.remove(event.path);
         break;
@@ -182,6 +177,6 @@ class ClientSimulator {
     // Remove the tmp folder from the message.
     message =
         message.replaceAll('${watcher.path}${Platform.pathSeparator}', '');
-    messages.add(message);
+    log(message);
   }
 }

pkgs/watcher/test/directory_watcher/end_to_end_tests.dart

@@ -7,6 +7,7 @@ import 'dart:io';
 
 import 'package:path/path.dart' as p;
 import 'package:test/test.dart' as package_test;
+import 'package:watcher/src/utils.dart';
 import 'package:watcher/watcher.dart';
 
 import '../utils.dart' as utils;
@@ -31,12 +32,16 @@ void endToEndTests() {
 /// and [printOnFailure] replacements.
 ///
 /// To run until failure, set [endlessMode] to `true`.
+///
+/// To fix the seed, set [seed]. The failure message prints the seed, so this
+/// can be used to run just the events that triggered the failure.
 Future<void> _runTest({
   void Function(void Function())? addTearDown,
   Watcher Function({required String path})? createWatcher,
   void Function(String)? fail,
   void Function(String)? printOnFailure,
   bool endlessMode = false,
+  int? seed,
 }) async {
   addTearDown ??= package_test.addTearDown;
   createWatcher ??= utils.createWatcher;
@@ -46,22 +51,28 @@ Future<void> _runTest({
   final temp = Directory.systemTemp.createTempSync();
   addTearDown(() => temp.deleteSync(recursive: true));
 
+  // Turn on logging of the watchers.
+  final log = <LogEntry>[];
+  logForTesting = (message) => log.add(LogEntry('W $message'));
+
   // Create the watcher and [ClientSimulator].
   final watcher = createWatcher(path: temp.path);
   final client = await ClientSimulator.watch(
-      watcher: watcher, printOnFailure: printOnFailure);
+      watcher: watcher, log: (message) => log.add(LogEntry('C $message')));
   addTearDown(client.close);
 
   // 40 iterations of making changes, waiting for events to settle, and
   // checking for consistency.
   final changer = FileChanger(temp.path);
   for (var i = 0; endlessMode || i != 40; ++i) {
+    final runSeed = seed ?? i;
+    log.clear();
     if (endlessMode) stdout.write('.');
     for (final entity in temp.listSync()) {
       entity.deleteSync(recursive: true);
     }
     // File changes.
-    final messages = await changer.changeFiles(times: 200);
+    log.addAll(await changer.changeFiles(times: 200, seed: runSeed));
 
     // Give time for events to arrive. To allow tests to run quickly when the
     // events are handled quickly, poll and continue if verification passes.
@@ -80,24 +91,30 @@ Future<void> _runTest({
       client.verify(printOnFailure: printOnFailure);
       // Write the file operations before the failure to a log, fail the test.
       final logTemp = Directory.systemTemp.createTempSync();
-      final fileChangesLogPath = p.join(logTemp.path, 'changes.txt');
-      File(fileChangesLogPath)
-          .writeAsStringSync(messages.map((m) => '$m\n').join(''));
-      final clientLogPath = p.join(logTemp.path, 'client.txt');
-      File(clientLogPath)
-          .writeAsStringSync(client.messages.map((m) => '$m\n').join(''));
+      final logPath = p.join(logTemp.path, 'log.txt');
+
+      // Sort the log entries by timestamp.
+      log.sort();
+
+      File(logPath).writeAsStringSync(log.map((m) => '$m\n').join(''));
       fail('''
-Failed on run $i.
-Files changes: $fileChangesLogPath
-Client log: $clientLogPath''');
+Failed on run $i, seed $runSeed. Run in a loop with that seed using:
+
+  dart test/directory_watcher/end_to_end_tests.dart $runSeed
+
+Changes/watcher/client log: $logPath
+''');
     }
   }
 }
 
 /// Main method for running the e2e test without `package:test`.
 ///
+/// Optionally, pass the seed to run with as the only argument.
+///
 /// Exits on failure, or runs forever.
-Future<void> main() async {
+Future<void> main(List<String> arguments) async {
+  final seed = arguments.isNotEmpty ? int.parse(arguments.first) : null;
   final teardowns = <void Function()>[];
   try {
     await _runTest(
@@ -109,10 +126,28 @@ Future<void> main() async {
       },
       printOnFailure: print,
       endlessMode: true,
+      seed: seed,
     );
   } finally {
     for (final teardown in teardowns) {
       teardown();
     }
   }
 }
+
+/// Log entry with timestamp.
+///
+/// Because file events happen on a different isolate the merged log uses
+/// timestamps to put entries in the correct order.
+class LogEntry implements Comparable<LogEntry> {
+  final DateTime timestamp;
+  final String message;
+
+  LogEntry(this.message) : timestamp = DateTime.now();
+
+  @override
+  int compareTo(LogEntry other) => timestamp.compareTo(other.timestamp);
+
+  @override
+  String toString() => message;
+}

pkgs/watcher/test/directory_watcher/file_changer.dart

@@ -9,6 +9,7 @@ import 'dart:math';
 import 'package:path/path.dart' as p;
 
 import '../utils.dart';
+import 'end_to_end_tests.dart';
 
 /// Changes files randomly.
 ///
@@ -26,22 +27,24 @@ class FileChanger {
   final String path;
 
   Random _random = Random(0);
-  final List<String> _messages = [];
+  final List<LogEntry> _messages = [];
 
   FileChanger(this.path);
 
   /// Changes files under [path], [times] times.
   ///
+  /// Changes are randomized with [seed], pass the same value to get the same
+  /// changes.
+  ///
   /// Returns a log of the changes made.
-  Future<List<String>> changeFiles({required int times}) async {
+  Future<List<LogEntry>> changeFiles(
+      {required int times, required int seed}) async {
+    _random = Random(seed);
     final result = await Isolate.run(() => _changeFiles(times: times));
-    // The `Random` instance gets copied to the isolate on every run, so by
-    // default it will produce the same numbers. Update it to get new numbers.
-    _random = Random(_random.nextInt(0xffffffff));
     return result;
   }
 
-  Future<List<String>> _changeFiles({required int times}) async {
+  Future<List<LogEntry>> _changeFiles({required int times}) async {
     _messages.clear();
     for (var i = 0; i != times; ++i) {
       await _changeFilesOnce();
@@ -163,6 +166,6 @@ class FileChanger {
   void _log(String message) {
     // Remove the tmp folder from the message.
     message = message.replaceAll(',$path${Platform.pathSeparator}', ',');
-    _messages.add(message);
+    _messages.add(LogEntry('F $message'));
   }
 }