Node.jsで「Error: getaddrinfo EMFILE」というエラーが出る

Docker上でNode.js + Nuxt.js + log4js-nodeで開発したアプリケーションを稼働したときの障害に対してどのように原因追求したかの記録

# 事象
Docker上にNode.js + Nuxt.js + log4js-nodeで構築したフロントエンドアプリとバックエンドアプリの間のHTTP通信が稼働２～４週間後に通信不能となった。

![Qiita_SystemPlatfrom.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/1793264/f961e197-1be5-3073-e60f-c72869e7f320.png)

スタックトレースとしは、下記を得ている。
```text: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]
}
```

Docker logsには、次のように１行だけ出ていた・・・・。
```docker:docker logs
EMFILE: too many open files
```

#  原因探究
## 1. Google先生に尋ねる編
通常は、この手のエラーはファイルの開き過ぎで起こる。しかし、今回はファイル開いていると言ってもログファイル１つだけであったので、別の原因かと思い調査を開始！
（↑後に思い違いだとわかるが・・・・、ここで深く考えていれば早期解決につながっていたかも）
キーワードとなりそうな ***「EMFLIE」***、***「getaddrinfo EMFILE」*** という単語で検索！
[***メモリリーク***](https://stackoverflow.com/questions/34952121/can-memory-leaks-cause-getaddrinfo-emfile)なんていう恐ろしいワードもヒットもヒットしたり（汗）

Linuxの場合、ネットワークソケットもファイルとして扱わることを思い出し、フロントエンドとバックエンド間のソケット通信が開放されない？のかと思い始める。

## 2.Twitterで情報提供を呼びかける編
<blockquote class="twitter-tweet"><p lang="ja" dir="ltr">Node.js v17.0.1って、ソケットが解放されないバクがある？？<br>コンテナのベースLinuxで、emfile too many openエラーが出てる💦<a href="https://twitter.com/hashtag/Nodejs?src=hash&amp;ref_src=twsrc%5Etfw">#Nodejs</a> <a href="https://twitter.com/hashtag/%E3%82%B3%E3%83%B3%E3%83%86%E3%83%8A?src=hash&amp;ref_src=twsrc%5Etfw">#コンテナ</a> <a href="https://twitter.com/hashtag/Docker?src=hash&amp;ref_src=twsrc%5Etfw">#Docker</a> <a href="https://twitter.com/hashtag/%E6%83%85%E5%A0%B1%E6%B1%82%E3%82%80?src=hash&amp;ref_src=twsrc%5Etfw">#情報求む</a></p>&mdash; LittleBear (@littlebear_6w6) <a href="https://twitter.com/littlebear_6w6/status/1519433119589302273?ref_src=twsrc%5Etfw">April 27, 2022</a></blockquote> <script async src="https://platform.twitter.com/widgets.js" charset="utf-8"></script>

###### 残念ながら有益な情報は得られず・・・・

## 3. Node.jsコミュニティにIssue投稿 & Discussion編
Node.jsでソケットが開放されないバグがあるんだろうと、息まえてIssueを投稿！

https://github.com/nodejs/node/issues/42906#issue-1220525137

TwitterでもIssue投稿したことを報告して情報提供を引き続き待つ！
<blockquote class="twitter-tweet"><p lang="ja" dir="ltr">どこにissue投げたら良いかわからないから、Node.jsのissueに投稿してみた。<a href="https://t.co/BoC9KFNRaI">https://t.co/BoC9KFNRaI</a><a href="https://twitter.com/hashtag/NodeJS?src=hash&amp;ref_src=twsrc%5Etfw">#NodeJS</a> <a href="https://twitter.com/hashtag/issues?src=hash&amp;ref_src=twsrc%5Etfw">#issues</a></p>&mdash; LittleBear (@littlebear_6w6) <a href="https://twitter.com/littlebear_6w6/status/1520003855718572033?ref_src=twsrc%5Etfw">April 29, 2022</a></blockquote> <script async src="https://platform.twitter.com/widgets.js" charset="utf-8"></script>

１日後、Node.jsコミュニティよりIssueがCloseされて、コアメンバーのBen Noordhuis([@bnoordhuis](https://github.com/bnoordhuis))氏によりDiscussionにスレを移設していただき継続議論となった。
移設理由は、「Node.js本体のバグを疑う明確な理由がない」というものだった。
***↑それは、そうだよね～！ソケットが開放されないバグがあったら一大事だわ！***

https://github.com/nodejs/node/discussions/42930#discussion-4044834

TwitterでもDiscussionに移設されたことを報告して追加情報を待つ！
<blockquote class="twitter-tweet"><p lang="ja" dir="ltr">バクじゃないということで、Discussionに移設された。<br>解決策が早く見つかるといいんだけどな。<a href="https://twitter.com/hashtag/Nodejs?src=hash&amp;ref_src=twsrc%5Etfw">#Nodejs</a> <a href="https://twitter.com/hashtag/Node?src=hash&amp;ref_src=twsrc%5Etfw">#Node</a> <a href="https://twitter.com/hashtag/github?src=hash&amp;ref_src=twsrc%5Etfw">#github</a> <a href="https://twitter.com/hashtag/javascript?src=hash&amp;ref_src=twsrc%5Etfw">#javascript</a> <a href="https://t.co/SgTcGf08Jp">https://t.co/SgTcGf08Jp</a></p>&mdash; LittleBear (@littlebear_6w6) <a href="https://twitter.com/littlebear_6w6/status/1520592522002587648?ref_src=twsrc%5Etfw">May 1, 2022</a></blockquote> <script async src="https://platform.twitter.com/widgets.js" charset="utf-8"></script>

### Ben Noordhuis氏より[「DockerのベースLinuxイメージで指定しているファイルディスプリタのMax値が低いのでは？」という有益な情報](https://github.com/nodejs/node/discussions/42930#discussioncomment-2668220)を得た！ ###

早速、調査を開始した！
`ulimit -n`でファイルディスプリタのMax値を確認したところ、「1,048,576」であった。
充分過ぎて問題ないじゃん！
そしたら、Node.js上で稼働しているアプリケーションプロセスが今開いているファイル数を`cat /proc/プロセスID/fd | wc -l`で確認すると「31722」で多いじゃん・・・！
どんなファイル開いているのよ～、`ls /proc/プロセスID/fd`で確認・・・・
***沈黙・・・・・***
**開発したアプリケーションが出力するログファイルが大量にリストに登場！！！（しかも同一ファイルを多重で開いている状況）**
**アプリケーションのバグじゃねか（汗）！**
ちなみに、ソケットは`ls /proc/プロセスID/fd | grep "socket"`を実行--->１行のみ。
やっぱりソケットは１つだけか！

## ～～～バグ原因の~~推定~~ 断定～～～
アプリログの出力を[log4js-nodeライブラリ](https://www.npmjs.com/package/log4js)を使用している。
ログ出力するたびにconfigureしてログファイルのオープンをしていた。
~~Node.jsはWebサーバで通信が終わってもプロセスは終了しないため、オープンしたログファイルが閉じられずに累積してしまったと推定される・・・。~~
**2022/06/19 事象の再現に成功し、バグ原因と断定**
Node.jsはWebサーバで通信が終わってもプロセスは終了しないため、オープンしたログファイルが閉じられずに累積してしまっていた。

## Node.jsコミュニティのDiscussionに解決報告
https://github.com/nodejs/node/discussions/42930#discussioncomment-2677639


### 最後になりますが、解決の糸口をくださったBen Noordhuis氏に御礼申し上げます！