logrtにて検知するログファイルレコードの制約について
logrtにて検知するログファイルレコードの制約について質問があります。
エラー検知しないケースが発生しているため原因調査を行っています。
Zabbix 3.0.24の環境にて以下アイテムとそれに紐づくトリガーを設定しています。
□アイテム
キー：logrt["[ログファイルPATH]$",@[正規表現],Shift-JIS]
タイプ：Zabbixエージェント(アクティブ)
更新間隔：1
ヒストリ保存期間(日)：90
□トリガー
条件式：{[テンプレート名]:logrt["[ログファイルPATH]$",@[正規表現],Shift-JIS].count(300)}<11
障害イベントを継続して生成：チェックあり
有効：チェックあり
この状況下にて[ログファイルPATH]の該当ファイル内に規定のエラー文字列が発生した場合、
エラーを検知するパターンとそうでないパターンが発生するため、原因調査を行っています。
同一方法でエラーを発生させてもその時によって検知有無が異なるため、エラー発生方法による差異ではありません。
調べていったところ以下のZabbixの制約に引っかかっているのではという疑問にたどり着きました。
https://www.zabbix.com/documentation/2.2/jp/manual/config/items/itemtype...
> log[]またはlogrt[]アイテムの更新間隔が1秒の場合、エージェントがデフォルトで分析できるログファイルレコードは最大400個までであり、
> 1回のチェックでZabbixサーバへ送信できる一致レコードは最大100個までです。
> エージェント設定ファイル中のMaxLinesPerSecondを上げることにより、または、アイテムキー中のmaxlinesパラメータを設定することにより、
> 分析できるログファイルレコードは最大4000個まで、1回のチェックでZabbixサーバへ送信できる一致レコードは最大1000個まで限界を上げることができます。
> ログファイルレコードが256kBよりも長い場合、最初の256kBのみが正規表現と照合され、レコードの残りは無視されます。
つまり、
1回のチェックでZabbixサーバへ送信できる一致レコードの最大1000個を超えている
ログファイルレコードが256kBよりも長い
などのパターンが発生しているのではないかという事です。
現状zabbix_agentd.confは以下設定となっておりデフォルトを設定しています。
# MaxLinesPerSecond=20
エージェントのログ(zabbix_agentd.log)を見ると制約に引っかかっているようなエラーは出ていないのですが、
実際に制約に引っかかった場合は上記ログに出力されるものでしょうか？
同じような状況になった方、何かお気づきの事がある方がいましたら何か情報を頂ければと思います。
Yasumi - 投稿数: 380
「同一方法でエラーを発生させてもその時によって検知有無が異なる」とありますが、どのような検証をしているのでしょうか。
【logrt["[ログファイルPATH]$",@[正規表現],Shift-JIS]】には1分間に何行のログが平均的に記録されているのでしょうか。
亜所区 - 投稿数: 9
コメントありがとうございます。
検証についてですが、まず今回検知させているログがAurora(Postgres)のログのためPostgresのログにエラーをさせるようにしています。
そのためPgAdminから構文エラーのSQLを発行し、エラーを発生させるという手法を取っています。
1分間に何行のログが出力されるかという点について、
およそですが平均としては2万～3万行で、最大約60万行程度出力される事があります。
(一つピックアップすると、5 分間分が250MBで130万行でした。)
これだけ行数が多くなる理由として、Auditのログも出力しているためデータ量が多くなっています。
行数と１行内のログファイルレコードが多くなっている事実はあるのですが、
本当に制限に引っかかっているのかどうかの確証が取れない状況です。
亜所区 - 投稿数: 9
コメントありがとうございます。
検証についてですが、まず今回検知させているログがAurora(Postgres)のログのためPostgresのログにエラーをさせるようにしています。
そのためPgAdminから構文エラーのSQLを発行し、エラーを発生させるという手法を取っています。
1分間に何行のログが出力されるかという点について、
およそですが平均としては2万～3万行で、最大約60万行程度出力される事があります。
(一つピックアップすると、5 分間分が250MBで130万行でした。)
これだけ行数が多くなる理由として、Auditのログも出力しているためデータ量が多くなっています。
行数と１行内のログファイルレコードが多くなっている事実はあるのですが、
本当に制限に引っかかっているのかどうかの確証が取れない状況です。
Yasumi - 投稿数: 380
Postgres logの出力件数が、130万行/5分間でしょうか。
アイテムは正規表現で絞っていますが、アイテムへの記録件数を教えてください。
亜所区 - 投稿数: 9
はい、Postgres logの出力件数が、130万行/5分間となります。
実際は１時間単位でローテーションされますが、１時間だと量が多すぎるので5分間隔で差分だけを抽出して別ファイルを生成しています。
この別ファイルは5分おきに同じファイル名で入れ替えが行われます。
その生成した別ファイルを監視していて、それが5分間分で最大60万行程度出力される可能性があります。
こちらでテストした結果として
MaxLinesPerSecond=1000
の設定に変更後、1行目、4000行目、10000行目に検知文字列(ERROR)を記入したテスト検知ファイルを配置したところ
1、4000行目までの文字列は即時で検知しましたが、10000行目の箇所は30秒後程度に遅れて検知しました。
このように行数の多さからZabbix Agentの設定値によって該当のログを読み込むまでに大量の時間がかかっている事は事実として認識しました。
Yasumi - 投稿数: 380
Zabbix3.0系だと、MaxLinesPerSecond×4の新しい行を処理します。
なので、指定のパラメータで4000行目以降の処理が遅延するのは想定された動作といえます。
https://www.zabbix.com/documentation/3.0/manual/config/items/itemtypes/l...
また、回答いただけていませんが、下記の2つは異なるものとして考えてください。
①Postgres logの出力件数⇒130万行/5分間
②【logrt["[ログファイルPATH]$",@[正規表現],Shift-JIS]】の記録件数⇒？
対策１
もし【logrt["[ログファイルPATH]$",@[正規表現],Shift-JIS]】の記録件数が、
①と同じなのであれば@[正規表現]の設定の見直しをして、
アイテムへの記録処理・負荷を軽減させるのが有効だと思います。
Zabbixインターナルで取得できる、データ収集プロセスの負荷値も確認してみてください。
対策２
「5分間隔で差分だけを抽出」しているのであれば、その130万行/5分間の中で確認が不要な行を省けばいいと思います。
必要なログメッセージのみ抽出してアイテムに取り込めば、Zabbixへの負荷が軽減されるでしょう。
亜所区 - 投稿数: 9
大変失礼しました。
以下２つを同じ意味と捉えてしまい回答をしそびれていました。
①Postgres logの出力件数⇒130万行/5分間
②【logrt["[ログファイルPATH]$",@[正規表現],Shift-JIS]】の記録件数⇒？
"[ログファイルPATH]$"がPostgres logなので同じ件数になると考えていたのですが、
アイテムでは@[正規表現]で対象を絞り込んでいるため、その結果は130万件などとは異なると理解しました。
そのため、
②【logrt["[ログファイルPATH]$",@[正規表現],Shift-JIS]】の記録件数
としては実績上は平均5分間で10件未満というのが回答となります。
正規表現の検知文字列(ERROR)で検索したあとにマッチする行は限りなく少ない状況です。
ご指摘頂きました通り、対策としては今は対策2を実施する必要があると考えています。
原因調査は引き続き進めています。
MaxLinesPerSecond=1000を設定した場合、
4000行目以降の処理は次のターン(現在更新間隔：1なので次の1秒)でまた4000行が処理されると理解しています。
5分間(300秒)の場合だと4000×300で120万行を仕様上は処理できるという理解で、認識合っていますでしょうか？
このあたりの仕様を実際の再現試験にて確かめているところです。
Yasumi - 投稿数: 380
Zabbix ServerのMaxLinesPerSecondの設定値だけ見れば、理論値で120万行を処理できると思いますが、
他にもCache SizeやDBの制限を受けますし、Agent側の送信バッファ量の設定などからも同様です。
Zabbixインターナルで取得できる、データ収集プロセスの負荷値を確認してみてください。
負荷率が100%に達しているものがあれば、Zabbixの動作に影響を与えますので、調整する必要があります。
zabbix[process,,avg]
https://www.zabbix.com/documentation/2.2/jp/manual/config/items/itemtype...
亜所区 - 投稿数: 9
色々とご確認ありがとうございます。
実際に何行程度処理できているのかを確認するために、
ファイルの指定行に検知文字列を記載し、検知のTimestampから処理のどの程度かかっているかを確認しました。
(MaxLinesPerSecond=1000の設定)
Timestamp 値 時間差
2020/5/22 19:43:34 1
2020/5/22 19:43:34 1000 0:00:00
2020/5/22 19:43:34 2000 0:00:00
2020/5/22 19:43:34 4000 0:00:00
2020/5/22 19:44:34 4100 0:01:00
2020/5/22 19:44:34 5000 0:01:00
2020/5/22 19:45:10 10000 0:01:36
2020/5/22 19:45:37 20000 0:02:03
2020/5/22 19:46:17 30000 0:02:43
2020/5/22 19:46:43 40000 0:03:09
2020/5/22 19:47:51 50000 0:04:17
2020/5/22 19:48:52 60000 0:05:18
2020/5/22 19:50:33 70000 0:06:59
2020/5/22 19:51:00 80000 0:07:26
2020/5/22 19:51:40 90000 0:08:06
結果、以下の事が分かりました。
・4000行目までは即時で検知できている
・その後の行については順次処理されている
・9万行の処理(文字列検知)までに8分06秒の時間差があった。(理論値よりはかなり処理速度が遅い)
MaxLinesPerSecondの理論値であれば、5分間で120万行を処理できるものの
Agent側のBufferSize,BufferSendなどの設定値、その他Zabixサーバ側の負荷などもあるため、確実のこの行数が処理できるものではないと理解しました。
Zabbixサーバ側のデータ収集プロセスの負荷値については確認致します。
もう１点仕様について認識を把握したいものがあるのですが、
> ログファイルレコードが256kBよりも長い場合、最初の256kBのみが正規表現と照合され、レコードの残りは無視されます
https://www.zabbix.com/documentation/2.2/jp/manual/config/items/itemtype...
ここでいるログファイルレコードとは1行の事を表している認識で正しいのでしょうか？
改行なしで256KBを超える対象行があった場合、256KB以降に正規表現で定義されている文字列が存在しても検知されない
という風に理解しています。
こちらについて認識誤りがあるかどうか、コメント頂けると助かります。
大変お手数ですがよろしくお願いします。
亜所区 - 投稿数: 9
度々申し訳ありません。
> ログファイルレコードが256kBよりも長い場合、最初の256kBのみが正規表現と照合され、レコードの残りは無視されます
https://www.zabbix.com/documentation/2.2/jp/manual/config/items/itemtype...
この内容についてはZabbixの仕様であり、Agentの設定値変更によって変えられるものではないと考えていますが正しいでしょうか？
ログファイルレコードとは1行の事を表しているのかの確認と共に、こちらも併せてご確認いただけますでしょうか。
大変お手数ですがよろしくお願いします。
Yasumi - 投稿数: 380
はい。そうだと思いますが、私も指定のテストをしたことがないので
検証してみるのが一番かと思います。
亜所区 - 投稿数: 9
1行で256KB(262144Byte)以上の文字列を作成して検証ところ、1行で256KBを超えた場合は検知されない事が実際の挙動で分かりましたので報告させて頂きます。
262120Byte 検知する
262200Byte 検知しない
という状況でした。
Agentのログファイルにも以下のようにエラーが出力され、この結果からも256kBまでしかチェックされない事が分かりました。
" 2012:20200528:201349.989 Logfile contains a large record: ""row3 262220 A1*********2*********3*********4*********5*********6"" (showing only the first 64 characters). Only the first 256 kB will be analyzed, the rest will be ignored while Zabbix agent is running.
"
アドバイス頂いたおかげで実際の仕様の挙動確認までできました。ありがとうございます。
この制限については仕様であり、変更不可能と考えているのですがこちらについてお分かりになりますでしょうか？
Yasumi - 投稿数: 380
はい。変更不能です。
この仕様は最新のZabbix5.0でも同様です。
亜所区 - 投稿数: 9
MaxLinesPerSecondに1000を設定した場合、理論値上は5分間で120万行(1秒4000行×300)を処理できるものの
アイテムの更新間隔(秒)が1の設定で試したところ、5分間で6万行程度しか処理されない状況でした。
その後、アイテムの更新間隔(秒)を10に変更したところ、5分間で約50万行処理されるように実測値が変化しました。
MaxLinesPerSecondの仕様として処理可能な行数は
更新間隔(秒)が1の時 →1秒間で最大4000行
更新間隔(秒)が10の時 →10秒間で最大4000×10の4万行
ただし、単位時間に直すと最大4000という事は変わらないものと考えていました。
つまり更新間隔(秒)を変更しても5分間に処理可能な行数は変化がない認識だったのですが、
結果としては更新間隔(秒)を1→10に変更した方が処理可能な行数が多くなりました。
この結果について、他の設定値などの兼ね合いで何が関連しているかお分かりになりますでしょうか？
質問の意図として、即時検知を目的として更新間隔(秒)1を設定しているのですが、
仕組み上、処理可能な行数が増えるのであれば更新間隔(秒)を10やそれ以上に上げる事を検討したいためです。
Yasumi - 投稿数: 380
実測値について、ここではこれ以上の回答は望めないと思いますので、
Zabbixの公式に問合せで聞いてみると良いと思います。
個人的には、更新間隔を広げたことがダイレクトに「処理可能な行数が増える」という結果に繋がっているのではないと思います。
まずはどこに負荷がかかっているかを突き止めると良いと思いますが（DBなのかIOなのか、エージェントなのかインターナルプロセスなのか）、
そもそもZabbixServerのアイテム取得に遅延が発生してしまうほどの処理をさせるのは、ほかの処理にも影響を与える可能性が大で
監視が破綻するリスクを孕んでいるので推奨できません。