Send most build-time output through logging

Author: kevmoo

bin/dartdoc.dart

@@ -12,6 +12,8 @@ import 'package:analyzer/src/dart/sdk/sdk.dart';
 import 'package:analyzer/src/generated/sdk.dart';
 import 'package:args/args.dart';
 import 'package:dartdoc/dartdoc.dart';
+import 'package:dartdoc/src/logging.dart';
+import 'package:logging/logging.dart' as logging;
 import 'package:path/path.dart' as path;
 import 'package:stack_trace/stack_trace.dart';
 
@@ -23,8 +25,8 @@ main(List<String> arguments) async {
   try {
     args = parser.parse(arguments);
   } on FormatException catch (e) {
-    print(e.message);
-    print('');
+    stderr.writeln(e.message);
+    stderr.writeln('');
     // http://linux.die.net/include/sysexits.h
     // #define EX_USAGE	64	/* command line usage error */
     _printUsageAndExit(parser, exitCode: 64);
@@ -46,12 +48,9 @@ main(List<String> arguments) async {
   }
 
   final bool sdkDocs = args['sdk-docs'];
+  final bool showProgress = args['show-progress'];
 
-  if (args['show-progress']) {
-    _showProgress = true;
-  }
-
-  var readme = args['sdk-readme'];
+  final String readme = args['sdk-readme'];
   if (readme != null && !(new File(readme).existsSync())) {
     stderr.writeln(
         " fatal error: unable to locate the SDK description file at $readme.");
@@ -123,6 +122,49 @@ main(List<String> arguments) async {
     _printUsageAndExit(parser, exitCode: 1);
   }
 
+  // By default, get all log output at `progressLevel` or greater.
+  // This allows us to capture progress events and print `...`.
+  logging.Logger.root.level = progressLevel;
+  final stopwatch = new Stopwatch()..start();
+
+  // Used to track if we're printing `...` to show progress.
+  // Allows unified new-line tracking
+  var writingProgress = false;
+
+  logging.Logger.root.onRecord.listen((record) {
+    if (record.level == progressLevel) {
+      if (showProgress && stopwatch.elapsed.inMilliseconds > 250) {
+        writingProgress = true;
+        stdout.write('.');
+        stopwatch.reset();
+      }
+      return;
+    }
+
+    stopwatch.reset();
+    if (writingProgress) {
+      // print a new line after progress dots...
+      print('');
+      writingProgress = false;
+    }
+    var message = record.message;
+    assert(message == message.trimRight());
+    assert(message.isNotEmpty);
+
+    if (record.level < logging.Level.WARNING) {
+      if (message.endsWith('...')) {
+        // Assume there may be more progress to print, so omit the trailing
+        // newline
+        writingProgress = true;
+        stdout.write(message);
+      } else {
+        print(message);
+      }
+    } else {
+      stderr.writeln(message);
+    }
+  });
+
   PackageMeta packageMeta = sdkDocs
       ? new PackageMeta.fromSdk(sdkDir,
           sdkReadmePath: readme, useCategories: args['use-categories'])
@@ -144,9 +186,8 @@ main(List<String> arguments) async {
     }
   }
 
-  print("Generating documentation for '${packageMeta}' into "
+  logInfo("Generating documentation for '${packageMeta}' into "
       "${outputDir.absolute.path}${Platform.pathSeparator}");
-  print('');
 
   var generators = await initGenerators(url, args['rel-canonical-prefix'],
       headerFilePaths: headerFilePaths,
@@ -157,7 +198,7 @@ main(List<String> arguments) async {
       prettyIndexJson: args['pretty-index-json']);
 
   for (var generator in generators) {
-    generator.onFileCreated.listen(_onProgress);
+    generator.onFileCreated.listen(logProgress);
   }
 
   DartSdk sdk = new FolderBasedDartSdk(PhysicalResourceProvider.INSTANCE,
@@ -203,10 +244,10 @@ main(List<String> arguments) async {
       outputDir, packageMeta, includeLibraries,
       includeExternals: includeExternals);
 
-  dartdoc.onCheckProgress.listen(_onProgress);
-  Chain.capture(() async {
+  dartdoc.onCheckProgress.listen(logProgress);
+  await Chain.capture(() async {
     DartDocResults results = await dartdoc.generateDocs();
-    print('\nSuccess! Docs generated into ${results.outDir.absolute.path}');
+    logInfo('Success! Docs generated into ${results.outDir.absolute.path}');
   }, onError: (e, Chain chain) {
     if (e is DartDocFailure) {
       stderr.writeln('\nGeneration failed: ${e}.');
@@ -218,8 +259,6 @@ main(List<String> arguments) async {
   });
 }
 
-bool _showProgress = false;
-
 ArgParser _createArgsParser() {
   var parser = new ArgParser();
   parser.addFlag('help',
@@ -232,7 +271,8 @@ ArgParser _createArgsParser() {
       defaultsTo: false);
   parser.addFlag('sdk-docs',
       help: 'Generate ONLY the docs for the Dart SDK.', negatable: false);
-  parser.addFlag('show-warnings', help: 'Display warnings.', negatable: false);
+  parser.addFlag('show-warnings',
+      help: 'Display warnings.', negatable: false, defaultsTo: false);
   parser.addFlag('show-progress',
       help: 'Display progress indications to console stdout', negatable: false);
   parser.addOption('sdk-readme',
@@ -318,15 +358,6 @@ ArgParser _createArgsParser() {
   return parser;
 }
 
-int _progressCounter = 0;
-
-void _onProgress(var file) {
-  if (_showProgress && _progressCounter % 5 == 0) {
-    stdout.write('.');
-  }
-  _progressCounter += 1;
-}
-
 /// Print help if we are passed the help option.
 void _printHelpAndExit(ArgParser parser, {int exitCode: 0}) {
   print('Generate HTML documentation for Dart libraries.\n');

lib/dartdoc.dart

@@ -33,6 +33,7 @@ import 'src/config.dart';
 import 'src/generator.dart';
 import 'src/html/html_generator.dart';
 import 'src/io_utils.dart';
+import 'src/logging.dart';
 import 'src/model.dart';
 import 'src/model_utils.dart';
 import 'src/package_meta.dart';
@@ -192,15 +193,15 @@ class DartDoc {
     int warnings = package.packageWarningCounter.warningCount;
     int errors = package.packageWarningCounter.errorCount;
     if (warnings == 0 && errors == 0) {
-      print("\nno issues found");
+      logInfo("no issues found");
     } else {
-      print("\nfound ${warnings} ${pluralize('warning', warnings)} "
+      logWarning("found ${warnings} ${pluralize('warning', warnings)} "
           "and ${errors} ${pluralize('error', errors)}");
     }
 
     double seconds = _stopwatch.elapsedMilliseconds / 1000.0;
-    print(
-        "\ndocumented ${package.libraries.length} librar${package.libraries.length == 1 ? 'y' : 'ies'} "
+    logInfo(
+        "Documented ${package.libraries.length} librar${package.libraries.length == 1 ? 'y' : 'ies'} "
         "in ${seconds.toStringAsFixed(1)} seconds");
 
     if (package.libraries.isEmpty) {
@@ -420,7 +421,7 @@ class DartDoc {
 
     final Set<String> visited = new Set();
     final String start = 'index.html';
-    stdout.write('\nvalidating docs...');
+    logInfo('Validating docs...');
     _doCheck(package, origin, visited, start);
     _doOrphanCheck(package, origin, visited);
     _doSearchIndexCheck(package, origin, visited);
@@ -486,7 +487,7 @@ class DartDoc {
         name = name.substring(Directory.current.path.length);
         if (name.startsWith(Platform.pathSeparator)) name = name.substring(1);
       }
-      print('parsing ${name}...');
+      logInfo('parsing ${name}...');
       JavaFile javaFile = new JavaFile(filePath).getAbsoluteFile();
       Source source = new FileBasedSource(javaFile);
 
@@ -578,12 +579,12 @@ class DartDoc {
           ..sort();
 
     double seconds = _stopwatch.elapsedMilliseconds / 1000.0;
-    print("parsed ${libraries.length} ${pluralize('file', libraries.length)} "
+    logInfo("parsed ${libraries.length} ${pluralize('file', libraries.length)} "
         "in ${seconds.toStringAsFixed(1)} seconds");
     _stopwatch.reset();
 
     if (errors.isNotEmpty) {
-      errors.forEach(print);
+      errors.forEach(logWarning);
       int len = errors.length;
       throw new DartDocFailure(
           "encountered ${len} analysis error${len == 1 ? '' : 's'}");

lib/src/html/html_generator_instance.dart

@@ -4,12 +4,13 @@
 
 import 'dart:async' show Future, StreamController;
 import 'dart:convert' show JsonEncoder;
-import 'dart:io' show Directory, File, stdout;
+import 'dart:io' show Directory, File;
 import 'dart:typed_data' show Uint8List;
 
 import 'package:collection/collection.dart' show compareNatural;
 import 'package:path/path.dart' as path;
 
+import '../logging.dart';
 import '../model.dart';
 import '../warnings.dart';
 import 'html_generator.dart' show HtmlGeneratorOptions;
@@ -183,14 +184,13 @@ class HtmlGeneratorInstance implements HtmlOptions {
 
   void generatePackage() {
     TemplateData data = new PackageTemplateData(this, package, useCategories);
-    stdout.write('\ndocumenting ${package.name}');
+    logInfo('documenting ${package.name}');
 
     _build('index.html', _templates.indexTemplate, data);
   }
 
   void generateLibrary(Package package, Library lib) {
-    stdout
-        .write('\ngenerating docs for library ${lib.name} from ${lib.path}...');
+    logInfo('Generating docs for library ${lib.name} from ${lib.path}...');
     if (!lib.isAnonymous && !lib.hasDocumentation) {
       package.warnOnElement(lib, PackageWarning.noLibraryLevelDocs);
     }

lib/src/logging.dart

@@ -0,0 +1,24 @@
+// Copyright (c) 2017, the Dart project authors.  Please see the AUTHORS file
+// 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:logging/logging.dart';
+
+final _logger = new Logger('dartdoc');
+
+/// A custom [Level] for tracking file writes and verification.
+///
+/// Has a value of `501` – one more than [Level.FINE].
+final Level progressLevel = new Level('progress', 501);
+
+void logWarning(Object message) {
+  _logger.log(Level.WARNING, message);
+}
+
+void logInfo(Object message) {
+  _logger.log(Level.INFO, message);
+}
+
+void logProgress(Object message) {
+  _logger.log(progressLevel, message);
+}

lib/src/model.dart

@@ -30,6 +30,7 @@ import 'package:tuple/tuple.dart';
 import 'config.dart';
 import 'element_type.dart';
 import 'line_number_cache.dart';
+import 'logging.dart';
 import 'markdown_processor.dart' show Documentation;
 import 'model_utils.dart';
 import 'package_meta.dart' show PackageMeta, FileContents;
@@ -3116,9 +3117,9 @@ abstract class ModelElement extends Nameable
         // TODO(jcollins-g): move this to Package.warn system
         var filePath =
             this.element.source.fullName.substring(dirPath.length + 1);
-        final msg =
-            '\nwarning: ${filePath}: @example file not found, ${fragmentFile.path}';
-        stderr.write(msg);
+
+        logWarning(
+            'warning: ${filePath}: @example file not found, ${fragmentFile.path}');
       }
       return replacement;
     });

lib/src/package_meta.dart

@@ -9,6 +9,8 @@ import 'dart:io';
 import 'package:path/path.dart' as path;
 import 'package:yaml/yaml.dart';
 
+import 'logging.dart';
+
 abstract class PackageMeta {
   final Directory dir;
   final bool useCategories;
@@ -103,8 +105,9 @@ class _FilePackageMeta extends PackageMeta {
     ProcessResult result =
         Process.runSync(pubPath, ['get'], workingDirectory: dir.path);
 
-    if (result.stdout.isNotEmpty) {
-      print(result.stdout.trim());
+    var trimmedStdout = (result.stdout as String).trim();
+    if (trimmedStdout.isNotEmpty) {
+      logInfo(trimmedStdout);
     }
 
     if (result.exitCode != 0) {

lib/src/warnings.dart

@@ -1,9 +1,8 @@
-import 'dart:io';
-
 import 'package:analyzer/dart/element/element.dart';
 import 'package:tuple/tuple.dart';
 
 import 'config.dart';
+import 'logging.dart';
 
 class PackageWarningHelpText {
   final String warningName;
@@ -165,7 +164,7 @@ class PackageWarningCounter {
   final _warningCounts = new Map<PackageWarning, int>();
   final PackageWarningOptions options;
 
-  final _buffer = new StringBuffer();
+  final _items = <String>[];
 
   PackageWarningCounter(this.options);
 
@@ -175,8 +174,10 @@ class PackageWarningCounter {
   /// warnings here might be duplicated across multiple Package constructions.
   void maybeFlush() {
     if (options.autoFlush) {
-      stderr.write(_buffer.toString());
-      _buffer.clear();
+      for (var item in _items) {
+        logWarning(item);
+      }
+      _items.clear();
     }
   }
 
@@ -192,18 +193,20 @@ class PackageWarningCounter {
       toWrite = "warning: ${fullMessage}";
     }
     if (toWrite != null) {
-      _buffer.write("\n ${toWrite}");
+      var entry = "  ${toWrite}";
       if (_warningCounts[kind] == 1 &&
           config.verboseWarnings &&
           packageWarningText[kind].longHelp.isNotEmpty) {
         // First time we've seen this warning.  Give a little extra info.
         final String separator = '\n            ';
         final String nameSub = r'@@name@@';
         String verboseOut =
-            '$separator${packageWarningText[kind].longHelp.join(separator)}';
-        verboseOut = verboseOut.replaceAll(nameSub, name);
-        _buffer.write(verboseOut);
+            '$separator${packageWarningText[kind].longHelp.join(separator)}'
+                .replaceAll(nameSub, name);
+        entry = '$entry$verboseOut';
       }
+      assert(entry == entry.trimRight());
+      _items.add(entry);
     }
     maybeFlush();
   }

pubspec.lock

@@ -350,4 +350,4 @@ packages:
     source: hosted
     version: "2.1.13"
 sdks:
-  dart: ">=1.23.0 <=2.0.0-dev.3.0"
+  dart: ">=1.23.0 <=2.0.0-dev.5.0"

pubspec.yaml

@@ -14,7 +14,7 @@ dependencies:
   # We don't use http_parser directly; this dep exists to ensure that we get at
   # least version 3.0.3 to work around an issue with 3.0.2.
   http_parser: '>=3.0.3 <4.0.0'
-  logging: '>=0.9.0 <0.12.0'
+  logging: ^0.11.3+1
   markdown: ^0.11.2
   mustache4dart: ^1.1.0
   package_config: '>=0.1.5 <2.0.0'