Add logging system to pub and sprinkle some logging in.

utils/pub/log.dart

Index: utils/pub/log.dart
diff --git a/utils/pub/log.dart b/utils/pub/log.dart
new file mode 100644
index 0000000000000000000000000000000000000000..8ef2a6445a13af4bfef3c9b4e2d04c7040230013
--- /dev/null
+++ b/utils/pub/log.dart
@@ -0,0 +1,194 @@
+// 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 logging;

[nweiz, 2012/12/05 23:56:54]

It makes me sad that we're rolling our own logging library from scratch when
several others already exist.

[Bob Nystrom, 2012/12/06 01:33:26]

I spent some time integrating pkg/logging in first. It's not bad but I found it
a weird fit. It uses a different set of levels that I had trouble mapping to
what we wanted. It didn't support per-level output configuration so I'd still be
doing most of the work that this does to handle that.

I wouldn't mind unifying at some point (or having this wrap pkg/logging).

+
+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.

[nweiz, 2012/12/05 23:56:54]

Mention which levels are enabled by default and which need to be explicitly
enabled.

[Bob Nystrom, 2012/12/06 01:33:26]

Done.

+class Level {
+  /// An error occurred and an operation could not be completed. Usually shown
+  /// to the user on stderr.
+  static const ERROR = const Level("Error");
+
+  /// Something unexpected happened, but the program was able to continue,
+  /// though possibly in a degraded fashion.
+  static const WARNING = const Level("Warning");
+
+  /// A message intended specifically to be shown to the user.
+  static const MESSAGE = const Level("Message");
+
+  /// 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);

[nweiz, 2012/12/05 23:56:54]

This should probably be private.

[Bob Nystrom, 2012/12/06 01:33:26]

Done.

+  final String name;
+
+  String toString() => name;
+  int get hashCode => name.hashCode;
+}
+
+/// A single log entry.
+class Entry {

[nweiz, 2012/12/05 23:56:54]

I'm not sure this class is more useful than Pair<Level, String>, given that such
a thing is available.

[Bob Nystrom, 2012/12/06 01:33:26]

I like nice named types and Dart is pretty compact at defining them. At some
point, this will likely include a timestamp as well, so I like having a type in
place for that.

+  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,

[nweiz, 2012/12/05 23:56:54]

I'm not sure these arguments are in the right order. ioAsync(operation,
startMessage, endMessage) seems like it would read better, especially if
operation is transformed at all. Having large code blocks come after message
strings always looks very awkward to me.

[Bob Nystrom, 2012/12/06 01:33:26]

I don't mind stuff coming before functions as much as I do stuff coming after.
But I ordered them this way since that's chronological. The start message gets
printed, the future completes, and then the end message is printed.

[nweiz, 2012/12/06 19:40:02]

But the future actually starts before either message gets printed. Ultimately
this is just an aesthetic thing, though, so go with your gut.

+               [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 [INFO]

[nweiz, 2012/12/05 23:56:54]

"INFO" -> "IO"

[Bob Nystrom, 2012/12/06 01:33:26]

Done.

+/// level.
+void process(String executable, List<String> arguments) {
+  io("Spawning $executable ${Strings.join(arguments, ' ')}");
+}
+
+/// Logs the results of running [executable] with [arguments].
+void processResult(String executable, List<String> arguments,

[nweiz, 2012/12/05 23:56:54]

"arguments" is unused.

[Bob Nystrom, 2012/12/06 01:33:26]

Done.

+                    PubProcessResult result) {
+  io("Finished $executable. Exit code ${result.exitCode}.");
+
+  dumpOutput(String name, List<String> output) {
+    if (output.length == 0) {

[nweiz, 2012/12/05 23:56:54]

Add a sanity check for length.

[Bob Nystrom, 2012/12/06 01:33:26]

Done.

+      fine("Nothing output on $name.");
+    } else {
+      fine("$name:");
+      output.forEach(fine);

[nweiz, 2012/12/05 23:56:54]

Another good place to indent.

[Bob Nystrom, 2012/12/06 01:33:26]

See other comments.

+    }
+  }
+
+  dumpOutput("stdout", result.stdout);
+  dumpOutput("stderr", result.stderr);
+}
+
+/// 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] = _logToStderrWithLabel;
+  _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');

[nweiz, 2012/12/05 23:56:54]

You could automatically handle that indentation I've been harping on here by
adding "| " to every line of [message] after the first. This will also make it
multi-line labeled messages clearer.

[Bob Nystrom, 2012/12/06 01:33:26]

See other comments. :)

+}
+
+/// Log function that prints the message to stdout with the level name.
+void _logToStdoutWithLabel(Level level, message) {
+  print('$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('$level: $message\n');
+}