ログ監視の取りこぼし
いつもお世話になっております。
ログの監視を設定して順調にエラーを検知できていましたが、1度だけ検知が出来ない事がありました。
監視対象のログファイルにはエラーメッセージが出力されていますが、障害として検知されず履歴にも残っておりません。
■環境
Zabbixサーバ：1.8.16(CentOS6、IP：10.10.25.12)
Zabbixエージェント：1.8.15(Windows 2008、IP：10.10.23.14、ホスト名：SP-G-APSRV-02)
■ログ監視設定
●アイテム
タイプ：Zabbixエージェント（アクティブ）
キー：log[{$JBOSS_LOG},"\[FATAL\].*"]
検知されなかったエラーログは、10/15 16:39に出力されましたが、監視対象のログの履歴には10/15以前のログが残っているだけです。
ログの出力された時間のサーバログは以下の通りです。
該当時刻付近で「Sending list of active checks to [10.10.23.14] failed: host [SP-G-APSRV-02] not monitored」が頻発していました。
また、ログには１つのサーバだけでなく、他のサーバの「not monitored」も頻発しています。
■サーバログ
1693:20131015:163734.848 executing housekeeper
1693:20131015:163735.924 housekeeper deleted: 4429 records from history and trends, 0 records of deleted items, 0 events, 0 alerts, 0 sessions
1675:20131015:164342.281 Sending list of active checks to [10.10.23.13] failed: host [SP-G-APSRV-01] not monitored
1681:20131015:164411.754 Sending list of active checks to [10.10.24.14] failed: host [SP-G-DBSRV-02] not monitored
1676:20131015:164719.648 Sending list of active checks to [10.10.23.14] failed: host [SP-G-APSRV-02] not monitored
1681:20131015:164919.141 Sending list of active checks to [10.10.23.14] failed: host [SP-G-APSRV-02] not monitored
1693:20131015:173736.584 executing housekeeper
1693:20131015:173737.439 housekeeper deleted: 4432 records from history and trends, 0 records of deleted items, 0 events, 0 alerts, 0 sessions
1693:20131015:183737.998 executing housekeeper
エージェントのログは以下の通りです。同じく、「No active checks on server: host [SP-G-APSRV-02] not monitored」が出力されていました。
■エージェントログ
3796:20131011:160258.200 No active checks on server: host [SP-G-APSRV-02] not monitored
3796:20131011:160458.328 No active checks on server: host [SP-G-APSRV-02] not monitored
3796:20131015:164716.961 No active checks on server: host [SP-G-APSRV-02] not monitored
3796:20131015:164916.453 No active checks on server: host [SP-G-APSRV-02] not monitored
サーバとエージェントの設定ファイルで、デフォルトから変更したのは以下のみです。
■zabbix_server.conf
ListenIP=10.10.25.12
■zabbix_agentd.conf
Server=10.10.25.12
Hostname=SP-G-APSRV-02 ←WEBインターフェース上のホスト名と一致していることは確認済み
# ListenIP=127.0.0.1 ←コメントアウト
ログの監視が全くできないわけではなく、今わかっているだけでは1度だけの取りこぼしですが、他にも取りこぼしがあるのではないか？や、対策が求められています。
原因や対策など教えていただけないでしょうか。よろしくお願いします。
TNK - 投稿数: 4740
とのことですが、それ以降はエラーログも発生せず、アクションも
実行されていないということでよろしいですか？
つまり、複数発生したエラーに対して、途中の1件だけ抜けてしま
っているのではなく、特定の時刻のエラー発生以降のログ監視がで
きていないということではありませんか？
not monitoredというログが出ているということは、その時点での
該当サーバの監視ができていない状態になっていることを示します。
つまり、監視できていませんので、エラーログが出力されても検知
できません。
ですので、その現象も解決することが必要です。
ログに関しては、どこまで確認したかをファイルの先頭からのバイ
ト数で記録しているので、1つのファイルに追記のみしているので
あれば、必ず次のチェックではその続きを読み込むようになってい
ます。
ですので、対象のログファイルのローテーションなどを行っていな
いかが影響してきます。
ローテーションの仕方によっては、logrt[]を利用した方が良い場
合があります。
アイテムの設定として、「$JBOSS_LOG」という名前から推測すると、
JBossのログの監視をされているのでしょうか？
その場合、そのログのローテーションなどはどのようにされていま
すか？
まずは、not monitoredになってしまう原因も調査されることをお
勧めします。
各サーバの応答が遅くなってタイムアウトが発生したことがきっか
けになっているのであれば、設定ファイルのTimeoutの値を伸ばす
ことで改善される場合があります。
監視対象や監視アイテムがたくさん登録されていて、1秒あたりの
監視項目数が多い場合は、Pollerと呼ばれるアイテムの値を取得す
るためのプロセスの数を増やすことで改善される場合もあります。
現時点のアイテムの値取得のための処理がキューに溜まってしまう
ことでも状態を確認できますので、「管理」->「キュー」でキュー
に溜まってしまった処理がないかもご確認ください。
katosai - 投稿数: 36
TNK様 いつもお世話になっております。早速の回答をありがとうございます。
書かれたように、途中の1件だけ抜けているわけではありません。
ただ、「特定の時刻のエラー発生以降のログ監視ができていない」というと、「SP-G-APSRV-02」の監視ができなくなったようにように見えますが、CPUやディスクの監視は出来ておりますので、通信が全く出来なくなったわけではないと思われます。
logrt[]を利用した方が良い場合というのを教えていただけないでしょうか。
やはりnot monitoredの場合は、検知できないのですね。
Timeoutの値は、デフォルト設定のままです。
過去ログを見ると、Timeout値では改善されない例があるようですね。
サーバ側とエージェント側の２つありますが、どちらを変えればよいでしょうか？
また、どのように原因を調査すればよいか教えていただけないでしょうか。
確認したところ、全て０となっており、溜まっているキューはありませんでした。
お忙しいところすみません。よろしくお願いします。
TNK - 投稿数: 4740
Red Hat Enterprise LinuxやCentOSでも利用されているlogrotate
というログローテーションの仕組みがあります。
このログローテーションの仕組みでログのローテーションを行って
いる環境で、ログをチェックする直前にローテーションが行われた
ときに、ローテーションする以前のログファイルで、チェックを行
っていないものがあった場合に、以前読み込んだ場所からログを確
認するような場合に利用します。
log[]キーを利用した場合は、ログファイルがローテーションされ
てしまうと、最新のファイルのみが対象となるので、前回チェック
した後に出力されたがローテーションされてしまったログは読み飛
ばされることになります。
logrotateを利用していなくても、古いログファイルのファイル名
を変更して、新しいログファイルを作成してその新しいログファイ
ルに出力先を切り替えるような処理を行っていれば、logrt[]を利
用して処理できると思います。
どこの処理でタイムアウトになっているのかわからないので、両方
とも変更してみてください。
特定するには、DebugLevelを4などにして詳細なログを出力させる
と、どこでタイムアウトが発生しているか特定できる情報が出力さ
れるはずですので、その詳細なログをご確認頂くことになります。
最後に、キューに溜まってしまっていないのであれば、他のアイテ
ムの監視には影響を与えていないのかもしれません。
「設定」->「ホスト」->特定のホストの「アイテム」
とクリックして、表示されたアイテム一覧のステータスが「取得不
可」になっているものがないかをご確認ください。
katosai - 投稿数: 36
TNK様、回答ありがとうございました。返信が遅くなりすみません。
本番環境へのタイムアウト設定の調整に時間がかかりました。
logrt[]の仕組みの説明をありがとうございました。
これは対応すべく、調整したいと思います。
本番環境のサーバとエージェントに以下のタイムアウト設定を入れました。
Timeout：3s→30s
この結果はまだわかりません。
検証環境にて、Timeout値はデフォルト3sのまま、DebugLevelを４にしてみました。
どこからどこまで抜き出していいのかわかりませんが、「Sending list of active checks ～」の前後を以下に載せます。
＃＃＃＃ Zabbixサーバログ ＃＃＃＃＃＃＃
1652:20131029:141213.860 Syncing ...
1652:20131029:141213.860 In DCsync_history() history_first:554 history_num:0
1652:20131029:141213.860 history syncer #3 spent 0.000043 seconds while processing 0 items
1652:20131029:141213.860 sleeping for 5 seconds
1653:20131029:141213.860 Syncing ...
1653:20131029:141213.860 In DCsync_history() history_first:554 history_num:0
1653:20131029:141213.860 history syncer #4 spent 0.000038 seconds while processing 0 items
1653:20131029:141213.860 sleeping for 5 seconds
1650:20131029:141213.860 Syncing ...
1650:20131029:141213.860 In DCsync_history() history_first:554 history_num:0
1650:20131029:141213.860 history syncer #1 spent 0.000038 seconds while processing 0 items
1650:20131029:141213.860 sleeping for 5 seconds
1644:20131029:141214.030 In get_pinger_hosts()
1644:20131029:141214.030 In DCconfig_get_poller_items() poller_type:3
1644:20131029:141214.030 End of DCconfig_get_poller_items():0
1644:20131029:141214.030 End of get_pinger_hosts():0
1644:20131029:141214.030 In process_pinger_hosts()
1644:20131029:141214.030 End of process_pinger_hosts()
1644:20131029:141214.030 icmp pinger #1 spent 0.000259 seconds while processing 0 items
1644:20131029:141214.030 In DCconfig_get_poller_nextcheck() poller_type:3
1644:20131029:141214.030 End of DCconfig_get_poller_nextcheck():1383023538
1644:20131029:141214.030 sleeping for 4 seconds
1640:20131029:141214.042 Trapper got [{
"request":"active checks",
"host":"TMI-K-APSRV-01"}] len 55
1640:20131029:141214.042 In send_list_of_active_checks_json()
1640:20131029:141214.042 In get_hostid_by_host() host:'TMI-K-APSRV-01'
1640:20131029:141214.042 query [txnlev:0] [select hostid,status from hosts where host='TMI-K-APSRV-01' and status in (0,1) and proxy_hostid=0 and hostid between 000000000000000 and 099999999999999]
1640:20131029:141214.042 Sending list of active checks to [10.10.13.12] failed: host [TMI-K-APSRV-01] not monitored
1640:20131029:141214.042 Sending [{
"response":"failed",
"info":"host [TMI-K-APSRV-01] not monitored"}]
1656:20131029:141214.443 In collect_selfmon_stats()
1656:20131029:141214.443 End of collect_selfmon_stats()
1656:20131029:141214.443 sleeping for 1 seconds
1654:20131029:141214.777 In process_escalations()
1654:20131029:141214.777 query [txnlev:0] [select escalationid,actionid,triggerid,eventid,r_eventid,esc_step,status from escalations where status in (0,4,5,1) and nextcheck<=1383023534 and escalationid between 000000000000000 and 099999999999999]
1654:20131029:141214.777 End of process_escalations()
1654:20131029:141214.777 escalator #1 spent 0.000593 seconds while processing escalations
1654:20131029:141214.777 sleeping for 3 seconds
＃＃＃＃ Zabbixサーバログ ＃＃＃＃＃＃＃
タイムアウトが起こる原因を教えていただけないでしょうか。よろしくお願いいたします。
kodai - 投稿数: 1341
上記のログだけでは原因の特定は難しいと思います。
アクティブチェックの処理が行われた時点で、すでにホストは"not monitored"だったようですから、原因の特定にはTMI-K-APSRV-01ホストがnot monitoredになってしまった原因(もしくはWebインターフェースから無効に設定されている？)箇所のログが必要になります。
zabbix_server.logをTMI-K-APSRV-01でgrepしてみると他に何かでてきませんか？
katosai - 投稿数: 36
kodai様、回答ありがとうございます。
対象となるホストは、メンテナンスの設定に出し入れはしておりますが、Webインターフェースでは無効にしておりません。
zabbix_server.logを「TMI-K-APSRV-01」でgrepして、10/29の起動からのログを抽出しました。
「他に何かでてきませんか？」とのことですが、怪しい箇所自体がわかりませんので、見ていただけないでしょうか。
お忙しいところすみません。よろしくお願いいたします。
TNK - 投稿数: 4740
先のログ内で、
とあるように、タイムアウトが発生しているのではなく、対象のホ
ストが「無効」(not monitored)と判断されているために、ログ取
得のアイテムに関する情報が引き渡されていないようです。
そして、添付して頂いたzabbix_server_log(activecheck問題).txt
を確認してみましたが、対象のホストが「無効」になっているため、
トリガーの評価を行おうとしても、対象のホスト自体が無効になっ
ているためにトリガーの評価を行わないというようなログが連続し
ているようにみうけられます。
手動でホストを無効に設定しなくても、値が取得できない時に、無
効となっていると判断される場合があったと思いますので、ログ以
外の値に関しては正常に値を取得できできているのかをご確認くだ
さい。
取得できていない場合は、対象のホストを手動で一時的に無効にし
てから有効にし直してみてください。
あと、トリガーの式の評価自体でもエラーが発生してしまっている
と見受けられる箇所もありますので、
・アイテム
・トリガー
の設定を再度ご確認ください。
有効なアイテムでなければ、トリガーの式に用いることはできませ
んのでご注意ください。
例えば、
となっていますので、ホスト「TMI-K-APSRV-01」にはkドライブが
ないのではありませんか？
ご確認ください。
katosai - 投稿数: 36
TNK様、回答ありがとうございます。
この設定は見直して既にアイテムを無効としております。近日中に削除します。
9月、10月の2ヶ月間、現在使用している商用の監視ツールと並行運用してきました。
このログはヒドイ時は2分間隔で30分間出力され続けたこともありましたが、運よく？なのか商用ツールで検知した障害をZabbixで検知できなかったというのは今回の1件のみでした。
ディスク監視やCPU監視、ポート監視も検知できていました。
TNK - 投稿数: 4740
今確認させて頂きたいのは、障害を検知したかではなく、障害を検
知するためのアイテムの値取得ができているかです。
対象のホストのアイテム一覧を開いて、「取得不可」の状態になっ
ているものが無いか、各アイテムで想定している間隔で継続して値
を取得できているかを確認していただけませんか？
katosai - 投稿数: 36
TNK様、ありがとうございます。
取得不可状態になっているアイテムはございません。
各アイテムの値ですが、10/29 13:45～10/29 14:15頃まで全てのアイテム（CPU、ディスク、ポートなど）の値が設定した監視間隔で取得ができておりませんでした。
添付した「zabbix_server_log(activecheck問題).txt」の中で「Sending list of active checks～」が出力されている時間と一致しています。
katosai - 投稿数: 36
他に確認するべき観点はございますでしょうか。
お忙しいところすみません。よろしくお願いいたします。
katosai - 投稿数: 36
未だに原因はわかっておりません。
grepせずに、ログから「not monitored」になる直前部分を以下に抜き出しました。
「not monitored」と表示される前にクエリを投げていますが、ここは関係ないでしょうか？
クエリの結果が「not monitored」だったか、結果が取れなかったから「not monitored」になったのでしょうか？
お忙しいところすみません。よろしくお願い致します。
katosai - 投稿数: 36
その結果ですが、「Sending list of active checks to～」がまだ出力されていました。
監視対象のホスト1台あたり約10分ほど「not monitored」状態になる現象が5時間ほどみられます。
ただ、「not monitored」状態になる頻度は若干減ったようにみえます。
他の原因や確認点などございませんでしょうか。
TNK - 投稿数: 4740
可能であれば、not monitoredが発生する時間帯に、Webフロントエ
ンドから、「管理」->「キュー」とキューの状態を確認して、それ
ぞれのタイプ別にキューに溜まった状態が発生していないかをご確
認ください。
難しければ、キーが「zabbix[queue]」のアイテムを作成してキュー
の変化を確認してみてください。
キューに溜まってしまっているようであれば、各アイテムの値を取
得してくるPollerの数が不足している場合も考えられます。
極端な例ですが、値の取得処理に3秒かかるのに、1秒間隔で取得す
るようなアイテムがあったりすると、そこで処理しきれずにキュー
に溜まるようなことが発生してしまうでしょう。
特定の時間帯だけ日次処理やバックアップの処理で応答が遅くなり、
特定のアイテムのキューがたまって値取得のタイムアウトを超えて
しまうなどして、not monitoredとなってしまう状況が発生してい
るのではないかと予想しています。
katosai - 投稿数: 36
TNK様、回答ありがとうございました。
not monitoredが発生する時間帯や条件などがわかりませんので、not monitored状態になっていることを把握することが難しいです。
そこで、以下を試してみました。
①Zabbixインターナルでzabbix[log]を設定
②「zabbix_server.log」のログ監視を設定
アイテム：log[/var/log/zabbix/zabbix_server.log,"Sending\ list\ of\ active\ checks"]
トリガー条件：{ホスト名:log[/var/log/zabbix/zabbix_server.log,"Sending\ list\ of\ active\ checks"].nodata(n)}=0
「Sending list of active checks～」がZabbixサーバログに出力されていましたが、①では通知されませんでした。
→通知されないものでしょうか？
また、デバッグレベルで出力しているため、②はループしそうです。
not monitored状態になっていることを通知することは可能でしょうか？
お忙しいところすみません。よろしくお願いいたします。
katosai - 投稿数: 36
katosai - 投稿数: 36
Timeoutの設定はデフォルトのまま、ログ出力をデバッグレベルにしていた検証環境のZabbixサーバログを確認していたところ、10分ほど前に「Sending list of active checks～」が出力され、「not monitored」状態がありました。
急いでキューの状態を確認したところ、以下が取得できました。
Zabbixエージェント：10分以上（33）
Zabbixエージェント（アクティブ）：10分以上(6)
※上記以外は皆0です。
検証環境はデータ更新の検証などで使っており、不要なホストは「メンテナンス中」になっております。
キューの詳細を見たところ、キューとなっている監視対象のホストは全てメンテナンス中のものでした。「not monitored」状態になっていたホストのキューはありませんでした。