ログ監視にて更新の無いアイテムからの発報が止まらない
皆様のお力をお借りしたく書きこませて頂きます。
ログ監視にて更新の無いアイテムからの発報が止まらないという事象に悩まされています。
v1.8.2のログ監視において、
・ログの同一行を何度も拾ってしまう
・ログのアイテムの更新が無いのにイベントを生成し続けてしまう
という不具合情報をご存知の方はいらっしゃいませんでしょうか
ほぼ同一の設定のログ監視を複数行っていますが、
「更新頻度が低いログ」のログ監視でのみこの症状が発生しています。
zabbixサーバを再起動することでこの事象が収まるので運用でカバーしている状況です。
■環境
・OS：CentOs 5.5
・zabbix-server：Zabbix Server v1.8.2 (revision 11211) (29 March 2010)
・zabbix-agentd：Zabbix Agent (daemon) v1.8.2 (revision 11211) (29 March 2010)
■アイテム設定
==============================
タイプ：Zabbixエージェント（アクティブ）
キー：log[/xxx/log/xxx,FATAL,,1000]
データ型：ログ
更新間隔：900秒
ステータス：有効
==============================
■トリガー設定
==============================
条件式：{テンプレート名:log[/xxx/log/xxx,FATAL,,1000].nodata(300)}=0&{テンプレート名:log[/xxx/log/xxx,FATAL,,1000].str(FATAL)}=1
イベント生成：ノーマル
==============================
■アクション設定
==============================
イベントソース：トリガー
デフォルトの件名：{HOSTNAME}:{ITEM.NAME}
デフォルトのメッセージ：{EVENT.DATE} {EVENT.TIME} {HOSTNAME} {ITEM.NAME}:{ITEM.VALUE}
リカバリメッセージ：チェック無し
ステータス：有効
==============================
■事象
▽何度も同じ発報をする
これは同一の行を何度も拾っているのでアクションとしては正常な動作のように思います。
▽数時間前の発報をする
受信：2011/03/15 13:05
件名：{HOSTNAME}:{ITEM.NAME}
本文：2011.03.15 11:10:32 {HOSTNAME} {ITEM.NAME}:{ITEM.VALUE}
▽監視対象側のログに更新は無い
# ls -l /xxx/log/xxx
-rw-r--r-- 1 root root 868 3月 15 11:00 xxx
▽zabbixサーバ側のアイテムデータを確認すると、同じ行を何度も拾っている
取得日時 ログ本文（全て同一の行）
2011-03-15 11:38:34 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:36:53 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:36:07 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:34:56 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:31:58 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:31:42 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:31:41 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:31:31 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:30:54 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:30:13 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:29:30 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:29:07 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:19:32 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:19:10 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:18:42 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:18:41 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:18:12 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:18:11 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:17:55 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:17:25 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:17:18 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:17:15 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:57 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:57 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:54 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:41 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:39 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:38 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:09 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:16:02 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:15:43 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:14:43 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:14:07 [2011/03/15 11:00:04:480] xxxx
2011-03-15 11:10:32 [2011/03/15 11:00:04:480] xxxx
▽zabbixサーバ側でアイテムの更新が無い時間にもイベントが発生している、しかも時間が入れ子で発生している
mysql> select * from events where objectid = 21285 order by eventid desc limit 10;
+---------+--------+--------+----------+------------+-------+--------------+
| eventid | source | object | objectid | clock | value | acknowledged |
+---------+--------+--------+----------+------------+-------+--------------+
| 2493914 | 0 | 0 | 21285 | 1300162200 | 0 | 0 |→clockを日時表記にすると→2011.Mar.15 13:10:00
| 2493084 | 0 | 0 | 21285 | 1300155032 | 1 | 0 |→clockを日時表記にすると→2011.Mar.15 11:10:32
| 2492885 | 0 | 0 | 21285 | 1300161875 | 0 | 0 |→clockを日時表記にすると→2011.Mar.15 13:04:35
| 2492645 | 0 | 0 | 21285 | 1300156183 | 2 | 0 |→clockを日時表記にすると→2011.Mar.15 11:29:43
| 2491884 | 0 | 0 | 21285 | 1300161780 | 0 | 0 |→clockを日時表記にすると→2011.Mar.15 13:03:00
| 2491883 | 0 | 0 | 21285 | 1300155283 | 1 | 0 |→clockを日時表記にすると→2011.Mar.15 11:14:43
| 2491841 | 0 | 0 | 21285 | 1300161720 | 0 | 0 |→clockを日時表記にすると→2011.Mar.15 13:02:00
| 2491833 | 0 | 0 | 21285 | 1300155247 | 1 | 0 |→clockを日時表記にすると→2011.Mar.15 11:14:07
| 2491815 | 0 | 0 | 21285 | 1300161691 | 0 | 0 |→clockを日時表記にすると→2011.Mar.15 13:01:31
| 2491814 | 0 | 0 | 21285 | 1300155343 | 1 | 0 |→clockを日時表記にすると→2011.Mar.15 11:15:43
+---------+--------+--------+----------+------------+-------+--------------+
10 rows in set (0.00 sec)
どなたかアドバイスを頂けると助かります。
よろしくお願い致します。
kodai - 投稿数: 1341
同じ現象になったことはないのですが、同じログ行を複数回受信しているということは、Zabbixエージェントの動きに何か問題があるのではと思います。
ZabbixエージェントやZabbixサーバのログには何か関連しそうなエラーなどは出ていないでしょうか？特にアクティブチェック関係のログや、タイムアウトのログなどがあれば関係する可能性があります。
84nm - 投稿数: 8
Kodaiさん
ご連絡ありがとうございます。
また、こちらからの連絡が遅くなり申し訳ありません。
Zabbixエージェントのログには特に何も出力が無かったので、
ログレベルをDebugに上げて時間をおいてみたところ以下のようなログが出力され、タイムアウトでアクティブチェックのリフレッシュが失敗しているようでした。
■Zabbixエージェント側
26300:20110401:035645.194 refresh_active_checks('192.168.100.112',10051)
26297:20110401:035645.464 Processing request.
〜中略〜
26300:20110401:035700.194 Timeout while answering request
26300:20110401:035700.194 Get active checks error: *** Cannot connect to [192.168.100.112]:10051 [Interrupted system call]
26300:20110401:040041.214 refresh_active_checks('192.168.100.112',10051)
26300:20110401:040044.295 Sending [{
"request":"active checks",
"host":"xxxxxxxxxxx"}]
〜中略〜
26300:20110401:040056.215 Timeout while answering request
26300:20110401:040056.215 Get active checks error: ZBX_TCP_READ() failed [Interrupted system call]
26300:20110401:040056.215 In process_active_checks('192.168.100.112',10051)
zabbixエージェントの設定はTimeout=15
ネットワークレベルでのZabbixサーバとのレイテンシーは100msec未満でした。
■Zabbixサーバ側
通常アクティブチェックのリフレッシュ時にはZabbixサーバ側のログには以下のような出力があるようなのですが、
今回問題の監視対象サーバとのやりとりについてはZabbixサーバ側のログには何も出力されていませんでした。
10156:20110401:035742.801 Trapper got [{
"request":"active checks",
"host":"xxxxxxxxxxxxx"}] len xx
その他気になる点として
・Zabbixサーバの負荷状況はCPUが2コアでロードアベレージが5、CPU使用率が80程度でやや高い状態です
・Zabbixサーバでnetstat -a で確認すると、CLOSE_WAITというStateのzabbix-trapperというポート宛の接続が100以上あり、Zabbixサーバを再起動するとゼロになります
バラバラと記載してしまい申し訳ありませんが、zabbixエージェントタイムアウト秒数を30秒に増やしてみようと思います。
その他お気づきの点があれば、ご指摘頂けると幸いです。
以上です。
tsuzuki - 投稿数: 78
はじめまして。
この現象は、Zabbixサーバ側のDBの負荷が高いことが原因で発生することがあります。
少し長くなりますが、仕組みを順にご説明します。
(1) Zabbix Agent から Zabbix Server へ ActiveCheck のデータを送信（この時点でネットワーク的には接続に成功）
(2) Zabbix Agent は Zabbix Server から「受け取ったよ」というメッセージをTimeoutの秒数まで待つ
(3) Zabbix Server は受け取った情報をDBに入れてから「受け取ったよ」というメッセージを返そうとするけども、負荷が高い場合時間が掛かり、場合によってはTimeoutの秒数以上かかる。けれども、遅延してるだけなのでデータの入力はされる。
(4) Zabbix Agent は Zabbix Server から「受け取ったよ」というメッセージを受け取っていないので、データ送信失敗と判断して、再度同じデータを送信する。
(5) Zabbix Server は再度同じデータを受信するが、負荷が高いとまたTimeoutの秒数以上掛かり、(1)〜(4)をループする。
以上を繰り返すと、結果的に、同じログを複数受信することになります。
なので、対策としては、書かれているようにTimeoutの秒数を延ばすか、DBのパフォーマンスを向上させる必要があります。
DBの設定を貼っていただくことは可能でしょうか。
例えばMySQLであれば、innodb_buffer_pool_sizeでメモリ割り当てを増やすなどして改善が見込める場合があります。
もしくは、Zabbix-1.8.3 からはDBへの負荷が減少するようなロジックが入っていますので、1.8.2からバージョンアップするのも対策の1つになるかと思います。
84nm - 投稿数: 8
tsuzukiさん
ご連絡ありがとうございます。
> DBの設定を貼っていただくことは可能でしょうか。
以下となります。
grep -v '#' /etc/my.cnf
-----------------------------------------------
[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
old_passwords=1
default-character-set=utf8
character-set-server=utf8
default-storage-engine=INNODB
[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid
-----------------------------------------------
初期構築を別の人員が行ったサーバでmysqlの設定をきちんと確認したていませんでした・・・。
ご指摘ありがとうございます。
zabbixエージェントタイムアウト秒数を伸ばす前に
ご指摘頂いた通りDBのパフォーマンスを向上を先に行いたいと思います。
innodb_file_per_table
innodb_buffer_pool_size=512M
innodb_log_file_size=128M
などを設定してみて様子を見てみます。
また1.8.2からバージョンアップは将来行う予定ですが、zabbixAPIを利用して監視設定を行う管轄が異なるプログラムがある関係ですぐには行うことが出来ない、という事情があります。
以上です。
tsuzuki - 投稿数: 78
hsnmさん
DBの情報ありがとうございます。
書かれているようなinnodb系のオプションを追加することでパフォーマンスは改善するかと思います。
あと、DBのパフォーマンスチューニングについては以下資料にも一部記載されてましたので、よかったら参照してみてください。
http://www.zabbix.jp/files/seminar/20100730_ZABBIX-JP_StudyMeeting_2.pdf