search

molnarg / node-http2

An HTTP/2 client and server implementation for node.js
MIT License
1.79k stars 185 forks source link

Error: stream.push() after EOF #117

Open jsha opened 9 years ago

jsha commented 9 years ago

When using the node-http2 client against Twitter's API server, I get an error when the server shuts down the open connection after 15 idle minutes.

Steps to reproduce:

Edit example/client.js to add as the last line:

setTimeout("", 60 * 20 * 1000);

Then run:

HTTP2_LOG=trace node example/client.js https://api.twitter.com/robots.txt

The error is:

21:04:07.977Z FATAL client/endpoint: Fatal error, closing connection (e=0, source=connection, message={})
21:04:07.977Z  WARN client/connection: Trying to close an already closed connection (e=0)

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: stream.push() after EOF
    at readableAddChunk (_stream_readable.js:146:15)
    at Connection.Readable.push (_stream_readable.js:127:10)
    at Connection._parentPush (/home/jsha/node-http2/lib/protocol/flow.js:244:32)
    at Connection._push (/home/jsha/node-http2/lib/protocol/flow.js:255:17)
    at Connection.push (/home/jsha/node-http2/lib/protocol/flow.js:286:23)
    at Connection._receivePing (/home/jsha/node-http2/lib/protocol/connection.js:528:10)
    at Connection.EventEmitter.emit (events.js:95:17)
    at Connection._writeControlFrame (/home/jsha/node-http2/lib/protocol/connection.js:128:10)
    at Connection._receive (/home/jsha/node-http2/lib/protocol/connection.js:372:19)
    at Connection._write (/home/jsha/node-http2/lib/protocol/flow.js:101:10)

Full trace output below:

20:49:07.819Z DEBUG client/endpoint: Sending the client connection header prelude. (e=0)
20:49:07.831Z DEBUG client/connection: Sending the first SETTINGS frame as part of the connection header. (e=0)
20:49:07.831Z DEBUG client/connection: Enqueueing outgoing frame (e=0)
    frame: {
      "id": 0,
      "type": "SETTINGS",
      "flags": [],
      "stream": 0,
      "settings": {}
    }
20:49:07.832Z TRACE client/connection: Pushing frame into the output queue (e=0, frame=0)
20:49:07.833Z  INFO client/http: New outgoing HTTP/2 connection (e=0, server=api.twitter.com:443)
20:49:07.833Z TRACE client/connection: Creating new outbound stream. (e=0)
20:49:07.834Z TRACE client/connection: Allocating priority for stream. (e=0, s=0)
20:49:07.834Z  INFO client/http: Sending request (e=0, s=0, scheme=https, method=GET, authority=api.twitter.com, path=/robots.txt, headers={})
20:49:07.834Z DEBUG client/stream: Enqueueing outgoing frame (e=0, s=0)
    frame: {
      "id": 1,
      "type": "HEADERS",
      "flags": [],
      "headers": {
        ":scheme": "https",
        ":method": "GET",
        ":authority": "api.twitter.com",
        ":path": "/robots.txt"
      }
    }
20:49:07.835Z TRACE client/stream: Pushing frame into the output queue (e=0, s=0, frame=1)
20:49:07.835Z DEBUG client/stream: State transition (e=0, s=0, from=IDLE, to=OPEN)
20:49:07.835Z DEBUG client/stream: Marking last frame with END_STREAM flag. (e=0, s=0, frame=1)
20:49:07.835Z DEBUG client/stream: State transition (e=0, s=0, from=OPEN, to=HALF_CLOSED_LOCAL)
20:49:07.836Z TRACE client/serializer: Outgoing frame (e=0, frame=0)
20:49:07.837Z TRACE client/connection: Starting forwarding frames from streams. (e=0)
20:49:07.837Z TRACE client/connection: Allocating ID for stream. (e=0, s=0, stream_id=1)
20:49:07.838Z TRACE client/stream: Increasing flow control window size. (e=0, s=0, window=65535, by=0)
20:49:07.838Z TRACE client/connection: Forwarding outgoing frame (e=0, s=0, frame=1)
20:49:07.838Z DEBUG client/connection: Enqueueing outgoing frame (e=0, frame=1)
20:49:07.838Z TRACE client/connection: Pushing frame into the output queue (e=0, frame=1)
20:49:07.838Z TRACE client/compressor: Emitting header representation (e=0, key=6, value=6, index=false)
20:49:07.839Z TRACE client/compressor: Emitting header representation (e=0, key=1, value=1, index=false)
20:49:07.839Z TRACE client/compressor: Emitting header representation (e=0, key=0, value=api.twitter.com, index=true)
20:49:07.839Z TRACE client/compressor: Emitting header representation (e=0, key=3, value=/robots.txt, index=true)
20:49:07.840Z TRACE client/serializer: Outgoing frame (e=0, frame=1)
20:49:07.840Z TRACE client/connection: Changing active stream count. (e=0, free=null, change=1)
20:49:07.840Z TRACE client/connection: Stopping forwarding frames from streams. (e=0, moreNeeded=true)
20:49:07.841Z TRACE client/deserializer: Incoming frame (e=0)
    frame: {
      "id": 2,
      "type": "SETTINGS",
      "flags": [],
      "stream": 0,
      "settings": {
        "SETTINGS_INITIAL_WINDOW_SIZE": 65536
      }
    }
20:49:07.842Z TRACE client/connection: Forwarding incoming frame (e=0, frame=2)
20:49:07.842Z DEBUG client/connection: Receiving the first SETTINGS frame as part of the connection header. (e=0)
20:49:07.842Z DEBUG client/connection: Receiving connection level frame (e=0, frame=2)
20:49:07.842Z DEBUG client/connection: Enqueueing outgoing frame (e=0)
    frame: {
      "id": 3,
      "type": "SETTINGS",
      "flags": [
        "ACK"
      ],
      "stream": 0,
      "settings": {}
    }
20:49:07.842Z TRACE client/connection: Pushing frame into the output queue (e=0, frame=3)
20:49:07.842Z TRACE client/serializer: Outgoing frame (e=0, frame=3)
20:49:07.843Z DEBUG client/connection: Changing stream initial window size. (e=0, size=65536)
20:49:07.843Z TRACE client/stream: Increasing flow control window size. (e=0, s=0, window=65535, by=1)
20:49:07.843Z TRACE client/connection: Starting forwarding frames from streams. (e=0)
20:49:07.843Z TRACE client/connection: Stopping forwarding frames from streams. (e=0)
20:49:07.953Z TRACE client/deserializer: Incoming frame (e=0)
    frame: {
      "id": 4,
      "type": "SETTINGS",
      "flags": [
        "ACK"
      ],
      "stream": 0,
      "settings": {}
    }
20:49:07.953Z TRACE client/connection: Forwarding incoming frame (e=0, frame=4)
20:49:07.953Z DEBUG client/connection: Receiving connection level frame (e=0, frame=4)
20:49:07.955Z TRACE client/deserializer: Incoming frame (e=0)
    frame: {
      "id": 5,
      "type": "HEADERS",
      "flags": [
        "END_HEADERS"
      ],
      "stream": 1,
      "data": "885c033135355f91497ca58ae819aafb24e3b1054c16a6559e6196d07abe94136a681fa50400b6a08171a7ee01e531...",
      "length": 199
    }
20:49:07.956Z TRACE client/compressor: Executing header representation (e=0, key=7, value=7, index=false)
20:49:07.956Z TRACE client/compressor: Executing header representation (e=0, key=27, value=155, index=true)
20:49:07.956Z TRACE client/compressor: Executing header representation (e=0, key=30, value=text/plain;charset=utf-8, index=true)
20:49:07.956Z TRACE client/compressor: Executing header representation (e=0, key=32, value="Mon, 25 May 2015 20:49:08 GMT", index=true)
20:49:07.956Z TRACE client/compressor: Executing header representation (e=0, key=53, value=tsa_a, index=true)
20:49:07.957Z TRACE client/compressor: Executing header representation (e=0, key=54, index=true)
    value: guest_id=v1%3A143258694801722754; Domain=.twitter.com; Path=/; Expires=Wed, 24-May-2017 20:49:08 UTC
20:49:07.957Z TRACE client/compressor: Executing header representation (e=0, key=55, value=max-age=631138519, index=true)
20:49:07.957Z TRACE client/compressor: Executing header representation (e=0, key=x-connection-hash, value=edb2cd4427d531e0e10bc22ded804753, index=true)
20:49:07.957Z TRACE client/compressor: Executing header representation (e=0, key=x-response-time, value=2, index=true)
20:49:07.957Z TRACE client/connection: Forwarding incoming frame (e=0, frame=5)
20:49:07.958Z DEBUG client/stream: Receiving frame (e=0, s=0, frame=5)
20:49:07.958Z  INFO client/http: Incoming response (e=0, s=0, status=200)
    headers: {
      "content-length": "155",
      "content-type": "text/plain;charset=utf-8",
      "date": "Mon, 25 May 2015 20:49:08 GMT",
      "server": "tsa_a",
      "set-cookie": "guest_id=v1%3A143258694801722754; Domain=.twitter.com; Path=/; Expires=Wed, 24-May-2017 20:49:08 UTC",
      "strict-transport-security": "max-age=631138519",
      "x-connection-hash": "edb2cd4427d531e0e10bc22ded804753",
      "x-response-time": "2"
    }
20:49:07.959Z TRACE client/deserializer: Incoming frame (e=0)
    frame: {
      "id": 6,
      "type": "DATA",
      "flags": [
        "END_STREAM"
      ],
      "stream": 1,
      "data": "23205573656420666f7220476f6f676c652061707020696e646578696e672e205365652068747470733a2f2f646576...",
      "length": 155
    }
20:49:07.959Z TRACE client/connection: Forwarding incoming frame (e=0, frame=6)
20:49:07.959Z DEBUG client/stream: Receiving frame (e=0, s=0, frame=6)
20:49:07.960Z DEBUG client/stream: State transition (e=0, s=0, from=HALF_CLOSED_LOCAL, to=CLOSED)
20:49:07.960Z TRACE client/connection: Changing active stream count. (e=0, free=null, change=-1)
20:49:07.961Z DEBUG client/connection: Enqueueing outgoing frame (e=0)
    frame: {
      "id": 7,
      "type": "WINDOW_UPDATE",
      "flags": [],
      "stream": 0,
      "window_size": 155
    }
20:49:07.961Z TRACE client/connection: Pushing frame into the output queue (e=0, frame=7)
20:49:07.961Z TRACE client/serializer: Outgoing frame (e=0, frame=7)
20:49:07.962Z TRACE client/connection: Starting forwarding frames from streams. (e=0)
20:49:07.962Z TRACE client/connection: Stopping forwarding frames from streams. (e=0)
21:04:07.967Z TRACE client/deserializer: Incoming frame (e=0)
    frame: {
      "id": 8,
      "type": "GOAWAY",
      "flags": [],
      "stream": 0,
      "last_stream": 2147483647,
      "error": "NO_ERROR"
    }
21:04:07.968Z TRACE client/connection: Forwarding incoming frame (e=0, frame=8)
21:04:07.968Z DEBUG client/connection: Receiving connection level frame (e=0, frame=8)
21:04:07.968Z DEBUG client/connection: Other end closed the connection (e=0, error=NO_ERROR)
21:04:07.968Z DEBUG client/connection: Enqueueing outgoing End Of Stream (e=0)
21:04:07.969Z TRACE client/connection: Pushing frame into the output queue (e=0, frame=null)
21:04:07.972Z TRACE client/deserializer: Incoming frame (e=0)
    frame: {
      "id": 9,
      "type": "PING",
      "flags": [],
      "stream": 0,
      "data": "0000000000000000",
      "length": 8
    }
21:04:07.974Z TRACE client/connection: Forwarding incoming frame (e=0, frame=9)
21:04:07.975Z DEBUG client/connection: Receiving connection level frame (e=0, frame=9)
21:04:07.976Z DEBUG client/connection: Answering PING. (e=0, data=0000000000000000)
21:04:07.976Z DEBUG client/connection: Enqueueing outgoing frame (e=0)
    frame: {
      "id": 10,
      "type": "PING",
      "flags": [
        "ACK"
      ],
      "stream": 0,
      "data": "0000000000000000",
      "length": 8
    }
21:04:07.976Z TRACE client/connection: Pushing frame into the output queue (e=0, frame=10)
21:04:07.977Z FATAL client/endpoint: Fatal error, closing connection (e=0, source=connection, message={})
21:04:07.977Z  WARN client/connection: Trying to close an already closed connection (e=0)

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: stream.push() after EOF
    at readableAddChunk (_stream_readable.js:146:15)
    at Connection.Readable.push (_stream_readable.js:127:10)
    at Connection._parentPush (/home/jsha/node-http2/lib/protocol/flow.js:244:32)
    at Connection._push (/home/jsha/node-http2/lib/protocol/flow.js:255:17)
    at Connection.push (/home/jsha/node-http2/lib/protocol/flow.js:286:23)
    at Connection._receivePing (/home/jsha/node-http2/lib/protocol/connection.js:528:10)
    at Connection.EventEmitter.emit (events.js:95:17)
    at Connection._writeControlFrame (/home/jsha/node-http2/lib/protocol/connection.js:128:10)
    at Connection._receive (/home/jsha/node-http2/lib/protocol/connection.js:372:19)
    at Connection._write (/home/jsha/node-http2/lib/protocol/flow.js:101:10)
jsha commented 9 years ago

Also, this is on Node v0.10.25. FWIW, I ran into a similar issue with yakaa, the backport of Node v0.12's agent, because of the difference between socket.destroyed vs socket._destroyed: https://github.com/newrelic/yakaa/pull/2

jsha commented 9 years ago

I just tested on Node v0.12.4, and the error reproduces on that version as well.

timmckenzie commented 9 years ago

Found a simple reproduction for this bug. Both of these tests will fail.

This test goes in /test/connection.js, under describe(connection.js) -> describe(testScenario). You should see the same stack trace

describe('Should not PING after GOAWAY', function () {
      it('server sends GOAWAY', function (done) {
        s.close();
        c.ping(function () {
          done();
        });
      });
      it('client sends GOAWAY', function (done) {
        c.close();
        c.ping(function () {
          done();
        });
      });
    });
});