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

[adamatan]

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

• Original SO question for reference.
• Minimal reproduction github example.

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.

[sindresorhus]

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

[Lifeuser]

@sindresorhus Hello! Can I give it a go?

[novemberborn]

Go for it @Lifeuser! 👍

[Lifeuser]

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.

ava/lib/main.js

Lines 35 to 38 in 1cb9d4f

	// Don't display anything if it's a passed hook
	if (!hasError && props.type !== 'test') {
	return;
	}

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

[novemberborn]

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

[razor-x]

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

[dlumma]

+1 to prioritizing this request

[Lifeuser]

Hi @novemberborn ! Can you remove assigned label please, 'cause I'm not actually working on this issue anymore.

[novemberborn]

@Lifeuser thanks for the heads up 👍

[IssueHuntBot]

@issuehuntfest has funded $100.00 to this issue. See it on IssueHunt

[IssueHuntBot]

@dflupu has submitted a pull request. See it on IssueHunt

[IssueHuntBot]

@sindresorhus has rewarded $90.00 to @dflupu. See it on IssueHunt

• 💰 Total deposit: $100.00
• 🎉 Repository reward(0%): $0.00
• 🔧 Service fee(10%): $10.00