Zabbix agent pingの誤検知について
いつもお世話になっております。
hirofumiと申します。
Zabbix agent pingで特定の機器だけ誤検知が発生しており、原因不明です。
大変お手数ではございますが、原因特定にご協力頂けないでしょうか。
【システム情報】
Zabbixサーバ(ZABBIX02)：CentOS 6 Update4 x86_64
Zabbixクライアント(XEN01)：Windows2008 SE
Zabbixクライアント(XEN07)：Windows2008 SE
Zabbixクライアント(XEN08)：Windows2008 SE
Zabbix Version：Zabbix-2.2.7
アイテム：Zabbix agent ping
キー：agent.ping
更新間隔：60秒
トリガー：{Template名:agent.ping.nodata(300)}=1
【現象】
・Zabbixクライアントは毎日AM5:20～5:50頃にかけてOS再起動を実施している。
・しかし、OS再起動を実施しているのにもかかわらず、Zabbix agent pingの値はずっと
「1」を取得している。
・Zabbix agent pingのトリガーは
{Template名:agent.ping.nodata(300)}=1
としているが、イベントとして検知するのは、なぜかOS停止が発生したタイミングで
ステータスが正常、OS起動後のタイミングでステータスが障害と、本来のステータス
とは逆の状態でイベントが挙がる。
・イベントではZabbix agent pingは障害が発生したままでリカバリとなっていないのに
システムステータスはオールグリーンで異常なしの状態である。
・Zabbixサーバのログを確認しても、該当時間帯のXEN01に関するログは以下の2行しか
挙がっておらず、OS起動後のタイミングで障害として検知している動作がログにない。
5269:20141211:052201.554 temporarily disabling Zabbix agent checks on host "XEN01": host unavailable
5269:20141211:052504.978 enabling Zabbix agent checks on host "XEN01": host became available
・なお、OS再起動の時間帯はメンテナンス期間として設定している。
(XEN01は毎日5:20-5:40、XEN07/XEN08は毎日5:30-5:50をメンテナンス期間と設定)
【疑問点】
(1) なぜOS再起動を実施しているのにもかかわらず、Zabbix agent pingの値はずっと
「1」を取得しているのか？
※ping、agent pingともに監視間隔は60秒です
(2) なぜZabbix agent pingの値はずっと「1」を取得しているにもかかわらずトリガー
に検知されるのか？
(3) なぜOS停止が発生したタイミングでステータスが正常になり、OS起動後のタイミング
でステータスが障害となるという、設定とは逆のイベントが検知されるのか？
(4) (3)が発生しているのはXEN01だけであり、同じテンプレートを使用している他の
クライアント(XEN07/XEN08)では発生していないのはなぜか？
バグ、不具合情報など、上記の現象の原因について心当たりなどありませんでしょうか。
原因特定にご協力頂けますと幸いです。
※各種画面ショットは取得しておりますが、ファイル数が多く、Zipファイルの添付が
できないようなので添付は見合わせます。
以上です。
- zabbix_server.txt (73.5 KB)
TNK - 投稿数: 4769
Agent pingの値が1のままとのことですが、最新データの画面で、
その時間帯の前後の値のタイムスタンプを確認してみてください。
恐らく、アイテムで設定されている60秒間隔になっていないところ
があるはずです。
ログにもhost unavailableなどと出ているようですので、その状態
ではagent.pingの値が取得できないので、その直前に取得できたタ
イミングの値1がその時点の最新値になっているのだと思われます。
取得した値のタイムスタンプも考慮してトリガーで設定されている
条件と再度照らし合わせてみてください。
hirofumi - 投稿数: 43
ご回答ありがとうございます。
本日12/12 AM05:00-06:00のAgent pingのタイムスタンプを添付致します。
このタイムスタンプよりAM05:20：27～05：25：27はOS再起動のため、
情報取得できていないことはわかりました。
イベントはAM05：25：27にリカバリし、その3秒後の05:25:30と05:40：00に
障害と検知しています。
上記のイベントは毎日同じ時間に発生しており、何らかの規則性があるのは
見えるのですが、なぜAgent pingの値が「1」と取得できているのにイベントに
障害通知が挙がるのか、同じテンプレートを使用している機器の中でなぜ1台
だけこの現象が発生するのか、その原因がわかりません。
設定を見る限りは問題ないように見えます。バグなどの可能性はございません
でしょうか。
以上、よろしくお願い致します。
TNK - 投稿数: 4769
トリガー：{Template名:agent.ping.nodata(300)}=1 と設定されて
いるのですから、値が取れていない場合に最後に取得したタイミン
グから300秒経過しているかどうかという基準で判定されます。
しかも、nodata()は30秒間隔でチェックされるので、アイテムが取
得したタイミングでトリガーの条件式が評価されるわけではありま
せん。
今回の場合、05:20:27に値を取得してから次に取得できるまでに5
分経過してしまったと判断されて05:25:30に障害と判断された可能
性が考えられます。
05:25:27に取得できているので、5分経っていないはずなのですが、
このあたりの処理タイミングのずれで、障害とみなされてしまった
可能性が考えられます。
あと、05:40：00は、障害発生ではなく障害が復旧してトリガーの
状態が正常になったということがイベントに記録されているのであ
りませんか？
参考までに、検知されない他のサーバで、Agent pingの値が取得で
きていなかった期間はどのような長さであったかも比較してみて頂
けませんでしょうか。
hirofumi - 投稿数: 43
ご回答ありがとうございます。
提示する情報が五月雨式となり、申し訳ありません。
XEN01のイベントログ、XEN08の同時間帯のAgent pingの取得値を添付致します。
内容を見て頂ければ、設定や取得値とは関係なくイベント出力されていることが
わかって頂けるかと思います。
なお、XEN08は再起動の時間帯が05:30:06-05:35:06となっております。
以上、よろしくお願い致します。
TNK - 投稿数: 4769
繰り返しになりますが、取得値の値は関係ありません。
トリガーにはnodata()しか指定されていないのですから、値を取得
できた時刻だけを見て判断してください。
イベントのログを確認させて頂きましたが、5:25は先ほど回答させ
て頂いた通り、タイミングの問題だと思われます。
5:40は、継続期間の値が異常ですので、保存されている履歴データ
に誤った情報が記録されてしまっているのかもしれません。
可能であれば、対象のホストのAgent pingの履歴を一度削除してみ
てはいかがでしょうか。
hirofumi - 投稿数: 43
ご回答ありがとうございます。
5:25:27のリカバリイベントと5:25:30の障害イベントはタイミングの問題とのことですが、
本来は、障害通知→リカバリとなるべきところが、内部処理で障害イベントの方が処理に
時間がかかるために、リカバリの後に障害通知がイベントとして挙がっているだけで、
Zabbix Agent pingのステータスは5:25:27で復帰した正常のステータスのままである
という見解でしょうか。
その場合、毎日同じ時間でリカバリの後に障害通知が挙がるものなのでしょうか。
5:40の方ですが、「継続期間の値が異常」というのがどういう意味なのかよくわかりませんが、
ひとまず履歴データを削除してみました。
ただ、削除後、5分経過しても障害イベントもリカバリイベントも挙がりませんでした。
一旦、OS再起動まで静観してみます。
以上、よろしくお願い致します。
TNK - 投稿数: 4769
例えば、2014/12/12 5:40の継続期間の欄をご覧ください。
7h 28m 58s
と7時間以上も障害状態が継続していると判断されているので、そ
う判断してしまうような履歴データがDB上にある可能性があると予
想したまでです。
あと、Zabbixサーバと監視対象のサーバの時計が合っているかも確
認しておいてください。
hirofumi - 投稿数: 43
本件、ご回答ありがとうございます。
履歴データを削除し、週末の動きを見てみましたが、やはり削除前と動作が
変わりません。
時刻ずれについても確認しましたが、時刻のずれはありませんでした。
メンテナンス期間を5:20-5:40としていますが、メンテナンス期間が空ける
5:40:00に必ず障害としてイベントに挙がり、継続期間もよくわからない時間
となっております。
他に考えられる要因はございますでしょうか。
また、5:25:27のリカバリイベントと5:25:30の障害イベントはタイミングの
問題と言われておりましたが、5:25:30の障害イベントの継続期間を見ると
3s となっておりますので、タイミングの問題で5:25:30の障害→5:25:27の
正常と検知されたのではなく、5:25:27の正常→5:25:30の障害と、正常から
障害になったということではないのでしょうか。
以上、よろしくお願い致します。
KAZ - 投稿数: 1085
hirofumiさん
横から失礼します。
nodata等の時刻に関する関数を使うと監視間隔とは関係なく０秒と３０秒にチェックが走ります。
なので、zbx_events_export.txtの
０秒と３０秒はnodataのチェックタイミング
２７秒は監視タイミングと思えます。
メンテナンス期間はデータの収集ありにしてますか？
それによっても動作変わってくるような…
hirofumi - 投稿数: 43
KAZさん、ご指摘ありがとうございます。
nodataは監視間隔と関係なく、0秒と30秒にチェックが入るのですね。
メンテナンス期間ですが、対象はホスト(XEN01)を指定し、データ収集ありにしています。
ただ、同様の設定でメンテナンスの時間帯(OS再起動の時間帯)だけ異なっている機器
(XEN07、XEN08)ではZabbix Agent pingのイベントは上がっていないため、なぜこの機器
だけ現象が発生しているのかの原因が特定できない状態です。
以上、よろしくお願い致します。
KAZ - 投稿数: 1085
hirofumiさん
最初のほうよく読んでいなかったのですが…
host unavailable
上記は、監視対象ホストに接続できていない時に出力されます。
host became available
上記は、監視対象ホストに接続できた時に出力されます。
で、下記ですがログレベルが3だからです。4にしないと出ません。
・Zabbixサーバのログを確認しても、該当時間帯のXEN01に関するログは以下の2行しか 挙がっておらず、OS起動後のタイミングで障害として検知している動作がログにない。XEN01とXEN07、XEN08の違いですが、何のOS使っていてどう言う設定しているかわからないとわからないかと。
Zabbixの設定に差がないなら、OS側に差があるということでは？
hirofumi - 投稿数: 43
KAZさん、ご返信ありがとうございます。
助言頂いた通り、ログレベルを変更して詳細を確認するように致します。
なお、XEN01、07、08のOSですが、1番最初の問い合わせ時に記載していますが、
すべて同じOS(Windows2008 SE)となっており、OS側に違いはございません。
OS再起動のタイミング以外はほぼ同じですので、Zabbix側のバグなのでは？と
いう疑問を持った次第です。
以上、よろしくお願い致します。
zinten - 投稿数: 69
hirofumiさん
この辺の障害の親戚じゃないですか？
https://support.zabbix.com/browse/ZBX-6170
評価タイミングが近い ＋ 評価を行うプロセスが異なる場合に発生するバグです。
特定のホストだけ起こるのは評価タイミングがitemidと監視間隔を元に決められているので
たまたま特定のアイテムだけこのタイミングになっているのかと。
違ってたらごめんなさい。
hirofumi - 投稿数: 43
zuntenさん
情報提供ありがとうございます。
まさにこういう情報を求めておりました。
ログレベルの設定変更は調整中でまだ確認できておりませんが、
頂いた情報と合わせて確認するように致します。
> 特定のホストだけ起こるのは評価タイミングがitemidと監視間隔を元に決められている
現在は1分間隔で、xx:xx:27 と毎分27秒のときに監視が行われていますが、
これはitemidから勝手に決まっているものなんでしょうか。
例えばこれを xx:xx:15 といったように毎分15秒のときに監視を行うように
変更することはできるのでしょうか。
タイミングの問題であれば、この部分を意図的に変更できれば回避できるのでは
ないかと思ったのですが、可能でしょうか。
以上、よろしくお願い致します。
TNK - 投稿数: 4769
次の監視タイミングの時間調整のシードにitemidが利用されている
ので、該当するアイテムのitemidが変わればタイミングが変わる可
能性があります。
アイテムを個別にホストに設定されていたのであれば、そのアイテ
ムを一時削除して再作成し、テンプレートを紐づけていたのであれ
ば、ホストの設定画面のテンプレートタブで該当するアイテムが含
まれるテンプレートを、
リンクデータと保存データを削除
を選択して削除して保存後、改めてテンプレートの紐づけをし直す
ことでitemidは変化します。
テンプレートの他のアイテムの履歴は削除したくないということで
あれば、「リンクを削除」でホストの変更を保存後、アイテムを確
認してください。
テンプレートから外れた個別のホストに設定されたアイテムとなる
と思いますので、ここで、該当するアイテムを削除後、テンプレー
トを紐づけしなおすことでも該当するアイテムを再作成することに
なります。
ご確認ください。
zinten - 投稿数: 69
TNKさん
itemidによる制御は現実的ではない気がしています。
検証がきちんとできているわけではないですが
問題点としては1つのプロセスが多くのヒストリー、トリガーを担当しており、
Begin ～ Commitまでの間がかかっているのがひとつ原因としてあるのでは？と思っています。
この点を解消するのにStartTimerやStartDBSyncerの数を増やしてあげることで
1プロセスあたりの担当するヒストリー、トリガー量を減らし、
事象の発生を軽減できないでしょうか。
根本原因を取り除けていないのであくまでも軽減策ですが。。。
TNK - 投稿数: 4769
根本的な解決策ではありませんが、タイミングを変えたいとのことであったので、
手順をご紹介したまでです。
KAZ - 投稿数: 1085
hirofumiさん
助言頂いた通り、ログレベルを変更して詳細を確認するように致します。
ログ見るのが一番手っ取り早いです。
TNK - 投稿数: 4769
hirofumiさんへ
Zabbixサーバの各プロセスの負荷状況に関しては、Zabbixサーバに
テンプレートの
Template App Zabbix Server
をリンクしてあると、ホストスクリーンの
Zabbix server health
を開くことで、各プロセスの稼働状況を確認することができます。
特定のプロセスのbusy率が60～70%を超えるような時間帯が無いか
確認してみてください。
もし、そのようなプロセスがある場合は、zintenさんが書かれてい
る通り、プロセス数を増やすような対応をされたほうが良いかもし
れません。
hirofumi - 投稿数: 43
TNKさん
zintenさん
KAZさん
皆さん、ご回答、ご助言ありがとうございます。
Zabbixサーバの各プロセスの負荷状況についても承知致しました。
こちらの設定も盛り込むか検討致します。
ただいま設定変更について調整中ですが、進捗があれば改めてご報告させて頂きます。
以上、よろしくお願い致します。