Add in basic logging system.

Review URL: https://codereview.chromium.org//11470023

git-svn-id: https://dart.googlecode.com/svn/branches/bleeding_edge/dart@15870 260f80e4-7a28-3924-810f-c04153c831b5

utils/pub/command_help.dart

@@ -7,6 +7,7 @@ library command_help;
 import 'dart:io' as io;
 import 'exit_codes.dart' as exit_codes;
 import 'io.dart';
+import 'log.dart' as log;
 import 'pub.dart';
 
 /** Handles the `help` pub command. */
@@ -22,8 +23,8 @@ class HelpCommand extends PubCommand {
       var name = commandOptions.rest[0];
       var command = pubCommands[name];
       if (command == null) {
-        printError('Could not find a command named "$name".');
-        printError('Run "pub help" to see available commands.');
+        log.error('Could not find a command named "$name".');
+        log.error('Run "pub help" to see available commands.');
         io.exit(exit_codes.USAGE);
       }
 

utils/pub/log.dart

@@ -0,0 +1,218 @@
+// Copyright (c) 2012, 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.
+
+/// Message logging.
+library log;
+
+import 'dart:io';
+import 'io.dart';
+
+typedef LogFn(Level level, message);
+final Map<Level, LogFn> _loggers = new Map<Level, LogFn>();
+
+/// The list of recorded log messages. Will only be recorded if
+/// [recordTranscript()] is called.
+List<Entry> _transcript;
+
+/// An enum type for defining the different logging levels. By default, [ERROR]
+/// and [WARNING] messages are printed to sterr. [MESSAGE] messages are printed
+/// to stdout, and others are ignored.
+class Level {
+  /// An error occurred and an operation could not be completed. Usually shown
+  /// to the user on stderr.
+  static const ERROR = const Level._("ERR ");
+
+  /// Something unexpected happened, but the program was able to continue,
+  /// though possibly in a degraded fashion.
+  static const WARNING = const Level._("WARN");
+
+  /// A message intended specifically to be shown to the user.
+  static const MESSAGE = const Level._("MSG ");
+
+  /// Some interaction with the external world occurred, such as a network
+  /// operation, process spawning, or file IO.
+  static const IO = const Level._("IO  ");
+
+  /// Fine-grained and verbose additional information. Can be used to provide
+  /// program state context for other logs (such as what pub was doing when an
+  /// IO operation occurred) or just more detail for an operation.
+  static const FINE = const Level._("FINE");
+
+  const Level._(this.name);
+  final String name;
+
+  String toString() => name;
+  int get hashCode => name.hashCode;
+}
+
+/// A single log entry.
+class Entry {
+  final Level level;
+  final String message;
+
+  Entry(this.level, this.message);
+}
+
+/// Logs [message] at [Level.ERROR].
+void error(message) => write(Level.ERROR, message);
+
+/// Logs [message] at [Level.WARNING].
+void warning(message) => write(Level.WARNING, message);
+
+/// Logs [message] at [Level.MESSAGE].
+void message(message) => write(Level.MESSAGE, message);
+
+/// Logs [message] at [Level.IO].
+void io(message) => write(Level.IO, message);
+
+/// Logs [message] at [Level.FINE].
+void fine(message) => write(Level.FINE, message);
+
+/// Logs [message] at [level].
+void write(Level level, message) {
+  if (_loggers.isEmpty) showNormal();
+
+  var logFn = _loggers[level];
+  if (logFn != null) logFn(level, message);
+
+  if (_transcript != null) {
+    _transcript.add(new Entry(level, '$message'));
+  }
+}
+
+/// Logs an asynchronous IO operation. Logs [startMessage] before the operation
+/// starts, then when [operation] completes, invokes [endMessage] with the
+/// completion value and logs the result of that. Returns a future that
+/// completes after the logging is done.
+///
+/// If [endMessage] is omitted, then logs "Begin [startMessage]" before the
+/// operation and "End [startMessage]" after it.
+Future ioAsync(String startMessage, Future operation,
+               [String endMessage(value)]) {
+  if (endMessage == null) {
+    io("Begin $startMessage.");
+  } else {
+    io(startMessage);
+  }
+
+  return operation.transform((result) {
+    if (endMessage == null) {
+      io("End $startMessage.");
+    } else {
+      io(endMessage(result));
+    }
+    return result;
+  });
+}
+
+/// Logs the spawning of an [executable] process with [arguments] at [IO]
+/// level.
+void process(String executable, List<String> arguments) {
+  io("Spawning $executable ${Strings.join(arguments, ' ')}");
+}
+
+/// Logs the results of running [executable].
+void processResult(String executable, PubProcessResult result) {
+  // Log it all as one message so that it shows up as a single unit in the logs.
+  var buffer = new StringBuffer();
+  buffer.add("Finished $executable. Exit code ${result.exitCode}.");
+
+  dumpOutput(String name, List<String> output) {
+    if (output.length == 0) {
+      buffer.add("Nothing output on $name.");
+    } else {
+      buffer.add("$name:");
+      var numLines = 0;
+      for (var line in output) {
+        if (++numLines > 1000) {
+          buffer.add('[${output.length - 1000}] more lines of output '
+                     'truncated...]');
+          break;
+        }
+
+        buffer.add(line);
+      }
+    }
+  }
+
+  dumpOutput("stdout", result.stdout);
+  dumpOutput("stderr", result.stderr);
+
+  io(buffer.toString());
+}
+
+/// Enables recording of log entries.
+void recordTranscript() {
+  _transcript = <Entry>[];
+}
+
+/// If [recordTranscript()] was called, then prints the previously recorded log
+/// transcript to stderr.
+void dumpTranscript() {
+  if (_transcript == null) return;
+
+  stderr.writeString('---- Log transcript ----\n');
+  for (var entry in _transcript) {
+    _logToStderrWithLabel(entry.level, entry.message);
+  }
+  stderr.writeString('---- End log transcript ----\n');
+}
+
+/// Sets the verbosity to "normal", which shows errors, warnings, and messages.
+void showNormal() {
+  _loggers[Level.ERROR]   = _logToStderr;
+  _loggers[Level.WARNING] = _logToStderr;
+  _loggers[Level.MESSAGE] = _logToStdout;
+  _loggers[Level.IO]      = null;
+  _loggers[Level.FINE]    = null;
+}
+
+/// Sets the verbosity to "io", which shows errors, warnings, messages, and IO
+/// event logs.
+void showIO() {
+  _loggers[Level.ERROR]   = _logToStderrWithLabel;
+  _loggers[Level.WARNING] = _logToStderrWithLabel;
+  _loggers[Level.MESSAGE] = _logToStdoutWithLabel;
+  _loggers[Level.IO]      = _logToStderrWithLabel;
+  _loggers[Level.FINE]    = null;
+}
+
+/// Sets the verbosity to "all", which logs ALL the things.
+void showAll() {
+  _loggers[Level.ERROR]   = _logToStderrWithLabel;
+  _loggers[Level.WARNING] = _logToStderrWithLabel;
+  _loggers[Level.MESSAGE] = _logToStdoutWithLabel;
+  _loggers[Level.IO]      = _logToStderrWithLabel;
+  _loggers[Level.FINE]    = _logToStderrWithLabel;
+}
+
+/// Log function that prints the message to stdout.
+void _logToStdout(Level level, message) {
+  print('$message');
+}
+
+/// Log function that prints the message to stdout with the level name.
+void _logToStdoutWithLabel(Level level, message) {
+  print(_splitAndPrefix(level, message));
+}
+
+/// Log function that prints the message to stderr.
+void _logToStderr(Level level, message) {
+  stderr.writeString('$message\n');
+}
+
+/// Log function that prints the message to stderr with the level name.
+void _logToStderrWithLabel(Level level, message) {
+  stderr.writeString(_splitAndPrefix(level, message));
+  stderr.writeString('\n');
+}
+
+/// Add the level prefix to the first line of [message] and prefix subsequent
+/// lines with "|".
+String _splitAndPrefix(Level level, message) {
+  // TODO(rnystrom): We're doing lots of splitting and joining in here. If that
+  // becomes a performance problem, we can optimize this to write directly to
+  // stdout/stderr a line at a time.
+  return "$level: ${Strings.join(message.toString().split('\n'), '\n    | ')}";
+}

utils/pub/pub.dart

@@ -18,6 +18,7 @@ import 'command_update.dart';
 import 'command_version.dart';
 import 'entrypoint.dart';
 import 'exit_codes.dart' as exit_codes;
+import 'log.dart' as log;
 import 'package.dart';
 import 'pubspec.dart';
 import 'source.dart';
@@ -54,10 +55,21 @@ Map<String, PubCommand> get pubCommands {
 ArgParser get pubArgParser {
   var parser = new ArgParser();
   parser.addFlag('help', abbr: 'h', negatable: false,
-    help: 'Prints this usage information');
+      help: 'print this usage information');
   parser.addFlag('version', negatable: false,
-    help: 'Prints the version of Pub');
-  parser.addFlag('trace', help: 'Prints a stack trace when an error occurs');
+      help: 'print the version of pub');
+  parser.addFlag('trace',
+       help: 'print debugging information when an error occurs');
+  parser.addOption('verbosity',
+      help: 'control output verbosity',
+      allowed: ['normal', 'io', 'all'],
+      allowedHelp: {
+        'normal': 'errors, warnings, and user messages are shown',
+        'io':     'IO operations are also shown',
+        'all':    'all output including internal tracing messages are shown'
+      });
+  parser.addFlag('verbose', abbr: 'v', negatable: false,
+      help: 'shortcut for "--verbosity=all"');
   return parser;
 }
 
@@ -66,8 +78,8 @@ main() {
   try {
     globalOptions = pubArgParser.parse(new Options().arguments);
   } on FormatException catch (e) {
-    printError(e.message);
-    printError('Run "pub help" to see available options.');
+    log.error(e.message);
+    log.error('Run "pub help" to see available options.');
     exit(exit_codes.USAGE);
   }
 
@@ -81,6 +93,24 @@ main() {
     return;
   }
 
+  if (globalOptions['trace']) {
+    log.recordTranscript();
+  }
+
+  switch (globalOptions['verbosity']) {
+    case 'normal': log.showNormal(); break;
+    case 'io': log.showIO(); break;
+    case 'all': log.showAll(); break;
+    default:
+      // No specific verbosity given, so check for the shortcut.
+      if (globalOptions['verbose']) {
+        log.showAll();
+      } else {
+        log.showNormal();
+      }
+      break;
+  }
+
   // TODO(nweiz): Have a fallback for this this out automatically once 1145 is
   // fixed.
   var sdkDir = Platform.environment['DART_SDK'];
@@ -99,8 +129,8 @@ main() {
   // Select the command.
   var command = pubCommands[globalOptions.rest[0]];
   if (command == null) {
-    printError('Could not find a command named "${globalOptions.rest[0]}".');
-    printError('Run "pub help" to see available commands.');
+    log.error('Could not find a command named "${globalOptions.rest[0]}".');
+    log.error('Run "pub help" to see available commands.');
     exit(exit_codes.USAGE);
     return;
   }
@@ -112,16 +142,16 @@ main() {
 
 /** Displays usage information for the app. */
 void printUsage([String description = 'Pub is a package manager for Dart.']) {
-  print(description);
-  print('');
-  print('Usage: pub command [arguments]');
-  print('');
-  print('Global options:');
-  print(pubArgParser.getUsage());
-  print('');
+  // Build up a buffer so it shows up as a single log entry.
+  var buffer = new StringBuffer();
+  buffer.add(description);
+  buffer.add('\n\n');
+  buffer.add('Usage: pub command [arguments]\n\n');
+  buffer.add('Global options:\n');
+  buffer.add('${pubArgParser.getUsage()}\n\n');
 
   // Show the commands sorted.
-  print('Available commands:');
+  buffer.add('Available commands:\n');
 
   // TODO(rnystrom): A sorted map would be nice.
   int length = 0;
@@ -136,15 +166,17 @@ void printUsage([String description = 'Pub is a package manager for Dart.']) {
   names.sort((a, b) => a.compareTo(b));
 
   for (var name in names) {
-    print('  ${padRight(name, length)}   ${pubCommands[name].description}');
+    buffer.add('  ${padRight(name, length)}   '
+        '${pubCommands[name].description}\n');
   }
 
-  print('');
-  print('Use "pub help [command]" for more information about a command.');
+  buffer.add('\n');
+  buffer.add('Use "pub help [command]" for more information about a command.');
+  log.message(buffer.toString());
 }
 
 void printVersion() {
-  print('Pub $pubVersion');
+  log.message('Pub $pubVersion');
 }
 
 abstract class PubCommand {
@@ -187,8 +219,8 @@ abstract class PubCommand {
     try {
      commandOptions = commandParser.parse(commandArgs);
     } on FormatException catch (e) {
-      printError(e.message);
-      printError('Use "pub help" for more information.');
+      log.error(e.message);
+      log.error('Use "pub help" for more information.');
       exit(exit_codes.USAGE);
     }
 
@@ -203,9 +235,10 @@ abstract class PubCommand {
         message = message.substring("Exception: ".length);
       }
 
-      printError(message);
+      log.error(message);
       if (globalOptions['trace'] && trace != null) {
-        printError(trace);
+        log.error(trace);
+        log.dumpTranscript();
       }
 
       exit(_chooseExitCode(error));
@@ -261,15 +294,19 @@ abstract class PubCommand {
   /** Displays usage information for this command. */
   void printUsage([String description]) {
     if (description == null) description = this.description;
-    print(description);
-    print('');
-    print('Usage: $usage');
+
+    var buffer = new StringBuffer();
+    buffer.add(description);
+    buffer.add('');
+    buffer.add('Usage: $usage');
 
     var commandUsage = commandParser.getUsage();
     if (!commandUsage.isEmpty) {
-      print('');
-      print(commandUsage);
+      buffer.add('');
+      buffer.add(commandUsage);
     }
+
+    log.message(buffer.toString());
   }
 
   /// Returns the appropriate exit code for [exception], falling back on 1 if no

utils/tests/pub/pub_test.dart

@@ -15,9 +15,16 @@ final USAGE_STRING = """
     Usage: pub command [arguments]
 
     Global options:
-    -h, --help          Prints this usage information
-        --version       Prints the version of Pub
-        --[no-]trace    Prints a stack trace when an error occurs
+    -h, --help            print this usage information
+        --version         print the version of pub
+        --[no-]trace      print debugging information when an error occurs
+        --verbosity       control output verbosity
+
+              [all]       all output including internal tracing messages are shown
+              [io]        IO operations are also shown
+              [normal]    errors, warnings, and user messages are shown
+
+    -v, --verbose         shortcut for "--verbosity=all"
 
     Available commands:
       help      display help information for Pub

utils/tests/pub/test_pub.dart

@@ -639,14 +639,14 @@ Future _doPub(Function fn, sandboxDir, List<String> args, Uri tokenEndpoint) {
     // Find the main pub entrypoint.
     var pubPath = fs.joinPaths(testDirectory, '../../pub/pub.dart');
 
-    var dartArgs =
-        ['--enable-type-checks', '--enable-asserts', pubPath, '--trace'];
+    var dartArgs = ['--checked', pubPath, '--trace'];
     dartArgs.addAll(args);
 
     var environment = {
       'PUB_CACHE': pathInSandbox(cachePath),
       'DART_SDK': pathInSandbox(sdkPath)
     };
+
     if (tokenEndpoint != null) {
       environment['_PUB_TEST_TOKEN_ENDPOINT'] = tokenEndpoint.toString();
     }