Node.jsのスタックトレースが読みづらいのはなぜ？

こんにちは、Legalscape コンテンツバリューチームでエンジニアをしている清水です。

LegalscapeではNode.jsで書かれたサーバーが多く存在するため、ログを読み取る際にNode.jsのスタックトレースを見ることも多いのですが、どうもエラーが起きている箇所が特定しづらいと思うことが多く、なぜそういったことが起きるのか調べてみました。

Node.js

v24.11.1

で動作確認しています。

function f3() {
  throw new Error('error');
};

function f2() {
  f3();
};

function f1() {
  f2();
};

try {
  f1();
} catch (e) {
  console.error(e.stack);
}

こういった同期的なシンプルなコードではエントリーポイントからエラー箇所までのスタックトレースが取得できます。

Error: error
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:2:9)
    at f2 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:6:3)
    at f1 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:10:3)
    at file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:14:3
    at ModuleJob.run (node:internal/modules/esm/module_job:377:25)
    at async onImport.tracePromise.__proto__ (node:internal/modules/esm/loader:671:26)
    at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:101:5)

async, awaitを使うとどうなるでしょうか？

async function f3() {
  throw new Error('error');
};

async function f2() {
  await f3();
};

async function f1() {
  await f2();
};

try {
  await f1();
} catch (e) {
  console.error(e.stack);
}

async, awaitを使った関数に書き換えてもスタックトレースが維持されます。

Error: error
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:2:9)
    at f2 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:6:9)
    at f1 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:10:9)
    at file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:14:9
    at ModuleJob.run (node:internal/modules/esm/module_job:377:25)
    at async onImport.tracePromise.__proto__ (node:internal/modules/esm/loader:671:26)
    at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:101:5)

Promiseを使うとどうなるでしょうか？

async function f3() {
  return new Promise((resolve, reject) => {
    reject(new Error("error"));
  });
};

async function f2() {
  await f3();
};

async function f1() {
  await f2();
};

try {
  await f1();
} catch (e) {
  console.error(e.stack);
}

new Promise (<anonymous>) という行が入ることでスタックトレースが読みづらくなりましたが、関数のスタックは維持されています。

Error: error
    at file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:3:12
    at new Promise (<anonymous>)
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:2:10)
    at f2 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:8:9)
    at f1 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:12:9)
    at file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:16:9
    at ModuleJob.run (node:internal/modules/esm/module_job:377:25)
    at async onImport.tracePromise.__proto__ (node:internal/modules/esm/loader:671:26)
    at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:101:5)

突然の process.processTicksAndRejections

エラーが起きる行より前にfetchをawaitしてみます。

async function f3() {
  throw new Error('error');
};

async function f2() {
  await fetch('http://google.com');
  await f3();
};

async function f1() {
  await f2();
};

try {
  await f1();
} catch (e) {
  console.error(e.stack);
}

すると突然 process.processTicksAndRejections が現れました。

Error: error
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:7:9)
    at process.processTicksAndRejections (node:internal/process/task_queues:103:5)
    at async f2 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:11:3)
    at async f1 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:15:3)
    at async file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:19:3

これはfetchしたときだけ起きるというわけでもありません。以下のように process.nextTick で resolve() のタイミングをずらすした関数をawaitしてみます。

async function f3() {
  await (new Promise((resolve) => {
    process.nextTick(() => {
      resolve();
    });
  }));
  throw new Error('error');
};

async function f2() {
  await f3();
};

async function f1() {
  await f2();
};

try {
  await f1();
} catch (e) {
  console.error(e.stack);
}

このときもスタックトレースに process.processTicksAndRejections を出すことができました。

Error: error
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:7:9)
    at process.processTicksAndRejections (node:internal/process/task_queues:103:5)
    at async f2 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:11:3)
    at async f1 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:15:3)
    at async file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:19:3

スタックトレースを読む際は process.processTicksAndRejections がエラーとは関係なくても出ることを注意して読むようにするべきのようです。

awaitによってスタックトレースが途中から消えることがある

async functionはJavascriptではPromiseを返す関数なので、awaitせずにPromiseとしてそのままreturnすることができます。

async function f3() {
  throw new Error('error');
};

async function f2() {
  return f3();
};

async function f1() {
  await f2();
};

try {
  await f1();
} catch (e) {
  console.error(e.stack);
}

このときのスタックトレースは以下のようになります。

Error: error
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:2:9)
    at f2 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:6:10)
    at f1 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:10:9)
    at file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:14:9
    at ModuleJob.run (node:internal/modules/esm/module_job:377:25)
    at async onImport.tracePromise.__proto__ (node:internal/modules/esm/loader:671:26)
    at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:101:5)

この場合、特に変化はないのですが、エラーを投げる直前にawaitを追加してみます。

async function f3() {
  await null;
  throw new Error('error');
};

async function f2() {
  return f3();
};

async function f1() {
  await f2();
};

try {
  await f1();
} catch (e) {
  console.error(e.stack);
}

この場合はスタックトレースが途中から消えてしまいました。

Error: error
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:3:9)

これはf2でPromiseが返されたあと、エラーが発生したためf2以降はエラーと関係を持たなくなるためです。

このケースでは return await f3(); としてPromiseをアンラップすると、スタックトレースを維持できるようになります。

Error: error
    at f3 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:3:9)
    at async f2 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:7:10)
    at async f1 (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:11:3)
    at async file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:15:3

個人的にはこのように return await promise とすることでパフォーマンスが悪くなるのではないかという想像をしていました。ですがV8による最適化があるため return await promise は return promise と同等以上の速度になるとのことです。積極的に使っていきたいですね。

コールバックの中で作られたエラーはスタックトレースが保持されない

Node.jsはイベント駆動な実行環境で、コールバックを使って非同期的な処理を書くこともできます。

function f3() {
  setTimeout(() => {
    throw new Error("error");
  }, 0);
};

function f2() {
  f3();
};

function f1() {
  f2();
};

try {
  f1();
} catch (e) {
  console.error(e.stack);
}

process.on('uncaughtException', e => {
  console.error('uncaughtException');
  console.error(e.stack);
})

このケースでは、コールバック以降しかスタックトレースに残らない上、f1をtry catchしても例外をcatchすることができず、uncaughtExceptionとなってしまいます。

uncaughtException
Error: error
    at Timeout._onTimeout (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:3:11)
    at listOnTimeout (node:internal/timers:605:17)
    at process.processTimers (node:internal/timers:541:7)

このコールバックによる非同期処理をPromiseとawaitを使うことでスタックトレースに乗せることができるのでしょうか。

async function f3() {
  return new Promise((_, reject) => {
    setTimeout(() => {
      reject(new Error("error"));
    }, 0);
  });
};

async function f2() {
  await f3();
};

async function f1() {
  await f2();
};

try {
  await f1();
} catch (e) {
  console.error(e.stack);
}

これによりsetTimeoutの中で起きたエラーはuncaughtExceptionではなくf1のtry catchで捕まえることができるようになりましたが、肝心のスタックトレースは同様でした。

Error: error
    at Timeout._onTimeout (file:///Users/uzimith/src/github.com/legalscape/uzimith-test/run.mjs:4:14)
    at listOnTimeout (node:internal/timers:605:17)
    at process.processTimers (node:internal/timers:541:7)

こうなった状況でのデバッグは困難が伴いますね。