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

Inconsistent timeout events #456

Open
Tracked by #2517
mikicho opened this issue Sep 29, 2023 · 1 comment
Open
Tracked by #2517

Inconsistent timeout events #456

mikicho opened this issue Sep 29, 2023 · 1 comment

Comments

@mikicho
Copy link
Contributor

mikicho commented Sep 29, 2023

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
Copy link
Contributor Author

mikicho commented Sep 29, 2023

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)
  })

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants