Add logging system to pub and sprinkle some logging in.

utils/pub/io.dart

 // 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.
 
 /**
  * Helper functionality to make working with IO easier.
  */
 library io;
 
 import 'dart:io';
 import 'dart:isolate';
 import 'dart:uri';
 
 // TODO(nweiz): Make this import better.
 import '../../pkg/http/lib/http.dart' as http;
+import 'curl_client.dart';
+import 'log.dart' as log;
 import 'utils.dart';
-import 'curl_client.dart';
 
 bool _isGitInstalledCache;
 
 /// The cached Git command.
 String _gitCommandCache;
 
 /** Gets the current working directory. */
 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.
  */
 String join(part1, [part2, part3, part4]) {
   final parts = _sanitizePath(part1).split('/');
 
   for (final part in [part2, part3, part4]) {
     if (part == null) continue;
 
@@ skipping 66 matching lines @@
     return results[0] || results[1];
   });
 }
 
 /**
  * Asynchronously determines if [file], which can be a [String] file path or a
  * [File], exists on the file system. Returns a [Future] that completes with
  * 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'}.");
 }
 
 /**
  * Reads the contents of the text file [file], which can either be a [String] or
  * a [File].
  */
 Future<String> readTextFile(file) {
-  return new File(_getPath(file)).readAsString(Encoding.UTF_8);
+  var path = _getPath(file);
+  return log.ioAsync("Reading text file $path.",
+      new File(path).readAsString(Encoding.UTF_8),
+      (contents) {
+        // Sanity check: don't spew a huge file.
+        if (contents.length < 1024 * 1024) {
+          return "Read $path. Contents:\n$contents";
+        } else {
+          return "Read ${contents.length} characters from $path.";
+        }
+      });
 }
 
 /**
  * Creates [file] (which can either be a [String] or a [File]), and writes
  * [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((_) {
+          log.fine("Wrote text file $path.");
+          return file;
+        });
     });
   });
 }
 
 /**
  * Asynchronously deletes [file], which can be a [String] or a [File]. Returns a
  * [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());
 }
 
 /// Writes [stream] to a new file at [path], which may be a [String] or a
 /// [File]. Will replace any file already at that path. Completes when the file
 /// is done being written.
 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);
   };
 
   // TODO(nweiz): remove this when issue 4061 is fixed.
   var stackTrace;
   try {
     throw "";
   } catch (_, localStackTrace) {
     stackTrace = localStackTrace;
   }
 
   completeError(error) {
-    if (!completer.isComplete) completer.completeException(error, stackTrace);
+    if (!completer.isComplete) {
+      completer.completeException(error, stackTrace);
+    } else {
+      log.fine("Got error after stream was closed: $error");
+    }
   }
 
   stream.onError = completeError;
   outputStream.onError = completeError;
 
   return completer.future;
 }
 
 /**
  * Creates a directory [dir]. Returns a [Future] that completes when the
  * directory is created.
  */
 Future<Directory> createDir(dir) {
   dir = _getDirectory(dir);
-  return dir.create();
+  return log.ioAsync("create directory ${dir.path}",
+      dir.create());
 }
 
 /**
  * Ensures that [path] and all its parent directories exist. If they don't
  * exist, creates them. Returns a [Future] that completes once all the
  * directories are created.
  */
 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);
       future.handleException((error) {
         if (error is! DirectoryIOException) return false;
         // Error 17 means the directory already exists (or 183 on Windows).
         if (error.osError.errorCode != 17 &&
-            error.osError.errorCode != 183) return false;
+            error.osError.errorCode != 183) {
+          log.fine("Got 'already exists' error when creating directory.");
+          return false;
+        }
 
         completer.complete(_getDirectory(path));
         return true;
       });
       future.then(completer.complete);
       return completer.future;
     });
   });
 }
 
 /**
  * Creates a temp directory whose name will be based on [dir] with a unique
  * suffix appended to it. If [dir] is not provided, a temp directory will be
  * created in a platform-dependent temporary location. Returns a [Future] that
  * completes when the directory is created.
  */
 Future<Directory> createTempDir([dir = '']) {
   dir = _getDirectory(dir);
-  return dir.createTemp();
+  return log.ioAsync("create temp directory ${dir.path}",
+      dir.createTemp());
 }
 
 /**
  * Asynchronously recursively deletes [dir], which can be a [String] or a
  * [Directory]. Returns a [Future] that completes when the deletion is done.
  */
 Future<Directory> deleteDir(dir) {
   dir = _getDirectory(dir);
-  return dir.delete(recursive: true);
+  return log.ioAsync("delete directory ${dir.path}",
+      dir.delete(recursive: true));
 }
 
 /**
  * Asynchronously lists the contents of [dir], which can be a [String] directory
  * path or a [Directory]. If [recursive] is `true`, lists subdirectory contents
  * (defaults to `false`). If [includeHiddenFiles] is `true`, includes files and
  * directories beginning with `.` (defaults to `false`).
  */
 Future<List<String>> listDir(dir,
     {bool recursive: false, bool includeHiddenFiles: false}) {
   final completer = new Completer<List<String>>();
   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')}");
+      completer.complete(contents);
+    }
   };
 
   // TODO(nweiz): remove this when issue 4061 is fixed.
   var stackTrace;
   try {
     throw "";
   } catch (_, localStackTrace) {
     stackTrace = localStackTrace;
   }
 
@@ skipping 10 matching lines @@
   return completer.future;
 }
 
 /**
  * Asynchronously determines if [dir], which can be a [String] directory path
  * or a [Directory], exists on the file system. Returns a [Future] that
  * completes with the result.
  */
 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'}.");
 }
 
 /**
  * "Cleans" [dir]. If that directory already exists, it will be deleted. Then a
  * new empty directory will be created. Returns a [Future] that completes when
  * the new clean directory is created.
  */
 Future<Directory> cleanDir(dir) {
   return dirExists(dir).chain((exists) {
     if (exists) {
       // Delete it first.
       return deleteDir(dir).chain((_) => createDir(dir));
     } else {
       // Just create it.
       return createDir(dir);
     }
   });
 }
 
 /// Renames (i.e. moves) the directory [from] to [to]. Returns a [Future] with
 /// 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
   // few times.
   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);
     });
 
     return from;
   }
 
   return attemptRename(null);
 }
 
 /**
  * Creates a new symlink that creates an alias from [from] to [to], both of
  * which can be a [String], [File], or [Directory]. Returns a [Future] which
  * completes to the symlink file (i.e. [to]).
  */
 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];
 
   if (Platform.operatingSystem == 'windows') {
     // Call mklink on Windows to create an NTFS junction point. Only works on
     // Vista or later. (Junction points are available earlier, but the "mklink"
     // command is not.) I'm using a junction point (/j) here instead of a soft
     // link (/d) because the latter requires some privilege shenanigans that
     // I'm not sure how to specify from the command line.
     command = 'mklink';
@@ skipping 11 matching lines @@
  * package [from] to [to], both of which can be a [String], [File], or
  * [Directory]. Returns a [Future] which completes to the symlink file (i.e.
  * [to]). If [from] does not have a `lib` directory, this shows a warning if
  * appropriate and then does nothing.
  */
 Future<File> createPackageSymlink(String name, from, to,
     {bool isSelfLink: false}) {
   // See if the package has a "lib" directory.
   from = join(from, 'lib');
   return dirExists(from).chain((exists) {
+    log.fine("Creating ${isSelfLink ? "self" : ""}link for package '$name'.");
     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('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);
   });
 }
 
 /// Given [entry] which may be a [String], [File], or [Directory] relative to
 /// the current working directory, returns its full canonicalized path.
 String getFullPath(entry) {
   var path = _getPath(entry);
@@ skipping 95 matching lines @@
 
 /// An HTTP client that transforms 40* errors and socket exceptions into more
 /// user-friendly error messages.
 class PubHttpClient extends http.BaseClient {
   final http.Client _inner;
 
   PubHttpClient([http.Client inner])
     : _inner = inner == null ? new http.Client() : inner;
 
   Future<http.StreamedResponse> send(http.BaseRequest request) {
+    log.io("Sending HTTP request $request.");
+
     // TODO(nweiz): remove this when issue 4061 is fixed.
     var stackTrace;
     try {
       throw null;
     } catch (_, localStackTrace) {
       stackTrace = localStackTrace;
     }
 
     // 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}.");
+
       var status = streamedResponse.statusCode;
       // 401 responses should be handled by the OAuth2 client. It's very
       // unlikely that they'll be returned by non-OAuth2 requests.
       if (status < 400 || status == 401) {
         return new Future.immediate(streamedResponse);
       }
 
       return http.Response.fromStream(streamedResponse).transform((response) {
         throw new PubHttpException(response);
       });
@@ skipping 85 matching lines @@
 Future<PubProcessResult> runProcess(String executable, List<String> args,
     {workingDir, Map<String, String> environment}) {
   return _doProcess(Process.run, executable, args, workingDir, environment)
       .transform((result) {
     // TODO(rnystrom): Remove this and change to returning one string.
     List<String> toLines(String output) {
       var lines = output.split(NEWLINE_PATTERN);
       if (!lines.isEmpty && lines.last == "") lines.removeLast();
       return lines;
     }
-    return new PubProcessResult(toLines(result.stdout),
+
+    var pubResult = new PubProcessResult(toLines(result.stdout),
                                 toLines(result.stderr),
                                 result.exitCode);
+
+    log.processResult(executable, pubResult);
+    return pubResult;
   });
 }
 
 /// Spawns the process located at [executable], passing in [args]. Returns a
 /// [Future] that will complete with the [Process] once it's been started.
 ///
 /// The spawned process will inherit its parent's environment variables. If
 /// [environment] is provided, that will be used to augment (not replace) the
 /// the inherited variables.
 Future<Process> startProcess(String executable, List<String> args,
@@ skipping 18 matching lines @@
   final options = new ProcessOptions();
   if (workingDir != null) {
     options.workingDirectory = _getDirectory(workingDir).path;
   }
 
   if (environment != null) {
     options.environment = new Map.from(Platform.environment);
     environment.forEach((key, value) => options.environment[key] = value);
   }
 
+  log.process(executable, args);
+
   return fn(executable, args, options);
 }
 
 /// Closes [response] while ignoring the body of [request]. Returns a Future
 /// that completes once the response is closed.
 ///
 /// Due to issue 6984, it's necessary to drain the request body before closing
 /// the response.
 Future closeHttpResponse(HttpRequest request, HttpResponse response) {
   // TODO(nweiz): remove this when issue 4061 is fixed.
@@ skipping 48 matching lines @@
 
 /// Creates a temporary directory and passes its path to [fn]. Once the [Future]
 /// returned by [fn] completes, the temporary directory and all its contents
 /// will be deleted.
 Future withTempDir(Future fn(String path)) {
   var tempDir;
   var future = createTempDir().chain((dir) {
     tempDir = dir;
     return fn(tempDir.path);
   });
-  future.onComplete((_) => tempDir.delete(recursive: true));
+  future.onComplete((_) {
+    log.fine('Cleaning up temp directory ${tempDir.path}.');
+    deleteDir(tempDir);
+  });
   return future;
 }
 
 /// Tests whether or not the git command-line app is available for use.
 Future<bool> get isGitInstalled {
   if (_isGitInstalledCache != null) {
     // TODO(rnystrom): The sleep is to pump the message queue. Can use
     // Future.immediate() when #3356 is fixed.
     return sleep(0).transform((_) => _isGitInstalledCache);
   }
@@ skipping 52 matching lines @@
   return completer.future;
 }
 
 /**
  * Extracts a `.tar.gz` file from [stream] to [destination], which can be a
  * directory or a path. Returns whether or not the extraction was successful.
  */
 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);
   }
 
   var completer = new Completer<int>();
   var processFuture = Process.start("tar",
       ["--extract", "--gunzip", "--directory", destination]);
   processFuture.then((process) {
     process.onExit = completer.complete;
     stream.pipe(process.stdin);
     process.stdout.pipe(stdout, close: false);
     process.stderr.pipe(stderr, close: false);
   });
   processFuture.handleException((error) {
     completer.completeException(error, processFuture.stackTrace);
     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.");
+    // TODO(rnystrom): Does anything check this result value? If not, it should
+    // throw on a bad exit code.
+    return exitCode == 0;
+  });
 }
 
 Future<bool> _extractTarGzWindows(InputStream stream, String destination) {
   // TODO(rnystrom): In the repo's history, there is an older implementation of
   // this that does everything in memory by piping streams directly together
   // instead of writing out temp files. The code is simpler, but unfortunately,
   // 7zip seems to periodically fail when we invoke it from Dart and tell it to
   // read from stdin instead of a file. Consider resurrecting that version if
   // we can figure out why it fails.
 
@@ skipping 36 matching lines @@
 
     // Untar the archive into the destination directory.
     return runProcess(command, ['x', tarFile], workingDir: destination);
   }).chain((result) {
     if (result.exitCode != 0) {
       throw 'Could not un-tar (exit code ${result.exitCode}). Error:\n'
           '${Strings.join(result.stdout, "\n")}\n'
           '${Strings.join(result.stderr, "\n")}';
     }
 
-    // Clean up the temp directory.
+    log.fine('Clean up 7zip temp directory ${tempDir.path}.');
     // TODO(rnystrom): Should also delete this if anything fails.
     return deleteDir(tempDir);
   }).transform((_) => true);
 }
 
 /// Create a .tar.gz archive from a list of entries. Each entry can be a
 /// [String], [Directory], or [File] object. The root of the archive is
 /// considered to be [baseDir], which defaults to the current working directory.
 /// Returns an [InputStream] that will emit the contents of the archive.
 InputStream createTarGz(List contents, {baseDir}) {
+  log.fine('Creating .tag.gz stream containing:');
+  contents.forEach(log.fine);
+
   // TODO(nweiz): Propagate errors to the returned stream (including non-zero
   // exit codes). See issue 3657.
   var stream = new ListInputStream();
 
   if (baseDir == null) baseDir = currentWorkingDir;
   baseDir = getFullPath(baseDir);
   contents = contents.map((entry) {
     entry = getFullPath(entry);
     if (!isBeneath(entry, baseDir)) {
       throw 'Entry $entry is not inside $baseDir.';
@@ skipping 45 matching lines @@
 
 /**
  * Exception thrown when an HTTP operation fails.
  */
 class PubHttpException implements Exception {
   final http.Response response;
 
   const PubHttpException(this.response);
 
   String toString() => 'HTTP error ${response.statusCode}: '
-    '${response.reasonPhrase}';
+      '${response.reasonPhrase}';
 }
 
 /**
  * Exception thrown when an operation times out.
  */
 class TimeoutException implements Exception {
   final String message;
 
   const TimeoutException(this.message);
 
@@ skipping 50 matching lines @@
   return new Directory(entry);
 }
 
 /**
  * Gets a [Uri] for [uri], which can either already be one, or be a [String].
  */
 Uri _getUri(uri) {
   if (uri is Uri) return uri;
   return new Uri.fromString(uri);
 }