Nodejs-storage: Storage: lots of "socket hang up" errors

[lukesneeringer]

_From @ovaris on September 21, 2017 8:31_

Environment details

• OS:
• Node.js version: 8.5.0
• npm version: 5.3.0
• google-cloud-node/storage version: 1.2.1

I have a utlity nodejs script that checks existence of few thousands of files in cloud storage.
I run script locally, so not in Cloud environment.
I'm executing those checks (bucket.file(fileName).exists()) in batch of 20, so not all checks are fired concurrently.
I'm seeing lots of these errors when trying to run script:

{ Error: socket hang up
    at TLSSocket.onHangUp (_tls_wrap.js:1140:19)
    at Object.onceWrapper (events.js:314:30)
    at emitNone (events.js:110:20)
    at TLSSocket.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:1059:12)
    at _combinedTickCallback (internal/process/next_tick.js:138:11)
    at process._tickCallback (internal/process/next_tick.js:180:9)
  code: 'ECONNRESET',
  path: null,
  host: 'accounts.google.com',
  port: 443,
  localAddress: undefined }

and these:

{ Error: read ECONNRESET
    at _errnoException (util.js:1026:11)
    at TLSWrap.onread (net.js:606:25) code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }

aaand these:

{ Error: socket hang up
    at createHangUpError (_http_client.js:345:15)
    at TLSSocket.socketOnEnd (_http_client.js:437:23)
    at emitNone (events.js:110:20)
    at TLSSocket.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:1059:12)
    at _combinedTickCallback (internal/process/next_tick.js:138:11)
    at process._tickCallback (internal/process/next_tick.js:180:9) code: 'ECONNRESET' }

I have added this fix (suggested here: https://github.com/GoogleCloudPlatform/google-cloud-node/issues/2254):

const gcs = storage();
//https://github.com/GoogleCloudPlatform/google-cloud-node/issues/2254
gcs.interceptors.push({
    request: function(reqOpts) {
        reqOpts.forever = false;
        return reqOpts
    }
});

I have tried to reduce the check batch size, but it didn't have any effect.

_Copied from original issue: GoogleCloudPlatform/google-cloud-node#2623_

[lukesneeringer]

_From @stephenplusplus on September 21, 2017 14:10_

Can you share a small gist or repo that I can use to try to reproduce?

[lukesneeringer]

_From @ovaris on September 21, 2017 14:57_

Here's gist, hopefully it makes sense: https://gist.github.com/ovaris/c30c492db06fbe73875ed71d00dcb547

[lukesneeringer]

_From @stephenplusplus on September 21, 2017 15:46_

It's a bit hard to go from that, since I can't tap into the firebase instance. Can you try to replicate the problem without any external dependencies?

[ovaris]

Here's simple test that replicates error, if I put 1000 times, it works, but with 3000 times it starts to fail:

import {chunk, times} from 'lodash';
import * as storage from '@google-cloud/storage';

const gcs = storage();
//https://github.com/GoogleCloudPlatform/google-cloud-node/issues/2254
gcs.interceptors.push({
    request: function(reqOpts) {
        reqOpts.forever = false;
        return reqOpts
    }
});

const bucket = gcs.bucket("xxx");


const checkFileExists = (fileName) =>
    bucket.file(fileName).exists()
        .then(([exists]) => exists || fileName)
        .catch((error) => {
            console.error('Error checking ', fileName);
            console.error(error);
            return `error: ${fileName}`;
        });


(async () => {
    const checkPromises = [];
    times(3000, () => checkPromises.push(checkFileExists(`xxx/1.png`)));

    const chunks = chunk(checkPromises, 20);
    let i = 1;
    let results = [];
    for (const chunk of chunks) {
        const chunkResults = await Promise.all(chunk);
        results = results.concat(chunkResults);
        i++;
    }
    const missing = results.filter((exists) => exists !== true);
    if (missing.length > 0) {
        console.log('Missing: \n');
        missing.forEach((file, i) => console.log(`${i}: ${file}`));
        process.exit(1);
    }
    console.log('YAY!');
    process.exit(0);
})();

[ovaris]

This is a stupid user error and can be closed. Of course code above will fire ALL requests at the same time

[ashleyhenderson]

ovaris, what code did you use to fix this issue? I'm having a similar problem where my code is firing 1000 database uploads at a time - hence the database returns socket hang up errors because of the excessive load

[stephenplusplus]

Glad to hear this was resolved!

[surjikal]

Getting some ESOCKETTIMEDOUT errors when using createWriteStream. This problem was also posted on stackoverflow:

https://stackoverflow.com/questions/47328578/getting-esockettimeout-econnreset-or-socket-hang-up-with-large-file-when-stream

I am opening at most 5 streams in parallel.

[stephenplusplus]

@surjikal could you try using the latest version (v1.5.2) and if the problem persists, please open a new issue with reproduction steps and I'll check it out.

[surjikal]

Cool will do, thanks.

[jeremymarc]

still getting this issue with the last version. Any workaround?

[danielrasmuson]

I can confirm I also occasionally receive this error with...

function uploadFile(path, fileContents) {
  const file = bucket.file(path);
  const stream = file.createWriteStream({});
  return new Promise((resolve, reject) => {
    stream.on('error', () => reject());
    stream.on('finish', () => resolve());
    stream.end(new Buffer(fileContents));
  });
}

Right now my work around it to just retry the request.

Interested if anyone else knows of a better workaround.

[Scarysize]

Here is the code producing the error:

const readline = require('readline');

const storage = new Storage({projectId: config.projectId});
const bucket = storage.bucket(config.bucketName);
const remoteFile = bucket.file('events.txt');

const lineReader = readline.createInterface(remoteFile.createReadStream());

lineReader.on('line', /* do stuff */);

The code runs on GCE:

• OS: Linux 4.9.0-8-amd64 SMP Debian 4.9.110-3+deb9u3 (2018-08-19) x86_64 GNU/Linux
• node: v8.11.4

It reliably times out after 60 seconds of streaming, only a single stream is opened at the same time.

Let me know if you need any further information.

[stephenplusplus]

@Scarysize is it an exceptionally large file?

[Scarysize]

990mb, I guess you could consider this exceptionally large.

[simllll]

I have a similar issue while writing to a stream.
Uncaught exception ESOCKETTIMEDOUT

What I do is streaming a database result into a csv on gloud storage with a writestream. The database has an async loop that writes to the result in parallel. (up to 150 writes at the same time, I was playing around with this number, it also happens with e.g. 5 concurrent writes).

[simllll]

I have resolved my issues by reading more about "backpressure" https://nodejs.org/en/docs/guides/backpressuring-in-streams/ ... I check for the write result of the upload now, and wait for a drain event before I continue. The upload is somehow way slower now, but it at least works.

Regards
Simon

[avishnyak]

Getting the same issue as @Scarysize when streaming a files from GCS using CreateReadStream.

The one difference is that we are using byte range parameters in the read stream so we are guaranteed that the amount of data downloaded is about 2mb.

return gcs.file(key).createReadStream({
  start,
  end,
})

We still encounter ESOCKETTIMEDOUT after 60 seconds on random requests. (Serving about 10 RPS)

[stephenplusplus]

I believe a fix has been found, (thanks, @zbjornson!), and a PR has been sent here: https://github.com/googleapis/nodejs-common/pull/268

[avishnyak]

We experience the issue with GET requests and the PR doesn't seem to address this case.

[stephenplusplus]

Thanks for pointing that out. I'll need to leave this one open for further investigation.

[stephenplusplus]

@Scarysize, I've tried again with your script, using a file I uploaded that is 990MB. I haven't been able to reproduce. The one obvious difference is I'm running locally, and you're on GCE. @avishnyak, are you running this in the cloud somewhere or locally? Also, any more details you think would make a difference, please share.

Thanks!

[micahwedemeyer]

I upgraded to @google-cloud/storage v2.2.0 and while I no longer see the ECONNRESET issue, I now get the following when writing files to Cloud Storage from Cloud Functions:

FetchError: network timeout at: https://www.googleapis.com/upload/storage/v1/b/my-bucket-name/o?uploadType=multipart&name=lookup_tmp%2Fdatafiles%2F20181031%2Fhit_data.tsv

It seems to happen 100% of the time, whereas the old ECONNRESET error was probably 50%. The files I'm writing are large'ish, around 2GB. I am reading a compressed .tar.gz file and writing out the individual entries to Cloud Storage.

Is there some way to change the timeout settings? Make it wait longer before timing out? Any other ideas? I'm glad that I can now see (I think?) the actual error, instead of the inscrutable ECONNRESET, but I'm not sure how to deal with the fact that it occurs 100% of the time, making my previous "retry until it finally works" strategy worthless.

[zbjornson]

@micahwedemeyer @stephenplusplus yeah, I'm still seeing two issues on master (3e5a196) with all the latest dependencies:

1. Streamed uploads are still being retried. These were supposed to be disabled by the earlier fix. See more info below.

2. node-fetch's default 60 second timeout seems to mean that the entire request and response must be completed within 60 seconds. See https://github.com/bitinn/node-fetch/issues/446. I think this is a regression introduced by c2c1382a2d11d271c5ef8b58c263d72db88ca4d8 in [email protected].

Repro:

const {Storage} = require("."); // nodejs-storage
const client = new Storage({projectId: "myproject"});
const {Readable} = require("stream");
const ws = client.bucket("zb-dev").file("test").createWriteStream({resumable: false});
const body = new Readable({
    read() {
        console.log(new Date(), "read request");
        setTimeout(() => { console.log(new Date(), "pushing"); this.push("info"); }, 15000);
    }
});
ws.on("error", console.error);
body.pipe(ws);

And add logging statements to node_modules/node-fetch/lib/index.js where the timeout is set and cleared (around line 1336):

2018-11-02T02:08:44.817Z 'read request'
2018-11-02T02:08:59.821Z 'pushing'
2018-11-02T02:09:00.014Z 'Setting timeout for' 60000
2018-11-02T02:10:00.015Z 'timeout' // attempt #1 timed out
2018-11-02T02:10:00.815Z 'Setting timeout for' 60000 // retrying
...
2018-11-02T02:11:00.818Z 'timeout' // attempt #2 timed out
2018-11-02T02:11:01.600Z 'Setting timeout for' 60000 // retrying
...
2018-11-02T02:12:01.602Z 'timeout' // attempt #3 timed out
 FetchError: network timeout // 3 strikes

[Scarysize]

@Scarysize, I've tried again with your script, using a file I uploaded that is 990MB. I haven't been able to reproduce.

Thanks for the update. I'll find some time to test this on GCE 👌

[stephenplusplus]

@fhinkel -- now that we are using teeny-request & node-fetch, would you mind taking a look to see what might be going on here?

[simllll]

Having the same timeout issue since I have upgraded the library to v2.2.0 . Downgrading to v2.1.0 works as a workaround

[micahwedemeyer]

Any update here?

[robotnealan]

Any update here?

[simllll]

This bug is very annoying, still not possible with latest release to upload a bigger document. Reproducable every time, as soon as the file is bigger / or the network is slower, so that the whole process takes more than 60 seconds, the upload fails. Always.

[micahwedemeyer]

Just updating anyone else still waiting: v2.3.3 still suffers from the FetchError: network timeout bug that I mentioned above. v2.1.0 is the latest version that even has a chance of working. v2.1.0 fails for me about 30% of the time, but the later versions fail 100% of the time.

[avishnyak]

@avishnyak, are you running this in the cloud somewhere or locally? Also, any more details you think would make a difference, please share.

Thanks!

We are running in a k8s environment on GCP. We are getting the same issue from all pods and across different language stacks (Node and Ruby).

[jbuck]

Thank you all for the notes to migrate down to v2.1.0 - that also fixed the network timeout error for us on send.firefox.com.

[DavidKuennen]

Having the same issue. Even the example code provided by google itself for running this within cloud functions creates timeouts.

[JustinBeckwith]

@kinwa91 @stephenplusplus this one has been going on for a while now, and I'm concerned about the whole downgrading to 2.1 thing. Can y'all prioritize an investigation for this tomorrow?

[stephenplusplus]

This should be resolved tomorrow morning, once a new release of @google-cloud/storage goes out. If you want to test in the meantime, please install from master and let me know how it goes!

[stephenplusplus]

Tomorrow came earlier than expected-- v2.4.2 is out now! Please update and report back any lingering issues.

[micahwedemeyer]

With v2.4.2 I was able to stream write 6 out of 6 files to GCS. With earlier versions, at least 2-3 of those would have failed, so this is much better.

The strange thing is that I still see a socket timeout error in the logs, but it looks as though the file was successfully written to GCS, so I'm not sure what's going on there. I'll keep an eye on it and report back.

Here's the error I saw:

Error: ESOCKETTIMEDOUT at ClientRequest.<anonymous> (/srv/node_modules/request/request.js:816:19) at Object.onceWrapper (events.js:313:30) at emitNone (events.js:106:13) at ClientRequest.emit (events.js:208:7) at TLSSocket.emitTimeout (_http_client.js:721:34) at Object.onceWrapper (events.js:313:30) at emitNone (events.js:106:13) at TLSSocket.emit (events.js:208:7) at TLSSocket.Socket._onTimeout (net.js:422:8) at ontimeout (timers.js:498:11)

[stephenplusplus]

request should be eliminated from the file.createWriteStream({resumable:false}) path. Are you using {resumable: true}? In either case, feel free to share additional details if the problem keeps up. Thanks for the update!

[micahwedemeyer]

Ugh, so stupid. I didn't deploy after making my updates. I'll deploy and check again. Sorry for the false alarm.

[micahwedemeyer]

I ran another test today with 7 files and they all successfully streamed to GCS. Great work.

[stephenplusplus]

Phew, glad to hear. Thanks for the update!