SIOS Tech. Lab | エンジニアのタメになるOSS・クラウド・認証の技術トピックス 
こんにちは。サイオステクノロジー OSS サポート担当 山本 です。
今回は systemd (journald) + rsyslog 環境で何かログが途切れている気がする、ある見慣れないログがある場合の対処法を見ていきたいと思います。
目次
■おさらい：journald、rsyslog って何だっけ？
いずれもログに関するものです。
一部の Linux ディストリビューション (Red Hat Enterprise Linux、Debian など) では、いずれもシステム上のログ管理のためにデフォルトでインストールされています。
journald は、システム管理ソフトウェア systemd のコンポーネントの一つで、システム全体のロギングを担うものです。
これのログはデフォルトで一時ディレクトリ /run/ 配下の /run/log/journal/ 配下に保存されます。
rsyslog はログに関する様々な処理を行うことのできるソフトウェアです。これは様々なものからログを受け取り、また様々なものにログを出力することができますが、journald とともにデフォルトで導入される場合は journald のログ を読み込んで、/var/log/ 配下の /var/log/messages などのファイルにログを記録しています。
■謎のログ “Suppressed X messages” について
では本題です。
まず滅多に見ることはないかと思いますが、journald、rsyslog で以下のようなログが記録されることがあります。
systemd-journald[XXXX]: Suppressed 64 messages from init.scope systemd-journald[XXXX]: Suppressed 4 messages from httpd.service
これらのログは、”Suppressed X messages” という内容のとおり、メッセージ (=ログ) の記録が抑制されたことを示すものです。
上記の例ではそれぞれ 64個、4個のログが抑制されています。
「抑制された」ログは記録されることはなく、いかなる手段でも確認することはできません。
これらのログのプロセス部分を見ればわかるとおり、このログは systemd-journald (journald) のものです。
つまり、このログ抑制は journald によって行われていることがわかります。
このようなログが記録され、ログが抑制される原因は非常にシンプルで、ログが多すぎるからです。
■ログ抑制の契機や設定
では具体的にはどれくらいで「ログが多すぎる」と判断されるかというと……これは設定によってある程度制御できます。
その設定は、設定ファイル /etc/systemd/journald.conf の以下の部分です。>
[Journal] : RateLimitIntervalSec=30s RateLimitBurst=10000
デフォルトではこの部分はコメントアウトされていますが、この 2つの設定項目 RateLimitIntervalSec と RateLimitBurst によって、journald が記録できるログの量が制御されます。
上記の例の設定であれば、[RateLimitIntervalSec] の設定 30秒の間に、[RateLimitBurst] の 10000 に journald の使用できるストレージ領域に応じた補正 (※) をかけた数値以上の数のログがあった場合、[RateLimitBurst ×補正値] 個目以降のログは抑制されます。
※ RateLimitBurst の補正の最低値は等倍で、journald の使用できるストレージ領域が大きいほど補正倍率は大きくなります。journald の使用できるストレージ領域は、保存先が /run/log/journal/ 配下となる設定なら RuntimeMaxUse、/var/log/journal/ 配下となるような設定なら SystemMaxUse など (いずれも /etc/systemd/journald.conf 内) により調節可能です。
なお、RateLimitIntervalSec および RateLimitBurst によるログ抑制までのログ数のカウントは、systemd の unit (≒systemd の管理単位) ごとに別々に行われます。
どういうことかというと……例えば、先のサンプルのログをもう一度見てください。
systemd-journald[XXXX]: Suppressed 64 messages from init.scope systemd-journald[XXXX]: Suppressed 4 messages from httpd.service
これらのログの後半部分 “from ～” の “～” の部分が、ログ抑制が行われた unit の名前になっています。
上のほうは “init.scope” unit のログが 64個抑制されたことを、下のほうは “httpd.service” unit のログが 4個抑制されたことがこれらのログから読み取れます。
このようにログの抑制や RateLimit により抑制されたログの数は別々に管理されており、例えば上記の 2つの unit のログが抑制されている状態でも、別の unit (例えば、”NetworkManager.service” など) のログは問題なく記録されます。
1個目のログとしてカウントされたログから [RateLimitIntervalSec] 秒経過した後に、次に最初にその unit のログが記録される際に抑制までのカウントはリセットされます。
この時、リセット前にログが抑制されている状態だった場合、問題のログが出力されるというわけです。
■検証：無理やりこのログを出してみる
このログは割と簡単に確認できるので、試してみます。
設定ファイル /etc/systemd/journald.conf を開き、以下のような記述を追加します。元々の記述を変更する場合は、行頭の “#” を消してコメント扱いにならないようにしましょう。
なおこれはあくまで検証用の設定で、間違ってもこれの確認用の検証環境以外ではこんな設定値にはしないでください。
[Journal] RateLimitIntervalSec=60s RateLimitBurst=2
変更を保存したら、journald を再起動すれば準備は OK です。
$ sudo systemctl restart systemd-journald
先述のとおり RateLimitBurst には環境に応じた補正がかかるため、実際にログが抑制されるまでに必要なログ数はまちまちになると思いますが、”RateLimitBurst=2″ であればあとは何か適当にログが出るような操作をすれば、程なく件のログを見ることができるでしょう。
ここでは httpd の再起動と journald のログ確認を繰り返してみます。
[ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname -- No entries -- [ ~]$ date Wed Aug 2 08:39:52 AM UTC 2023 [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Wed 2023-08-02 08:39:55 UTC systemd[1]: Starting The Apache HTTP Server... Wed 2023-08-02 08:39:55 UTC systemd[1]: Started The Apache HTTP Server. Wed 2023-08-02 08:39:55 UTC httpd[1821]: Server configured, listening on: port 80 [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Wed 2023-08-02 08:39:55 UTC systemd[1]: Starting The Apache HTTP Server... Wed 2023-08-02 08:39:55 UTC systemd[1]: Started The Apache HTTP Server. Wed 2023-08-02 08:39:55 UTC httpd[1821]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:01 UTC systemd[1]: Stopping The Apache HTTP Server... Wed 2023-08-02 08:40:03 UTC httpd[2046]: Server configured, listening on: port 80 [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Wed 2023-08-02 08:39:55 UTC systemd[1]: Starting The Apache HTTP Server... Wed 2023-08-02 08:39:55 UTC systemd[1]: Started The Apache HTTP Server. Wed 2023-08-02 08:39:55 UTC httpd[1821]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:01 UTC systemd[1]: Stopping The Apache HTTP Server... Wed 2023-08-02 08:40:03 UTC httpd[2046]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:12 UTC httpd[2271]: Server configured, listening on: port 80 [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Wed 2023-08-02 08:39:55 UTC systemd[1]: Starting The Apache HTTP Server... Wed 2023-08-02 08:39:55 UTC systemd[1]: Started The Apache HTTP Server. Wed 2023-08-02 08:39:55 UTC httpd[1821]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:01 UTC systemd[1]: Stopping The Apache HTTP Server... Wed 2023-08-02 08:40:03 UTC httpd[2046]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:12 UTC httpd[2271]: Server configured, listening on: port 80 [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Wed 2023-08-02 08:39:55 UTC systemd[1]: Starting The Apache HTTP Server... Wed 2023-08-02 08:39:55 UTC systemd[1]: Started The Apache HTTP Server. Wed 2023-08-02 08:39:55 UTC httpd[1821]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:01 UTC systemd[1]: Stopping The Apache HTTP Server... Wed 2023-08-02 08:40:03 UTC httpd[2046]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:12 UTC httpd[2271]: Server configured, listening on: port 80 [ ~]$ date Wed Aug 2 08:40:38 AM UTC 2023
このとおり 5回 httpd の再起動と journald のログ確認を繰り返してみましたが、httpd unit のログ “Server configured, listening on: port 80” が 4回目、5回目の再起動の際に増えていない (=ログが抑制された) ことがわかります。(この環境では RateLimitBurst=2 にしていたので、この環境では RateLimitBurstの補正値は 2倍だったようですね)
この後、RateLimitIntervalSec (今回は 60秒) 以上経過した後に
・一度 “Suppressed” のログが記録されているか確認
・httpd unit のログを出すために httpd を再起動
・再度 “Suppressed” のログが記録されているか確認
の順に実行してみます。
[ ~]$ date Wed Aug 2 08:45:34 AM UTC 2023 [ ~]$ sudo journalctl -u systemd-journald -o short-full -n 5 --no-pager --no-hostname Wed 2023-08-02 07:59:57 UTC systemd-journald[1705]: Journal started Wed 2023-08-02 07:59:57 UTC systemd-journald[1705]: Runtime Journal (/run/log/journal/f916240cadcd4e01a3c7bd69560fe7c2) is 1.9M, max 15.3M, 13.4M free. Wed 2023-08-02 08:44:12 UTC systemd-journald[1705]: [🡕] Suppressed 27 messages from session-1.scope Wed 2023-08-02 08:45:39 UTC systemd-journald[1705]: [🡕] Suppressed 3 messages from session-1.scope Wed 2023-08-02 08:45:39 UTC systemd-journald[1705]: [🡕] Suppressed 22 messages from init.scope [ ~]$ [ ~]$ sudo systemctl restart httpd [ ~]$ sudo journalctl -u systemd-journald -o short-full -n 5 --no-pager --no-hostname Wed 2023-08-02 07:59:57 UTC systemd-journald[1705]: Runtime Journal (/run/log/journal/f916240cadcd4e01a3c7bd69560fe7c2) is 1.9M, max 15.3M, 13.4M free. Wed 2023-08-02 08:44:12 UTC systemd-journald[1705]: [🡕] Suppressed 27 messages from session-1.scope Wed 2023-08-02 08:45:39 UTC systemd-journald[1705]: [🡕] Suppressed 3 messages from session-1.scope Wed 2023-08-02 08:45:39 UTC systemd-journald[1705]: [🡕] Suppressed 22 messages from init.scope Wed 2023-08-02 08:45:51 UTC systemd-journald[1705]: [🡕] Suppressed 2 messages from httpd.service [ ~]$ [ ~]$ sudo journalctl -u httpd -o short-full --no-pager --no-hostname Wed 2023-08-02 08:39:55 UTC systemd[1]: Starting The Apache HTTP Server... Wed 2023-08-02 08:39:55 UTC systemd[1]: Started The Apache HTTP Server. Wed 2023-08-02 08:39:55 UTC httpd[1821]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:01 UTC systemd[1]: Stopping The Apache HTTP Server... Wed 2023-08-02 08:40:03 UTC httpd[2046]: Server configured, listening on: port 80 Wed 2023-08-02 08:40:12 UTC httpd[2271]: Server configured, listening on: port 80 Wed 2023-08-02 08:45:51 UTC systemd-journald[1705]: [🡕] Suppressed 2 messages from httpd.service Wed 2023-08-02 08:45:51 UTC httpd[2970]: Server configured, listening on: port 80 [ ~]$
このとおり、件の “Suppressed” のログは RateLimitIntervalSec が経過した後に、当該 unit の何らかのログが記録されて初めて出力されるものであることが確認できます。
また、抑制されていた httpd unit のログが再度記録できていることや、”Suppressed” ログ内の数値が抑制されたログの数と一致することも確認できるかと思います。
このログはちゃんと journald のログとして記録されるものなので、/var/log/messages でも確認することができます。
[ ~]$ sudo tail -n 5 /var/log/messages Aug 2 08:45:39 localhost systemd[1]: Starting Automatically configure NetworkManager in cloud... Aug 2 08:45:39 localhost systemd[1]: nm-cloud-setup.service: Deactivated successfully. Aug 2 08:45:39 localhost systemd[1]: Finished Automatically configure NetworkManager in cloud. Aug 2 08:45:51 localhost systemd-journald[1705]: Suppressed 2 messages from httpd.service Aug 2 08:45:51 localhost httpd[2970]: Server configured, listening on: port 80 [ ~]$
■設定変更の際に注意したいこと
動作を確認できたところで、改めてこのログ “Suppressed X messages” が出にくくするための方法についてですが、journald の設定ファイル /etc/systemd/journald.conf の……
・RateLimitBurst の値を増やす (ログ抑制が行われるまでのログ数)
・RateLimitIntervalSec の値を減らす (ログ抑制が行われるまでのログ数カウントのリセット間隔)
ことが考えられます。
何なら、これら両方の値を “0” にするとログ抑制自体を無効化することもできます。
しかし一方で、このログ抑制機能はあまりにも過剰な量のログが出力された際の、ログの書き込みによる負荷やストレージの圧迫を事前に防ぐためには必要なものであるとも言えます。
一方で、RateLimitBurst のデフォルト値は 10000、RateLimitIntervalSec のデフォルト値は 30s (30秒) であり、
つまるところ 30秒で 10000 (×補正倍率) 個ものログを 1つの unit から出力されない限りはこのログを見ることはありません。
もちろん環境によってはありえなくはない数である可能性もなくはないですが、あまりに多量のログが出力されるのは何らかの異常や設定ミスなども疑われます。
これらを踏まえて、”Suppressed X messages” とログに出ているからと言って安易に RateLimit を緩和するのではなく、まずは抑制された Unit の出力しているログが想定されたとおりのものなのか、想定のとおりならそのログ量は適切なのか、想定外であるなら原因は……などなど、様々な観点からログの数が多すぎる原因を探ったほうがよいものと考えられます。
(もちろん、抑制されるほどのログが出力された原因を探るために必要であれば、一時的に RateLimit を緩和・無制限化するのは有効な考え方です。)
■最後に
今回は journald のログ “Suppressed X messages” とログ抑制の動作についてお話ししました。
色々お話ししてみましたが、ここまででお話ししたとおり、今回検証でやったようなよほど変な設定でもしていない限りは恐らくこのログを目にする機会はまず殆どないでしょう。
だからこそ万が一このログに出くわしてしまった場合には混乱してしまうかもしれませんが、そんな時こそ落ち着いてこのログの意味とこのログが記録されるだけの量のログが記録された理由を探るべき、と頭の片隅の端っこのほうに置いておいていただければ、と思います。
関連する他の回：
/var/log/messages を知りたい：journald 編
/var/log/messages を知りたい：rsyslog 編
journald のログを永続化したい
Short Tips：journald のログ抑制の設定 おまけ
ログ “X messages lost due to rate-limiting” とログの抑制について (rsyslog)
rsyslog のログフォーマットを変更する
journald をログファイルに記録させずに rsyslog のログファイルに記録する
Be the first to comment