ログ監視にて膨大な量のメールが発生

お世話になっております。

本件、ログ監視を行っていたところメールが止まらなくなったという事象が発生しましたので、原因がわかればと思います。

使用のバージョンは以下の通りです。

サーバー:ZABBIX 1.8.4
エージェント:1.8.5

今まではなんとも無く、エラーのときだけメールが行われていたログ監視が、急に大量のメールを送信するようになりました。
内容を確認したところ、過去の全てのログを何度も洗い出してメールを送信していたように思えました。

現在はサーバのサービスを停止し、ネットワークも切り離しています。

特にエージェント側でエラーや再起動などが発生していようでもありませんでした。
ただ、ログファイルサイズが15MBで行数が44000行程あったため、エージェントの行を管理する変数の桁あふれでも発生したのかと思っています。

何か心当たりなどあればお教えいただけると助かります。
以上です。

コメント表示オプション

お好みのコメント表示方法を選び「設定の保存」をクリックすると変更が反映されます。
ユーザー KAZ の写真

Cuturnさん

OSは何を使ってますか?
また、ログのローテートはどうしてますか?

昔Zabbix1.4/1.6系でLinuxでは下記の流れでローテートすると昔の情報からファイルを読み直しされたことがあります。

1)コピー
2)コピーしたファイルの中身の過去分を削除
3)元ファイル削除
4)コピーしたファイルをログファイル名にリネーム

OSバンドルのローテート使っている場合は起きません。

確かソースを確認した結果、ファイルサイズが一旦0になるのがまずかった気様な記憶があります。

ユーザー Cuturn の写真

>KAZ様

エージェントが導入されているOSはWindowsです。
対象ログのローテートの方式はあまりよくわかってはいませんが、
現在のところ対象のログについてローテートの類は走っていません。
常に追記の状態です。

なお、ログはIBM Systems Director 6.1が制御しているログです。
25MB程度になるとローテートされます。
いただいたような問題があるとすると、ローテートの際は少し気を配らないといけないですね。

以上です。

ユーザー kodai の写真

どのようなアイテム設定をされているのでしょうか?

また、Zabbixのログ監視は内部的に「どこまで読んだか」を記録していて、ログのファイルサイズが前回よりも小さくなったら、最初から読み直す動きをします。

つまり、ログファイルから手動で1行削除して保存したような場合でも最初から読み直してしまう可能性があります。

内容を確認したところ、過去の全てのログを何度も洗い出してメールを送信していたように思えました。

そのアイテムを設定している状態だと、「何度も読み直している」(ログを最後まで読み切ったら、必ず再度最初から読み直している)状態ということでしょうか?

もしそうであるなら、何か内部的におかしなことが起こっている可能性があると思います。

ユーザー KAZ の写真

Cuturnさん、kodaiさん

また、Zabbixのログ監視は内部的に「どこまで読んだか」を記録していて、ログのファイルサイズが前回よりも小さくなったら、最初から読み直す動きをします。

そうでしたね!

つまり、ログファイルから手動で1行削除して保存したような場合でも最初から読み直してしまう可能性があります。

1.4/1.6では飛びますね。
検証したことあります。

ユーザー Cuturn の写真

ZABBIXサーバにて対象のログテキストのヒストリを確認したところ、10分間にログを6週くらいした形跡がありました。

この間にデータ量が減ることも無いと思うので、原因は不明です。
ZABBIXのエージェント、サーバのログを見ても特に当該時間帯のみに出力された不穏なログはありませんでした。

とりあえずログ監視を一旦止めて監視を再開したいところなのですが、
未だ多くのイベントが進捗中のため、繋げた途端に間違いなくメールの嵐が・・・(^^;
さしあたって進捗中のアクションを全て削除するか、あるいは済みであるかのように見せかけるSQL文をどなたかご存知で無いでしょうか。

ユーザー KAZ の写真

Cuturnさん

ZABBIXサーバにて対象のログテキストのヒストリを確認したところ、10分間にログを6週くらいした形跡がありました。

異常な動きですね…
ソース追って見ないといけないですね…

すいませんが、ログファイルの文字コードは何でしょうか?
SJISですか?
それともUTF-8ですか?

とりあえずログ監視を一旦止めて監視を再開したいところなのですが、 未だ多くのイベントが進捗中のため、繋げた途端に間違いなくメールの嵐が・・・(^^; さしあたって進捗中のアクションを全て削除するか、あるいは済みであるかのように見せかけるSQL文をどなたかご存知で無いでしょうか。

これ以降は一旦トリガーを無効にするとして、進行中の物はどうすれば良いか…
メールサーバ(または中継しているメールサーバ)を止めると言うのは…駄目ですよね…きっと…

ユーザー Cuturn の写真

すみません質問に返答しておりませんでした。

kodai様

どのようなアイテム設定をされているのでしょうか?

アイテム設定は以下のキーです。
log[C:\Program Files\IBM\Director\log\direvent.log,@DIREVENT]

正規表現@DIREVENTは以下の通りです。
条件式:1 » SEV=CRITICAL,SEV=WARNING [いずれかの文字列が含まれる]

KAZ様

すいませんが、ログファイルの文字コードは何でしょうか?
SJISですか?
それともUTF-8ですか?

ログファイルの文字コードはnkfコマンドで確認したところASCIIでした。Terapad上ではShift_JISとして扱われています。

メールサーバ(または中継しているメールサーバ)を止めると言うのは…駄目ですよね…きっと…

ちょっとメールサーバは止められないですね…。
ただネットワークを止めることは可能ですので、完全に失敗となったアクションが再実行されないのであれば問題ないかもしれません。

以上です。

ユーザー kodai の写真

ZABBIXサーバにて対象のログテキストのヒストリを確認したところ、10分間にログを6週くらいした形跡がありました。

この間にデータ量が減ることも無いと思うので、原因は不明です。
ZABBIXのエージェント、サーバのログを見ても特に当該時間帯のみに出力された不穏なログはありませんでした。

となると、何かが原因で読み込み位置がリセットされてしまったことになりますね。
可能であれば、エージェントのログをデバッグモードに設定して、デバッグログを取得いただけると何か分かるかもしれません。

とりあえずログ監視を一旦止めて監視を再開したいところなのですが、
未だ多くのイベントが進捗中のため、繋げた途端に間違いなくメールの嵐が・・・(^^;
さしあたって進捗中のアクションを全て削除するか、あるいは済みであるかのように見せかけるSQL文をどなたかご存知で無いでしょうか。

こちらをご参考ください。
http://www.zabbix.jp/modules/newbb/viewtopic.php?topic_id=1110&forum=2

ユーザー Cuturn の写真

kodai様

ありがとうございます。
無事6250件のイベントが送信済みになりました。怖い怖い。

エージェントのログ設定をデバッグレベルにして監視を再開しましたが、
昨日のような事象は起こっておりません。
エージェントの再起動によって解消したのか、サーバ側のサービス再起動によって解消したのか不明です。
良いような悪いような…。

ログ監視のみメール連絡を止め、しばらく様子を見ます。
ご回答いただいておいてすっきりしない感じになりまして申し訳ありません。

ユーザー kodai の写真

エージェントのログ設定をデバッグレベルにして監視を再開しましたが、
昨日のような事象は起こっておりません。

うーん、原因が気になりますね。もし再発するようなら情報を頂ければと思います。

ちなみに、logキーを使っていてログを最初から読み直す可能性があるのは、

- ログファイルのサイズがが前回よりも小さくなった
- アイテムの設定を作成し直した
- zabbix_senderを利用してデータを手動で送信した

などが考えられます。

ユーザー KAZ の写真

Cuturnさん、kodaiさん

■容量オーバー?
Linuxではファイルサイズ・行数(は余り関係ないはずですが…)ともにもっと大きなファイルでも問題はおきていなかったような…
Windowsでは余り大きなログを扱ったこと無いですが、15MBは少ない分類ではないかと…

■動作から考えると…
今日は1.8のソース読める状況に無いのでファイルサイズが小さくなったと思って再読み込みしているように見えます。

念の為確認ですが監視しているファイルの文字コードは何でしょうか?

■ローテートについて

いただいたような問題があるとすると、ローテートの際は少し気を配らないといけないですね。

ローテートは微妙に気を付ける必要があります。
kodaiさんも書かれていましたがファイルサイズが小さくなると頭から読み直します。その為、既に検出した項目でも再検出してしまいます。