ログ監視で3回同じ通知が出てしまう
お世話になっております。
CentOSで/var/log/secureを監視し、sshのログインを追いかけているのですが、一回のログイン通知が3回通知現象が発生しました。
実際のログインは2014/11/14 13:38ですが、
このメールが11/14 13:39、11/15 6:40、11/15 16:11に通知されています。
ZBX-8916が関係してるかとは思ったものの、agentは2.0.13、serverも2.0.13であり該当バージョンではありません。
secureログの最新データは現在取得中ですが、すでに流れてしまっており最新500個では出てこない状態です。
なにか、原因などありますでしょうか?
また、別途調べるべき所が合ったりしますでしょうか?
以上、よろしくお願いいたします。
TNK - 投稿数: 4720
ご提供頂けている情報が少なすぎて、様々な要因が考えられます。
アイテムの設定がおかしいかもしれませんし、トリガーの設定が
おかしいかもしれませんし、アクションで設定している内容がお
かしいことも考えられます。
ZBX-8916を気にされるということは、定期的にサーバもしくはデ
ーモンを再起動するような運用を行われているということでしょ
うか？
そうであるならば、問題を特定するには、どのような運用をされて
いるのかなども関係してくるかもしれません。
まずは、アイテム、トリガー、アクションにどのように設定されて
いるのかをお教えください。
直接的な影響は少ないかもしれませんが、利用されているCentOSの
バージョンもお教えください。
minashiro - 投稿数: 16
お世話になっております。
アイテム:log[/var/log/secure]
トリガー:（{HOSTNAME}のログインをsecure fileで検出しました。）
{hostname:log[/var/log/secure].str(Accepted password)}=1
アクション:
(A) メンテナンスの状態 期間外 "メンテナンス"
(B) トリガーの値 = "障害"
（略）
(H) トリガー名 含まれる "ログイン"
（略）
ユーザーにメッセージを送信: Admin すぐに
という具合で、「secure」の中で、「Accepted password」を検出したら通知するというものです。
特別なことはしていないつもりです。
CentOSは5.9を利用しています。
ZBX-8916を気にしたのは、たまたま16日にメンテナンスを行い再起動を行った可能性があるためです。
（ただ、この時間は9時～15時なので6時のメールは説明がつきません・・・）
TNK - 投稿数: 4720
アクション内の件名、メッセージには何を指定していますか？
3回メールが送られたようですが、内容に違いはありませんでしたか？
minashiro - 投稿数: 16
トリガーの名前は、
{HOST.NAME}のログインをsecure fileで検出しました。
にしており、アクションで"ログイン"が含まれていたら通知するという具合です。
アクションの中で、{ITEM.VALUE1}を指定していますが、３通ともまったく同じ内容でした。
結果として、ログのテキストが３回、クライアントからサーバに通知されてたのではないか？
と考えております。
TNK - 投稿数: 4720
必要な情報を具体的にご提示いただけないので、同じログを再読み
込みしてしまったかどうかは判別できません。
「まったく同じ内容」というのは、/var/log/secureから取得され
ているとのことですので、ログの行の、
・日時
・ログインしたユーザ名
・アクセス元
もすべて合致するということでしょうか？
また、{EVENT.ID}とかはメッセージ内に入れていないのですか？
入れているのであれば、イベントIDにも違いが無いかをご確認くだ
さい。
あと、何らかの手段で /var/log/secure を編集して保存してしま
ったりすると、Zabbix側で認識しているログファイルをどこまで読
み込んだかを記録している値との差異が発生して新規ファイルとみ
なしてファイルを先頭から読み込みなおす場合がありますので、ご
注意ください。
minashiro - 投稿数: 16
すみません、ご指摘の通りで、 ・日時 ・ログインしたユーザ名 ・アクセス元がまったく同じです。
具体的には、以下のようなメールが上に記した時間に一字一句違わず通知されます。
あと、特にsecureの編集は行っておりません。
Trigger: xxxxxxのログインをsecure fileで検出しました。
Trigger status: PROBLEM
Trigger severity: 情報
Trigger URL:
Item values:
1. Log of /var/log/secure (xxxxxx:log[/var/log/secure]): Nov 14 13:38:28 xxxxxx sshd[14154]:
Accepted password for user名 from 192.168.0.xxxx port 58xxxx ssh2 2. *UNKNOWN*
(*UNKNOWN*:*UNKNOWN*): *UNKNOWN* 3. *UNKNOWN* (*UNKNOWN*:*UNKNOWN*): *UNKNOWN*
TNK - 投稿数: 4720
log[]関連は、2.0.13でもいくつかの改善が行われているので、極
力ログの再読み込みは発生しないようになっているはずです。
しかし、現時点までに頂いた情報からは、ログの再読み込みを行っ
てしまっている可能性が無いとは言い切れません。
Zabbixサーバ側、エージェント側の両方のログにもエラーが出てい
ないとすれば、やはり、先ほど書かせて頂いた/var/log/secureが
何らかの要因で編集された可能性があると考えています。
2回目3回目の通知が行われた前後に、主にZabbixサーバやエージェ
ントのログに何らかの出力が行われていないか再度ご確認ください。
minashiro - 投稿数: 16
TNKさん
お世話になっております。
ありがとうございます。
ServerとAgentのログを確認してみましたが、発生時刻になにもエラーは出力されておりませんでした。
/var/log/secureのローテートもその時間には発生しておりません。
KAZさんのご指摘のバグかもしれませんので、2.2へのアップグレードを検討してみます。
KAZ - 投稿数: 1085
minashiroさん、TNKさん
ZBX-8916を気にしたのは、たまたま16日にメンテナンスを行い再起動を行った可能性があるためです。
（ただ、この時間は9時～15時なので6時のメールは説明がつきません・・・）
ZBX-8916ですが、これはZabbixサーバを再起動しないと絶対に発生しません。A(^^;
別件かと…
因みに、その時間帯にイベント大量に派生してたりしますか？
うる覚えですが2.0系ではイベント大量に派生すると１件しか検知していないのに複数件イベントが発生するバグが有った筈です。
ZBX-6170とかZBX-6164とかですかね…
確か複数のプロセスからエスカレーションテーブルに書込を行っていて、排他制御に問題が合ったはずです。
2.2系ではその処理を丸っと書きなおしたので発生しなくなった筈です。
KAZ - 投稿数: 1085
minashiroさん、TNKさん
補足ですが…
ZBX-6170とZBX-6164は解決してません。
と言うか、2.2系で処理とDB構成をガラリと変えたので、2.0ではその処理を入れられないというか…
minashiro - 投稿数: 16
お世話になっております。
なるほど、こちらのバグならありそうですね。
解決策は2.2系にアップグレードしかないという具合でしょうか。
検討・提案してみます。
ありがとうございます。