Aws-sdk-js: S3 getObject read stream fails when piping to slow stream

[iffyio]

The failure in this case happens when piping to a stream that has an initial delay.
A simplified repro for this using a relatively large file. I used a file with 10million randomly generated uuids
~370MB.

const stream = require('stream');
const AWS = require('aws-sdk'); // v2.418.0

const S3 = new AWS.S3({
  httpOptions: {timeout: 1 * 60 * 60 * 1000},
  accessKeyId: '',
  secretAccessKey: '',
});

const request = S3.getObject({ Bucket: '', Key: '' });
request.on('complete', () => console.log('request complete'));
request.on('success', () => console.log('request success'));
request.on('error', err => console.log('request error', err));
request.on('httpError', (err, res) => console.log('request httpError', err, res));

const s = request.createReadStream()
s.on('error', err => console.error(err));
s.pipe(new stream.Transform({
  async transform(ev, enc, cb) {
    if (!this.slept) {
      this.slept = true;
      await new Promise(r => setTimeout(r, 10 * 60 * 1000));
    }
    cb();
  },
}));

After the timeout elapses I get the following

{ StreamContentLengthMismatch: Stream content length mismatch. Received 390564 of 37000000 bytes.
    at PassThrough.checkContentLengthAndEmit (/node_modules/aws-sdk/lib/request.js:612:15)
    at PassThrough.emit (events.js:187:15)
    at PassThrough.EventEmitter.emit (domain.js:442:20)
    at endReadableNT (_stream_readable.js:1092:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)
  message:
   'Stream content length mismatch. Received 390564 of 37000000 bytes.',
  code: 'StreamContentLengthMismatch',
  time: 2019-03-12T09:40:51.124Z }

Worth noting also is that the error is emitted on the stream object s and not request
itself. In this scenario where the request wasn't successful and there was an error, I would
expect an event via request but instead that emits both complete and success events
but no error or httpError events. I'm not sure if this is by design.

aws-sdk v2.418.0
node v10.11.0

[AllanZhengYP]

Hey @iffyio

In this case the request itself actually succeeded but because you didn't start to read from the response stream, the response stream somehow ended after reading the first chunk. The end event makes SDK believes the response is ended properly and starts to verify the length of response. Since you only got 1 chunk, you saw this content length mismatch exception. The error was emitted on stream object because this is a verification on the stream, the request itself was successful.

[iffyio]

Hi @AllanFly120 Thanks for looking into this :)
I did start reading from the response stream since that is what triggers the sleep (it has a destination piped in) - it's the processing of the first chunk that takes time.
I figured as much that the content length mismatch was between what was supposed to be read vs actual since their bytecounts matched - what I find surprising is that the request is considered successful even though the data was not read in its entirety from the server.
I think what's confusing would be why end is being triggered? This should only be done internally when all data has been received from the server right?

[iffyio]

Hey @AllanFly120 Could you confirm whether this issue is a bug?

[wmbutler]

Interested in the outcome here as well. We seem to have a similar issue that happens periodically on our application. An excerpt from our logs:

May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log /home/code/node_modules/aws-sdk/lib/request.js:612
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log               new Error('Stream content length mismatch. Received ' +
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log               ^
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log StreamContentLengthMismatch: Stream content length mismatch. Received 8594 of 23300 bytes.
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log     at PassThrough.checkContentLengthAndEmit (/home/code/node_modules/aws-sdk/lib/request.js:612:15)
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log     at emitNone (events.js:111:20)
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log     at PassThrough.emit (events.js:208:7)
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log     at endReadableNT (_stream_readable.js:1064:12)
 May 17 08:13:43.928 cavo_production /home/ubuntu/.pm2/logs/cavo.log     at _combinedTickCallback (internal/process/next_tick.js:138:11)
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log     at process._tickDomainCallback (internal/process/next_tick.js:218:9)
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR! code ELIFECYCLE
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR! errno 1
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR! [email protected] start: `ts-node --max_old_space_size=6144 --project lib/tsconfig.json ./lib`
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR! Exit status 1
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR!
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR! Failed at the [email protected] start script.
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log message=''
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR! A complete log of this run can be found in:
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log npm ERR!     /home/ubuntu/.npm/_logs/2019-05-17T13_13_41_490Z-debug.log
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log message=''
 May 17 08:13:43.929 cavo_production /home/ubuntu/.pm2/logs/cavo.log > [email protected] prestart /home/code

[this-sam]

Has anybody been able to work around this issue or determine the root cause? @iffyio I am seeing the same problem as you when reading large files from S3 and transforming the results.

[larryboymi]

Can recreate similar issue when reading data from several S3 read streams.

[ajredniwja]

Hey @iffyio, was not able to reproduce the behavior using the code snippet provided?
Is this still a persisting issue?

[lock[bot]]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs and link to relevant comments in this thread.