こんにちは。サイオステクノロジー OSS サポート担当 山本 です。
今回は前回お話しした、journald の RateLimit のもう一つの設定方法についてお話しします。
■おさらい：journald と RateLimit って？
journald は、システム管理ソフトウェア systemd のコンポーネントの一つで、システム全体のロギングを担うものです。
これのログはデフォルトでは一時ディレクトリ /run/ 配下の /run/log/journal/ 配下に保存されます。
journald は記録するログがあまりにも多すぎると、一時的にログの記録を書き出すのをやめます。
この時、「ログが多すぎる」と判断する基準になる設定が RateLimit です。
前回の記事では RateLimit についてもう少し詳しくお話ししているので、よければ読み進める前にこちらも確認してみてください。
参考：ログ “Suppressed X messages” とログの抑制について (journald)
■unit 毎に RateLimit を設定する
前回は一括で RateLimit を適用するための設定方法を確認しましたが、journald の RateLimit は unit 毎に別々に設定することもできます。今回はこちらの方法を見ていきます。
unit 毎に RateLimit を設定する場合は、対象となる unit の unit ファイルに設定を記述します。
unit ファイルがどこにあるかわからない場合は、“systemctl status” コマンドで確認することができます。例えば、今回の例で使う環境での httpd であれば、以下のように “/usr/lib/systemd/system/httpd.service” であることが確認できます。
[ ~]$ sudo systemctl status httpd
● httpd.service - The Apache HTTP Server
Loaded: loaded (/usr/lib/systemd/system/httpd.service; disabled; preset: disabled)
↑コレ
この unit ファイルに以下のような設定を記述することで、その unit に RateLimit を適用できます。
LogRateLimitIntervalSec=30s LogRateLimitBurst=15000
これらは前回お話しした /etc/systemd/journald.conf の “RateLimitIntervalSec” および “RateLimitBurst” と同等の機能を持ちます。
つまり、上記の設定であれば 30秒 (LogRateLimitIntervalSec) 以内での [補正値 (前回参照)] × 15000 (LogRateLimitBurst) 個目以降のログが抑制されるようになります。
なお、unit ファイルの設定には “[Unit]” のような記述で分けられたセクションという区分がありますが、”LogRateLimitIntervalSec” と “LogRateLimitBurst” の設定は unit ファイルの拡張子と同名のセクションに記述するようにしてください。
例えば、unit “httpd.service” であれば [Service] セクション、unit “dbus.socket” であれば [Socket] セクション、unit “tmp.mount” であれば [Mount] セクション……に記述します。
■検証：”Suppressed X messages” を出させてみる
今回もログ抑制の動作を確認してみます。
前回の /etc/systemd/journald.conf での RateLimit 設定に続いて同じ環境で検証する場合、先に /etc/systemd/journald.conf の設定を元に戻してから試してみてください。
確認には今回も httpd を使用します。
今回の検証環境では httpd の unit ファイルは “/usr/lib/systemd/system/httpd.service” なのでこれを開き、unit ファイルの拡張子と同名のセクション “[Service]” セクションに以下のような設定を追加します。
なおこの設定値はあくまで RateLimit のログ抑制機能の検証のためのものであり、実際に運用している環境では間違ってもこんな設定値にしないでください。
[Service] LogRateLimitIntervalSec=90s LogRateLimitBurst=2
設定を変更したら、以下のコマンドで systemd の unit 設定を再読み込みをすれば準備 OK です。
$ sudo systemctl daemon-reload
あとは RateLimit を設定した unit からのログが出力される操作を何回か繰り返せば、ログ抑制の動作が確認できるはずです。
(先述 & 前回お話ししたとおり、実際にログ抑制が行われるログの数は LogRateLimitBurst の値に環境に応じた “補正倍率” をかけた数になる点には注意してください。)
それでは、httpd の再起動と journal ログの確認を繰り返して、ログ抑制の動作を確認してみます。
[ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname -- No entries -- [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Tue 2023-08-15 08:46:26 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:26 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:26 UTC httpd[1499]: Server configured, listening on: port 80 [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Tue 2023-08-15 08:46:26 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:26 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:26 UTC httpd[1499]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:37 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:38 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC httpd[1724]: Server configured, listening on: port 80 [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Tue 2023-08-15 08:46:26 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:26 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:26 UTC httpd[1499]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:37 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:38 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC httpd[1724]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:50 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:51 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC httpd[1950]: Server configured, listening on: port 80 [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Tue 2023-08-15 08:46:26 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:26 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:26 UTC httpd[1499]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:37 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:38 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC httpd[1724]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:50 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:51 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC httpd[1950]: Server configured, listening on: port 80 Tue 2023-08-15 08:47:04 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:47:05 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:47:05 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:47:05 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:47:05 UTC systemd[1]: Started The Apache HTTP Server. [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Tue 2023-08-15 08:46:26 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:26 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:26 UTC httpd[1499]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:37 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:38 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC httpd[1724]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:50 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:51 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC httpd[1950]: Server configured, listening on: port 80 Tue 2023-08-15 08:47:04 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:47:05 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:47:05 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:47:05 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:47:05 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:47:15 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:47:16 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:47:16 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:47:16 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:47:16 UTC systemd[1]: Started The Apache HTTP Server. [ ~]$
このとおり、4回目以降の再起動のログではプロセス名が “httpd” のログがなくなっていることが確認できます。
この後に “LogRateLimitIntervalSec” で設定した時間 (今回は 90秒) 以上待ってから、再度 httpd を再起動して httpd unit のログを出力させてみると…
[ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Tue 2023-08-15 08:46:26 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:26 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:26 UTC httpd[1499]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:37 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:38 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:38 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:38 UTC httpd[1724]: Server configured, listening on: port 80 Tue 2023-08-15 08:46:50 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:46:51 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:46:51 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:46:51 UTC httpd[1950]: Server configured, listening on: port 80 Tue 2023-08-15 08:47:04 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:47:05 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:47:05 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:47:05 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:47:05 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:47:15 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:47:16 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:47:16 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:47:16 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:47:16 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:48:45 UTC systemd[1]: Stopping The Apache HTTP Server... Tue 2023-08-15 08:48:46 UTC systemd[1]: httpd.service: Deactivated successfully. Tue 2023-08-15 08:48:46 UTC systemd[1]: Stopped The Apache HTTP Server. Tue 2023-08-15 08:48:46 UTC systemd[1]: Starting The Apache HTTP Server... Tue 2023-08-15 08:48:46 UTC systemd[1]: Started The Apache HTTP Server. Tue 2023-08-15 08:48:46 UTC systemd-journald[490]: [🡕] Suppressed 2 messages from httpd.service Tue 2023-08-15 08:48:46 UTC httpd[2635]: Server configured, listening on: port 80 [ ~]$
このとおり、httpd unit のログが出力される直前に問題のログ “Suppressed X messages” が出力されます。
前回の記事と見比べていただけば、今回の unit ファイルで設定する方法と /etc/systemd/journald.conf に設定する方法が同等の動作をしていることが確認できるかと思います。
■最後に
今回は journald の RateLimit を unit 毎に設定する方法を確認しました。
今回 (と前回) のお話しはあくまで “Suppressed X messages” というログの正体についてと、これが出てしまった場合の対処のための豆知識であり、このログを出すことは本来目的にはなり得ないことには注意してください。
前回のやり方は systemd-journald 全体に対して影響があるのに対し、今回は特定の unit だけに設定できるため、影響範囲を小さくすることができます。
問題となっている unit が少なくかつ特定できている場合には、今回の unit 毎の設定方法のほうが便利かもしれません。
ただし、前回にもお話ししましたが RateLimit の調整というのはログ抑制への根本対策の一案とはなりますが、そもそも抑制されるほどの量のログが発生しているのは適正な状況・構成なのかというのは確認する必要があり、その妥当性を確認するためのログを出力させるための暫定対処という見方・考え方も重要です。
関連する他の回：
/var/log/messages を知りたい：journald 編
/var/log/messages を知りたい：rsyslog 編
journald のログを永続化したい
ログ “Suppressed X messages” とログの抑制について (journald)
ログ “X messages lost due to rate-limiting” とログの抑制について (rsyslog)
rsyslog のログフォーマットを変更する
journald をログファイルに記録させずに rsyslog のログファイルに記録する
