fix the headersSent check and avoid Error: write EPIPE #79

raymondfeng · 2018-10-17T16:44:30Z

Description

This issue was discovered when an over-limit request body is
sent to LB4. Destroying the request socket causing the client
to fail instead of receiving a meaningful error.

Related issues

See https://travis-ci.org/strongloop/loopback-next/jobs/442256976
loopbackio/loopback-next#1838

connect to <link_to_referenced_issue>

Checklist

New tests added or existing tests modified to cover all changes
Code conforms with the style
guide

dhmlau · 2018-10-17T18:03:18Z

lib/handler.js

@@ -50,9 +49,12 @@ function writeErrorToResponse(err, req, res, options) {

  options = options || {};

-  if (res._header) {


we're removing the case for res._header because it no longer exists and replaced by headersSent?

headersSent is the documented api while _header is an internal property.

+1 to use res.headersSent

b-admike · 2018-10-17T18:50:12Z

lib/handler.js

+  // See https://nodejs.org/api/http.html#http_response_headerssent
+  if (res.headersSent) {
+    debug('Response was already sent. Skipping error response.');
+    // We should not destroy the request socket as it causes Error: write EPIPE


For me, the EPIPE error is still happening without destroying the request socket. Do we want to throw a meaningful error here instead?

No. The EPIPE error is reported from the client side as the socket is destroyed by the server.

Okay, any idea on why it's failing for me on node 10?

49 passing (236ms) 1 failing 1) strong-error-handler handles response headers already sent without destroying the request: Error: write EPIPE at WriteWrap.afterWrite [as oncomplete] (net.js:788:14) npm ERR! Test failed. See above for more details. biniams-mbp:strong-error-handler badmike$ node -v v10.11.0 biniams-mbp:strong-error-handler badmike$ npm -v 6.4.1 biniams-mbp:strong-error-handler badmike$ git br * fix-write-error master

A bit more verbose logs:

biniams-mbp:strong-error-handler badmike$ DEBUG=strong-error-handler npm t > strong-error-handler@3.2.0 test /Users/badmike/loopback/strong-error-handler> mocha strong-error-handler strong-error-handler Initializing with options {"log":false} +0ms strong-error-handler Handling Error: an error at givenErrorHandlerForError (/Users/badmike/loopback/strong-error-handler/test/handler.test.js :859:23) at Context.<anonymous> (/Users/badmike/loopback/strong-error-handler/test/handler.test.js:43:7) at callFnAsync (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runnable.js :400:21) at Test.Runnable.run (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runna ble.js:342:7) at Runner.runTest (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.j s:455:10) at /Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.js:573:12 at next (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.js:369:14) at /Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.js:379:7 at next (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.js:303:14) at /Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.js:342:7 at done (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runnable.js:319:5) at callFn (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runnable.js:395:7) at Hook.Runnable.run (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runnable.js:364:7) at next (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.js:317:10) at Immediate.<anonymous> (/Users/badmike/loopback/strong-error-handler/node_modules/mocha/lib/runner.js:347:5) at runCallback (timers.js:694:18) at tryOnImmediate (timers.js:665:5) at processImmediate (timers.js:647:5) +40ms strong-error-handler Response was already sent. Skipping error response. +1ms 1) handles response headers already sent without destroying the request 0 passing (71ms) 1 failing 1) strong-error-handler handles response headers already sent without destroying the request: Error: write EPIPE at WriteWrap.afterWrite [as oncomplete] (net.js:788:14)

I see it now. It's interesting, res.end should half-close the socket and it should allow in-progress request to finish.

This issue was discovered when an over-limit request body is sent to LB4. Destroying the request socket causing the client to fail instead of receiving a meaningful error.

bajtos

I would like to better understand ramifications of this change before going forward. The current implementation is based on code from Express.

https://github.com/pillarjs/finalhandler/blob/262126e744630d71207fd2d15c92628f7d720796/index.js#L126-L130

    if (headersSent(res)) {
      debug('cannot %d after headers sent', status)
      req.socket.destroy()
      return
    }

https://github.com/expressjs/errorhandler/blob/43f2f5b29baa8d89511a772c1622ce1930e60c6e/index.js#L108-L111

    // cannot actually respond
    if (res._header) {
      return req.socket.destroy()
    }

Let's check what other frameworks do:

AFAICT from reading fastify's lib/reply.js, they call res.destroy() when sending the response from a stream which error-ed on read, and don't do anything in all other cases.
Hapi does not seem to deal with headersSent state at all.
Restify detect headersSent and simply skips further processing without touching req/res/socket objects, at least AFAICT from their lib/index.js

bajtos · 2018-10-18T07:36:09Z

lib/handler.js

@@ -50,9 +49,12 @@ function writeErrorToResponse(err, req, res, options) {

  options = options || {};

-  if (res._header) {


+1 to use res.headersSent

bajtos · 2018-10-18T08:43:42Z

test/handler.test.js

+      request.post('/').send(givenLargeRequest())
+        .expect(200, 'empty', function(err) {
+          // Skip EPIPE
+          if (err && err.code !== 'EPIPE') return done(err);


I am afraid this test does not fail with the old implementation either. I am concerned that this test may never fail, which would give us a false sense of security.

bajtos · 2018-10-18T08:47:01Z

I was playing with the test. IMO, to correctly test the behavior when response headers were sent and an error occurs, we need to drop to low-level Node.js APIs. Below is a modified test that is correctly ignoring EPIPE on the request and still verifies that the server responds with 200 OK and empty body.

Please note that this test is currently passing with both implementations, regardless on whether we destroy the socket or not.

  it.only('handles response headers already sent without destroying the request',
    function(done) {
      givenErrorHandlerForError();
      var handler = _requestHandler;
      _requestHandler = function(req, res, next) {
        res.end('empty');
        process.nextTick(function() {
          handler(req, res, next);
        });
      };

      const requestOptions = {
        hostname: '127.0.0.1',
        port: server.address().port,
        method: 'POST',
      };
      const req = http.request(requestOptions, res => {
        expect(res.statusCode).to.equal(200);
        res.on('error', done);
        let body = '';
        res.on('data', chunk => body += chunk.toString());
        res.on('end', () => {
          expect(body).to.equal('empty');
          done();
        });
      });
      req.on('error', err =>{
        if (err.code === 'EPIPE') {
          // The server closed the connection on us.
          // This is an expected error we need to ignore,
          // so that we can see the HTTP response returned by the server.
          return;
        }
        done(err);
      });

      // send a small chunk to force the HTTP layer to send request headers
      req.write(Buffer.alloc(10, 'I'));
      // defer sending the rest of the request to give the server time
      // to handle the incoming request
      setTimeout(() => {
        req.write(givenLargeRequest());
        req.end();
      }, 50);
    });

My conclusion is that this test scenario is not describing the case when req.socket.close is required.

bajtos · 2018-10-18T10:06:58Z

I am proposing to close this pull request as invalid/rejected.

raymondfeng · 2018-10-18T14:34:40Z

I think we need to do more investigation to understand why the request socket is destroyed. From a client's perspective, it's going to be hard to deal with EPIPE error for most developers. I would expect the server gives me an error response gracefully if my request is invalid.

bajtos · 2018-10-18T14:40:51Z

I think we need to do more investigation to understand why the request socket is destroyed.

Here is my understanding: when the HTTP server detects that a response has been sent (res.end() was called) but the request body has not been fully consumed yet, it closes the underlying socket, which triggers EPIPE on the client.

It's just my guess, we should take a look at Node.js source code to build a better understanding.

Or perhaps ask our fellow IBMers that are familiar with Node.js internals to help - ping @bnoordhuis & @sam-github .

From a client's perspective, it's going to be hard to deal with EPIPE error for most developers.

Agreed.

I would expect the server gives me an error response gracefully if my request is invalid.

If you take a look at my test code posted above, the server does send an HTTP error response! As I understand it, the problem is at the client side, where the client gives more importance to EPIPE error and ignores the actual server response.

raymondfeng · 2018-10-18T14:43:27Z

If you take a look at my test code posted above, the server does send an HTTP error response! As I understand it, the problem is at the client side, where the client gives more importance to EPIPE error and ignores the actual server response.

Yes, the response arrives. But the client crashes with EPIPE before it has chance to read the response.

raymondfeng · 2018-10-18T14:48:21Z

I think it may have something to do with allowHalfOpen option of https://nodejs.org/api/net.html#net_event_end.

raymondfeng · 2018-10-19T23:04:57Z

@bajtos See nodejs/node#12339

bajtos · 2019-01-25T10:01:45Z

I think we should close this pull request and work with Node.js core to get this issue fixed at Node.js server level, as described in nodejs/node#12339.

@raymondfeng feel free to reopen if you disagree.

raymondfeng requested review from bajtos and zbarbuto as code owners October 17, 2018 16:44

raymondfeng force-pushed the fix-write-error branch 2 times, most recently from 2b4813c to ac22099 Compare October 17, 2018 17:00

dhmlau reviewed Oct 17, 2018

View reviewed changes

b-admike reviewed Oct 17, 2018

View reviewed changes

fix headersSent check

26e8f8f

This issue was discovered when an over-limit request body is sent to LB4. Destroying the request socket causing the client to fail instead of receiving a meaningful error.

raymondfeng force-pushed the fix-write-error branch from ac22099 to 26e8f8f Compare October 17, 2018 21:21

bajtos reviewed Oct 18, 2018

View reviewed changes

bajtos closed this Jan 25, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix the headersSent check and avoid Error: write EPIPE #79

fix the headersSent check and avoid Error: write EPIPE #79

raymondfeng commented Oct 17, 2018 •

edited

Loading

dhmlau Oct 17, 2018

raymondfeng Oct 17, 2018

bajtos Oct 18, 2018

b-admike Oct 17, 2018

raymondfeng Oct 17, 2018

b-admike Oct 17, 2018

b-admike Oct 17, 2018

raymondfeng Oct 17, 2018

bajtos left a comment

bajtos Oct 18, 2018

bajtos Oct 18, 2018

bajtos commented Oct 18, 2018

bajtos commented Oct 18, 2018

raymondfeng commented Oct 18, 2018

bajtos commented Oct 18, 2018

raymondfeng commented Oct 18, 2018

raymondfeng commented Oct 18, 2018

raymondfeng commented Oct 19, 2018

bajtos commented Jan 25, 2019

		@@ -50,9 +49,12 @@ function writeErrorToResponse(err, req, res, options) {

		options = options \|\| {};

		if (res._header) {

fix the headersSent check and avoid Error: write EPIPE #79

fix the headersSent check and avoid Error: write EPIPE #79

Conversation

raymondfeng commented Oct 17, 2018 • edited Loading

Description

Related issues

Checklist

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bajtos left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bajtos commented Oct 18, 2018

bajtos commented Oct 18, 2018

raymondfeng commented Oct 18, 2018

bajtos commented Oct 18, 2018

raymondfeng commented Oct 18, 2018

raymondfeng commented Oct 18, 2018

raymondfeng commented Oct 19, 2018

bajtos commented Jan 25, 2019

raymondfeng commented Oct 17, 2018 •

edited

Loading