Zabbix agent on hostname is unreachable for 5 minites

この一ヶ月ほど、Zabbixで監視しているすべてのサーバで上記エラーがでるようになりました。ずっと出るわけではなく、時々発生。
でもってzabbix serverプロセスを再起動すると何事もなく動作する。

現象を整理

現象が発生したときに実際にzabbixサーバとzabbix agent間で通信ができなくなっているかというと全くそういうことはなく、ちゃんと通信はできている。
telnetで10050ポートをつつくとちゃんと返答が帰ってくるし、zabbix_getでagentに値を要求してもちゃんと答えが帰ってくる。

$ zabbix_get -s 172.18.1.57 -p 10050 -k agent.version
3.0.7

ではサーバ側のログになにか出ているかというと全くエラーっぽいものは出ておらず、それどころかagentとの通信ログが順調に積み上がっている。
つまりまったくunreachableではない模様。

じゃあ、誤検知なのか

誤検知だったらいいんですが、上記エラー状態になったときには実際にagentから帰ってくるデータが全く蓄積されない。グラフをみると障害発生時間帯がちょん切れる感じ。通信できていないわけじゃないけど、データは取れてませんよってことですね。

このエラーはどのトリガーで発生しているのか

このトリガーとそのもとになっているアイテムはTemplate App Zabbix Agentというテンプレートに含まれています。アイテム名は"Agent Ping"でキーは

agent.ping

という簡単なもの。トリガーはこれが最新の5分間NGになったときにキックされるようになっています。
https://www.miraclelinux.com/tech-blog/835fku
ここの情報によれば、本トリガーが判定されるのは、

アイテムのデータを取得した後、HistoryCacheからDBへ書き込むとき
タイマー(本例の様に5分間とか)判定があるときは、30秒に一度

とのこと。
上の条件でデータが取れていてもDBへの投入ができなければトリガが判定されるということです。
agentから集めてきたデータをいちどHistoryCacheへ投入、DBSyncerプロセスでバックエンドDBへ投入終了後ようやくトリガとしてはOKになる。
つまりagentとは通信できているけど、DBへのinertが追いついてないよってことですね。
障害が発生しているまでのCahce状態はこんな感じ。

じゃあDBの性能をチューニングしよう

ってことでいろいろやってみたんです。

InnnoDBテーブル単位にする(前からそうでしたが)
innodb_read_io_threads,innodb_write_io_threadsを増やす
innodb_old_block_timeを増やす
innodb_io_capacityを800にする。
sync_binlog=0
query_cache_size=0, query_cache_type=0
sort_buffer_size, join_buffer_size, read_rnd_buffer_size を調整

全部 https://www.percona.com/blog/2014/11/14/optimizing-mysql-zabbix/ に書いていることですけど。
あと、バックエンドのMySQLをzabbix serverからもっと高性能なDBサーバへ移したりしんだですが、全部ムダでした。
多少は障害が派生する頻度はへるもののそのうち、HistoryCacheがいっぱいになって停止。

どんなSQLが原因なんだろう

zabbixのDBでhistoryやhistory_logのテーブルに入ってくるデータってそんなにおおきなものじゃないのに、なんでそんなに時間がかかるんだろう。
ということで現象(障害)が発生しているときにZabbix Serverを停止してみる。そうすると、HistoryCacheに溜まっているデータをDBSyncerが一生懸命DBへ吐き出そうとします。これがまぁ遅いこと。zabbix_serverのログをみていると進捗が出てくるんですがこんなんですよ。

zabbix_server.log: 14466:20181024:094716.374 syncing history data... 0.000868%
zabbix_server.log: 14466:20181024:094734.958 syncing history data... 0.002083%
zabbix_server.log: 14466:20181024:094744.395 syncing history data... 0.002690%
zabbix_server.log: 14466:20181024:094812.096 syncing history data... 0.003905%
zabbix_server.log: 14466:20181024:094830.815 syncing history data... 0.005120%
zabbix_server.log: 14466:20181024:094857.605 syncing history data... 0.006335%

その間にMySQLで一般クエリのログを取れるようにして再起動。

#General log
general_log = 1
log_output = FILE
general_log_file = /var/lib/mysql/mysqld-general.log

でもってこのログを眺める。だいたいはselectなんですが、ときおりなにやら妙な文字列がhistory_logにinsertされているのを観測しました。
どんなデータかというと、こんな感じ。これ、Windowsのセキュリティログですね。

 
オブジェクトに対して操作が実行されました。

サブジェクト:
        セキュリティ ID:                S-1-5-21-1446844220-300872527-1797055100-40755
        アカウント名:           ict_logrev
        アカウント ドメイン:            HOGE
        ログオン ID:            0x5BBA054C0

オブジェクト:
        オブジェクト サーバー:          DS
        オブジェクトの種類:             %{bf967a8b-0de6-11d0-a285-00aa003049e2}
        オブジェクト名:         %{b8c85098-76be-444b-a007-6d33f04ddb58}
        ハンドル ID:            0x0

操作:
        操作の種類:             Object Access
        アクセス:               プロパティの読み取り

        アクセス マスク:                0x10
        プロパティ:             プロパティの読み取り
                {e48d0154-bcf8-11d1-8702-00c04fb96050}
                        {bf9679e4-0de6-11d0-a285-00aa003049e2}
        {bf967a8b-0de6-11d0-a285-00aa003049e2}


追加情報:
        パラメーター 1:         -
        パラメーター 2:

とこんな文字列を延々とinsertしようとしている。おそらくだけどhistory_logのvalueカラムって数値が入ってくることを前提としているので、こんなデカイ文字列が入ってくると途端にパフォーマンスがおちちゃんだろうなぁと。
別にログをチェックするのは悪いことじゃないけど、全部zabbixに送ってくる必要なないよなぁ。

対処

上記アイテムはTemplate Log Check Windowsというテンプレートに含まれています。Eventlog Securityという名前。キーは

eventlog[Security]

全部かよ。どうせみないでしょうってことでこれを無効にしました。危ういのをチェックしたいんだったら、フィルタをかけるのがいいかと。こんな感じで、

evnetlog[Security,,"Error|Critical"]

結果は

上記対処をして48時間立ちましたが、どうやらヒットだった模様。HistoryCacheの値はいろいろ調べている過程で上限の2GBまで増やしてみましが、512MBまで削減。それでも100%で安定しています。すらすらと書いていますが、この結論と対処をするまで結構悩みました。