Simplify logging code in flutter_driver (#45945)

* Simplify logging code in flutter_driver

It appears nobody is benefitting from this logic, so we may as well not pay the cost.

* Make all of the driver interface public.

This is the second attempt at this; it should be better than before because the Logger interface, which conflicted in various places, no longer exists.

See #45733 for original attempt.

This reverts commit 0ce9206e (PR #45924).

packages/flutter_driver/lib/driver_extension.dart

@@ -24,4 +24,4 @@
 ///     }
 library flutter_driver_extension;
 
-export 'src/extension/extension.dart' show enableFlutterDriverExtension, DataHandler;
+export 'src/extension/extension.dart';

packages/flutter_driver/lib/flutter_driver.dart

@@ -11,39 +11,22 @@
 /// Protractor (Angular), Espresso (Android) or Earl Gray (iOS).
 library flutter_driver;
 
-export 'src/common/error.dart' show
-  DriverError,
-  LogLevel,
-  LogRecord,
-  flutterDriverLog;
-export 'src/common/find.dart' show
-  SerializableFinder;
-export 'src/common/health.dart' show
-  Health,
-  HealthStatus;
-export 'src/common/message.dart' show
-  Command,
-  Result;
-export 'src/common/render_tree.dart' show
-  RenderTree;
-export 'src/common/wait.dart' show
-  CombinedCondition,
-  FirstFrameRasterized,
-  NoPendingFrame,
-  NoPendingPlatformMessages,
-  NoTransientCallbacks,
-  SerializableWaitCondition;
-export 'src/driver/common.dart' show
-  testOutputsDirectory;
-export 'src/driver/driver.dart' show
-  find,
-  CommonFinders,
-  EvaluatorFunction,
-  FlutterDriver,
-  TimelineStream;
-export 'src/driver/timeline.dart' show
-  Timeline,
-  TimelineEvent;
-export 'src/driver/timeline_summary.dart' show
-  TimelineSummary,
-  kBuildBudget;
+export 'src/common/diagnostics_tree.dart';
+export 'src/common/enum_util.dart';
+export 'src/common/error.dart';
+export 'src/common/find.dart';
+export 'src/common/frame_sync.dart';
+export 'src/common/fuchsia_compat.dart';
+export 'src/common/geometry.dart';
+export 'src/common/gesture.dart';
+export 'src/common/health.dart';
+export 'src/common/message.dart';
+export 'src/common/render_tree.dart';
+export 'src/common/request_data.dart';
+export 'src/common/semantics.dart';
+export 'src/common/text.dart';
+export 'src/common/wait.dart';
+export 'src/driver/common.dart';
+export 'src/driver/driver.dart';
+export 'src/driver/timeline.dart';
+export 'src/driver/timeline_summary.dart';

packages/flutter_driver/lib/src/common/error.dart

@@ -2,7 +2,6 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
-import 'dart:async';
 import 'dart:io' show stderr;
 
 /// Standard error thrown by Flutter Driver API.
@@ -14,14 +13,16 @@ class DriverError extends Error {
   /// Human-readable error message.
   final String message;
 
-  /// The error object that was caught and wrapped by this error object.
+  /// The error object that was caught and wrapped by this error object, if any.
   final dynamic originalError;
 
-  /// The stack trace that was caught and wrapped by this error object.
+  /// The stack trace that was caught and wrapped by this error object, if any.
   final dynamic originalStackTrace;
 
   @override
   String toString() {
+    if (originalError == null)
+      return 'DriverError: $message\n';
     return '''DriverError: $message
 Original error: $originalError
 Original stack trace:
@@ -30,122 +31,24 @@ $originalStackTrace
   }
 }
 
-// Whether someone redirected the log messages somewhere.
-bool _noLogSubscribers = true;
-
-final StreamController<LogRecord> _logger =
-  StreamController<LogRecord>.broadcast(sync: true, onListen: () {
-    _noLogSubscribers = false;
-  });
-
-void _log(LogLevel level, String loggerName, Object message) {
-  final LogRecord record = LogRecord._(level, loggerName, '$message');
-  // If nobody expressed interest in rerouting log messages somewhere specific,
-  // print them to stderr.
-  if (_noLogSubscribers)
-    stderr.writeln(record);
-  else
-    _logger.add(record);
-}
-
-/// Emits log records from Flutter Driver.
-final Stream<LogRecord> flutterDriverLog = _logger.stream;
-
-/// Severity of a log entry.
-enum LogLevel {
-  /// Messages used to supplement the higher-level messages with more details.
-  ///
-  /// This will likely produce a lot of output.
-  trace,
-
-  /// Informational messages that do not indicate a problem.
-  info,
-
-  /// A potential problem.
-  warning,
-
-  /// A certain problem but the program will attempt to continue.
-  error,
-
-  /// A critical problem; the program will attempt to quit immediately.
-  critical,
-}
-
-/// A log entry, as emitted on [flutterDriverLog].
-class LogRecord {
-  const LogRecord._(this.level, this.loggerName, this.message);
-
-  /// The severity of the log record.
-  final LogLevel level;
-
-  /// The name of the logger that logged the message.
-  final String loggerName;
-
-  /// The log message.
-  ///
-  /// The message should be a normal and complete sentence ending with a period.
-  /// It is OK to omit the subject in the message to imply [loggerName]. It is
-  /// also OK to omit article, such as "the" and "a".
-  ///
-  /// Example: if [loggerName] is "FlutterDriver" and [message] is "Failed to
-  /// connect to application." then this log record means that FlutterDriver
-  /// failed to connect to the application.
-  final String message;
-
-  /// Short description of the log level.
-  ///
-  /// It is meant to be read by humans. There's no guarantee that this value is
-  /// stable enough to be parsed by machines.
-  String get levelDescription => level.toString().split('.').last;
-
-  @override
-  String toString() => '[${levelDescription.padRight(5)}] $loggerName: $message';
-}
-
-/// Logger used internally by Flutter Driver to avoid mandating any specific
-/// logging library.
+/// Signature for [driverLog].
 ///
-/// By default the output from this logger is printed to [stderr]. However, a
-/// subscriber to the [flutterDriverLog] stream may redirect the log records
-/// elsewhere, including other logging API. The logger stops sending messages to
-/// [stderr] upon first subscriber.
+/// The first argument is a string representing the source of the message,
+/// typically the class name or library name calling the method.
 ///
-/// This class is package-private. Flutter users should use other public logging
-/// libraries.
-class Logger {
-  /// Creates a new logger.
-  Logger(this.name);
-
-  /// Identifies the part of the system that emits message into this object.
-  ///
-  /// It is common for [name] to be used as an implicit subject of an action
-  /// described in a log message. For example, if you emit message "failed" and
-  /// [name] is "FlutterDriver", the meaning of the message should be understood
-  /// as "FlutterDriver failed". See also [LogRecord.message].
-  final String name;
-
-  /// Emits a [LogLevel.trace] record into `this` logger.
-  void trace(Object message) {
-    _log(LogLevel.trace, name, message);
-  }
-
-  /// Emits a [LogLevel.info] record into `this` logger.
-  void info(Object message) {
-    _log(LogLevel.info, name, message);
-  }
-
-  /// Emits a [LogLevel.warning] record into `this` logger.
-  void warning(Object message) {
-    _log(LogLevel.warning, name, message);
-  }
+/// The second argument is the message being logged.
+typedef DriverLogCallback = void Function(String source, String message);
 
-  /// Emits a [LogLevel.error] record into `this` logger.
-  void error(Object message) {
-    _log(LogLevel.error, name, message);
-  }
-
-  /// Emits a [LogLevel.critical] record into `this` logger.
-  void critical(Object message) {
-    _log(LogLevel.critical, name, message);
-  }
-}
+/// Print the given message to the console.
+///
+/// The first argument is a string representing the source of the message.
+///
+/// The second argument is the message being logged.
+///
+/// This can be set to a different callback to override the handling of log
+/// messages from the driver subsystem.
+///
+/// The default implementation prints `"$source: $message"` to stderr.
+DriverLogCallback driverLog = (String source, String message) {
+  stderr.writeln('$source: $message');
+};

packages/flutter_driver/lib/src/common/fuchsia_compat.dart

@@ -32,7 +32,9 @@ class _DummyPortForwarder implements PortForwarder {
 class _DummySshCommandRunner implements SshCommandRunner {
   _DummySshCommandRunner();
 
-  final Logger _log = Logger('_DummySshCommandRunner');
+  void _log(String message) {
+    driverLog('_DummySshCommandRunner', message);
+  }
 
   @override
   String get sshConfigPath => null;
@@ -58,7 +60,7 @@ class _DummySshCommandRunner implements SshCommandRunner {
       final ProcessResult r = await Process.run(exe, args);
       return r.stdout.split('\n');
     } on ProcessException catch (e) {
-      _log.warning("Error running '$command': $e");
+      _log("Error running '$command': $e");
     }
     return <String>[];
   }

packages/flutter_driver/lib/src/driver/driver.dart

@@ -93,7 +93,9 @@ String _timelineStreamsToString(List<TimelineStream> streams) {
   return '[$contents]';
 }
 
-final Logger _log = Logger('FlutterDriver');
+void _log(String message) {
+  driverLog('FlutterDriver', message);
+}
 
 Future<T> _warnIfSlow<T>({
   @required Future<T> future,
@@ -103,7 +105,7 @@ Future<T> _warnIfSlow<T>({
   assert(future != null);
   assert(timeout != null);
   assert(message != null);
-  return future..timeout(timeout, onTimeout: () { _log.warning(message); return null; });
+  return future..timeout(timeout, onTimeout: () { _log(message); return null; });
 }
 
 /// A convenient accessor to frequently used finders.
@@ -201,9 +203,12 @@ class FlutterDriver {
     // If the user has already supplied an isolate number/URL to the Dart VM
     // service, then this won't be run as it is unnecessary.
     if (Platform.isFuchsia && isolateNumber == null) {
-      // TODO(awdavies): Use something other than print. On fuchsia
-      // `stderr`/`stdout` appear to have issues working correctly.
-      flutterDriverLog.listen(print);
+      // On Fuchsia stderr/stdout appear to have issues working correctly,
+      // so we work around the issue by using print directly.
+      // TODO(awdavies): Fix Dart or Fuchsia to not need this workaround.
+      driverLog = (String source, String message) {
+        print('$source: $message');
+      };
       fuchsiaModuleTarget ??= Platform.environment['FUCHSIA_MODULE_TARGET'];
       if (fuchsiaModuleTarget == null) {
         throw DriverError(
@@ -234,7 +239,7 @@ class FlutterDriver {
     }
 
     // Connect to Dart VM services
-    _log.info('Connecting to Flutter application at $dartVmServiceUrl');
+    _log('Connecting to Flutter application at $dartVmServiceUrl');
     final VMServiceClientConnection connection =
         await vmServiceConnectFunction(dartVmServiceUrl);
     final VMServiceClient client = connection.client;
@@ -243,7 +248,7 @@ class FlutterDriver {
         null ? vm.isolates.first :
                vm.isolates.firstWhere(
                    (VMIsolateRef isolate) => isolate.number == isolateNumber);
-    _log.trace('Isolate found with number: ${isolateRef.number}');
+    _log('Isolate found with number: ${isolateRef.number}');
 
     VMIsolate isolate = await isolateRef.loadRunnable();
 
@@ -275,12 +280,12 @@ class FlutterDriver {
     // the isolate is already resumed. There could be a race with other tools,
     // such as a debugger, any of which could have resumed the isolate.
     Future<dynamic> resumeLeniently() {
-      _log.trace('Attempting to resume isolate');
+      _log('Attempting to resume isolate...');
       return isolate.resume().catchError((dynamic e) {
         const int vmMustBePausedCode = 101;
         if (e is rpc.RpcException && e.code == vmMustBePausedCode) {
           // No biggie; something else must have resumed the isolate
-          _log.warning(
+          _log(
             'Attempted to resume an already resumed isolate. This may happen '
             'when we lose a race with another tool (usually a debugger) that '
             'is connected to the same isolate.'
@@ -315,7 +320,7 @@ class FlutterDriver {
 
     // Attempt to resume isolate if it was paused
     if (isolate.pauseEvent is VMPauseStartEvent) {
-      _log.trace('Isolate is paused at start.');
+      _log('Isolate is paused at start.');
 
       // If the isolate is paused at the start, e.g. via the --start-paused
       // option, then the VM service extension is not registered yet. Wait for
@@ -325,7 +330,7 @@ class FlutterDriver {
       final Future<dynamic> whenResumed = resumeLeniently();
       await whenResumed;
 
-      _log.trace('Waiting for service extension');
+      _log('Waiting for service extension...');
       // We will never receive the extension event if the user does not
       // register it. If that happens, show a message but continue waiting.
       await _warnIfSlow<String>(
@@ -342,12 +347,12 @@ class FlutterDriver {
                isolate.pauseEvent is VMPauseInterruptedEvent) {
       // If the isolate is paused for any other reason, assume the extension is
       // already there.
-      _log.trace('Isolate is paused mid-flight.');
+      _log('Isolate is paused mid-flight.');
       await resumeLeniently();
     } else if (isolate.pauseEvent is VMResumeEvent) {
-      _log.trace('Isolate is not paused. Assuming application is ready.');
+      _log('Isolate is not paused. Assuming application is ready.');
     } else {
-      _log.warning(
+      _log(
         'Unknown pause event type ${isolate.pauseEvent.runtimeType}. '
         'Assuming application is ready.'
       );
@@ -363,10 +368,7 @@ class FlutterDriver {
         if (e.code != error_code.METHOD_NOT_FOUND) {
           rethrow;
         }
-        _log.trace(
-          'Check Health failed, try to wait for the service extensions to be'
-          'registered.'
-        );
+        _log('Check Health failed, try to wait for the service extensions to be registered.');
         await enableIsolateStreams();
         await waitForServiceExtension();
         return driver.checkHealth();
@@ -379,7 +381,7 @@ class FlutterDriver {
       throw DriverError('Flutter application health check failed.');
     }
 
-    _log.info('Connected to Flutter application.');
+    _log('Connected to Flutter application.');
     return driver;
   }
 
@@ -403,11 +405,7 @@ class FlutterDriver {
     if (!_peer.isClosed || _dartVmReconnectUrl == null) {
       return;
     }
-
-    _log.warning(
-        'Peer connection is closed! Trying to restore the connection...'
-    );
-
+    _log('Peer connection is closed! Trying to restore the connection...');
     final String webSocketUrl = _getWebSocketUrl(_dartVmReconnectUrl);
     final WebSocket ws = await WebSocket.connect(webSocketUrl);
     ws.done.whenComplete(() => _checkCloseCode(ws));
@@ -459,7 +457,7 @@ class FlutterDriver {
 
   void _logCommunication(String message) {
     if (_printCommunication)
-      _log.info(message);
+      _log(message);
     if (_logCommunicationToFile) {
       final f.File file = fs.file(p.join(testOutputsDirectory, 'flutter_driver_commands_$_driverId.log'));
       file.createSync(recursive: true); // no-op if file exists
@@ -975,7 +973,7 @@ class FlutterDriver {
     await action();
 
     if (!(await _isPrecompiledMode())) {
-      _log.warning(_kDebugWarning);
+      _log(_kDebugWarning);
     }
     return stopTracingAndDownloadTimeline();
   }
@@ -1116,7 +1114,7 @@ void _unhandledJsonRpcError(dynamic error, dynamic stack) {
   if (_ignoreRpcError(error)) {
     return;
   }
-  _log.trace('Unhandled RPC error:\n$error\n$stack');
+  _log('Unhandled RPC error:\n$error\n$stack');
   // TODO(dnfield): https://github.com/flutter/flutter/issues/31813
   // assert(false);
 }
@@ -1135,7 +1133,7 @@ String _getWebSocketUrl(String url) {
 
 void _checkCloseCode(WebSocket ws) {
   if (ws.closeCode != 1000 && ws.closeCode != null) {
-    _log.warning('$ws is closed with an unexpected code ${ws.closeCode}');
+    _log('$ws is closed with an unexpected code ${ws.closeCode}');
   }
 }
 
@@ -1165,7 +1163,7 @@ Future<VMServiceClientConnection> _waitAndConnect(String url) async {
       await ws1?.close();
       await ws2?.close();
       if (attempts > 5)
-        _log.warning('It is taking an unusually long time to connect to the VM...');
+        _log('It is taking an unusually long time to connect to the VM...');
       attempts += 1;
       await Future<void>.delayed(_kPauseBetweenReconnectAttempts);
     }
@@ -1248,5 +1246,5 @@ class DriverOffset {
   }
 
   @override
-  int get hashCode => dx.hashCode + dy.hashCode;
+  int get hashCode => dx.hashCode ^ dy.hashCode;
 }

packages/flutter_driver/lib/src/extension/extension.dart

@@ -168,7 +168,9 @@ class FlutterDriverExtension {
   final DataHandler _requestDataHandler;
   final bool _silenceErrors;
 
-  static final Logger _log = Logger('FlutterDriverExtension');
+  void _log(String message) {
+    driverLog('FlutterDriverExtension', message);
+  }
 
   final WidgetController _prober = LiveWidgetController(WidgetsBinding.instance);
   final Map<String, CommandHandlerCallback> _commandHandlers = <String, CommandHandlerCallback>{};
@@ -207,14 +209,14 @@ class FlutterDriverExtension {
       final Result response = await responseFuture;
       return _makeResponse(response?.toJson());
     } on TimeoutException catch (error, stackTrace) {
-      final String msg = 'Timeout while executing $commandKind: $error\n$stackTrace';
-      _log.error(msg);
-      return _makeResponse(msg, isError: true);
+      final String message = 'Timeout while executing $commandKind: $error\n$stackTrace';
+      _log(message);
+      return _makeResponse(message, isError: true);
     } catch (error, stackTrace) {
-      final String msg = 'Uncaught extension error while executing $commandKind: $error\n$stackTrace';
+      final String message = 'Uncaught extension error while executing $commandKind: $error\n$stackTrace';
       if (!_silenceErrors)
-        _log.error(msg);
-      return _makeResponse(msg, isError: true);
+        _log(message);
+      return _makeResponse(message, isError: true);
     }
   }
 

packages/flutter_driver/test/flutter_driver_test.dart

@@ -21,21 +21,23 @@ const Duration _kTestTimeout = Duration(milliseconds: 1234);
 const String _kSerializedTestTimeout = '1234';
 
 void main() {
+  final List<String> log = <String>[];
+  driverLog = (String source, String message) {
+    log.add('$source: $message');
+  };
+
   group('FlutterDriver.connect', () {
-    List<LogRecord> log;
-    StreamSubscription<LogRecord> logSub;
     MockVMServiceClient mockClient;
     MockVM mockVM;
     MockIsolate mockIsolate;
     MockPeer mockPeer;
 
     void expectLogContains(String message) {
-      expect(log.map<String>((LogRecord r) => '$r'), anyElement(contains(message)));
+      expect(log, anyElement(contains(message)));
     }
 
     setUp(() {
-      log = <LogRecord>[];
-      logSub = flutterDriverLog.listen(log.add);
+      log.clear();
       mockClient = MockVMServiceClient();
       mockVM = MockVM();
       mockIsolate = MockIsolate();
@@ -53,7 +55,6 @@ void main() {
     });
 
     tearDown(() async {
-      await logSub.cancel();
       restoreVmServiceConnectFunction();
     });
 
@@ -548,8 +549,7 @@ void main() {
 
     group('sendCommand error conditions', () {
       test('local default timeout', () async {
-        final List<String> log = <String>[];
-        final StreamSubscription<LogRecord> logSub = flutterDriverLog.listen((LogRecord s) => log.add(s.toString()));
+        log.clear();
         when(mockIsolate.invokeExtension(any, any)).thenAnswer((Invocation i) {
           // completer never completed to trigger timeout
           return Completer<Map<String, dynamic>>().future;
@@ -559,13 +559,11 @@ void main() {
           expect(log, <String>[]);
           time.elapse(kUnusuallyLongTimeout);
         });
-        expect(log, <String>['[warning] FlutterDriver: waitFor message is taking a long time to complete...']);
-        await logSub.cancel();
+        expect(log, <String>['FlutterDriver: waitFor message is taking a long time to complete...']);
       });
 
       test('local custom timeout', () async {
-        final List<String> log = <String>[];
-        final StreamSubscription<LogRecord> logSub = flutterDriverLog.listen((LogRecord s) => log.add(s.toString()));
+        log.clear();
         when(mockIsolate.invokeExtension(any, any)).thenAnswer((Invocation i) {
           // completer never completed to trigger timeout
           return Completer<Map<String, dynamic>>().future;
@@ -576,8 +574,7 @@ void main() {
           expect(log, <String>[]);
           time.elapse(customTimeout);
         });
-        expect(log, <String>['[warning] FlutterDriver: waitFor message is taking a long time to complete...']);
-        await logSub.cancel();
+        expect(log, <String>['FlutterDriver: waitFor message is taking a long time to complete...']);
       });
 
       test('remote error', () async {

packages/flutter_driver/test/src/extension_test.dart

@@ -2,6 +2,7 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+import 'package:flutter/foundation.dart';
 import 'package:flutter/material.dart';
 import 'package:flutter/rendering.dart';
 import 'package:flutter/scheduler.dart';
@@ -17,6 +18,16 @@ import 'package:flutter_driver/src/common/wait.dart';
 import 'package:flutter_driver/src/extension/extension.dart';
 import 'package:flutter_test/flutter_test.dart';
 
+Future<void> silenceDriverLogger(AsyncCallback callback) async {
+  final DriverLogCallback oldLogger = driverLog;
+  driverLog = (String source, String message) { };
+  try {
+    await callback();
+  } finally {
+    driverLog = oldLogger;
+  }
+}
+
 void main() {
   group('waitUntilNoTransientCallbacks', () {
     FlutterDriverExtension extension;
@@ -530,7 +541,7 @@ void main() {
   });
 
   testWidgets('descendant finder', (WidgetTester tester) async {
-    flutterDriverLog.listen((LogRecord _) {}); // Silence logging.
+    await silenceDriverLogger(() async {
       final FlutterDriverExtension extension = FlutterDriverExtension((String arg) async => '', true);
 
       Future<String> getDescendantText({ String of, bool matchRoot = false}) async {
@@ -572,9 +583,10 @@ void main() {
       await tester.pump(const Duration(seconds: 2));
       expect(await result, null);
     });
+  });
 
   testWidgets('descendant finder firstMatchOnly', (WidgetTester tester) async {
-    flutterDriverLog.listen((LogRecord _) {}); // Silence logging.
+    await silenceDriverLogger(() async {
       final FlutterDriverExtension extension = FlutterDriverExtension((String arg) async => '', true);
 
       Future<String> getDescendantText() async {
@@ -605,9 +617,10 @@ void main() {
 
       expect(await getDescendantText(), 'Hello1');
     });
+  });
 
   testWidgets('ancestor finder', (WidgetTester tester) async {
-    flutterDriverLog.listen((LogRecord _) {}); // Silence logging.
+    await silenceDriverLogger(() async {
       final FlutterDriverExtension extension = FlutterDriverExtension((String arg) async => '', true);
 
       Future<Offset> getAncestorTopLeft({ String of, String matching, bool matchRoot = false}) async {
@@ -674,9 +687,10 @@ void main() {
       await tester.pump(const Duration(seconds: 2));
       expect(await result, null);
     });
+  });
 
   testWidgets('ancestor finder firstMatchOnly', (WidgetTester tester) async {
-    flutterDriverLog.listen((LogRecord _) {}); // Silence logging.
+    await silenceDriverLogger(() async {
       final FlutterDriverExtension extension = FlutterDriverExtension((String arg) async => '', true);
 
       Future<Offset> getAncestorTopLeft() async {
@@ -722,6 +736,7 @@ void main() {
         const Offset((800 - 100) / 2, (600 - 100) / 2),
       );
     });
+  });
 
   testWidgets('GetDiagnosticsTree', (WidgetTester tester) async {
     final FlutterDriverExtension extension = FlutterDriverExtension((String arg) async => '', true);