Ava: `t.log()` does not work in before/after hooks

Created on 25 Sep 2017 · 12Comments · Source: avajs/ava

Bug Description

Ava logging with t.log only work inside a test function, but not during setup (before, beforeEach) or teardown (after.*) functions.

This means that meaningful setup / teardown data, which is very useful for debugging and reproducing, is lost. This happens both for successful and failed tests, and with and without the --verbose flag.

Steps to reproduce

I've created a small git repo exemplifying the problem:

git clone [email protected]:adamatan/ava-logging-bug.git
cd ava-logging-bug
npm install
ava run.js --verbose

Test Source

import test from 'ava';

test.before((t) => {
  // This runs before all tests
  t.log('before - 1');
});

test.before((t) => {
  // This runs after the above, but before tests
  t.log('before - 2');
});

test.after('cleanup', (t) => {
  // This runs after all tests
  t.log('after');
});

test.after.always('guaranteed cleanup', (t) => {
  // This will always run, regardless of earlier failures
  t.log('after always');
});

test.beforeEach((t) => {
  // This runs before each test
  t.log('beforeEach');
});

test.afterEach((t) => {
  // This runs after each test
  t.log('afterEach');
});

test.afterEach.always((t) => {
  // This runs after each test and other test hooks, even if they failed
  t.log('afterEachAlways');
});

test('Passing test', (t) => {
  t.log('Log from the passing test');
  t.pass();
});


test('Failing test', (t) => {
  t.log('Log from the failing test');
  t.fail();
});

Error Message & Stack Trace

Only the log output from the test function appear:

  ✔ Passing test
    ℹ Log from the passing test
  ✖ Failing test Test failed via `t.fail()`
    ℹ Log from the failing test

  1 test failed [14:00:40]

  Failing test
    ℹ Log from the failing test

  /Users/adam/Personal/tmp/ava-bug-log-in-before-each/run.js:46

   45:     t.log('Log from the failing test');
   46:     t.fail();
   47: });

  Test failed via `t.fail()`

Command-Line Arguments

ava run.js --verbose

Relevant Links

Environment

Node.js v8.1.2
darwin 16.7.0
0.22.0 // ava
5.4.2 . // npm

dflupu earned $100.00 by resolving this issue!

Checkout the Issuehunt explorer to discover more funded issues.

Need some help from other developers? Add your repositories on Issuehunt to raise funds.

Rewarded on Issuehunt bug help wanted internals reporters

Source

adamatan

👍4

Most helpful comment

@sindresorhus Hello! Can I give it a go?

Lifeuser on 23 Oct 2017

🎉3

All 12 comments

// @nowells In case you would be interested in working on this. No worries if not though.

sindresorhus on 18 Oct 2017

@sindresorhus Hello! Can I give it a go?

Lifeuser on 23 Oct 2017

🎉3

Go for it @Lifeuser! 👍

novemberborn on 23 Oct 2017

I took a look at the code and this lines seems to be causing the problem.
We don't pass hooks execution object to reporter except an error has occurred.

https://github.com/avajs/ava/blob/1cb9d4f9e455c076313f53cb7ac5003246740b02/lib/main.js#L35-L38

How exactly do we want treat hooks in each reporter?

Mini-reporter

I guess user should only see logs from failed hooks in mini reporter (correct me please if I'm wrong).

So, there are two options:

we don't need to pass hooks to this reporter unless it's an error or failure
or
we need to fix the reporter to count right, 'cause it's counting hooks as passed tests

➜  ava-logging-bug git:(master) ✗ ava run.js

  9 passed
  1 failed

  Failing test
    ℹ Log from the failing test

  /Users/lifeuser/projects/ava-logging-bug/run.js:46

   45:   t.log('Log from the failing test');
   46:   t.fail();
   47: });

  Test failed via `t.fail()`

Tap and Verbose

Even in case of only two files it starts to look rather messy for me...
Maybe we should group them somehow?

➜  ava-logging-bug git:(master) ✗ ava . --verbose

  ✔ run › before
    ℹ before - 1
  ✔ run › before
    ℹ before - 2
  ✔ run › beforeEach for Passing test
    ℹ beforeEach
  ✔ run › Passing test
    ℹ Log from the passing test
  ✔ run › afterEach for Passing test
    ℹ afterEach
  ✔ run › afterEach for Passing test
    ℹ afterEachAlways
  ✔ run › beforeEach for Failing test
    ℹ beforeEach
  ✔ run2 › before
    ℹ before - 1
  ✔ run2 › before
    ℹ before - 2
  ✔ run2 › beforeEach for Passing test
    ℹ beforeEach
  ✔ run2 › Passing test
    ℹ Log from the passing test
  ✔ run2 › afterEach for Passing test
    ℹ afterEach
  ✔ run2 › afterEach for Passing test
    ℹ afterEachAlways
  ✔ run2 › beforeEach for Failing test
    ℹ beforeEach
...

It's only second day that I'm digging in project.
Maybe I am not on the right track with this all.
Need advice =)

Lifeuser on 24 Oct 2017

Ah yikes, this does look quite complicated @Lifeuser!

With the beforeEach and afterEach hooks, I think we need to output their logs together with the test itself. This hints at refactoring what counts as test completion, to be honest. See also https://github.com/avajs/ava/issues/1330.

The before and after hooks should probably just be printed. That's not hard to do but I don't know if we should land that without fixing this for the per-test hooks.

novemberborn on 24 Oct 2017

My use case is passing a logger that uses t.log to all my injected dependencies:

import test from 'ava'
import createLogger from '@private/logger'

import Foo from './foo'

// How it works now
test('does bar', t => {
  const foo = new Foo({log: createLogger({t})})
  const bar = foo.bar()
  t.true(bar)
})

// How I would like it to work
test.beforeEach(t => {
  t.context.foo = new Foo({log: createLogger({t})})
})
test('does bar', t => {
  const bar = t.context.foo.bar()
  t.true(bar)
})

// How I have to work around it
test.beforeEach(t => {
  t.context.foo = t => new Foo({log: createLogger({t})})
})
test('does bar', t => {
  const foo = t.context.foo(t)
  const bar = foo.bar()
  t.true(bar)
})