Add more debugging logs to overall_experience_test (flutter#86368)

Author: Hixie

dev/bots/test.dart

@@ -722,7 +722,7 @@ Future<void> _runFrameworkTests() async {
   Future<void> runMisc() async {
     print('${green}Running package tests$reset for directories other than packages/flutter');
     await _pubRunTest(path.join(flutterRoot, 'dev', 'bots'));
-    await _pubRunTest(path.join(flutterRoot, 'dev', 'devicelab'), ensurePrecompiledTool: false);
+    await _pubRunTest(path.join(flutterRoot, 'dev', 'devicelab'), ensurePrecompiledTool: false); // See https://github.com/flutter/flutter/issues/86209
     await _pubRunTest(path.join(flutterRoot, 'dev', 'snippets'));
     // TODO(fujino): Move this to its own test shard
     await _pubRunTest(path.join(flutterRoot, 'dev', 'conductor'), forceSingleCore: true);

packages/flutter_tools/test/integration.shard/overall_experience_test.dart

@@ -23,6 +23,7 @@
 // to the runFlutter function.
 
 // @dart = 2.8
+// This file is ready to transition, just uncomment /*?*/, /*!*/, and /*late*/.
 
 import 'dart:async';
 import 'dart:convert';
@@ -113,39 +114,67 @@ class Multiple extends Transition {
 
   @override
   String toString() {
+    if (_originalPatterns.length == patterns.length) {
+      return '${_originalPatterns.map(describe).join(', ')} (all matched)';
+    }
     return '${_originalPatterns.map(describe).join(', ')} (matched ${_originalPatterns.length - patterns.length} so far)';
   }
 }
 
-class ProcessTestResult {
-  const ProcessTestResult(this.exitCode, this.stdout, this.stderr);
-  final int exitCode;
-  final List<String> stdout;
-  final List<String> stderr;
+class LogLine {
+  const LogLine(this.channel, this.stamp, this.message);
+  final String channel;
+  final String stamp;
+  final String message;
+
+  bool get couldBeCrash => message.contains('Oops; flutter has exited unexpectedly:');
 
   @override
-  String toString() => 'exit code $exitCode\nstdout:\n  ${stdout.join('\n  ')}\nstderr:\n  ${stderr.join('\n  ')}\n';
-}
+  String toString() => '$stamp $channel: $message';
 
-String clarify(String line) {
-  return line.runes.map<String>((int rune) {
-    if (rune >= 0x20 && rune <= 0x7F) {
-      return String.fromCharCode(rune);
-    }
-    switch (rune) {
-      case 0x00: return '<NUL>';
-      case 0x07: return '<BEL>';
-      case 0x08: return '<TAB>';
-      case 0x09: return '<BS>';
-      case 0x0A: return '<LF>';
-      case 0x0D: return '<CR>';
-    }
-    return '<${rune.toRadixString(16).padLeft(rune <= 0xFF ? 2 : rune <= 0xFFFF ? 4 : 5, '0')}>';
-  }).join('');
+  void printClearly() {
+    print('$stamp $channel: ${clarify(message)}');
+  }
+
+  static String clarify(String line) {
+    return line.runes.map<String>((int rune) {
+      if (rune >= 0x20 && rune <= 0x7F) {
+        return String.fromCharCode(rune);
+      }
+      switch (rune) {
+        case 0x00: return '<NUL>';
+        case 0x07: return '<BEL>';
+        case 0x08: return '<TAB>';
+        case 0x09: return '<BS>';
+        case 0x0A: return '<LF>';
+        case 0x0D: return '<CR>';
+      }
+      return '<${rune.toRadixString(16).padLeft(rune <= 0xFF ? 2 : rune <= 0xFFFF ? 4 : 5, '0')}>';
+    }).join('');
+  }
 }
 
-void printClearly(String line) {
-  print(clarify(line));
+class ProcessTestResult {
+  const ProcessTestResult(this.exitCode, this.logs);
+  final int exitCode;
+  final List<LogLine> logs;
+
+  List<String> get stdout {
+    return logs
+      .where((LogLine log) => log.channel == 'stdout')
+      .map<String>((LogLine log) => log.message)
+      .toList();
+  }
+
+  List<String> get stderr {
+    return logs
+      .where((LogLine log) => log.channel == 'stderr')
+      .map<String>((LogLine log) => log.message)
+      .toList();
+  }
+
+  @override
+  String toString() => 'exit code $exitCode\nlogs:\n  ${logs.join('\n  ')}\n';
 }
 
 Future<ProcessTestResult> runFlutter(
@@ -156,13 +185,12 @@ Future<ProcessTestResult> runFlutter(
   bool logging = true,
   Duration expectedMaxDuration = const Duration(seconds: 25), // must be less than test timeout of 30 seconds!
 }) async {
+  final Stopwatch clock = Stopwatch()..start();
   final Process process = await processManager.start(
     <String>[flutterBin, ...arguments],
     workingDirectory: workingDirectory,
   );
-  final List<String> stdoutLog = <String>[];
-  final List<String> stderrLog = <String>[];
-  final List<String> stdinLog = <String>[];
+  final List<LogLine> logs = <LogLine>[];
   int nextTransition = 0;
   void describeStatus() {
     if (transitions.isNotEmpty) {
@@ -175,13 +203,13 @@ Future<ProcessTestResult> runFlutter(
                                        '                '} ${transitions[index]}');
       }
     }
-    if (stdoutLog.isEmpty && stderrLog.isEmpty && stdinLog.isEmpty) {
+    if (logs.isEmpty) {
       print('So far nothing has been logged${ debug ? "" : "; use debug:true to print all output" }.');
     } else {
       print('Log${ debug ? "" : " (only contains logged lines; use debug:true to print all output)" }:');
-      stdoutLog.map<String>((String line) => 'stdout: $line').forEach(printClearly);
-      stderrLog.map<String>((String line) => 'stderr: $line').forEach(printClearly);
-      stdinLog.map<String>((String line) => 'stdin: $line').forEach(printClearly);
+      for (final LogLine log in logs) {
+        log.printClearly();
+      }
     }
   }
   bool streamingLogs = false;
@@ -190,28 +218,30 @@ Future<ProcessTestResult> runFlutter(
     if (!streamingLogs) {
       streamingLogs = true;
       if (!debug) {
-        print('Test is taking a long time.');
+        print('Test is taking a long time (${clock.elapsed.inSeconds} seconds so far).');
       }
       describeStatus();
       print('(streaming all logs from this point on...)');
     } else {
       print('(taking a long time...)');
     }
   }
+  String stamp() => '[${(clock.elapsed.inMilliseconds / 1000.0).toStringAsFixed(1).padLeft(5, " ")}s]';
   void processStdout(String line) {
+    final LogLine log = LogLine('stdout', stamp(), line);
     if (logging) {
-      stdoutLog.add(line);
+      logs.add(log);
     }
     if (streamingLogs) {
-      print('stdout: $line');
+      log.printClearly();
     }
     if (nextTransition < transitions.length && transitions[nextTransition].matches(line)) {
       if (streamingLogs) {
         print('(matched ${transitions[nextTransition]})');
       }
       if (transitions[nextTransition].logging != null) {
         if (!logging && transitions[nextTransition].logging/*!*/) {
-          stdoutLog.add(line);
+          logs.add(log);
         }
         logging = transitions[nextTransition].logging/*!*/;
         if (streamingLogs) {
@@ -225,9 +255,10 @@ Future<ProcessTestResult> runFlutter(
       if (transitions[nextTransition].handler != null) {
         final String/*?*/ command = transitions[nextTransition].handler/*!*/(line);
         if (command != null) {
-          stdinLog.add(command);
+          final LogLine inLog = LogLine('stdin', stamp(), command);
+          logs.add(inLog);
           if (streamingLogs) {
-            print('stdin: $command');
+            inLog.printClearly();
           }
           process.stdin.write(command);
         }
@@ -238,9 +269,10 @@ Future<ProcessTestResult> runFlutter(
     }
   }
   void processStderr(String line) {
-    stderrLog.add(line);
+    final LogLine log = LogLine('stdout', stamp(), line);
+    logs.add(log);
     if (streamingLogs) {
-      print('stderr: $line');
+      log.printClearly();
     }
   }
   if (debug) {
@@ -251,19 +283,24 @@ Future<ProcessTestResult> runFlutter(
   process.stdout.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(processStdout);
   process.stderr.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(processStderr);
   unawaited(process.exitCode.timeout(expectedMaxDuration, onTimeout: () {
-    print('(process is not quitting, trying to send a "q" just in case that helps)');
+    print('${stamp()} (process is not quitting, trying to send a "q" just in case that helps)');
     print('(a functional test should never reach this point)');
+    final LogLine inLog = LogLine('stdin', stamp(), 'q');
+    logs.add(inLog);
+    if (streamingLogs) {
+      inLog.printClearly();
+    }
     process.stdin.write('q');
-    return null;
+    return -1; // discarded
   }).catchError((Object error) { /* ignore the error here, it'll be reported on the next line */ }));
   final int exitCode = await process.exitCode;
   if (streamingLogs) {
-    print('(process terminated with exit code $exitCode)');
+    print('${stamp()} (process terminated with exit code $exitCode)');
   }
   timeout?.cancel();
   if (nextTransition < transitions.length) {
     print('The subprocess terminated before all the expected transitions had been matched.');
-    if (stderrLog.any((String line) => line.contains('Oops; flutter has exited unexpectedly:'))) {
+    if (logs.any((LogLine line) => line.couldBeCrash)) {
       print('The subprocess may in fact have crashed. Check the stderr logs below.');
     }
     print('The transition that we were hoping to see next but that we never saw was:');
@@ -275,9 +312,9 @@ Future<ProcessTestResult> runFlutter(
     throw TestFailure('Missed some expected transitions.');
   }
   if (streamingLogs) {
-    print('(completed execution successfully!)');
+    print('${stamp()} (completed execution successfully!)');
   }
-  return ProcessTestResult(exitCode, stdoutLog, stderrLog);
+  return ProcessTestResult(exitCode, logs);
 }
 
 const int progressMessageWidth = 64;