Add logging system to pub and sprinkle some logging in.

Add logging system to pub and sprinkle some logging in.

We'll have to tune which things we log over time, but this covers
most IO operations which is where almost all of our problems come
from.

This patch also means that going forward you should no longer call
print() or printError() (which is gone) directly. Instead:

print() -> log.message()
printError() -> log.error()

That ensures all messages will correctly get added to the log's
transcript.

Committed: https://code.google.com/p/dart/source/detail?r=15827

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

https://codereview.chromium.org/11437019/diff/2001/pkg/http/lib/src/base_requ...
File pkg/http/lib/src/base_request.dart (right):

https://codereview.chromium.org/11437019/diff/2001/pkg/http/lib/src/base_requ...
pkg/http/lib/src/base_request.dart:130: // TODO(rnystrom): Include headers?
I don't think we want to include the headers (or stuff like request body) here.
I feel like toString() methods intended for debugging should be a summary when
possible, rather than the whole shebang.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/command_lish.dart
File utils/pub/command_lish.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/command_lish.dar...
utils/pub/command_lish.dart:55: files.forEach(log.fine);
Probably more readable if we indent these file names (see also _logToSdout).

It seems like createTarGz should have this logging.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart
File utils/pub/curl_client.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart...
utils/pub/curl_client.dart:41: log.process(executable, arguments);
Style nit: swap this with the line above it.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart...
utils/pub/curl_client.dart:105: log.fine("Curl request arguments: $arguments");
This seems redundant with log.process above.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart...
utils/pub/curl_client.dart:133: log.fine(message);
Give some context for this message.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/entrypoint.dart
File utils/pub/entrypoint.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/entrypoint.dart#...
utils/pub/entrypoint.dart:85: log.fine("Deleting package directory
$packageDir.");
Redundant with deleteDir.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/entrypoint.dart#...
utils/pub/entrypoint.dart:167: log.fine("Loading lockfile $lockFilePath.");
"$lockFilePath" is redundant.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/entrypoint.dart#...
utils/pub/entrypoint.dart:199: log.fine("Saving lockfile $lockFilePath.");
"$lockFilePath" is redundant.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart
File utils/pub/io.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode130
utils/pub/io.dart:130: return new
File(path).readAsString(Encoding.UTF_8).transform((contents) {
Why aren't you using log.ioAsync here?

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode133
utils/pub/io.dart:133: log.fine("Read $path. Contents:\n$contents");
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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode157
utils/pub/io.dart:157: return opened.close().transform((ignore) {
"ignore" -> "_"

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode172
utils/pub/io.dart:172: new File(path).delete());
Looks like this could be one line? Same goes for several calls below.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode202
utils/pub/io.dart:202: if (!completer.isComplete)
completer.completeException(error, stackTrace);
Log the error if the completer is complete.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode244
utils/pub/io.dart:244: error.osError.errorCode != 183) return false;
Log this case as well.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode297
utils/pub/io.dart:297: "${Strings.join(contents, '\n')}");
Indent contents.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode435
utils/pub/io.dart:435: "$from to $to.");
Including "$from" and "$to" seems redundant with createSymlink.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode559
utils/pub/io.dart:559: log.io("Sending HTTP request $request.");
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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode678
utils/pub/io.dart:678: var pubResult = new
PubProcessResult(toLines(result.stdout),
nit: "pubResult" -> "result"

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode696
utils/pub/io.dart:696: }
:(

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode787
utils/pub/io.dart:787: Future withTempDir(Future fn(String path)) {
It would probably help with debugging if this and createTempDir() could make
directories with reasonable names, like the "mktemp" command on Linux.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode791
utils/pub/io.dart:791: log.fine('Within temp directory ${tempDir.path}.');
"Within" is a little confusing, since the working directory doesn't change. This
also seems redundant with the logging for createTempDir/deleteDir.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode892
utils/pub/io.dart:892: return exitCode == 0;
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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode950
utils/pub/io.dart:950: log.fine('Clean up 7zip temp directory
${tempDir.path}.');
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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart
File utils/pub/log.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode6
utils/pub/log.dart:6: library logging;
It makes me sad that we're rolling our own logging library from scratch when
several others already exist.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode18
utils/pub/log.dart:18: /// An enum type for defining the different logging
levels.
Mention which levels are enabled by default and which need to be explicitly
enabled.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode40
utils/pub/log.dart:40: const Level(this.name);
This should probably be private.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode48
utils/pub/log.dart:48: class Entry {
I'm not sure this class is more useful than Pair<Level, String>, given that such
a thing is available.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode89
utils/pub/log.dart:89: Future ioAsync(String startMessage, Future operation,
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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode107
utils/pub/log.dart:107: /// Logs the spawning of an [executable] process with
[arguments] at [INFO]
"INFO" -> "IO"

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode114
utils/pub/log.dart:114: void processResult(String executable, List<String>
arguments,
"arguments" is unused.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode119
utils/pub/log.dart:119: if (output.length == 0) {
Add a sanity check for length.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode123
utils/pub/log.dart:123: output.forEach(fine);
Another good place to indent.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode178
utils/pub/log.dart:178: print('$message');
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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart
File utils/pub/oauth2.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:95: log.fine('Loading OAuth2 credentials from $path.');
"from $path" is redundant, and also false if _credentials is null. I'd remove
it, and also log if we return early due to _credentials.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:99: log.fine('No credentials found at $path.');
I wouldn't include most of these fine log statements; they'll be clear from the
io.dart operations. Maybe add a transform at the end that mentions whether or
not re-authorization is required.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:127: log.fine('Saving OAuth2 credentials to $path.');
"to $path" is redundant.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:181: log.message(
Unlike print(), passing multiline strings to log.message isn't equivalent to
calling it multiple times. Probably want to switch to the latter here?

https://codereview.chromium.org/11437019/diff/2001/utils/pub/pub.dart
File utils/pub/pub.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/pub.dart#newcode68
utils/pub/pub.dart:68: allowed: ['normal', 'info', 'debug', 'all'],
"info" -> "io"

https://codereview.chromium.org/11437019/diff/2001/utils/pub/version_solver.dart
File utils/pub/version_solver.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/version_solver.d...
utils/pub/version_solver.dart:456: log.fine("Removing $depender's constraint on
$dependent.");
Log what the removed constraint was.

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

Thanks!

https://codereview.chromium.org/11437019/diff/2001/pkg/http/lib/src/base_requ...
File pkg/http/lib/src/base_request.dart (right):

https://codereview.chromium.org/11437019/diff/2001/pkg/http/lib/src/base_requ...
pkg/http/lib/src/base_request.dart:130: // TODO(rnystrom): Include headers?
On 2012/12/05 23:56:54, nweiz wrote:
> I don't think we want to include the headers (or stuff like request body)
here.
> I feel like toString() methods intended for debugging should be a summary when
> possible, rather than the whole shebang.

Removed TODO.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/command_lish.dart
File utils/pub/command_lish.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/command_lish.dar...
utils/pub/command_lish.dart:55: files.forEach(log.fine);
On 2012/12/05 23:56:54, nweiz wrote:
> Probably more readable if we indent these file names (see also _logToSdout).
> 
> It seems like createTarGz should have this logging.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart
File utils/pub/curl_client.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart...
utils/pub/curl_client.dart:41: log.process(executable, arguments);
On 2012/12/05 23:56:54, nweiz wrote:
> Style nit: swap this with the line above it.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart...
utils/pub/curl_client.dart:105: log.fine("Curl request arguments: $arguments");
On 2012/12/05 23:56:54, nweiz wrote:
> This seems redundant with log.process above.

Removed. I think for some reason when I skimmed the code I didn't think the args
were actually just the command-line args.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/curl_client.dart...
utils/pub/curl_client.dart:133: log.fine(message);
On 2012/12/05 23:56:54, nweiz wrote:
> Give some context for this message.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/entrypoint.dart
File utils/pub/entrypoint.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/entrypoint.dart#...
utils/pub/entrypoint.dart:85: log.fine("Deleting package directory
$packageDir.");
On 2012/12/05 23:56:54, nweiz wrote:
> Redundant with deleteDir.

Replaced path with package name in log. I still want to log here so I know why
the directory is being deleted.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/entrypoint.dart#...
utils/pub/entrypoint.dart:167: log.fine("Loading lockfile $lockFilePath.");
On 2012/12/05 23:56:54, nweiz wrote:
> "$lockFilePath" is redundant.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart
File utils/pub/io.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode130
utils/pub/io.dart:130: return new
File(path).readAsString(Encoding.UTF_8).transform((contents) {
On 2012/12/05 23:56:54, nweiz wrote:
> Why aren't you using log.ioAsync here?

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode133
utils/pub/io.dart:133: log.fine("Read $path. Contents:\n$contents");
On 2012/12/05 23:56:54, nweiz wrote:
> log.io? Seems like almost every log call in this file should be log.io.

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.

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

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode157
utils/pub/io.dart:157: return opened.close().transform((ignore) {
On 2012/12/05 23:56:54, nweiz wrote:
> "ignore" -> "_"

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode172
utils/pub/io.dart:172: new File(path).delete());
On 2012/12/05 23:56:54, nweiz wrote:
> Looks like this could be one line? Same goes for several calls below.

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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode202
utils/pub/io.dart:202: if (!completer.isComplete)
completer.completeException(error, stackTrace);
On 2012/12/05 23:56:54, nweiz wrote:
> Log the error if the completer is complete.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode244
utils/pub/io.dart:244: error.osError.errorCode != 183) return false;
On 2012/12/05 23:56:54, nweiz wrote:
> Log this case as well.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode297
utils/pub/io.dart:297: "${Strings.join(contents, '\n')}");
On 2012/12/05 23:56:54, nweiz wrote:
> Indent contents.

See previous comment.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode435
utils/pub/io.dart:435: "$from to $to.");
On 2012/12/05 23:56:54, nweiz wrote:
> Including "$from" and "$to" seems redundant with createSymlink.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode559
utils/pub/io.dart:559: log.io("Sending HTTP request $request.");
On 2012/12/05 23:56:54, nweiz wrote:
> 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.

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode678
utils/pub/io.dart:678: var pubResult = new
PubProcessResult(toLines(result.stdout),
On 2012/12/05 23:56:54, nweiz wrote:
> nit: "pubResult" -> "result"

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode696
utils/pub/io.dart:696: }
On 2012/12/05 23:56:54, nweiz wrote:
> :(

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode787
utils/pub/io.dart:787: Future withTempDir(Future fn(String path)) {
On 2012/12/05 23:56:54, nweiz wrote:
> It would probably help with debugging if this and createTempDir() could make
> directories with reasonable names, like the "mktemp" command on Linux.

Agreed, but dart:io doesn't support that. :(

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode791
utils/pub/io.dart:791: log.fine('Within temp directory ${tempDir.path}.');
On 2012/12/05 23:56:54, nweiz wrote:
> "Within" is a little confusing, since the working directory doesn't change.
This
> also seems redundant with the logging for createTempDir/deleteDir.

Removed.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode892
utils/pub/io.dart:892: return exitCode == 0;
On 2012/12/05 23:56:54, nweiz wrote:
> 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.

Not sure. I'll add a TODO.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode950
utils/pub/io.dart:950: log.fine('Clean up 7zip temp directory
${tempDir.path}.');
On 2012/12/05 23:56:54, nweiz wrote:
> It seems more useful to log that tempDir is the 7zip temp directory as soon as
> it's created.

You should see:

Extracting .tar.gz stream to $destination.

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

> Then you can rely on the underlying logging for the rest of the
> operations.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart
File utils/pub/log.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode6
utils/pub/log.dart:6: library logging;
On 2012/12/05 23:56:54, nweiz wrote:
> It makes me sad that we're rolling our own logging library from scratch when
> several others already exist.

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode18
utils/pub/log.dart:18: /// An enum type for defining the different logging
levels.
On 2012/12/05 23:56:54, nweiz wrote:
> Mention which levels are enabled by default and which need to be explicitly
> enabled.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode40
utils/pub/log.dart:40: const Level(this.name);
On 2012/12/05 23:56:54, nweiz wrote:
> This should probably be private.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode48
utils/pub/log.dart:48: class Entry {
On 2012/12/05 23:56:54, nweiz wrote:
> I'm not sure this class is more useful than Pair<Level, String>, given that
such
> a thing is available.

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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode89
utils/pub/log.dart:89: Future ioAsync(String startMessage, Future operation,
On 2012/12/05 23:56:54, nweiz wrote:
> 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.

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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode107
utils/pub/log.dart:107: /// Logs the spawning of an [executable] process with
[arguments] at [INFO]
On 2012/12/05 23:56:54, nweiz wrote:
> "INFO" -> "IO"

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode114
utils/pub/log.dart:114: void processResult(String executable, List<String>
arguments,
On 2012/12/05 23:56:54, nweiz wrote:
> "arguments" is unused.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode119
utils/pub/log.dart:119: if (output.length == 0) {
On 2012/12/05 23:56:54, nweiz wrote:
> Add a sanity check for length.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode123
utils/pub/log.dart:123: output.forEach(fine);
On 2012/12/05 23:56:54, nweiz wrote:
> Another good place to indent.

See other comments.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode178
utils/pub/log.dart:178: print('$message');
On 2012/12/05 23:56:54, nweiz wrote:
> 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.

See other comments. :)

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart
File utils/pub/oauth2.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:95: log.fine('Loading OAuth2 credentials from $path.');
On 2012/12/05 23:56:54, nweiz wrote:
> "from $path" is redundant, and also false if _credentials is null. I'd remove
> it, and also log if we return early due to _credentials.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:99: log.fine('No credentials found at $path.');
On 2012/12/05 23:56:54, nweiz wrote:
> I wouldn't include most of these fine log statements; they'll be clear from
the
> io.dart operations.

Done.

> Maybe add a transform at the end that mentions whether or
> not re-authorization is required.

Unless you really want, I'll leave that off for now. We can always add more
later.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:127: log.fine('Saving OAuth2 credentials to $path.');
On 2012/12/05 23:56:54, nweiz wrote:
> "to $path" is redundant.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:181: log.message(
On 2012/12/05 23:56:54, nweiz wrote:
> Unlike print(), passing multiline strings to log.message isn't equivalent to
> calling it multiple times.

It's equivalent in normal verbosity, I think. In verbose mode, it isn't, but in
that case I think this is actually better because it makes it clear it's a
single message from a single place in code.

> Probably want to switch to the latter here?

I think this might actually be slightly preferred?

https://codereview.chromium.org/11437019/diff/2001/utils/pub/pub.dart
File utils/pub/pub.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/pub.dart#newcode68
utils/pub/pub.dart:68: allowed: ['normal', 'info', 'debug', 'all'],
On 2012/12/05 23:56:54, nweiz wrote:
> "info" -> "io"

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/version_solver.dart
File utils/pub/version_solver.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/version_solver.d...
utils/pub/version_solver.dart:456: log.fine("Removing $depender's constraint on
$dependent.");
On 2012/12/05 23:56:54, nweiz wrote:
> Log what the removed constraint was.

Done.

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

lgtm

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart
File utils/pub/io.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode133
utils/pub/io.dart:133: log.fine("Read $path. Contents:\n$contents");
On 2012/12/06 01:33:26, Bob Nystrom wrote:
> On 2012/12/05 23:56:54, nweiz wrote:
> > log.io? Seems like almost every log call in this file should be log.io.
> 
> 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.
> 
> > 
> > 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.
> 
> 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

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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode559
utils/pub/io.dart:559: log.io("Sending HTTP request $request.");
On 2012/12/06 01:33:26, Bob Nystrom wrote:
> On 2012/12/05 23:56:54, nweiz wrote:
> > 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.
> 
> Is that easy to do? I thought that would be tricky since we only see the
> response stream.

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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode787
utils/pub/io.dart:787: Future withTempDir(Future fn(String path)) {
On 2012/12/06 01:33:26, Bob Nystrom wrote:
> On 2012/12/05 23:56:54, nweiz wrote:
> > It would probably help with debugging if this and createTempDir() could make
> > directories with reasonable names, like the "mktemp" command on Linux.
> 
> Agreed, but dart:io doesn't support that. :(

File a bug?

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode950
utils/pub/io.dart:950: log.fine('Clean up 7zip temp directory
${tempDir.path}.');
On 2012/12/06 01:33:26, Bob Nystrom wrote:
> On 2012/12/05 23:56:54, nweiz wrote:
> > It seems more useful to log that tempDir is the 7zip temp directory as soon
as
> > it's created.
> 
> You should see:
> 
> Extracting .tar.gz stream to $destination.
> 
> and then the next thing after that will be creating the temp directory for it.
> 
> > Then you can rely on the underlying logging for the rest of the
> > operations.
> 

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart
File utils/pub/log.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/log.dart#newcode89
utils/pub/log.dart:89: Future ioAsync(String startMessage, Future operation,
On 2012/12/06 01:33:26, Bob Nystrom wrote:
> On 2012/12/05 23:56:54, nweiz wrote:
> > 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.
> 
> 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.

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

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart
File utils/pub/oauth2.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:181: log.message(
On 2012/12/06 01:33:26, Bob Nystrom wrote:
> On 2012/12/05 23:56:54, nweiz wrote:
> > Unlike print(), passing multiline strings to log.message isn't equivalent to
> > calling it multiple times.
> 
> It's equivalent in normal verbosity, I think. In verbose mode, it isn't, but
in
> that case I think this is actually better because it makes it clear it's a
> single message from a single place in code.

There are other places where multiple lines get printed in multiple messages. At
least we should be consistent.

> I think this might actually be slightly preferred?

I think the other way looks nicer, but that's just me.

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

Forgot to publish these comments yesterday...

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart
File utils/pub/io.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode133
utils/pub/io.dart:133: log.fine("Read $path. Contents:\n$contents");
On 2012/12/06 19:40:02, nweiz wrote:
> On 2012/12/06 01:33:26, Bob Nystrom wrote:
> > On 2012/12/05 23:56:54, nweiz wrote:
> > > log.io? Seems like almost every log call in this file should be log.io.
> > 
> > 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.
> > 
> > > 
> > > 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.
> > 
> > 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
> 
> 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.

Done.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode787
utils/pub/io.dart:787: Future withTempDir(Future fn(String path)) {
On 2012/12/06 19:40:02, nweiz wrote:
> On 2012/12/06 01:33:26, Bob Nystrom wrote:
> > On 2012/12/05 23:56:54, nweiz wrote:
> > > It would probably help with debugging if this and createTempDir() could
make
> > > directories with reasonable names, like the "mktemp" command on Linux.
> > 
> > Agreed, but dart:io doesn't support that. :(
> 
> File a bug?

Eh, I don't care that much about it.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/io.dart#newcode950
utils/pub/io.dart:950: log.fine('Clean up 7zip temp directory
${tempDir.path}.');
On 2012/12/06 19:40:02, nweiz wrote:
> On 2012/12/06 01:33:26, Bob Nystrom wrote:
> > On 2012/12/05 23:56:54, nweiz wrote:
> > > It seems more useful to log that tempDir is the 7zip temp directory as
soon
> as
> > > it's created.
> > 
> > You should see:
> > 
> > Extracting .tar.gz stream to $destination.
> > 
> > and then the next thing after that will be creating the temp directory for
it.
> > 
> > > Then you can rely on the underlying logging for the rest of the
> > > operations.
> > 
> 
> In that case, this log line is probably redundant with the deleteDir logging.

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.

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart
File utils/pub/oauth2.dart (right):

https://codereview.chromium.org/11437019/diff/2001/utils/pub/oauth2.dart#newc...
utils/pub/oauth2.dart:181: log.message(
On 2012/12/06 19:40:02, nweiz wrote:
> On 2012/12/06 01:33:26, Bob Nystrom wrote:
> > On 2012/12/05 23:56:54, nweiz wrote:
> > > Unlike print(), passing multiline strings to log.message isn't equivalent
to
> > > calling it multiple times.
> > 
> > It's equivalent in normal verbosity, I think. In verbose mode, it isn't, but
> in
> > that case I think this is actually better because it makes it clear it's a
> > single message from a single place in code.
> 
> There are other places where multiple lines get printed in multiple messages.
At
> least we should be consistent.
> 
> > I think this might actually be slightly preferred?
> 
> I think the other way looks nicer, but that's just me.

Per our discussion, this way is the new hotness since it will appear as a single
log entry. Syntactically, I kind of like the other way a bit more too, but
utility wins.