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