Default reporter swallows console.log

[TrySound]

test.js

import test from 'ava';

test('log test', t => {
    console.log('log1\nlog2');
});

terminal output

log1

  1 passed

Seems like the last string of logged text is swallowed.It complicate debuggin.

[sindresorhus]

I noticed this too. This is because of the animated reporting. Although, logging like that isn't very useful when you have more than one tests as the logging is synchronous while the test is not, so the logging could be outputted with a different test. I think a solution here is to handle the logging so that it's outputted with the correct test in verbose mode and with the default minimal reporter we could either show all logging at the end or during the testing by pushing the animated output down (meaning calling logUpdate.done()).

For now you can use the --verbose flag.

// @vdemedes

[jamestalmage]

I think a solution here is to handle the logging so that it's outputted with the correct test in verbose mode

That would be hard to do with console.log unless we either:

1. Force --serial when --verbose is used (I don't like this idea).
2. Use domains to determine which test console.log is used from.
3. Provide a t.log method.

I think 3 is pretty interesting. It won't help much with capturing logs from production code (unless you use proxyquire to inject it some how). For the verbose reporter, we could always print t.log statements. For the mini reporter, only output logs with failed tests

[sindresorhus]

Yes, 3 is what I was thinking.

For the mini reporter, only output logs with failed tests

I think we should still log it with the mini reporter as it's still useful to quickly print out some values.

[ariporad]

@sindresorhus, @jamestalmage: We could also try hijacking/monkey-patching wither process.stdout/stderr or console.log.

[sindresorhus]

Yes, we could, but I have a feeling that comes with a lot of edge-cases, so we should first figure out t.log.

[ecowden]

Humble lurker here, so feel free to tell me I'm wrong --

Usually, when I find myself dropping in log statements for debugging, it's in the code under test, not the test itself. If the data I'm trying to learn about is accessible from the test, I'd just write an assertion anyway. I doubt I'd use t.log very much.

I've found debugging particularly tricky when experimenting with AVA since it also seems to give debuggers like node-inspector a hard time. In an ideal world, I'd love to see the log output for failed tests alongside the failed assertion or error. Successful tests could hide logs unless handed --verbose. Of course, easier said than done, right?

[vadimdemedes]

I think we should just hide the output from the mini reporter. I've encountered many TAP/mocha reporters, that just don't show console.log()s and that's it. With our animated beauty, there is simply no good way to display console.log() output.

I doubt I'd use t.log very much.

Highly agree with @ecowden, I don't think anyone would use t.log.

[TrySound]

But how to debug?

[jamestalmage]

use --verbose

[vadimdemedes]

@jamestalmage++

[jamestalmage]

I don't think anyone would use t.log

Yeah, that was my concern as well. However, I think having a way to log output that you can be sure will be printed right underneath the ✅ of the related test is pretty valuable. Obviously --serial is a way to achieve that.

At some point I think we need to start developing a "best practices / hints and tips / faq" document with stuff like this in it (where we fail to find ideal / straightforward solutions to these types of problems). For example, a good heading for the discussion we are having here would be "Debugging async tests", that talks about the difficulty of debugging async tests (it's hard to reason about console.log statements unless you enable --serial).

[jamestalmage]

For the mini reporter, only output logs with failed tests

I think we should still log it with the mini reporter as it's still useful to quickly print out some values.

@sindresorhus - for quickly printing out some values, console.log works just as well, assuming you intend to delete the log statement later. The output of the mini reporter offers no context for log statements in passing tests anyways. There are advantages to not displaying in the mini reporter unless there is a failure:

1. The log statements can be given context (by being grouped with the failure output for that specific test).
2. You can leave the log statements in the test. As long as the test passes, it is not cluttering up your output. If/when the test fails - you are given additional information beyond the simple assertion failure.

[sindresorhus]

The output of the mini reporter offers no context for log statements in passing tests anyways.

Usually I just console log in one place so I don't really need a context, but ok with using --verbose when I do that.

[jamestalmage]

Usually I just console log in one place so I don't really need a context

In that case the mini reporter should be fine. Though maybe we should somehow use hook-std or something to detect a line has been written and avoid deleting it.

[sindresorhus]

Yup, already suggested something like that initially, using logUpdate.done(). Would be nice.

[Qix-]

Yes, we could, but I have a feeling that comes with a lot of edge-cases

Not really. Patching process.stdout, process.stderr and fs.write(1|2, ...) could do it completely. The only thing that this wouldn't cover is native modules writing to either of those, though that's hard to cover anyway.

For the first two, you could even .pipe() them to a logger stream that AVA would provide. Would be much cleaner than an override.

Definitely not against t.log() though, however that doesn't stand up if the code being tested (not the tests themselves) have any sort of console output.

Not sure what #415 does (haven't looked into it yet) but I figured I'd jump here and comment. Ava is a standalone application that has the special ability to be able to set up hooks in the environment to do what it does (it's a testing framework, after all). I'm surprised we don't hook more things (side effect testing and whatnot; t.assertFileWritten(filename), etc).