ログローテーション時の新ファイルへの出力先更新について

Question

実現したいこと

・ログローテーションが実行され、ログファイルの出力先が更新されなかった理由を知りたい。
・logrotateコマンドにてログローテーションがされる際に、どのタイミングでどのプロセスがファイルinodeを更新するのかを知りたい。
・HUPシグナルを発報する設定がないにもかかわらず、なぜログの出力先が更新されたのかを知りたい。

前提

・snmptrapを受信するサーバにおいて、snmptrap.logを日次でローテーションしている。
・snmptrap.logの出力先は/etc/rsyslog.confにて/var/log/snmptrap.logに出力するように設定している。
・ログローテーションは毎日00:00にcronにて「/usr/sbin/logrotate -f /etc/logrotate.d/snmptrap」で実行している。
・「/etc/logrotate.d/snmptrap」の内容は下記のとおり。
/var/log/snmptrap.log{
daily
rotate 15
notifempty
missingok
create 0664 root root
}

発生している問題・エラーメッセージ

ある日、ログが古いファイル(snmptrap.log.1)に書き込まれているという事象が発生した。
※事象自体はOS再起動にて解消し、その後は通常通りにログローテーションをしている。

試したこと

・検証環境にて、snmptrapを10件/秒を受信、10秒ごとに200世代ログローテーションする検証を行ったが、事象を再現できなかった。
・logrotate、rsyslog、snmptrapに関する設定ファイルを確認したが、HUPシグナルを発報するような設定は見当たらなかった。

補足情報（FW/ツールのバージョンなど）

自身で調査したところ、ログローテーションはログを出力しているプロセスにHUPシグナルを投げないとログの出力先(inode)が更新されず、
古いファイルにログが出力されるとの記載があった。しかし、上記に記載したとおり、ログローテーションの設定にHUPシグナルに関する記述はない。

============================================================

事象自体はOS再起動で解消したのですが、根本原因が不明な状況となっております。
知見をお持ちの方がいらっしゃれば、ご教授願いたく思います。

Comments

[melian]

> logrotate、rsyslog、snmptrapに関する設定ファイルを確認したが、HUPシグナルを発報するような設定は見当たらなかった。

ディストリビューションが異なるかもしれませんが、手元の Ubuntu 23.04 では、/etc/logrotate.d/rsyslogd に postrotate が指定されています。

postrotate
/usr/lib/rsyslog/rsyslog-rotate
endscript

この /usr/lib/rsyslog/rsyslog-rotate の中身は以下の通りです。

#!/bin/sh

if [ -d /run/systemd/system ]; then
systemctl kill -s HUP rsyslog.service
fi

Ubuntu での設定では毎週日曜日の午前6時47分に /var/log/ 以下の特定のログファイル(/var/log/syslog, /var/log/mail.log, /var/log/cron.log, etc.)に対してログローテートが行われていて、その際に rsyslogd に SIGHUP が送られています。

[FRISKER]

melian様　コメントありがとうございます。

今回のSNMPTrap受信サーバにつきましては、構築担当がログローテーション周りをOSデフォルトから変更しております。構築時になぜこのような設定になったのかということは不明です。おそらく、設定・テストして問題なくローテーションされたからOKとなったのでしょうが。。。

ちなみに、snmptrap.logと同じ時間帯にログローテーションする、シスログ等のいくつかのログにつきましては、上記に記載のあるようなHUPの記述はありました。それがあるからsnmptrap.logも影響を受けてファイルのinodeが更新されたのか？とも考えております。

[melian]

既にご存知かもしれませんが、rsyslogd(8) には、

SIGNALS
　　HUP This lets rsyslogd perform close all open files.

と書かれています。同じ時間帯にログローテーションする処理で rsyslogd に SIGHUP が送られて、その後に snmptrap.log がローテートされる場合には snmptrap.log.1 にログが出力され続けることになります。

[FRISKER]

melian様　コメントありがとうございます。

上記については確認できておりませんでした。
snmptrap.logでHUPがなくても他のログローテーションで記載があればsnmptrap.logのinodeも更新がかかるのですね。
つまり、ローテーションの際にsnmptrap.logのローテーション始まる前に他のログファイルのローテーションでHUPが発報されてsnmptrap.logのinodeが更新されずに今回の障害が発生したと考えることが出来そうです。

Answer 1

logroatateには１つのfdをオープンしたままのプログラムに対応するための構文 copytruncateがあります。
これはローテートのタイミングで現在の内容を別ファイルにコピーした後、現在のファイルをtrancate(0バイトに)する方法です。
そのため、コピー→trancateの間にログ出力があるとその部分が欠損する可能性がありますがこれが使えるか試してみてはいかがでしょうか。

Comments

[FRISKER]

hqf00342様

コメントありがとうございます。

copytruncateについての知識がなかったので、少し調べてみたのですが、
ログが欠損する可能性があるとの記事を見つけました。

https://rooter.jp/data-format/omission_of_logrotate_copytruncate/

create方式では、古いファイルにログが出力される可能性はあるものの、
ログの欠損がない認識なので、ログが欠損する可能性のあるcopytruncateは採用できないかと思います。

Answer 2

logrotateは、prerotateやpostrotateでコマンドを実行することを除けばファイルをリネームして新規作成するだけです。

Unix/Linuxの場合は、稼働中のプロセスがaaa.logをオープンしたままでログを書いている時にmv aaa.log aaa.log.1; touch aaa.logをした場合、プロセスはファイルの名前が変わったことなど無関係なので、そのまま最初にオープンしたファイル（現在はaaa.log.1という名前に変わっている）に書き続けます。
ファイル名はオープンの時に必要なだけで、オープンしたら無用で、mvやrmしてもプログラム動作に無関係です。

稼働中のプロセスがオープンしたままの古いログファイルをクローズして、新規作成されたファイルをオープンし直すのは、稼働中のプロセスにその旨指示する必要があります。デーモンプロセスはSIGHUPを未使用(※1)なので、「SIGHUPを受け取るとファイルをオープンし直す」という仕様のデーモンプロセスが多いようですので、そういうプロセスの場合は、postrotateでSIGHUPを送るコマンドを実行します。
（※1: SIGHUPは制御端末に関するシグナルだが、デーモンは制御端末を持たないので本来のSIGHUPを受け取ることは無い）

「HUPを送る」とかは、「ログファイルをオープンしっぱなしのデーモンプロセスは、上記のような仕様のことが多い」という以上の意味は無いので、そういう仕様かどうか確認すること無しにHUPを送っても無駄かも知れません。

そういう「外部からの指示でファイルをオープンし直す」機能を持たないプログラムの場合は、HUPを送ってもしょうがないので、ログファイルをオープンし直すには、postrotateでプログラムの停止＆再起動などが必要です。

こういう「ログファイルをオープンしっぱなしで書く方式」じゃなくて、「ログを書く都度、オープン、書き込み、クローズ」を繰り返している場合（オーバーヘッドが大きいので普通はしないが、大量にログを書くことが絶対にあり得ないプログラムならあるかも）は、オープン時点でaaa.logと言う名前のファイルに書きますので、HUPを送ったり再起動しなくてよいわけです。

デーモンによっては他にも「HUPを受けると、設定ファイルを読み直す機能」があったりします。これも、そういう仕様のプログラムかどうかを確認する必要があります。

Comments

[FRISKER]

otn様　コメントありがとうございます。

上記内容から、今回ファイルに書き込みを行っているrsyslogdの仕様を確認する必要があると理解いたしました。
いただいた情報から再度調査を行いたいと思います。

[otn]

rsyslogdはSIGHUPでファイルのオープンし直しをするので、
> そういうプロセスの場合は、postrotateでSIGHUPを送るコマンドを実行します。
でいいです。