0
Help us understand the problem. What are the problem?

posted at

updated at

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

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

事象

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

Qiita_SystemPlatfrom.png

スタックトレースとしは、下記を得ている。

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には、次のように1行だけ出ていた・・・・。

docker logs
EMFILE: too many open files

原因探究

1. Google先生に尋ねる編

通常は、この手のエラーはファイルの開き過ぎで起こる。しかし、今回はファイル開いていると言ってもログファイル1つだけであったので、別の原因かと思い調査を開始!
(↑後に思い違いだとわかるが・・・・、ここで深く考えていれば早期解決につながっていたかも)
キーワードとなりそうな 「EMFLIE」「getaddrinfo EMFILE」 という単語で検索!
メモリリークなんていう恐ろしいワードもヒットもヒットしたり(汗)

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

2.Twitterで情報提供を呼びかける編

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

3. Node.jsコミュニティにIssue投稿 & Discussion編

Node.jsでソケットが開放されないバグがあるんだろうと、息まえてIssueを投稿!

TwitterでもIssue投稿したことを報告して情報提供を引き続き待つ!

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

TwitterでもDiscussionに移設されたことを報告して追加情報を待つ!

Ben Noordhuis氏より「DockerのベースLinuxイメージで指定しているファイルディスプリタのMax値が低いのでは?」という有益な情報を得た!

早速、調査を開始した!
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"を実行--->1行のみ。
やっぱりソケットは1つだけか!

~~~バグ原因の推定 断定~~~

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

Node.jsコミュニティのDiscussionに解決報告

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

Register as a new user and use Qiita more conveniently

  1. You can follow users and tags
  2. you can stock useful information
  3. You can make editorial suggestions for articles
What you can do with signing up
0
Help us understand the problem. What are the problem?