Move all printing during run to flow through logging

Tests are no longer noisy on the console
Provides a common entry point to provide alternate (JSON) output formats
Centralized new-line handling
Standardize on stdout for non-fatal output
  (use of stderr was not consistent)

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';
 import 'package:path/path.dart' as path;
 import 'package:stack_trace/stack_trace.dart';
 
@@ -47,9 +49,9 @@ main(List<String> arguments) async {
 
   final bool sdkDocs = args['sdk-docs'];
 
-  var showProgress = args['show-progress'] as bool;
+  final showProgress = args['show-progress'] as bool;
 
-  var readme = args['sdk-readme'];
+  var readme = args['sdk-readme'] as String;
   if (readme != null && !(new File(readme).existsSync())) {
     stderr.writeln(
         " fatal error: unable to locate the SDK description file at $readme.");
@@ -121,6 +123,50 @@ main(List<String> arguments) async {
     _printUsageAndExit(parser, exitCode: 1);
   }
 
+  final processLevel = new Level('progress', 299);
+  Logger.root.level = Level.ALL;
+  final stopwatch = new Stopwatch()..start();
+
+  // Used to track if we're printing `...` to show progress.
+  // Allows unified new-line tracking
+  var writingProgress = false;
+
+  log.onRecord.listen((record) {
+    try {
+      if (identical(record.level, processLevel)) {
+        if (showProgress &&
+            writingProgress &&
+            stopwatch.elapsed.inMilliseconds > 500) {
+          stdout.write('.');
+          stopwatch.reset();
+        }
+      } else {
+        if (writingProgress) {
+          // print a new line after progress dots...
+          print('');
+          writingProgress = false;
+        }
+        var message = record.message;
+        assert(message == record.message.trimRight());
+        assert(message.isNotEmpty);
+
+        if (message.endsWith('...')) {
+          // Assume there may be more progress to print, so omit the trailing
+          // newline
+          writingProgress = true;
+          stdout.write(message);
+        } else {
+          print(message);
+        }
+      }
+    } catch (e, stack) {
+      // Errors thrown in logging listeners get swallowed
+      // Explicitly echoing them here
+      stderr.writeln('Error while logging:$e\n$stack');
+      rethrow;
+    }
+  });
+
   PackageMeta packageMeta = sdkDocs
       ? new PackageMeta.fromSdk(sdkDir,
           sdkReadmePath: readme, useCategories: args['use-categories'])
@@ -142,9 +188,8 @@ main(List<String> arguments) async {
     }
   }
 
-  print("Generating documentation for '${packageMeta}' into "
+  log.info("Generating documentation for '${packageMeta}' into "
       "${outputDir.absolute.path}${Platform.pathSeparator}");
-  print('');
 
   var generators = await initGenerators(url, args['rel-canonical-prefix'],
       headerFilePaths: headerFilePaths,
@@ -154,13 +199,8 @@ main(List<String> arguments) async {
       useCategories: args['use-categories'],
       prettyIndexJson: args['pretty-index-json']);
 
-  var progressCounter = 0;
-
   void onProgress(Object file) {
-    if (showProgress && progressCounter % 5 == 0) {
-      stdout.write('.');
-    }
-    progressCounter += 1;
+    log.log(processLevel, file);
   }
 
   for (var generator in generators) {
@@ -211,9 +251,9 @@ main(List<String> arguments) async {
       includeExternals: includeExternals);
 
   dartdoc.onCheckProgress.listen(onProgress);
-  Chain.capture(() async {
+  await Chain.capture(() async {
     DartDocResults results = await dartdoc.generateDocs();
-    print('\nSuccess! Docs generated into ${results.outDir.absolute.path}');
+    log.info('Success! Docs generated into ${results.outDir.absolute.path}');
   }, onError: (e, Chain chain) {
     if (e is DartDocFailure) {
       stderr.writeln('\nGeneration failed: ${e}.');
@@ -237,7 +277,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',

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");
+      log.info("no issues found");
     } else {
-      print("\nfound ${warnings} ${pluralize('warning', warnings)} "
+      log.warning("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'} "
+    log.info(
+        "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...');
+    log.info('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}...');
+      log.info('parsing ${name}...');
       JavaFile javaFile = new JavaFile(filePath).getAbsoluteFile();
       Source source = new FileBasedSource(javaFile);
 
@@ -578,12 +579,13 @@ class DartDoc {
           ..sort();
 
     double seconds = _stopwatch.elapsedMilliseconds / 1000.0;
-    print("parsed ${libraries.length} ${pluralize('file', libraries.length)} "
+    log.info(
+        "parsed ${libraries.length} ${pluralize('file', libraries.length)} "
         "in ${seconds.toStringAsFixed(1)} seconds");
     _stopwatch.reset();
 
     if (errors.isNotEmpty) {
-      errors.forEach(print);
+      errors.forEach(log.warning);
       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}');
+    log.info('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}...');
+    log.info('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,7 @@
+// Copyright (c) 2014, 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';
+
+Logger get log => Logger.root;

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);
+
+        log.warning(
+            '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) {
+      log.info(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) {
+        log.warning(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();
   }

test/compare_output_test.dart

@@ -145,7 +145,7 @@ void main() {
       final sep = '.'; // We don't care what the path separator character is
       final firstUnfoundExample = new RegExp('warning: lib${sep}example.dart: '
           '@example file not found.*test_package${sep}dog${sep}food.md');
-      if (!result.stderr.contains(firstUnfoundExample)) {
+      if (!result.stdout.contains(firstUnfoundExample)) {
         fail('Should warn about unfound @example files: \n'
             'stdout:\n${result.stdout}\nstderr:\n${result.stderr}');
       }