概要

ある日、ReduxからRedux Toolkitに変更した。
すると今まで通っていたテストが落ちるようになってしまった。
しかし、ブラウザ上では期待通り動いている。
一体これはなんなんでしょうか？🥺

内容

テスト内容
- jest.useFakeTimers()とjest.spyOnを使用して時間が5秒ごとに更新されているか
実装内容
- 5秒ごとにDate.now()を使って時刻を取得し表示している。
TestCode

it('5秒ごとに時間が更新されているかのテスト', async () => {
    jest.useFakeTimers()
    const date = new Date('2022-08-30T09:00:00.300').getTime()
    jest.spyOn(global.Date, 'now')
        .mockImplementationOnce(() => date)
        .mockImplementationOnce(() => date + 5000)
        .mockImplementation(() => date + 10000)

        await render('/')
        jest.advanceTimersByTime(５０００)
        expect(await screen.findByText('09:00:05')).toBeInTheDocument()
        //　　Fail
        // Unable to find an element with the text: 09:00:05. This could be because the text is broken up by multiple elements.
        // In this case, you can provide a function for your text matcher to make your matcher more flexible.



        jest.advanceTimersByTime(５０００)
        expect(screen.getByText('09:00:10')).toBeInTheDocument()

        })

かくしてこの謎の調査作戦を行うことにした。
作戦名は「ウォールマリア奪還作戦」と名付けた。

調査(ウォールマリア奪還作戦)

実装の方でDate.now()を呼んでいるところにconsole.log()で何回呼ばれているか
-> 期待通りの回数しか呼ばれていない
テストのjest.spyOn()を使用しているところにconsole.logを置いて何回呼ばれているか

    jest.spyOn(global.Date, 'now')
        .mockImplementation(() => {console.log('yay!'); return date})

-> なぜか34回ほど呼ばれていた。

  console.log
    yay!
      at Function.<anonymous> (src/tests/App.test.tsx:163:79)

  console.log
    yay!
      at Function.<anonymous> (src/tests/App.test.tsx:163:79)

  console.log
    yay!
      at Function.<anonymous> (src/tests/App.test.tsx:163:79)
                        　　　　　・
                        　　　　　・
                        　　　　　・
                        　　　　　・

期待値は３回なはずなのにどうして３４回も呼ばれているのかわからなくなったので一旦以下のサイトに逃げた。
https://black-300.com

・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・
・

色を見分ける才能はあるかもしれない。。。

そうこうしている時、ある人から助言をいただいた。
「「「console.trace()を使ってみるのじゃ」」」
言われた通り、調査を続けることにした。

そもそもconsole.trace()ってなにそれ美味しいの?状態だったので調べてみることにした。
簡単に言うと呼ばれた経緯を確認できるらしい。
下記サイト参考
https://qiita.com/mooriii/items/afad70b19f8150f4f1b1#consoletrace

`console.trace()を入れて呼ばれた経緯を確認

    jest.spyOn(global.Date, 'now')
        .mockImplementation(() => {console.trace('yay!'); return date})

-> すると実装で呼び出しているものフローに以下の場所でこのようなログが出た。

  console.error
    Trace: yay!
        at Function.<anonymous> (/Users/src/tests/App.test.tsx:163:79)
        at /Users/node_modules/jest-mock/build/index.js:449:39
        at Function.<anonymous> (/Users/node_modules/jest-mock/build/index.js:457:13)
        at Function.mockConstructor [as now] (/Users/node_modules/jest-mock/build/index.js:170:19)
        at Object.measureTime (/Users/node_modules/@reduxjs/toolkit/src/utils.ts:8:28)
        at dispatch (/Users/node_modules/@reduxjs/toolkit/src/immutableStateInvariantMiddleware.ts:238:20)
        at /Users/src/App.tsx:37:17
        at processTicksAndRejections (node:internal/process/task_queues:96:5)

at Object.measureTime (/Users/node_modules/@reduxjs/toolkit/src/utils.ts:8:28)
この行を辿ると実装の他に別の場所でDate.nowを使っている部分を発見した
どうやらこのせいでDate.nowが余計に呼ばれていたそうだ。

export function getTimeMeasureUtils(maxDelay: number, fnName: string) {
  let elapsed = 0
  return {
    measureTime<T>(fn: () => T): T {
      const started = Date.now()
      try {
        return fn()
      } finally {
        const finished = Date.now()
        elapsed += finished - started
      }
    },
    warnIfExceeded() {
      if (elapsed > maxDelay) {
        console.warn(`${fnName} took ${elapsed}ms, which is more than the warning threshold of ${maxDelay}ms. 
If your state or actions are very large, you may want to disable the middleware as it might cause too much of a slowdown in development mode. See https://redux-toolkit.js.org/api/getDefaultMiddleware for instructions.
It is disabled in production builds, so you don't need to worry about that.`)
      }
    },
  }
}

最終的に以下のようにTestCodeを変更した

it('5秒ごとに時間が更新されているかのテスト', async () => {
    jest.useFakeTimers()
    const date = new Date('2022-08-30T09:00:00.300').getTime()
    jest.spyOn(global.Date, 'now')
        .mockImplementation(() => date)

        await render('/')
        jest.spyOn(global.Date, 'now').mockImplementation(() => date + 5000)
        jest.advanceTimersByTime(５０００)
        expect(await screen.findByText('09:00:05')).toBeInTheDocument()
        //Pass
        jest.spyOn(global.Date, 'now').mockImplementation(() => date + 10000)
        jest.advanceTimersByTime(５０００)
        expect(screen.getByText('09:00:10')).toBeInTheDocument()
        //Pass
        })

これで無事にRedux Tool-kitでもテストが通るようになったので、
ウォールマリア奪還作戦は終了する。

成果

Redux Tool-kitの場合
jest.spyOn(global.Date, 'now').mockImplementationOnce(() => date)(Onceなど回数で判断しているテスト)
を使うときは注意する。
console.trace()でどういう経路で呼ばれているか確認できる