このエントリーは、GMOアドマーケティング Advent Calendar 2018
（https://qiita.com/advent-calendar/2018/gmo-am）の【12/24】の記事です。
GMOアドマーケティングとしては初のAdvent Calendar参戦です。

はじめに

はじめまして、2017年3月にインフラエンジニアになりました@sandatsです。

インフラエンジニアになって様々な事件(障害)に遭遇したので、それを書きたかったのですがあまりに多かったので、今日はその中で最近起きたNginxのlogrotateの設定を誤って、アクセスログが消失した話を記したいと思います。

TL;DR

logrotateのpostrotateとNginxのログ書き込み動作を把握しておらず、ローテートする瞬間のログが一部消失していた。

詳しく

一部のプロダクトで、Nginxのログを整形し集計ログとして扱っていました。

ログの書き込み先は以下の通り。

Nginxログ : /var/log/nginx
logrotateで整形されたログ出力先 : /var/log/nginx/preformatted

ログの整形は、logrotate内のprerotateでシェル芸を駆使して行うという奇想天外な手法で行っていました。
(同じ方法使っている人が居たらごめんなさい)

logrotate設定内容

/var/log/nginx/*.access.log
{
    create 0644 hoge hoge
    missingok
    hourly
    rotate 24
    nocompress
    dateext
    dateformat -%Y%m%d%H
    sharedscripts
    prerotate
        for filename in $1; do
            cat $filename | sed 's/\\x22/"/g' | sed 's/-}$/{}}/g' | gzip -c > /var/log/nginx/preformatted/`basename $filename`-`date -d '1 hour ago' '+%Y%m%d%H'`.gz
        done
    endscript
    postrotate
        [ ! -f /var/run/nginx.pid ] || kill -USR1 `cat /var/run/nginx.pid`
        for filename in $1; do
            cat $filename-`date '+%Y%m%d%H'` | gzip -c > $filename-`date '+%Y%m%d%H' -d '1 hour ago'`.gz
        done
    endscript
}

あれれ〜おかしいゾ〜？

既に一部の方はお気付きかと思いますが、 prerotate内でログを整形し、postrotateでNginxのログを再読み込みした事により、アクセスログの一部が消失してしまっているのである。

図解すると下記感じになります。

1. prerotateの実行

時間を跨ぐと、/etc/logrotate.hourly/nginx がキックされ、preroteが実行される。

2. postrotateの実行

postrotate内でログを圧縮します。(何故かloglotate設定内のcompressで行っていませんでした。

3. ログが消える

＿人人人人人人人人人＿
＞　突然のログ消失　＜
￣Y^Y^Y^Y^Y^Y^Y^Y￣

突然でもなんでもないですが、prerotateが実施された後に書き込まれたアクセスログは、整形後のアクセスログ内には書き込まれていませんでした。

その後

prerotate→postrotate、postrotate→lastactionへ修正し、ログの欠損は無くなりました。

そもそもどうやって気づいたのか

Nginxのupstream先でJAVAアプリケーションが動作し、そのアプリケーションが出すログと比較した結果、差異があり発覚しました。

反省点

ログローテート設定のレビュー
- 整形後のログが正しく出力されていたので、そこで問題ないと思ってしまっていた
実稼働後のログチェック
- トラフィックが徐々に増え、差異が大きくなりようやく気付いた。
- そもそもlogrotateのpostrotateで何が起こっているのかしっかり把握していればこんな事にはならなかったはず…

最後に

こんな事件もありましたが、なんとか元気にインフラやってます。
他にも様々な事件があったので、自分への戒めという意味も込めてお伝えできたらなあと思います！

明日はいよいよカレンダーも最終日！ @dandasoさんのお話です。
GMOアドマーケティング Advent Calendar 2018 最終日の投稿もお楽しみに！

■エンジニアによるTechblog公開中！
https://techblog.gmo-ap.jp/
■Wantedlyページ　～ブログや求人を公開中！～
https://www.wantedly.com/projects/199431
■エンジニア採用ページ　～福利厚生や各種制度のご案内はこちら～
https://www.gmo-ap.jp/engineer/
■エンジニア学生インターン募集中！　～有償型インターンで開発現場を体験しよう～
https://hrmos.co/pages/gmo-ap/jobs/0000027

聖なる夜に贈るインフラ事件簿〜Nginxアクセスログをlogrotateで欠損させてしまった話〜