mswjs / interceptors

Low-level network interception library.
https://npm.im/@mswjs/interceptors
MIT License
535 stars 120 forks source link

Inconsistent timeout events #456

Closed mikicho closed 1 month ago

mikicho commented 11 months ago

I couldn't create a consistent example to reproduce the issue, but sometimes (once to 2-3 runs) the code fails to emit a timeout event when using an invalid URL (e.g. example.test). However, it emits the event every time when using nowhere.com.

It reproduces only after at least one request prior to the request with the timeout.

My best guess is that something within Node aborts the request with ENOTFOUND before it checks the timeout.

const { ClientRequestInterceptor } = require('@mswjs/interceptors/ClientRequest')
const http = require('http');

const interceptor = new ClientRequestInterceptor({
  name: 'my-interceptor',
})
interceptor.apply();
interceptor.on('request', async ({ request }) => {
  await new Promise(r => setTimeout(r, 1000));
  request.respondWith(new Response('hello'))
});

http.get('http://example.text/', { timeout: 10 }, res => {
  res.on('data', () => { })
  res.on('end', () => {
    console.log(1)
    http.get('http://example.text/', { timeout: 10 }, res => {
      res.on('data', () => { })
      res.on('end', () => {
        console.log(1)
      })
    })
      .on('timeout', () => console.log('timeout'))
      .on('error', e => {
        console.log(e)
      })
  })
})
  .on('timeout', () => console.log('timeout'))
  .on('error', e => {
    console.log(e)
  })

image

logs:

15:27:50:202 [http] constructing the interceptor...
15:27:50:219 [http:apply] applying the interceptor...
15:27:50:219 [http] retrieved global instance: undefined
15:27:50:219 [http:apply] no running instance found, setting up a new instance...
15:27:50:220 [http:setup] native "http" module patched!
15:27:50:220 [http:setup] native "https" module patched!
15:27:50:220 [http] set global instance! http
15:27:50:220 [http:on] adding "request" event listener:
15:27:50:221 [http normalizeClientRequestArgs] arguments ["http://example.text/",null]
15:27:50:221 [http normalizeClientRequestArgs] using default protocol: http:
15:27:50:221 [http normalizeClientRequestArgs] first argument is a location string: http://example.text/
15:27:50:221 [http normalizeClientRequestArgs] created a url: "http://example.text/"
15:27:50:222 [http normalizeClientRequestArgs] request options from url: {"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/"}
15:27:50:222 [http normalizeClientRequestArgs] request options not provided, deriving from the url "http://example.text/"
15:27:50:222 [http normalizeClientRequestArgs] resolved request options: {"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/"}
15:27:50:222 [http normalizeClientRequestArgs] resolved fallback agent: {"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":false,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0}
15:27:50:222 [http normalizeClientRequestArgs] has no default agent, setting the default agent for "http:"
15:27:50:222 [http normalizeClientRequestArgs] successfully resolved url: http://example.text/
15:27:50:223 [http normalizeClientRequestArgs] successfully resolved options: {"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/","agent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":false,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0},"_defaultAgent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"keepAlive":true,"scheduling":"lifo","timeout":5000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0}}
15:27:50:223 [http normalizeClientRequestArgs] successfully resolved callback: res => {
  res.on('data', () => { })
  res.on('end', () => {
    console.log(1)
    http.get('http://example.text/', { timeout: 10 }, res => {
      res.on('data', () => { })
      res.on('end', () => {
        console.log(1)
      })
    })
      .on('timeout', () => console.log('timeout'))
      .on('error', e => {
        console.log(e)
      })
  })
}
15:27:50:228 [http:request GET http://example.text/] constructing ClientRequest using options: {"url":"http://example.text/","requestOptions":{"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/","agent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"noDelay":true,"path":null},"requests":{},"sockets":{"example.text:80:":[{"connecting":true,"_hadError":false,"_parent":null,"_host":"example.text","_closeAfterHandlingError":false,"_readableState":{"objectMode":false,"highWaterMark":16384,"buffer":{"head":null,"tail":null,"length":0},"length":0,"pipes":[],"flowing":null,"ended":false,"endEmitted":false,"reading":false,"constructed":true,"sync":true,"needReadable":false,"emittedReadable":false,"readableListening":false,"resumeScheduled":false,"errorEmitted":false,"emitClose":false,"autoDestroy":true,"destroyed":false,"errored":null,"closed":false,"closeEmitted":false,"defaultEncoding":"utf8","awaitDrainWriters":null,"multiAwaitDrain":false,"readingMore":false,"dataEmitted":false,"decoder":null,"encoding":null},"_events":{},"_eventsCount":6,"_writableState":{"objectMode":false,"highWaterMark":16384,"finalCalled":false,"needDrain":false,"ending":false,"ended":false,"finished":false,"destroyed":false,"decodeStrings":false,"defaultEncoding":"utf8","length":0,"writing":false,"corked":0,"sync":true,"bufferProcessing":false,"writecb":null,"writelen":0,"afterWriteTickInfo":null,"buffered":[],"bufferedIndex":0,"allBuffers":true,"allNoop":true,"pendingcb":0,"constructed":true,"prefinished":false,"errorEmitted":false,"emitClose":false,"autoDestroy":true,"errored":null,"closed":false,"closeEmitted":false},"allowHalfOpen":false,"_sockname":null,"_pendingData":null,"_pendingEncoding":"","server":null,"_server":null}]},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":false,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":1},"_defaultAgent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"keepAlive":true,"scheduling":"lifo","timeout":5000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0}}}
15:27:50:229 [http:request GET http://example.text/] end []
15:27:50:229 [utils getUrlByRequestOptions] arguments []
15:27:50:230 [utils getUrlByRequestOptions] normalized args [null,null,null]
15:27:50:230 [http:request GET http://example.text/] normalized arguments: {"chunk":null,"encoding":null,"callback":null}
15:27:50:245 [http:request GET http://example.text/] emitting the "request" event for 2 listener(s)...
15:27:50:248 [http:request GET http://example.text/] emit: socket
15:27:50:250 [http:request GET http://example.text/] emit: error
15:27:50:250 [http:request GET http://example.text/] error:
 {"errno":-3008,"code":"ENOTFOUND","syscall":"getaddrinfo","hostname":"example.text"}
15:27:50:251 [http:request GET http://example.text/] captured the first error: {"errno":-3008,"code":"ENOTFOUND","syscall":"getaddrinfo","hostname":"example.text"}
15:27:50:252 [http:request GET http://example.text/] emit: close
15:27:51:254 [http:request GET http://example.text/] all "request" listeners done!
15:27:51:255 [http:request GET http://example.text/] event.respondWith called with: {}
15:27:51:256 [http:request GET http://example.text/] the listeners promise awaited!
15:27:51:256 [http:request GET http://example.text/] received mocked response: 200
15:27:51:264 [http:request GET http://example.text/] responding with a mocked response... {}
15:27:51:265 [http:request GET http://example.text/] emit: finish
15:27:51:265 [http:request GET http://example.text/] mocked response headers ready: {}
15:27:51:266 [http:request GET http://example.text/] emit: response
15:27:51:266 [http:request GET http://example.text/] found "response" event, cloning the response...
15:27:51:269 [http:request GET http://example.text/] emit: response-internal
15:27:51:269 [http:request GET http://example.text/] response successfully cloned, emitting "response" event...
15:27:51:270 [http:request GET http://example.text/] 200  (MOCKED)
15:27:51:270 [http:request GET http://example.text/] emitting the custom "response" event...
15:27:51:270 [http:request GET http://example.text/] request (mock) is completed
15:27:51:276 [http:request GET http://example.text/] finished response stream!
15:27:51:277 [http:request GET http://example.text/] finalizing response...
15:27:51:278 [http:request GET http://example.text/] request complete!
1
15:27:51:279 [http normalizeClientRequestArgs] arguments ["http://example.text/",{"timeout":10},null]
15:27:51:280 [http normalizeClientRequestArgs] using default protocol: http:
15:27:51:280 [http normalizeClientRequestArgs] first argument is a location string: http://example.text/
15:27:51:280 [http normalizeClientRequestArgs] created a url: "http://example.text/"
15:27:51:280 [http normalizeClientRequestArgs] request options from url: {"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/"}
15:27:51:280 [http normalizeClientRequestArgs] has custom RequestOptions! {"timeout":10}
15:27:51:280 [http normalizeClientRequestArgs] derived RequestOptions from the URL: {"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/"}
15:27:51:281 [http normalizeClientRequestArgs] cloning RequestOptions...
15:27:51:281 [cloneObject] cloning object: {"timeout":10}
15:27:51:281 [cloneObject] analyzing key-value pair: timeout 10
15:27:51:281 [cloneObject] is plain object? 10
15:27:51:281 [cloneObject] checking the object constructor: Number
15:27:51:281 [cloneObject] is plain object? {"timeout":10}
15:27:51:281 [cloneObject] checking the object constructor: Object
15:27:51:281 [http normalizeClientRequestArgs] successfully cloned RequestOptions! {"timeout":10}
15:27:51:281 [http normalizeClientRequestArgs] resolved request options: {"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/","timeout":10}
15:27:51:281 [http normalizeClientRequestArgs] resolved fallback agent: {"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":false,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0}
15:27:51:282 [http normalizeClientRequestArgs] has no default agent, setting the default agent for "http:"
15:27:51:282 [http normalizeClientRequestArgs] successfully resolved url: http://example.text/
15:27:51:282 [http normalizeClientRequestArgs] successfully resolved options: {"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/","timeout":10,"agent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":false,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0},"_defaultAgent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"keepAlive":true,"scheduling":"lifo","timeout":5000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0}}
15:27:51:282 [http normalizeClientRequestArgs] successfully resolved callback: res => {
      res.on('data', () => { })
      res.on('end', () => {
        console.log(1)
      })
    }
15:27:51:283 [http:request GET http://example.text/] constructing ClientRequest using options: {"url":"http://example.text/","requestOptions":{"method":"GET","protocol":"http:","hostname":"example.text","host":"example.text","path":"/","timeout":10,"agent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"noDelay":true,"path":null},"requests":{},"sockets":{"example.text:80:":[{"connecting":true,"_hadError":false,"_parent":null,"_host":"example.text","_closeAfterHandlingError":false,"_readableState":{"objectMode":false,"highWaterMark":16384,"buffer":{"head":null,"tail":null,"length":0},"length":0,"pipes":[],"flowing":null,"ended":false,"endEmitted":false,"reading":false,"constructed":true,"sync":true,"needReadable":false,"emittedReadable":false,"readableListening":false,"resumeScheduled":false,"errorEmitted":false,"emitClose":false,"autoDestroy":true,"destroyed":false,"errored":null,"closed":false,"closeEmitted":false,"defaultEncoding":"utf8","awaitDrainWriters":null,"multiAwaitDrain":false,"readingMore":false,"dataEmitted":false,"decoder":null,"encoding":null},"_events":{},"_eventsCount":6,"_writableState":{"objectMode":false,"highWaterMark":16384,"finalCalled":false,"needDrain":false,"ending":false,"ended":false,"finished":false,"destroyed":false,"decodeStrings":false,"defaultEncoding":"utf8","length":0,"writing":false,"corked":0,"sync":true,"bufferProcessing":false,"writecb":null,"writelen":0,"afterWriteTickInfo":null,"buffered":[],"bufferedIndex":0,"allBuffers":true,"allNoop":true,"pendingcb":0,"constructed":true,"prefinished":false,"errorEmitted":false,"emitClose":false,"autoDestroy":true,"errored":null,"closed":false,"closeEmitted":false},"allowHalfOpen":false,"_sockname":null,"_pendingData":null,"_pendingEncoding":"","server":null,"_server":null,"timeout":10}]},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":false,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":1},"_defaultAgent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"keepAlive":true,"scheduling":"lifo","timeout":5000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0}}}
15:27:51:284 [http:request GET http://example.text/] end []
15:27:51:284 [utils getUrlByRequestOptions] arguments []
15:27:51:284 [utils getUrlByRequestOptions] normalized args [null,null,null]
15:27:51:284 [http:request GET http://example.text/] normalized arguments: {"chunk":null,"encoding":null,"callback":null}
15:27:51:285 [http:request GET http://example.text/] emitting the "request" event for 2 listener(s)...
15:27:51:286 [http:request GET http://example.text/] emit: socket
15:27:51:291 [http:request GET http://example.text/] emit: error
15:27:51:291 [http:request GET http://example.text/] error:
 {"errno":-3008,"code":"ENOTFOUND","syscall":"getaddrinfo","hostname":"example.text"}
15:27:51:291 [http:request GET http://example.text/] captured the first error: {"errno":-3008,"code":"ENOTFOUND","syscall":"getaddrinfo","hostname":"example.text"}
15:27:51:291 [http:request GET http://example.text/] emit: close
15:27:52:288 [http:request GET http://example.text/] all "request" listeners done!
15:27:52:288 [http:request GET http://example.text/] event.respondWith called with: {}
15:27:52:289 [http:request GET http://example.text/] the listeners promise awaited!
15:27:52:289 [http:request GET http://example.text/] received mocked response: 200
15:27:52:292 [http:request GET http://example.text/] responding with a mocked response... {}
15:27:52:293 [http:request GET http://example.text/] emit: finish
15:27:52:293 [http:request GET http://example.text/] mocked response headers ready: {}
15:27:52:294 [http:request GET http://example.text/] emit: response
15:27:52:294 [http:request GET http://example.text/] found "response" event, cloning the response...
15:27:52:295 [http:request GET http://example.text/] emit: response-internal
15:27:52:296 [http:request GET http://example.text/] response successfully cloned, emitting "response" event...
15:27:52:296 [http:request GET http://example.text/] 200  (MOCKED)
15:27:52:296 [http:request GET http://example.text/] emitting the custom "response" event...
15:27:52:297 [http:request GET http://example.text/] request (mock) is completed
15:27:52:299 [http:request GET http://example.text/] finished response stream!
15:27:52:299 [http:request GET http://example.text/] finalizing response...
15:27:52:300 [http:request GET http://example.text/] request complete!
1
mikicho commented 11 months ago

I discovered that by wrapping the second call with setImmediate, the likelihood of missing the timeout event significantly increases.

const { ClientRequestInterceptor } = require('@mswjs/interceptors/ClientRequest')
const http = require('http');

const interceptor = new ClientRequestInterceptor({
  name: 'my-interceptor',
})
interceptor.apply();
interceptor.on('request', async ({ request }) => {
  await new Promise(r => setTimeout(r, 1000));
  request.respondWith(new Response('hello'))
});

http.get('http://example.text/', res => {
  res.on('data', () => { })
  res.on('end', () => {
    console.log(1)
    setImmediate(() => {
      http.get('http://example.text/', { timeout: 10 }, res => {
        res.on('data', () => { })
        res.on('end', () => {
          console.log(1)
        })
      })
        .on('timeout', () => console.log('timeout'))
        .on('error', e => {
          console.log(e)
        })
    })
  })
})
  .on('timeout', () => console.log('timeout'))
  .on('error', e => {
    console.log(e)
  })
mikicho commented 1 month ago

Our tests are no longer inconsistent. I will reopen if found otherwise.