s3.getObject(params).createReadStream().pipe(res) throws "Error: write after end"

[mcprostar205]

I have a Node.js Express application that is byte-streaming AWS S3 objects and is terminating when the Express response has ended due to user abandoning the connection. The following code successfully streams bytes (videos and audio file) to a media player to the client. The error appears to be recently introduced in AWS S3 streaming. I'm looking for advice on catching this error to prevent process termination.

AWS S3 SDK Reference:
http://docs.aws.amazon.com/sdk-for-javascript/v2/developer-guide/requests-using-stream-objects.html

Node Version : 6.10.3
Express Version : 4.15.3
AWS SDK Version : 2.77.0

Tried With No Effect - Process Still Terminated with "Error: write after end":

1. Added try-catch block around createReadStream. Catch never called.
2. Attempted to "unpipe" in .on('error'). Exception thrown before unpipe statement.
3. Listened to to res.on('final') and performed "unpipe". No affect.
4. Reviewed other reported issues here with same error for clues but others are not byte-streaming through a Node/Express response object.

Code

var awshttps = require('https');
var awsAgent = new awshttps.Agent({ maxSockets: 25 });
var s3 = new awsS3({ httpOptions:{ agent: awsAgent }, params: settings.aws.s3 });

s3.listObjectsV2({MaxKeys: 1, Prefix: file}, function(err, data)
{
   if (err || data.KeyCount < 1) 
   { 
      return res.sendStatus(404); 
   }	

   var range = req.headers.range;
   var positions = range.replace(/bytes=/, '').split('-');
   var start = parseInt(positions[0], 10);

   var total = data.Contents[0].Size;
   var end = positions[1] ? parseInt(positions[1], 10) : total - 1;
   var chunksize = (end - start) + 1;

   res.writeHead(206, 
   {
      'Cache-Control'  : 'max-age=' + cache + ', private',
      'Content-Range'  : 'bytes ' + start + '-' + end + '/' + total,
      'Accept-Ranges'  : 'bytes',
      'Content-Length' : chunksize,
      'Last-Modified'  : data.Contents[0].LastModified,
      'Content-Type'   : mimetype
   });

// 1. try-catch didn't capture thrown exception
// try {
	
   var stream = s3.getObject({Key: file, Range: range}).createReadStream();

   stream.on('error', function(err) 
   { 
      console.log(err);

// 2. exception thrown before reaching the unpipe - observed in debug tracing
//      stream.unpipe();

   });

// 3. Listen for res 'final' but didn't have an affect - exception still thrown
/*
   res.on('final', function() 
   {
      stream.unpipe();
   }
*/

   stream.pipe(res);  //successfully sends byte stream requested when response is open. media player plays and continues to ask for bytes

/*
   } catch (_err) {
      console.log(_err);
   };
*/

}

S3 ERROR

{ TimeoutError: Connection timed out after 120000ms
    at ClientRequest.<anonymous> (/../node_modules/aws-sdk/lib/http/node.js:83:34)
    at ClientRequest.g (events.js:292:16)
    at emitNone (events.js:86:13)
    at ClientRequest.emit (events.js:185:7)
    at TLSSocket.emitTimeout (_http_client.js:629:10)
    at TLSSocket.g (events.js:292:16)
    at emitNone (events.js:86:13)
    at TLSSocket.emit (events.js:185:7)
    at TLSSocket.Socket._onTimeout (net.js:338:8)
    at ontimeout (timers.js:386:14)
  message: 'Connection timed out after 120000ms',
  code: 'NetworkingError',
  time: 2017-06-26T19:22:35.234Z,
  region: '<region>',
  hostname: 's3-<region>.amazonaws.com',
  retryable: false,
  statusCode: 206,
  retryDelay: 75.23787321405521 }

NODE EXCEPTION

events.js:160
      throw er; // Unhandled 'error' event
      ^
Error: write after end
    at writeAfterEnd (_stream_writable.js:193:12)
    at PassThrough.Writable.write (_stream_writable.js:240:5)
    at IncomingMessage.ondata (_stream_readable.js:555:20)
    at emitOne (events.js:96:13)
    at IncomingMessage.emit (events.js:188:7)
    at IncomingMessage.Readable.read (_stream_readable.js:381:10)
    at flow (_stream_readable.js:761:34)
    at resume_ (_stream_readable.js:743:3)
    at _combinedTickCallback (internal/process/next_tick.js:80:11)
    at process._tickDomainCallback (internal/process/next_tick.js:128:9)

[Hyperblaster]

Same problem!!

[chrisradek]

@mcprostar205
Sorry for the delayed response. This was a difficult issue to try and reproduce!

First, with regards to what you've tried:

1. try-catch won't catch errors emitted on streams or async operations. Instead you should listen to the error event directly on the streams. You've done this with the S3 stream, but not the response stream.
2. I'm not sure that you'd need to call unpipe yourself here. Since the error is being thrown before this line, I don't think it is necessary.
3. I don't believe httpOutgoingMessage streams have a final event. I think you may have meant to use finish instead.

As called out in 1, one thing you should do in general is listen for error events emitted on the response stream.

I was finally able to reproduce your issue when using node v6.10.3. Previously I was using the latest version (8.1.3) and wasn't able to trigger it.

I think the issue happens because we have a PassThrough stream (used to validate the number of bytes streamed matches the Content-Length) that is configured with {end: false}. There is a node.js issue where streams configured this way don't emit the unpipe event:
nodejs/node#11837
This issue is already fixed in some versions of node 7 and 8, but hasn't been backported to 6 yet.

It also may explain why #1549 seems to fix this issue. We'll need to review the PR and see if that fixes the error for your use case. Alternatively, we can rewrite the PassThrough stream so that we let node.js handle stream cleanup.

Are you able to test your code on the latest version of node to see if you can reproduce it? If the error goes away, then we've probably found part of the problem.

[mcprostar205]

@chrisradek
Really appreciate the thorough analysis for this issue.

RE: 1) If I listen to error on the http event stream, what would I do to prevent the exception from being thrown? Or, does #1549 address this issue?

RE: 3) Yes, I meant "finish" :-) ...thanks for the catch....sorry.

That's great if #1549 may fix the issue on v6.10.3. I'll perform a test in development with the latest AWS SDK and report back.

My production environment is on v6.10.3 LTS. We won't be moving production to 7 or 8 in the near future. Are you looking for me to confirm the issues is resolved on node 8 if #1549 didn't resolve this issue to confirm?

[chrisradek]

@mcprostar205
Hopefully, #1549 (just released today) fixes the issue you're seeing. Doing 1) would let you catch the error, but you're right that it wouldn't prevent it from being thrown in the first place.

Yes, if #1549 does not resolve the issue, could you try the latest version of node.js in development? I wasn't able to reproduce this error when using node.js 8, so if you're still able to encounter it I might need some more info so I can see it as well.

[mcprostar205]

@chrisradek
Looks like aws-sdk v2.82.0 with #1549 resolves the crash issue for node v6.10.3. Listening to the S3 stream 'error' emits the timeout but no longer causes the node exception that terminates the process.

TimeoutError: Connection timed out after 120000ms
    at ClientRequest.<anonymous> (/../node_modules/aws-sdk/lib/http/node.js:83:34)
    at ClientRequest.g (events.js:292:16)
    at emitNone (events.js:86:13)
    at ClientRequest.emit (events.js:185:7)
    at TLSSocket.emitTimeout (_http_client.js:629:10)
    at TLSSocket.g (events.js:292:16)
    at emitNone (events.js:86:13)
    at TLSSocket.emit (events.js:185:7)
    at TLSSocket.Socket._onTimeout (net.js:338:8)
    at ontimeout (timers.js:386:14)
  message: 'Connection timed out after 120000ms',
  code: 'NetworkingError',
  time: 2017-07-08T15:59:56.137Z,
  region: '<region>',
  hostname: 's3-<region>.amazonaws.com',
  retryable: false,
  statusCode: 206,
  retryDelay: 41.75920457979259

A big thank you to you and the AWS team for your professionalism in working with customers to understand and help resolve issues.

[jeskew]

Glad everything's working on your end! Please feel free to reopen if you have any questions or concerns.

[lock]

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.