got 🚀 - Intermittent uncaught errors

Could you make it reproducible?
What's the unhandled error? I'm not sure but did you mean that the unhandled error is the timed out error?

I'm gonna look at it.

szmarczak on 10 Oct 2018

It happens under high load, which would make sense for a timeout: it doesn't finish whatever it was doing in time.
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.

timdp on 10 Oct 2018

👍1

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)

aghuddleston on 11 Oct 2018

👍1

It seems like the emitter throws an error twice:

https://github.com/sindresorhus/got/blob/8d2e91171509bc2aec71c4483978cfd421ebcf1d/source/as-promise.js#L95

Can you try adding emitter.on('error', e => console.log('on each error:', e)); and try again?

szmarczak on 11 Oct 2018

Added the code but haven't been able to duplicate yet.

aghuddleston on 11 Oct 2018

I haven't been able to isolate it as it doesn't happen too often, but in our server logs, I can see that we get uncaught TimeoutErrors on both 'lookup' and 'response'. It's possible that they would also occur for the other configurable timeouts but we never run into those.

timdp on 13 Oct 2018

I did look at the code when I originally reported this and my assessment was also that it would have to be multiple 'error' events on the same EventEmitter. Perhaps it's worth adding code that generically protects against that on every emitter created. Once the object enters the error state, it should really just stop doing things altogether.

timdp on 13 Oct 2018

I've looked at the timed-out file and it seems there are some holes.

https://github.com/sindresorhus/got/blob/8d2e91171509bc2aec71c4483978cfd421ebcf1d/source/timed-out.js#L47-L49

~1. There's missing request.setTimeout(0);.~ (nah Node handles it itself)

timeoutHandler may invoke two errors: socket hang up & the timeout one.

Also, we shouldn't proxy errors. It just gets worse when it's time to read them.

@aghuddleston you're case is more complicated. I'm looking into it.

szmarczak on 15 Oct 2018

@aghuddleston If you could tell the previous error before that one, it'd help a lot.

szmarczak on 15 Oct 2018

we get uncaught TimeoutErrors on both 'lookup' [...]

On lookup? Impossible to happen. Full stack trace please?

szmarczak on 15 Oct 2018

It's possible that they would also occur for the other configurable timeouts but we never run into those.

Nope, it's not.

szmarczak on 15 Oct 2018

@aghuddleston request.once.error gets called so this is the first time when the HTTP lib thrown an error. I guess you set timeouts, didn't you?

szmarczak on 15 Oct 2018

Once the object enters the error state, it should really just stop doing things altogether.

Ignoring further errors should be our last option if we don't come up with anything :)

szmarczak on 15 Oct 2018

Once the object enters the error state, it should really just stop doing things altogether.

Ignoring further errors should be our last option if we don't come up with anything :)

My point was more that there should only be a single error event per EventEmitter, at which point its internal state is updated to reflect that there was an error and that there's no coming back from it. To be frank, I don't know what the policy is around that in Node's internal APIs, but promises and observables both have this concept of a final, deterministic error state and it makes things a lot clearer.

timdp on 15 Oct 2018

we get uncaught TimeoutErrors on both 'lookup' [...]

On lookup? Impossible to happen. Full stack trace please?

I'm pretty sure we saw the log lines from my original message in our logs but with lookup instead of response. I might be confusing uncaught errors with warnings from failed requests though.

We've since started using DNS caching and switched to a different DNS provider to decrease the likelihood of running into DNS-related issues, because Node's internal implementation doesn't handle errors very well. We haven't seen the errors anymore since then, but given that we didn't upgrade got either, I would expect them to reoccur if we reverted our patch.

We don't log async stack traces, so all I have is the Immediate.timeoutHandler one. However, the message is clearly from got. Additionally, we did see it in the debugger at one point, and all signs pointed to timed-out.js there as well.

You should be able to reproduce it by using a slow or invalid DNS server. That's how I started noticing these errors in the first place.

timdp on 15 Oct 2018

Actually, scratch that: I can confirm that I really do see several of these in our logs:

Uncaught error: TimeoutError: Timeout awaiting 'lookup' for 500ms 
  at Immediate.timeoutHandler (node_modules/got/source/timed-out.js:39:25)

These are from before the aforementioned DNS patch to our own code, but as explained above, the issue must still exist with got.

timdp on 15 Oct 2018

My point was more that there should only be a single error event per EventEmitter

That's right.

Actually, scratch that: I can confirm that I really do see several of these in our logs

Then I believe it's the fault of timed-out, because I've checked hundred times and it's the only way.

You should be able to reproduce it by using a slow or invalid DNS server. That's how I started noticing these errors in the first place.

Thanks for the advice. I'll give it a try.

szmarczak on 15 Oct 2018

I found a bug where using cookies and timeouts it may double-throw.

@timdp Were you using cookies?

szmarczak on 15 Oct 2018

Yes, I set timeouts. And, unfortunately, I have _not_ been able to duplicate once adding the code. I'm using this as the call though, and I'll keep trying to recreate.

    const res = await got(url, { method: 'HEAD', timeout: 3000, retries: 0, throwHttpErrors: false })

aghuddleston on 15 Oct 2018

Our system never sets any cookies on the request. It might get some back on the response though (which we ignore).

The error presumably occurred under high load (due to the unreliable DNS) so it almost has to be latency-induced.

timdp on 15 Oct 2018

working on a fix + code cleanup: https://github.com/sindresorhus/got/compare/master...szmarczak:unhandled-fix

szmarczak on 15 Oct 2018

fixed!

szmarczak on 16 Oct 2018

Unfortunately, with v9.3.0, I'm getting this error even more:

TimeoutError: Timeout awaiting 'connect' for 500ms 
  at Immediate.timeoutHandler (node_modules/got/source/utils/timed-out.js:50:25)

timdp on 2 Nov 2018

@sindresorhus @szmarczak Should I create a new issue or do you want to reopen this one?

timdp on 2 Nov 2018

You can reopen this one. I checked the code hundred times, it's hard to believe it's Got's failure. If that's the full stack trace, it looks like the request has no error event attached, which isn't true, so there are missing some functions [in the stacktrace] that the error is passed by. Is it the full stack trace?

What's your Node and NPM version?

Otherwise, if it isn't reproducible, I won't be able to help. If you could reproduce it somehow, that would be great :)

Anyway, if it's really an uncaught error, you could make a handler for it and log the errors before (place it right after request.once('error, ...) in request-as-event-emitter. It would help very much.

const errors = [];

request.on('error', error => {
    errors.push(error);
    if (error instanceof timedOut.TimeoutError && error.message === `Timeout awaiting 'connect' for 500ms`) {
        console.log('verify uncaught error', errors);
    }
});

Also, what are your got options?

szmarczak on 2 Nov 2018

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.

timdp on 4 Nov 2018

👍1

Ah, I see I originally reported this about response. I do seem to recall getting connect failures as well. Maybe my example code never gets to response though.

timdp on 4 Nov 2018

As far as I know, that's all you get with errors thrown from timers, at least by default?

Right. Then pardon me, let's blame Node for that.

I've also added longjohn to obtain the async stack trace.

Awesome! It helps a lot :)

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.

You're right. Good spot! 👍

But then, that should still reject the promise rather than producing an uncaught error.

Yup.

Maybe my example code never gets to response though.

It doesn't matter. It should caught it, and it doesn't.

On Windows 10 (Node 10) I get:

uncaught error: { TimeoutError: Timeout awaiting 'connect' for 1ms
    at Immediate.timeoutHandler (C:\Users\Szymon Marczak\Desktop\got-master\source\utils\timed-out.js:50:25)
    at runCallback (timers.js:694:11)
    at tryOnImmediate (timers.js:664:5)
    at processImmediate (timers.js:646:5) name: 'TimeoutError', code: 'ETIMEDOUT', event: 'connect' }

EDIT: The previous stacktrace was on my local [outdated] Got. I had to replace require('got') with require('.'), as I am working in the Got directory.

szmarczak on 4 Nov 2018

It's very weird. I logged request.once('error', ...) and this happens:

request.once.error { TimeoutError: Timeout awaiting 'request' for 1ms
    at Immediate.timeoutHandler [as _onImmediate] (C:\Users\Szymon Marczak\Desktop\got-master\source\utils\timed-out.js:50:25)
    at runCallback (timers.js:694:11)
    at tryOnImmediate (timers.js:664:5)
    at processImmediate (timers.js:646:5) name: 'TimeoutError', code: 'ETIMEDOUT', event: 'request' }

uncaught error: { TimeoutError: Timeout awaiting 'connect' for 1ms
    at Immediate.timeoutHandler (C:\Users\Szymon Marczak\Desktop\got-master\source\utils\timed-out.js:50:25)
    at runCallback (timers.js:694:11)
    at tryOnImmediate (timers.js:664:5)
    at processImmediate (timers.js:646:5) name: 'TimeoutError', code: 'ETIMEDOUT', event: 'connect' }

It means that it doesn't prevent new timeouts. So, what happens:

A request has been made.
Timeout: request 1ms. Clears all the current timed-out timers.
Lookup gets called with an error. It creates a new timer for the connect event, but it shouldn't. Another timed-out error had been thrown before.

I'll make a PR which will prevent further timeouts in the future.

szmarczak on 4 Nov 2018

@szmarczak We're making progress, but this is still not fully resolved in v9.3.2:

Uncaught error: TimeoutError: Timeout awaiting 'socket' for 1000ms 
  at timeoutHandler (node_modules/got/source/utils/timed-out.js:63:25) 
  at ClientRequest.request.setTimeout (node_modules/got/source/utils/timed-out.js:86:4) 
  at ClientRequest.origin.emit.args [as emit] (node_modules/@szmarczak/http-timer/source/index.js:36:11)

The server that encountered it was under heavy load, so the error isn't common. However, it's still an uncaught async exception rather than a promise rejection.

timdp on 9 Nov 2018

Hmm... That's even more weird. I'll check it now.

szmarczak on 9 Nov 2018

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.

timdp on 9 Nov 2018

👍1

Good spot! Fixed. I'll just send a PR right now.

szmarczak on 13 Nov 2018

@szmarczak For what it's worth, with v9.6.0, there was/is indeed an issue with cookies as well. Since I originally reported this, we've actually added a cookie jar, and if that one throws on setCookie (e.g. because of a domain mismatch), it can cause a double error in got, followed by an unhandled rejection.

I don't think that this is the same issue that I originally reported but it's worth investigating whether it still happens with v11.

As a workaround, we've made our cookie jar silence errors.

timdp on 4 Dec 2020

Got: Intermittent uncaught errors

All 34 comments

Related issues