Skip to content
This repository

Memory leak using http's request/get/clientRequest and closures #3179

Closed
vvo opened this Issue · 34 comments

7 participants

Vincent Voyer Ben Noordhuis Isaac Z. Schlueter Romain Paul Selden Matt Ranney fredericgermain
Vincent Voyer
vvo commented

Using nodejs 0.6.15 on Linux 64bits Debian Wheezy.

I made a small test file that is leaking memory when using http.get.
It seems that callback functions are retained.

The test just use http.get on a lot of google domains.

https://gist.github.com/2488897

var
  http = require('http'),
  extensions = ['com', 'ac', 'ad', 'ae', 'com.af', 'com.ag', 'com.ai', 'am', 'it.ao', 'com.ar', 'as', 'at', 'com.au', 'az', 'ba', 'com.bd', 'be', 'bf', 'bg', 'com.bh', 'bi', 'bj', 'com.bn', 'com.bo', 'com.br', 'bs', 'co.bw', 'com.by', 'com.bz', 'ca', 'com.kh', 'cc', 'cd', 'cf', 'cat', 'cg', 'ch', 'ci', 'co.ck', 'cl', 'cm', 'cn', 'com.co', 'co.cr', 'com.cu', 'cv', 'cz', 'de', 'dj', 'dk', 'dm', 'com.do', 'dz', 'com.ec', 'ee', 'com.eg', 'es', 'com.et', 'fi', 'com.fj', 'fm', 'fr', 'ga', 'gd', 'ge', 'gf', 'gg', 'com.gh', 'com.gi', 'gl', 'gm', 'gp', 'gr', 'com.gt', 'gy', 'com.hk', 'hn', 'hr', 'ht', 'hu', 'co.id', 'iq', 'ie', 'co.il', 'im', 'co.in', 'io', 'is', 'it', 'je', 'com.jm', 'jo', 'co.jp', 'co.ke', 'com.kh', 'ki', 'kg', 'co.kr', 'com.kw', 'kz', 'la', 'com.lb', 'com.lc', 'li', 'lk', 'co.ls', 'lt', 'lu', 'lv', 'com.ly', 'co.ma', 'md', 'me', 'mg', 'mk', 'ml', 'mn', 'ms', 'com.mt', 'mu', 'mv', 'mw', 'com.mx', 'com.my', 'co.mz', 'com.na', 'ne', 'com.nf', 'com.ng', 'com.ni', 'nl', 'no', 'com.np', 'nr', 'nu', 'co.nz', 'com.om', 'com.pa', 'com.pe', 'com.ph', 'com.pk', 'pl', 'pn', 'com.pr', 'ps', 'pt', 'com.py', 'com.qa', 'ro', 'rs', 'ru', 'rw', 'com.sa', 'com.sb', 'sc', 'se', 'com.sg', 'sh', 'si', 'sk', 'com.sl', 'sn', 'sm', 'so', 'st', 'com.sv', 'td', 'tg', 'co.th', 'com.tj', 'tk', 'tl', 'tm', 'to', 'com.tn', 'com.tr', 'tt', 'com.tw', 'co.tz', 'com.ua', 'co.ug', 'co.uk', 'us', 'com.uy', 'co.uz', 'com.vc', 'co.ve', 'vg', 'co.vi', 'com.vn', 'vu', 'ws', 'co.za', 'co.zm', 'co.zw'],
  nbloop = 9, nblaunch = 2, done = 0, todo = nblaunch*nbloop*extensions.length;

console.log('We should do '+ todo +' requests');

// show memused and progress while running
setInterval(status, 5000);status();

// 2 launch
loop();setTimeout(loop, 10000);

function loop() {
  console.log('Starting a new request loop');
  for(var i = 0; i < nbloop; i++) {
    getall();
  }
}

function getall() {
  // creates a big buffer
  var megabig = new Big();

  // this should not trigger a memory leak but it does when using http.get
  function cb() {
    done+=1;
    return megabig;
  }

  extensions.forEach(function(ext) {
    // using setTimeout instead of http.get shows no mem leak
    // setTimeout(cb, 10);

    http.get({
      hostname: 'www.google.' + ext,
      pathname: '/index.html?' + Math.random(),
      port: 80,
      protocol: 'http:'
    }, cb);
  });
}

function Big() {
  this.yo = (new Buffer(1 * 1024 * 1024 * 3)).toString();
}

function status() {
  console.log((process.memoryUsage().heapUsed/1024/1024).toFixed() + 'MB used');
  console.log('Done: '+ done +'/'+ todo);
  if (done === todo) {
    console.log('all requests done, memory should be collected by now ?')
  }
}

After all requests are done, I get ~105MB used memory that will not be freed.
Calling cb() with setTimeout does not leak so it is http related.

I'm using a lot of # domains because memory usage goes up the more domains I have.

Using https://github.com/c4milo/node-webkit-agent (great great tool) I was able to get this retain paths:
Memory leak

And after looking at http.js it seems I solved this, you decide.

Camilo Aguilar c4milo referenced this issue in einaros/ws
Closed

High memory usage (or memleak?) #43

Vincent Voyer
vvo commented

Results:

node 0.6.15

105MB used
Done: 3510/3510
all requests done, memory should be collected by now ?

node HEAD

88MB used
Done: 3510/3510
all requests done, memory should be collected by now ?

node HEAD with FIX e138f76

10MB used
Done: 3510/3510
all requests done, memory should be collected by now ?

No more (big) leak, tests ok. I guess there are some other leaks, will debug more but right now this is a good fix I guess.

Also I do no think we need .on but .once should be enough.

Ben Noordhuis

Thanks for the detailed bug report. I'm trying to reproduce it but without much luck. I see an initial jump to 90-110 MB RSS but it comes down again once the script is done and settles around 15-30 MB (0.6.15 and master both), which is what you'd expect for a live but mostly idle VM.

What happens if you add a if (typeof gc === 'function') gc() at the top of status() and run your script with --expose-gc?

Ben Noordhuis

By the way, does it also happen when you run it against a local server? Here is a script you can test against:

for (var i = 0; i < 1000; ++i)
  require('net').createServer(onConnection).listen(30000 + i);

function onConnection(conn)
{
  conn.write('HTTP/1.0 200 OK\r\nServer: test\r\n\r\n',
             conn.destroy.bind(conn));
}
Ben Noordhuis

Okay, I'm getting more and more convinced that the HTTP client leaks memory. I've added a benchmark in 12a90e9 that spawns a couple of servers and clients. Memory usage of the servers is relatively stable (RSS grows and shrinks as you would expect) but with the clients it keeps growing and growing.

Ben Noordhuis

I tried your patch from #3181 but I'm afraid it didn't make an appreciable difference. To be continued.

Romain

Hi,

I made the gist simpler (no need of google servers :) ): https://gist.github.com/2518326 , and test it without and with #3181

Without #3181

[romain@myhost trace-memory-leaks]$ node --expose-gc gistfile1.js 
We should do 5 requests
3MB used
Done: 0/5, not yet GC: 0
24MB used
Done: 5/5, not yet GC: 5
all requests done, memory should be collected by now ?
24MB used
Done: 5/5, not yet GC: 5
all requests done, memory should be collected by now ?

With #3181

[romain@myhost trace-memory-leaks]$ node --expose-gc gistfile1.js 
We should do 5 requests
3MB used
Done: 0/5, not yet GC: 0
24MB used
Done: 5/5, not yet GC: 0
all requests done, memory should be collected by now ?
3MB used
Done: 5/5, not yet GC: 0
all requests done, memory should be collected by now ?
Isaac Z. Schlueter isaacs referenced this issue from a commit
Isaac Z. Schlueter Null references to request object on socket errors.
Regarding #3199 and #3179 and issues seen in production.
Hopefully this fixes them.
bfe9cdb
Matt Ranney mranney referenced this issue from a commit in Voxer/node
Isaac Z. Schlueter Null references to request object on socket errors.
Regarding #3199 and #3179 and issues seen in production.
Hopefully this fixes them.
9863ad0
Vincent Voyer
vvo commented

@bnoordhuis I was measuring heapUsed and not rss. Although I do not know how to distinguish rss/heapUsed/heapTotal.

About #3181. I'm pretty sure we should not .on('response', cb) but .once('reponse', cb).
Why would we wait for more than one response event on an ClientRequest object?
I saw that @isaacs is working on https://github.com/joyent/node/tree/http-memleak so I decided to do some testing on this branch.

Here are my results using his branch, then applying #3181.
Using a much simpler test file using some modified work from @Filirom1 : https://gist.github.com/2488897
This test now creates 100MB Buffers, an HTTP Server and do 30 request in localhost.

I'm outputing all memory usage information. I only hid some /path informations on my system.

Using joyent/node/tree/http-memleak :

vvo@think-vvo [01:08:46] [~/node] [http-memleak]
-> % git branch                                                                              
* http-memleak
  master
vvo@think-vvo [01:08:49] [~/node] [http-memleak]
-> % ./out/Release/node -v                                                                   
v0.6.17-pre
vvo@think-vvo [01:08:56] [~/node] [http-memleak]
-> % time ./out/Release/node /memleak.js
We should do 30 requests
rss: 13MB, heapUsed: 4MB, heapTotal: 6MB
Done: 0/30
rss: 113MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 113MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
^C./out/Release/node   0.18s user 0.06s system 0% cpu 25.686 total

rss: 111MB, heapUsed: 103MB, heapTotal: 105MB

Then, applying #3181 and configure and make and re-run :

vvo@think-vvo [01:11:54] [~/node] [http-memleak *]
-> % git branch
* http-memleak
  master
vvo@think-vvo [01:11:56] [~/node] [http-memleak *]
-> % ./out/Release/node -v
v0.6.17-pre
vvo@think-vvo [01:11:57] [~/node] [http-memleak *]
-> % git diff   
diff --git a/lib/http.js b/lib/http.js
index 9aaff7f..e8ca291 100644
--- a/lib/http.js
+++ b/lib/http.js
@@ -1014,7 +1014,7 @@ function ClientRequest(options, cb) {
   var method = self.method = (options.method || 'GET').toUpperCase();
   self.path = options.path || '/';
   if (cb) {
-    self.on('response', cb);
+    self.once('response', cb);
   }

   if (!Array.isArray(options.headers)) {
vvo@think-vvo [01:13:40] [~/node] [http-memleak *]
-> % time ./out/Release/node /memleak.js
We should do 30 requests
rss: 13MB, heapUsed: 4MB, heapTotal: 6MB
Done: 0/30
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 11MB, heapUsed: 3MB, heapTotal: 5MB
Done: 30/30
All requests done, memory should be collected
^C./out/Release/node   0.18s user 0.05s system 1% cpu 17.587 total

rss: 11MB, heapUsed: 3MB, heapTotal: 5MB

Using node 0.6.16 :

vvo@think-vvo [01:22:07] [~/node] [http-memleak *]
-> % node -v
v0.6.16
vvo@think-vvo [01:22:09] [~/node] [http-memleak *]
-> % time node /memleak.js
We should do 30 requests
rss: 13MB, heapUsed: 4MB, heapTotal: 6MB
Done: 0/30
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
^Cnode /memleak.js  0.18s user 0.06s system 1% cpu 22.355 total

rss: 111MB, heapUsed: 103MB, heapTotal: 105MB

The fact that the mem goes up to >100MB without #3181 is due to always keeping a reference to the latest callback request done by an http agent in memory. That request callback holds a reference to a 100MB Buffer.

I bet this is due to the .on('reponse') which is never cleared and should be. Once we use .once('response') and a response event is emitted there is no more callback reference hold.

Hope I'm not mistaking.

I'm sure there are other mem leaks using http request since it didn't solved all our production memleaks. Will try to find more...

Romain

Hi,

For me the branch https://github.com/joyent/node/tree/http-memleak works well, but I still have a memory leak when I use setTimeout

http.get({
  hostname: 'localhost',
  pathname: '/index.html?' + Math.random(),
  port: 3000,
  protocol: 'http:'
}, cb).on('error', function(e) {
  cb(e);
}).setTimeout(10, function(){
  console.log('nothing here')
})

https://gist.github.com/2577565

Isaac Z. Schlueter
Collaborator
isaacs commented

We've been tracking down an error that looks suspiciously like this at @joyent that @mranney is encountering at @Voxer.

If bfe9cdb doesn't fix it, then we'll look into other things.

e25611e is not acceptable, because it puts http-specific logic into FreeList, which is not where it belongs.

Vincent Voyer
vvo commented

@isaacs I can confirm bfe9cdb does not solves #3179 as tested above

Romain

@vvo if you force gc (--expose-gc) in https://gist.github.com/2488897, the heapUsed stays at 3MB

@isaacs did you try the setTimeout issue ? https://gist.github.com/2577565

Romain

@vvo I forgot to mention with #3181 applied

Isaac Z. Schlueter
Collaborator
isaacs commented

Reproducing the timeout issue. The interesting thing is that if you make the timeout actually fire (eg, by using setTimeout in the server to delay the response), then all the objects are GC'ed normally. But, apparently timeouts that don't get hit put us back on the bad path.

Romain

Yes this is because of this.once('timeout', callback);
https://github.com/Filirom1/node/blob/master/lib/net.js#L173

The once remove the listener when the the timeout is triggered, but we have to do it manually if the timeout is not triggered https://github.com/joyent/node/pull/3208/files

Paul Selden
pselden commented

#3068 refers to the timeout issue.

Clearing the listeners on the socket "sort of" works unless you are re-using the socket for multiple requests.

Romain

@pselden4 but when destroy is called, the socket will be nore more re-usable. That's why I added removeAllListeners('timeout'); in Socket.prototype._destroy

Romain

@isaacs I try your commit c9be1d5ffd but it didn't fix https://gist.github.com/2577565

On branch http-memleak + #3181 + #3208, the 3 previous gists do not leak anymore:

Unfortunately I found something else with an http request and a fs.writeFile.

http.get({
  hostname: 'localhost',
  pathname: '/index.html?' + Math.random(),
  port: 3000,
  protocol: 'http:'
}, function(res){
  require('fs').writeFile('/tmp/toto', 'toto', function(e){
    if(e) return cb(e);
    cb();
  });
}).on('error', function(e) {
  cb(e);
});

https://gist.github.com/2584366

Not all objects are GC.

node --expose-gc leakGetAndWrite.js
webkit-devtools-agent started on 0.0.0.0:1337
We should do 18 requests
3MB used
Done: 0/18, not yet GC: 0
96MB used
Done: 18/18, not yet GC: 6
all requests done, memory should be collected by now ?
33MB used
Done: 18/18, not yet GC: 6
all requests done, memory should be collected by now ?
33MB used
Done: 18/18, not yet GC: 6
all requests done, memory should be collected by now ?
Romain

In facts, the leaks is not due to the fs.writeFile, it's because of the .on('error', function(e) { cb(e); });.

Romain

I have updated the gist for the .on('error') leak : https://gist.github.com/2584366

And have updated the patch https://github.com/joyent/node/pull/3208/files to fix this gist.

But something is broken, so do not take it. It's just ugly patches to show you where leaks may be hidden.

Romain

BTW, an even uglier solution but working is

diff --git a/lib/freelist.js b/lib/freelist.js
index 61a3f78..0bde0cc 100644
--- a/lib/freelist.js
+++ b/lib/freelist.js
@@ -38,6 +38,6 @@ exports.FreeList.prototype.alloc = function() {
 exports.FreeList.prototype.free = function(obj) {
   //debug("free " + this.name + " " + this.list.length);
   if (this.list.length < this.max) {
-    this.list.push(obj);
+    //this.list.push(obj);
   }
 };
diff --git a/lib/http.js b/lib/http.js
index eb8473c..e8ca291 100644
--- a/lib/http.js
+++ b/lib/http.js
@@ -1014,7 +1014,7 @@ function ClientRequest(options, cb) {
   var method = self.method = (options.method || 'GET').toUpperCase();
   self.path = options.path || '/';
   if (cb) {
-    self.on('response', cb);
+    self.once('response', cb);
   }

   if (!Array.isArray(options.headers)) {
@@ -1128,8 +1128,6 @@ ClientRequest.prototype.onSocket = function(socket) {
     var freeParser = function() {
       if (parser) {
         parsers.free(parser);
-        parser.socket.removeAllListeners();
-        parser.socket._httpMessage.removeAllListeners();
         parser.socket.onend = null;
         parser.socket.ondata = null;
         parser.socket = null;
Isaac Z. Schlueter isaacs closed this in 75f2365
Isaac Z. Schlueter
Collaborator
isaacs commented

@Filirom1 Yes, as you say, these patches are quite ugly. In general, we can never safely call removeAllListeners on objects that we've passed to client code, since the user may have put some listener on there with good reason. But the clues were helpful, thank you :)

This is fixed (with tests etc) in v0.6...http-memleak

Comments welcome.

Romain

Good job for the tests, it's very helpful :)

Unfortunately, the fix seems to work, but some times it fails.

Try to increase the number of requests in the gc tests to 50 for exemple.

And stress the tests

for i in {1..20}; do 
  make test-gc >/dev/null 2>&1 && echo "ok" || echo "error"; 
done;
ok
ok
ok
ok
ok
ok
error
ok
ok
error
ok
ok
ok
error
ok
error
ok
error
ok
error

The ouput is

[romain@myhost node]$ make test-gc 
Waf: Entering directory `/home/romain/node/out'
DEST_OS: linux
DEST_CPU: x64
Parallel Jobs: 1
Product type: program
Waf: Leaving directory `/home/romain/node/out'
'build' finished successfully (0.113s)
-rwxr-xr-x 1 root root 12M  3 mai   23:18 out/Release/node
python tools/test.py --mode=release gc
=== release test-http-client-onerror ===                        
Path: gc/test-http-client-onerror
We should do 50 requests
Done: 5/50
Collected: 3/50
Done: 5/50
Collected: 3/50
Done: 5/50
Collected: 3/50
Done: 5/50
Collected: 3/50
Done: 5/50
Collected: 3/50
Done: 10/50
Collected: 8/50
Done: 10/50
Collected: 8/50
Done: 10/50
Collected: 8/50
Done: 10/50
Collected: 8/50
Done: 10/50
Collected: 8/50
Done: 15/50
Collected: 13/50
Done: 15/50
Collected: 13/50
Done: 15/50
Collected: 13/50
Done: 15/50
Collected: 13/50
Done: 15/50
Collected: 13/50
Done: 20/50
Collected: 18/50
Done: 20/50
Collected: 18/50
Done: 20/50
Collected: 18/50
Done: 20/50
Collected: 18/50
Done: 20/50
Collected: 18/50
Done: 25/50
Collected: 23/50
Done: 25/50
Collected: 23/50
Done: 25/50
Collected: 23/50
Done: 25/50
Collected: 23/50
Done: 25/50
Collected: 23/50
Done: 30/50
Collected: 28/50
Done: 30/50
Collected: 28/50
Done: 30/50
Collected: 28/50
Done: 30/50
Collected: 28/50
Done: 30/50
Collected: 28/50
Done: 35/50
Collected: 33/50
Done: 35/50
Collected: 33/50
Done: 35/50
Collected: 33/50
Done: 35/50
Collected: 33/50
Done: 35/50
Collected: 33/50
Done: 40/50
Collected: 38/50
Done: 40/50
Collected: 38/50
Done: 40/50
Collected: 38/50
Done: 40/50
Collected: 38/50
Done: 40/50
Collected: 38/50
Done: 45/50
Collected: 43/50
Done: 45/50
Collected: 43/50
Done: 45/50
Collected: 43/50
Done: 45/50
Collected: 43/50
Done: 45/50
Collected: 43/50
Done: 50/50
Collected: 46/50
All should be collected now.
timers.js:96
            if (!process.listeners('uncaughtException').length) throw e;
                                                                      ^
AssertionError: false == true
    at Object.status [as _onTimeout] (/home/romain/node/test/gc/test-http-client-onerror.js:62:5)
    at Timer.ontimeout (timers.js:94:19)
Command: out/Release/node --expose-gc /home/romain/node/test/gc/test-http-client-onerror.js
[00:01|% 100|+   4|-   1]: Done                            
make: *** [test-gc] Erreur 1
Romain

One more clue, if you remove agent (agent:false), everything works well :)

for i in {1..20}; do make test-gc >/dev/null 2>&1 && echo "ok" || echo "error"; done;
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
Romain

Second tips, if you execute the tests with --nocrankshaft:

diff --git a/test/gc/testcfg.py b/test/gc/testcfg.py
index 30f3bdb..9daa61c 100644
--- a/test/gc/testcfg.py
+++ b/test/gc/testcfg.py
@@ -92,7 +92,7 @@ class GCTestCase(test.TestCase):
       additional_files += files_match.group(1).strip().split()
     for a_file in additional_files:
       result.append(join(dirname(self.config.root), '..', a_file))
-    result += ["--expose-gc"]
+    result += ["--expose-gc", "--nocrankshaft"]
     result += [self.file]
     return result

It works well

$ for i in {1..20}; do make test-gc >/dev/null 2>&1 && echo "ok" || echo "error"; done;
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
ok
Matt Ranney
mranney commented

Woah, crankshaft changes it? Crazy.

Ben Noordhuis bnoordhuis reopened this
Ben Noordhuis

Reopening.

Romain

In my humble opinion, the test are focusing on HTTPRequest references, but the role of the agent is to keep a pool of HTTPRequests. So it's ok to see a leak.

I think that it would be more accurate to test a reference of a variable in a closure.
91120e0#L2R39

If you do that, you will see a leak in the agent. I think that it may be fixed this way:

iff --git a/lib/http.js b/lib/http.js
index 4c55db0..1202cd2 100644
--- a/lib/http.js
+++ b/lib/http.js
@@ -906,6 +906,16 @@ function Agent(options) {
   self.maxSockets = self.options.maxSockets || Agent.defaultMaxSockets;
   self.on('free', function(socket, host, port) {
     var name = host + ':' + port;
+
+    if(socket._httpMessage) {
+      socket._httpMessage.removeAllListeners();
+      socket._httpMessage = null;
+      socket.ondrain = null;
+      socket.ondata = null;
+      socket.onend = null;
+    }
+    socket.removeAllListeners('timeout');
+
     if (self.requests[name] && self.requests[name].length) {
       self.requests[name].shift().onSocket(socket);
       if (self.requests[name].length === 0) {
@@ -1111,7 +1121,7 @@ function createHangUpError() {
 }
Isaac Z. Schlueter
Collaborator
isaacs commented

There's a race condition in the test. It looks like the crankshaft gc() isn't blocking or something, I'm not sure. But removing the existing timeout when we create a new one, and adding another gc() call in another place, seems to make it pass.

The core issue appears to have been in fact fixed, just the test was busted.

While digging into it, I realized that we could have avoided a lot of headaches in the first place with a pretty minor parser usage cleanup, so I'm going to try to get that in as well.

Isaac Z. Schlueter isaacs referenced this issue from a commit
Isaac Z. Schlueter Clean up gc tests
This fixes the additional issues brought up in #3179.
62c12d2
Romain

I am sorry, v0.6.17-release doesn't fix the stressed-test issue

git checkout origin/v0.6.17-release
./configure
make
sudo make install

for i in {1..20}; do make test-gc >stdout 2>&1 && echo "ok" || echo "error"; done;
ok
ok
ok
ok
error
ok
ok
ok
ok
ok
ok
ok
ok
ok
error
ok
error
error
ok
ok

Collected: 494/500
Done: 500/500
Collected: 498/500
All should be collected now.
timers.js:96
            if (!process.listeners('uncaughtException').length) throw e;
                                                                      ^
AssertionError: false == true
    at Object.status [as _onTimeout] (/home/romain/node/test/gc/test-http-client-onerror.js:65:5)
    at Timer.ontimeout (timers.js:94:19)
Command: out/Release/node --expose-gc /home/romain/node/test/gc/test-http-client-onerror.js
[00:14|% 100|+   4|-   1]: Done                            
make: *** [test-gc] Erreur 1

And I still have a leak with the following code:

$ node --expose-gc leak1.js 
We should do 18 requests
2MB used
Done: 0/18, not yet GC: 0
3MB used
Done: 18/18, not yet GC: 4
all requests done, memory should be collected by now ?
2MB used
Done: 18/18, not yet GC: 4
all requests done, memory should be collected by now ?
2MB used
Done: 18/18, not yet GC: 4
all requests done, memory should be collected by now ?

The GC is called every 5 seconds, but 4 requests stays.

Here is the code :

var http  = require('http'),
  weak    = require('weak'),
  done    = 0,
  count   = 0,
  countGC = 0,
  todo    = 18;

console.log('We should do '+ todo +' requests');

// show memused and progress while running
setInterval(status, 5000);status();

var http = require('http');
http.createServer(function (req, res) {
  res.writeHead(200, {'Content-Type': 'text/plain'});
  res.end('Hello World\n');
}).listen(3000, '127.0.0.1', getall);


function getall() {
  for(var i = 0; i < todo; i++) {
    (function(){

      // this should not trigger a memory leak but it does when using http.get
      function cb(e) {
        done+=1;
      }

      var req = http.get({
        hostname: 'localhost',
        pathname: '/index.html?' + Math.random(),
        port: 3000,
        //agent: false,
        protocol: 'http:'
      }, cb)

      req.on('error', function(e) {
        cb(e);
      })

      req.setTimeout(10, function(){
        console.log('nothing here')
      })
      count ++;
      weak(req, afterGC);
    })()
  }
}

function afterGC(){
  countGC ++
}

function status() {
  gc()
  console.log((process.memoryUsage().heapUsed/1024/1024).toFixed() + 'MB used');
  console.log('Done: '+ done +'/'+ todo + ', not yet GC: ' + (count - countGC));
  if (done === todo) {
    console.log('all requests done, memory should be collected by now ?')
  }
}

setTimeout(function(){}, 1000000000);
Romain

And here is a screenshot http://i.imgur.com/OiJju.png done by webkit-devtools-agent, we saw references on timeout

Romain

Now, if I apply the patch given below, I still saw a leak, but webkit-devtools-agent gives me a smaller retained tree http://i.imgur.com/h9ThS.png.

But I am not sure to understand what this means:

__proto__ in ClientRequest @1669
[574] in (GC roots) @3
req in function() @6531

I tried to name every function containing a variable req in http and net, but it is still the same : req in function(), not very useful.

Isaac Z. Schlueter isaacs referenced this issue from a commit in isaacs/node
Isaac Z. Schlueter Null references to request object on socket errors.
Regarding #3199 and #3179 and issues seen in production.
Hopefully this fixes them.
9164fa6
Isaac Z. Schlueter isaacs referenced this issue from a commit in isaacs/node
Vincent Voyer Fix #3179 HTTP memory leak using ClientRequest. 5eac8d6
Isaac Z. Schlueter isaacs referenced this issue from a commit in isaacs/node
Isaac Z. Schlueter Clean up gc tests
This fixes the additional issues brought up in #3179.
a9fc63f
Romain Filirom1 referenced this issue
Closed

V0.6 mem leak #3256

fredericgermain

Hi, I've found a leak closely related on the http.request.setTimeout that I need to use to handle some problem on the tcp stack happening on my use case...
The thing is, when there is a http.Agent involved, http keepalive is activated, and one socket is being reused by different http.requests. Each time a socket is associated to a http.request, and a timeout is already defined, socket.setTimeout is called, but this function just queue callbacks in a list, there is no one exclusive timeout socket callback.
So I probably http.request needs to unregister the timeout socket callback when it "detaches" from the socket.

Here is a trace I have when several requests with a timeout callback use the same socket
(node) warning: possible EventEmitter memory leak detected. 11 listeners added. Use emitter.setMaxListeners() to increase limit.
Trace
at Socket.EventEmitter.addListener (events.js:168:15)
at Socket.EventEmitter.once (events.js:189:8)
at Socket.setTimeout (net.js:167:12)
at ClientRequest.setTimeout (http.js:1549:17)
at ClientRequest.setTimeout (http.js:1561:10)
at ClientRequest.g (events.js:185:14)
at ClientRequest.EventEmitter.emit (events.js:115:20)
at ClientRequest.onSocket (http.js:1506:9)
at process.startup.processNextTick.process._tickCallback (node.js:244:9)

fredericgermain

I've created a pull request for the last problem : #3788
I dunno how to associate it with this issue, but it's not related to the initial problem of this issue anyway ...

Isaac Z. Schlueter
Collaborator

The original issue here was fixed by a9fc63f.

Isaac Z. Schlueter isaacs closed this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.