got: Intermittent uncaught errors

Looks like it’s because the socket timeout handler doesn’t call addTimeout()? The timeoutHandler that it calls doesn’t guarantee that it will emit an error at most once.

Yes, it’s the full stack trace. As far as I know, that’s all you get with errors thrown from timers, at least by default?

I think this is related to the retry option. I can reproduce it by passing in a hostname that has never been looked up before, setting all timeouts to 1 ms, and setting retry to 1:

const got = require('got')

process.once('uncaughtException', err => {
  console.error('uncaught error:', err)
  process.exit(1)
})

process.once('unhandledRejection', err => {
  console.error('unhandled rejection:', err)
  process.exit(1)
})

const url = `http://${Date.now()}.dev/`

const options = {
  retry: 1,
  timeout: {
    lookup: 1,
    connect: 1,
    secureConnect: 1,
    socket: 1,
    response: 1,
    send: 1,
    request: 1
  }
}

;(async () => {
  try {
    await got(url, options)
  } catch (err) {
    console.error('caught:', err)
  }
})()

With got v9.3.1 on Node v8.12.0, that logs:

uncaught error: { TimeoutError: Timeout awaiting 'connect' for 1ms
    at Immediate.timeoutHandler [as _onImmediate] (node_modules/got/source/utils/timed-out.js:50:25)
    at runCallback (timers.js:814:20)
    at tryOnImmediate (timers.js:768:5)
    at processImmediate [as _immediateCallback] (timers.js:745:5) name: 'TimeoutError', code: 'ETIMEDOUT', event: 'connect' }

I get the same behavior with Node 10 and 11.

Strange that it times out on connect as well. That would mean that the DNS lookup happened, failed (the hostname is invalid), and the timeout logic for the TCP socket still kicked in. Perhaps that’s part of the problem?

I’ve also added longjohn to obtain the async stack trace. That gives me:

uncaught error: { TimeoutError: Timeout awaiting 'connect' for 1ms
    at Immediate.timeoutHandler (node_modules/got/source/utils/timed-out.js:50:25)
    at runCallback (timers.js:814:20)
    at tryOnImmediate (timers.js:768:5)
    at processImmediate [as _immediateCallback] (timers.js:745:5)
---------------------------------------------
    at Timeout.setTimeout (node_modules/got/source/utils/timed-out.js:21:15)
    at ontimeout (timers.js:498:11)
    at Timer.unrefdHandle (timers.js:611:5)
---------------------------------------------
    at addTimeout (node_modules/got/source/utils/timed-out.js:20:18)
    at timeConnect (node_modules/got/source/utils/timed-out.js:93:28)
    at Socket.socket.once (node_modules/got/source/utils/timed-out.js:102:30)
    at emitMany (events.js:152:20)
    at Socket.emit (events.js:224:7)
    at GetAddrInfoReqWrap.emitLookup [as callback] (net.js:1092:12)
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:67:17)
---------------------------------------------
    at Socket.Readable.on (_stream_readable.js:772:35)
    at Socket.once (events.js:341:8)
    at ClientRequest.request.once.socket (node_modules/got/source/utils/timed-out.js:101:13)
    at emitOne (events.js:121:20)
    at ClientRequest.emit (events.js:211:7)
    at ClientRequest.origin.emit.args [as emit] (node_modules/@szmarczak/http-timer/source/index.js:36:11)
    at tickOnSocket (_http_client.js:653:7)
---------------------------------------------
    at ClientRequest.once (events.js:341:8)
    at module.exports (node_modules/got/source/utils/timed-out.js:89:11)
    at handleRequest (node_modules/got/source/request-as-event-emitter.js:176:5)
    at get (node_modules/got/source/request-as-event-emitter.js:219:5)
    at Immediate.setImmediate (node_modules/got/source/request-as-event-emitter.js:291:10)
    at <anonymous> name: 'TimeoutError', code: 'ETIMEDOUT', event: 'connect' }

In timed-out.js, shouldn’t you be checking the first argument of the lookup handler? It’s an Error if the lookup fails, so in that case, you’ll never get the connect event. But then, that should still reject the promise rather than producing an uncaught error.

I believe I’m seeing something similar. It’s also intermittent. Trace looks like this

events.js:165
      throw er; // Unhandled 'error' event
      ^

RequestError: Parse Error
    at ClientRequest.request.once.error (/Users/ahuddleston/dev/body-data-conversion/node_modules/got/source/request-as-event-emitter.js:173:14)
    at Object.onceWrapper (events.js:272:13)
    at ClientRequest.emit (events.js:185:15)
    at ClientRequest.origin.emit.args [as emit] (/Users/ahuddleston/dev/body-data-conversion/node_modules/@szmarczak/http-timer/source/index.js:36:11)
    at Socket.socketOnData (_http_client.js:451:9)
    at Socket.emit (events.js:180:13)
    at addChunk (_stream_readable.js:274:12)
    at readableAddChunk (_stream_readable.js:261:11)
    at Socket.Readable.push (_stream_readable.js:218:10)
    at TCP.onread (net.js:581:20)
Emitted 'error' event at:
    at emitter.emit.retried (/Users/ahuddleston/dev/body-data-conversion/node_modules/got/source/request-as-event-emitter.js:177:15)
    at EventEmitter.emitter.on (/Users/ahuddleston/dev/body-data-conversion/node_modules/got/source/request-as-event-emitter.js:210:3)
    at EventEmitter.emit (events.js:180:13)
    at ClientRequest.request.once.error (/Users/ahuddleston/dev/body-data-conversion/node_modules/got/source/request-as-event-emitter.js:175:13)
    at Object.onceWrapper (events.js:272:13)
    [... lines matching original stack trace ...]
    at addChunk (_stream_readable.js:274:12)

1. It happens under high load, which would make sense for a timeout: it doesn’t finish whatever it was doing in time.
2. The error is in my original message: there’s some EventEmitter that emits an error event and the argument of that is the TimeoutError that gets logged.