nock and popsicle not working nicely together

[KrayzeeKev]

What is the expected behavior?

Context: Sitting behind firewall - no external DNS possible.
nock'ed URL should return nock'ed response.

What is the actual behavior?

nock returns THEN a dns exception is raised

Possible solution

Is nock returning before it's done? Or is it popsicle being too clever for its own good.

How to reproduce the issue

Runkit: Bug Demo

Does the bug have a test case?

This code:

'use strict';
const nock = require('nock');
const popsicle = require('popsicle');

nock('http://badserver.com/whatever')
  .persist()
  .get(/details/)
  .reply(uri => {
    return [200, {
      statusCode: 200,
      result: `Got ${uri} successfully`,
    }];
  });

async function doit() {
  const gres = await popsicle.fetch('http://badserver.com/whatever/details');
  console.log('Fetch complete');
  //const text = await gres.text();
}

(async function main() {
  await doit();
  console.log('After doit');
  let count = 0;
  while (true) {
    console.log('Before timeout', ++count);
    await new Promise( resolve => setTimeout(resolve, 1) );
    console.log('After timeout', count);
  }

})();

Runs and then, AFTER, the fetch/get is complete, it gets a DNS error. And SOMETIMES nock debug entries are emitted AFTER the fetch/get is complete:

$ DEBUG=nock.* node test.js
  nock.back New nock back mode: dryrun +0ms
  nock.recorder 0 restoring all the overridden http/https properties +0ms
  nock.common restoring requests +0ms
  nock.intercept restoring overridden ClientRequest +0ms
  nock.intercept - ClientRequest was not overridden +0ms
  nock.intercept Overriding ClientRequest +0ms
  nock.intercept ClientRequest overridden +1ms
  nock.common overriding requests +1ms
  nock.common - overriding request for http +0ms
  nock.common - overridden request for http +0ms
  nock.common - overriding request for https +0ms
  nock.common - overridden request for https +0ms
  nock.interceptor reply.headers: {} +0ms
  nock.interceptor reply.rawHeaders: [] +2ms
  nock.common options.hostname in the end: "blahblahx.com" +269ms
  nock.common options.host in the end: "blahblahx.com:80" +1ms
  nock.intercept interceptors for "blahblahx.com:80" +270ms
  nock.intercept filtering interceptors for basepath http://blahblahx.com:80 +0ms
  nock.intercept matched base path (1 interceptor) +1ms
  nock.common options.host: blahblahx.com:80 +3ms
  nock.common options.hostname in the end: "blahblahx.com" +0ms
  nock.common options.host in the end: "blahblahx.com:80" +0ms
  nock.intercept interceptors for "blahblahx.com:80" +2ms
  nock.intercept filtering interceptors for basepath http://blahblahx.com:80 +0ms
  nock.intercept matched base path (1 interceptor) +1ms
  nock.intercept using 1 interceptors +0ms
  nock.request_overrider req.end +0ms
  nock.request_overrider write [Arguments] { '0': undefined, '1': undefined } +0ms
  nock.request_overrider ending +5ms
  nock.interceptor match {"protocol":"http:","hostname":"blahblahx.com","port":80,"defaultPort":80,"method":"GET","path":"/whatever/details","headers":{"user-agent":"Popsicle (https://github.com/serviejs/popsicle)","accept-encoding":"gzip, deflate, br","connection":"keep-alive"},"proto":"http","host":"blahblahx.com:80"}, body = "" +202ms
  nock.interceptor query matching skipped +1ms
  nock.scope matching http://blahblahx.com:80/whatever/details to GET http://blahblahx.com:80/whatever//details/: true +0ms
  nock.request_overrider interceptor identified, starting mocking +5ms
  nock.playback_interceptor response.rawHeaders: [] +0ms
  nock.playback_interceptor full response from callback result: [200,{"statusCode":200,"result":"Got /whatever/details successfully"}] +2ms
  nock.playback_interceptor response.rawHeaders after reply: [] +0ms
  nock.playback_interceptor transform the response body +1ms
  nock.playback_interceptor emitting response +2ms
  nock.playback_interceptor adding body to buffer list +2ms
Fetch complete
After doit
Before timeout 1
After timeout 1
Before timeout 2
  nock.playback_interceptor emitting response chunk +9ms
After timeout 2
Before timeout 3
  nock.playback_interceptor ending response stream +3ms
After timeout 3
Before timeout 4
After timeout 4
Before timeout 5
events.js:174
      throw er; // Unhandled 'error' event
      ^

Error: getaddrinfo ENOTFOUND blahblahx.com blahblahx.com:80
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:56:26)
Emitted 'error' event at:
    at emitErrorNT (internal/streams/destroy.js:91:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:59:3)
    at process._tickCallback (internal/process/next_tick.js:63:19)

NOTE1 - the number of timeout loops varies.
NOTE2 - There are two nock.playback_interceptor debug lines output AFTER the fetch is complete. This could be async debugging? Or is it nock returning too early? Or not awaiting a promise?
NOTE3 - the two late debug lines don't always happen - if the DNS failure happens quickly then it fails immediately after "Before timeout 1".

Is this a popsicle problem? Or a nock problem?
Versions

Software	Version(s)
Nock	12.0.3 (also on 11.x.x)
Popsicle	12.0.5 (latest)
Node	10.20.1
TypeScript	N/A

[KrayzeeKev]

And another one:
I've got a simple nock on an OATH endpoint which completes fine:

  nock.interceptor match {"protocol":"http:","hostname":"validhostname.com","port":80,"defaultPort":80,"method":"POST","path":"/v2/oauth/token","headers":{"accept":"application/json, application/x-www-form-urlencoded","content-type":"application/x-www-form-urlencoded","authorization":"Basic XXXXXXXX","content-length":"36","user-agent":"Popsicle (https://github.com/serviejs/popsicle)","accept-encoding":"gzip, deflate, br","connection":"keep-alive"},"proto":"http","host":"validhostname.com:80"}, body = "scope=&grant_type=client_credentials" +37ms
  nock.interceptor query matching skipped +0ms
  nock.scope matching http://validhostname.com:80/v2/oauth/token to POST http://validhostname.com:80//token/: true +38ms
  nock.request_overrider interceptor identified, starting mocking +1ms

And then, after several more calls are completed, we get this error thrown:

     Uncaught Error: connect ECONNREFUSED 10.1.2.3:80
      at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1107:14)

I have masked hostnames and IP addresses but the IP address in question is what validhostname.com resolves to in our environment. It's just not accepting connections right now. Which is one reason we're nocking it!

It would appear these are the same problem - this is just a case where the hostname resolves, so it moves on to connecting whereas the one in the OP is one that doesn't resolve. Either way, it seems nock isn't stopping popsicle from trying to do everything itself. And we use .persist() everywhere so it's not a second call not being nocked.

[mastermatt]

@KrayzeeKev thanks for the ticket. I haven't used Popsicle before and I think you're the first to bring up this issue.

Looking at the debug output, Nock seems to be successfully intercepting the requests and returning your desired fake responses.
The two nock.playback_interceptor logs that happen after Fetch complete seems to be because Popsicle is logging the Fetch complete on the response event from the request. So the whole request/response flow isn't actually complete at that point, only the response headers have shown up, but the response body still needs to stream in.
That being said, I don't know why a ENOTFOUND would happen if Nock is intercepting the call, there shouldn't be a DNS lookup happening from Node's stdlib at that point. So I'm curious is Popsicle is doing it directly for some reason.

Thanks for the RunKit. The fact that I can swap out popsicle.fetch with got or request-promise and everything is fine is a heavy indication that Popsicle is doing something fancy.
We might need someone familiar with the internals of Popsicle and/or someone who wants to walk through the flow in a debugger to answer this one.

Minor call out; you shouldn't be putting any of the path in the string for the first arg to nock.
nock('http://badserver.com/whatever') in this case "whatever" is never matched against because only the origin is used (there is a WIP PR to throw an error instead of being silent). In your example, this isn't an issue because you're using a regex in the verb method .get(/details/) so it happens to match away.

[KrayzeeKev]

Thanks Matt - I've delved into the popsicle stuff quite a bit but it very quickly becomes so abstracted that it's very difficult to follow. But it is on my list. Anybody else who might want to try will have our eternal gratitude. We don't use popsicle directly. We use it via client-oauth2 so we don't have a choice in the matter. I'd happily replace it with Axios or got (just working through eliminating request because it's dead and has security holes). But that's not something we can control.

Thanks for the call out about the first arg. I'll do a sweep of our tests and refactor them a bit and inform the team.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. We try to do our best, but nock is maintained by volunteers and there is only so much we can do at a time. Thank you for your contributions.

[MichaelFroelich]

Is there any movement on this?

[paulmelnikow]

Would suggest posting in popsicle :)