zabbix-agentがmemory leakしていたのでZabbix communityにBug patch/reportを出してみた話
// ちなみのこのbugreportを出したのもmergeされたのももうしばらく前(2019年末から2020年頭)の話．
私は仕事でも趣味(?)でも，OSSの監視ツールであるZabbixに大変お世話になっている．
zabbixは主にネットワークやサーバなどのインフラに強みをもった監視ツールで，サーバならzabbix-agent, ネットワーク機器ならSNMPなどを主に用いて，各種ステータスやメトリクスの監視，可視化が行えるツールである．
先日このzabbixから一つのalertが飛んできた．アラート内容は available memory に関するアラート．これが何を意味するかと言うとつまり，空きメモリに余裕がないということである．
グラフ波形を見る限り日を追うごとにメモリが少しずつ侵食されており，典型的なメモリリークの症状であった．また身の回りの他の人からも同様の症状があるという報告を得た．
top/htop等を見てmemoryを専有するプロセスを探したところ zabbix-agentd と書かれたプロセスのメモリ使用率が著しく高いことがわかった．
ここまでで，何らかの原因でzabbix-agentdがmemory leakしていることがわかった．
zabbixがOSSであることを知っていたため，私は原因を突き止め，デバッグし，まず自分の身の回りで生じているメモリリークによる影響を排除しようと考えた． また，まだreportが上がっていないのであればzabbixのOSS communityに対しbug patch/reportをあげ，自分自身が少しでも普段利用しているzabbixに貢献し，また同様のことで困っている方の助けに少しでもなれればうれしい，と考えた． 今回はその過程を少し記録しておく．
Root Causeの特定
top等のコマンドを用いて特定できるのはあくまでどのプロセスがメモリを専有しているか，という情報のみである．
ここからzabbix-agentdがメモリを大きく専有していることまではわかったが，ここからやるべきことは "zabbix-agentdのどこでこのメモリリークが生じているか" を確かめることである．
メモリリークを検出する方法はたくさんの手法があるが，今回の場合実行ファイルがあるだけで利用できるという点にメリットを感じて Valgrind を用いた．
Valgrindの詳細な動作については，私は理解していないが，おそらくはサンドボックス上でバイナリを実行し，その実行時に特にメモリを取り扱うシステムコール等をwrapすることでリーク等を検知できる仕組みが備わっているのではないかと思う．
zabbix-agentdをValgrindを食わせて実行した結果，次のような結果が得られた(一部抜粋)．
==27583== HEAP SUMMARY: ==27583== in use at exit: 109,825 bytes in 188 blocks ==27583== total heap usage: 44,181 allocs, 43,993 frees, 4,111,671 bytes allocated ==27583== ==27583== 1 bytes in 1 blocks are definitely lost in loss record 1 of 38 ==27583== at 0x4C2FB0F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so) ==27583== by 0x162F4D: zbx_malloc2 (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x168C40: zbx_strncpy_alloc (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x168EA4: zbx_strcpy_alloc (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x13F420: VFS_FILE_CONTENTS (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x12C91C: process (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x128C9C: ??? (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x12911E: listener_thread (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x14FF44: zbx_thread_start (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x11A597: MAIN_ZABBIX_ENTRY (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x1516A7: daemon_start (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x11A9FA: main (in /usr/sbin/zabbix_agentd.orig) ==27583== ==27583== 98,304 bytes in 1 blocks are definitely lost in loss record 38 of 38 ==27583== at 0x4C31D2F: realloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so) ==27583== by 0x162FFC: zbx_realloc2 (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x168CC0: zbx_strncpy_alloc (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x168EA4: zbx_strcpy_alloc (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x13F420: VFS_FILE_CONTENTS (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x12C91C: process (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x128C9C: ??? (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x12911E: listener_thread (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x14FF44: zbx_thread_start (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x11A597: MAIN_ZABBIX_ENTRY (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x1516A7: daemon_start (in /usr/sbin/zabbix_agentd.orig) ==27583== by 0x11A9FA: main (in /usr/sbin/zabbix_agentd.orig) ==27583== ==27583== LEAK SUMMARY: ==27583== definitely lost: 98,305 bytes in 2 blocks ==27583== indirectly lost: 0 bytes in 0 blocks ==27583== possibly lost: 0 bytes in 0 blocks ==27583== still reachable: 11,520 bytes in 186 blocks ==27583== suppressed: 0 bytes in 0 blocks ==27583== Reachable blocks (those to which a pointer was found) are not shown. ==27583== To see them, rerun with: --leak-check=full --show-leak-kinds=all ==27583== ==27583== For counts of detected and suppressed errors, rerun with: -v ==27583== Use --track-origins=yes to see where uninitialised values come from ==27583== ERROR SUMMARY: 592818 errors from 11 contexts (suppressed: 0 from 0)
1 bytes in 1 blocks are definitely lost in loss record 1 of 38 などの出力がみられる．
これはこの部分でmemory leakがある(具体的にはメモリへのポインタを失う)ことを示している．
続けて，lostしたと考えられる箇所が記述されている．
上記に示した2件ではどうやら zbx_strncpy_alloc() 内部で利用されているzbx_malloc2(), zbx_realloc2()で生じているように見受けられる．
ここのコードを見てみる．
void zbx_strncpy_alloc(char **str, size_t *alloc_len, size_t *offset, const char *src, size_t n)
{
if (NULL == *str)
{
*alloc_len = n + 1;
*offset = 0;
*str = (char *)zbx_malloc(*str, *alloc_len);
}
else if (*offset + n >= *alloc_len)
{
while (*offset + n >= *alloc_len)
*alloc_len *= 2;
*str = (char *)zbx_realloc(*str, *alloc_len);
}
while (0 != n && '\0' != *src)
{
(*str)[(*offset)++] = *src++;
n--;
}
(*str)[*offset] = '\0';
}
ref: zabbix/str.c at 4.4.5 · zabbix/zabbix · GitHub
内部でzbx_malloc()やzbx_realloc()がcallされていることがわかる．この定義を見ると
#define zbx_calloc(old, nmemb, size) zbx_calloc2(__FILE__, __LINE__, old, nmemb, size) #define zbx_malloc(old, size) zbx_malloc2(__FILE__, __LINE__, old, size) #define zbx_realloc(src, size) zbx_realloc2(__FILE__, __LINE__, src, size) #define zbx_strdup(old, str) zbx_strdup2(__FILE__, __LINE__, old, str)
ref:zabbix/common.h at b93f5c4fc09286ec199910c7d450b8a4bf4dd3de · zabbix/zabbix · GitHub
zbx_malloc2(), zbx_realloc2()がcallされる．これらをみてみると．
void *zbx_malloc2(const char *filename, int line, void *old, size_t size)
{
int max_attempts;
void *ptr = NULL;
/* old pointer must be NULL */
if (NULL != old)
{
zabbix_log(LOG_LEVEL_CRIT, "[file:%s,line:%d] zbx_malloc: allocating already allocated memory. "
"Please report this to Zabbix developers.",
filename, line);
}
for (
max_attempts = 10, size = MAX(size, 1);
0 < max_attempts && NULL == ptr;
ptr = malloc(size), max_attempts--
);
if (NULL != ptr)
return ptr;
zabbix_log(LOG_LEVEL_CRIT, "[file:%s,line:%d] zbx_malloc: out of memory. Requested " ZBX_FS_SIZE_T " bytes.",
filename, line, (zbx_fs_size_t)size);
exit(EXIT_FAILURE);
}
void *zbx_realloc2(const char *filename, int line, void *old, size_t size)
{
int max_attempts;
void *ptr = NULL;
for (
max_attempts = 10, size = MAX(size, 1);
0 < max_attempts && NULL == ptr;
ptr = realloc(old, size), max_attempts--
);
if (NULL != ptr)
return ptr;
zabbix_log(LOG_LEVEL_CRIT, "[file:%s,line:%d] zbx_realloc: out of memory. Requested " ZBX_FS_SIZE_T " bytes.",
filename, line, (zbx_fs_size_t)size);
exit(EXIT_FAILURE);
}
ref: zabbix/misc.c at b93f5c4fc09286ec199910c7d450b8a4bf4dd3de · zabbix/zabbix · GitHub
このように書かれている．まずこの周辺の処理に問題がある可能性がある．
また，別の観点では，このmalloc()やrealloc()をcallする際，ポインタとsizeを引数として渡している事がわかる．
このポインタやsizeが不適切に設定されている可能性も考えられる．
結論から述べると，これはcallする側に問題があった．
debugをすすめていくと，Valgrindのリーク元として記載されている関数であるVFS_FILE_CONTENTSのうち，このzbx_readを用いた判定がwhileループを抜けることなく不自然に繰り返されている事に気がついた．
本来であればこのロジックはzbx_read()でファイルディスクリプタからbufferに取り込み，utf8に文字コード変換をしcontentsとして保存するようなロジックであると考えられ，whileを複数回繰り返すことはあれど，zbx_read()からの戻り値が常に返却されることは考えにくい．
ここからたどっていき，zbx_read()が返却するnbytesが不適切に返却されている可能性が高いことがわかった．
int zbx_read(int fd, char *buf, size_t count, const char *encoding)
{
size_t i, szbyte, nbytes;
const char *cr, *lf;
zbx_offset_t offset;
if ((zbx_offset_t)-1 == (offset = zbx_lseek(fd, 0, SEEK_CUR)))
return -1;
if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
return (int)nbytes;
find_cr_lf_szbyte(encoding, &cr, &lf, &szbyte);
for (i = 0; i <= nbytes - szbyte; i += szbyte)
{
if (0 == memcmp(&buf[i], lf, szbyte)) /* LF (Unix) */
{
i += szbyte;
break;
}
if (0 == memcmp(&buf[i], cr, szbyte)) /* CR (Mac) */
{
/* CR+LF (Windows) ? */
if (i < nbytes - szbyte && 0 == memcmp(&buf[i + szbyte], lf, szbyte))
i += szbyte;
i += szbyte;
break;
}
}
if ((zbx_offset_t)-1 == zbx_lseek(fd, offset + (zbx_offset_t)i, SEEK_SET))
return -1;
return (int)i;
}
ref: zabbix/file.c at b93f5c4fc09286ec199910c7d450b8a4bf4dd3de · zabbix/zabbix · GitHub
このどこかで不適切なreturnが存在する可能性がある．
前述の通りwhileループを抜けることなく繰り返していることから，正の値の返却があり，可能性は2つに絞られる．
最後の
return (int)i;
もしくは10行目の
if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
return (int)nbytes;
である．
可能性としてかなり絞られたのでprintf debugしかり，logとして出力してdebugした．
int zbx_read(int fd, char *buf, size_t count, const char *encoding)
{
size_t i, szbyte, nbytes;
const char *cr, *lf;
zbx_offset_t offset;
if ((zbx_offset_t)-1 == (offset = zbx_lseek(fd, 0, SEEK_CUR)))
return -1;
if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
{
zabbix_log(LOG_LEVEL_CRIT, "zbx_read: read() returned: %d nbytes", (int)nbytes);
return (int)nbytes;
}
find_cr_lf_szbyte(encoding, &cr, &lf, &szbyte);
for (i = 0; i <= nbytes - szbyte; i += szbyte)
{
if (0 == memcmp(&buf[i], lf, szbyte)) /* LF (Unix) */
{
i += szbyte;
break;
}
if (0 == memcmp(&buf[i], cr, szbyte)) /* CR (Mac) */
{
/* CR+LF (Windows) ? */
if (i < nbytes - szbyte && 0 == memcmp(&buf[i + szbyte], lf, szbyte))
i += szbyte;
i += szbyte;
break;
}
}
if ((zbx_offset_t)-1 == zbx_lseek(fd, offset + (zbx_offset_t)i, SEEK_SET))
return -1;
zabbix_log(LOG_LEVEL_CRIT, "zbx_read: zbx_read() returned: %d nbytes", i);
return (int)i;
}
returnの直前にreturnとして返却する値をlogに表示した．
得られた結果はこうだ．
19207:20191202:093521.406 zbx_read: read() returned: -1 nbytes 19207:20191202:093521.406 zbx_read: zbx_read() returned: 66 nbytes
気づくべきなのは1行目．
if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
{
zabbix_log(LOG_LEVEL_CRIT, "zbx_read: read() returned: %d nbytes", (int)nbytes);
return (int)nbytes;
}
というブロックに対して
19207:20191202:093521.406 zbx_read: read() returned: -1 nbytes
というログが出力されている．
意図としてはread()からのreturn値が0以上である場合if内部を実行する．
具体的にはzabbix_log()を実行し(int)nbytesをreturnするようなロジックを書きたいと考えられる．
しかしこのログ出力からは，return値が-1であるにも関わらずログに出力されている(if内部が実行されている)．
このことからキャストが不足している可能性があることに気づく．
軽率に
if (0 >= (int)(nbytes = read(fd, buf, (unsigned int)count)))
{
zabbix_log(LOG_LEVEL_CRIT, "zbx_read: read() returned: %d nbytes", (int)nbytes);
return (int)nbytes;
}
とintキャストしてコンパイル，実行したところ，このメモリリークが解消された．
原因はnbytesがsize_tとして宣言されていたことによりread()のreturnが-1である場合でも正の値として判定されているところにあった．
これによりreturnされるべきでない-1というread()からの返り値が正の値としてint castされて返却されてしまいVFS_FILE_CONTENTS()におけるwhileでの異常なループが起きていたと考えられる．
上記の内容から原因はzbx_read内部における不適切な値返却だとわかった．
これらの内容をzabbix communityにbug patchとして報告した．まぁ実際はreviewerが色々訂正してくれたからbug report程度なんだけど．
内容を読んだ人はわかると思うが，当初私はValgrindの出力から，zbx_strncpy_alloc() 内部で利用されているzbx_malloc2(), zbx_realloc2()に問題があるのではないかと信じ込み，不適切な報告をしてしまっている．
しかし対応していただいたレビューアには，「その部分は問題ないように見える」と優しく教えてもらった．
のちに手元で検証したところ，やはり問題はなく，自分のc言語に対する理解力の不足と思い込みがこのミスを招いている．
しかしそれとは別に私は上記のcast不足を提言し，改善したコードの提示をした．
そのコードはレビュアーによってより改善(具体的にはsize_t型(unsigned)として宣言されていたnbytesをssize_t(signed)として定義するように変更)され，このメモリリークのbugは解消された．
めでたしめでたし．
これによって私の身の回りのメモリリークは落ち着いた．よかった．
また，これをきっかけにVFS_FILE_CONTENTS 内で2箇所memory leakの危険性があることがわかり，ついでになおしてもらった．これに気づいたのはreviewerだったけど，この報告がきっかけになっていたのはうれしい．
P.S.
BugfixとしてChangelogに名前載せてくれた．ありがとう！
まとめ
いつもお世話になってるzabbixに1nmくらいは貢献した気分．
OSSへの貢献ってなかなか技術力がない自分には難しいところがあるが，やれる部分でなんとか協力してやっていきたい．
また不適切な報告をしたのは大変申し訳ない事案であったので技術力をもうちょい高めていきたい．
「C言語ぜんぜんわかってなくてすまん」といったらありがたいお言葉をいただいた．気が休まる思い．ありがたい．
なんにせよリークが治って個人的には助かった．
英語でbugの議論したりするの，ちょっと楽しかった．まだまだだけど．
つい先日zabbix5.0がリリースされて，zabbix-agent2というgoで書かれた新しいagentも登場している．このcで書かれたagentがいつまで使われるのかわからないが，しばらくは使われる気もする．なんにせよ人に使われるものに1nmでも貢献できたことが嬉しい．
そういえばValgrindをつかってこうやってまともにメモリリークを調べたのも初めてのことだったっぽい．意外となんとかなるものだ．
Special Thanks(Reviewer)!
- Glebs Ivanovskis
- Andris Mednis
- Martins Abele
