DanLevy.net

非同期スタックトレース: Error.stackが正しく表示しない理由

マイクロタスクキューが宿題を食べてしまった（そしてデバッグコンテキストも）

午前2時。PagerDutyのアラームが鳴り響いている。

ログを開くと、次のようなエラーが表示されます：

Error: Cannot read properties of undefined (reading 'id')
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

それだけです。関数名も、行番号も、ファイルパスも何もありません。ただの「processTicksAndRejections」です。

async JavaScriptへようこそ。ここでスタックトレースはでたらめで、行番号は関係ありません。

スタックトレースが壊れる理由

同期的なコードでは、コールスタックは美しい系譜です。AがBを呼び出し、BがCを呼び出します。Cがクラッシュしたとき、どうやってそこにたどり着いたのかを正確に見ることができます。

非同期コード（async/await）では、すべてのawaitキーワードが停止点となります。

awaitするたびに、あなたの関数はスタックから引き裂かれます。それはマイクロタスクキューというクライオジェニックフリーザーに保管されます。スタックは今や空（または他の処理を行っている）です。

Promiseが解決すると、あなたの関数は解凍されてスタックに戻されます。しかし履歴は失われています。

エンジンは500ミリ秒前に関数がawaitを呼び出したのは誰かまったく把握していません。ただ実行すべきタスクがあることを知っているだけです。

V8が試みた対処法

Node.jsは助けようと試みています。我々には以下の手段があります：

  1. Error.captureStackTrace()：スタックを作成時にキャプチャします。エラーが後で投げられると無意味です。
  2. --async-stack-traces：Node.jsがPromiseチェーンの「シャドウスタック」を保持するフラグです。
    • コスト：アプリケーションのパフォーマンスが30%低下します。
    • 結果：役立ちますが、すぐにノイズが増えて使いづらくなります。

本質的な解決策：AsyncLocalStorage

本番環境で生き残るためには、スタックトレースではなく因果関係に注目してください。

実行スレッドがスタックとマイクロタスクキューの間をジャンプしても、コンテキスト（ユーザーID、リクエストID）を”スレッド”にアタッチする必要があります。

Node.jsにはこのための組み込みツールがあります：AsyncLocalStorage

import { AsyncLocalStorage } from 'async_hooks';


const context = new AsyncLocalStorage();


// 1. リクエストをラップ
context.run({ requestId: '123' }, () => {
  // 2. 深い非同期コードを呼び出す
  await processOrder();
});


// 3. processOrderの内部：
async function processOrder() {
  await db.query();


  // 魔法！requestIdがまだ見える
  const { requestId } = context.getStore();
  console.log(`[${requestId}] 注文の処理に失敗`);
}

中間で何層ものawaitが発生しても構いません。コンテキストは生存します。

本番運用の手順書

  1. err.stackを信用しないでください。設計上不完全です。
  2. 構造化ログを使用してください。AsyncLocalStorageを使ってすべてのログラインにrequestIdをアタッチします。
  3. スタックではなくトレースしてください。OpenTelemetryを使用しましょう。これはサービス間の因果関係を可視化し、実際に気にすべき点を示します。

あなたのコードは非同期です。デバッグコンテキストはそうあってはいけません。

Loading comments...