Reusing HTTP connection lead to no destroy triggered

[winguse]

• Version: v8.9.0
• Platform: Linux cms-03 4.4.0-1052-aws #61-Ubuntu SMP Mon Feb 12 23:05:58 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: NaN

poc.js:

const http = require('http');

const agent = new http.Agent({
    keepAlive: true
});

function get(id) {
    http.get({
        host: 'www.google.com',
        path: '/generate_204',
        agent
    }, () => {
        console.log('get response #' + id);
    });
}

for (let i = 0; i < 5; i++) {
    get(i);
}

run it with why-is-node-running:

$ why-is-node-running poc.js
probing program /root/poc.js
kill -SIGUSR1 32671 for logging
get response #0
get response #4
get response #3
get response #1
get response #2
There are 11 handle(s) keeping the process running

# SIGNALWRAP
/usr/lib/node_modules/why-is-node-running/include.js:3 - process.on('SIGUSR1', function() { why() })

# TCPWRAP
/root/poc.js:8 - http.get({

# TCPWRAP
/root/poc.js:8 - http.get({

# TCPWRAP
/root/poc.js:8 - http.get({

# TCPWRAP
/root/poc.js:8 - http.get({

# TCPWRAP
/root/poc.js:8 - http.get({

# HTTPPARSER
(unknown stack trace)

# HTTPPARSER
(unknown stack trace)

# HTTPPARSER
(unknown stack trace)

# HTTPPARSER
(unknown stack trace)

# HTTPPARSER
(unknown stack trace)

if there are requests to the same endpoint, the socket never closed and those destroys never get called.

---

old description

Hi team,

Thanks for the awesome job!

I am using the async_hooks in our production, but I've found some memory issue that possible related to async_hooks.

For debugging, I created a counter variable:

• when init hook is called, increase by 1
• when destroy hook is called, decrease by 1

And I got the following chart for the past 1.5 days (2018-04-05T13:06:12.724Z to 2018-04-06T22:46:53.753Z)

As check with pm2 info, the the chart above drop down to 0 is the time pm2 when restart the application.

And here is the memory usage:

As comparing, this is what the memory looks like one week before:

Our application is a web service running on top of restify.

The memory is consumption may beyond your expectation, it's because of I am holding some resource after init is called and those resource's releasing require destroy to be called.

Any ideas?

[Trott]

@nodejs/async_hooks

[ofrobots]

For debugging, I created a counter variable:
when init hook is called, increase by 1
when destroy hook is called, decrease by 1

If you have a leaking resource in the application, one would observe the above counter to increment. This doesn't necessarily indicate a leak in async hooks, but more likely in the application itself.

As comparing, this is what the memory looks like one week before:

You didn't specify how the code was different a week before. I am guessing that you didn't have async hooks enabled then. If that's the case, my main suspicion would be the hook functions you're installing. Are you storing the resource objects into a array/map/set etc.? That's an easy way to write a memory leak. Keeping a reference to the resources will prevent them from getting garbage collected, preventing the destroy hook from being called.

[winguse]

Thanks for reply! I do use map to keep an object in side hooks:

• when init I add it
• when destroy I want to remove it

But destroy looks not called as I expected. What do you suggest me to do?

[winguse]

BTW, I did not touch the resource object passed in init function. You may check here: https://github.com/Tubitv/envoy-node/blob/dbc512fa1df73203a75cd0cc03b2b251fa597da8/src/envoy-context-store.ts#L55

[winguse]

Closed by mistake, sorry

[winguse]

@ofrobots is there any possibility that in our application (code run under restify, not under createHook) code has memory leak issues that stop async_hooks' destroy from being called?

[AndreasMadsen]

@winguse I think that is the most likely cause. You could try running https://github.com/mafintosh/why-is-node-running to see what isn't being destroyed.

[winguse]

Thanks @AndreasMadsen , I can see it's some problem of our code. It looks like our conversion from generator code to promise has some problems. The reason why we didn't see them before may due to it's not wasting too many memory.

[winguse]

As dig into detail, I find that it's not the generator problem -- they are destroyed a little bit late.

And as I collect data from our production, over 99.9% not destroyed stacks are this one:

TCPWRAP

at Agent.addRequest (_http_agent.js:178:22)
at new ClientRequest (_http_client.js:258:16)
at Object.request (http.js:38:10)
at Request.start (.../node_modules/request/request.js:748:32)
at Request.end (.../node_modules/request/request.js:1512:10)
at end (.../node_modules/request/request.js:561:14)
at Immediate. (.../node_modules/request/request.js:575:7)
at runCallback (timers.js:789:20)
at tryOnImmediate (timers.js:751:5)
at processImmediate [as _immediateCallback] (timers.js:722:5)

in the top of the stack, i see this code: socket._handle.asyncReset();

    if (socket._handle && typeof socket._handle.asyncReset === 'function') {
      // Assign the handle a new asyncId and run any init() hooks.
      socket._handle.asyncReset();
      socket[async_id_symbol] = socket._handle.getAsyncId();
    }

I have no ideas about it, anyone can help?

[winguse]

I find the root cause of this now, it's because we are using request({ forever: true }) for reusing the http connection.

And request will use:

new http.Agent({
  keepAlive: true
});

updated the title and description as above.

[AndreasMadsen]

@winguse Do you still think this is an issue with node.js? If so, could you try writing up a test case?