nodejs / undici

An HTTP/1.1 client, written from scratch for Node.js
https://nodejs.github.io/undici
MIT License
6.23k stars 540 forks source link

fetch error loses stack context #2331

Open KhafraDev opened 1 year ago

KhafraDev commented 1 year ago

repro from #2328

without the Error.captureStackTrace in index.js:

NODE_V8_COVERAGE='./coverage/tmp' node test.mjs
/var/github/undici/lib/compat/dispatcher-weakref.js:25
    dispatcher.on('disconnect', () => {
               ^

TypeError: dispatcher.on is not a function
    at CompatFinalizer.register (/var/github/undici/lib/compat/dispatcher-weakref.js:25:16)
    at new Request (/var/github/undici/lib/fetch/request.js:391:26)
    at fetch (/var/github/undici/lib/fetch/index.js:136:21)
    at fetch (/var/github/undici/index.js:107:20)
    at file:///var/github/undici/test.mjs:5:7
    at ModuleJob.run (node:internal/modules/esm/module_job:217:25)
    at async ModuleLoader.import (node:internal/modules/esm/loader:308:24)
    at async loadESM (node:internal/process/esm_loader:42:7)
    at async handleMainPromise (node:internal/modules/run_main:66:12)

Node.js v20.6.1

with:

 NODE_V8_COVERAGE='./coverage/tmp' node test.mjs
/var/github/undici/index.js:110
        Error.captureStackTrace(err, this)
              ^

TypeError: dispatcher.on is not a function
    at fetch (/var/github/undici/index.js:110:15)
    at async file:///var/github/undici/test.mjs:5:1

Node.js v20.6.1
metcoder95 commented 1 year ago

Shall we remove the Error.captureStackTrace at all?

KhafraDev commented 1 year ago

yes probably, although it was added on purpose to show where the error originated from

KhafraDev commented 1 year ago

if we remove it the stack trace doesn't contain where fetch was called from, probably not much we can do here?

metcoder95 commented 1 year ago

It has it, isn't it? I'm looking at these 5 traces:

    at CompatFinalizer.register (/var/github/undici/lib/compat/dispatcher-weakref.js:25:16)
    at new Request (/var/github/undici/lib/fetch/request.js:391:26)
    at fetch (/var/github/undici/lib/fetch/index.js:136:21)
    at fetch (/var/github/undici/index.js:107:20)
    at file:///var/github/undici/test.mjs:5:7

It is more verbose, sure but at least it won't point directly to the Error.captureStackTrace call only. Or do you refer to something else?

KhafraDev commented 1 year ago

with this code:

import { fetch } from './index.js'

await fetch('https://a')
TypeError: fetch failed
    at Object.processResponse (/var/github/undici/lib/fetch/index.js:227:23)
    at /var/github/undici/lib/fetch/index.js:939:38
    at node:internal/process/task_queues:140:7
    at AsyncResource.runInAsyncScope (node:async_hooks:203:9)
    at AsyncResource.runMicrotask (node:internal/process/task_queues:137:8)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5) {

with:

TypeError: fetch failed
    at fetch (/var/github/undici/index.js:110:15)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async file:///var/github/undici/test.mjs:3:1 {

notice that the "with" stack trace includes the file fetch was called from, test.mjs, while the without does not.

metcoder95 commented 1 year ago

Ah, ok now I see; within the dispatcher example you shared, the entry point is still there; but not with fetch.

Playing a bit, I think we can have a quick workaround, but replacing the constructor with module.exports.fetch instead of this, the stack trace remains the same but removes the pointer to the Error.captureStackTrace(err) as it removes one stack more. i.e.

With Error.captureStackTrace(err, module.exports.fetch)

+node:internal/process/task_queues:95
    runMicrotasks();
    ^

TypeError: fetch failed
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async file:///var/users/github/undici/playground.mjs:28:1 {
  cause: Error: getaddrinfo ENOTFOUND a
      at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26) {
    errno: -3008,
    code: 'ENOTFOUND',
    syscall: 'getaddrinfo',
    hostname: 'a'
  }
}

With Error.captureStackTrace(err, this):

+/Users/metcoder/Documents/Workspace/MetCoder/Undici_Core/index.js:113
        Error.captureStackTrace(err, this)
              ^

TypeError: fetch failed
    at fetch (/Users/metcoder/Documents/Workspace/MetCoder/Undici_Core/index.js:113:15)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async file:///Users/metcoder/Documents/Workspace/MetCoder/Undici_Core/playground.mjs:28:1 {
  cause: Error: getaddrinfo ENOTFOUND a
      at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26) {
    errno: -3008,
    code: 'ENOTFOUND',
    syscall: 'getaddrinfo',
    hostname: 'a'
  }
}

I imagine the execution context and how fetch gets managed adds quite a few stacks that move out of the scope of the entry point, the reason for the captureStackTrace in the first place. By seeking for the function and only the function, the stack trace gets slightly better; at least points that something failed internally instead of pointing to a Error.captureStackTrace; but somehow ended nearby 🤔

hanayashiki commented 6 months ago

I think fetch is quite commonly used, but erroring in fetch is now a pain in the ass

image

There is zero hint about who is fetching.

It's 2024.4 and will this issue get some notice?

tamird commented 6 months ago

The original "fix" was in https://github.com/nodejs/undici/pull/1619, where diff was

-    return fetchImpl.apply(dispatcher, arguments)
+    try {
+      return await fetchImpl.apply(dispatcher, arguments)
+    } catch (err) {
+      Error.captureStackTrace(err, this)
+      throw err
+    }

this changes two things:

Could we revert the second part? That should gives us a stack trace from the broken internals of undici all the way up to user code.

mcollina commented 6 months ago

@KhafraDev @metcoder95 was there any progress with thisv

metcoder95 commented 6 months ago

Not really, I haven't dig deeper after that I showed; once done with the other opened PRs I might be able to revisit this.

Stills open if anyone wants to give it a try 👍

KhafraDev commented 6 months ago

That should gives us a stack trace from the broken internals of undici all the way up to user code.

It does not, the original issue then pops up again.

prljav commented 2 months ago

will this ever be resolved? i just encountered this and there is literally no origin of the actual source

mcollina commented 2 months ago

I'm 100% lost on the reproduction for this. Can somebody add one?