Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Wrapping RequestError obscures its source #795

Closed
1 task done
paulmelnikow opened this issue May 8, 2019 · 14 comments · Fixed by #935
Closed
1 task done

Wrapping RequestError obscures its source #795

paulmelnikow opened this issue May 8, 2019 · 14 comments · Fixed by #935
Labels
bug Something does not work as it should

Comments

@paulmelnikow
Copy link
Contributor

What would you like to discuss?

When I’m working on and with nock, I often see stack traces that look like this:

OverriddenClientRequest.request.once.error (node_modules/got/source/request-as-event-emitter.js:178:14)
OverriddenClientRequest.origin.emit.args (node_modules/@szmarczak/http-timer/source/index.js:37:11)
lib/request_overrider.js:24:552

Or sometimes:

OverriddenClientRequest.request.once.error (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:178:14)
OverriddenClientRequest.emit (events.js:187:15)
OverriddenClientRequest.EventEmitter.emit (domain.js:442:20)
OverriddenClientRequest.origin.emit.args (/Users/pnm/code/nock/node_modules/@szmarczak/http-timer/source/index.js:37:11)
/Users/pnm/code/nock/lib/request_overrider.js:24:552
process._tickCallback (internal/process/next_tick.js:61:11)

The underlying stack trace is this:

end (/Users/pnm/code/nock/lib/request_overrider.js:32:187)
/Users/pnm/code/nock/lib/request_overrider.js:13:2198
OverriddenClientRequest.RequestOverrider.req.write (/Users/pnm/code/nock/lib/request_overrider.js:13:1387)
OverriddenClientRequest.RequestOverrider.req.end (/Users/pnm/code/nock/lib/request_overrider.js:13:1970)
handleRequest (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:212:14)
get (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:236:5)
Immediate.setImmediate (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:307:10)

However when got wraps the error in a RequestError, the original stack trace is no longer available.

To be fair, part of what makes this confusing is that the test runner’s output (which has nothing to do with nock or got) and looks like this:

 FAIL  tests/test_intercept.js
Nock: No match for request {   "method": "GET",   "url": "http://example.com/",   "headers": {     "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",     "accept-encoding": "gzip, deflate"   } }

				} else {
					error = new RequestError(error, options);
-------------^
				}

  stack: >
    OverriddenClientRequest.request.once.error
    (node_modules/got/source/request-as-event-emitter.js:178:14)

    OverriddenClientRequest.origin.emit.args (node_modules/@szmarczak/http-timer/source/index.js:37:11)

    lib/request_overrider.js:24:552
  at:
    line: 178
    column: 14
    file: node_modules/got/source/request-as-event-emitter.js
    function: OverriddenClientRequest.request.once.error

For a long time it was unclear that the error and had anything to do with Nock. Nock doesn’t appear in the stack trace despite being the layer that threw the error. And the test runner's output doesn't make it quite so clear to me that “Nock: No match for request” was the message for the error that was being emitted by got.

There is not much that is documented about RequestError, though I imagine the benefit of wrapping errors in RequestError is to associate with the thrown error the additional bits information about the request. In this case, however, the wrapping did not provide a benefit. Instead, it made it harder to understand what was happening.

Some possible ideas for making this easier for developers to understand:

  1. Preserve the original error.stack and attach it to the new RequestError. This could be done in GotError’s constructor. I experimented with this locally and it seems to work. (Though it is slightly disorienting to see Nock’s stack trace attached to something called RequestError, which is not from nock.)
  2. Replace the wrapping with decorating. Instead of creating a new error, attach the got-related options to the existing error object.
  3. Modify nock so it doesn’t emit this error through the request.

I’d be really curious to hear your thoughts on (1) and (2)! Regardless of what's decided here, I think (3) could be worth pursuing, as it will make it easier both to test nock and also to use it.

I can’t find a discussion on this specific topic, though there was some discussion about async stack traces in #279 and #447.

Thanks so much for all your work on this amazing library!

Checklist

  • I have read the documentation.
@sindresorhus
Copy link
Owner

What Node.js version is this from? Are you sure this is caused by wrapping the error and not by catching and then emitting the error asynchronously? Note that Node.js 12 has support for async stack traces, so the error stacks should ideally be much better there. Could you try?

nodejs/node#11865 (comment)

@paulmelnikow
Copy link
Contributor Author

Hi! Sorry it's taken me a moment to get back to this.

I'm testing now in Node 10, and it's definitely the wrapping and not the async emitting that's causing it. If I comment out the wrapping and emitError(error), the stack trace changes.

With wrapping:

  stack: >
    OverriddenClientRequest.request.once.error
    (node_modules/got/source/request-as-event-emitter.js:197:14)

    OverriddenClientRequest.origin.emit.args (node_modules/@szmarczak/http-timer/source/index.js:37:11)

    lib/request_overrider.js:32:555
  at:
    line: 197
    column: 14
    file: node_modules/got/source/request-as-event-emitter.js
    function: OverriddenClientRequest.request.once.error

Without:

  stack: >
    end (lib/request_overrider.js:40:187)

    lib/request_overrider.js:21:637

    OverriddenClientRequest.RequestOverrider.req.write (lib/request_overrider.js:19:743)

    OverriddenClientRequest.RequestOverrider.req.end (lib/request_overrider.js:21:411)

    handleRequest (node_modules/got/source/request-as-event-emitter.js:235:14)

    get (node_modules/got/source/request-as-event-emitter.js:258:5)

    Immediate.setImmediate (node_modules/got/source/request-as-event-emitter.js:336:10)

The stack trace of the wrapped errors in Node 12 looks the same as in Node 10:

    OverriddenClientRequest.<anonymous>
    (node_modules/got/source/request-as-event-emitter.js:197:14)

    OverriddenClientRequest.origin.emit (node_modules/@szmarczak/http-timer/source/index.js:37:11)

    lib/request_overrider.js:32:555

@szmarczak
Copy link
Collaborator

szmarczak commented Jul 11, 2019

@paulmelnikow Can you provide some code example?

@paulmelnikow
Copy link
Contributor Author

Sure! Here are two fairly small examples that show two different ways errors can be emitted through Nock. The first one trigger's nock's "no match for request" error, which is triggered when the application makes an unmocked request to a mocked hostname. It's one of the most common errors in Nock. The second one simulates a programmer error in a nock consumer.

const nock = require('.')
const got = require('got').extend({ retry: 0 })

async function noMatch() {
  nock('http://example.com')
    .get('/')
    .reply()

  await got('http://example.com/this-route-is-not-mocked')
}

async function programmerError() {
  nock('http://example.com')
    .get('/')
    .reply(() => {
      throw Error('This is a programmer error in test.js')
    })

  await got('http://example.com/')
}

;(async () => {
  try {
    await noMatch()
  } catch (e) {
    console.error(e)
  }

  nock.cleanAll()

  try {
    await programmerError()
  } catch (e) {
    console.error(e)
  }

  process.exit(0)
})()

I tried to add it in RunKit but I'm not sure how to request the beta release of nock. This was tested on the beta branch of nock though it works equally well with the latest beta release 11.0.0-beta.23.

There are a few places in request-as-event-emitter where errors are wrapped, and these two errors trigger different paths. If I replace each of them, the stack traces change from:

RequestError: Nock: No match for request {
  "method": "GET",
  "url": "http://example.com/this-route-is-not-mocked",
  "headers": {
    "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",
    "accept-encoding": "gzip, deflate"
  }
}
    at OverriddenClientRequest.request.once.error (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:197:19) <-- line in got where the error is wrapped
    at OverriddenClientRequest.emit (events.js:187:15)
    at OverriddenClientRequest.origin.emit.args (/Users/pnm/code/nock/node_modules/@szmarczak/http-timer/source/index.js:37:11)
    at /Users/pnm/code/nock/lib/request_overrider.js:213:11
    at process._tickCallback (internal/process/next_tick.js:61:11)
RequestError: This is a programmer error in test.js
    at handleRequest (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:238:19) <-- line in got where the error is wrapped
    at get (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:259:9)
    at Immediate.setImmediate (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:337:13)

to what I'd like to see:

Error: Nock: No match for request {
  "method": "GET",
  "url": "http://example.com/this-route-is-not-mocked",
  "headers": {
    "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",
    "accept-encoding": "gzip, deflate"
  }
}
    at end (/Users/pnm/code/nock/lib/request_overrider.js:268:19) <-- line in nock where the error is emitted
    at req.write (/Users/pnm/code/nock/lib/request_overrider.js:147:9)
    at OverriddenClientRequest.RequestOverrider.req.write (/Users/pnm/code/nock/lib/request_overrider.js:119:9)
    at OverriddenClientRequest.RequestOverrider.req.end (/Users/pnm/code/nock/lib/request_overrider.js:143:11)
    at handleRequest (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:235:19)
    at get (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:259:9)
    at Immediate.setImmediate (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:337:13)
Error: This is a programmer error in test.js
    at Interceptor.nock.get.reply [as fullReplyFunction] (/Users/pnm/code/nock/test.js:16:13) <-- line in my example test file where the error is created and thrown
    at end (/Users/pnm/code/nock/lib/request_overrider.js:344:43)
    at req.write (/Users/pnm/code/nock/lib/request_overrider.js:147:9)
    at OverriddenClientRequest.RequestOverrider.req.write (/Users/pnm/code/nock/lib/request_overrider.js:119:9)
    at OverriddenClientRequest.RequestOverrider.req.end (/Users/pnm/code/nock/lib/request_overrider.js:143:11)
    at handleRequest (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:235:19)
    at get (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:259:9)
    at Immediate.setImmediate (/Users/pnm/code/nock/node_modules/got/source/request-as-event-emitter.js:337:13)

@szmarczak
Copy link
Collaborator

Thanks for the quick response! I'll solve this issue tomorrow because it's late here.

@paulmelnikow
Copy link
Contributor Author

Amazing! Let me know if there's anything I can help clarify :)

@szmarczak szmarczak added the bug Something does not work as it should label Jul 12, 2019
@szmarczak
Copy link
Collaborator

					const oldStack = error.stack;
					error = new RequestError(error, options);
					console.log('OLD STACKTRACE', oldStack, '\n', 'NEW STACKTRACE', error.stack);

gives me:

OLD STACKTRACE Error: Nock: No match for request {
  "method": "GET",
  "url": "http://example.com/this-route-is-not-mocked",
  "headers": {
    "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",
    "accept-encoding": "gzip, deflate, br"
  }
}
    at end (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:268:19)
    at /home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:147:9
    at OverriddenClientRequest.RequestOverrider.req.write (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:119:9)
    at OverriddenClientRequest.RequestOverrider.req.end (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:143:11)
    at handleRequest (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:190:29)
    at get (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:214:17)
    at Immediate.<anonymous> (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:310:19) 
 NEW STACKTRACE RequestError: Nock: No match for request {
  "method": "GET",
  "url": "http://example.com/this-route-is-not-mocked",
  "headers": {
    "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",
    "accept-encoding": "gzip, deflate, br"
  }
}
    at OverriddenClientRequest.<anonymous> (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:160:29)
    at OverriddenClientRequest.emit (events.js:208:15)
    at OverriddenClientRequest.origin.emit (/home/szm/Desktop/got/node_modules/@szmarczak/http-timer/dist/index.js:38:20)
    at /home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:213:11
    at processTicksAndRejections (internal/process/task_queues.js:75:11)

IOW RequestErrors doesn't save the old stacktrace. Yup, this may seem odd.

@szmarczak
Copy link
Collaborator

szmarczak commented Jul 12, 2019

Node solves this via: https://github.com/nodejs/node/blob/cc6f99de449beb0993db3647de4ef979bead804d/lib/internal/errors.js#L870-L878

Possible alternatives:

I think we should do the same as Node.

@szmarczak
Copy link
Collaborator

szmarczak commented Jul 12, 2019

Another solution would be to requestErrorInstance.stack += '\n' + error.stack;

@szmarczak szmarczak changed the title Wrapping request error obscures its source Wrapping RequestError obscures its source Jul 14, 2019
@sindresorhus
Copy link
Owner

Another solution would be to requestErrorInstance.stack += '\n' + error.stack;

How does the error stack trace look when you do that?

@szmarczak
Copy link
Collaborator

It looks like this:

RequestError: Nock: No match for request {
  "method": "GET",
  "url": "http://example.com/this-route-is-not-mocked",
  "headers": {
    "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",
    "accept-encoding": "gzip, deflate, br"
  }
}
    at OverriddenClientRequest.<anonymous> (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:160:29)
    at OverriddenClientRequest.emit (events.js:208:15)
    at OverriddenClientRequest.origin.emit (/home/szm/Desktop/got/node_modules/@szmarczak/http-timer/dist/index.js:38:20)
    at /home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:213:11
    at processTicksAndRejections (internal/process/task_queues.js:75:11)
Error: Nock: No match for request {
  "method": "GET",
  "url": "http://example.com/this-route-is-not-mocked",
  "headers": {
    "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",
    "accept-encoding": "gzip, deflate, br"
  }
}
    at end (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:268:19)
    at /home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:147:9
    at OverriddenClientRequest.RequestOverrider.req.write (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:119:9)
    at OverriddenClientRequest.RequestOverrider.req.end (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:143:11)
    at handleRequest (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:190:29)
    at get (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:214:17)
    at Immediate.<anonymous> (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:310:19) 

It'll be more readable without the first line of the NockError because it's already contained in the RequestError:

RequestError: Nock: No match for request {
  "method": "GET",
  "url": "http://example.com/this-route-is-not-mocked",
  "headers": {
    "user-agent": "got/9.6.0 (https://github.com/sindresorhus/got)",
    "accept-encoding": "gzip, deflate, br"
  }
}
    at OverriddenClientRequest.<anonymous> (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:160:29)
    at OverriddenClientRequest.emit (events.js:208:15)
    at OverriddenClientRequest.origin.emit (/home/szm/Desktop/got/node_modules/@szmarczak/http-timer/dist/index.js:38:20)
    at /home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:213:11
    at processTicksAndRejections (internal/process/task_queues.js:75:11)
    at end (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:268:19)
    at /home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:147:9
    at OverriddenClientRequest.RequestOverrider.req.write (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:119:9)
    at OverriddenClientRequest.RequestOverrider.req.end (/home/szm/Desktop/demo/node_modules/nock/lib/request_overrider.js:143:11)
    at handleRequest (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:190:29)
    at get (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:214:17)
    at Immediate.<anonymous> (/home/szm/Desktop/got/dist/source/request-as-event-emitter.js:310:19) 

@sindresorhus
Copy link
Owner

The last one looks good 👍

@paulmelnikow
Copy link
Contributor Author

Thanks so much for fixing this! It’s going to make debugging nock much easier.

When you release another beta I’d be glad to take it for a spin.

@szmarczak
Copy link
Collaborator

No problem! If there are any enhancements left to be done, just open an issue, we're happy to help :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something does not work as it should
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants