Result outputs go wrong with using async tasks in `{before,after}xxx` #jest

同期処理だけの正常パターン

beforeAll(() => {
  console.log('beforeAll');
});
beforeEach(() => {
  console.log('beforeEach');
});
afterEach(() => {
  console.log('afterEach');
});
afterAll(() => {
  console.log('afterAll');
});

describe('d1', () => {
  test('t11', () => { expect('ok'); });
});
describe('d2', () => {
  test('t21', () => { expect('ok'); });
  test('t22', () => { expect('ok'); });
});
describe('d3', () => {
  test('t31', () => { expect('ok'); });
});

これを普通に実行すると、ログは想定通りこうなる。

pass  __tests__/foo.test.js
 d1
   ✓ t11 (2ms)
 d2
   ✓ t21
   ✓ t22 (1ms)
 d3
   ✓ t31 (1ms)

 console.log __tests__/foo.test.js:4
   beforeAll

 console.log __tests__/foo.test.js:8
   beforeEach

 console.log __tests__/foo.test.js:13
   afterEach

 console.log __tests__/foo.test.js:8
   beforeEach

 console.log __tests__/foo.test.js:13
   afterEach

 console.log __tests__/foo.test.js:8
   beforeEach

 console.log __tests__/foo.test.js:13
   afterEach

 console.log __tests__/foo.test.js:8
   beforeEach

 console.log __tests__/foo.test.js:13
   afterEach

 console.log __tests__/foo.test.js:16
   afterAll

test suites: 1 passed, 1 total
tests:       4 passed, 4 total
snapshots:   0 total
time:        0.874s, estimated 1s

何の問題もない。

• テストのファイル別結果
• `console.log`
• テスト全体に関する情報

という感じで見やすい。

非同期処理を`{before,after}xxx`でやるパターン

ただし、非同期をまぜると途端に出力されるログがおかしくなる。

const sleep = msec => new promise(resolve => settimeout(resolve, msec));

// ここだけ変えてみる
beforeEach(done => {
  sleep(100).then(() => {
    console.log('beforeEach');
    done();
  });
});

各テストの直前で100ms待つように。

すると、

  console.log __tests__/foo.test.js:4
    beforeAll

  console.log __tests__/foo.test.js:8
    beforeEach

  console.log __tests__/foo.test.js:13
    afterEach

  console.log __tests__/foo.test.js:8
    beforeEach

  console.log __tests__/foo.test.js:13
    afterEach

  console.log __tests__/foo.test.js:8
    beforeEach

  console.log __tests__/foo.test.js:13
    afterEach

 pass  __tests__/foo.test.js
  d1
    ✓ t11 (107ms)
  d2
    ✓ t21 (102ms)
    ✓ t22 (106ms)
  d3
    ✓ t31 (102ms)

test suites: 1 passed, 1 total
tests:       4 passed, 4 total
snapshots:   0 total
time:        1.04s
  console.log __tests__/foo.test.js:8
    beforeEach

  console.log __tests__/foo.test.js:13
    afterEach

  console.log __tests__/foo.test.js:16
    afterAll

というようになる。
さっきとログの体裁が違う！なんで！

Promiseのところは`async / await`にしても同じ結果になる。

// こっちでも
beforeEach(async done => {
  await sleep(100);
  console.log('beforeEach');
  done();
});

// こっちでも一緒だった
beforeEach(async () => {
  await sleep(100);
  console.log('beforeEach');
});

ログが気持ち悪い。

forceExitをつけて実行する

Jest process doesn’t quit after last test completes · Issue #1456 · facebook/jest · GitHub

このissueにもあるように、処理が終わらないとjestの実行も終わらない場合がある。
そんな時に、強制終了したいよねって話で、`--forceExit`ってオプションがある。

さっきの非同期コードにこれを使うと・・、

console.log __tests__/foo.test.js:4
  beforeAll

console.log __tests__/foo.test.js:8
  beforeEach

console.log __tests__/foo.test.js:11
  afterEach

console.log __tests__/foo.test.js:8
  beforeEach

console.log __tests__/foo.test.js:11
  afterEach

console.log __tests__/foo.test.js:8
  beforeEach

console.log __tests__/foo.test.js:11
  afterEach

pass  __tests__/foo.test.js
d1
  ✓ t11 (108ms)
d2
  ✓ t21 (102ms)
  ✓ t22 (105ms)
d3
  ✓ t31 (101ms)

test suites: 1 passed, 1 total
tests:       4 passed, 4 total
snapshots:   0 total
time:        1.043s

と、`afterAll`が呼ばれてないのに終わる・・ように見える。
ただし実際は`afterAll`は動いてるっぽく、適当に`fs.writeFile`とかやるとわかる。
けど、ログには出ない。謎。

これはバグなのかなんなのか・・。