Add logging system to pub and sprinkle some logging in.

utils/pub/io.dart

Index: utils/pub/io.dart
diff --git a/utils/pub/io.dart b/utils/pub/io.dart
index e070aeeb0c0d3530721c8965c8f09e8e4ee46117..aae29874d85b25aff8e2071303e04bb0dd5edaf9 100644
--- a/utils/pub/io.dart
+++ b/utils/pub/io.dart
@@ -13,8 +13,9 @@ import 'dart:uri';
 
 // TODO(nweiz): Make this import better.
 import '../../pkg/http/lib/http.dart' as http;
-import 'utils.dart';
 import 'curl_client.dart';
+import 'log.dart' as log;
+import 'utils.dart';
 
 bool _isGitInstalledCache;
 
@@ -27,15 +28,6 @@ String get currentWorkingDir => new File('.').fullPathSync();
 final NEWLINE_PATTERN = new RegExp("\r\n?|\n\r?");
 
 /**
- * Prints the given string to `stderr` on its own line.
- */
-void printError(value) {
-  stderr.writeString(value.toString());
-  stderr.writeString('\n');
-}
-
-
-/**
  * Joins a number of path string parts into a single path. Handles
  * platform-specific path separators. Parts can be [String], [Directory], or
  * [File] objects.
@@ -122,7 +114,10 @@ Future<bool> exists(path) {
  * the result.
  */
 Future<bool> fileExists(file) {
-  return new File(_getPath(file)).exists();
+  var path = _getPath(file);
+  return log.ioAsync("Seeing if file $path exists.",
+      new File(path).exists(),
+      (exists) => "File $path ${exists ? 'exists' : 'does not exist'}.");
 }
 
 /**
@@ -130,7 +125,17 @@ Future<bool> fileExists(file) {
  * a [File].
  */
 Future<String> readTextFile(file) {
-  return new File(_getPath(file)).readAsString(Encoding.UTF_8);
+  var path = _getPath(file);
+  log.io("Reading text file $path.");
+  return new File(path).readAsString(Encoding.UTF_8).transform((contents) {

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

Why aren't you using log.ioAsync here?

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

Because it uses log.fine and not log.io for the result.

+    // Sanity check: don't spew a huge file.
+    if (contents.length < 1024 * 1024) {
+      log.fine("Read $path. Contents:\n$contents");

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

log.io? Seems like almost every log call in this file should be log.io.

It would be nice to indent the contents so it's visually distinct from the rest
of the output. Maybe prefix "| "? Same goes for writeTextFile.

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

My initial thought was that file contents and process stdout would make the logs
very verbose so I put those in fine. But fine also has all of the important
program flow stuff now, so that's probably useless. I've played around with a
few different sets of log levels. Maybe I should have separate "trace" and
"fine" ones.

For now, just made it io like you suggest.
Since the log entries are prefixed by their level, it works OK now, I think. You
get:

IO: Read file "foo" Contents:
foo
bar
blah
IO: The next log entry

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

I think

IO: Read file "foo" Contents:
| foo
| bar
| blah
IO: The next log entry

would be easier to read. Also, what if the file happens to contain "IO:" or
another log-like prefix? That could get pretty confusing.

[Bob Nystrom, 2012/12/07 21:13:44]

Done.

+    } else {
+      log.fine("Read ${contents.length} characters from $path.");
+    }
+    return contents;
+  });
 }
 
 /**
@@ -138,10 +143,21 @@ Future<String> readTextFile(file) {
  * [contents] to it. Completes when the file is written and closed.
  */
 Future<File> writeTextFile(file, String contents) {
-  file = new File(_getPath(file));
+  var path = _getPath(file);
+  file = new File(path);
+
+  // Sanity check: don't spew a huge file.
+  log.io("Writing ${contents.length} characters to text file $path.");
+  if (contents.length < 1024 * 1024) {
+    log.fine("Contents:\n$contents");
+  }
+
   return file.open(FileMode.WRITE).chain((opened) {
     return opened.writeString(contents).chain((ignore) {
-        return opened.close().transform((ignore) => file);
+        return opened.close().transform((ignore) {

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

"ignore" -> "_"

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

Done.

+          log.fine("Wrote text file $path.");
+          return file;
+        });
     });
   });
 }
@@ -151,7 +167,9 @@ Future<File> writeTextFile(file, String contents) {
  * [Future] that completes when the deletion is done.
  */
 Future<File> deleteFile(file) {
-  return new File(_getPath(file)).delete();
+  var path = _getPath(file);
+  return log.ioAsync("delete file $path",
+      new File(path).delete());

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

Looks like this could be one line? Same goes for several calls below.

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

I put the future stuff on the second line even when I didn't have to since
that's the major action here and I want it to be visible.

 }
 
 /// Writes [stream] to a new file at [path], which may be a [String] or a
@@ -160,12 +178,15 @@ Future<File> deleteFile(file) {
 Future<File> createFileFromStream(InputStream stream, path) {
   path = _getPath(path);
 
+  log.io("Creating $path from stream.");
+
   var completer = new Completer<File>();
   var file = new File(path);
   var outputStream = file.openOutputStream();
   stream.pipe(outputStream);
 
   outputStream.onClosed = () {
+    log.fine("Created $path from stream.");
     completer.complete(file);
   };
 
@@ -193,7 +214,8 @@ Future<File> createFileFromStream(InputStream stream, path) {
  */
 Future<Directory> createDir(dir) {
   dir = _getDirectory(dir);
-  return dir.create();
+  return log.ioAsync("create directory ${dir.path}",
+      dir.create());
 }
 
 /**
@@ -203,10 +225,15 @@ Future<Directory> createDir(dir) {
  */
 Future<Directory> ensureDir(path) {
   path = _getPath(path);
+  log.fine("Ensuring directory $path exists.");
   if (path == '.') return new Future.immediate(new Directory('.'));
 
   return dirExists(path).chain((exists) {
-    if (exists) return new Future.immediate(new Directory(path));
+    if (exists) {
+      log.fine("Directory $path already exists.");
+      return new Future.immediate(new Directory(path));
+    }
+
     return ensureDir(dirname(path)).chain((_) {
       var completer = new Completer<Directory>();
       var future = createDir(path);
@@ -233,7 +260,8 @@ Future<Directory> ensureDir(path) {
  */
 Future<Directory> createTempDir([dir = '']) {
   dir = _getDirectory(dir);
-  return dir.createTemp();
+  return log.ioAsync("create temp directory ${dir.path}",
+      dir.createTemp());
 }
 
 /**
@@ -242,7 +270,8 @@ Future<Directory> createTempDir([dir = '']) {
  */
 Future<Directory> deleteDir(dir) {
   dir = _getDirectory(dir);
-  return dir.delete(recursive: true);
+  return log.ioAsync("delete directory ${dir.path}",
+      dir.delete(recursive: true));
 }
 
 /**
@@ -257,12 +286,17 @@ Future<List<String>> listDir(dir,
   final contents = <String>[];
 
   dir = _getDirectory(dir);
+  log.io("Listing directory ${dir.path}.");
   var lister = dir.list(recursive: recursive);
 
   lister.onDone = (done) {
     // TODO(rnystrom): May need to sort here if it turns out onDir and onFile
     // aren't guaranteed to be called in a certain order. So far, they seem to.
-    if (done) completer.complete(contents);
+    if (done) {
+      log.fine("Listed directory ${dir.path}:\n"
+                "${Strings.join(contents, '\n')}");

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

Indent contents.

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

See previous comment.

+      completer.complete(contents);
+    }
   };
 
   // TODO(nweiz): remove this when issue 4061 is fixed.
@@ -293,7 +327,10 @@ Future<List<String>> listDir(dir,
  */
 Future<bool> dirExists(dir) {
   dir = _getDirectory(dir);
-  return dir.exists();
+  return log.ioAsync("Seeing if directory ${dir.path} exists.",
+      dir.exists(),
+      (exists) => "Directory ${dir.path} "
+                  "${exists ? 'exists' : 'does not exist'}.");
 }
 
 /**
@@ -317,8 +354,14 @@ Future<Directory> cleanDir(dir) {
 /// the destination directory.
 Future<Directory> renameDir(from, String to) {
   from = _getDirectory(from);
+  log.io("Renaming directory ${from.path} to $to.");
 
-  if (Platform.operatingSystem != 'windows') return from.rename(to);
+  if (Platform.operatingSystem != 'windows') {
+    return from.rename(to).transform((dir) {
+      log.fine("Renamed directory ${from.path} to $to.");
+      return dir;
+    });
+  }
 
   // On Windows, we sometimes get failures where the directory is still in use
   // when we try to move it. To be a bit more resilient, we wait and retry a
@@ -326,13 +369,17 @@ Future<Directory> renameDir(from, String to) {
   var attempts = 0;
   attemptRename(_) {
     attempts++;
-    return from.rename(to).transformException((e) {
+    return from.rename(to).transform((dir) {
+      log.fine("Renamed directory ${from.path} to $to.");
+      return dir;
+    }).transformException((e) {
       if (attempts >= 10) {
         throw 'Could not move directory "${from.path}" to "$to". Gave up '
               'after $attempts attempts.';
       }
 
       // Wait a bit and try again.
+      log.fine("Rename ${from.path} failed, retrying (attempt $attempts).");
       return sleep(500).chain(attemptRename);
     });
 
@@ -351,6 +398,8 @@ Future<File> createSymlink(from, to) {
   from = _getPath(from);
   to = _getPath(to);
 
+  log.fine("Create symlink $from -> $to.");
+
   var command = 'ln';
   var args = ['-s', from, to];
 
@@ -382,15 +431,16 @@ Future<File> createPackageSymlink(String name, from, to,
   // See if the package has a "lib" directory.
   from = join(from, 'lib');
   return dirExists(from).chain((exists) {
+    log.fine("Creating package ${isSelfLink ? "self" : ""}link from "
+             "$from to $to.");

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

Including "$from" and "$to" seems redundant with createSymlink.

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

Done.

     if (exists) return createSymlink(from, to);
 
     // It's OK for the self link (i.e. the root package) to not have a lib
     // directory since it may just be a leaf application that only has
     // code in bin or web.
     if (!isSelfLink) {
-      printError(
-          'Warning: Package "$name" does not have a "lib" directory so you '
-          'will not be able to import any libraries from it.');
+      log.warning('Package "$name" does not have a "lib" directory so you '
+                  'will not be able to import any libraries from it.');
     }
 
     return new Future.immediate(to);
@@ -506,6 +556,8 @@ class PubHttpClient extends http.BaseClient {
     : _inner = inner == null ? new http.Client() : inner;
 
   Future<http.StreamedResponse> send(http.BaseRequest request) {
+    log.io("Sending HTTP request $request.");

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

We should do the same trick as for reading/writing files and write the
request/response data if it's short enough and plain text.

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

Is that easy to do? I thought that would be tricky since we only see the
response stream.

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

For the response it may not be possible until we have a better API. For the
request, we can at least check if it's an http.Request and print the body in
that case.

+
     // TODO(nweiz): remove this when issue 4061 is fixed.
     var stackTrace;
     try {
@@ -517,6 +569,9 @@ class PubHttpClient extends http.BaseClient {
     // TODO(nweiz): Ideally the timeout would extend to reading from the
     // response input stream, but until issue 3657 is fixed that's not feasible.
     return timeout(_inner.send(request).chain((streamedResponse) {
+      log.fine("Got response ${streamedResponse.statusCode} "
+               "${streamedResponse.reasonPhrase}.");
+
       if (streamedResponse.statusCode < 400) {
         return new Future.immediate(streamedResponse);
       }
@@ -619,9 +674,13 @@ Future<PubProcessResult> runProcess(String executable, List<String> args,
       if (!lines.isEmpty && lines.last == "") lines.removeLast();
       return lines;
     }
-    return new PubProcessResult(toLines(result.stdout),
+
+    var pubResult = new PubProcessResult(toLines(result.stdout),

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

nit: "pubResult" -> "result"

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

"result" is the already the name of the closure's parameter.

                                 toLines(result.stderr),
                                 result.exitCode);
+
+    log.processResult(executable, args, pubResult);
+    return pubResult;
   });
 }
 
@@ -632,8 +691,9 @@ Future<PubProcessResult> runProcess(String executable, List<String> args,
 /// [environment] is provided, that will be used to augment (not replace) the
 /// the inherited variables.
 Future<Process> startProcess(String executable, List<String> args,
-    {workingDir, Map<String, String> environment}) =>
-  _doProcess(Process.start, executable, args, workingDir, environment);
+    {workingDir, Map<String, String> environment}) {
+  return _doProcess(Process.start, executable, args, workingDir, environment);
+}

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

:(

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

Fixed. Leftover code from some discarded changes to this. I think there used to
be a parameter that wasn't used or something?

 
 /// Calls [fn] with appropriately modified arguments. [fn] should have the same
 /// signature as [Process.start], except that the returned [Future] may have a
@@ -660,6 +720,8 @@ Future _doProcess(Function fn, String executable, List<String> args, workingDir,
     environment.forEach((key, value) => options.environment[key] = value);
   }
 
+  log.process(executable, args);
+
   return fn(executable, args, options);
 }
 
@@ -726,9 +788,13 @@ Future withTempDir(Future fn(String path)) {
   var tempDir;
   var future = createTempDir().chain((dir) {
     tempDir = dir;
+    log.fine('Within temp directory ${tempDir.path}.');

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

"Within" is a little confusing, since the working directory doesn't change. This
also seems redundant with the logging for createTempDir/deleteDir.

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

Removed.

     return fn(tempDir.path);
   });
-  future.onComplete((_) => tempDir.delete(recursive: true));
+  future.onComplete((_) {
+    log.fine('Cleaning up temp directory ${tempDir.path}.');
+    deleteDir(tempDir);
+  });
   return future;
 }
 
@@ -801,6 +867,8 @@ Future<bool> _tryGitCommand(String command) {
 Future<bool> extractTarGz(InputStream stream, destination) {
   destination = _getPath(destination);
 
+  log.fine("Extracting .tar.gz stream to $destination.");
+
   if (Platform.operatingSystem == "windows") {
     return _extractTarGzWindows(stream, destination);
   }
@@ -819,7 +887,10 @@ Future<bool> extractTarGz(InputStream stream, destination) {
     return true;
   });
 
-  return completer.future.transform((exitCode) => exitCode == 0);
+  return completer.future.transform((exitCode) {
+    log.fine("Extracted .tar.gz stream to $destination. Exit code $exitCode.");
+    return exitCode == 0;

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

Not strictly related to this change, but do we ever do anything with this return
value? If not, we should just throw if it's unsuccessful.

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

Not sure. I'll add a TODO.

+  });
 }
 
 Future<bool> _extractTarGzWindows(InputStream stream, String destination) {
@@ -876,7 +947,7 @@ Future<bool> _extractTarGzWindows(InputStream stream, String destination) {
           '${Strings.join(result.stderr, "\n")}';
     }
 
-    // Clean up the temp directory.
+    log.fine('Clean up 7zip temp directory ${tempDir.path}.');

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

It seems more useful to log that tempDir is the 7zip temp directory as soon as
it's created. Then you can rely on the underlying logging for the rest of the
operations.

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

You should see:

Extracting .tar.gz stream to $destination.

and then the next thing after that will be creating the temp directory for it.

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

In that case, this log line is probably redundant with the deleteDir logging.

[Bob Nystrom, 2012/12/07 21:13:44]

I don't think so. Since this is async, the delete can happen much later than the
create, so it may no longer be obvious what the delete is for. This log is
synchronous with the later delete.

     // TODO(rnystrom): Should also delete this if anything fails.
     return deleteDir(tempDir);
   }).transform((_) => true);
@@ -951,7 +1022,8 @@ class PubHttpException implements Exception {
 
   const PubHttpException(this.response);
 
-  String toString() => 'HTTP error ${response.statusCode}: ${response.reason}';
+  String toString() => 'HTTP error ${response.statusCode}: '
+      '${response.reasonPhrase}';
 }
 
 /**