跳转至

捕获异步堆栈跟踪

Caution:

  • 捕获异步堆栈跟踪会严重降低性能!

想跳过这篇文章?请参阅Conclusion，我们在其中讨论了一个普通的解决方案。

我们生活在一个充满虫子的世界。 软件变得越来越复杂，这使得调试变得越来越困难。 你是否曾经犯过错误，却不知道错误来自哪里?是的，通常不容易找到。

您可能已经注意到，错误的.stack有时看起来不完整。 这通常是由于计时器触发的异步函数的执行。 示例如下:

1
2
3
4
5
await new Promise((resolve, reject) => {
  setTimeout(() => {
    reject(new Error("here"));
  });
});

1
2
3
4
5
6
7
8
file:///home/szm/Desktop/got/demo.js:3
                reject(new Error('here'));
                       ^

Error: here
    at Timeout._onTimeout (file:///home/szm/Desktop/got/demo.js:3:10)
    at listOnTimeout (node:internal/timers:557:17)
    at processTimers (node:internal/timers:500:7)

The stack trace does not show where the timeout was set. It's currently not possible to determine this with the native Promises. However, bluebird exposes an option dedicated to capturing async stack traces:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
import Bluebird from "bluebird";

Bluebird.config({ longStackTraces: true });
global.Promise = Bluebird;

await new Promise((resolve, reject) => {
  setTimeout(() => {
    reject(new Error("here"));
  });
});

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
node:internal/process/esm_loader:74
    internalBinding('errors').triggerUncaughtException(
                              ^

Error: here
    at Timeout._onTimeout (file:///home/szm/Desktop/got/demo.js:7:10)
    at listOnTimeout (node:internal/timers:557:17)
    at processTimers (node:internal/timers:500:7)
From previous event:
    at file:///home/szm/Desktop/got/demo.js:5:7
    at ModuleJob.run (node:internal/modules/esm/module_job:183:25)
    at async Loader.import (node:internal/modules/esm/loader:178:24)
    at async Object.loadESM (node:internal/process/esm_loader:68:5)
    at async handleMainPromise (node:internal/modules/run_main:63:12)

Now it's clear. We know that the timeout was set on line 5. Bluebird should be sufficient for Got:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
import Bluebird from "bluebird";
import got from "got";

Bluebird.config({ longStackTraces: true });
global.Promise = Bluebird;

try {
  await got("https://httpbin.org/delay/1", {
    timeout: {
      request: 1,
    },
    retry: {
      limit: 0,
    },
  });
} catch (error) {
  console.error(error.stack);
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
TimeoutError: Timeout awaiting 'request' for 1ms
    at ClientRequest.<anonymous> (file:///home/szm/Desktop/got/dist/source/core/index.js:780:61)
    at Object.onceWrapper (node:events:514:26)
    at ClientRequest.emit (node:events:406:35)
    at TLSSocket.socketErrorListener (node:_http_client:447:9)
    at TLSSocket.emit (node:events:394:28)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
    at processTicksAndRejections (node:internal/process/task_queues:83:21)
    at Timeout.timeoutHandler [as _onTimeout] (file:///home/szm/Desktop/got/dist/source/core/timed-out.js:42:25)
    at listOnTimeout (node:internal/timers:559:11)
    at processTimers (node:internal/timers:500:7)
From previous event:
    at new PCancelable (file:///home/szm/Desktop/got/node_modules/p-cancelable/index.js:31:19)
    at asPromise (file:///home/szm/Desktop/got/dist/source/as-promise/index.js:21:21)
    at lastHandler (file:///home/szm/Desktop/got/dist/source/create.js:42:27)
    at iterateHandlers (file:///home/szm/Desktop/got/dist/source/create.js:49:28)
    at got (file:///home/szm/Desktop/got/dist/source/create.js:69:16)
    at file:///home/szm/Desktop/got/demo.js:8:8
    at ModuleJob.run (node:internal/modules/esm/module_job:183:25)
    at async Loader.import (node:internal/modules/esm/loader:178:24)
    at async Object.loadESM (node:internal/process/esm_loader:68:5)
    at async handleMainPromise (node:internal/modules/run_main:63:12)

As expected, we know where the timeout has been set. Unfortunately, if we increase our retry count limit to 1, the stack trace remains the same. That's because bluebird doesn't track I/O events. Please note that this should be sufficient for most cases. In order to debug further, we can use async_hooks instead. A Stack Overflow user has come up with an awesome solution:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
import asyncHooks from "async_hooks";

const traces = new Map();

asyncHooks
  .createHook({
    init(id) {
      const trace = {};
      Error.captureStackTrace(trace);
      traces.set(id, trace.stack.replace(/(^.+$\n){4}/m, "\n"));
    },
    destroy(id) {
      traces.delete(id);
    },
  })
  .enable();

globalThis.Error = class extends Error {
  constructor(message) {
    super(message);
    this.constructor.captureStackTrace(this, this.constructor);
  }

  static captureStackTrace(what, where) {
    super.captureStackTrace.call(Error, what, where);

    const trace = traces.get(asyncHooks.executionAsyncId());
    if (trace) {
      what.stack += trace;
    }
  }
};

If we replace the bluebird part with this, we get:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
Error: Timeout awaiting 'request' for 1ms
    at ClientRequest.<anonymous> (file:///home/szm/Desktop/got/dist/source/core/index.js:780:61)
    at Object.onceWrapper (node:events:514:26)
    at ClientRequest.emit (node:events:406:35)
    at TLSSocket.socketErrorListener (node:_http_client:447:9)
    at TLSSocket.emit (node:events:394:28)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
    at processTicksAndRejections (node:internal/process/task_queues:83:21)
    at emitInitScript (node:internal/async_hooks:493:3)
    at process.nextTick (node:internal/process/task_queues:133:5)
    at onDestroy (node:internal/streams/destroy:96:15)
    at TLSSocket.Socket._destroy (node:net:677:5)
    at _destroy (node:internal/streams/destroy:102:25)
    at TLSSocket.destroy (node:internal/streams/destroy:64:5)
    at ClientRequest.destroy (node:_http_client:371:16)
    at emitInitScript (node:internal/async_hooks:493:3)
    at initAsyncResource (node:internal/timers:162:5)
    at new Timeout (node:internal/timers:196:3)
    at setTimeout (node:timers:164:19)
    at addTimeout (file:///home/szm/Desktop/got/dist/source/core/timed-out.js:32:25)
    at timedOut (file:///home/szm/Desktop/got/dist/source/core/timed-out.js:59:31)
    at Request._onRequest (file:///home/szm/Desktop/got/dist/source/core/index.js:771:32)
    at emitInitScript (node:internal/async_hooks:493:3)
    at promiseInitHook (node:internal/async_hooks:323:3)
    at promiseInitHookWithDestroyTracking (node:internal/async_hooks:327:3)
    at Request.flush (file:///home/szm/Desktop/got/dist/source/core/index.js:274:24)
    at makeRequest (file:///home/szm/Desktop/got/dist/source/as-promise/index.js:125:30)
    at Request.<anonymous> (file:///home/szm/Desktop/got/dist/source/as-promise/index.js:121:17)
    at Object.onceWrapper (node:events:514:26)
    at emitInitScript (node:internal/async_hooks:493:3)
    at promiseInitHook (node:internal/async_hooks:323:3)
    at promiseInitHookWithDestroyTracking (node:internal/async_hooks:327:3)
    at file:///home/szm/Desktop/got/dist/source/core/index.js:357:27
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at emitInitScript (node:internal/async_hooks:493:3)
    at promiseInitHook (node:internal/async_hooks:323:3)
    at promiseInitHookWithDestroyTracking (node:internal/async_hooks:327:3)
    at file:///home/szm/Desktop/got/dist/source/core/index.js:338:50
    at Request._beforeError (file:///home/szm/Desktop/got/dist/source/core/index.js:388:11)
    at ClientRequest.<anonymous> (file:///home/szm/Desktop/got/dist/source/core/index.js:781:18)
    at Object.onceWrapper (node:events:514:26)
    at emitInitScript (node:internal/async_hooks:493:3)
    at process.nextTick (node:internal/process/task_queues:133:5)
    at onDestroy (node:internal/streams/destroy:96:15)
    at TLSSocket.Socket._destroy (node:net:677:5)
    at _destroy (node:internal/streams/destroy:102:25)
    at TLSSocket.destroy (node:internal/streams/destroy:64:5)
    at ClientRequest.destroy (node:_http_client:371:16)
    at emitInitScript (node:internal/async_hooks:493:3)
    at initAsyncResource (node:internal/timers:162:5)
    at new Timeout (node:internal/timers:196:3)
    at setTimeout (node:timers:164:19)
    at addTimeout (file:///home/szm/Desktop/got/dist/source/core/timed-out.js:32:25)
    at timedOut (file:///home/szm/Desktop/got/dist/source/core/timed-out.js:59:31)
    at Request._onRequest (file:///home/szm/Desktop/got/dist/source/core/index.js:771:32)
    at emitInitScript (node:internal/async_hooks:493:3)
    at promiseInitHook (node:internal/async_hooks:323:3)
    at promiseInitHookWithDestroyTracking (node:internal/async_hooks:327:3)
    at Request.flush (file:///home/szm/Desktop/got/dist/source/core/index.js:274:24)
    at lastHandler (file:///home/szm/Desktop/got/dist/source/create.js:37:26)
    at iterateHandlers (file:///home/szm/Desktop/got/dist/source/create.js:49:28)
    at got (file:///home/szm/Desktop/got/dist/source/create.js:69:16)
    at Timeout.timeoutHandler [as _onTimeout] (file:///home/szm/Desktop/got/dist/source/core/timed-out.js:42:25)
    at listOnTimeout (node:internal/timers:559:11)
    at processTimers (node:internal/timers:500:7)

This is extremely long, and not a complete Node.js app. Just a demo. Imagine how long it would be if this was used with databases, file systems, etc.

Conclusion

All these workarounds have a large impact on performance. However, there is a possible solution to this madness. Got provides handlers, hooks, and context. We can capture the stack trace in a handler, store it in a context and expose it in a beforeError hook.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
import got from "got";

const instance = got.extend({
  handlers: [
    (options, next) => {
      Error.captureStackTrace(options.context);
      return next(options);
    },
  ],
  hooks: {
    beforeError: [
      (error) => {
        error.source = error.options.context.stack.split("\n");
        return error;
      },
    ],
  },
});

try {
  await instance("https://httpbin.org/delay/1", {
    timeout: {
      request: 100,
    },
    retry: {
      limit: 0,
    },
  });
} catch (error) {
  console.error(error);
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
RequestError: Timeout awaiting 'request' for 100ms
    at ClientRequest.<anonymous> (file:///home/szm/Desktop/got/dist/source/core/index.js:780:61)
    at Object.onceWrapper (node:events:514:26)
    at ClientRequest.emit (node:events:406:35)
    at TLSSocket.socketErrorListener (node:_http_client:447:9)
    at TLSSocket.emit (node:events:394:28)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
    at processTicksAndRejections (node:internal/process/task_queues:83:21)
    at Timeout.timeoutHandler [as _onTimeout] (file:///home/szm/Desktop/got/dist/source/core/timed-out.js:42:25)
    at listOnTimeout (node:internal/timers:559:11)
    at processTimers (node:internal/timers:500:7) {
  input: undefined,
  code: 'ETIMEDOUT',
  timings: { <too long to include> },
  name: 'TimeoutError',
  options: { <too long to include> },
  event: 'request',
  source: [
    'Error',
    '    at got.extend.handlers (file:///home/szm/Desktop/got/demo.js:6:10)',
    '    at iterateHandlers (file:///home/szm/Desktop/got/dist/source/create.js:49:28)',
    '    at got (file:///home/szm/Desktop/got/dist/source/create.js:69:16)',
    '    at file:///home/szm/Desktop/got/demo.js:23:8',
    '    at ModuleJob.run (node:internal/modules/esm/module_job:183:25)',
    '    at async Loader.import (node:internal/modules/esm/loader:178:24)',
    '    at async Object.loadESM (node:internal/process/esm_loader:68:5)',
    '    at async handleMainPromise (node:internal/modules/run_main:63:12)'
  ]
}

Yay! This is much more readable. Furthermore, we capture the stack trace only when got is called. This is definitely going to have some performance impact, but it will be much more performant than the other mentioned solutions.

Curious to know more? Check out these links: