はじめに

この記事はHamee Advent Calendar 2020 16日目の記事です。
初のアドカレ参加ですね、めっちゃ緊張してます（嘘）

log4j 2 って？

公式より

Apache Log4j 2 is an upgrade to Log4j that provides significant improvements over its predecessor, Log4j 1.x, and provides many of the improvements available in Logback while fixing some inherent problems in Logback’s architecture.

log4j を改良したやつだよ。
Logback の構造を引き継いだことによる弊害もいい感じに解消してるよ。

とのこと。
　

いやそもそも log4j はなんなんだよ？という方に１行で解説すると、
log4j は、Java 用のロガーAPIです。

じゃあ、ログローテートって？

ログローテーションとも言いますね。

どんなシステムでもログを出力するってことはしてると思いますが、出力される量は時間を追うごとに増えストレージを食い荒らすことになります。
それじゃまずいので、ある一定の期間を過ぎたログを自動的に削除したり、ログのサイズがある一定量に達したら古いものを削除したりすることが必要です。

これがログローテートです。

設定してみる

まずはロガーを定義するために、log4j2.xml を以下のように書きます。

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="OFF">
    <Properties>
        <Property name="standard">[%d{yyyy/MM/dd HH:mm:ss.SSS}] %m%n</Property>
        <Property name="log_path">logs</Property>
        <Property name="log_filename">app</Property>
    </Properties>
    <Appenders>
        <RollingFile name="app" fileName="${log_path}/${log_filename}.log" filePattern="${log_path}/${log_filename}.%d{yyyy-MM-dd}.log.gz">
            <PatternLayout pattern="[%d{yyyy.MM.dd HH:mm:ss.SSS}] %p - %m%n" />
            <TimeBasedTriggeringPolicy />
            <DefaultRolloverStrategy>
                <Delete basePath="${log_path}" maxDepth="1">
                    <IfFileName glob="${log_filename}*.log.gz" />
                    <IfLastModified age="7d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Root name="app_logger" level="info">
            <AppenderRef ref="app" />
        </Root>
    </Loggers>
</Configuration>

　
ちょいちょいと設定をかいつまんで説明します。

<Properties>

<Properties>
    <Property name="standard">[%d{yyyy/MM/dd HH:mm:ss.SSS}] %m%n</Property>
    <Property name="log_path">logs</Property>
    <Property name="log_filename">app</Property>
</Properties>

log4j2.xml 内で定数を利用したい時に使えるタグ。
例えば、上記の設定なら<Property name="standard">で囲まれた書式を${standard}と書くことで一発で利用できる。

つまるところ、この設定が

 <RollingFile name="app" fileName="${log_path}/${log_filename}.log" filePattern="${log_path}/${log_filename}.%d{yyyy-MM-dd}.log.gz">

　
こんな風に変換されるわけですね。

 <RollingFile name="app" fileName="logs/app.log" filePattern="logs/app.%d{yyyy-MM-dd}.log.gz">

<Loggers>

<Loggers>
    <Root name="app_logger" level="info">
        <AppenderRef ref="app" />
    </Root>
</Loggers>

ここにロガーの定義を書いていく。
<Root>はデフォルトで利用するロガーを定義するが、今回は1つしかないのでこれでOK。
ref="app"は、<Appenders>で定義されてるname="app"のやつから出力を受け取りますよ、的な意味合い。

これでログを出力するインターフェース（と勝手に思っている）を定義できた。

<RollingFile>

<Appenders>
    <RollingFile name="app" fileName="${log_path}/${log_filename}.log" filePattern="${log_path}/${log_filename}.%d{yyyy-MM-dd}.log.gz">
        <PatternLayout pattern="[%d{yyyy.MM.dd HH:mm:ss.SSS}] %p - %m%n" />
            <TimeBasedTriggeringPolicy />
            <DefaultRolloverStrategy>
            <Delete basePath="${log_path}" maxDepth="1">
                <IfFileName glob="${log_filename}*.log.gz" />
                <IfLastModified age="7d" />
            </Delete>
        </DefaultRolloverStrategy>
    </RollingFile>
</Appenders>

<Appenders>に実際にログとして出力するフォーマットなどを定義していく。
<RollingFile>がその中の１つ。

詳細は省くが、
ログローテートは日単位で行い、7日より前のログは消す！
みたいな設定をここではしている。

動作チェック

サーバー側でなんやかんやログ出力の動作を追記してデプロイ、日付が変わるのを待つ。
ワクワクしながら ssh して確認すると、アレ？

$ ls -la
drwxr-xr-x 3 tomcat tomcat    4096 12月 12 23:39 .
drwxr-xr-x 3 tomcat tomcat    4096 12月 12 16:44 ..
-rw-r--r-- 1 tomcat tomcat     207 12月 13 00:00 app.log

アレ？

今日の日付を何回確認しても 12/13 ...。
本来ならばログローテートが行われて 12/12 日分のログが残るはずなのにない...。

本来なら↓になってて欲しいのだ。

$ ls -la
drwxr-xr-x 3 tomcat tomcat    4096 12月 12 23:39 .
drwxr-xr-x 3 tomcat tomcat    4096 12月 12 16:44 ..
-rw-r--r-- 1 tomcat tomcat   20507 12月 13 00:00 app.2020-12-12.log
-rw-r--r-- 1 tomcat tomcat     207 12月 13 00:00 app.log

原因解明

（ここではさらっと書くが、本来は1週間くらいかけて直している）

ここでまず、俺の crontab をみて欲しい。

*/10 * * * * sh ./batch1

0 0 1 * * sh ./batch2

cron で定期実行バッチの設定をしているだけである。

一見何の変哲もない設定だが、ここでポイントなのが どちらのバッチも 0:00:00 に実行される ことである。
これが全ての元凶である。

どうやら log4j2 では、

複数プロセスによるログへの同時の書き込み
ログローテートの対象

の2つの条件が満たされた時、正常にログローテートが行われず前日のログが消え去るのである。
（そんなことがあっていいのか...？）

　
batch2 は 0:00:00 の実行でなくても問題ないので、少々時間をずらしてログローテートを試したらちゃんと正常に動作した。

（ちなみにこれを解決するために ScoketAppender というものが存在するらしい？間違ってたらごめんなさい。）

まとめ

フレームワークの仕様とはいえ、ここまでログの出力で悩まされるとは思わなかった。
みなさまも良きログライフを！