イベントログ(予期せぬシャットダウン)の検知について
お世話になります。
バージョン1.8.16を利用しています。
イベントログ設定についてご教示下さい。
Windows Serverの予期せぬシャットダウンを以下のトリガーで設定しています。
{サーバ名:eventlog[system].str(6008)}=1
先日、あるサーバにて予期せぬシャットダウンのアラートメールが発砲されましたが
実際には予期せぬシャットダウンは発生しておらず
アラートメールには以下のメッセージが記載されていました。
イベントログ(予期せぬシャットダウン) : ドキュメント 120, document (所有者 982) は セッション 10 の (PC名 からの) プリンタ名 (ポート TS145 経由) で印刷されました。バイト数: 23485; ページ数: 1
上記ログのイベントIDは「10」となっており、本来監視したいイベントIDの「6008」ではないログを誤って取得して発砲してしまったように見受けられます。
何故このような現象になったのかの原因が分かりますでしょうか。
調査に必要な設定情報などがあれば追記させていただきますのでご協力いただけますと幸いです。
以上、よろしくお願い致します。
TNK - 投稿数: 4760
eventlogメッセージ内に6008が含まれていないのに、アクションで
そのアイテムの値をメールのメッセージとして送った際に、該当し
ないような値でのメールが届くような場合、可能性として考えられ
るのは、Zabbix 1.8系を利用していて、eventlogに大量のログが出
力されている場合に発生する可能性があると思います。
最新データの画面などで、そのメールで受け取った内容のメッセー
ジの直前に、恐らく6008が含まれるようなeventlogが記録されてい
ませんか？
これは、Zabbix 1.8系で取得したアイテムの値の時刻管理を秒単位
でしか行っていなかったことに影響していて、防ぐためにはZabbix
のバージョンを2.0以降のバージョンにアップグレードすることで
防ぐことができるようになります。
summer-09 - 投稿数: 16
TNK様
早速のご回答ありがとうございます。
>Zabbix 1.8系を利用していて、eventlogに大量のログが出力されている場合に発生する可能性があると思います。
ご察しの通り、本サーバのイベントログには大量のログが出力されております。
＞最新データの画面などで、そのメールで受け取った内容のメッセージの直前に、恐らく6008が含まれるようなeventlogが記録されていませんか？
対象となったイベントログの2分ほど前に、以下のイベントログが記録されておりました。
ドキュメント 118, ActiveReports Document (所有者 638) は セッション 31 の (PC名 からの) プリンタ名 (ポート TS720 経由) で印刷されました。バイト数: 516008; ページ数: 8
上記文章中に「バイト数: 516008」とあり、「6008」が含まれているため検知されたということでよろしいのでしょうか。
また追加で1点確認なのですが、仮に上記の様な動きをしているとなると
今回設定しているトリガー({サーバ名:eventlog[system].str(6008)}=1)は、
イベントログのイベントIDを検知するするのではなく、イベントログ内の文章(説明)を検知する仕組みなのでしょうか。
TNK - 投稿数: 4760
その通りです。
記載頂いたトリガー条件式の中では、str()という関数を利用され
ているので、eventlog[system]で取得してきた文字列の中に「6008」
という文字列が存在するかをチェックする条件式になっています。
イベントIDを条件にされたいのであれば、logeventid()という関数
を利用されてみてはいかがでしょうか？
トリガーの条件式は、
{サーバ名:eventlog[system].logeventid(6008)}=1のように記述できたと思います。
ご参考：
https://www.zabbix.com/documentation/1.8/manual/config/triggers
# logeventidは、Zabbix 1.8.5以降で利用できるようです。
summer-09 - 投稿数: 16
TNK様
str()という関数の仕組みについて理解することが出来ました。
logeventid()という関数については一度設定をして確認してみたいと思います。
最後に、以下の内容についていまいち理解が出来なかったためご教示下さい。
＞これは、Zabbix 1.8系で取得したアイテムの値の時刻管理を秒単位でしか行っていなかったことに影響していて
時刻管理を秒単位でしか行っていなかったとあるのですが、イベントログには
① 先ほどの「6008」が記述されていたイベントログが出力
② ①の1分35秒後にイベントログに出力
③ ②の14秒後にイベントログに出力 ←このイベントログが発砲
となっており、1分49秒後のイベントログがアラート発砲されています。
1秒毎などで出力されていれば、何となく理解できるのですが、1分以上間が空いているのに正しく動作されていない理由がいまいち理解できておりません。
私の理解不足かもしれませんが、この点についてご教示いただけますと幸いです。
TNK - 投稿数: 4760
イベントログからの取得処理は、リアルタイムで行われているわけ
ではありません。
アイテムで設定した取得間隔で、新しいイベントログが出力されて
いないかを確認しますので、実際のイベントログが出力されてから
のタイムラグが発生する可能性があります。
さらに、取得して障害を検知したあとで、実際にアクションが実行
処理されるまでにもデフォルトだと最大30秒程度のタイムラグが発
生する場合があったはずです。
実際にアクションの処理を実行する時に、メッセージ内に記述され
たマクロを展開するので、メッセージ内に記載されたマクロによっ
ては、障害が発生したタイミングのイベントログではなく、最新の
イベントログを取得する場合があるため、必ずしも障害検知した際
のイベントログとメール内の内容とか合致しない場合があります。
これ以上は、
・アイテムの設定
・トリガーの設定
・アクションの設定
・Zabbix上に保存されている各イベントログの詳細情報
・Zabbixが障害と判定したイベントの詳細情報
など、設定内容の詳細と、取得されたイベントログの詳細、メール
で送信された内容などの詳細情報がなければ、確認することができ
ません。
(2)で、何が出力されたのかがわかりません。
Windows上のイベントログと、Zabbix上のイベントとを明確に分け
て、それぞれどのタイミングで何が出力されたのかをお教え頂けま
せんか？
(3)で「このイベントログが発砲」と書かれていますが、そのタイ
ミングのイベントログがメール内にあったということですか？
ZabbixのWebインターフェース上の「監視データ」->「イベント」
で表示されるイベント一覧から、該当するイベントの内容の詳細も
確認してみてください。
恐らく、eventlog[]アイテムの監視間隔とアクションが実行される
までのタイムラグ、そして、メッセージ内に記載されているマクロ
の組み合わせによって、1分以上のずれが発生したのだと思われます。
summer-09 - 投稿数: 16
TNK様
ご丁寧に説明いただきありがとうございます。
記載いただいた内容で理解できました。
>(2)で、何が出力されたのかがわかりません。
>Windows上のイベントログと、Zabbix上のイベントとを明確に分け
>て、それぞれどのタイミングで何が出力されたのかをお教え頂けませんか？
(2)は以下のWindowsのイベントログが出力されています。
ドキュメント 119, document (所有者 982) は セッション 10 の (PC名 からの) プリンタ名 (ポート TS145 経由) で印刷されました。バイト数: 44834; ページ数: 1
このWindowsイベントログはZabbix上のイベントには表示されていません。
>(3)で「このイベントログが発砲」と書かれていますが、そのタイ
>ミングのイベントログがメール内にあったということですか？
>ZabbixのWebインターフェース上の「監視データ」->「イベント」
>で表示されるイベント一覧から、該当するイベントの内容の詳細も
>確認してみてください。
ご認識の通りで、発砲されたメールに記載されていた内容が、(3)のWindowsのイベントログのものでした。
#私が一番最初に投稿した以下のものがメールに記載されていた内容です。
#イベントログ(予期せぬシャットダウン) : ドキュメント 120, document (所有者 982) は セッション 10 の (PC名 からの) プリンタ名 (ポート TS145 経由) で印刷されました。バイト数: 23485; ページ数: 1
また、これはZabbix上のイベントにも同じものが記載されております。
本来は(1)の「6008」が記載されたWindowsのイベントログがメールに記載されていないといけないのですが
タイムラグが発生した影響で、取得時に最新だった(3)のイベントログの情報が取得され、その内容のメールが発砲されたという理解ですが正しいでしょうか。
TNK - 投稿数: 4760
正しいと思います。
あと、ZabbixサーバとWindowsの時計のずれなどでも、Zabbix上の
タイムスタンプとイベントログ内のタイムスタンプがずれて、発生
した事象の時系列がくずれてしまうこともありますので、時刻同期
に関してもご注意ください。
summer-09 - 投稿数: 16
TNK様
了解致しました。ありがとうございます。
なお、以前ご教示いただいた下記の設定を実施したところ問題なく動作致しました。
#ただし、既にカットオーバーされているお客様のサーバでイベントID6008は発生させることはできなかったため、別のID番号で検証しましたが。
{サーバ名:eventlog[system].logeventid(6008)}=1色々とありがとうございました。
本件はこれにてクローズとさせていただければと思います。