Improve logging in tests

dwds/lib/src/debugging/inspector.dart

@@ -371,7 +371,7 @@ function($argsString) {
         return instance;
       }
     } catch (e, s) {
-      _logger.log(Level.FINE, 'getObject failed with exception: $e:$s');
+      _logger.fine('getObject $objectId failed', e, s);
       rethrow;
     }
     throw UnsupportedError('Only libraries, instances, classes, and scripts '

dwds/lib/src/handlers/dev_handler.dart

@@ -39,6 +39,8 @@ import 'injector.dart';
 /// Note: this should not be checked in enabled.
 const _enableLogging = false;
 
+final _logger = Logger('DevHandler');
+
 /// SSE handler to enable development features like hot reload and
 /// opening DevTools.
 class DevHandler {
@@ -53,7 +55,6 @@ class DevHandler {
   final _servicesByAppId = <String, AppDebugServices>{};
   final _appConnectionByAppId = <String, AppConnection>{};
   final Stream<BuildResult> buildResults;
-  final _logger = Logger('DevHandler');
   final Future<ChromeConnection> Function() _chromeConnection;
   final ExtensionBackend _extensionBackend;
   final StreamController<DebugConnection> extensionDebugConnections =

dwds/lib/src/services/expression_compiler_service.dart

@@ -351,7 +351,7 @@ class ExpressionCompilerService implements ExpressionCompiler {
 
       return await _assetHandler(request);
     } catch (e, s) {
-      _logger.severe('Error loading $uri: $e:$s');
+      _logger.severe('Error loading $uri', e, s);
       rethrow;
     }
   }

dwds/test/build_daemon_evaluate_test.dart

@@ -39,23 +39,19 @@ class TestSetup {
   ChromeProxyService get service =>
       fetchChromeProxyService(context.debugConnection);
   WipConnection get tabConnection => context.tabConnection;
-
-  /// Redirect the logs for the current zone to emit on failure.
-  ///
-  /// All messages are stored and reported on test failure.
-  /// Needs to be called in both setUpAll() and setUp() to store
-  /// the logs in the current zone.
-  ///
-  /// Note: change 'printOnFailure' to 'print' for debug printing.
-  static void setCurrentLogWriter() {
-    configureLogWriter(
-        customLogWriter: (level, message,
-                {loggerName, error, stackTrace, verbose}) =>
-            printOnFailure('[$level] $loggerName: $message'));
-  }
 }
 
 void main() async {
+  // Enable verbose logging for debugging.
+  var debug = false;
+
+  // Change to 'true' to print expression compiler messages to console.
+  //
+  // Note: expression compiler runs in an isolate, so its output is not
+  // currently redirected to a logger. As a result, it will be printed
+  // regardless of the logger settings.
+  var verboseCompiler = false;
+
   for (var soundNullSafety in [false, true]) {
     var setup = soundNullSafety ? TestSetup.sound() : TestSetup.unsound();
     var context = setup.context;
@@ -79,20 +75,18 @@ void main() async {
 
       group('shared context with evaluation', () {
         setUpAll(() async {
-          TestSetup.setCurrentLogWriter();
+          setCurrentLogWriter(debug: debug);
           await context.setUp(
             enableExpressionEvaluation: true,
-            verbose: false,
+            verboseCompiler: verboseCompiler,
           );
         });
 
         tearDownAll(() async {
           await context.tearDown();
         });
 
-        setUp(() async {
-          TestSetup.setCurrentLogWriter();
-        });
+        setUp(() => setCurrentLogWriter(debug: debug));
 
         group('evaluateInFrame', () {
           VM vm;
@@ -105,6 +99,7 @@ void main() async {
           Stream<Event> stream;
 
           setUp(() async {
+            setCurrentLogWriter(debug: debug);
             vm = await setup.service.getVM();
             isolate = await setup.service.getIsolate(vm.isolates.first.id);
             scripts = await setup.service.getScripts(isolate.id);
@@ -136,7 +131,7 @@ void main() async {
 
               var param = object as InstanceRef;
 
-              expect(
+              await expectLater(
                   () => setup.service.evaluateInFrame(
                         isolate.id,
                         event.topFrame.index,
@@ -520,8 +515,8 @@ void main() async {
               var event = await stream.firstWhere(
                   (event) => event.kind == EventKind.kPauseBreakpoint);
 
-              expect(
-                  () => setup.service
+              await expectLater(
+                  setup.service
                       .evaluateInFrame('bad', event.topFrame.index, 'local'),
                   throwsRPCError);
             });
@@ -533,6 +528,7 @@ void main() async {
           Isolate isolate;
 
           setUp(() async {
+            setCurrentLogWriter(debug: debug);
             vm = await setup.service.getVM();
             isolate = await setup.service.getIsolate(vm.isolates.first.id);
 
@@ -602,20 +598,18 @@ void main() async {
 
       group('shared context with no evaluation', () {
         setUpAll(() async {
-          TestSetup.setCurrentLogWriter();
+          setCurrentLogWriter(debug: debug);
           await context.setUp(
             enableExpressionEvaluation: false,
-            verbose: false,
+            verboseCompiler: verboseCompiler,
           );
         });
 
         tearDownAll(() async {
           await context.tearDown();
         });
 
-        setUp(() async {
-          TestSetup.setCurrentLogWriter();
-        });
+        setUp(() => setCurrentLogWriter(debug: debug));
 
         group('evaluateInFrame', () {
           VM vm;
@@ -645,8 +639,8 @@ void main() async {
               var event = await stream.firstWhere(
                   (event) => event.kind == EventKind.kPauseBreakpoint);
 
-              expect(
-                  () => setup.service.evaluateInFrame(
+              await expectLater(
+                  setup.service.evaluateInFrame(
                       isolate.id, event.topFrame.index, 'local'),
                   throwsRPCError);
             });

dwds/test/chrome_proxy_service_test.dart

@@ -33,11 +33,8 @@ WipConnection get tabConnection => context.tabConnection;
 void main() {
   group('shared context', () {
     setUpAll(() async {
-      configureLogWriter(
-          customLogWriter: (level, message,
-                  {loggerName, error, stackTrace, verbose}) =>
-              printOnFailure('[$level] $loggerName: $message'));
-      await context.setUp(verbose: false);
+      setCurrentLogWriter();
+      await context.setUp(verboseCompiler: false);
     });
 
     tearDownAll(() async {
@@ -52,6 +49,7 @@ void main() {
       ScriptRef mainScript;
 
       setUp(() async {
+        setCurrentLogWriter();
         vm = await fetchChromeProxyService(context.debugConnection).getVM();
         isolate = await fetchChromeProxyService(context.debugConnection)
             .getIsolate(vm.isolates.first.id);
@@ -160,6 +158,8 @@ void main() {
     });
 
     group('callServiceExtension', () {
+      setUp(setCurrentLogWriter);
+
       test('success', () async {
         var serviceMethod = 'ext.test.callServiceExtension';
         await tabConnection.runtime
@@ -208,6 +208,8 @@ void main() {
     });
 
     group('VMTimeline', () {
+      setUp(setCurrentLogWriter);
+
       test('clearVMTimeline', () async {
         await expectLater(service.clearVMTimeline(), throwsRPCError);
       });
@@ -246,12 +248,15 @@ void main() {
       LibraryRef bootstrap;
 
       setUpAll(() async {
+        setCurrentLogWriter();
         var vm = await service.getVM();
         isolate = await service.getIsolate(vm.isolates.first.id);
         bootstrap = isolate.rootLib;
       });
 
       group('top level methods', () {
+        setUp(setCurrentLogWriter);
+
         test('can return strings', () async {
           expect(
               await service.evaluate(
@@ -304,6 +309,8 @@ void main() {
         });
 
         group('with provided scope', () {
+          setUp(setCurrentLogWriter);
+
           Future<InstanceRef> createRemoteObject(String message) async {
             return await service.evaluate(
                     isolate.id, bootstrap.id, 'createObject("$message")')
@@ -362,6 +369,8 @@ void main() {
     });
 
     group('getIsolate', () {
+      setUp(setCurrentLogWriter);
+
       test('works for existing isolates', () async {
         var vm = await service.getVM();
         var result = await service.getIsolate(vm.isolates.first.id);
@@ -393,13 +402,16 @@ void main() {
       Library rootLibrary;
 
       setUpAll(() async {
+        setCurrentLogWriter();
         var vm = await service.getVM();
         isolate = await service.getIsolate(vm.isolates.first.id);
         bootstrap = isolate.rootLib;
         rootLibrary =
             await service.getObject(isolate.id, bootstrap.id) as Library;
       });
 
+      setUp(setCurrentLogWriter);
+
       test('Libraries', () async {
         expect(rootLibrary, isNotNull);
         // TODO: library names change with kernel dart-lang/sdk#36736
@@ -654,6 +666,8 @@ void main() {
     });
 
     group('getSourceReport', () {
+      setUp(setCurrentLogWriter);
+
       test('Coverage report', () async {
         var vm = await service.getVM();
         var isolateId = vm.isolates.first.id;
@@ -698,6 +712,7 @@ void main() {
       ScriptRef mainScript;
 
       setUp(() async {
+        setCurrentLogWriter();
         var vm = await service.getVM();
         isolateId = vm.isolates.first.id;
         scripts = await service.getScripts(isolateId);
@@ -732,6 +747,7 @@ void main() {
       ScriptRef mainScript;
 
       setUp(() async {
+        setCurrentLogWriter();
         var vm = await service.getVM();
         isolateId = vm.isolates.first.id;
         scripts = await service.getScripts(isolateId);
@@ -800,6 +816,7 @@ void main() {
       ScriptRef mainScript;
 
       setUp(() async {
+        setCurrentLogWriter();
         var vm = await service.getVM();
         isolateId = vm.isolates.first.id;
         scripts = await service.getScripts(isolateId);
@@ -954,6 +971,7 @@ void main() {
       InstanceRef testInstance;
 
       setUp(() async {
+        setCurrentLogWriter();
         vm = await service.getVM();
         isolate = await service.getIsolate(vm.isolates.first.id);
         bootstrap = isolate.rootLib;
@@ -1156,6 +1174,7 @@ void main() {
         Stream<Event> eventStream;
 
         setUp(() async {
+          setCurrentLogWriter();
           expect(await service.streamListen('Debug'),
               const TypeMatcher<Success>());
           eventStream = service.onEvent('Debug');

dwds/test/events_test.dart

@@ -24,20 +24,6 @@ WipConnection get tabConnection => context.tabConnection;
 
 final context = TestContext();
 
-/// Redirect the logs for the current zone to emit on failure.
-///
-/// All messages are stored and reported on test failure.
-/// Needs to be called in both setUpAll() and setUp() to store
-/// the logs in the current zone.
-///
-/// Note: change 'printOnFailure' to 'print' for debug printing.
-void setCurrentLogWriter() {
-  configureLogWriter(
-      customLogWriter: (level, message,
-              {loggerName, error, stackTrace, verbose}) =>
-          printOnFailure('[$level] $loggerName: $message'));
-}
-
 void main() {
   setUpAll(() async {
     setCurrentLogWriter();

dwds/test/expression_compiler_service_test.dart

@@ -50,8 +50,7 @@ void main() async {
       output.stream.listen(printOnFailure);
 
       configureLogWriter(
-          customLogWriter: (level, message,
-                  {loggerName, error, stackTrace, verbose}) =>
+          customLogWriter: (level, message, {error, loggerName, stackTrace}) =>
               output.add('[$level] $loggerName: $message'));
 
       // start expression compilation service