その日のログはもう消えていた

一言でいうと

保存は勘ではなく、計算です。何日分が実際に残っているかは、ファイル名ではなく内容で測り、何日分を残すべきかは、圧縮率を実測して、ディスクのバジェットと突き合わせて決める必要があります。

なぜ必要なのか

調査の初日に最もよくぶつかる壁は、難しい質問ではなく、空のディレクトリです。「3週間前のその時刻のログを送ってください」と言ったのに、残っているのが5日分だけという状況。このとき必要なのは、嘆きではなく、3つの数字です。何日足りなかったか、あと何日分残すべきか、その値がディスクのバジェットに合うか。

そして、この3つの数字は、すべて今あるファイルから測れます。1日分の原本サイズと圧縮ファイルのサイズを測れば圧縮率が出て、圧縮率と1日分があれば、N日分のバイト数が出ます。バジェットがわかれば、Nの上限が出ます。ここに、推測は1か所もありません。

どう動くのか

ローテーションは、名前のルールが2種類あります。logrotate(8)のデフォルトは番号を付ける方式で、このときは数字が大きいほど古いものです(app.log.1よりapp.log.2のほうが過去です)。dateextを有効にすると、代わりに日付が付き、デフォルトの形式は-%Y%m%dで、このときは名前が小さいほど古いものです。1台のサーバーで2つのルールが混ざっていることも、珍しくありません。olddirに移しておいた古いファイルだけが、日付の名前という場合です。そのため、「ファイルを時間順に並べること」が、調査の実際の最初のステップになります。

rotateは、現在のファイルを除いた個数です。マニュアルは、rotate countを「削除されるまでにローテーションされる回数」と定義し、countが0なら、ローテーションせずにすぐ削除すると書いています。つまり、30日分を残したいなら、daily + rotate 29です。ここで、1つずれるミスがよくあります。

delaycompressは、圧縮を1周期遅らせます。マニュアルは、このオプションの目的をはっきり書いています。ログファイルを閉じるよう指示できないプログラムが、以前のファイルにしばらく書き込み続けることがあるからです。そのため、直近の2日分は圧縮されないままで、容量の計算でも、その2日分は原本のサイズで見積もる必要があります。

copytruncateは、行を失います。同じマニュアルが明記しています。コピーしたあと、原本を0に空にしますが、その2つの間にごく短い隙間があり、その間に書かれたログは消える可能性があります。再起動やシグナルを受けてファイルを開き直せないプログラムのための最後の手段であり、デフォルトとして使うものではありません。

systemdを使うなら、バジェットはまた別の場所にあります。journald.conf(5)のSystemMaxUse=は、デフォルトがファイルシステムの10パーセントですが、4Gで頭打ちになります。SystemMaxFiles=はデフォルトが100、MaxRetentionSec=はデフォルトが0、つまり時間基準の削除はオフです。容量だけで押し出されるので、トラフィックが増えると、保存期間が黙って短くなります。

現場での姿

保管を延ばしても、残らないものがあります。journaldのRateLimitIntervalSec=とRateLimitBurst=は、1つのサービスが決められた区間の中で、決められた数より多く出力すると、その区間の残りを捨てます。デフォルトは30秒に10000件で、サービスごとに適用され、捨てた数を知らせるメッセージが残ります。マニュアルは、ここにもう1つ書いています。実効上限は、journalに残っている空きディスク容量に応じて掛け算されます(底が2の対数で計算した倍数)。つまり、ディスクが埋まっているほど、より早く捨てます。障害でログが急増するまさにその瞬間に、最も多く捨てられる仕組みです。

そのため、事故の区間のログが「ない」には、2つの意味があります。ローテーションで消えたか、そもそも記録されなかったか。2つは対策がまったく違います。前者は保存を延ばせばよく、後者は、レベルを下げるか、上限を上げるか、そのサービスのログを別に分ける必要があります。

圧縮率は、データごとに違います。似た行が繰り返されるアクセスログは、10分の1以下に縮みますが、スタックトレースやJSONの本文が混ざると、はるかに縮みません。そのため、「普通は10倍」のような目分量を使わず、その顧客のファイルで測ってください。測るのに1分かかり、目分量で見積もってディスクが埋まると、ログではなくサービスが止まります。

容量の計算で最もよく抜けるのが、圧縮されていない日です。delaycompressを使うと、現在のファイルと前日のファイルの2つが、原本のサイズでディスクにあります。圧縮ファイルのサイズだけで掛け算すると、その2つの分がバジェットから抜けますが、よりによって圧縮率が良いほど、この誤差が相対的に大きくなります。1日分の原本が200MBで圧縮ファイルが30MBなら、2日分の差だけで340MBで、30日分のバジェットの3分の1になることもある値です。

そして、バジェットは、ログだけが使うものではありません。同じファイルシステムに、コアダンプ、監査ログ、コンテナランタイムのログが一緒に溜まります。journaldのSystemKeepFree=が、デフォルトで15パーセントを空けておこうとする理由もそれで、マニュアルは、2つの上限のうち小さいほうが適用されると書いています。そのため、ローテーションのポリシーを決めるときは、「ログにいくら割り当てられるか」を先に合意し、その数字の中で日数を計算する必要があります。順序を逆にすると、必要な日数を先に決めておいて、ディスクが埋まるのを待つことになります。

次のラボですること

ローテーション済みファイルが2種類の名前ルールで混ざっている保管状態を作り、それを古いものから並べます。そのあと、ファイルごとに実際に含まれる区間を内容で測って、事故の区間が範囲外であることを数字で明らかにします。圧縮率を実測して、30日分のバイト数とバジェットの中で可能な最大日数を計算し、その値でlogrotateの設定を書きます。最後に、レート制限の設定で捨てられる行数を数えて、保存を延ばすだけでは防げない損失があることを示します。