Network connection issues Error: getaddrinfo EMFILE

[LittleBear-6w6]

Version

17.0.1

Platform

Docker container on Linux

Subsystem

GetAddrInfoReqWrap.onlookup [as oncomplete]

What steps will reproduce the bug?

I boot frontend application container and backend application container on docker engine in Linux.
This frontend application container connects to backend application container on docker network if being accessed.
Booting for 2~4 weeks, this frontend application container can't connects to backend application container.

How often does it reproduce? Is there a required condition?

Twice in 2 months.
Accessed about 6,000 times before stopping.

What is the expected behavior?

This frontend application container can connects to backend application container on docker network.

What do you see instead?

I'm getting these stack traces:

[ERROR] Error: getaddrinfo EMFILE backend-service
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:72:26) {
  errno: -24,
  code: 'EMFILE',
  syscall: 'getaddrinfo',
  hostname: 'backend-service',
  config: {
    url: 'http://backend-service:9999/api/xxxx',
    method: 'post',
    data: '{"applicationId":"xxxxxxxxxx","apiAccessTime":"xxxx/xx/xx xx:xx:xx.xxx"}',
    headers: {
      Accept: 'application/json, text/plain, */*',
      'Content-Type': 'application/json',
      'User-Agent': 'axios/0.21.4',
      'Content-Length': 72
    },
    transformRequest: [ [Function: transformRequest] ],
    transformResponse: [ [Function: transformResponse] ],
    timeout: 0,
    adapter: [Function: httpAdapter],
    xsrfCookieName: 'XSRF-TOKEN',
    xsrfHeaderName: 'X-XSRF-TOKEN',
    maxContentLength: -1,
    maxBodyLength: -1,
    validateStatus: [Function: validateStatus],
    transitional: {
      silentJSONParsing: true,
      forcedJSONParsing: true,
      clarifyTimeoutError: false
    }
  },
  request: <ref *1> Writable {
    _writableState: WritableState {
      objectMode: false,
      highWaterMark: 16384,
      finalCalled: false,
      needDrain: false,
      ending: false,
      ended: false,
      finished: false,
      destroyed: false,
      decodeStrings: true,
      defaultEncoding: 'utf8',
      length: 0,
      writing: false,
      corked: 0,
      sync: true,
      bufferProcessing: false,
      onwrite: [Function: bound onwrite],
      writecb: null,
      writelen: 0,
      afterWriteTickInfo: null,
      buffered: [],
      bufferedIndex: 0,
      allBuffers: true,
      allNoop: true,
      pendingcb: 0,
      constructed: true,
      prefinished: false,
      errorEmitted: false,
      emitClose: true,
      autoDestroy: true,
      errored: null,
      closed: false,
      closeEmitted: false,
      [Symbol(kOnFinished)]: []
    },
    _events: [Object: null prototype] {
      response: [Function: handleResponse],
      error: [Function: handleRequestError]
    },
    _eventsCount: 2,
    _maxListeners: undefined,
    _options: {
      maxRedirects: 21,
      maxBodyLength: 10485760,
      protocol: 'http:',
      path: '/api/xxxx',
      method: 'POST',
      headers: [Object],
      agent: undefined,
      agents: [Object],
      auth: undefined,
      hostname: 'backend-service',
      port: '9999',
      nativeProtocols: [Object],
      pathname: '/api/xxxx'
    },
    _ended: false,
    _ending: true,
    _redirectCount: 0,
    _redirects: [],
    _requestBodyLength: 72,
    _requestBodyBuffers: [ [Object] ],
    _onNativeResponse: [Function (anonymous)],
    _currentRequest: ClientRequest {
      _events: [Object: null prototype],
      _eventsCount: 7,
      _maxListeners: undefined,
      outputData: [],
      outputSize: 0,
      writable: true,
      destroyed: false,
      _last: true,
      chunkedEncoding: false,
      shouldKeepAlive: false,
      maxRequestsOnConnectionReached: false,
      _defaultKeepAlive: true,
      useChunkedEncodingByDefault: true,
      sendDate: false,
      _removedConnection: false,
      _removedContLen: false,
      _removedTE: false,
      _contentLength: null,
      _hasBody: true,
      _trailer: '',
      finished: false,
      _headerSent: true,
      _closed: false,
      socket: [Socket],
      _header: 'POST /api/xxxx HTTP/1.1\r\n' +
        'Accept: application/json, text/plain, */*\r\n' +
        'Content-Type: application/json\r\n' +
        'User-Agent: axios/0.21.4\r\n' +
        'Content-Length: 72\r\n' +
        'Host: backend-service:9999\r\n' +
        'Connection: close\r\n' +
        '\r\n',
      _keepAliveTimeout: 0,
      _onPendingData: [Function: nop],
      agent: [Agent],
      socketPath: undefined,
      method: 'POST',
      maxHeaderSize: undefined,
      insecureHTTPParser: undefined,
      path: '/api/xxxx',
      _ended: false,
      res: null,
      aborted: false,
      timeoutCb: null,
      upgradeOrConnect: false,
      parser: null,
      maxHeadersCount: null,
      reusedSocket: false,
      host: 'backend-service',
      protocol: 'http:',
      _redirectable: [Circular *1],
      [Symbol(kCapture)]: false,
      [Symbol(kNeedDrain)]: false,
      [Symbol(corked)]: 0,
      [Symbol(kOutHeaders)]: [Object: null prototype]
    },
    _currentUrl: 'http://backend-service:9999/api/xxxx',
    [Symbol(kCapture)]: false
  },
  response: undefined,
  isAxiosError: true,
  toJSON: [Function: toJSON]
}

Additional information

Docker logs shows "EMFILE: too many open files".

[LittleBear-6w6]

Using docker image is node:17.0.1 from dockerhub

[theanarkh]

EMFILE indicates that the number of files your process have opened has reached the upper limit. Perhaps you can run lsof -p your_pid to see how many files your process has opened.

[LittleBear-6w6]

Thanks for your comment!
I think so. But I don't understand why the number of files my process have opened has reached the upper limit.
My frontend application doesn't open any local files.
I know that the network sockets are used as file on Linux system. So I guess that the socket connecting to backend application has remain open since the frontend application connected to backend application.
In case of socket programing in Node.js, I know that I should write statement that the socket close.
But I use Node.js as JavaScript runtime(engine). In this case, I think Node.js close socket automatically.
If I should write statement that socket close in this case, please tell me how to write statement in my application code in JavaScript! Additionally, please tell me URL of documentation written about usage and example if possible!

[bnoordhuis]

I've converted this to a discussion as there's no reason to believe it's a bug in node itself.

[LittleBear-6w6]

Thanks for converting to a discussion!
I was not sure that it's a bug in node itself.
I hope I can find any solutions in this discussion.
Could you tell me as much as you know about this current situation, even if it's not much!

[LittleBear-6w6]

Can I solve this problem if I use latest version?
I read node/CHANGELOG_V17.md.
I find that some fixes on network socket are committed.
For example
0aacd4926d - http2: handle existing socket data when creating HTTP/2 server sessions (Tim Perry) nodejs/node#41185
80ce97f514- http: change totalSocketCount only on socket creation/close (Subhi Al Hasan) nodejs/node#40572

[bnoordhuis]

I'd start by figuring out if your program is actually leaking file descriptors. Maybe the file descriptor limit is simply set too low and you just need to tweak ulimit -n. Run lsof or netstat to see open connections, etc.

[LittleBear-6w6]

Thank you so much for your comment! I could find the solution thanks to your advice.
I found that my program was actually leaking file descriptors due to a elementary bug on writing logs.
Sorry about the fuss!

As a matter of fact, my program open local file to write logs by log4js-node library.
It open log file whenever it write logs. Therefore this problem has occurred because file descriptors was being wasted.
I fix my program and I'd like to keep an eye on it for a while.

[LittleBear-6w6]

I found that my program was actually leaking file descriptors due to a elementary bug on writing logs.
As a matter of fact, my program open local file to write logs by log4js-node library.
It open log file whenever it write logs. Therefore this problem has occurred because file descriptors was being wasted.
I fix my program and I'd like to keep an eye on it for a while.