Docker上でNode.js + Nuxt.js + log4js-nodeで開発したアプリケーションを稼働したときの障害に対してどのように原因追求したかの記録
事象
Docker上にNode.js + Nuxt.js + log4js-nodeで構築したフロントエンドアプリとバックエンドアプリの間のHTTP通信が稼働２～４週間後に通信不能となった。
スタックトレースとしは、下記を得ている。
[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には、次のように１行だけ出ていた・・・・。
EMFILE: too many open files
原因探究
1. Google先生に尋ねる編
通常は、この手のエラーはファイルの開き過ぎで起こる。しかし、今回はファイル開いていると言ってもログファイル１つだけであったので、別の原因かと思い調査を開始！
（↑後に思い違いだとわかるが・・・・、ここで深く考えていれば早期解決につながっていたかも）
キーワードとなりそうな 「EMFLIE」、「getaddrinfo EMFILE」 という単語で検索！
メモリリークなんていう恐ろしいワードもヒットもヒットしたり（汗）
Linuxの場合、ネットワークソケットもファイルとして扱わることを思い出し、フロントエンドとバックエンド間のソケット通信が開放されない？のかと思い始める。
2.Twitterで情報提供を呼びかける編
Node.js v17.0.1って、ソケットが解放されないバクがある？？
— LittleBear (@littlebear_6w6) April 27, 2022
コンテナのベースLinuxで、emfile too many openエラーが出てる💦#Nodejs #コンテナ #Docker #情報求む
残念ながら有益な情報は得られず・・・・
3. Node.jsコミュニティにIssue投稿 & Discussion編
Node.jsでソケットが開放されないバグがあるんだろうと、息まえてIssueを投稿！
TwitterでもIssue投稿したことを報告して情報提供を引き続き待つ！
どこにissue投げたら良いかわからないから、Node.jsのissueに投稿してみた。https://t.co/BoC9KFNRaI#NodeJS #issues
— LittleBear (@littlebear_6w6) April 29, 2022
１日後、Node.jsコミュニティよりIssueがCloseされて、コアメンバーのBen Noordhuis(@bnoordhuis)氏によりDiscussionにスレを移設していただき継続議論となった。
移設理由は、「Node.js本体のバグを疑う明確な理由がない」というものだった。
↑それは、そうだよね～！ソケットが開放されないバグがあったら一大事だわ！
TwitterでもDiscussionに移設されたことを報告して追加情報を待つ！
バクじゃないということで、Discussionに移設された。
— LittleBear (@littlebear_6w6) May 1, 2022
解決策が早く見つかるといいんだけどな。#Nodejs #Node #github #javascript https://t.co/SgTcGf08Jp
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"を実行--->１行のみ。
やっぱりソケットは１つだけか！
～～～バグ原因の推定 断定～～～
アプリログの出力をlog4js-nodeライブラリを使用している。
ログ出力するたびにconfigureしてログファイルのオープンをしていた。
Node.jsはWebサーバで通信が終わってもプロセスは終了しないため、オープンしたログファイルが閉じられずに累積してしまったと推定される・・・。
2022/06/19 事象の再現に成功し、バグ原因と断定
Node.jsはWebサーバで通信が終わってもプロセスは終了しないため、オープンしたログファイルが閉じられずに累積してしまっていた。
Node.jsコミュニティのDiscussionに解決報告