http.js parser.onIncoming

[lvphpwb]

TypeError: Property 'onIncoming' of object #<HTTPParser> is not a function
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:119:23)

[bnoordhuis]

Do you have a test case I can try? With what version of node.js are you seeing this?

[lvphpwb]

version of node is 0.9.8

[lvphpwb]

Sometimes be wrong，so i don't know why it get error

[bnoordhuis]

Can you post the full stack trace then?

[lvphpwb]

http.js:119
skipBody = parser.onIncoming(parser.incoming, info.shouldKeepAlive);
^
TypeError: Property 'onIncoming' of object # is not a function
at HTTPParser.parserOnHeadersComplete as onHeadersComplete
at Socket.socketOnData as ondata
at TCP.onread (net.js:476:27)
at process._makeCallback (node.js:306:20)

[jankuca]

It's happening to me too.
I don't know how to reproduce it in a test case.

TypeError: Property 'onIncoming' of object #<HTTPParser> is not a function
  at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:119:23)
  at Socket.socketOnData [as ondata] (http.js:1469:20)
  at TCP.onread (net.js:476:27)
  at process._makeCallback (node.js:306:20)

Both stable (v0.8.18) and latest (v0.9.8)

[Lecernawx]

I'm having the same problem as well.
I also don't have a test case, but it happens exclusively when I'm streaming large video files (.avi, .mov, .mp4) to video players such as divx for example.

Trace:

http.js:119
    skipBody = parser.onIncoming(parser.incoming, info.shouldKeepAlive);
                      ^
TypeError: Property 'onIncoming' of object #<HTTPParser> is not a function
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:119:23)
    at Socket.socket.ondata (http.js:1824:22)
    at TCP.onread (net.js:479:27)
    at process._makeCallback (node.js:323:24)

[legege]

Same here, a MJPEG stream over HTTP triggered this issue.

[isaacs]

It seems like this bug is the perfect combination of happening rarely and only-under-load, thus making it nearly impossible to reproduce.

Anyone seeing this frequently, can you try applying this patch and let me know if it makes a difference? https://gist.github.com/isaacs/4948917

The patch just changes the order in which we add the .onbody and .onIncoming functions.

[isaacs]

Update: the patch I posted above doesn't solve the problem.

[dougwilson]

@isaacs I'm still looking into it, but it may be interesting to know that if I change the parsers FreeList to have a max of 0 (so there is no parser-reuse) then the issue goes away. So I'm thinking it is some kind of issue where a parser is reused too early, not fully cleaned up, or some such.

[dougwilson]

I'm still working on it, but I'm starting to think it looks like the issue may be within the connectionListener function. serverSocketCloseListener closes over the parser variable and is added to the close listener. I think the parser gets freed and another socket starts to use it and then serverSocketCloseListener is called and freeParser gets called on a parser that is in use.

[dougwilson]

I changed FreeList such that a call to free would not return an object to be free (i.e. so objects where never reused) and then recorded the stack when objects were freed. I was then able to detect two stacks where the same parser object would be freed (double-freed, the second free would of course mean it was freed while another socket was using it). These are the stacks (line numbers may be off; they have your patch applied):

Error
    at exports.FreeList.free (freelist.js:50:29)
    at freeParser (http.js:1396:13)
    at Socket.serverSocketCloseListener (http.js:1793:5)
    at Socket.EventEmitter.emit (events.js:126:20)
    at Socket._destroy.destroyed (net.js:358:10)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
Error
    at exports.FreeList.free (freelist.js:48:17)
    at freeParser (http.js:1396:13)
    at Socket.serverSocketCloseListener (http.js:1793:5)
    at Socket.EventEmitter.emit (events.js:126:20)
    at Object._onTimeout (http.js:516:16)
    at Timer.list.ontimeout (timers.js:101:19)

Both frees on the same parser was called from serverSocketCloseListener which also means that close was emitted twice on the socket. One from the socket being destroyed and a second from the new changes to _writeRaw (called from a timer).

I know _writeRaw listens to the close event and will clear the timeout, but apparently the close event was emitted on the socket before _writeRaw got called, so it double-emits and the parser object will get freed (and properties reset) again later. When there are a lot of connections going on, it becomes more and more likely that another socket will be using that parser when freeParser suddenly gets called on it from that close listener.

[dougwilson]

@isaacs I doubt this is the right way to do it, but this patch (on v0.8.21-pre) solves the issue for me:

diff --git a/lib/http.js b/lib/http.js
index 0081432..b2b5df6 100644
--- a/lib/http.js
+++ b/lib/http.js
@@ -1788,7 +1788,9 @@ function connectionListener(socket) {
   function serverSocketCloseListener() {
     debug('server socket close');
     // mark this parser as reusable
-    freeParser(parser);
+    if (this === parser.socket) {
+      freeParser(parser);
+    }

     abortIncoming();
   }

It checks that the socket property on parser is the same as the socket that close was emitted on before calling freeParser on the parser object, preventing the double-free condition.

[dougwilson]

@isaacs I just wanted to let you know I have not even looked into the cause on v0.9, but it is likely to be the same (or similar) to that on v0.8 I found (calling freeParser on a parser that was already back in the free pool). All the copies of stack traces above are from node v0.9 (http.js:119) or node v0.8.21-pre (http.js:111). @jankuca claims it also occurred on node v0.8.18, but I was not able to reproduce it at all on v0.8.18 and the posted stack trace was from v0.9, so I don't think it was an issue in node v0.8.18.

Also, a better patch for v0.8.21-pre would be:

diff --git a/lib/http.js b/lib/http.js
index aee579a..90725f0 100644
--- a/lib/http.js
+++ b/lib/http.js
@@ -1749,8 +1749,11 @@ function connectionListener(socket) {

   function serverSocketCloseListener() {
     debug('server socket close');
-    // mark this parser as reusable
-    freeParser(parser);
+    var parser = this.parser;
+    if (parser) {
+      // mark this parser as reusable
+      freeParser(parser);
+    }

     abortIncoming();
   }

as it would match the way the parser is loaded and detected before attempting to free in other parts of the code (if it were freed from the socket before, this.parser would be null).

Also, the work-around in user-space for the issue is to do require('http').parsers.max = 0;. node v0.9 has the same parser pool, so if that fixes the issue on node v0.9 as well, then there is also a double-free issue in the v0.9 http module. The patch above should also apply against node v0.9. It may be the same issue (close event called more than once on the socket), in which case it'll also fix v0.9.

[vadim-pavlov]

Thank you dougwilson for your investigation. I'm going to try this patch on the v0.9.8-release branch and let you guys know how it will go. We had a couple of outages each week as a result of this issue, so with our current load It could take 2 weeks to make sure that this issue is solved.

[isaacs]

@dougwilson This is awesome. Thanks!

[isaacs]

@dougwilson Would you mind signing the CLA? I'm going to dig into this a bit before just taking the patches here, but since I'm tainted now, it'd be good to know that I have permission to use your patch to fix your bug :) http://nodejs.org/cla.html

[dougwilson]

@isaacs Good to know I was able to help :) I have just signed the CLA (been looking for an excuse to for a while ;) ).

[isaacs]

Should be fixed on 0.8.21

[lvphpwb]

Thank you~~~~

[Peter-E-Lenz]

http.js:119
skipBody = parser.onIncoming(parser.incoming, info.shouldKeepAlive);
^
TypeError: Property 'onIncoming' of object # is not a function
at HTTPParser.parserOnHeadersComplete as onHeadersComplete
at Socket.socketOnData as ondata
at TCP.onread (net.js:476:27)
at process._makeCallback (node.js:306:20)

Still occuring under load in 0.9.8

[dougwilson]

@Peter-E-Lenz that patch did not apply to version 0.9.8, as 0.9.8 was released a month before this patch. The patch is in 0.8.21 and higher 0.8.x series and in 0.9.11 and up.

[Peter-E-Lenz]

You're right - mental date parsing fail on my part. whoops

[cjihrig]

v0.10 is end of life as of November 1st. Additionally, this repo is largely abandoned. If you can reproduce a bug on v4, v6, or v7, feel free to open it at https://github.com/nodejs/node.