Ava: Group log output with the relevant test.

[jamestalmage]

Continuation from here.

1. Use domains to determine which test console.log is used from.
2. Provide a t.log method.

2 is a less controversial choice, but won't help for logging from production code.

One possibility for such grouping would be to only display the logs when the test failed. I think this is an especially a good idea for t.log, as it lets you leave them in your tests without consequence if you think they will help troubleshoot future failures.

[vadimdemedes]

only display the logs when the test failed

I'm strongly against this one as it's very irritating when obvious & simple things (like console.log()) don't work as expected.

Domains looks like a good solution for our issues. We could also group exceptions & rejections, not just console.log()s. It was mentioned before in some issue too.

The problem with domains is this:

But if a replacement will be provided, that shouldn't be an issue to just migrate to a new API.

[vadimdemedes]

Am I crazy or we could use cluster module for that? It allows to listen to error events when worker (test) fails. Also we could attach to message events and:

console.log = function () {
  process.send(...);
};

[sindresorhus]

I'm strongly against this one as it's very irritating when obvious & simple things (like console.log()) don't work as expected.

:+1: I also want them visible by default.

Provide a t.log method.

Do we really need this if we manage to route console calls correctly?

The problem with domains is this:

Domains are deprecated, but so much depend on it that they're not going to remove it anytime soon (source: Node.js core people). They don't even have an alternative yet. And the alternative is going to be powerful enough to enable building a user-land implementation of domains. More here: https://github.com/sindresorhus/ava/issues/214#issuecomment-157402230.

[jamestalmage]

only display the logs when the test failed

I'm strongly against this one as it's very irritating when obvious & simple things (like console.log()) don't work as expected.

You are probably right. I was more thinking this for t.log. My only irritation is that if I put console.log in a production file that is called by a lot of tests, I probably only want to see the output of the failing ones. Still - probably best not to.

[vadimdemedes]

they're not going to remove domains anytime soon

In that case, let's move on with domains on board.

[sindresorhus]

Am I crazy or we could use cluster module for that?

I'm not really familiar with the cluster module.

[jamestalmage]

Do we really need this (t.log) if we manage to route console calls correctly?

My thought was that it would be similar to console.log, but hidden unless the test fails.

cluster

That only gives you per-process resolution. We need domains to narrow it down per-test

[vadimdemedes]

@jamestalmage I actually thought about running a worker per test. I just realized it's completely insane.

[vadimdemedes]

Mind wonders when you're desperate :D

[jamestalmage]

I actually thought about running a worker per test.

It's crossed my mind, and I definitely don't think it's insane, but probably not very performant.

[sindresorhus]

I actually thought about running a worker per test.

I considered that a year ago, but decided not to open an issue about it as it would come with a lot of overhead. Might be something worth exploring at some point as totally isolated tests would be so nice.

[sindresorhus]

You are probably right. I was more thinking this for t.log.

That's kinda what the message arguments in assertions are meant for, but I guess it could be useful for generic debug stuff when it fails. Not sure .log is the best name for something like that, though. Maybe t.debug(), which is shown when a test fail or in debug mode?

[jamestalmage]

I actually thought about running a worker per test.

Could be cool as a configurable option. Turn it off for faster testing on the local dev machine. On for your CI build so you ensure you are writing truly isolated tests.

See https://github.com/jamestalmage/forking-tap

[jamestalmage]

One downside to this is that it hides the async nature of your code from you. Take the following:

var l;
var r;

function addLater(testName, a, b) {
  console.log('saving values ' + testName);
  l = a;
  r = b;
  Promise.resolve().then(function() {
    console.log('adding values ' + testName);
    return l + r;
  });
}

test(async t => t.is(await addLater('test 1', 3, 4), 7));
test(async t => t.is(await addLater('test 2', 5, 6), 11));

With this proposal, the above will give you a nice, seemingly synchronous log:

saving values test 1
adding values test 1
saving values test 2
adding values test 2

When what will almost certainly be happening is:

saving values test 1
saving values test 2
adding values test 1
adding values test 2

[sindresorhus]

Could be cool as a configurable option. Turn it off for faster testing on the local dev machine. On for your CI build so you ensure you are writing truly isolated tests.

Yeah, can you open an issue? I don't think we should prioritize it right now, but can have an issue to at least discuss and so we don't forget.

[sindresorhus]

Paste your above comment into that issue so not to derail this discussion ;)

[jamestalmage]

My big comment above is directly related to this one.

[sindresorhus]

With this proposal, the above will give you a nice, seemingly synchronous log:

I don't really see that as much of a problem.

[novemberborn]

Is this something we need to solve, or a pitfall that should be documented? (See #404).

Presumably invoking with --serial and using console.error() gives you synchronous output. Alternatively you can use t.only(). Normaly console should only be used for debugging anyway.

[jamestalmage]

It's just so very surprising to people, I think it's worth trying someday.

It definitely could get the low-priority label though

[vadimdemedes]

Actually, I don't think it's surprising, considering that we promote parallelism & concurrency all over the place.

However, as a solution to this issue, I see implementing t.log() method, but instead of forcing developers to use it, add a babel plugin that transforms console.log() inside test() to t.log(). Bam, simple and it works.

What do you think?

[jamestalmage]

You frequently use console.log outside your test code (where you wouldn't have access to t).

[0x1mason]

I've implemented a simple solution to this problem, similar to Tape's test::comment. Here's the basic pattern using a wrapper:

function testWrapper (title, fnc) {
      return ava (title, function (avaTest) {
         let _logs = [];

         // This is a quick and dirty monkey patch to ensure logs print together after
         // the test has completed. The downside is logs are not printed in real time.
         avaTest.comment = function () {
            let msg = "      # " + util.format.apply(null, arguments);
            _logs.push(msg);
         }

         let test = avaTest._test;
         test._exit = test.exit.bind(test);
         test.exit = function () {
            return Promise.resolve(test._exit())
               .then(res => {
                  if (_logs.length > 0) {
                     process.stdout.write(_logs.join("\n")+"\n");
                  }
                  return res;
               });
         }
         return fnc(avaTest);
      }
}

Output:

  ✔ test_foo › Lorem ipsum dolor sit amet (15.5s)
        # Sed ut perspiciatis unde omnis iste natus error
        # Nemo enim ipsam voluptatem quia
  ✔ test_bar › Ut enim ad minim veniam (31.4s)
  ✔ test_baz › Quis autem vel eum iure reprehenderit (36.7s)
        # Neque porro quisquam est
        # At vero eos et accusamus et iusto odio dignissimos

It needs full integration into the Ava code (e.g., lose the wrapper, add to lib/test.js, etc), but I'd be willing to submit this as a proper PR.

[novemberborn]

@0x1mason what's your experience using this t.comment() interface, versus relying on console.log()?

Supporting console methods would have the least developer friction, but is a lot trickier given asynchronous test methods. Reading the thread here it sounds like we were hoping for a solution that would work with console methods, but that hasn't happened in 11 months so having a t.log() / t.comment() solution would be great to have now. (We can bikeshed the naming later.)

[0x1mason]

Nobody on my team has complained about having to use t.comment instead of console.log, but it's a pretty tiny sample of Ava users. :) We use it everyday as part our CI and have never had any issues.

I still use console.log sometimes when debugging, but I use it with test.only so asynchrony isn't an issue.

It also just occurred to me that for people already using console.log, transpilation/domain magic would change behavior in existing test setups, which might not be desireable in all cases.

[0x1mason]

As far as console.log vs t.comment, I think console.log is unusable for concurrent tests, esp if there are a number of logs. Some of our team use the logging as a sanity check -- you know test passed, but do you know the test passed? ;) They like lots of logs, giving a similar effect to the way Tape prints each assertion. Fine by me.

Incidentally the code above is essentially the same pattern I used to implement request local logging in an express js server, the difference being the additional use of domains.

[novemberborn]

Nobody on my team has complained about having to use t.comment instead of console.log, but it's a pretty tiny sample of Ava users. :)

Sure, but you've already been experimenting with it so that's useful input.

@avajs/core any thoughts? I'd be happy to see t.comment() land, as proposed by @0x1mason.

[vadimdemedes]

How about t.log() instead? Shorter and simpler.

[0x1mason]

log works for me.

On Dec 4, 2016 10:33 AM, "Vadim Demedes" [e-mail] wrote:

How about t.log() instead? Shorter and simpler.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/avajs/ava/issues/420#issuecomment-264710570, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AEX_-1w-3WpCNjJewPEGGRia-137fv7iks5rEt1egaJpZM4HEVoZ
.

[novemberborn]

Cool. All yours @0x1mason!