- 2021/01/13 その後、問題が起きたので追記を書きました
はじめに
本記事は、某SNSにて「node-redが時々落ちる」という質問があり、その調査内容です。
実際には試行錯誤しているのですがサクッと、まとめています。
※再現環境を用意したかったのですが無理でした....
症状
さくらVPS の下記構成で、Node-REDを動作させていると不定期にNode-REDが再起動するとのこと。
- Centos 7
- CPU 1Core
- メモリ 512MB
- SSD 25GB
PM2 log
PM2 log: App [node-red:0] exited with code [0] via signal [SIGKILL]
SIGKILLは「何らかの理由で強制終了させられている」という事を示します。
調査
直接サーバー内を見せて頂く事になりましたので、Centosのログを確認してみます。
日付とホスト名はカットしてあります
$ cat /var/log/messages
kernel: node-red invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
kernel: node-red cpuset=/ mems_allowed=0
kernel: CPU: 0 PID: 21712 Comm: node-red Not tainted 3.10.0-957.12.2.el7.x86_64 #1
...略...
kernel: Swap cache stats: add 162358025, delete 162320555, find 105131914/129375220
kernel: Free swap = 3742716kB
kernel: Total swap = 4194300kB
...略...
kernel: Out of memory: Kill process 21712 (node-red) score 34 or sacrifice child
kernel: Killed process 21712 (node-red) total-vm:1355860kB, anon-rss:134392kB, file-rss:1144kB, shmem-rss:0kB
Linuxでは、物理メモリ以上のメモリを扱えるように仮想メモリの仕組みがあります。
oom-killerはメモリをどうしても確保できない場合にプロセスをKILLする死神みたいなヤツです。
何かが原因でメモリ不足になったので、node-redを殺したということのようです。
しかし、仮想メモリのSwapには余裕があるので、KILLする必要がない気もします。
おそらくswapでは解決できないメモリ不足に陥ったんでしょう。
kernel: Swap cache stats: add 162358025, delete 162320555, find 105131914/129375220
kernel: Free swap = 3742716kB
kernel: Total swap = 4194300kB
なんで、node-redがkillのターゲットになったのか？
『他のプロセスよりメモリを多く使っていたのでoom-killerに目をつけられた』ということなんでしょう。
実験
理由は不明ですが、oom-killerが発動すると、node-redがkillされたということは分かりました。
では、oom-killerがnode-redをkill出来ない場合はどうなるか？を実験してみることにしました。
まずは、node-red が oom-killer に殺されないように oom_score_adj = -1000 に設定します。
# pgrep node-red
353
# echo -1000 > /proc/353/oom_score_adj
# cat /proc/353/oom_score_adj
-1000
次にメモリを大量に確保するプログラムを実行してみます。
# include <malloc.h>
# include <memory.h>
int main(int argc, char** argv)
{
int i, sz = 16* 1024 * 1024;
void* p = 0;
for(i=0; i<800; i++ ) {
p = malloc(sz);
printf("[%d] %p\n", i, p);
if ( p ) {
memset(p, 0, sz);
}
}
return 0;
}
結果、 /var/log/messages には、下記のようなログが出力され main がKILLされています。
kernel: node-red invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=-1000
kernel: node-red cpuset=/ mems_allowed=0
...略...
kernel: Free swap = 59536kB
kernel: Total swap = 4194300kB
...略...
kernel: Out of memory: Kill process 27912 (main) score 787 or sacrifice child
kernel: Killed process 27912 (main) total-vm:3870952kB, anon-rss:336628kB, file-rss:408kB, shmem-rss:0kB
この結果から...
メモリ不足状態になると、oom-killerが発動し、KILL対象プロセスのoom_score_adjが-1000の場合は、
メモリを確保しようとしているプログラムがKILLされるように見えます(実際は違うかもしれませんが)。
この状態で放置して、oom-killerが発生するとメモリ不足を起こしているプログラムが特定できると予想できます。
ということで、しばらく放置してみると....
kernel: node-red invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=-1000
kernel: node-red cpuset=/ mems_allowed=0
...略...
kernel: Out of memory: Kill process 32139 (fail2ban-server) score 32 or sacrifice child
kernel: Killed process 32139 (fail2ban-server) total-vm:462736kB, anon-rss:145732kB, file-rss:1160kB, shmem-rss:920kB
はい。 fail2ban-server が 原因なのかな？と予想しました。
fail2ban
fail2ban-serverのバージョンを確認すると 0.9.7でした。
最新版は 0.11.2 でしたので、ChangeLogを調べてみると...
https://github.com/fail2ban/fail2ban/blob/0.11.2/ChangeLog
ver. 0.10.0-alpha-1 (2016/07/14) - ipv6-support-etc
にて、メモリリークの対策を行っているようなので、fail2banをアップデート。
しばらく放置しても、node-redが再起動する症状が発生しなくなりました。
まとめ
- fail2banのバージョンをチェックしましょう！
$ fail2ban-server --v
Fail2Ban v0.9.7
-
systemd → PM2 → Node-REDと起動する場合は、systemd の設定で oom_score_adj を -1000 にすると良いかも。
参考記事
https://qiita.com/poruruba/items/10df0d94e9127797498f
https://qiita.com/smallpalace/items/cfc3c8bfa32b4f27eaca
2021/1/13 追記
その後、しばらく放置したところ、再びoom-killerが発動しました。
rsyslogdがメモリを確保しているようなので、アップデートを行いました。
どうやらメモリーリークがあるようで修正されていました。