ログ監視の値の前半が欠ける
はじめまして。ryo_kと申します。
ログ監視で、値の前半が欠ける事象が発生しております。
zabbix-serverのバージョンは、zabbix-server-2.2.0-1となります。
log[(ログファイルのパス)]のアイテムで24時間監視を行っており、
何か文字列があれば検出する設定にしています。
概ね正常に全文取れているので、設定には問題がないように思えま
すが、まれに発生し、最後の数文字しか取れない事があるので、困
惑しております。
該当のログファイルはログローテートが9:00にありますが、ZABBIX
の巡回は8:58:03に行われており、直接関係はないように思えます。
原因や対策などご存じの方いらっしゃいましたら、お知恵を貸して
頂けませんでしょうか。どうぞよろしくお願いいたします。
KAZ - 投稿数: 1085
ryo_kさん
具体的な例を出して頂けると皆さんわかりやすいかと…A(^^;
尚、2.2系ですがログファイルのローテート絡みで問題点が色々あって、次の2.2.4でログ周りの処理が一新するはずです。
ryo_k - 投稿数: 13
KAZさん、ご返信ありがとうございます。
分かりにくい説明で、大変失礼いたしました。具体例を交え、再度説明させて頂ければと存じます。
監視対象はWebサーバであり、ssl_error_logに何かログがあれば検知したい思い、更新
間隔86400秒(24時間)でアイテムlog[var/xxx_xxxx_xxx/logs/ssl_error_log]を設定しています。
(IP、パス、ファイル名等は伏せさせて頂きます。)
本事象は、6/6、6/18、6/23に発生したのですが、該当ログファイルに書きこまれたログは、
それぞれ下記のようなものでした。
・[Fri Jun 06 09:22:35 2014] [error] [client xxx.xxx.xxx.xxx] user testxxx not found: /
・[Wed Jun 18 11:08:23 2014] [error] [client xxx.xxx.xxx.xxx] user corp xxxx found: /xxxxx.cgi
・[Mon Jun 23 21:34:32 2014] [error] [client xxx.xxx.xxx.xxx] client denied by server configuration: /xxx/xxx_xxxx_xxx/xxxx/xxxxxxxxm
その時の、ZABBIXの監視データ>概要>ヒストリに表示される「値」は、下記のように前方
が欠けてしまっていたという状況となります。
・ound: /
・t xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
・m
この事象は時々発生する程度で、その他は欠ける事なく全文が表示されております。
ログローテートは、cron.dailyでlogrotateを毎朝9時に走らせています。
ZABBIXの監視データ>概要>ヒストリには、毎日8:58:03でタイムスタンプがありますので、
下のように、ローテート前にZABBIXが巡回できていると認識している次第です。
----------------
<私の認識している動き>
9:00:00 var/xxx_xxxx_xxx/logs/ssl_error_logのログローテート
↓
↓
8:58:03 ZABBIXの巡回 (9:00:00～8:58:03までのログを確認)
↓
9:00:00 var/xxx_xxxx_xxx/logs/ssl_error_logのログローテート
----------------
2.2系でログローテート絡みの問題点がある事を教えて頂き、ありがとうございました。
こちらについて、一覧で紹介されているサイトやスレッドなど、もしお心当たりがありました
ら、教えて頂けませんでしょうか。
TNK - 投稿数: 4671
Zabbixエージェント側のバージョンは何を利用されていますか？
あと、監視間隔はどのくらいの時間を設定されていますか？
問題が発生しているのがローテーションの前後というわけではない
ようですので、logrt[]を利用しないことによる問題ではなさそう
です。
ただし、ローテーションされるログの場合、log[]を利用している
と、ローテーション直前のログが読み込まれない場合がありますの
でご注意ください。
症状からして、ログの行の特定の桁で切れているわけでもないよう
ですので、考えられることとしては、ログに出力されてファイルシ
ステムに同期している途中でZabbixエージェントがログを読み取ろ
うとしたことが考えられます。
もしそうだとすると、監視データ->最新データ->ヒストリで、
ound: /
の前に、
[Fri Jun 06 09:22:35 2014] [error] [client xxx.xxx.xxx.xxx] user testxxx not f
と後ろが切れてしまっているものが登録されていたりしませんか？
ご確認をお願いいたします。
主にlogrt[]を利用する際に発生する問題だったと思います。
今回はlog[]を利用されているようですので、直接関係無いかも知
れませんが、
logrt[]で、ローテーション後、毎回旧ファイルの全内容を読み込んでしまう
http://www.zabbix.jp/node/2757
logrt possibly read old log file from very beginning after log rotation
https://support.zabbix.com/browse/ZBX-7098
logrt may continue reading an old file repeatedly.
https://support.zabbix.com/browse/ZBX-8238
などで、修正されたはずであったのが、その修正内容が不十分で、
別の問題が発生してしまい、大幅にロジックを変更したようです。
ということで、logrt[]を利用されるのであれば、これからリリー
スされる2.2.4以降を利用したほうがよさそうです。
KAZ - 投稿数: 1085
ryo_kさん
OSは何でしょうか？
OSとZabbixエージェントのバージョンは？
ログはZabbixエージェント側で取得するのでZabbixエージェントのバージョンは重要かと…A(^^;
因みにcron.dailyは9時に動いてますか？
→/var/log/cronで確認すると起動時間がわかります。
CentOS6.xからcronの動き変わっていてCentOS5.xみたいに動かすためにはcronie-nonanacronいれてcronie-anacron抜いて、/etc/cron.d/dailyjobsに起動時間設定しないと指定時間では動かないことあります。
※：上記、今回の事象には関係ないと思いますが…
下記と言う認識で良いですか？
----------------
前日 09:00:00 var/xxx_xxxx_xxx/logs/ssl_error_logのログローテート
↓
↓
当日 08:58:03 ZABBIXの巡回 (9:00:00～8:58:03までのログを確認)
↓
当日 09:00:00 var/xxx_xxxx_xxx/logs/ssl_error_logのログローテート
----------------
つまり、「ローテーション後のログの読み込みで行頭がかけてしまう」事象でしょうか？
・[Fri Jun 06 09:22:35 2014] [error] [client xxx.xxx.xxx.xxx] user testxxx not found: /
・[Wed Jun 18 11:08:23 2014] [error] [client xxx.xxx.xxx.xxx] user corp xxxx found: /xxxxx.cgi
・[Mon Jun 23 21:34:32 2014] [error] [client xxx.xxx.xxx.xxx] client denied by server configuration: /xxx/xxx_xxxx_xxx/xxxx/xxxxxxxxm
その時の、ZABBIXの監視データ>概要>ヒストリに表示される「値」は、下記のように前方
が欠けてしまっていたという状況となります。
・ound: /
・t xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
・m
この事象は時々発生する程度で、その他は欠ける事なく全文が表示されております。
ここ詳細が欲しいですね。A(^^;
この事象は私の知る中で初めての事象です。
2.2系でログローテート絡みの問題点がある事を教えて頂き、ありがとうございました。
こちらについて、一覧で紹介されているサイトやスレッドなど、もしお心当たりがありました
ら、教えて頂けませんでしょうか。
このサイトの画面右上(ログイン/ログアウトの下)にサイト内検索の入力できる箇所があるのでlogと入力して検索ボタン押せば過去の事例が探せます。A(^^;
これはローテーションしたログを読みなおしてしまう障害についてのスレッド(Zabbix2.2)
http://www.zabbix.jp/node/2757
ここに色々な不具合情報等が集まります。
本家のサポートサイト
https://support.zabbix.com/secure/Dashboard.jspa
ryo_k - 投稿数: 13
TNKさん
迅速なご返信を頂いたにも関わらず、レスポンスが翌日となり、申し訳ありません。
昨日は急な業務が入り、本件に関われなくなってしまっておりました。
頂いたご質問に対し、インラインにて回答させて頂きます。
エージェントのバージョンは、1.4.6-2です。
監視間隔は、86400秒を設定しています。
http://www.zabbix.jp/node/2629でもご指摘されている件ですね？拝見いたしました。
残念ながら、後ろが切れてしまっているログはございませんでした。
ご丁寧にありがとうございます。参考にさせて頂きます。
TNK - 投稿数: 4671
監視間隔が86400秒(=1日)と設定されているのであれば、zintenさん
が書かれているような問題に該当していると思われます。
防ぐためには、第一段階として、ログの監視間隔を短くすることを
お勧めします。
そうしないと、zintenさんが書かれている問題の他にも、恐らく
log[]でZabbixがログを読み込む前にローテーションされてしまっ
ていて、ログの欠損が発生している可能性が高いことが予想されま
す。
次に、Zabbixエージェントのバージョンが古いので対応していない
かもしれませんが、log[]ではなくlogrt[]を利用した方が良いでし
ょう。
logrt[]を利用することで、ログがローテーションされた場合でも、
同じディレクトリに過去のローテートされたログファイルも確認す
るようになるので、ログファイルを読み込む前にローテーションさ
れてしまった場合でも、過去のログファイルからも読み込むことで、
ログ取得の欠損を防ぐことができるようになります。
ただし、先にご提供した情報の通り、2.2.3以前のものには問題が
あるようですので、logrt[]を利用するのであれば、サーバ側も、
エージェント側も両方とも2.2.4以降にすることで対応できるはず
です。
ただ、大丈夫だとは思うのですが、まだ2.2.4はリリースされたば
かりですのでご注意ください。
私自身もこれから動作確認に入ります。
ryo_k - 投稿数: 13
KAZさん
お世話になっております。ryo_kです。
返信遅くなり、申し訳ありませんでした。
下記に回答させて頂きます。
OSは、マネージャ側がCentOS6.5、エージェント側がCentOS5.6です。
Zabbixエージェントは1.4.6-2となります。
情報ありがとうございます。
確認しましたところ、3日とも9:00:01で動いておりました。
ログの読み込みはローテーションの「直前」で行っておりますが、概ねご認識の通りとなります。
監視ファイルは、Webサイトへのアクセス失敗に起因するログで、ログが書き込まれないまま
ローテートされる日も多く、書き込まれても1日に1行～数行程度です。
下記が、直近のZABBIXの監視データ>概要>ヒストリのデータとなります。
「→」印が本事象に該当する値です。実は、本日(6/25)分も欠けてしまいました。
---------
タイムスタンプ ローカル時間 値
2014/06/25 08:58:03 - [Tue Jun 24 23:25:10 2014] [error] [client xxx.xxx.xxx.xxx] client denied by server configuration: /xxx/xxx_xxxx_xxx/html/xxxxxx
→2014/06/25 08:58:03 - 12:40:49 2014] [error] [client xxx.xxx.xxx.xxx] client denied by server configuration: /xxx/xxx_xxxx_xxx/html/
→2014/06/24 08:58:03 - m
2014/06/23 08:58:03 - [Sun Jun 22 13:43:36 2014] [error] [client xxx.xxx.xxx.xxx] client denied by server configuration: /xxx/xxx_xxxx_xxx/xxxx/xxxxxxxxm
2014/06/19 08:58:03 - [Wed Jun 18 11:08:54 2014] [error] [client xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
2014/06/19 08:58:03 - [Wed Jun 18 11:08:45 2014] [error] [client xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
2014/06/19 08:58:03 - [Wed Jun 18 11:08:38 2014] [error] [client xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
2014/06/19 08:58:03 - [Wed Jun 18 11:08:35 2014] [error] [client xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
2014/06/19 08:58:03 - [Wed Jun 18 11:08:23 2014] [error] [client xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
→2014/06/19 08:58:03 - t xxx.xxx.xxx.xxx] user xxxx not found: /xxxxx.cgi
2014/06/17 08:58:03 - [Mon Jun 16 11:06:15 2014] [error] [client xxx.xxx.xxx.xxx] client denied by server configuration: /xxx/xxx_xxxx_xxx/xxxx/xxxxxxxxm
---------
何から何までご親切にありがとうございます。
実は、フォーラム内のほうは質問させて頂く前にいくらか調べ、下記と似ている事象だと思ったのですが、
http://www.zabbix.jp/node/735
私のはvarchar(255)に収まらない程長い文字列ではないし、前方が欠けるのは説明がつかないと感じ、
皆様のご意見をお伺いさせて頂いた次第となります。
本家のほうは未確認でした。とても参考になります。
zinten - 投稿数: 69
ryo_kさん
ローテーション前とローテーション後のファイルサイズの関係は分かりますでしょうか。
Zabbixのログ監視ではログのローテーションが行われたかどうかは見ておらず、
ファイルサイズが以前監視したときとどのように変わったかによって監視動作を決定しています。
※2.2.4からローテーションが行われたかどうかも見るようになったはず！(たぶん)
例）
old filesize ： 最後にどこまで読み込んだのか
current filesize ： 現在のファイルサイズ
①old filesize ＜ current filesize ⇒ old filesize以降を読み込む
②old filesize ＝ current filesize ⇒ ファイルサイズが変わらないので何も読み込まない
③old filesize ＞ current filesize ⇒ ログのローテーションをしたとみなして先頭から読み込む
途中から読み込まれてしまう現象は上記①のパターンに当てはまるときに発生する可能性があります。
ローテーション前のファイルが100byte
ローテーション後のファイルが120byteだったときに
Zabbixはローテーション後のファイルを101byteから読み込みます。
この時にローテーション後のファイルの101byte目は行の先頭とは限らないので
行の途中から読み込まれる現象が発生します。
KAZ - 投稿数: 1085
ryo_kさん
Zabbix1.4.6-2のエージェント…
かなり古いですね。A(^^;
エージェントとサーバのバージョンに差がありすぎると動作おかしくなる場合あります。
※：1.4系ではマイナーバージョンが違ってもメモリ破壊する場合がありました。
Zabbixエージェントのバージョンを上げて頂いて再現確認したほうが良いかと。
Zabbix2.2.4が6/23にでてますので、バージョンアップされた方が良いと思います。
ryo_k - 投稿数: 13
zintenさん
そういった仕組みになっているのですね。
分かりやすい説明を頂き、誠にありがとうございます。
下記が、監視対象ログファイルのサイズとなります。
(圧縮されて保存されていたものを解凍したため、元のファイルサイズと誤差があるかも知れません。)
-----------------
-rw-rw---- 1 apache apache 368 6月 25 09:00 ssl_error_log.1 ←障害発生
-rw-rw---- 1 apache apache 132 6月 24 09:00 ssl_error_log.2 ←障害発生
-rw-rw---- 1 apache apache 130 6月 23 09:00 ssl_error_log.3
-rw-rw---- 1 apache apache 0 6月 22 09:00 ssl_error_log.4
-rw-rw---- 1 apache apache 0 6月 21 09:00 ssl_error_log.5
-rw-rw---- 1 apache apache 0 6月 20 09:00 ssl_error_log.6
-rw-rw---- 1 apache apache 623 6月 19 09:00 ssl_error_log.7 ←障害発生
-rw-rw---- 1 apache apache 130 6月 18 09:00 ssl_error_log.8
-rw-rw---- 1 apache apache 130 6月 17 09:00 ssl_error_log.9
-rw-rw---- 1 apache apache 0 6月 16 09:00 ssl_error_log.10
-----------------
本事象が発生した日のログファイルのサイズは、いずれも①の場合に該当し、かつ、
前日分のファイルサイズが0ではない事がわかりました。
他の皆様も仰っているように、まずはバージョンアップを検討してみたいと思います。
ryo_k - 投稿数: 13
KAZさん
ryo_kです。コメントありがとうございます。
それは恐ろしいですね。
エージェントのバージョンアップ、一度検討してみます。
色々とありがとうございました。
KAZ - 投稿数: 1085
ryo_kさん
ログ監視は下記の状態で1.6以降ならあまり問題ないと思います。
Zabbixサーバ >= zabbixエージェント
ryo_k - 投稿数: 13
TNKさん
ryo_kです。色々アドバイスありがとうございます。
監視間隔86400秒はサーバ管理者からの要望でしたので、まずはバージョンアップについて
検討してみたいと思います。
そうすればlogrt[]も利用できると思いますので。
ご忠告の通り、リリース直後のバージョンは、思わぬバグや不具合に注意したいと思います。
ryo_k - 投稿数: 13
KAZさん
ryo_kです。再三のご助言、本当にありがとうございます。
Zabbixサーバ側は現在運用中で、停止→アップグレードの許可を取るのが比較的困難なので、
まずはエージェント側のアップグレードを一気に最新(2.2.4)にする事を検討しておりました。
http://www.zabbix.jp/documents/installation/upgradeによると、「Zabbixサーバはエージェントに対して下方互換性を持つ」との事ですので、
両者のバージョンに差がある場合、バージョンが低い方に応じた機能までしかサポートされない事は認識しておりますが、
その他に Zabbixサーバ <= zabbixエージェント となる事で不都合が発生する例をご存じでしたら、教えて頂けませんでしょうか。
KAZ - 投稿数: 1085
ryo_kさん
Zabbixサーバ側は現在運用中で、停止→アップグレードの許可を取るのが比較的困難なので、
運用中は言われますよね。A(^^;
その他に Zabbixサーバ <= zabbixエージェント となる事で不都合が発生する例をご存じでしたら、教えて頂けませんでしょうか。
すいません、わざとサーバのバージョンを低くして試した事がないので…A(^^;
ryo_k - 投稿数: 13
KAZさん、わざわざありがとうございました。
ryo_k - 投稿数: 13
KAZさん TNKさん zintenさん その他の皆様
お世話になっております。ryo_kです。
先日、監視先のzabbix-agent-2.2.0-2.el5に入れ替え、logrt[]を使用したところ、
本障害は発生しなくなりました！
皆様、本当にお世話になり、ありがとうございました。
ただ、現在、別の障害が発生しており、このログ監視はまだ正式稼働には至っておりません..↓↓
http://www.zabbix.jp/node/2846にスレッドを立てておりますので、もし、
そちらについても情報をお持ちの方がいらっしゃいましたら、お力を貸して頂ければ助かります。