目次
CI のモバイルのテストは、30 分のタイムアウトまで終わらなかった。手元で同じ jest を叩くと、1483 件がちゃんと緑で終わる。違いは CPU のコア数だけだった。
この記事は、React Native(Expo)と TanStack Query のアプリで起きた「CI でだけ jest が終わらない」問題の調査記録だ。原因は次の 2 つの組み合わせだった。
- CI ランナーが 2 コアなので、jest がワーカーを使わず本体プロセスでテストを走らせていた
- TanStack Query が、pending のままの Mutation の削除タイマーを 5 分ごとに張り直し続けていた
こんな人向け
- React Native と TanStack Query のアプリで、CI の jest が
Jest did not exitやタイムアウトで止まるのに、手元では再現しない --detectOpenHandlesを付けても何も出ず、--forceExitで黙らせようか迷っている- GitHub Actions のランナーと多コアの開発機で、テストの結果が食い違ったことがある
環境
| 項目 | バージョン |
|---|---|
| jest | 29.7.0 |
| jest-expo | 54.0.17 |
| React Native | 0.81 系 |
| @tanstack/query-core | 5.99.0 |
| CI | GitHub Actions ubuntu-latest(2 コア) |
| 手元 | 10 コアの Mac |
1. 症状:CI でだけ終わらない
テストは 241 ファイル・1483 件。手元では数十秒で全部緑になる。CI では lint・test・build をまとめたジョブが 30 分のタイムアウトに達し、mobile の jest の途中でキャンセルされていた。
実はこの CI は、しばらく赤のまま放置されていた。別の静的検査で先に落ちていたので、jest まで処理が進んでいなかったのだ。その検査を直したら、今度は jest が終わらなくなった。
まず「遅いだけなのか、止まっているのか」を切り分けるため、mobile の jest だけを単独のステップに切り出して CI で回した。
.github/workflows/ci.yml
# 調査用の一時ステップ。原因が分かったら消す
- name: "[diag] mobile jest"
timeout-minutes: 12
continue-on-error: true
working-directory: apps/mobile
run: |
nproc
free -m
npx jest --listTests | wc -l
npx jest --ci --verbose=false 2>&1
nproc は 2 だった。テストは全部パスしているのに、最後の結果が出たあと jest プロセスが終わらない。遅いのではなく、止まっていた。
2. 2 コアで何が変わるのか
jest のワーカー数の既定は「コア数 − 1」だ。
jest-config/build/getMaxWorkers.js
Math.max(
isWatchModeEnabled ? Math.floor(numCpus / 2) : numCpus - 1,
1,
)
2 コアなら 1 になる。そしてワーカーが 1 つ以下だと、jest はワーカーを立てずに本体プロセスで直接テストを走らせる。これを in-band 実行という。
@jest/core/build/testSchedulerHelper.js
if (runInBand || detectOpenHandles) {
return true;
}
// ...
const oneWorkerOrLess = maxWorkers <= 1;
const oneTestOrLess = tests.length <= 1;
return (
!workerIdleMemoryLimit &&
(oneWorkerOrLess ||
oneTestOrLess ||
(tests.length <= 20 && timings.length > 0 && areFastTests))
);
この違いが、タイマーが残ったときの挙動を分ける。
| 実行方式 | タイマーが 1 つ残ったとき |
|---|---|
| in-band(CI の 2 コア) | 本体プロセスのイベントループが空にならず、プロセスが終わらない |
| ワーカー(手元の 10 コア) | 警告を 1 行出してワーカーごと強制終了し、exit 0 で終わる |
手元で出ていたのは、この警告だけだった。
A worker process has failed to exit gracefully and has been force exited.
This is likely caused by tests leaking due to improper teardown.
Try running with --detectOpenHandles to find leaks.
Active timers can also cause this, ensure that .unref() was called on them.
つまり手元の緑は、ワーカーの強制終了が問題を隠した結果だった。手元で CI と同じ状況を作るには、-i(--runInBand)を付ければいい。
CI=true npx jest --ci -i
これで手元でも止まるようになった。
3. --detectOpenHandles は黙っている
残ったタイマーを探すなら、まず --detectOpenHandles だ。これを付けると in-band 実行が強制される(上のコードの最初の条件)。
ところが今回は、止まっているのに何も報告されなかった。報告されたのはタイマーのごく一部で、犯人は出てこなかった。
そこで、setTimeout を横取りして「どこで作られ、まだ消えていないタイマー」を記録する仕込みを入れた。NODE_OPTIONS=--require で jest より先に読み込ませる。考え方は次のとおりだ。
trace-timers.js
// 生きているタイマーと、それを作った場所のスタックを記録する
const live = new Map();
const origSetTimeout = global.setTimeout;
const origClearTimeout = global.clearTimeout;
global.setTimeout = function (cb, ms, ...args) {
const stack = new Error().stack;
const t = origSetTimeout(function () {
live.delete(t);
return cb.apply(this, arguments);
}, ms, ...args);
live.set(t, { ms, stack });
return t;
};
global.clearTimeout = function (t) {
live.delete(t);
return origClearTimeout(t);
};
// 定期的に件数と、作成場所ごとの内訳を出す
const report = origSetTimeout(function tick() {
const byStack = new Map();
for (const { stack } of live.values()) {
const key = stack.split("\n").slice(2, 6).join("\n");
byStack.set(key, (byStack.get(key) ?? 0) + 1);
}
process.stderr.write(`[timers] live=${live.size}\n`);
for (const [k, n] of [...byStack].sort((a, b) => b[1] - a[1]).slice(0, 3)) {
process.stderr.write(` x${n}\n${k}\n`);
}
origSetTimeout(tick, 10_000).unref();
}, 10_000);
report.unref();
NODE_OPTIONS="--require ./trace-timers.js" CI=true npx jest --ci -i
最初に入れたときは、こうなって jest が起動すらしなかった。
Tests: 0 total
Time: 2.945 s, estimated 46 s
仕込みを調整して入れ直し、ようやく記録が取れた。
全テストが終わった時点で、生きているタイマーは 252 個あった。それが約 5 分かけて 65 個、1 個と減っていく。ほとんどのスタックが指していたのは、TanStack Query の内部だった。
4. 犯人:pending のままの Mutation が gc を永久に張り直す
5 分のタイマーが 250 個
TanStack Query は、使われなくなった Query や Mutation を gcTime(既定 5 分)たってからキャッシュから消す。そのために 5 分の setTimeout を張る。
テストでは、ファイルごと・テストごとに QueryClient を作るのが普通だ。今回のテストでも 64 ファイルがそれぞれ自前の QueryClient を作っていた。テストが終わっても、そこで張られた 5 分のタイマーは残る。これが 252 個の正体で、5 分たつと順に発火して消えていった。
ここまでなら「5 分待てば終わる」だけだ。最後の 1 個がいつまでも消えなかった。
pending の Mutation は消えない
最後の 1 個は、Mutation の gc タイマーだった。mutation.ts を見ると、こうなっている。
@tanstack/query-core/src/mutation.ts
protected optionalRemove() {
if (!this.#observers.length) {
if (this.state.status === 'pending') {
this.scheduleGc() // pending なら 5 分後にもう一度予約する
} else {
this.#mutationCache.remove(this)
}
}
}
pending の Mutation は削除されず、5 分後の削除予約をし直す。5 分後にまだ pending なら、また予約する。終わらない。
そして、該当するテストがあった。楽観的更新の「リクエスト完了前のキャッシュ」を検証するために、絶対に resolve しない Promise を返していた。
usePreferences.test.ts(修正前)
// リクエスト完了前の状態を検証したい
mockPatch.mockReturnValue(new Promise(() => {}));
const { result } = renderHook(() => useUpdatePreferences(), { wrapper });
act(() => result.current.update({ enabled: true }));
await waitFor(() => {
const cache = queryClient.getQueryData(PREFERENCES_QUERY_KEY);
expect(cache?.enabled).toBe(true);
});
この Mutation は永久に pending のままになる。つまり 5 分ごとに永久にタイマーを張り直す。queryClient.clear() を呼んでも、このタイマーは止まらなかった。
なぜ React Native(と jsdom)だけで起きるのか
gcTime の既定値は、実行環境で変わる。
@tanstack/query-core/src/removable.ts
newGcTime ?? (environmentManager.isServer() ? Infinity : 5 * 60 * 1000)
@tanstack/query-core/src/utils.ts
export const isServer = typeof window === 'undefined' || 'Deno' in globalThis
window が無い環境はサーバー扱いになり、gcTime は Infinity になる。Infinity なら gc のタイマー自体が張られない。素の Node 環境で TanStack Query をテストしても、この問題は起きない。
ところが React Native の jest プリセットは、jest/setup.js で window を global として定義している。jest の環境は Node なのに、TanStack Query からはブラウザに見える。だから 5 分のタイマーが張られる。jsdom 環境でも同じだ。
最小構成で確かめる
pending のまま残る Mutation を 1 件持つテストファイルに、ダミーのテストファイル 25 個を足して計 26 ファイルにし、window = global の条件で回した。
| 条件 | 結果 |
|---|---|
-i、または --maxWorkers=1 | 終わらない(20 秒で強制終了) |
-w 2 | 「force exited」の警告だけ出て exit 0 |
-i --detectOpenHandles | 何も報告せずに止まる |
window 未定義(純粋な Node 環境) | すぐ終わる |
setTimeoutProvider で unref | すぐ終わる |
mutations.gcTime: Infinity | すぐ終わる |
CI と手元の差、--detectOpenHandles の沈黙、React Native でだけ起きる理由が、すべてこの表で再現できた。
5. 直し方
直したのは 3 か所だ。
TanStack Query のタイマーをすべて unref する
TanStack Query v5 には、内部で使うタイマーの実装を差し替える timeoutManager.setTimeoutProvider がある。これで、TanStack Query が作るタイマーをすべて unref() する。unref したタイマーは、残っていてもプロセスの終了を妨げない。
jest.setup.js
// TanStack Query の内部タイマー(gcTime 既定 5 分の gc タイマーなど)を unref する。
// テストごとに QueryClient を作るため、全テスト完了後もタイマーが残り、
// in-band 実行では jest プロセスの終了を最大 5 分遅らせる。
// global の setTimeout は呼び出し時に参照し、jest のフェイクタイマーとの連携を保つ。
const { timeoutManager } = require("@tanstack/react-query");
function unrefTimer(timerId) {
if (typeof timerId?.unref === "function") {
timerId.unref();
}
return timerId;
}
timeoutManager.setTimeoutProvider({
setTimeout: (callback, delay) => unrefTimer(setTimeout(callback, delay)),
clearTimeout: (timeoutId) => clearTimeout(timeoutId),
setInterval: (callback, delay) => unrefTimer(setInterval(callback, delay)),
clearInterval: (intervalId) => clearInterval(intervalId),
});
setTimeout を provider の外で掴まず、呼び出すたびに参照しているのがポイントだ。テストで jest.useFakeTimers() を使うと global の setTimeout が差し替わるので、それに追従できる。
絶対に resolve しない Promise を mutate に渡さない
unref でプロセスは終わるようになるが、永久 pending の Mutation はテストとしても行儀が悪い。resolve を手元に持っておき、検証のあとで完了させる。
usePreferences.test.ts(修正後)
// リクエスト完了前の状態を検証するため、resolve を手元に保持して応答を保留する。
// 永久 pending のまま残すと Mutation の gc タイマーが再スケジュールされ続けるため、
// 検証後に必ず完了させる。
let resolvePatch: (value: { data: PreferencesResponse }) => void = () => {};
mockPatch.mockReturnValue(
new Promise((resolve) => {
resolvePatch = resolve;
}),
);
const { result } = renderHook(() => useUpdatePreferences(), { wrapper });
act(() => result.current.update({ enabled: true }));
await waitFor(() => {
const cache = queryClient.getQueryData(PREFERENCES_QUERY_KEY);
expect(cache?.enabled).toBe(true);
});
expect(result.current.isPending).toBe(true);
await act(async () => {
resolvePatch({ data: { ...INITIAL_PREFERENCES, enabled: true } });
});
await waitFor(() => expect(result.current.isPending).toBe(false));
new Promise(() => {}) は「待ち状態を作る」ための定番の書き方だが、TanStack Query の Mutation に渡すと今回の問題を起こす。チームではこの書き方を禁止にした。
テスト終了後も動く Animated.timing を止める
タイマーを片付けて in-band 実行で最後まで走るようになると、今度は exit code 1 で終わった。テスト終了後のログに、このエラーが約 240 件出ていた。
ReferenceError: You are trying to access a property or method of the Jest environment after it has been torn down.
トーストやバナーのテストで、Animated.timing がテストファイル終了後も動き続けていた。Animated.timing は requestAnimationFrame、つまり実際の setTimeout でフレームを進める。テストが終わってもアニメーションは止まらず、破棄済みの jest 環境に触って落ちる。
ワーカー実行ではこれもワーカーの強制終了に隠れていた。該当する 2 ファイルで、フェイクタイマーにアニメーションを閉じ込めた。
Toast.test.tsx
// Animated.timing は実タイマーでフレームを進めるため、実タイマーのままだと
// テストファイル終了後もアニメーションが走り続け、破棄済みの jest 環境へアクセスする。
jest.useFakeTimers();
結果
| 修正前 | 修正後 | |
|---|---|---|
| 手元の in-band 実行 | 終わらない | 47 秒 |
| CI(2 コア) | 30 分でタイムアウト | 3 分 |
gcTime: Infinity ではダメなのか
TanStack Query の公式ドキュメント寄りの対策は、テスト用の QueryClient に gcTime: Infinity を指定することだ。gc のタイマー自体を張らせない。上の最小構成でも、これで止まることを確認している。
const queryClient = new QueryClient({
defaultOptions: {
queries: { retry: false, gcTime: Infinity },
mutations: { gcTime: Infinity },
},
});
それでも unref を選んだのは、QueryClient を作っている場所が多すぎたからだ。今回のテストでは 64 ファイルがそれぞれ自前の QueryClient を作っていて、共通のヘルパーも無かった。gcTime: Infinity にするには全ファイルを書き換えるか、ヘルパーを作って全ファイルを移行する必要がある。しかも、新しいテストで指定を忘れたら再発する。
setTimeoutProvider なら jest.setup.js の 1 か所で済み、今後書かれるテストにも効く。使い分けはこう考えている。
| 対策 | 向いている場面 |
|---|---|
gcTime: Infinity | テスト用の QueryClient を共通ヘルパーで作っている。タイマーを張らせないほうが素直 |
setTimeoutProvider で unref | QueryClient の生成があちこちに散っている。アプリ側のシングルトンの QueryClient もテストで読み込まれる |
どちらを選んでも、永久 pending の Mutation を作らないことは別に守ったほうがいい。unref はプロセスの終了を妨げなくするだけで、Mutation が pending のまま残ること自体は変わらない。
6. 持ち帰ること
- CI でだけ出る差分は、コア数からも生まれる。2 コアのランナーでは jest は in-band 実行になる
- 「ワーカーなら通る」は、緑ではなく強制終了で黙らせた結果かもしれない。
force exitedの警告 1 行を見逃さない - CI でだけ止まるなら、まず手元で
-iを付けて、CI と同じ 1 プロセスにして再現する --detectOpenHandlesが黙っていたら、setTimeoutを横取りして作成場所を記録する- React Native の jest 環境は、TanStack Query からはブラウザに見える。
gcTimeの既定は 5 分になる
--forceExit を付ければ、今回の CI もとりあえず緑になったはずだ。ただそれだと、永久 pending の Mutation も、破棄済みの環境に触るアニメーションも、気づかないまま残っていた。手元の緑は、多コアのワーカーが失敗を握りつぶしてくれた結果かもしれない。
