/var/log/messages を知りたい：rsyslog 編

◆ Live配信スケジュール ◆
サイオステクノロジーでは、Microsoft MVPの武井による「わかりみの深いシリーズ」など、定期的なLive配信を行っています。
⇒ 詳細スケジュールはこちらから
⇒ 見逃してしまった方はYoutubeチャンネルをご覧ください

【5/21開催】Azure OpenAI ServiceによるRAG実装ガイドを公開しました
生成AIを活用したユースケースで最も一番熱いと言われているRAGの実装ガイドを公開しました。そのガイドの紹介をおこなうイベントです!!
https://tech-lab.connpass.com/event/315703/

こんにちは。サイオステクノロジー OSS サポート担当山本です。

此度も systemd 環境のログファイル /var/log/messages について見ていこうと思います。
今回はこのログファイルに関連する要素のもう片割れ、rsyslog について確認します。

1 ■rsyslog って？
2 ■rsyslog の記録するログについて
3 ■logger コマンドで確認してみる
4 ■最後に

■rsyslog って？

rsyslog はログに関連する処理を行うソフトウェアです。

豊富なモジュールによる拡張性とカスタマイズ性、そのモジュールにより様々な入力元や出力先に対応できることや、柔軟なフィルタリングによるログの出し分けや転送、ログの加工…
などなどログに関する多彩な処理ができながらも、名前の由来 “Rocket-fast SYStem for LOG processing” のとおり超高速な処理ができることなどを魅力としています。
入出力がローカル、かつそこまで複雑な処理を入れなければ秒間 100万個分をも超える量のログを処理できる、とされています。
一言で纏めてしまえば、いろんなところからログを受け取って、なんかいい感じに好きな場所に記録してくれるヤツ…といったところでしょうか。

このとおりログの処理をするというあたりから想像はつくかと思いますが、rsyslog は daemon である rsyslogd が基本的に本体と呼べるものになります。

■rsyslog の記録するログについて

先述のとおり、rsyslog は様々な入力元や出力先を持つことができるログ処理用のソフトウェアです。
実際にどんな処理をするのかは、設定ファイル /etc/rsyslog.conf によって決まります。

今回もデフォルトで systemd + rsyslog という構成を取る RHEL9 の設定を例に、この設定ファイルから /var/log/messages 周りに影響する部分を見ていきます。

■出力方法の設定部分

まずは出力方法の部分です。
先述のとおり rsyslog は様々な入力元や出力先に対応できますが、そうであるが故に「何を入力元、出力先にするか」という設定が必要になります。

とりあえず設定ファイルの以下の部分を見てください。

#### GLOBAL DIRECTIVES ####

# Where to place auxiliary files
global(workDirectory="/var/lib/rsyslog")

# Use default timestamp format
module(load="builtin:omfile" Template="RSYSLOG_TraditionalFileFormat")

# Include all config files in /etc/rsyslog.d/
include(file="/etc/rsyslog.d/*.conf" mode="optional")

これの真ん中あたりにある omfile が、ファイルへ出力する機能を提供する公式のモジュール “omfile” を読み込む設定になります。

# Use default timestamp format
module(load="builtin:omfile" Template="RSYSLOG_TraditionalFileFormat")

このように入力元や出力先、その他必要な機能に合わせてモジュールを読み込むことで、rsyslog は様々な動作をすることができるわけです。
望む機能のモジュールがない場合は、モジュールを自作することもできます。

なお今回の話からは少し離れますが、以下の部分によって /etc/rsyslog.d/ 配下の “～.conf” という名前の各ファイルも rsyslog の設定として読み込まれます。
実際に設定を追う場合、こちらも見落とさないように気を付けましょう。

# Include all config files in /etc/rsyslog.d/
include(file="/etc/rsyslog.d/*.conf" mode="optional")

■入力元の設定部分

続いて入力元の設定周りを見てみましょう。
このあたりですね。

#### MODULES ####

module(load="imuxsock"    # provides support for local system logging (e.g. via logger command)
       SysSock.Use="off") # Turn off message reception via local log socket;
                          # local messages are retrieved through imjournal now.
module(load="imjournal"             # provides access to the systemd journal
       StateFile="imjournal.state") # File to store the position in the journal

今回着目するのは後ろの方のモジュール “imjournal” です。
これは systemd の journal…前回紹介した journald を入力元とするモジュールです。

module(load="imjournal"             # provides access to the systemd journal
       StateFile="imjournal.state") # File to store the position in the journal

ということで、このデフォルトの rsyslog 設定は、journald のログを入力元にして、ファイルへ出力するものだということがわかりました。

■フィルタ (=出力先ファイル) の設定部分

最後に、実際の出力先 /var/log/messages を指定している箇所を確認してみましょう。
以下の部分を見てみましょう。

#### RULES ####

# Log all kernel messages to the console.
# Logging much else clutters up the screen.
#kern.*                                                 /dev/console

# Log anything (except mail) of level info or higher.
# Don't log private authentication messages!
*.info;mail.none;authpriv.none;cron.none                /var/log/messages

# The authpriv file has restricted access.
authpriv.*                                              /var/log/secure

# Log all the mail messages in one place.
mail.*                                                  -/var/log/maillog


# Log cron stuff
cron.*                                                  /var/log/cron

# Everybody gets emergency messages
*.emerg                                                 :omusrmsg:*

# Save news errors of level crit and higher in a special file.
uucp,news.crit                                          /var/log/spooler

# Save boot messages also to boot.log
local7.*                                                /var/log/boot.log

これはフィルタという機能を使って設定されています。
ここではファシリティとプライオリティ…前回の journald でもお話しした、カテゴリ・区分のようなものと優先度のようなものですね…を基準にした振り分けが設定されています。

/var/log/messages の部分は…ここですね。

# Log anything (except mail) of level info or higher.
# Don't log private authentication messages!
*.info;mail.none;authpriv.none;cron.none                /var/log/messages

直前の “#” で始まるコメント行にもあるとおり、基本的にプライオリティ “info” 以上のログ全てを記録するようですね。
少し細かく見るなら、セミコロン (;) で設定は区切られているので

　・ファシリティ全てのプライオリティ “info” 以上が対象 (*.info)
　・ファシリティ “mail” は除く (mail.none)
　・ファシリティ “authpriv” は除く (authpriv.none)
　・ファシリティ “cron” は除く (cron.none)

を全て満たすログが、/var/log/messages に記録されているようです。
一方、ここでは記録されないことになっている “mail” “authpriv” “cron” は…以下を見るとそれぞれ /var/log/maillog、/var/log/secure、/var/log/cron に記録されるようですね。

# The authpriv file has restricted access.
authpriv.*                                              /var/log/secure

# Log all the mail messages in one place.
mail.*                                                  -/var/log/maillog

# Log cron stuff
cron.*                                                  /var/log/cron

他に目立つところとしては、プライオリティ “emerg” のログがモジュール omusrmsg によって、ログイン中の各ユーザのターミナルに出力される以下の設定でしょうか。

# Everybody gets emergency messages
*.emerg                                                 :omusrmsg:*

このように、rsyslog ではフィルタによって自由に出力先の変更などを行うことができます。
更に柔軟に様々な動作を設定することもできるようですが、細かい話はまた機会があればということで…。

■logger コマンドで確認してみる

rsyslog が、journald のログを読み取ってなんかいい感じに分けてファイルに出力しているらしい、ということはなんとなくわかりました。
では折角なのでこれをシステムログを生成する (=journald のログに書き込める) logger コマンドを使って確認してみましょう。
logger コマンドにはファシリティ・プライオリティを指定できる “-p” というオプションがあるのでこれを使います。

       -p, --priority priority
           Enter the message into the log with the specified priority. The priority may be specified numerically or
           as a facility.level pair. For example, -p local3.info logs the message as informational in the local3
           facility. The default is user.notice.

まずはコンソールに表示されるプライオリティ “emerg” が一番わかりやすいでしょうか。
試してみましょう。

[~]# logger -p user.emerg test message emerg
[~]#
Broadcast message from systemd-journald@localhost (Mon 2023-07-03 09:33:30 UTC):

root[7509]: test message emerg


Message from syslogd@localhost at Jul  3 09:33:30 ...
 root[7509]:test message emerg
[~]#

このような感じで、コンソール上にメッセージが表示されるはずです。(journald からも同じログがコンソールに表示されていますね…)
ともあれ、確かに設定どおりにプライオリティ “emerg” のログがコンソールに出力されました。

一方、先のコマンドではファシリティ “user” でメッセージを作ったので、/var/log/messages にもこのログが記録されているはずです。
journald のログと合わせて確認してみましょう。

[~]# journalctl -n 5 -o short-full --no-pager --no-hostname
Mon 2023-07-03 09:33:17 UTC systemd[1]: httpd.service: Consumed 8.942s CPU time.
Mon 2023-07-03 09:33:17 UTC systemd[1]: Starting The Apache HTTP Server...
Mon 2023-07-03 09:33:17 UTC systemd[1]: Started The Apache HTTP Server.
Mon 2023-07-03 09:33:17 UTC httpd[7289]: Server configured, listening on: port 80
Mon 2023-07-03 09:33:30 UTC root[7509]: test message emerg
[~]#
[~]# tail -n 5 /var/log/messages
Jul  3 09:33:17 localhost systemd[1]: httpd.service: Consumed 8.942s CPU time.
Jul  3 09:33:17 localhost systemd[1]: Starting The Apache HTTP Server...
Jul  3 09:33:17 localhost systemd[1]: Started The Apache HTTP Server.
Jul  3 09:33:17 localhost httpd[7289]: Server configured, listening on: port 80
Jul  3 09:33:30 localhost root[7509]: test message emerg
[~]#

このとおり、先に logger コマンドで生成した “test message emerg” というログが journald と /var/log/messages の両方で確認できます。
また、journald と /var/log/messages のログの内容に同じ部分があることも確認できると思います。(※このサンプルでは完全に一致していますが、先述のとおりファシリティ次第では /var/log/messages に出ないログもあります。)

もう一種類、今度はプライオリティ “info” で試してみましょう。ファシリティは /var/log/messages に出るものから適当に “daemon” にしてみましょうか。
併せて journald と /var/log/messages も確認すると以下のようになりました。

[~]# logger -p daemon.info test message daemon
[~]# journalctl -n 5 -o short-full --no-pager --no-hostname
Mon 2023-07-03 09:34:54 UTC systemd[1]: Starting Automatically configure NetworkManager in cloud...
Mon 2023-07-03 09:34:54 UTC systemd[1]: nm-cloud-setup.service: Deactivated successfully.
Mon 2023-07-03 09:34:54 UTC systemd[1]: Finished Automatically configure NetworkManager in cloud.
Mon 2023-07-03 09:35:25 UTC NetworkManager[659]:   [1688376925.7818] dhcp6 (eth0): state changed new lease, address=XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX
Mon 2023-07-03 09:36:00 UTC root[7543]: test message daemon
[~]#
[~]# tail -n 5 /var/log/messages
Jul  3 09:34:54 localhost systemd[1]: Starting Automatically configure NetworkManager in cloud...
Jul  3 09:34:54 localhost systemd[1]: nm-cloud-setup.service: Deactivated successfully.
Jul  3 09:34:54 localhost systemd[1]: Finished Automatically configure NetworkManager in cloud.
Jul  3 09:35:25 localhost NetworkManager[659]:   [1688376925.7818] dhcp6 (eth0): state changed new lease, address=XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX
Jul  3 09:36:00 localhost root[7543]: test message daemon
[~]#

こちらではコンソール上にはメッセージは出てきませんが、やはり journald と /var/log/messages の両方に、生成したメッセージ “test message daemon” の記録が確認できます。

最後に、rsyslog のログ出し分けを確認するために /var/log/messages に出ないはずのログを生成してみましょう。
ファシリティ “cron” なら /var/log/messages ではなく /var/log/cron に記録される設定でしたね。

[~]# logger -p cron.info test message cron
[~]# journalctl -n 5 -o short-full --no-pager --no-hostname
Mon 2023-07-03 09:34:54 UTC systemd[1]: Finished Automatically configure NetworkManager in cloud.
Mon 2023-07-03 09:35:25 UTC NetworkManager[659]:   [1688376925.7818] dhcp6 (eth0): state changed new lease, address=XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX
Mon 2023-07-03 09:36:00 UTC root[7543]: test message daemon
Mon 2023-07-03 09:36:35 UTC NetworkManager[659]:   [1688376995.7823] dhcp6 (eth0): state changed new lease, address=XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX
Mon 2023-07-03 09:37:21 UTC root[7568]: test message cron
[~]#
[~]# tail -n 5 /var/log/messages
Jul  3 09:34:54 localhost systemd[1]: nm-cloud-setup.service: Deactivated successfully.
Jul  3 09:34:54 localhost systemd[1]: Finished Automatically configure NetworkManager in cloud.
Jul  3 09:35:25 localhost NetworkManager[659]:   [1688376925.7818] dhcp6 (eth0): state changed new lease, address=XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX
Jul  3 09:36:00 localhost root[7543]: test message daemon
Jul  3 09:36:35 localhost NetworkManager[659]:   [1688376995.7823] dhcp6 (eth0): state changed new lease, address=XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX
[~]#
[~]# tail -n 5 /var/log/cron
Jul  3 09:01:01 localhost CROND[6726]: (root) CMD (run-parts /etc/cron.hourly)
Jul  3 09:01:01 localhost run-parts[6726]: (/etc/cron.hourly) starting 0anacron
Jul  3 09:01:02 localhost run-parts[6726]: (/etc/cron.hourly) finished 0anacron
Jul  3 09:01:02 localhost CROND[6725]: (root) CMDEND (run-parts /etc/cron.hourly)
Jul  3 09:37:21 localhost root[7568]: test message cron
[~]#

このとおり、生成したファシリティ “cron” のログ “test message cron” は、journald には記録されていますが /var/log/messages には記録されておらず、代わりに /var/log/cron に記録されていることが確認できるかと思います。

ということで、rsyslog が journald のログを入力元にして各種ログファイルに適切にログを出しわけるということが確認できるかと思います。

■最後に

今回は rsyslog と /var/log/messages についてお話ししてみました。

勿論、前回の journald と合わせて細かく覚えていなくても「/var/log/messages になんか総合的なログがある」くらい覚えていれば困ることは滅多にないはずですが、
今回の記事で /var/log/messages がどんなものかちょっとだけ理解が深まったかな、と思っていただければ幸いです。