Storage: Unhandled ETIMEDOUT

[eknkc]

Hi,

I've been using the storage module exclusively with read/write stream interfaces on files. The issue is, the app occasionally has an unhandled error like this:

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

Error: connect ETIMEDOUT 74.125.202.128:443
    at Object.exports._errnoException (util.js:856:11)
    at exports._exceptionWithHostPort (util.js:879:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1063:14)

I'm absolutely certain that there are no missing callbacks on any calls and all stream instances have proper error handlers attached. Some of these timeout errors are being catched by error handlers and does not crash the process.

However, I can not find the source for the unhandled ones within our app. There are only 3 calls to stream creator functions and all of them has proper error handling.

Any ideas?

[stephenplusplus]

Can you narrow it down to a reproducible test case by any chance?

[eknkc]

I've been trying to find a way to reproduce it but I believe it depends on intermittent network issues and that's hard to debug.

Since all my trials came up empty I just created test instances where one has resumable: false on writables. One uses bucket.upload rather than creating streams and one uses https://github.com/juliangruber/multipipe since I got paranoid if I was doing something wrong myself. Gonna see if any / all of these report errors.

[stephenplusplus]

Looking forward to hearing what you come up with. I've tried to reproduce without success yet. Any code you can share that has lit up your terminal in the past will be helpful. I manipulated the write stream code to simulate a timeout error, and was able to see it throw without my handler, but I was able to catch it when I assigned one.

[eknkc]

Hi! Thanks for looking into it. I wanted to give it some time to make sure but none of my tries resulted in any improvement (and I did try a lot of stuff). This is the latest log:

Error: read ECONNRESET
    at exports._errnoException (util.js:856:11)
    at TLSWrap.onread (net.js:544:26)
cluster: worker 20 died
Listening to port 3000
events.js:141
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at exports._errnoException (util.js:856:11)
    at TLSWrap.onread (net.js:544:26)
cluster: worker 392 died
Listening to port 3000
events.js:141
      throw er; // Unhandled 'error' event
      ^

Error: connect ETIMEDOUT 74.125.202.128:443
    at Object.exports._errnoException (util.js:856:11)
    at exports._exceptionWithHostPort (util.js:879:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1063:14)
cluster: worker 403 died
Listening to port 3000

Not sure about ECONNRESET stuff but I've pinned the issue on gcloud due to the storage server IP on ETIMEDOUT error.

Just to make sure, I have written a barebones storage api client (https://gist.github.com/eknkc/20d05610ad05fb18bb03) and planning to switch to this one for a while to see if it resolves the issues completely. Then I'm planning to introduce gcloud back to different parts of the app to find the origin of the issue. Now that I think of it, maybe I could use node domains to pinpoint it..

Anyway, gonna let you know when I know more.

[eknkc]

Just a little more info:

Node 5.1.1
gcloud 0.25.1

This happens maybe once in a couple hundred requests. Tried brute forcing it but that did not result in reproducible errors.

Found some reports about keepalive agents causing unhandled econnreset errors on node 4+ but as far as I can tell, gcloud does not use a custom agent or forever: true option on request calls.

[stephenplusplus]

Thanks for all the details. So it's occurred from both read and write streams?

We recently set a lib-wide 60s timeout for all requests that hasn't been released yet. Also, I've made some changes to our request dispatcher as part of an upcoming PR: #989. Specifically, this file: https://github.com/stephenplusplus/gcloud-node/blob/spp--prediction/lib/common/util.js. Previously, we were passing write streams to retry-request, when they should have only been tried once. This changed some of the event handling on a global basis. Might be nothing, but given the scope of the change, thought it might be worth mentioning.

Sorry I'm not more helpful in this case. I haven't tried with 5.x yet, so I'll be trying more tomorrow.

[eknkc]

As far as I can tell, read streams did also cause some timeouts but they were handled properly by our error middleware:

  URL: /media/get/id-8fd7109d-dc96-4e97-b3af-63a70c1cd224/raw/s-qLCLyY8oIDNIj9cT3kwPggNZpDO.gif
  Error: connect ETIMEDOUT 74.125.202.84:443
      at Object.exports._errnoException (util.js:856:11)
      at exports._exceptionWithHostPort (util.js:879:20)
      at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1063:14)

This is completely fine as it would simply return http 500 to the request. It seems that the unhandled ones are coming from write streams. I'll check around the code base again and report you back about my findings. Thanks.

[cbraynor]

I'm seeing similar issues. I managed to create a simple reproducible case on createReadStream() using nock here: https://gist.github.com/drtriumph/6048bccb1afdc9f881e6

[cbraynor]

From running that script on Node 4.2.3, and then Node 0.12.9, the last time this gist worked as expected was v0.16.0 - something changed here in v0.17.0

[stephenplusplus]

Thanks for the gist, that was very helpful. Hopefully, I caught the bug here: googleapis/retry-request@fff8a73

You can re-install gcloud to pick it up in your projects. Let me know if it works!

[cbraynor]

Awesome, that appears to have fixed the problem for me at least

[stephenplusplus]

@eknkc I'm going to close this issue, but please re-open if you're still having issues. Thanks for helping us catch this.