Error: stream.push() after EOF

[umutm]

Hi,

I'm sending a large number of HTTP requests to multiple hosts.

Using nodejs v0.10.5 and sometimes getting the error below:

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: stream.push() after EOF
    at readableAddChunk (_stream_readable.js:131:15)
    at IncomingMessage.Readable.push (_stream_readable.js:113:10)
    at HTTPParser.parserOnBody [as onBody] (http.js:140:22)
    at Socket.socketOnData [as ondata] (http.js:1535:20)
    at TCP.onread (net.js:510:27)

Couldn't isolate it yet as I couldn't find a clue about it with Googling.

Any help is so appreciated.

[isaacs]

That's super weird. Can you share the code?

It looks like we're getting the EOF, and then getting some more data.

[umutm]

I believe that happens for some URLs.

Currently sending requests to lots of URLs, I'll be locating the problematic one and updating back.

[umutm]

Managed to catch it.

Writing quickly as it can disappear.

That happens when sending a request (I'm sending HEAD) to: http://www.pourton.info/

The site is having some problems as far as I can see that generates lots of errors and that is somehow causing that error to appear.

On the other hand, the issue doesn't appear always but once in 15-20 requests.

Will be adding a test code soon.

[umutm]

Until I prepare the test environment, the error no longer exists on the site.

However, I was able to take a snapshot (headers - response) of the request using web-sniffer: http://www.fileswap.com/dl/TIoYb6MQQX/ to give an idea.

Btw, is there a way to detect that error, isolate it and prevent the process from failing?

[kpwn]

I'm having this bug as well, on v0.10.9 as well as on latest git master branch.

[umutm]

Btw, I couldn't found a fix and downgraded to an older version.

[karli2000]

Having it on 0.10.10 too i am grabbing a lot of urls (no HEAD request, only GET), any idea how i can catch it?

[isaacs]

Hm. Every attempt I make to reproduce this only results in a parse error. Can you try applying isaacs/node@547c336 and see if that fixes the problem you're having? If so, it's potentially a duplicate of #5695, but no one has mentioned calling abort(), so I somewhat doubt that.

[kpwn]

I am calling abort(). Reverting to 0.10.4 as #5695 fixed the issue, so I think it's probably that.
Can't test ATM since I have troubles accessing my server (not on main computer and no private ssh key here!)

[isaacs]

@kpwn Great news, thanks!

@umutm Does the fix in isaacs/node-v0.x-archive@547c336 address your problem as well? If so, I suggest closing this as a dupe of #5695.

[bnoordhuis]

This still happens with the latest v0.10, haven't tried v0.11.

I don't have a test case that finishes within a reasonable amount of time - it seems to be rather timing sensitive, it happens only once every few hundred or thousand requests - but I have been able to establish that:

1. The offending stream object is always an instance of http.IncomingMessage (a ServerRequest, though that's not a real class anymore.)
2. It occurs in streams1 and streams2 mode, i.e. it happens with both req.pipe(foo) and req.on('data', foo.write.bind(foo)) or even req.on('data', function() {}).

The stack trace looks different now than it does in the original bug report:

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: stream.push() after EOF
    at readableAddChunk (_stream_readable.js:146:15)
    at Readable.push (_stream_readable.js:127:10)
    at parserOnBody (http.js:142:22)
    at socket.ondata (http.js:1968:22)
    at onread (net.js:527:27)

My current working hypothesis is that two TCP packets come in on the same tick and that response.end() is called after processing the first one but before the second one.

I've been trying to follow the logic in lib/_stream_*.js but man, streams2... it's a maze of twisty little callbacks all alike, and that's putting it mildly.

[bnoordhuis]

I think my working hypothesis is right. Here is a test case:

var http = require('http');
var net = require('net');

http.createServer(function(req, res) {
  req.once('data', function() { res.end() });
  res.write('.');
  this.close();
}).listen(function() {
  var conn = net.connect({
    host: this.address().address,
    port: this.address().port,
  });
  conn.write('POST / HTTP/1.1\r\n' +
             'Transfer-Encoding: chunked\r\n' +
             'Connection: close\r\n' +
             '\r\n');
  conn.once('data', function() {
    var chunk = Array(1 << 6).join('.');
    chunk = chunk.length.toString(16) + '\r\n' + chunk + '\r\n';
    while (conn.write(chunk) !== false) delay(1);
  });
  conn.once('error', console.error.bind(null, 'conn error'));
});

function delay(ms) {
  var t = Date.now();
  while (ms > Date.now() - t);
}

It looks like it's fixed in master but caveat emptor, I didn't try too hard.

I don't believe @isaacs is still around so I'm channeling, oh I don't know, @indutny?

[tjfontaine]

So IncomingMessage.socket.readable is false, which triggers a .push(null) simulating an EOF even though socket._readableState is not ended -- IncomingMessage._readableState still has data and it's pushing that through when it gets the EOF

https://github.com/joyent/node/blame/v0.10/lib/http.js#L347 Is the offending code, in master that code path changed with a454063

Speculatively I made that change locally before finding that commit and your test case works fine.

I'm not sure why socket.readable is being used in this path as opposed to readableState in this case anyway

It seems like we can reasonably backport this

[tjfontaine]

Both readable and writable on the IncomingMessage.socket are being set false when OutgoingMessage.end is calling destroySoon

[indutny]

bumping myself @indutny

[indutny]

Should be fixed by f2b297c