皆さんこんにちは。この記事では、筆者が最近業務中に経験した恐るべき罠についてシェアしたいと思います。
CIでユニットテストを実行することは、とても多くのプロジェクトで行われています。ユニットテストは特に、既存のコードの変更を自信を持って行うために必要なものです。弊社でも、CI (GitHub Actions) でユニットテストを実行しています。
あるとき、CIの挙動が不安定になったことをきっかけに、CI上でのユニットテストの実行について調べてみました。その結果、とんでもないことが判明したのです。
不安定になったCI
時折、CIにすごく時間がかかり、30分経ったあたりでタイムアウトしてしまうことがありました。そのときのログを見てみると、jestによるユニットテストが実行されている最中に、何のログも出力せずに突然止まっているようでした。そのようなときはリトライするとそこそこの確率で成功します。
成功時はユニットテストは10分弱くらいで終了するので、テストにちょっと時間がかかったという様子でもありません。突然30分もかかるというのは異常な状態です。
ログもろくに出ていない状況では何が起こっているのか全然分かりませんが、このようなときに頼りになるのがcatchpoint/workflow-telemetry-actionです。ワークフローにこれを混ぜておくことで、プロセスのトレース、CPU使用量、メモリ使用量などの情報をお手軽に取得できます。
このアクションを使ってみると収穫がありました。メモリ使用量がかなりカツカツになっていることが分かったのです。
筆者もあまり詳しくありませんが、メモリ不足の状態では何が起こるか分かったものではありません。ログを何も出さずに応答しなくなることもあるでしょう。成功する場合もあることを踏まえると、運が悪いとメモリ使用量が限界に達して動作が停止してしまうのだと考えられました。
メモリリークの問題に対処する
この結果からは、Jestの実行中にメモリリークが起きていると判断できます。調べてみると、JestのGitHubリポジトリには次のようなissueがあります。どうも根本的にはNode.js側の問題で、16系の特定のバージョンから問題が発生しているようです。
この記事の公開時点では、Node.js 21系で修正済み、20系にはバックポート済、18系はバックポート予定という状態です。
ただ、筆者がこの問題に対処した当時はバックポートがまだだったため、別の方法で対処する必要がありました。幸いにもJestにはworkerIdleMemoryLimitというオプションがあり、これを有効にするとメモリ使用量が限界に達する前にワーカーを再起動してメモリを解放することができます。ワークアラウンドとしてこのオプションを導入することにしました。
// ...
workerIdleMemoryLimit: 0.3,
// ...
これを導入すると、メモリ使用量は次の画像のようになり、テストが最後まで実行されるようになりました。
これで一件落着……と思いきや、問題はこれだけではありませんでした。
テストが落ちる！
メモリリークの問題に対処したと思ったら、テストが落ちるようになってしまいました。数十個のテストが失敗してしまいます。しかも中身を見てみると、Flakyなテストなどではなく本当にテストが落ちているようです。
ここで判明した恐ろしい事実というのが、これまでCIが通ったように見えるケースでも、実はテストは最後まで走っていなかったということです。
つまり、この事象は「メモリリークによってCIが失敗することがある」というものではありませんでした。次の2種類の問題があり、一度たりとも成功などしていなかったのです。
- メモリリークによってテストが応答しなくなり、30分経ってタイムアウトする。（CIが失敗する）
- メモリリークによってテストが強制終了するが、その場合でもCIが通ってしまう。
後者の場合、おそらくメモリ不足によってプロセスが終了しています。ちょっと前に「運が悪いとメモリ使用量が限界に達して動作が停止してしまうのだと考えられました」と書きましたが、あれは実は違いますね。グラフをみると3分くらいでもうメモリ使用量が限界に達しているので、運が良ければメモリが足りるなんてことはまずありません。
このような場合、普通はプロセスが異常終了したらCIが落ちるものですが、そうならずにCIが通ってしまうという問題がありました。これがとても恐ろしい罠です。
npm-run-allの問題
この問題の原因を探っていたときに見つけたのが次のissueです。今回の場合、これが問題となっていました。
実は、このプロジェクトではnpm-run-allを介してjestを実行していました。具体的には、run-s test:*のようなスクリプトを書くとtest:*という名前のスクリプトを順に実行してくれるというものです。その中にtest:jestがあるイメージです。npm-run-allはnpm scriptsを書きやすくするユーティリティの中でも有名で、よく使われているものです。
上記のissueで説明されている問題は、npm-run-allで実行された子プロセスがSIGABRTを受け取って終了した場合にnpm-run-allからは成功として扱われてしまうというものです。また、よく調べてみるとSIGABRTに限らず、シグナルを受け取って終了した場合全般に同じ問題があるように見えます。
我々のプロジェクトではこの問題を見事に踏んでしまい、メモリリークによりテストが強制終了した場合にCIが通ってしまうという事態になっていました。
仕方がないので、落ちているテストは全部手作業で修正することで無事にCIが通るようになりました。
実は、上記のissueはopenのままですが、問題自体は2019年に修正済みであり、マージはされたもののまだリリースされていないという状態のようです。npm-run-allが最後にリリースされたのは2018年です。
よって、今後の類似事象を回避するためにはnpm-run-allを使わないようにするしかありません。OSSですからメンテナンスが止まってしまうこと自体を非難するつもりは全くありませんが、この状態で使い続けるのはやはり厳しいでしょう。このような足回りを担当し、プロセス周りのややこしい部分を扱うパッケージは特に、やはり使われれば使われるほどバグが見つかり洗練されていくものですから、継続的にメンテナンスされることが重要です。
幸いにも、npm-run-all2としてフォークをメンテナンスしてくれている人がいるので、こちらに乗り換えるのも良いでしょう。こちらであればこの問題は修正済みです。そのほか、同じような機能を提供する別のパッケージでも良いでしょう。
まとめ
今回は、2つの問題が運悪く組み合わさったことで、実際にはテストが通っていないのにCIが通り続けるという事態に陥ってしまった事例を紹介しました。確率的にタイムアウトが発生してCIが失敗するようになったのはむしろ幸運だったと言えるでしょう。これが無ければ、テストが正しく動いていない状態がより長く続いていたかもしれません。
教訓は色々ありますが、一度組んだCIが意図どおりに動いているかを時々確認することの重要性が改めて感じられますね。
jest + npm-run-allの組み合わせというのは世の中に結構ありそうです。この組み合わせの場合、現状だとNode.js 20以上を使っていなければ同じ問題の影響を受けている可能性があります。先日Node.js 16のEOLがありましたから、とりあえずNode.js 18に上げたという人も多いのではないでしょうか。
皆さんも、テストが最後まで実行されているかを確認してみてくださいね。
顧客満足度No.1*の商談解析クラウド ailead（エーアイリード）を提供しています。 AIが商談データを自動で収集・解析・可視化することで、営業現場の業務効率化と「売れる」営業人材の育成を実現します。 ailead.app/
Discussion
聞いただけで恐ろしすぎる……貴重な知見ありがとうございました。