Improve barback/pub logging.

Improve barback/pub logging.

Barback now lets you provide a logger, and pub gives it one that
pipes through pub's logging infrastructure. I'll need this to
get pub build using barback and easily testable with well-defined
console output.

BUG=https://code.google.com/p/dart/issues/detail?id=13880
R=alanknight@google.com

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

[Bob Nystrom, 2013-10-09 23:57:24]

I'm getting pub build hooked up to barback, but that's rubbing against barback's
primitive logging. Since the pub build tests care specifically about console
output, I wanted pub to be able to control that.

This also makes a lot of other stuff nicer. For example, you don't get pointless
stack traces on dart2js compile errors.

I know this patch is a little rough, but time is very critical here, so I'm
trying to get something in quickly with a bunch of TODOs that we can resolve
after 1.0.

Alan, I added you in case Nathan isn't able to find the time for this while he's
in NYC. Thank you!

[Alan Knight, 2013-10-10 22:34:34]

lgtm

[Bob Nystrom, 2013-10-10 23:17:10]

Committed patchset #2 manually as r28486 (presubmit successful).

[nweiz, 2013-10-16 19:41:26]

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/asset_...
File pkg/barback/lib/src/asset_cascade.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/asset_...
pkg/barback/lib/src/asset_cascade.dart:88: /// A stream that emits an event
whenever any transforms in this cascade log
"log" -> "logs"

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback.dart:67: Barback(PackageProvider provider,
{BarbackLogger logger})
I'm not a big fan of using injection here. What do you think of providing a log
stream (maybe replacing the [errors] stream), and having it log to stdout if
there are no listeners?

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:16: void logEntry(LogEntry entry) {
I'd rather just call this "log". "logEntry" reads as a noun to me, which is
weird for a method name.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:20: var message = entry.message;
Unused variable.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:21: if (entry.span == null) {
!=

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:32: class LogLevel {
Do we want to have a FINE level as well?

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:49: final AssetId asset;
I'd call this "assetId", since Asset is a different public class.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/group_...
File pkg/barback/lib/src/group_runner.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/group_...
pkg/barback/lib/src/group_runner.dart:35: /// A stream that emits an event
whenever any transforms in this group log an
"log" -> "logs"

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/packag...
File pkg/barback/lib/src/package_graph.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/packag...
pkg/barback/lib/src/package_graph.dart:28: /// The logger used to report
transformer log entries. If this is null, then
paragraph break

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/packag...
pkg/barback/lib/src/package_graph.dart:29: /// [_defaultLogger] will be used
instead.
_defaultLogger isn't defined anywhere

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase....
File pkg/barback/lib/src/phase.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase....
pkg/barback/lib/src/phase.dart:96: /// A stream that emits an event whenever any
transforms in this phase log an
"log" -> "logs"

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase_...
File pkg/barback/lib/src/phase_input.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase_...
pkg/barback/lib/src/phase_input.dart:83: /// their primary input log an entry.
"log" -> "logs"

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
File pkg/barback/lib/src/transform_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
pkg/barback/lib/src/transform_logger.dart:22: /// If [asset] is provided, the
log entry is associated with that asset,
", otherwise" -> ". Otherwise"

also below

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
File pkg/barback/lib/src/transform_node.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
pkg/barback/lib/src/transform_node.dart:212: var info = new
TransformInfo(transformer, primary.id);
There's already an info getter that does this.

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
File sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart:23: // Show the
level (unless the message mentions it.)
".)" -> ")."

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart:43: var prefix =
"[${prefixParts.join(' ')}]:";
Minor formatting thing, but it seems weird to have a colon after this prefix.

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart:51:
log.error("${log.red(prefix)}\n$message");
Use prefixLines to make it clear that the message belongs to the given log
entry.

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
File sdk/lib/_internal/pub/lib/src/dart.dart (left):

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/dart.dart:63: throw new
ApplicationException('Failed to compile "$entrypoint".');
I really don't like getting rid of this. It makes this much less intuitive as a
library function, and it would be perfectly reasonable to just catch this error
in the dart2js transformer.

[Bob Nystrom, 2013-10-28 23:45:55]

Thanks! Revised here: https://codereview.chromium.org/48993007

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/asset_...
File pkg/barback/lib/src/asset_cascade.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/asset_...
pkg/barback/lib/src/asset_cascade.dart:88: /// A stream that emits an event
whenever any transforms in this cascade log
On 2013/10/16 19:41:27, nweiz wrote:
> "log" -> "logs"

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback.dart:67: Barback(PackageProvider provider,
{BarbackLogger logger})
On 2013/10/16 19:41:27, nweiz wrote:
> I'm not a big fan of using injection here. What do you think of providing a
log
> stream (maybe replacing the [errors] stream), and having it log to stdout if
> there are no listeners?

I thought about that (and it is using streams internally), but I'm not a fan of
there being different behavior based on whether or not a stream has listeners.
I'm up for discussing this though, I could be convinced.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:16: void logEntry(LogEntry entry) {
On 2013/10/16 19:41:27, nweiz wrote:
> I'd rather just call this "log". "logEntry" reads as a noun to me, which is
> weird for a method name.

In pub, we import log.dart with a "log" prefix, so implementing this class in
pub is nasty if the method is called "log" too. :-/

My intent is for the method to read like "log entry" where "log" is the verb.
It's not ideal.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:20: var message = entry.message;
On 2013/10/16 19:41:27, nweiz wrote:
> Unused variable.

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:21: if (entry.span == null) {
On 2013/10/16 19:41:27, nweiz wrote:
> !=

Eek. Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:32: class LogLevel {
On 2013/10/16 19:41:27, nweiz wrote:
> Do we want to have a FINE level as well?

Sure, I just added the ones I needed for dart2js, but we can expand this over
time.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:49: final AssetId asset;
On 2013/10/16 19:41:27, nweiz wrote:
> I'd call this "assetId", since Asset is a different public class.

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/group_...
File pkg/barback/lib/src/group_runner.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/group_...
pkg/barback/lib/src/group_runner.dart:35: /// A stream that emits an event
whenever any transforms in this group log an
On 2013/10/16 19:41:27, nweiz wrote:
> "log" -> "logs"

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/packag...
File pkg/barback/lib/src/package_graph.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/packag...
pkg/barback/lib/src/package_graph.dart:28: /// The logger used to report
transformer log entries. If this is null, then
On 2013/10/16 19:41:27, nweiz wrote:
> paragraph break

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/packag...
pkg/barback/lib/src/package_graph.dart:29: /// [_defaultLogger] will be used
instead.
On 2013/10/16 19:41:27, nweiz wrote:
> _defaultLogger isn't defined anywhere

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase....
File pkg/barback/lib/src/phase.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase....
pkg/barback/lib/src/phase.dart:96: /// A stream that emits an event whenever any
transforms in this phase log an
On 2013/10/16 19:41:27, nweiz wrote:
> "log" -> "logs"

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase_...
File pkg/barback/lib/src/phase_input.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/phase_...
pkg/barback/lib/src/phase_input.dart:83: /// their primary input log an entry.
On 2013/10/16 19:41:27, nweiz wrote:
> "log" -> "logs"

This one's actually correct. :)

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
File pkg/barback/lib/src/transform_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
pkg/barback/lib/src/transform_logger.dart:22: /// If [asset] is provided, the
log entry is associated with that asset,
On 2013/10/16 19:41:27, nweiz wrote:
> ", otherwise" -> ". Otherwise"
> 
> also below

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
File pkg/barback/lib/src/transform_node.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/transf...
pkg/barback/lib/src/transform_node.dart:212: var info = new
TransformInfo(transformer, primary.id);
On 2013/10/16 19:41:27, nweiz wrote:
> There's already an info getter that does this.

Done.

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
File sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart:23: // Show the
level (unless the message mentions it.)
On 2013/10/16 19:41:27, nweiz wrote:
> ".)" -> ")."

Done.

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart:43: var prefix =
"[${prefixParts.join(' ')}]:";
On 2013/10/16 19:41:27, nweiz wrote:
> Minor formatting thing, but it seems weird to have a colon after this prefix.

I think it helps make it clearer that the prefix is associated with the
following line and not the previous:

...
[SomeTransformer path/to/asset.txt]
This is an error message.
[SomeTransformer path/to/asset.txt]
This is an error message.
[SomeTransformer path/to/foo.txt]
This is an error message. <-- wait, is this for foo or bar?
[SomeTransformer path/to/bar.txt]
This is an error message.
[SomeTransformer path/to/asset.txt]
...

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart:51:
log.error("${log.red(prefix)}\n$message");
On 2013/10/16 19:41:27, nweiz wrote:
> Use prefixLines to make it clear that the message belongs to the given log
> entry.

See above. In my manual testing, I thought this form looked pretty nice. The
prefix is too long to put any part of the message on the same line as it. Given
that, it seemed like a waste of space to prefix every line.

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
File sdk/lib/_internal/pub/lib/src/dart.dart (left):

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/dart.dart:63: throw new
ApplicationException('Failed to compile "$entrypoint".');
On 2013/10/16 19:41:27, nweiz wrote:
> I really don't like getting rid of this. It makes this much less intuitive as
a
> library function, and it would be perfectly reasonable to just catch this
error
> in the dart2js transformer.

Done.

[nweiz, 2013-10-29 00:40:13]

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback.dart:67: Barback(PackageProvider provider,
{BarbackLogger logger})
On 2013/10/28 23:45:56, Bob Nystrom wrote:
> On 2013/10/16 19:41:27, nweiz wrote:
> > I'm not a big fan of using injection here. What do you think of providing a
> log
> > stream (maybe replacing the [errors] stream), and having it log to stdout if
> > there are no listeners?
> 
> I thought about that (and it is using streams internally), but I'm not a fan
of
> there being different behavior based on whether or not a stream has listeners.
> I'm up for discussing this though, I could be convinced.

There's some precedent for this in that buffered streams will only top-level
exceptions if they have a listener. I don't think triggering based on a listener
is something we want to do all the time, but I think this is a case where it
makes sense, especially since the behavioral change when a listener added isn't
something that affects the actual code -- just what the end user sees.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:16: void logEntry(LogEntry entry) {
On 2013/10/28 23:45:56, Bob Nystrom wrote:
> On 2013/10/16 19:41:27, nweiz wrote:
> > I'd rather just call this "log". "logEntry" reads as a noun to me, which is
> > weird for a method name.
> 
> In pub, we import log.dart with a "log" prefix, so implementing this class in
> pub is nasty if the method is called "log" too. :-/
> 
> My intent is for the method to read like "log entry" where "log" is the verb.
> It's not ideal.

Does it actually cause a conflict to define a method with the same name as a
prefix that's in scope? That seems like it should be fine.

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
File sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/sdk/lib/_internal/pub/lib/...
sdk/lib/_internal/pub/lib/src/barback/pub_barback_logger.dart:51:
log.error("${log.red(prefix)}\n$message");
On 2013/10/28 23:45:56, Bob Nystrom wrote:
> On 2013/10/16 19:41:27, nweiz wrote:
> > Use prefixLines to make it clear that the message belongs to the given log
> > entry.
> 
> See above. In my manual testing, I thought this form looked pretty nice. The
> prefix is too long to put any part of the message on the same line as it.
Given
> that, it seemed like a waste of space to prefix every line.

I just meant prefixing it with a couple of spaces, not the entire location
string. So it ends up looking like

[WARNING in transformer on file]
  text of warning
  more text

[Bob Nystrom, 2013-10-29 18:29:44]

Revised over in other patch.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback.dart:67: Barback(PackageProvider provider,
{BarbackLogger logger})
On 2013/10/29 00:40:13, nweiz wrote:
> On 2013/10/28 23:45:56, Bob Nystrom wrote:
> > On 2013/10/16 19:41:27, nweiz wrote:
> > > I'm not a big fan of using injection here. What do you think of providing
a
> > log
> > > stream (maybe replacing the [errors] stream), and having it log to stdout
if
> > > there are no listeners?
> > 
> > I thought about that (and it is using streams internally), but I'm not a fan
> of
> > there being different behavior based on whether or not a stream has
listeners.
> > I'm up for discussing this though, I could be convinced.
> 
> There's some precedent for this in that buffered streams will only top-level
> exceptions if they have a listener. I don't think triggering based on a
listener
> is something we want to do all the time, but I think this is a case where it
> makes sense, especially since the behavioral change when a listener added
isn't
> something that affects the actual code -- just what the end user sees.

Done.

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
File pkg/barback/lib/src/barback_logger.dart (right):

https://codereview.chromium.org/26572010/diff/4001/pkg/barback/lib/src/barbac...
pkg/barback/lib/src/barback_logger.dart:16: void logEntry(LogEntry entry) {
On 2013/10/29 00:40:13, nweiz wrote:
> On 2013/10/28 23:45:56, Bob Nystrom wrote:
> > On 2013/10/16 19:41:27, nweiz wrote:
> > > I'd rather just call this "log". "logEntry" reads as a noun to me, which
is
> > > weird for a method name.
> > 
> > In pub, we import log.dart with a "log" prefix, so implementing this class
in
> > pub is nasty if the method is called "log" too. :-/
> > 
> > My intent is for the method to read like "log entry" where "log" is the
verb.
> > It's not ideal.
> 
> Does it actually cause a conflict to define a method with the same name as a
> prefix that's in scope? That seems like it should be fine.

It doesn't conflict, it wins. So you have to do "this.log" to get to the method.

Removed this class, though, so done.