Provide a subset of adb logcat logs streaming during scenario_app testing (#50886)

Work towards flutter/flutter#143458.

What this _doesn't_ change:

1. The full output of `adb logcat` is still written to `$FLUTTER_LOGS_DIR/logcat.txt`

Example output:

<img width="580" alt="Screenshot 2024-02-22 at 2 53 51�PM" src="https://github.com/flutter/engine/assets/168174/bef24370-c066-4203-ae0e-552cc0fd73ad">

/cc @dnfield @gaaclarke

Author: matanlurey

testing/scenario_app/bin/README.md

@@ -24,6 +24,8 @@ dart bin/android_integration_tests.dart --smoke-test dev.flutter.scenarios.Engin
 
 ## Additional arguments
 
+- `--verbose`: Print additional information about the test run.
+
 - `--adb`: The path to the `adb` tool. Defaults to
   `third_party/android_tools/sdk/platform-tools/adb`.
 

testing/scenario_app/bin/android_integration_tests.dart

@@ -14,6 +14,7 @@ import 'package:path/path.dart';
 import 'package:process/process.dart';
 import 'package:skia_gold_client/skia_gold_client.dart';
 
+import 'utils/adb_logcat_filtering.dart';
 import 'utils/logs.dart';
 import 'utils/process_manager_extension.dart';
 import 'utils/screenshot_transformer.dart';
@@ -38,6 +39,11 @@ void main(List<String> args) async {
       help: 'Prints usage information',
       negatable: false,
     )
+    ..addFlag(
+      'verbose',
+      help: 'Prints verbose output',
+      negatable: false,
+    )
     ..addOption(
       'adb',
       help: 'Absolute path to the adb tool',
@@ -74,8 +80,8 @@ void main(List<String> args) async {
       help: 'Enable Impeller for the Android app.',
     )
     ..addOption('output-contents-golden',
-      help:
-        'Path to a file that will be used to check the contents of the output to make sure everything was created.')
+      help: 'Path to a file that will be used to check the contents of the output to make sure everything was created.',
+    )
     ..addOption(
       'impeller-backend',
       help: 'The Impeller backend to use for the Android app.',
@@ -105,6 +111,7 @@ void main(List<String> args) async {
         panic(<String>['--adb is required']);
       }
 
+      final bool verbose = results['verbose'] as bool;
       final Directory outDir = Directory(results['out-dir'] as String);
       final File adb = File(results['adb'] as String);
       final bool useSkiaGold = results['use-skia-gold'] as bool;
@@ -117,6 +124,7 @@ void main(List<String> args) async {
       }
       final Directory logsDir = Directory(results['logs-dir'] as String? ?? join(outDir.path, 'scenario_app', 'logs'));
       await _run(
+        verbose: verbose,
         outDir: outDir,
         adb: adb,
         smokeTestFullPath: smokeTest,
@@ -155,6 +163,7 @@ enum _ImpellerBackend {
 }
 
 Future<void> _run({
+  required bool verbose,
   required Directory outDir,
   required File adb,
   required String? smokeTestFullPath,
@@ -201,21 +210,29 @@ Future<void> _run({
   final List<Future<void>> pendingComparisons = <Future<void>>[];
   await step('Starting server...', () async {
     server = await ServerSocket.bind(InternetAddress.anyIPv4, _tcpPort);
-    stdout.writeln('listening on host ${server.address.address}:${server.port}');
+    if (verbose) {
+      stdout.writeln('listening on host ${server.address.address}:${server.port}');
+    }
     server.listen((Socket client) {
-      stdout.writeln('client connected ${client.remoteAddress.address}:${client.remotePort}');
+      if (verbose) {
+        stdout.writeln('client connected ${client.remoteAddress.address}:${client.remotePort}');
+      }
       client.transform(const ScreenshotBlobTransformer()).listen((Screenshot screenshot) {
         final String fileName = screenshot.filename;
         final Uint8List fileContent = screenshot.fileContent;
-        log('host received ${fileContent.lengthInBytes} bytes for screenshot `$fileName`');
+        if (verbose) {
+          log('host received ${fileContent.lengthInBytes} bytes for screenshot `$fileName`');
+        }
         assert(skiaGoldClient != null, 'expected Skia Gold client');
         late File goldenFile;
         try {
           goldenFile = File(join(screenshotPath, fileName))..writeAsBytesSync(fileContent, flush: true);
         } on FileSystemException catch (err) {
           panic(<String>['failed to create screenshot $fileName: $err']);
         }
-        log('wrote ${goldenFile.absolute.path}');
+        if (verbose) {
+          log('wrote ${goldenFile.absolute.path}');
+        }
         if (isSkiaGoldClientAvailable) {
           final Future<void> comparison = skiaGoldClient!
             .addImg(fileName, goldenFile,
@@ -247,8 +264,30 @@ Future<void> _run({
       if (exitCode != 0) {
         panic(<String>['could not clear logs']);
       }
+
       logcatProcess = await pm.start(<String>[adb.path, 'logcat', '-T', '1']);
-      logcatProcessExitCode = pipeProcessStreams(logcatProcess, out: logcat);
+      final (Future<int> logcatExitCode, Stream<String> logcatOutput) = getProcessStreams(logcatProcess);
+
+      logcatProcessExitCode = logcatExitCode;
+      logcatOutput.listen((String line) {
+        // Always write to the full log.
+        logcat.writeln(line);
+
+        // Conditionally parse and write to stderr.
+        final AdbLogLine? adbLogLine = AdbLogLine.tryParse(line);
+        switch (adbLogLine?.process) {
+          case null:
+            break;
+          case 'ActivityManager':
+          // TODO(matanlurey): Figure out why this isn't 'flutter.scenario' or similar.
+          // Also, why is there two different names?
+          case 'utter.scenario':
+          case 'utter.scenarios':
+          case 'flutter':
+          case 'FlutterJNI':
+            log('[adb] $line');
+        }
+      });
     });
 
     await step('Configuring emulator...', () async {
@@ -400,6 +439,7 @@ Future<void> _run({
     await step('Flush logcat...', () async {
       await logcat.flush();
       await logcat.close();
+      log('wrote logcat to $logcatPath');
     });
   }
 }

testing/scenario_app/bin/utils/adb_logcat_filtering.dart

@@ -0,0 +1,68 @@
+/// Some notes about filtering `adb logcat` output, especially as a result of
+/// running `adb shell` to instrument the app and test scripts, as it's
+/// non-trivial and error-prone.
+///
+/// 1. It's probably worth keeping `ActivityManager` lines unconditionally.
+///    They are the most important ones, and they are not too verbose (for
+///    example, they don't typically contain stack traces).
+///
+/// 2. `ActivityManager` starts with the application name and process ID:
+///
+/// ```txt
+/// [stdout] 02-15 10:20:36.914  1735  1752 I ActivityManager: Start proc 6840:dev.flutter.scenarios/u0a98 for added application dev.flutter.scenarios
+/// ```
+///
+/// The "application" comes from the file `android/app/build.gradle` under
+/// `android > defaultConfig > applicationId`.
+///
+/// 3. Once we have the process ID, we can filter the logcat output further:
+///
+/// ```txt
+/// [stdout] 02-15 10:20:37.430  6840  6840 E GeneratedPluginsRegister: Tried to automatically register plugins with FlutterEngine (io.flutter.embedding.engine.FlutterEngine@144d737) but could not find or invoke the GeneratedPluginRegistrant.
+/// ```
+///
+/// A sample output of `adb logcat` command lives in `./sample_adb_logcat.txt`.
+///
+/// See also: <https://developer.android.com/tools/logcat>.
+library;
+
+/// Represents a line of `adb logcat` output parsed into a structured form.
+///
+/// For example the line:
+/// ```txt
+/// 02-22 13:54:39.839   549  3683 I ActivityManager: Force stopping dev.flutter.scenarios appid=10226 user=0: start instr
+/// ```
+///
+/// ## Implementation notes
+///
+/// The reason this is an extension type and not a class is partially to use the
+/// language feature, and partially because extension types work really well
+/// with lazy parsing.
+extension type const AdbLogLine._(Match _match) {
+  // RegEx that parses into the following groups:
+  // 1. Everything up to the severity (I, W, E, etc.).
+  //    In other words, any whitespace, numbers, hyphens, colons, and periods.
+  // 2. The severity (a single uppercase letter).
+  // 3. The name of the process (up to the colon).
+  // 4. The message (after the colon).
+  //
+  // This regex is simple versus being more precise. Feel free to improve it.
+  static final RegExp _pattern = RegExp(r'([^A-Z]*)([A-Z])\s([^:]*)\:\s(.*)');
+
+  /// Parses the given [adbLogCatLine] into a structured form.
+  ///
+  /// Returns `null` if the line does not match the expected format.
+  static AdbLogLine? tryParse(String adbLogCatLine) {
+    final Match? match = _pattern.firstMatch(adbLogCatLine);
+    return match == null ? null : AdbLogLine._(match);
+  }
+
+  /// The full line of `adb logcat` output.
+  String get line => _match.group(0)!;
+
+  /// The process name, such as `ActivityManager`.
+  String get process => _match.group(3)!;
+
+  /// The actual log message.
+  String get message => _match.group(4)!;
+}

testing/scenario_app/bin/utils/process_manager_extension.dart

@@ -8,35 +8,50 @@ import 'dart:io';
 
 import 'package:process/process.dart';
 
-/// Pipes the [process] streams and writes them to [out] sink.
-/// If [out] is null, then the current [Process.stdout] is used as the sink.
-Future<int> pipeProcessStreams(
-  Process process, {
-  StringSink? out,
-}) async {
-  out ??= stdout;
+(Future<int> exitCode, Stream<String> output) getProcessStreams(
+  Process process,
+) {
   final Completer<void> stdoutCompleter = Completer<void>();
-  final StreamSubscription<String> stdoutSub = process.stdout
+  final Completer<void> stderrCompleter = Completer<void>();
+  final StreamController<String> outputController = StreamController<String>();
+
+  final StreamSubscription<void> stdoutSub = process.stdout
     .transform(utf8.decoder)
     .transform<String>(const LineSplitter())
-    .listen((String line) {
-      out!.writeln('[stdout] $line');
-    }, onDone: stdoutCompleter.complete);
+    .listen(outputController.add, onDone: stdoutCompleter.complete);
 
-  final Completer<void> stderrCompleter = Completer<void>();
-  final StreamSubscription<String> stderrSub = process.stderr
+  // From looking at historic logs, it seems that the stderr output is rare.
+  // Instead of prefacing every line with [stdout] unnecessarily, we'll just
+  // use [stderr] to indicate that it's from the stderr stream.
+  //
+  // For example, a historic log which has 0 occurrences of stderr:
+  // https://gist.github.com/matanlurey/84cf9c903ef6d507dcb63d4c303ca45f
+  final StreamSubscription<void> stderrSub = process.stderr
     .transform(utf8.decoder)
     .transform<String>(const LineSplitter())
-    .listen((String line) {
-      out!.writeln('[stderr] $line');
-    }, onDone: stderrCompleter.complete);
+    .map((String line) => '[stderr] $line')
+    .listen(outputController.add, onDone: stderrCompleter.complete);
 
-  final int exitCode = await process.exitCode;
-  await stderrSub.cancel();
-  await stdoutSub.cancel();
+  final Future<int> exitCode = process.exitCode.then<int>((int code) async {
+    await (stdoutSub.cancel(), stderrSub.cancel()).wait;
+    outputController.close();
+    return code;
+  });
+
+  return (exitCode, outputController.stream);
+}
+
+/// Pipes the [process] streams and writes them to [out] sink.
+///
+/// If [out] is null, then the current [Process.stdout] is used as the sink.
+Future<int> pipeProcessStreams(
+  Process process, {
+  StringSink? out,
+}) async {
+  out ??= stdout;
 
-  await stdoutCompleter.future;
-  await stderrCompleter.future;
+  final (Future<int> exitCode, Stream<String> output) = getProcessStreams(process);
+  output.listen(out.writeln);
   return exitCode;
 }