はじめに
こんにちは。APP/UXグループの大谷と申します。 寒くなってきてグラコロが美味しい季節ですね。年がわりで発売されるデミグラスソースがかかっているバージョンより、ノーマルバージョンのグラコロが個人的には好みです。
バージョンといえば先日Node.jsのバージョンを更新した際に困ったことについて書いていきたいと思います。
何が起きたか
弊社では一部の機能の画面をNuxtを使って提供しており、server middlewareをBFFとして利用しAPIリクエストはserver middlewareを経由して投げられています。 (詳しい構成についてはこちらの記事に添付の資料をご参照ください)
今回はNode.jsのバージョンを v12 → v14 → v16に段階的に更新する作業をおこなっていました。(バージョンが一部歯抜けになっているのは依存関係の解消の関係でやりやすかったバージョンを選んだためです)v14に更新するリリースは無事に完了していて、v16に更新する際は関連のWarningも解消するためコード修正が行われていました。Warningが発生していた対象は記載順や命名に関するlintエラーの解消などロジックに影響するような変更は含んでおりませんでした。
しかしv16に更新した直後Nuxtのプロセスが終了/ 再開を繰り返していしまっていることが発覚し、ただちにロールバックを行いました。
調査したこと
プロセスが終了している周辺のNuxtのアクセスログを確認したところ、いくつかのエラーが確認できました。
Error: Cannot set headers after they are sent to the client at new NodeError (node:internal/errors:387:5) at ServerResponse.setHeader (node:_http_outgoing:644:11) at ServerResponse.header (/app/node_modules/express/lib/response.js:794:10) at sendJsonResponse (/app/apiServer/api/endpoint.js:215:11) at {Nuxtのserver middleware内}:80:5 at runMicrotasks (<anonymous>) at processTicksAndRejections (node:internal/process/task_queues:96:5)
上記のエラーは検証環境では発生が確認できていなかったものでした。
何がトリガーになっているか上記のエラーの周辺のアクセスログやAPIのリクエスト状況などを確認したところ、エラーがでる直前のタイミングのいくつかのAPIリクエストでエラーレスポンスが返っていることが確認できました。
エラーレスポンスが返る状況を強制的に発生させたところ、検証環境でもプロセスの終了がおきる現象を再現することができました。
再現はできたもののプロセスが終了する原因になる確証がなく、この時点では修正が必要な箇所を特定する情報を割り出すことができませんでした。 変更前後の状況を比較するために一度Node.js v16 → v14にバージョンを戻した状態でも検証を行いました。
その時にログで確認できたのが
UnhandledPromiseRejectionWarning: Error: Cannot set headers after they are sent to the client at new NodeError (node:internal/errors:387:5) at ServerResponse.setHeader (node:_http_outgoing:644:11) at ServerResponse.header (/app/node_modules/express/lib/response.js:794:10) at sendJsonResponse (/app/apiServer/api/endpoint.js:225:11) at {Nuxtのserver middleware内}:80:5 at processTicksAndRejections (node:internal/process/task_queues:96:5) (Use `node --trace-warnings ...` to show where the warning was created) (node:36) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 4) (node:35) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
という内容でした。
原因
エラーの内容をよく読むと
(node:36) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 4) (node:35) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
UnhandledPromiseRejectionWarningは非同期関数内でエラーがthrowされた場合や、Promiseがrejectされた時にcatchで捕捉されなかった場合に発生するようで、今後上記のようにエラーが処理されていなかった場合にNode.js のプロセスを終了するという記述がされていました。 まさに！という状況で、Node.jsのバージョンごとの変更点を確認したところUnhandledPromiseRejectionWarningはNode.js v15以降でプロセスが終了するオプションがデフォルト設定になっていたことがわかりました(これだ。。。。)
エラーの前半部分については
UnhandledPromiseRejectionWarning: Error: Cannot set headers after they are sent to the client
特定の条件下でserver middlewareからclientにレスポンスを返した後に、処理を終了せずに再びレスポンスを返そうとしていて発生しているものでした。 プロセス終了につながる原因となっていたエラー発生箇所は他にもいくつかありましたが、このエラーについてはAPIレスポンスのステータスコードを使った条件分岐の単純な考慮不足で潜在的に発生していたエラーハンドリングのミスがNode.jsのバージョン更新によって思わぬ形で浮き彫りになるという結果となってしまいました。
対策
UnhandledPromiseRejectionWarningが発生している状況をNuxtのアクセスログから精査し、上記のCannot set headers after they are sent to the clientのように不正なハンドリングをしてしまっていた部分は修正を行いました。
また、server middlewareの部分で最終的にエラーが野放しになってしまうことがないようリクエストルートにcatchを追加し、エラーを必ず補足できるように対応しました。
最後に保険的な対応として、万が一完全にエラーが解消できていなかったケースを考慮しUnhandledPromiseRejectionWarningが発生してもプロセスを終了せず、ログだけ残せるように下記のオプションをNuxtの起動コマンドに追加しました。
NODE_OPTIONS='--trace-warnings=warn'
リリース後のログの状況を監視し、万が一UnhandledPromiseRejectionWarningが発生していた場合は都度修正を行うという方針にしました。
おわりに
Node.js v15以降のUnhandledPromiseRejectionWarningの扱いの変更は破壊的な変更にとなっていました。
当たり前な話なのですが、こういった変更が入っているという情報はライブラリのバージョン毎の変更差分を確認し事前に対策することが必要となります。
しかしそもそも、今回はエラーのハンドリングが不十分なところがあり不安定なコードになってた事実も根底としてありました。
異常系のテストはUTでもサポートする等、実装時点で警告を見逃さずより安全にシステムを運用できるよう努めたいと思います。
調査の流れも含めて長文になってしまいましたが最後まで読んでいただきありがとうございました。
