Node: In node V 9.0.0, HTTP Client Agent is leaking when reusing a socket in HTTP Request

[CesarLRosa]

• Version: 9.0.0
• Platform: x86_64 GNU/Linux
• Subsystem: core http

This is the first issue that I open. I apologize in advanced if I did something wrong...

When making HTTP requests with an HTTP Agent to make the reuse of the connected socket, I got the following warning:

• (node:27613) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connect listeners added. Use emitter.setMaxListeners() to increase limit

I look at the source, and I discovered that this block of code is causing the leak:
https://github.com/nodejs/node/blob/master/lib/_http_client.js#L731-L733

In node 8.9.0, there isn't the * sock.once('connect', function() { block, only the line * sock.setTimeout(msecs, emitTimeout);. I change those lines to ** block, only the line * sock.setTimeout(msecs, emitTimeout); in node 9.0.0 and everything work just fine.

Here is the code that can evidence the problem:

"use strict";

const util = require('util');

const http = require("http");

const agentOptions = new Object();
agentOptions.keepAlive = true;
agentOptions.keepAliveMsecs = 15000;
agentOptions.maxSockets = 32;
agentOptions.maxFreeSockets = 32;

const httpAgent = new http.Agent(agentOptions);


const requestObj = new Object();
requestObj.host = '127.0.0.1';
requestObj.port = 55001;
requestObj.method = 'GET';
requestObj.path = '/';


requestObj.agent = httpAgent;


var counter = 0;



process.on('warning', function(emmiter) {

  console.error(`process.on warning ${util.inspect(emmiter)}`);

});



const doRequest = function(requestObj) {

  const req = http.request(requestObj, httpOk);

  req.on('error', httpError);

  req.setTimeout(15000, httpTimeout);

  req.end();

}


const httpTimeout = function(err) {

  console.error(`httpError():err=${err}`);

}

const httpError = function(err) {

  console.error(`httpError():err=${err}`);

}


const onResponseError = function(err) {

  console.error(`onResponseError():err=${err}`);

}

const onResponseEnd = function() {

  if (counter != 20000) {

    doRequest(requestObj);

    if ((counter % 1000) == 0) {
      console.log(`onResponseEnd():Make ${counter} requests ok.`);
    }

  } else {
    console.log(`onResponseEnd():Done.`);
  }

}


const onResponseData = function(data) {

}


const httpOk = function(response) {

  response.on('data', onResponseData);
  response.on('end', onResponseEnd);
  response.on('error', onResponseError);

  if (response.statusCode == 200) {

    counter++;

  } else {
    console.log(`httpOk():Got Unexpected response=${response.statusCode}`);
  }

}


doRequest(requestObj);

Here is an server code that can be used with the client above:

"use strict";


const onRequest = function(request, response) {
  response.on('error', function(e) {console.log(`Error ${e} ${e.stack}`)});
  response.end();

}

const port = 55001;
const http = require("http");

const server = http.createServer(onRequest);

server.listen(port);
console.log(`Server is listening on port '${port}'`);

If the socket in the HTTP Agent is reused for thousands of requests without be closed, it can cause the node process to stop because there is no more memory to allocate.

Here is the output of the client code in node 8.9.0:
./node-v8.9.0/bin/node --use_strict main-httpAgentClient.js
onResponseEnd():Make 1000 requests ok.
onResponseEnd():Make 2000 requests ok.
onResponseEnd():Make 3000 requests ok.
onResponseEnd():Make 4000 requests ok.
onResponseEnd():Make 5000 requests ok.
onResponseEnd():Make 6000 requests ok.
onResponseEnd():Make 7000 requests ok.
onResponseEnd():Make 8000 requests ok.
onResponseEnd():Make 9000 requests ok.
onResponseEnd():Make 10000 requests ok.
onResponseEnd():Make 11000 requests ok.
onResponseEnd():Make 12000 requests ok.
onResponseEnd():Make 13000 requests ok.
onResponseEnd():Make 14000 requests ok.
onResponseEnd():Make 15000 requests ok.
onResponseEnd():Make 16000 requests ok.
onResponseEnd():Make 17000 requests ok.
onResponseEnd():Make 18000 requests ok.
onResponseEnd():Make 19000 requests ok.
onResponseEnd():Done.

Here is the output of the client code in node 9.0.0:
/node-v9.0.0-ORIG/bin/node --use_strict main-httpAgentClient.js
(node:27930) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connect listeners added. Use emitter.setMaxListeners() to increase limit
process.on warning { MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connect listeners added. Use emitter.setMaxListeners() to increase limit
at _addListener (events.js:289:19)
at Socket.addListener (events.js:306:10)
at Socket.Readable.on (_stream_readable.js:775:35)
at Socket.once (events.js:349:8)
at ClientRequest. (_http_client.js:731:10)
at Object.onceWrapper (events.js:324:30)
at emitOne (events.js:130:20)
at ClientRequest.emit (events.js:221:7)
at tickOnSocket (_http_client.js:656:7)
at onSocketNT (_http_client.js:672:5)
name: 'MaxListenersExceededWarning',
emitter:
Socket {
connecting: false,
_hadError: false,
_handle:
TCP {
reading: true,
owner: [Circular],
onread: [Function: onread],
onconnection: null,
writeQueueSize: 0 },
_parent: null,
_host: null,
_readableState:
ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: [BufferList],
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
destroyed: false,
defaultEncoding: 'utf8',
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null },
readable: true,
domain: null,
_events:
{ end: [Array],
finish: [Function: onSocketFinish],
_socketEnd: [Function: onSocketEnd],
free: [Function: onFree],
close: [Array],
agentRemove: [Function: onRemove],
connect: [Array],
drain: [Function: ondrain],
error: [Function: socketErrorListener],
data: [Function: socketOnData] },
_eventsCount: 10,
_maxListeners: undefined,
_writableState:
WritableState {
objectMode: false,
highWaterMark: 16384,
finalCalled: false,
needDrain: false,
ending: false,
ended: false,
finished: false,
destroyed: false,
decodeStrings: false,
defaultEncoding: 'utf8',
length: 0,
writing: false,
corked: 0,
sync: false,
bufferProcessing: false,
onwrite: [Function: bound onwrite],
writecb: null,
writelen: 0,
bufferedRequest: null,
lastBufferedRequest: null,
pendingcb: 0,
prefinished: false,
errorEmitted: false,
bufferedRequestCount: 0,
corkedRequestsFree: [Object] },
writable: true,
allowHalfOpen: false,
_bytesDispatched: 780,
_sockname: null,
_pendingData: null,
_pendingEncoding: '',
server: null,
_server: null,
parser:
HTTPParser {
'0': [Function: parserOnHeaders],
'1': [Function: parserOnHeadersComplete],
'2': [Function: parserOnBody],
'3': [Function: parserOnMessageComplete],
'4': null,
_headers: [],
_url: '',
_consumed: false,
socket: [Circular],
incoming: null,
outgoing: [ClientRequest],
maxHeaderPairs: 2000,
onIncoming: [Function: parserOnIncomingClient] },
_httpMessage:
ClientRequest {
domain: null,
_events: [Object],
_eventsCount: 3,
_maxListeners: undefined,
output: [],
outputEncodings: [],
outputCallbacks: [],
outputSize: 0,
writable: true,
_last: true,
upgrading: false,
chunkedEncoding: false,
shouldKeepAlive: true,
useChunkedEncodingByDefault: false,
sendDate: false,
_removedConnection: false,
_removedContLen: false,
_removedTE: false,
_contentLength: 0,
_hasBody: true,
_trailer: '',
finished: true,
_headerSent: true,
socket: [Circular],
connection: [Circular],
_header: 'GET / HTTP/1.1rnHost: 127.0.0.1:55001rnConnection: keep-alivernrn',
_onPendingData: [Function: noopPendingOutput],
agent: [Agent],
socketPath: undefined,
timeout: undefined,
method: 'GET',
path: '/',
_ended: false,
res: null,
aborted: undefined,
timeoutCb: [Function: emitTimeout],
upgradeOrConnect: false,
parser: [HTTPParser],
maxHeadersCount: null,
[Symbol(outHeadersKey)]: [Object] },
read: [Function],
_consuming: true,
_idleTimeout: -1,
_idleNext: null,
_idlePrev: null,
_idleStart: 60,
_destroyed: false,
[Symbol(asyncId)]: 278,
[Symbol(bytesRead)]: 0,
[Symbol(asyncId)]: 14,
[Symbol(triggerAsyncId)]: 9 },
type: 'connect',
count: 11 }
(node:27930) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connect listeners added. Use emitter.setMaxListeners() to increase limit
process.on warning { MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connect listeners added. Use emitter.setMaxListeners() to increase limit
at _addListener (events.js:289:19)
at Socket.addListener (events.js:306:10)
at Socket.Readable.on (_stream_readable.js:775:35)
at Socket.once (events.js:349:8)
at ClientRequest. (_http_client.js:731:10)
at Object.onceWrapper (events.js:324:30)
at emitOne (events.js:130:20)
at ClientRequest.emit (events.js:221:7)
at tickOnSocket (_http_client.js:656:7)
at onSocketNT (_http_client.js:672:5)
name: 'MaxListenersExceededWarning',
emitter:
Socket {
connecting: false,
_hadError: false,
_handle:
TCP {
reading: true,
owner: [Circular],
onread: [Function: onread],
onconnection: null,
writeQueueSize: 0 },
_parent: null,
_host: null,
_readableState:
ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: [BufferList],
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
destroyed: false,
defaultEncoding: 'utf8',
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null },
readable: true,
domain: null,
_events:
{ end: [Array],
finish: [Function: onSocketFinish],
_socketEnd: [Function: onSocketEnd],
free: [Function: onFree],
close: [Array],
agentRemove: [Function: onRemove],
connect: [Array],
drain: [Function: ondrain],
error: [Function: socketErrorListener],
data: [Function: socketOnData] },
_eventsCount: 10,
_maxListeners: undefined,
_writableState:
WritableState {
objectMode: false,
highWaterMark: 16384,
finalCalled: false,
needDrain: false,
ending: false,
ended: false,
finished: false,
destroyed: false,
decodeStrings: false,
defaultEncoding: 'utf8',
length: 0,
writing: false,
corked: 0,
sync: false,
bufferProcessing: false,
onwrite: [Function: bound onwrite],
writecb: null,
writelen: 0,
bufferedRequest: null,
lastBufferedRequest: null,
pendingcb: 0,
prefinished: false,
errorEmitted: false,
bufferedRequestCount: 0,
corkedRequestsFree: [Object] },
writable: true,
allowHalfOpen: false,
_bytesDispatched: 780,
_sockname: null,
_pendingData: null,
_pendingEncoding: '',
server: null,
_server: null,
parser:
HTTPParser {
'0': [Function: parserOnHeaders],
'1': [Function: parserOnHeadersComplete],
'2': [Function: parserOnBody],
'3': [Function: parserOnMessageComplete],
'4': null,
_headers: [],
_url: '',
_consumed: false,
socket: [Circular],
incoming: null,
outgoing: [ClientRequest],
maxHeaderPairs: 2000,
onIncoming: [Function: parserOnIncomingClient] },
_httpMessage:
ClientRequest {
domain: null,
_events: [Object],
_eventsCount: 3,
_maxListeners: undefined,
output: [],
outputEncodings: [],
outputCallbacks: [],
outputSize: 0,
writable: true,
_last: true,
upgrading: false,
chunkedEncoding: false,
shouldKeepAlive: true,
useChunkedEncodingByDefault: false,
sendDate: false,
_removedConnection: false,
_removedContLen: false,
_removedTE: false,
_contentLength: 0,
_hasBody: true,
_trailer: '',
finished: true,
_headerSent: true,
socket: [Circular],
connection: [Circular],
_header: 'GET / HTTP/1.1rnHost: 127.0.0.1:55001rnConnection: keep-alivernrn',
_onPendingData: [Function: noopPendingOutput],
agent: [Agent],
socketPath: undefined,
timeout: undefined,
method: 'GET',
path: '/',
_ended: false,
res: null,
aborted: undefined,
timeoutCb: [Function: emitTimeout],
upgradeOrConnect: false,
parser: [HTTPParser],
maxHeadersCount: null,
[Symbol(outHeadersKey)]: [Object] },
read: [Function],
_consuming: true,
_idleTimeout: -1,
_idleNext: null,
_idlePrev: null,
_idleStart: 63,
_destroyed: false,
[Symbol(asyncId)]: 293,
[Symbol(bytesRead)]: 0,
[Symbol(asyncId)]: 29,
[Symbol(triggerAsyncId)]: 26 },
type: 'connect',
count: 11 }
onResponseEnd():Make 1000 requests ok.
onResponseEnd():Make 2000 requests ok.
onResponseEnd():Make 3000 requests ok.
onResponseEnd():Make 4000 requests ok.
onResponseEnd():Make 5000 requests ok.
onResponseEnd():Make 6000 requests ok.
onResponseEnd():Make 7000 requests ok.
onResponseEnd():Make 8000 requests ok.
onResponseEnd():Make 9000 requests ok.
onResponseEnd():Make 10000 requests ok.
onResponseEnd():Make 11000 requests ok.
onResponseEnd():Make 12000 requests ok.
onResponseEnd():Make 13000 requests ok.
onResponseEnd():Make 14000 requests ok.
onResponseEnd():Make 15000 requests ok.
onResponseEnd():Make 16000 requests ok.
onResponseEnd():Make 17000 requests ok.
onResponseEnd():Make 18000 requests ok.
onResponseEnd():Make 19000 requests ok.
onResponseEnd():Done.

Here is the output of the client code in node 9.0.0 with the fix:
./node-v9.0.0-NEW/bin/node --use_strict main-httpAgentClient.js
onResponseEnd():Make 1000 requests ok.
onResponseEnd():Make 2000 requests ok.
onResponseEnd():Make 3000 requests ok.
onResponseEnd():Make 4000 requests ok.
onResponseEnd():Make 5000 requests ok.
onResponseEnd():Make 6000 requests ok.
onResponseEnd():Make 7000 requests ok.
onResponseEnd():Make 8000 requests ok.
onResponseEnd():Make 9000 requests ok.
onResponseEnd():Make 10000 requests ok.
onResponseEnd():Make 11000 requests ok.
onResponseEnd():Make 12000 requests ok.
onResponseEnd():Make 13000 requests ok.
onResponseEnd():Make 14000 requests ok.
onResponseEnd():Make 15000 requests ok.
onResponseEnd():Make 16000 requests ok.
onResponseEnd():Make 17000 requests ok.
onResponseEnd():Make 18000 requests ok.
onResponseEnd():Make 19000 requests ok.
onResponseEnd():Done.

Thanks.

[maclover7]

@CesarLRosa Can you confirm that this did not occur in previous versions of Node, and first appeared in v9.0.0?

[apapirovski]

This looks like a result of https://github.com/nodejs/node/pull/8895 — ping @lpinca @nodejs/http

[lpinca]

It makes sense, the socket is reused and still connected so we only keep adding more listeners as the 'connect' event is not emitted.

It should be easily fixable by checking if the socket is connected and use the 'connect' listener only when it isn't.

[lpinca]

I'll work on a fix and add a regression test as soon as I can.

[lpinca]

@CesarLRosa can you confirm that this patch fixes the issue?

[CesarLRosa]

@lpinca
Yes, your patch fix the issue! I run the test that I posted on this issue, and several other tests to check the HTTP Agent behavior, and everything is working just fine!

Thanks a lot for the fast fixing!

[lpinca]

Let's keep this open until the patch lands in master.