CentOS7(RHEL7)でメールログが正常に出なかったときの対応

CentOS7で構築されたシステムでメルマガ配信などを行った際に、Posrfixのメールログ(/var/log/maillog)が
送信件数と比較して異常に少なかったので、その時の対応方法をメモしておきます。

CentOS7のメールログの出力の仕組み

CentOS7からログの出力はsystemd-journald.service(Journald)で管理されている。
Journaldからrsyslogがログを抜き取って、見慣れた/var/log/maillogを生成していました。
※説明はこちらが分かりやすいかもしれません
Linux女子部　systemd徹底入門

出力制限のログを確認

下記のようなログが出力されていたら、制限に引っかかってログが捨てられています。

Oct 13 19:15:35 moge journal: Suppressed 8385 messages from /system.slice/postfix.service

実際にjournalctlコマンドでpostfixのログを見ても制限された非常に少ないログ件数しかありませんでした。

Journaldの出力制限

journald.confのmanページに記載がある通り、10秒間で200以上のメッセージ出力が発生すると制限がかかります。
サービス毎の制限みたいなので、他のログ出力は妨げられることはないそうです。

[hoge@moge ~]$ man journald.conf
       RateLimitInterval=, RateLimitBurst=
           Configures the rate limiting that is applied to all messages generated on the system. If, in
           the time interval defined by RateLimitInterval=, more messages than specified in
           RateLimitBurst= are logged by a service, all further messages within the interval are
           dropped until the interval is over. A message about the number of dropped messages is
           generated. This rate limiting is applied per-service, so that two services which log do not
           interfere with each other's limits. Defaults to 200 messages in 10s. The time specification
           for RateLimitInterval= may be specified in the following units: "s", "min", "h", "ms", "us".
           To turn off any kind of rate limiting, set either value to 0.

journaldの出力制限を緩和

出力したいメールの出力件数と時間から超えない程度に大きな値を設定して様子をみることにしました。
メールの件数だけを考慮すればいいので予測は立てやすいかと。

RateLimitInterval=10s
RateLimitBurst=20000

注意
メールログなどはメール1通で5～6メッセージ出力されるので計算を間違えないように注意が必要です。

journaldの出力は正常に出力されるようになった

journalctlコマンドでの出力結果は正常に出力されるようになったことが確認できました。

sudo journalctl -u postfix --no-pager | wc -l

ただ、まだメールログは正常に出力されていません！！
案の定、今度は下記のようなメッセージが捨てられた旨のログが出力されていました。

Oct 14 16:16:40 moge rsyslogd-2177: imjournal: begin to drop messages due to rate-limiting
Oct 14 16:17:18 moge rsyslogd-2177: imjournal: 108443 messages lost due to rate-limiting

rsyslogの出力制限

rsyslogがjournalからのログを受け取って出力するモジュールにも出力制限がありました。

seconds では、レート制限の間隔を設定します。この間隔内に処理されるメッセージ数は、burst_number で指定して値を超えることはでき ません。デフォルト設定は、600 秒あたり 20,000 メッセージです。Rsyslog は、この指定された時間枠内で最大バースト後に届いたメッセージを破棄します。

※詳細はこちら
サポート -> 製品マニュアル -> Red Hat Enterprise Linux -> 7 -> システム管理者のガイド - 18.6. RSYSLOG での構造化ロギング

rsyslogの出力制限の緩和

出力したいメールの出力件数と時間から超えない程度に大きな値を設定して様子をみることにしました。
この設定はメールだけじゃなく他のログ出力（/var/log/messages等）の件数も考慮する必要があるので
制限をかけるならかなり大きくする必要があります。

$imjournalRatelimitInterval 600
$imjournalRatelimitBurst    2400000

注意
下記の設定はjournalを経由しない方式でログを出力する場合の設定なので間違えないように

$SystemLogRateLimitInterval
$SystemLogRateLimitBurst

rsyslogの出力も正常に出力されるようになった

これで/var/log/maillogに正常な件数のログが出力されるようになりました。

最後に

実は出力されていなかったってパターンは、世の中的に結構ありそうな気がします。
/var/log/messages に制限に引っかかったログが出ていないかチェックしてみてはいかがでしょうか。

参考リンク

JOURNAL: SUPPRESSED MESSAGES FROM /SYSTEM.SLICE/POSTFIX.SERVICE
Linux女子部　systemd徹底入門
サポート -> 製品マニュアル -> Red Hat Enterprise Linux -> 7 -> システム管理者のガイド - 18.6. RSYSLOG での構造化ロギング

追記

2015/12/10

実は上記の設定値では、一部正常に動作していなかったことが発覚しました。
こちらを踏まえて計算すると
$imjournalRatelimitBurst 2400000 -> 40704
として動作していたと考えられます。