Zenn
Microsoft (有志)Publicationへの投稿
〽️

Sentinel への syslog 転送の欠損を検知したい

k.sato
2023/10/10に公開
Azure
Microsoft
Microsoft Sentinel
tech

はじめに

オンプレミスのファイアウォールやプロキシの syslog を Sentinel に記録する場合、Azure Monitor エージェントもしくは Log Analytics エージェント (2024/8 にリタイア予定) をインストールした Linux マシンが必要になります。このときマシンの性能不足やネットワークの不具合により、Sentinel へのログ転送が失敗もしくは欠損しているケースを検知したいと思いまして、方法を模索しています。

Azure Monitor エージェントでの転送確認

Azure Monitor エージェントには転送状況を記録する機能が準備されていますので、Azure Monitor エージェントのみの観点であればこちらで事足ります。
https://learn.microsoft.com/ja-jp/azure/azure-monitor/agents/azure-monitor-agent-troubleshoot-linux-vm#issues-collecting-syslog

なお、今回は Azure Monitor エージェントがログを受け取れていない場合も想定して、 rsyslog で件数を検出する方法を検証しています。

rsyslog の統計情報を出力

本来、syslog 出力元でログ件数を取得でき、それと Sentinel の件数を比較できるのが理想的です。そうすることで、ログに記録されている時間が一致するため、特定時間範囲のログが同数となるはずです。しかしながら、API がないなどで件数を取得できない場合、次のポイントとしては rsyslog でログを受信する箇所の統計情報かと思います。ただしこの場合、rsyslog プロセスが処理した時間での件数カウントになり、ログ内に記録される時間と乖離があるため、Sentinel 側と件数が一致しない可能性が高い点は注意が必要です。

  1. rsyslog の統計モジュールを有効化
    rsyslog の設定ファイル (通常は /etc/rsyslog.conf または /etc/rsyslog.d/ 下の .conf ファイル) を編集して、統計モジュールを有効にします。
module(load=“impstats” interval=“600” log.syslog=“off” log.file=“/var/log/rsyslog-stats.log”)

この例では、10分 (600秒) ごとに統計情報を /var/log/rsyslog-stats.log に出力します。log.syslog=“off” は、統計情報を syslog 自体にログとして出力しないようにするためのオプションです。

  1. rsyslog を再起動
    設定変更を適用するために rsyslog を再起動します。
sudo systemctl restart rsyslog
  1. 統計情報を確認
    指定した統計ログファイルを確認して、統計情報を見ることができます。
cat /var/log/rsyslog-stats.log
rsyslog-stats.log
Sun Oct 8 10:41:04 2023: global: origin=dynstats 
Sun Oct 8 10:41:04 2023: imuxsock: origin=imuxsock submitted=813 ratelimit.discarded=0 ratelimit.numratelimiters=0
Sun Oct 8 10:41:04 2023: action 0: origin=core.action processed=1353 failed=0 suspende d=0 suspended.duration=0 resumed=0 
Sun Oct 8 10:41:04 2023: action 1: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 8 10:41:04 2023: action 2: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 8 10:41:04 2023: action 3: origin=core.action processed=111 failed=0 suspended =0 suspended.duration=0 resumed=0 
Sun Oct 8 10:41:04 2023: action 4: origin=core.action processed=653 failed=0 suspended =0 suspended.duration=0 resumed=0 
Sun Oct 8 10:41:04 2023: action 5: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 8 10:41:04 2023: action 6: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 8 10:41:04 2023: action 7: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 8 10:41:04 2023: action 8: origin=core.action processed=0 failed=0 suspended=0 suspended.duration=0 resumed=0
Sun Oct 8 10:41:04 2023: imudp(*:514): origin=imudp submitted=0 Sun Oct 8 10:41:04 2023: imudp(*:514): origin=imudp submitted=0
Sun Oct 8 10:41:04 2023: imtcp(514): origin=imtcp submitted=540
Sun Oct 8 10:41:04 2023: resource-usage: origin=impstats utime=69844 stime=74209 maxrs s=5472 minflt=513 majflt=1 inblock=40 oublock=424 nvcsw=1503 nivcsw=104 openfiles=18
Sun Oct 8 10:41:04 2023: main Q: origin=core.queue size=0 enqueued=1353 full=0 discard ed.full=0 discarded.nf=0 maxqsize=37
Sun Oct 8 10:41:04 2023: imudp(w0): origin=imudp called.recvmmsg=0 called.recvmsg=0 ms gs.received=0

ログの読み方は以下の通り。(ChatGPT にて作成)
imuxsock:
Sun Oct 8 10:41:04 2023: imuxsock: origin=imuxsock submitted=813 ratelimit.discarded=0 ratelimit.numratelimiters=0
これは、ローカルの syslog ソケット (通常は /dev/log) から受信したメッセージ数です。この場合、813 件のメッセージが受信されました。

core.action:
Sun Oct 8 10:41:04 2023: action 0: origin=core.action processed=1353 failed=0 suspended=0 suspended.duration=0 resumed=0
これは、rsyslog のアクションに関する情報です。アクションは、メッセージをどのように処理するかを示しています (例: ファイルに保存、リモートサーバに送信など)。ここでは、action 0 が 1353 件のメッセージを処理し、失敗、中断は0回です。

imudp & imtcp:
Sun Oct 8 10:41:04 2023: imudp(*:514): origin=imudp submitted=0 Sun Oct 8 10:41:04 2023: imtcp(514): origin=imtcp submitted=540
これは UDP と TCP 経由で受信したメッセージ数を示しています。UDP は0件、TCP は 540 件のメッセージが受信されました。

resource-usage:
これは、rsyslog のリソース使用状況に関する情報です。例えば、CPU の使用時間やメモリ使用量などの情報が含まれています。

main Q:
Sun Oct 8 10:41:04 2023: main Q: origin=core.queue size=0 enqueued=1353 full=0 discarded.full=0 discarded.nf=0 maxqsize=37
これは、rsyslog のメインキューに関する情報です。キューはメッセージを一時的に保持し、後続の処理を待つためのものです。ここでは、1353 件のメッセージがキューに追加され、最大キューサイズは 37 でした。

rsyslog の統計情報を Sentinel に取り込み

Sentinel のログ件数と比較するため、rsyslog の統計情報を Sentinel に取り込みます。ファイルベースのログ取得になるので、以下を参考にしてください。(ここでは割愛します)
https://zenn.dev/microsoft/articles/c43655c3905329

変換していないので、以下のように RsyslogStats_CL テーブルに RawData にそのまま取り込んでいます。

Sentinel のログ件数と比較

KQL でログ件数を比較します。ざっくり KQL は以下の構造になっています。

  • RsyslogStats_CL テーブルのうち、TCP での受信件数のログでフィルタ
  • 最新 2 件のみピックアップ
  • 正規表現で受信件数を抽出 (ここは累計となるので次で差分を計算)
  • 変数に最新とその 1 つ前の時刻と件数の差分を格納
  • CommonSecurityLog テーブルで ingestion_time() を取得 (TimeGenerated の場合ログ生成時刻となり、処理された時間と乖離する可能性があるため)
  • rsyslog 統計情報の記録時間に対応した Sentinel のログ件数を算出
  • それぞれの件数と差分を確認
let StatsTable = RsyslogStats_CL
| where RawData has "origin=imtcp"
| top 2 by TimeGenerated desc
| extend Submitted = toint(extract(@"submitted=(\d+)", 1, RawData))
| project TimeGenerated,Submitted;
let StatsTime = toscalar(StatsTable | top 1 by TimeGenerated desc | project TimeGenerated);
let PrevStatsTime = toscalar(StatsTable | top 1 by TimeGenerated asc | project TimeGenerated);
let StatsCount = toscalar(StatsTable | project StatsCount = Submitted - next(Submitted) | where StatsCount > 0);
CommonSecurityLog
| extend IngestedTime = ingestion_time()
| where IngestedTime between (PrevStatsTime .. StatsTime)
| summarize count()
| project RsyslogCount = StatsCount, SentinelCount = count_, Diff = StatsCount - count_

実際の結果は以下の通りです。(今回は 1 時間単位で比較)

まとめ

処理のタイミングなどによってやはり若干の件数の差分は出てしまうという印象で、それをどこまで許容するかが難しい点です。また、rsyslog などのプロセスのリスタートや長時間動作時の挙動など考慮する点があります。

Microsoft (有志)
Microsoft (有志)Publication

Microsoft Azureをはじめとする最新技術情報をお届けします。 ※このPublicationは日本マイクロソフトまたは米Microsoft社員による個人の見解であり、所属する組織の公式見解ではありません。 ※Publicationに参加希望の社員は @07JP27までご連絡ください。

Discussion