ServerプロセスがSIGTERMを受信して勝手に止まる
Zabbix5.0.1（公式dockerコンテナ zabbix-server-mysql）を利用しています。
最近、ServerのコンテナがSIGTERMを受信して停止するようになりました。
一度こうなると、通常の手順では復帰できません。
2.4の頃から長年使い続けている環境なので、どこかに綻びがあるのだろうと想像しています。
最悪はまっさらにして一から作り込みを行うつもりでいますが、
後学のためにもできれば問題点を特定したいと思っています。
・現象
dockerのコンテナログに"Got signal [signal:15(SIGTERM),sender_pid:1,sender_uid:0,reason:0]. Exiting ..."が記録され、
zabbix_serverプロセスが停止する。以降起動→停止を延々繰り返す
・確認できたこと
(1)現象発生後、DB（mysqlコンテナ）を停止するなどしてDBを読めない状態にすると、現象自体は発生しなくなりDB接続待ちになる
(2)DBをフルバックアップ→フルリストアするといったん現象は解消し、動作も正常に戻る。しかしそのまま運用すると数日後に同じ現象が発生する
(3)上の(2)でフルリストア直後、すべてのホストデータを削除(=テンプレや設定は残存)し、全く別の環境を新規に監視してみたところ、数ヶ月にわたって現象は発生していない
(4)上の(2)でフルリストア直後、いったんすべてのヒストリ、トレンドデータを削除し再度同じ監視を開始したところ、数日後に同じ現象が発生した
(5)DBの問題と考え、mysqlcheckを行ったが、問題は検出されず
(6)現象発生時は必ず、Zabbix value cache working in low memory modeトリガーが発動するが、実際のValueCache値に不足はない
・補足
確認できたことの要点を推測込みで述べると、
「zabbix_serverが、ある条件を満たしたDBを読みに行くと現象が発生するようだ」
「監視対象を変えると問題が発生しないため、現状の監視設定（ホスト設定、テンプレ、カスタムスクリプト等々）のどこかに問題がありそう」
と考えています。
zabbix_server.confの"DebugLevel"を4,5,6にして現象発生時のログをつぶさに調べてもみたのですが、
これだというものは見当たりませんでした。（長すぎるのでペーストは控えますが）
mysql側のerror.logにも特段エラーは出ていません。
他に取っかかりにできそうなポイントはありませんでしょうか。
TNK - 投稿数: 4671
もう少し前後に何かヒントになるログが出力されていると思います。
low memory modeになるということは、メモリ不足などの問題が発
生している可能性があるのではないでしょうか？
Zabbixサーバーのリソースの使用状況や負荷状況は確認されました
か？
5.0.1と古いバージョンを使用されているようですので、もしかし
たらメモリリークなどの問題が残っているのかもしれません。
最新版へのバージョンアップもご検討ください。
nakaring - 投稿数: 27
ご返信ありがとうございます。
まず、現在の最新コンテナである5.0.4に更新しても現象は変わらず発生しました。
またValuecacheのサイズを、平時は512MBとしているところ2048MBまで上げてみましたが、やはり現象は変わらず発生しました。
なお直近で正常に稼働していた20日間の、512MB設定でのValueCache %usedは、平均45%最大58%でした。
しかし現実にlow memory modeトリガーは発生しているので、vcache,cache,modeが1になったのだとは思うのですが、
なにぶん正常稼働に戻せていないこともあり、このあたりの機序を詳しく見ることができていません。
現在は"現象"が発生した状態のまま直しておらず、起動→DB接続→SIGTERMまでは2秒ほどなので、
DEBUGLEVELを4や5にして(6はありませんでした…勘違いでした)この2秒間のログを穴が空くほど眺めています。
が、アイテムの計算式がおかしいとか、データが十分ではないといったデータ処理上のエラーはあれど、
SIGTERMのきっかけになっているようなものは見つけられていません。
Yasumi - 投稿数: 373
特定の監視設定が原因で、記載のような事象が起こることはまずないと思います。
監視設定ではなく、リソースや性能部分に起因する問題ではないでしょうか。
nakaring - 投稿数: 27
ご返信ありがとうございます。
監視設定によってSIGTERMというのは確かに考えにくいと思います。
しかし切り分けを進めていく中で、
「理論上同じコンテナで、監視データだけ削除して別環境を監視させると現象が発生しない」と思われることから、
念のため疑っているところです。
リソースですが、ValueCache以外の値も念のため平時の4倍にしてみました。
具体的には以下のような値まで広げてみたのですが、やはり挙動は変わりませんでした。（docker-composeの書式です）
ZBX_CACHESIZE: 768M
ZBX_HISTORYCACHESIZE: 1536M
ZBX_HISTORYINDEXCACHESIZE: 64M
ZBX_VALUECACHESIZE: 2048M
ZBX_TRENDCACHESIZE: 64M
ZBX_VMWARECACHESIZE: 128M
※念のためですが、dockerホスト側メモリ容量は24GBあり、不足していません
TNK - 投稿数: 4671
ホスト側ではなく、対象のコンテナにどれだけのメモリを割り当て
るよう指定していますか？
nakaring - 投稿数: 27
特にコンテナリソースを制限していないため、コンテナ側が求めるだけ使える状態です。
データクリアを行い再発待ちのため正常稼働中ですが、docker statsは以下の通りです。
MEM USAGE / LIMIT MEM %
5.037GiB / 23.54GiB 21.40%
現象再発時にも改めてstatsを確認してみます。
Yasumi - 投稿数: 373
Zabbixインターナルで取得される各Zabbixプロセスやリソースの使用率はどの程度でしょうか。
nakaring - 投稿数: 27
現在、監視データクリアを行い再発を待っている状況です。
Configuration Syncerが3.5%、History Syncerが2%前後、あとは1%以下といった状態です。
また現象が発生し次第、報告・相談させていただきたいと思っています。
nakaring - 投稿数: 27
2020/10/23 15:22頃、現象が再発しました。
■わかったこと
(1)"Zabbix value cache working in low memory mode"の発生直後に、このスレッドの主題である「現象」が発生
(2)各リソース消費量は平時と変わらず。Value cache %usedは69%。dockerコンテナのメモリ使用は22%、5GB。
internal process busy %も含め、発生前数時間～数日にわたってほとんど変化なし。
（ご参考までに、Zabbixグラフスクリーン画像を添付しています）
(3)発生時のログ（後半に貼り付けます）を見ると、free chunkの残りが1になっている部分がある。
これが問題であるという海外フォーラムの書き込みを発見。
https://www.zabbix.com/forum/zabbix-troubleshooting-and-problems/403427-zabbix-value-cache-working-in-low-memory-mode-but-used-always-20#post403454
しかし、返信では大した問題ではないと言っているように見える
■発生時のServer(のコンテナ)ログ
先頭行は今回の現象とは関係ない、アイテムの処理エラーです。
同様のエラーはそれまでに多量に出ています。
------------------ログここから
1. Failed: cannot apply multiplier "1048576" to value of type "string": cannot convert value to numeric type
233:20201023:152117.907 === most used items statistics for value cache ===
233:20201023:152117.925 itemid:48399 active range:604802 hits:145466810 count:10632 perc:0.048994%
233:20201023:152117.925 itemid:48398 active range:604802 hits:145452172 count:10630 perc:0.048985%
233:20201023:152117.925 itemid:185888 active range:604801 hits:145352130 count:10623 perc:0.048953%
233:20201023:152117.925 itemid:174548 active range:604801 hits:145200824 count:10607 perc:0.048879%
233:20201023:152117.925 itemid:174558 active range:604802 hits:145121167 count:10598 perc:0.048837%
233:20201023:152117.925 itemid:177270 active range:604801 hits:145167751 count:10597 perc:0.048833%
233:20201023:152117.925 itemid:177259 active range:604802 hits:145094573 count:10597 perc:0.048833%
233:20201023:152117.925 itemid:177272 active range:604802 hits:145170843 count:10596 perc:0.048828%
233:20201023:152117.925 itemid:198886 active range:604801 hits:144775779 count:10568 perc:0.048699%
233:20201023:152117.925 itemid:198885 active range:604801 hits:144764152 count:10566 perc:0.048690%
233:20201023:152117.925 itemid:31716 active range:604802 hits:144789027 count:10564 perc:0.048681%
233:20201023:152117.925 itemid:31950 active range:604801 hits:144695815 count:10561 perc:0.048667%
233:20201023:152117.925 itemid:29539 active range:604802 hits:144636120 count:10559 perc:0.048658%
233:20201023:152117.925 itemid:31951 active range:604802 hits:144802523 count:10558 perc:0.048653%
233:20201023:152117.925 itemid:198968 active range:604801 hits:144414596 count:10530 perc:0.048524%
233:20201023:152117.925 itemid:199102 active range:604802 hits:144413630 count:10526 perc:0.048506%
233:20201023:152117.925 itemid:199103 active range:604802 hits:144371671 count:10519 perc:0.048473%
233:20201023:152117.925 itemid:181396 active range:604801 hits:180570870 count:10387 perc:0.047865%
233:20201023:152117.925 itemid:181395 active range:604801 hits:180570870 count:10387 perc:0.047865%
233:20201023:152117.925 itemid:181397 active range:604802 hits:180570869 count:10386 perc:0.047860%
233:20201023:152117.925 itemid:181398 active range:604802 hits:180570869 count:10386 perc:0.047860%
233:20201023:152117.925 itemid:31354 active range:604801 hits:152606156 count:10366 perc:0.047768%
233:20201023:152117.925 itemid:31356 active range:604801 hits:180637261 count:10366 perc:0.047768%
233:20201023:152117.925 itemid:31355 active range:604802 hits:152606156 count:10366 perc:0.047768%
233:20201023:152117.925 itemid:198751 active range:604802 hits:141262448 count:10348 perc:0.047685%
233:20201023:152117.925 ==================================================
233:20201023:152117.935 === memory statistics for value cache size ===
233:20201023:152117.936 free chunks of size 24 bytes: 44
233:20201023:152117.936 free chunks of size 32 bytes: 796
233:20201023:152117.936 free chunks of size 40 bytes: 15
233:20201023:152117.936 free chunks of size 48 bytes: 1140
233:20201023:152117.936 free chunks of size 56 bytes: 13
233:20201023:152117.936 free chunks of size 64 bytes: 2
233:20201023:152117.936 free chunks of size 80 bytes: 7
233:20201023:152117.936 free chunks of size 96 bytes: 2
233:20201023:152117.936 free chunks of size 112 bytes: 13
233:20201023:152117.936 free chunks of size 120 bytes: 2
233:20201023:152117.936 free chunks of size 128 bytes: 38
233:20201023:152117.936 free chunks of size 136 bytes: 1
233:20201023:152117.936 free chunks of size 144 bytes: 48
233:20201023:152117.936 free chunks of size 152 bytes: 6
233:20201023:152117.936 free chunks of size 160 bytes: 4
233:20201023:152117.936 free chunks of size 176 bytes: 21
233:20201023:152117.936 free chunks of size 192 bytes: 3
233:20201023:152117.936 free chunks of size 224 bytes: 1
233:20201023:152117.936 free chunks of size 240 bytes: 3
233:20201023:152117.936 free chunks of size >= 256 bytes: 69230
233:20201023:152117.936 min chunk size: 24 bytes
233:20201023:152117.936 max chunk size: 58696 bytes
233:20201023:152117.936 memory of total size 531492600 bytes fragmented into 336122 chunks
233:20201023:152117.936 of those, 166848688 bytes are in 71389 free chunks
233:20201023:152117.936 of those, 364643912 bytes are in 264733 used chunks
233:20201023:152117.936 of those, 5377936 bytes are used by allocation overhead
233:20201023:152117.936 ================================
233:20201023:152117.936 value cache is fully used: please increase ValueCacheSize configuration parameter
7:20201023:152124.887 Got signal [signal:15(SIGTERM),sender_pid:1,sender_uid:0,reason:0]. Exiting ...
234:20201023:152124.887 syncing history data in progress...
234:20201023:152124.894 syncing history data... 100.000000%
234:20201023:152124.894 syncing history data done
7:20201023:152125.022 syncing trend data...
7:20201023:152127.385 syncing trend data done
7:20201023:152127.394 Zabbix Server stopped. Zabbix 5.0.4 (revision 69c0ad3).
------------------ログここまで
■疑問
正直言って、Value cacheのstatsの意味するところはよくわかっておりません…
空き容量自体は十分だとすれば、メモリのフラグメント？
アドバイスいただけると助かります。
Yasumi - 投稿数: 373
「Failed: cannot apply multiplier "1048576" to value of type "string": cannot convert value to numeric type」とありますが、
本来データ型「整数/浮動小数」を選択すべきアイテムで、「文字列」にしているやつがいるのではないでしょうか。
そのデータ型「文字列」に、保存前処理で乗数を掛けていることで、Failが起きているように見えます。
すぐに修正すべきではないでしょうか。
⇒過去に上記のエラーを体験・見たことはありませんが、全体の事象に関与している可能性もありますね。
「value cache is fully used: please increase ValueCacheSize configuration parameter」とあるので、
アイテムのうち「データ型（整数/浮動小数）」を格納する共有メモリ(ValueCacheSize)が不足していると思われます。
69%というのは相当高い数値だと思います。少なくとも、ValueCacheSizeの値を倍に上げてはどうでしょうか。
Value cacheのstatsはZabbixの動作処理能力にとって極めて重要なステータスです。
nakaring - 投稿数: 27
ご指摘ありがとうございます。
>「Failed: cannot apply multiplier "1048576" to value of type "string": cannot convert value to numeric type」とありますが、
>本来データ型「整数/浮動小数」を選択すべきアイテムで、「文字列」にしているやつがいるのではないでしょうか。
これは原因部位は特定できていて、外部チェックである値を取ってきているんですが、
タイミングによっては数値でなく"null"を取ってしまっており、この場合に上記エラーが出てしまいます。
（外部スクリプトのデバッグが必要ですが、間に合っていません…）
また、おっしゃるとおりValueCacheに余裕があるとは言えません。
それはそれとして、一度現象が発生してしまうと、以前記載したとおりValueCacheをいくら増やしても
現象は一向に解消しないという点が不思議ではあるのですが、まずは
再度DBを問題発生前に戻し、以下2つを試した上で再発があるかないか様子を見てみます。
・ValueCacheを512MB→1024MBにする
・問題のアイテムを含むホストを無効にする
nakaring - 投稿数: 27
現象が発生しなくなりました。
これまで2週間持ったことはなかったので、おそらく解決したと思います。
■やったこと
・ValueCacheを512MB→1024MBにした
→現在、使用率は最大、平均とも33%です。そのうち512MBに戻してみようと思います
・"Failed: cannot apply multiplier "1048576" to value of type "string": cannot convert value to numeric type"を根本から解消した
→カスタムスクリプトの実行タイミングによって値が取得できず、結果このエラーがかなりの頻度で発生している状態でした。
スクリプトにリトライ処理を追加することで、このエラーが発生しないよう改善しました。
■まとめ
おそらくはエラー頻発状態の放置により、機序はともかく結果としてメモリリーク(※)のようなものが堆積し、
主題に記載した"現象"に結びついたのではないかと思います。
※とは言え解決前でも、Zabbix Agentから報告されるZabbix内部リソース値、OS側リソースとも
いわゆるメモリリーク的な漸増は全く見られませんでした。
あまりすっきりしませんが、妙なエラーを放置するのはやめようという結論になりそうです。
ありがとうございました。
nakaring - 投稿数: 27
本日、現象が再発しました。
結局、再発までの期間は延びたものの原因は解消していない状態です。
やはり監視対象（ホスト）の設定に問題があるとしか思えない発生パターンなので、
あとはホストグループ（テンプレート）を順番に無効化して再発有無を見るとか、
泥臭い絞り込みしかないかなと思っています。
はっきりとした原因が判明しない限り、こちらでは最終報告になると思います。
お騒がせしました。