ログ “X messages lost due to rate-limiting” とログの抑制について (rsyslog)

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

今回は /var/log/messages に出てくる……可能性のある、”imjournal: [ZZ] messages lost due to rate-limiting ([XX] allowed within [YY] seconds)” というログについてお話ししてみたいと思います。

1 ■おさらい：ログファイル /var/log/messages と rsyslog
2 ■謎のログ “imjournal: [ZZ] messages lost due to rate-limiting”
3 ■ログ消失の基準の設定
4 ■検証：無理やりこのログを出してみる
5 ■最後に

■おさらい：ログファイル /var/log/messages と rsyslog

ログファイル /var/log/messages は、systemd + rsyslog でロギング環境を構成するシステムでの主要なログファイルです。
このログファイルは、rsyslog によって作成・記録されています。

rsyslog はログに関する様々な処理を行うことができるソフトウェアで、例えば systemd のロギングを担当するコンポーネント systemd-journald (journald) のログを読み取って /var/log/messages に記録する……というようなことなどができます。

もう少し詳しくは、過去の記事にてお願いします。

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

■謎のログ “imjournal: [ZZ] messages lost due to rate-limiting”

では本題です。
まず滅多に見ることはないかと思いますが、/var/log/messages には以下のようなログが記録されることがあります。

rsyslogd[XXXX]: imjournal: 2083 messages lost due to rate-limiting (20000 allowed within 600 seconds)

このログは……まあ書いてあるとおりで、”rate-limiting” なるもののせいでメッセージ (=ログ) が失われて (=消えて) しまった、ということを知らせるものです。
この例では 2083個のログが消えてしまった、ということになります。

消えてしまったログは rsyslog のログファイルに記録されることはなく、後からそれらのログを確認することはできません。

では “rate-limiting” というのは一体何なのかというと、主に異常な動作 (例えば、無限ループ) などによって有意性のない多量のログが発生した際に、ログを記録するための負荷を軽減するなどのために一定量以上のログを切り捨てる機能です。
言ってしまえば、”ログ多すぎるから捨てとくね” というものです。

このログ自体のプロセス名を確認すると “rsyslog” となっていることからもわかるとおり、この「”rate-limiting” によりログが失われる」挙動は rsyslog によって行われていることがわかります。

■ログ消失の基準の設定

さて、ログが多すぎると消失してしまうとは言いましたが、実際にどれくらいのログがあると “多すぎる” と判断されるのかと言うと……これは設定に依存します。
その設定は rsyslog の設定ファイル /etc/rsyslog.conf 内の使用しているモジュールの設定箇所……今回例に取ったログは “imjournal” というモジュールの場合のものですが、この場合は以下の箇所です。

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

この “imjournal” を load している設定箇所の括弧内に、”Ratelimit.Interval” および “Ratelimit.Burst” という 2つの項目を設定することで、ログが多すぎると判断してログを切り捨て始めるタイミングを調整することができます。
これらの設定項目の大まかな意味とデフォルト値は以下のとおりです。

　・Ratelimit.Interval：ratelimit のログ数のカウントをリセットするまでの時間 (秒単位)。デフォルト：600 (秒)
　・Ratelimit.Burst：ratelimit によって切り捨てられないログ数。この設定値を超える数のログが切り捨てられる。デフォルト：20000 (個)

つまり、何も設定していなければ 600秒 (=10分) で 20000個を超えるログがあった場合にのみ、件のログを見ることになります。そう簡単に出るログではないことがわかってもらえるかと思います。

この RateLimit の設定を変える場合、例えば 60秒以内に 10000個以上のログがあった場合に切り捨てる、という設定にするのであれば、先述の設定箇所を以下のように書き換えれば OK です。
“#” 以降の部分は設定として扱われないコメント (メモ書きのようなもの) なので、消しても消さなくても問題ありません。

module(load="imjournal"
       StateFile="imjournal.state"
       Ratelimit.Interval="60"
       Ratelimit.Burst="10000")

設定の変更後は、rsyslog を再起動することで設定を反映することができます。

$ sudo systemctl restart rsyslog

■検証：無理やりこのログを出してみる

では試しにこのログが消失する現象と、件のログの出力を確認してみます。
今回の記事の検証は、デフォルトで systemd + rsyslog でのロギング環境を提供している、Red Hat Enterprise Linux 9 を使用しています。
この手順ではログが消失しやすくなる設定をして大量の無意味なログを生成するため、試してみるなら必ず検証用の環境を用意してやってみてください。

設定を変えていく前に……今回は以下のようなコマンドで大量のログを生成して、検証してみます。

$ seq 1 2000 | logger

上記の例では 1 ～ 2000 の数字だけのログがそれぞれ記録されますので、2000個のログを生成することができます。
デフォルトの設定であれば、このコマンド実行後に /var/log/messages の末尾のほうを確認するときちんと “2000” のログまで記録されていることが確認できるはずです。

[ ~]$ sudo tail -n10 /var/log/messages
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1991
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1992
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1993
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1994
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1995
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1996
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1997
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1998
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 1999
Aug 30 01:53:49 ip-172-31-23-112 user1[1478]: 2000
[ ~]$

では、設定を変えてみましょう。
設定ファイル /etc/rsyslog.conf を開き、”module(load=”imjournal” ” で始まる設定箇所を以下のように書き換えます。

module(load="imjournal"
       StateFile="imjournal.state"
       Ratelimit.Interval="60"
       Ratelimit.Burst="1000")

この例では 60秒で 1000個までしか、rsyslog はログを書き出さないようにしています。
設定を変更したら、rsyslog を再起動して設定を反映させます。

$ sudo systemctl restart rsyslog

これで準備は完了です。もう一度、先のコマンドで 2000個のログを生成してみましょう。

$ seq 1 2000 | logger

コマンド実行後に再度 /var/log/messages の末尾付近を確認してみると、今度は 1000 弱のところでログがなくなっていることが確認できるかと思います。
※ Ratelimit.Burst のカウントは、imjournal で書き込まれる全てのログがカウント対象になります。当然、この操作以外のシステムのログもカウントに含まれるため、このコマンドによるログが何番まで書き込まれているかは、実行するごとに変わります。

[ ~]$ sudo tail -n10 /var/log/messages
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 987
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 988
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 989
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 990
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 991
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 992
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 993
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 994
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 995
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 996
[ ~]$

60秒間で 1000個までしかログを記録しないように設定したので、期待したとおりですね。

更に、”Ratelimit.Interval” に設定した 60秒以上が経過した後に /var/log/messages を再確認してみると、何らかの新しいログの付近に件のログが確認できるはずです。

[ ~]$ sudo tail -n10 /var/log/messages
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 989
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 990
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 991
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 992
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 993
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 994
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 995
Aug 30 02:23:05 ip-172-31-23-112 user1[1625]: 996
Aug 30 02:23:30 ip-172-31-23-112 NetworkManager[626]:   [1693362210.2544] dhcp6 (eth0): state changed new lease, address=XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX
Aug 30 02:23:30 ip-172-31-23-112 rsyslogd[1494]: imjournal: 1009 messages lost due to rate-limiting (1000 allowed within 60 seconds)

なお、この “imjournal” のログ消失はあくまで journald のログを読み込んでログファイルに記録している rsyslog 側の動作であるため、元となっている journald のログが消失しているわけではありません。
そのため、journald のログを確認してみると、先ほどのログ消失を確認した時間帯の分も 2000番目までのログがきちんと記録されていることが確認できます。

[ ~]$ sudo journalctl -o short-full --no-pager --no-hostname -n 10
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1992
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1993
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1994
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1995
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1996
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1997
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1998
Wed 2023-08-30 02:23:05 UTC user1[1625]: 1999
Wed 2023-08-30 02:23:05 UTC user1[1625]: 2000
Wed 2023-08-30 02:23:05 UTC rsyslogd[1494]: imjournal from : begin to drop messages due to rate-limiting

■最後に

今回は rsyslog のログ消失と RateLimit 機能についてお話ししました。

なお、今回の設定方法や確認手順、制限に引っかかった場合のログ内容などは モジュール “imjournal” を使用している場合のものです。
別のモジュールを使用する場合は設定箇所や設定項目が異なるので、気を付けてください。
例えば、モジュール “imuxsock” を使用する場合は、そのモジュールの設定箇所に “SysSock.RateLimit.Interval” や “SysSock.RateLimit.Burst” を設定します。
(その他のモジュールの場合については、rsyslog のドキュメントなどを参照してください。)

このログを見ること、ログの消失が起こることは稀かと思いますが、
実際に発生してしまった場合にはただ「ログ記録をよりたくさんできるようにしたから大丈夫！！」とは考えず、その多量に出ているログは正当・妥当なものなのか、そもそも何か異常が発生していないかなども必ず確認するようにしましょう。