Ubuntu
Logcheck

Ubuntu24.04 Logcheckの報告レベルを調整する

Ubuntu

毎日メールでLogcheckの報告を受けているのに、全然見ていない…
ノイズを落としきれず、読むのが億劫になってしまっている。



ここから広告
広告
広告ここまで

運用方針の変更

本来、Logcheckを運用するなら、1行1行ログを見定めて、いる・いらないを選択し、いらないときにはフィルターをかける。

Geminiさんによると、これをしっかり管理しているエンジニアは「本当に恐ろしい攻撃(クラッカーの侵入やゼロデイ脆弱性)が起きた時、システムや犯人は、ログレベルを親切に error や warning にしてログを吐いてくれるだろうか？ いや、絶対にそんなことはない。」と考え、informationのログを見ているとのこと。

でも、ウチでの現実は、明日やろう、来月やろう、とほったらかしで「ただメールを受けているだけ」という状態だった。

そこで方針変更、informationログを諦めてerrorやwarningだけ見ることにした。
システムの状態はLogcheckで確認し、攻撃はFail2Banで確認する、という役割分担へ。

実装

Logcheckのラッパーを作り、以下の通り動かす。

  • ジャーナルログからwarning以上のログを抽出し、ログファイルを作る。
  • Logcheckでそのログファイルをチェックする。

LogcheckはJournalとsyslog、auth.logをチェックするが、これらはinformationを含んでいる。
そこで、Journalからレベルを絞ってログをとりだして、それをチェックする、という作戦。

ラッパー

Logcheckを参考に、ラッパーを作ってみた。

/usr/local/sbin/my-logcheck

#!/usr/bin/env bash
LOGCHECK_BIN="/usr/sbin/logcheck"
STATEDIR="/var/lib/logcheck"
LOGFILE="$STATEDIR/my-logcheck.log"
OFFSETFILE="$STATEDIR/my-offset.journal"
IS_TESTMODE=0

# テストモード指定の確認
for arg in "$@"; do
	if [ "$arg" = "-t" ]; then
		IS_TESTMODE=1
		break
	fi
done

# 前回実行時刻を取得
if [ -f "$OFFSETFILE" ]; then
	OFFSETTIME="--since=@$(stat -c %Y "$OFFSETFILE")"
else
	OFFSETTIME="--since=-5h"
fi

# ログファイルを待避
if [ -f "$LOGFILE" ]; then
	mv -f "$LOGFILE" "$LOGFILE.1"
fi

# ジャーナルログから警告以上のログを抽出
LASTTIME=$(date +"%Y-%m-%d %H:%M:%S")
journalctl -p warning..emerg --quiet "$OFFSETTIME" >> "$LOGFILE" 2>&1

# Logcheckを実行
"$LOGCHECK_BIN" "$@"
LOGCHECK_EXITCODE=$?

# Logcheckが正常終了したら実行時刻を更新
if [ $LOGCHECK_EXITCODE -eq 0 ]; then
	if [ $IS_TESTMODE -eq 0 ]; then
		touch -d "$LASTTIME" "$OFFSETFILE"
	fi
else
	echo "E: my-logcheck: logcheck exited with error status $LOGCHECK_EXITCODE. Offset not updated." >&2
	exit $LOGCHECK_EXITCODE
fi

テストの時にoffsetファイルのタイムスタンプを更新しないようにした。
(本家はテストでもoffsetファイルのタイムスタンプが更新されるため、繰り返しテストができない)

このユニットはerror以上、あのユニットはinformation以上、と細かく制御したければ、journalctlの行を複数書く。
その場合は時系列が崩れるが、いざ調べるとなったらジャーナルを見に行くので、大きな問題にはならないだろう。

このスクリプトに実行権限を付けておく。

Logcheckの監視対象を変更

監視対象は /etc/logcheck/logcheck.logfiles.d ディレクトリで設定する。
よくよく見ると、Journalもsyslogも確認しており、同じ問題が2回報告される設定だった。

今回はそれらを無効にして、ラッパーが作るログを見に行くように修正する。

/etc/logcheck/logcheck.logfiles.d/journal.logfiles

## The word 'journal' tells logcheck to check log entries in the
## systemd journal

# (This is enabled by default, but if you do not want to check entries
# in the journal you can comment out the next line)
#journal

/etc/logcheck/logcheck.logfiles.d/syslog.logfiles

## Log entries in the logs listed below will be checked by logcheck

# The default is to check standard syslog files
# created by rsyslog or other syslog daemons

# (If your system does not use a syslog daemon you
# can comment these lines out)
#/var/log/syslog
#/var/log/auth.log

/etc/logcheck/logcheck.logfiles.d/my.logfiles ※新規作成

/var/lib/logcheck/my-logcheck.log

これで、監視対象が /var/lib/logcheck/my-logcheck.log になる。

レポートの調整

改めて、過去にまとめたレポートの3層構造を確認。
報告させたいログ、無視したいログを定義する。

無視する SYSTEM EVENTS

実際にメールを受け取ってから考える、で問題なし。

問題に対処すべきなのか、無視すべきなのかは、そのログが何を言っているのかを確かめて決める。
今回、ラッパーを入れたことによってwarning以上のログしか報告されなくなっているので、対処することもそれなりにあった。

以下は参考程度に。

/etc/logcheck/ignore.d.server/local-my ※新規作成

^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ \(cron\)\[[0-9]+\]: cron\.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ \(udev-worker\)\[[0-9]+\]: id: Truncating stdout of 'dmi_memory_id' up to 16384 byte\.$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ kernel: core: CPUID marked event: '[ 0-9a-zA-Z]+' unavailable$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled\. Duplicate IMA measurements will not be recorded in the IMA log\.$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ kernel: kauditd_printk_skb: [0-9]+ callbacks suppressed$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ kernel: piix4_smbus [.:0-9]+: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ kernel: sd [:0-9]+: \[sd[a-z]\] Assuming drive cache: write through$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ kernel: sd [:0-9]+: \[sd[a-z]\] No Caching mode page found$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ kernel: workqueue: [^ ]+ (\[[0-9a-zA-Z]+\] )?hogged CPU.*$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ networkctl\[[0-9]+\]: Interface "[._0-9a-zA-Z-]+" not found.$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ systemd\[[0-9]+\]: networkd-dispatcher.service: Got notification message from PID [0-9]+, but reception only permitted for main PID [0-9]+$
^([a-zA-Z]{3} [ :0-9]{11}|[0-9T:.+-]{32}) [._0-9a-zA-Z-]+ systemd-resolved\[[0-9]+\]: Using degraded feature set (TCP|UDP) instead of UDP(\+EDNS0)? for DNS server [.:0-9a-fA-F]+$

POSIX文字クラスを使っていないのは、それを使うとどういうわけか動作が安定しなかったため。
色々とトライしてみたけれど、POSIX文字クラスを使わないことでしか解決ができなかった。

Geminiさんによれば、フィルターはlocal-<service name>みたいな形にして、複数ファイルで管理するのが一般的とのこと。
とはいえ、warning以上に絞ったことで、フィルターするログも減ると思うので、アルファベット順で並べて管理することにした。

SECURITY EVENTS として報告させる

S25Rを運用しているので、それをSECURITY EVENTSとして報告させて、即座に対応できるようにする。

/etc/logcheck/violations.d/local-my

に書いておけばOK。

テスト

今回作成したラッパーは、Logcheckのソースをまねて
　/var/lib/logcheck/my-offset.journal
のタイムスタンプを見て、いつのログから読み込むのかを決めている。

そこで、時間を巻き戻してテストするスクリプトを作って実行した。

lctest.sh ※名前は何でもOK

#!/bin/bash
ORIG_TIME=$(sudo date -r /var/lib/logcheck/my-offset.journal +"%Y-%m-%d %H:%M:%S.%N")
sudo -u logcheck touch -d "2026-07-01 00:00:00" /var/lib/logcheck/my-offset.journal
sudo -u logcheck bash -c "nice -n10 /usr/local/sbin/my-logcheck -t -o"  > lc.txt
sudo touch -d "$ORIG_TIME" /var/lib/logcheck/my-offset.journal
sudo rm -f /var/lib/logcheck/offset.var.lib.logcheck.logcheck.log

この場合、2026年7月1日以降のログをチェックする。
最初にmy-offset.journalのタイムスタンプを読み取っておいて、開始日時で更新し、最後に元に戻すようにしている。

my-offset.journalがない場合には作っておいて、このスクリプトを実行する。

$ sudo -u logcheck touch /var/lib/logcheck/my-offset.journal
$ ./lctest.sh

ラッパーはJournalからログを読み取ってファイルを作成する前に、前回分のファイルを logcheck.log.1 にリネームしている。
しかし、連続で実行すると、何故か前回のファイルを途中で見ることがあった。

Geminiさんに相談してみたところ、このような挙動であると整理してくれた。

Linuxカーネルおよびファイルシステムの動作

  • LinuxのExt4などのファイルシステムにおいて、ファイルが削除（アンリンク）されると、その iノード番号は即座に「空きiノード（フリーリスト/ビットマップ）」に戻されます。
  • 同じディレクトリ内で直後に新しいファイルが作成された場合、アロケータ（割り当てアルゴリズム）は局所性を高めるため、直前に解放されたばかりの最も若いiノード番号を優先的に再再再割り当てする仕様になっています。

エンジニアコミュニティ・各種ツールでの既知のトラブル

  • ファイルの識別を「パス名」ではなく「iノード番号」に依存しているログ収集・監視ツール（Logstash, Filebeat, Fluentd, Logtailなど）において、ログローテーション直後にiノードが再利用されることで、「新しいファイルを古いファイルの続きと誤認してログの先頭を読み飛ばす」という障害が世界中で多数報告されています。

そこで、テスト用スクリプトでは offset.var.lib.logcheck.logcheck.log を削除して、必ず logcheck.log を見に行くようにしてある。

Cronからラッパーを呼び出す

Cronからラッパーを呼び出すように変更する。

/etc/cron.d/logcheck

# /etc/cron.d/logcheck: crontab entries for the logcheck package

PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=root

#@reboot        logcheck    if [ -x /usr/sbin/logcheck ]; then nice -n10 /usr/sbin/logcheck -R; fi
#2 * * * *      logcheck    if [ -x /usr/sbin/logcheck ]; then nice -n10 /usr/sbin/logcheck; fi
@reboot         logcheck    if [ -x /usr/sbin/logcheck ]; then nice -n10 /usr/local/sbin/my-logcheck -R; fi
2 * * * *       logcheck    if [ -x /usr/sbin/logcheck ]; then nice -n10 /usr/local/sbin/my-logcheck; fi

# EOF

これで、再起動時＋毎時2分に「調整されたレポート」が届く。

例えば、メールサーバーは四六時中warningを出力しているが、不正な要求をブロックしているなら、侵害されてはいない。
落とされれば別のログが出るだろうし、メールを受け取ったことが心配になったとしても、それは別の方法で確認するしかない。
ならばフィルターに入れよう…

問題に対処し、無視するログはフィルターに入れる、という処置をしていくことで、レポートはめったに送られないものになっていく。

運用してみた感想

報告がwarningに絞られたことで、すべてを確かめるようになった。
そして、生成AIが色々と教えてくれるようになったことで、確認時間が激減している。

実際に色々問題を発見しては修正したが、例を挙げるとこんな感じ。

  • nftablesが出力するログを見て、誤りを修正したり、無言ドロップしたりと、設定を修正した。
  • シャットダウン時にApacheがエラーを起こしていたので、DockerとApacheの順序制御をした。
  • いらなくなったパッケージが入っているのを発見して、パージした。

ただし、落ち着くまでには1ヶ月程度を要した。

  • 何が起きているのかを理解するのに時間がかかる。
  • 問題だと分かったとしても、最善の対応手段を探し出すのに時間がかかる。
  • 無視すると決めたログは報告されなくなるので、単純には決められない。
  • 時に、報告させて無視する、という選択をする場合もある。

今までサボっていたことによる知識不足が原因だが、今回色々と勉強できたとも言える。
Geminiさんは、聞けば親切に付き合ってくれて、知識を補完してくれるので大助かり。

ただし、時々論理が飛躍することがあるので、回答は注意深く見ていくことになる。
論理が飛躍するときは、大抵、検索してもダイレクトに答えが見つからない。
世界のエンジニア達はもっと本質的なところで議論をしていて、ウチで起きているような枝葉で発生する問題を軸にはしていないから。

結局、ログを丁寧に確かめることは必須であり、提案される対策も鵜呑みにせずに丹念に調べる必要がある。

ということもあって、大変ではあるが、システムが浄化されていく感触はあった。

さいごに

メモを書き始めてから1ヶ月以上が経過して、ようやくリリース。
この間、他のこともやっているとはいえ、完成までにだいぶ時間がかかった。

大変だったけど気持ちいい、という大掃除に似た感覚。
毎日のレポートが楽しみにさえなってきた。

さぁ、これで一旦きれいになったし、試しにinformationに行ってみる？

いやー、無理無理。
他のことをやろう。

ここから広告
広告
広告ここまで
rohhie

コメントはこちらから お気軽にどうぞ ～ 投稿に関するご意見・感想・他