Improved logging (#4011)

* Improved logging.

* Address review comments. Time AnalysisDriverModel.performResolve time as `resolve`.

* Move log of server status before build.

* Remove unused import.

* Address review comments.

* Fix test.

Author: davidmorgan

_test/test/build_integration_test.dart

@@ -8,7 +8,7 @@ library;
 import 'dart:io';
 
 import 'package:build_runner/src/build_script_generate/build_script_generate.dart';
-import 'package:build_runner_core/src/util/constants.dart';
+import 'package:build_runner_core/build_runner_core.dart';
 import 'package:path/path.dart' as p;
 import 'package:test/test.dart';
 
@@ -54,10 +54,10 @@ void main() {
 
     test('rebuilds if the input file changes and not otherwise', () async {
       var result = await runBuild();
-      expect(result.stdout, contains('with 0 outputs'));
+      expect(result.stdout, contains('wrote 0 outputs'));
       await replaceAllInFile('lib/hello.txt', 'hello', 'goodbye');
       result = await runBuild();
-      expect(result.stdout, contains('with 1 outputs'));
+      expect(result.stdout, contains('wrote 1 output'));
       var content = await readGeneratedFileAsString('_test/lib/hello.txt.post');
       expect(content, contains('goodbye'));
     });
@@ -70,7 +70,7 @@ void main() {
       );
 
       expect(result.exitCode, isNot(0));
-      expect(result.stdout, contains('Failed to precompile build script'));
+      expect(result.stdout, contains('Failed to compile build script'));
       expect(
         result.stdout,
         contains('Unknown experiment: fake-experiment'),
@@ -134,14 +134,13 @@ void main() {
       expect(
         (nextBuild.stdout as String).split('\n'),
         containsAllInOrder([
-          contains('Generating build script'),
+          contains('Generating the build script'),
+          contains('Compiling the build script.'),
+          contains('Creating the asset graph.'),
           contains(
-            'Invalidated precompiled build script due to missing asset '
-            'graph.',
+            'Building, full build because there is no valid asset graph.',
           ),
-          contains('Precompiling build script'),
-          contains('Building new asset graph.'),
-          contains('Succeeded after'),
+          contains(BuildLog.successPattern),
         ]),
       );
     });

_test/test/common/utils.dart

@@ -7,6 +7,7 @@ import 'dart:convert';
 import 'dart:io';
 import 'dart:isolate';
 
+import 'package:build_runner_core/build_runner_core.dart';
 import 'package:path/path.dart' as p;
 import 'package:test/test.dart';
 import 'package:test_process/test_process.dart';
@@ -155,11 +156,15 @@ Future<void> _resetGitClient() async {
 }
 
 Future<void> get nextSuccessfulBuild async {
-  await _stdOutLines!.firstWhere((line) => line.contains('Succeeded after'));
+  await _stdOutLines!.firstWhere(
+    (line) => line.contains(BuildLog.successPattern),
+  );
 }
 
 Future<void> get nextFailedBuild async {
-  await _stdOutLines!.firstWhere((line) => line.contains('Failed after'));
+  await _stdOutLines!.firstWhere(
+    (line) => line.contains(BuildLog.failurePattern),
+  );
 }
 
 Future<String> nextStdOutLine(String message) =>

_test/test/goldens/generated_build_script.dart

@@ -1,5 +1,6 @@
 // @dart=3.6
 // ignore_for_file: directives_ordering
+// build_runner >=2.4.16
 // ignore_for_file: no_leading_underscores_for_library_prefixes
 import 'package:build_runner_core/build_runner_core.dart' as _i1;
 import 'package:provides_builder/builders.dart' as _i2;

_test_common/lib/test_environment.dart

@@ -6,7 +6,6 @@ import 'dart:async';
 
 import 'package:build/build.dart';
 import 'package:build_runner_core/build_runner_core.dart';
-import 'package:logging/logging.dart';
 
 import 'common.dart';
 
@@ -32,8 +31,6 @@ class TestBuildEnvironment implements BuildEnvironment {
   /// [prompt].
   final bool throwOnPrompt;
 
-  final logRecords = <LogRecord>[];
-
   /// The next response for calls to [prompt]. Must be set before calling
   /// [prompt].
   set nextPromptResponse(int next) {
@@ -48,9 +45,6 @@ class TestBuildEnvironment implements BuildEnvironment {
     this.throwOnPrompt = false,
   }) : _readerWriter = readerWriter ?? TestReaderWriter();
 
-  @override
-  void onLog(LogRecord record) => logRecords.add(record);
-
   /// Prompt the user for input.
   ///
   /// The message and choices are displayed to the user and the index of the
@@ -67,17 +61,14 @@ class TestBuildEnvironment implements BuildEnvironment {
   }
 
   @override
-  BuildEnvironment copyWith({
-    void Function(LogRecord)? onLogOverride,
-    RunnerAssetWriter? writer,
-    AssetReader? reader,
-  }) => TestBuildEnvironment(
-    readerWriter:
-        (writer as TestReaderWriter?) ??
-        (reader as TestReaderWriter?) ??
-        _readerWriter,
-    throwOnPrompt: throwOnPrompt,
-  );
+  BuildEnvironment copyWith({RunnerAssetWriter? writer, AssetReader? reader}) =>
+      TestBuildEnvironment(
+        readerWriter:
+            (writer as TestReaderWriter?) ??
+            (reader as TestReaderWriter?) ??
+            _readerWriter,
+        throwOnPrompt: throwOnPrompt,
+      );
 
   @override
   Future<BuildResult> finalizeBuild(

_test_common/lib/test_phases.dart

@@ -52,8 +52,7 @@ void _printOnFailure(LogRecord record) {
 ///
 /// [status] optionally indicates the desired outcome.
 ///
-/// [logLevel] sets the builder log level and [onLog] can optionally capture
-/// build log messages.
+/// [onLog] can optionally capture log messages.
 ///
 /// Example:
 ///
@@ -80,7 +79,6 @@ Future<TestBuildersResult> testPhases(
   PackageGraph? packageGraph,
   BuildStatus status = BuildStatus.success,
   Map<String, BuildConfig>? overrideBuildConfig,
-  Level? logLevel,
   // A better way to "silence" logging than setting logLevel to OFF.
   void Function(LogRecord record) onLog = _printOnFailure,
   bool checkBuildStatus = true,
@@ -141,15 +139,14 @@ Future<TestBuildersResult> testPhases(
     packageGraph,
     reader: readerWriter,
     writer: readerWriter,
-    onLogOverride: onLog,
-  );
-  var logSubscription = LogSubscription(
-    environment,
-    verbose: verbose,
-    logLevel: logLevel,
   );
+
+  buildLog.configuration = buildLog.configuration.rebuild((b) {
+    b.onLog = onLog;
+    b.verbose = verbose;
+  });
+
   var options = await BuildOptions.create(
-    logSubscription,
     deleteFilesByDefault: deleteFilesByDefault,
     packageGraph: packageGraph,
     skipBuildScriptCheck: true,
@@ -172,7 +169,6 @@ Future<TestBuildersResult> testPhases(
     buildFilters: buildFilters,
   );
   await build.beforeExit();
-  await options.logListener.cancel();
 
   if (checkBuildStatus) {
     checkBuild(

build/CHANGELOG.md

@@ -1,5 +1,7 @@
 ## 2.4.3-wip
 
+- Improved logging: show what builders are running and, for long-running
+  builders, where the time is spent.
 - `AssetNotFoundException` now also reports the missing `path`.
 - Bump the min sdk to 3.7.0.
 - Use `build_test` 3.0.0.

build/lib/src/analyzer/resolver.dart

@@ -169,40 +169,35 @@ class SyntaxErrorInAssetException implements Exception {
 
   @override
   String toString() {
-    final buffer =
-        StringBuffer()
-          ..writeln('This builder requires Dart inputs without syntax errors.')
-          ..writeln(
-            'However, ${assetId.uri} (or an existing part) contains the '
-            'following errors.',
-          );
+    final buffer = StringBuffer();
 
     // Avoid generating too much output for syntax errors. The user likely has
     // an editor that shows them anyway.
     final entries = errorToResult.entries.toList();
+    var first = true;
     for (final errorAndResult in entries.take(_maxErrorsInToString)) {
+      if (!first) {
+        buffer.write('\n');
+      }
+      first = false;
       final error = errorAndResult.key;
-      // Use a short name: We present the full context by including the asset id
-      // and this is easier to skim through
-      final sourceName = error.source.shortName;
 
       final lineInfo = errorAndResult.value.lineInfo;
       final position = lineInfo.getLocation(error.offset);
 
-      // Output messages like "foo.dart:3:4: Expected a semicolon here."
-      buffer.writeln(
-        '$sourceName:${position.lineNumber}:${position.columnNumber}: '
+      // The file name will be added by `BuildLog`, so write just the line
+      // number and column, for example: "3:4: Expected a semicolon here."
+      buffer.write(
+        '${position.lineNumber}:${position.columnNumber}: '
         '${error.message}',
       );
     }
 
     final additionalErrors = entries.length - _maxErrorsInToString;
     if (additionalErrors > 0) {
-      buffer.writeln('And $additionalErrors more...');
+      buffer.write('\nAnd $additionalErrors more.');
     }
 
-    buffer.writeln('\nTry fixing the errors and re-running the build.');
-
     return buffer.toString();
   }
 }

build/lib/src/builder/logging.dart

@@ -14,31 +14,3 @@ final _default = Logger('build.fallback');
 ///
 /// Will be `null` when not running within a build.
 Logger get log => Zone.current[logKey] as Logger? ?? _default;
-
-/// Runs [fn] in an error handling [Zone].
-///
-/// Any calls to [print] will be logged with `log.warning`, and any errors will
-/// be logged with `log.severe`.
-///
-/// Completes with the first error or result of `fn`, whichever comes first.
-Future<T> scopeLogAsync<T>(Future<T> Function() fn, Logger log) {
-  var done = Completer<T>();
-  runZonedGuarded(
-    fn,
-    (e, st) {
-      log.severe('', e, st);
-      if (done.isCompleted) return;
-      done.completeError(e, st);
-    },
-    zoneSpecification: ZoneSpecification(
-      print: (self, parent, zone, message) {
-        log.warning(message);
-      },
-    ),
-    zoneValues: {logKey: log},
-  )?.then((result) {
-    if (done.isCompleted) return;
-    done.complete(result);
-  });
-  return done.future;
-}

build/lib/src/generate/run_builder.dart

@@ -3,6 +3,7 @@
 // BSD-style license that can be found in the LICENSE file.
 import 'dart:isolate';
 
+import 'package:build_runner_core/build_runner_core.dart';
 // ignore: implementation_imports
 import 'package:build_runner_core/src/generate/build_step_impl.dart';
 // ignore: implementation_imports
@@ -102,7 +103,10 @@ Future<void> runBuilder(
     }
   }
 
-  await scopeLogAsync(() => Future.wait(inputs.map(buildForInput)), logger);
+  await BuildLogLogger.scopeLogAsync(
+    () => Future.wait(inputs.map(buildForInput)),
+    logger,
+  );
 
   if (shouldDisposeResourceManager) {
     await resources.disposeAll();

build/lib/src/generate/run_post_process_builder.dart

@@ -2,14 +2,13 @@
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 
+import 'package:build_runner_core/build_runner_core.dart';
 import 'package:logging/logging.dart';
 
 import '../asset/id.dart';
 import '../asset/reader.dart';
 import '../asset/writer.dart';
-import '../builder/logging.dart';
 import '../builder/post_process_build_step.dart';
-import '../builder/post_process_builder.dart';
 
 /// Run [builder] with [inputId] as the primary input.
 ///
@@ -26,7 +25,7 @@ Future<void> runPostProcessBuilder(
   required void Function(AssetId) addAsset,
   required void Function(AssetId) deleteAsset,
 }) async {
-  await scopeLogAsync(() async {
+  await BuildLogLogger.scopeLogAsync(() async {
     var buildStep = postProcessBuildStep(
       inputId,
       reader,