[flutter_tools] prevent StateError when log reader is disposed (#52173)

Previously the AdbLogReader did async setup in the StreamController.onListen callback, specifically it would query the api version and start the adb process. If the log subscription was cancelled before this setup completed, then the log output could (haven't confirmed) get added to a closed controller, causing the above state error. 

packages/flutter_tools/lib/src/android/android_device.dart

@@ -5,6 +5,7 @@
 import 'dart:async';
 
 import 'package:meta/meta.dart';
+import 'package:process/process.dart';
 
 import '../android/android_builder.dart';
 import '../android/android_sdk.dart';
@@ -219,13 +220,14 @@ class AndroidDevice extends Device {
 
   @override
   Future<String> get sdkNameAndVersion async =>
-      'Android ${await _sdkVersion} (API ${await _apiVersion})';
+      'Android ${await _sdkVersion} (API ${await apiVersion})';
 
   Future<String> get _sdkVersion => _getProperty('ro.build.version.release');
 
-  Future<String> get _apiVersion => _getProperty('ro.build.version.sdk');
+  @visibleForTesting
+  Future<String> get apiVersion => _getProperty('ro.build.version.sdk');
 
-  _AdbLogReader _logReader;
+  AdbLogReader _logReader;
   _AndroidDevicePortForwarder _portForwarder;
 
   List<String> adbCommandForDevice(List<String> args) {
@@ -554,7 +556,7 @@ class AndroidDevice extends Device {
       // TODO(devoncarew): Remember the forwarding information (so we can later remove the
       // port forwarding or set it up again when adb fails on us).
       observatoryDiscovery = ProtocolDiscovery.observatory(
-        getLogReader(),
+        await getLogReader(),
         portForwarder: portForwarder,
         hostPort: debuggingOptions.hostVmServicePort,
         devicePort: debuggingOptions.deviceVmServicePort,
@@ -677,10 +679,9 @@ class AndroidDevice extends Device {
   }
 
   @override
-  DeviceLogReader getLogReader({ AndroidApk app }) {
+  FutureOr<DeviceLogReader> getLogReader({ AndroidApk app }) async {
     // The Android log reader isn't app-specific.
-    _logReader ??= _AdbLogReader(this);
-    return _logReader;
+    return _logReader ??= await AdbLogReader.createLogReader(this, globals.processManager);
   }
 
   @override
@@ -1013,55 +1014,66 @@ void parseADBDeviceOutput(
 }
 
 /// A log reader that logs from `adb logcat`.
-class _AdbLogReader extends DeviceLogReader {
-  _AdbLogReader(this.device) {
+class AdbLogReader extends DeviceLogReader {
+  AdbLogReader._(this._adbProcess, this.name)  {
     _linesController = StreamController<String>.broadcast(
       onListen: _start,
       onCancel: _stop,
     );
   }
 
-  final AndroidDevice device;
-
-  StreamController<String> _linesController;
-  Process _process;
+  @visibleForTesting
+  factory AdbLogReader.test(Process adbProcess, String name) = AdbLogReader._;
 
-  @override
-  Stream<String> get logLines => _linesController.stream;
-
-  @override
-  String get name => device.name;
-
-  Future<void> _start() async {
-    final String lastTimestamp = device.lastLogcatTimestamp;
-    // Start the adb logcat process and filter the most recent logs since `lastTimestamp`.
-    final List<String> args = <String>[
-      'logcat',
-      '-v',
-      'time',
-    ];
+  /// Create a new [AdbLogReader] from an [AndroidDevice] instance.
+  static Future<AdbLogReader> createLogReader(
+    AndroidDevice device,
+    ProcessManager processManager,
+  ) async {
     // logcat -T is not supported on Android releases before Lollipop.
     const int kLollipopVersionCode = 21;
     final int apiVersion = (String v) {
       // If the API version string isn't found, conservatively assume that the
       // version is less recent than the one we're looking for.
       return v == null ? kLollipopVersionCode - 1 : int.tryParse(v);
-    }(await device._apiVersion);
-    if (apiVersion != null && apiVersion >= kLollipopVersionCode) {
-      args.addAll(<String>[
+    }(await device.apiVersion);
+
+    // Start the adb logcat process and filter the most recent logs since `lastTimestamp`.
+    final List<String> args = <String>[
+      'logcat',
+      '-v',
+      'time',
+      if (apiVersion != null && apiVersion >= kLollipopVersionCode) ...<String>[
+        // Empty `-T` means the timestamp of the logcat command invocation.
         '-T',
-        lastTimestamp ?? '', // Empty `-T` means the timestamp of the logcat command invocation.
-      ]);
+        device.lastLogcatTimestamp ?? '',
+      ],
+    ];
+    final Process process = await processManager.start(device.adbCommandForDevice(args));
+    return AdbLogReader._(process, device.name);
   }
 
-    _process = await processUtils.start(device.adbCommandForDevice(args));
+  final Process _adbProcess;
+
+  @override
+  final String name;
+
+  StreamController<String> _linesController;
+
+  @override
+  Stream<String> get logLines => _linesController.stream;
 
+  void _start() {
     // We expect logcat streams to occasionally contain invalid utf-8,
     // see: https://github.com/flutter/flutter/pull/8864.
     const Utf8Decoder decoder = Utf8Decoder(reportErrors: false);
-    _process.stdout.transform<String>(decoder).transform<String>(const LineSplitter()).listen(_onLine);
-    _process.stderr.transform<String>(decoder).transform<String>(const LineSplitter()).listen(_onLine);
-    unawaited(_process.exitCode.whenComplete(() {
+    _adbProcess.stdout.transform<String>(decoder)
+      .transform<String>(const LineSplitter())
+      .listen(_onLine);
+    _adbProcess.stderr.transform<String>(decoder)
+      .transform<String>(const LineSplitter())
+      .listen(_onLine);
+    unawaited(_adbProcess.exitCode.whenComplete(() {
       if (_linesController.hasListener) {
         _linesController.close();
       }
@@ -1101,6 +1113,11 @@ class _AdbLogReader extends DeviceLogReader {
   // adb logcat. We are currently passing 'time', which has the format:
   // mm-dd hh:mm:ss.milliseconds Priority/Tag( PID): ....
   void _onLine(String line) {
+    // This line might be processed after the subscription is closed but before
+    // adb stops streaming logs.
+    if (_linesController.isClosed) {
+      return;
+    }
     final Match timeMatch = AndroidDevice._timeRegExp.firstMatch(line);
     if (timeMatch == null || line.length == timeMatch.end) {
       return;
@@ -1160,7 +1177,8 @@ class _AdbLogReader extends DeviceLogReader {
   }
 
   void _stop() {
-    _process?.kill();
+    _linesController.close();
+    _adbProcess?.kill();
   }
 
   @override

packages/flutter_tools/lib/src/commands/attach.dart

@@ -245,7 +245,7 @@ class AttachCommand extends FlutterCommand {
       if (observatoryUri == null) {
         final ProtocolDiscovery observatoryDiscovery =
           ProtocolDiscovery.observatory(
-            device.getLogReader(),
+            await device.getLogReader(),
             portForwarder: device.portForwarder,
             ipv6: ipv6,
             devicePort: deviceVmservicePort,

packages/flutter_tools/lib/src/commands/drive.dart

@@ -427,9 +427,8 @@ Future<LaunchResult> _startApp(DriveCommand command, Uri webUri) async {
   globals.printTrace('Starting application.');
 
   // Forward device log messages to the terminal window running the "drive" command.
-  command._deviceLogSubscription = command
-      .device
-      .getLogReader(app: package)
+  final DeviceLogReader logReader = await command.device.getLogReader(app: package);
+  command._deviceLogSubscription = logReader
     .logLines
     .listen(globals.printStatus);
 

packages/flutter_tools/lib/src/commands/logs.dart

@@ -46,7 +46,7 @@ class LogsCommand extends FlutterCommand {
       device.clearLogs();
     }
 
-    final DeviceLogReader logReader = device.getLogReader();
+    final DeviceLogReader logReader = await device.getLogReader();
 
     Cache.releaseLockEarly();
 

packages/flutter_tools/lib/src/device.dart

@@ -383,7 +383,7 @@ abstract class Device {
   /// Get a log reader for this device.
   /// If [app] is specified, this will return a log reader specific to that
   /// application. Otherwise, a global log reader will be returned.
-  DeviceLogReader getLogReader({ covariant ApplicationPackage app });
+  FutureOr<DeviceLogReader> getLogReader({ covariant ApplicationPackage app });
 
   /// Get the port forwarder for this device.
   DevicePortForwarder get portForwarder;

packages/flutter_tools/lib/src/resident_runner.dart

@@ -193,7 +193,7 @@ class FlutterDevice {
       globals.printTrace('Successfully connected to service protocol: $observatoryUri');
 
       vmService = service;
-      device.getLogReader(app: package).connectedVMService = vmService;
+      (await device.getLogReader(app: package)).connectedVMService = vmService;
       completer.complete();
       await subscription.cancel();
     }, onError: (dynamic error) {
@@ -369,11 +369,11 @@ class FlutterDevice {
     return to;
   }
 
-  void startEchoingDeviceLog() {
+  Future<void> startEchoingDeviceLog() async {
     if (_loggingSubscription != null) {
       return;
     }
-    final Stream<String> logStream = device.getLogReader(app: package).logLines;
+    final Stream<String> logStream = (await device.getLogReader(app: package)).logLines;
     if (logStream == null) {
       globals.printError('Failed to read device log stream');
       return;
@@ -393,8 +393,8 @@ class FlutterDevice {
     _loggingSubscription = null;
   }
 
-  void initLogReader() {
-    device.getLogReader(app: package).appPid = vmService.vm.pid;
+  Future<void> initLogReader() async {
+    (await device.getLogReader(app: package)).appPid = vmService.vm.pid;
   }
 
   Future<int> runHot({
@@ -426,7 +426,7 @@ class FlutterDevice {
 
     final Map<String, dynamic> platformArgs = <String, dynamic>{};
 
-    startEchoingDeviceLog();
+    await startEchoingDeviceLog();
 
     // Start the application.
     final Future<LaunchResult> futureResult = device.startApp(
@@ -499,7 +499,7 @@ class FlutterDevice {
       platformArgs['trace-startup'] = coldRunner.traceStartup;
     }
 
-    startEchoingDeviceLog();
+    await startEchoingDeviceLog();
 
     final LaunchResult result = await device.startApp(
       package,

packages/flutter_tools/lib/src/run_cold.dart

@@ -94,7 +94,7 @@ class ColdRunner extends ResidentRunner {
       if (device.vmService == null) {
         continue;
       }
-      device.initLogReader();
+      await device.initLogReader();
       await device.refreshViews();
       globals.printTrace('Connected to ${device.device.name}');
     }
@@ -143,7 +143,7 @@ class ColdRunner extends ResidentRunner {
       return 2;
     }
     for (final FlutterDevice device in flutterDevices) {
-      device.initLogReader();
+      await device.initLogReader();
     }
     await refreshViews();
     for (final FlutterDevice device in flutterDevices) {

packages/flutter_tools/lib/src/run_hot.dart

@@ -239,7 +239,7 @@ class HotRunner extends ResidentRunner {
     }
 
     for (final FlutterDevice device in flutterDevices) {
-      device.initLogReader();
+      await device.initLogReader();
     }
     try {
       final List<Uri> baseUris = await _initDevFS();

packages/flutter_tools/test/general.shard/android/adb_log_reader_test.dart

+// Copyright 2014 The Flutter Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+import 'dart:async';
+
+import 'package:flutter_tools/src/android/android_device.dart';
+import 'package:mockito/mockito.dart';
+
+import '../../src/common.dart';
+import '../../src/context.dart';
+
+const int kLollipopVersionCode = 21;
+const String kLastLogcatTimestamp = '11-27 15:39:04.506';
+
+void main() {
+  testWithoutContext('AdbLogReader calls adb logcat with expected flags apiVersion 21', () async {
+    final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
+      const FakeCommand(
+        command: <String>[
+          'adb',
+          '-s',
+          '1234',
+          'logcat',
+          '-v',
+          'time',
+          '-T',
+          kLastLogcatTimestamp,
+        ],
+      )
+    ]);
+    await AdbLogReader.createLogReader(
+      createMockDevice(kLollipopVersionCode),
+      processManager,
+    );
+
+    expect(processManager.hasRemainingExpectations, false);
+  });
+
+  testWithoutContext('AdbLogReader calls adb logcat with expected flags apiVersion < 21', () async {
+    final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
+      const FakeCommand(
+        command: <String>[
+          'adb',
+          '-s',
+          '1234',
+          'logcat',
+          '-v',
+          'time',
+        ],
+      )
+    ]);
+    await AdbLogReader.createLogReader(
+      createMockDevice(kLollipopVersionCode - 1),
+      processManager,
+    );
+
+    expect(processManager.hasRemainingExpectations, false);
+  });
+
+  testWithoutContext('AdbLogReader calls adb logcat with expected flags null apiVersion', () async {
+    final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
+      const FakeCommand(
+        command: <String>[
+          'adb',
+          '-s',
+          '1234',
+          'logcat',
+          '-v',
+          'time',
+        ],
+      )
+    ]);
+    await AdbLogReader.createLogReader(
+      createMockDevice(null),
+      processManager,
+    );
+
+    expect(processManager.hasRemainingExpectations, false);
+  });
+
+  testWithoutContext('AdbLogReader handles process early exit', () async {
+    final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
+      FakeCommand(
+        command: const <String>[
+          'adb',
+          '-s',
+          '1234',
+          'logcat',
+          '-v',
+          'time',
+        ],
+        completer: Completer<void>.sync(),
+        stdout: 'Hello There\n',
+      )
+    ]);
+    final AdbLogReader logReader = await AdbLogReader.createLogReader(
+      createMockDevice(null),
+      processManager,
+    );
+    final Completer<void> onDone = Completer<void>.sync();
+    logReader.logLines.listen((String _) { }, onDone: onDone.complete);
+
+    logReader.dispose();
+    await onDone.future;
+  });
+}
+
+MockAndroidDevice createMockDevice(int sdkLevel) {
+  final MockAndroidDevice mockAndroidDevice = MockAndroidDevice();
+  when(mockAndroidDevice.apiVersion)
+    .thenAnswer((Invocation invocation) async => sdkLevel.toString());
+  when(mockAndroidDevice.lastLogcatTimestamp).thenReturn(kLastLogcatTimestamp);
+  when(mockAndroidDevice.adbCommandForDevice(any))
+    .thenAnswer((Invocation invocation) => <String>[
+      'adb', '-s', '1234', ...invocation.positionalArguments.first as List<String>
+    ]);
+  return mockAndroidDevice;
+}
+
+class MockAndroidDevice extends Mock implements AndroidDevice {}

packages/flutter_tools/test/general.shard/android/android_device_test.dart

@@ -693,97 +693,6 @@ flutter:
     });
   });
 
-  group('logReader', () {
-    ProcessManager mockProcessManager;
-    AndroidSdk mockAndroidSdk;
-
-    setUp(() {
-      mockAndroidSdk = MockAndroidSdk();
-      mockProcessManager = MockProcessManager();
-    });
-
-    void setupGetprop({int apiVersion}) {
-      when(mockProcessManager.run(
-        argThat(contains('getprop')),
-        stderrEncoding: anyNamed('stderrEncoding'),
-        stdoutEncoding: anyNamed('stdoutEncoding'),
-      )).thenAnswer((_) {
-        final String buf = apiVersion == null
-          ? ''
-          : '[ro.build.version.sdk]: [$apiVersion]\n';
-        final ProcessResult result = ProcessResult(1, 0, buf, '');
-        return Future<ProcessResult>.value(result);
-      });
-    }
-
-    const int kLollipopVersionCode = 21;
-    void callsAdbLogcatCorrectly({int apiVersion}) {
-      testUsingContext('calls adb logcat with expected flags, apiVersion=$apiVersion', () async {
-        const String kLastLogcatTimestamp = '11-27 15:39:04.506';
-        setupGetprop(apiVersion: apiVersion);
-        when(mockAndroidSdk.adbPath).thenReturn('adb');
-        when(mockProcessManager.runSync(<String>[
-          'adb', '-s', '1234', 'shell', '-x', 'logcat', '-v', 'time', '-t', '1',
-        ]))
-          .thenReturn(ProcessResult(0, 0, '$kLastLogcatTimestamp I/flutter: irrelevant', ''));
-
-        final Completer<void> logcatCompleter = Completer<void>();
-        when(mockProcessManager.start(argThat(contains('logcat'))))
-          .thenAnswer((_) {
-            logcatCompleter.complete();
-            return Future<Process>.value(createMockProcess());
-          });
-
-        final AndroidDevice device = AndroidDevice('1234');
-        final DeviceLogReader logReader = device.getLogReader();
-        logReader.logLines.listen((_) {});
-        await logcatCompleter.future;
-
-        verify(mockProcessManager.start(<String>[
-          'adb', '-s', '1234', 'logcat', '-v', 'time',
-          if (apiVersion != null && apiVersion >= kLollipopVersionCode)
-            ...<String>['-T', kLastLogcatTimestamp],
-        ])).called(1);
-      }, overrides: <Type, Generator>{
-        AndroidSdk: () => mockAndroidSdk,
-        ProcessManager: () => mockProcessManager,
-      });
-
-      testUsingContext('calls adb logcat with expected flags when the device logs are empty, apiVersion=$apiVersion', () async {
-        setupGetprop(apiVersion: apiVersion);
-        when(mockAndroidSdk.adbPath).thenReturn('adb');
-        when(mockProcessManager.runSync(<String>[
-          'adb', '-s', '1234', 'shell', '-x', 'logcat', '-v', 'time', '-t', '1',
-        ])).thenReturn(ProcessResult(0, 0, '', ''));
-
-        final Completer<void> logcatCompleter = Completer<void>();
-        when(mockProcessManager.start(argThat(contains('logcat'))))
-          .thenAnswer((_) {
-            logcatCompleter.complete();
-            return Future<Process>.value(createMockProcess());
-          });
-
-        final AndroidDevice device = AndroidDevice('1234');
-        final DeviceLogReader logReader = device.getLogReader();
-        logReader.logLines.listen((_) {});
-        await logcatCompleter.future;
-
-        verify(mockProcessManager.start(<String>[
-          'adb', '-s', '1234', 'logcat', '-v', 'time',
-          if (apiVersion != null && apiVersion >= kLollipopVersionCode)
-            ...<String>['-T', ''],
-        ])).called(1);
-      }, overrides: <Type, Generator>{
-        AndroidSdk: () => mockAndroidSdk,
-        ProcessManager: () => mockProcessManager,
-      });
-    }
-
-    callsAdbLogcatCorrectly(apiVersion: kLollipopVersionCode);
-    callsAdbLogcatCorrectly(apiVersion: kLollipopVersionCode - 1);
-    callsAdbLogcatCorrectly();
-  });
-
   test('Can parse adb shell dumpsys info', () {
     const String exampleOutput = r'''
 Applications Memory Usage (in Kilobytes):

packages/flutter_tools/test/src/fake_process_manager.dart

@@ -165,7 +165,7 @@ class _FakeProcess implements Process {
 
   @override
   bool kill([io.ProcessSignal signal = io.ProcessSignal.sigterm]) {
-    assert(false, 'Process.kill() should not be used directly in flutter_tools.');
+    // Killing a fake process has no effect.
     return false;
   }
 }
@@ -281,7 +281,7 @@ abstract class FakeProcessManager implements ProcessManager {
 
   @override
   bool killPid(int pid, [io.ProcessSignal signal = io.ProcessSignal.sigterm]) {
-    assert(false, 'ProcessManager.killPid() should not be used directly in flutter_tools.');
+    // Killing a fake process has no effect.
     return false;
   }
 }