logbackで任意の分刻みでローテートさせる

logbackで5分,10分,...といった任意の単位でローテートさせる実装メモ。

検索するとAppenderのrolloverメソッドをカスタマイズする方法は出てくるけど、なんだか微妙な感じだったので、よりコアなところでちゃんと制御させる方向で

前提等

私の環境

logbackのバージョン: 1.2.3
言語: Scala

私が仕事で使ってるのがScala + PlayFrameworkなので、それで使う用です。
Javaのほうが需要あるかもしれんけど、まあだいたい同じなので上手く読み替えていただけると。

要件

• 1分だと微妙に細かすぎる
• 1時間だとでかくなりすぎる
• ファイルサイズじゃなくてちゃんと時間でローテートさせたい
• できれば、アプリケーション起動からの相対時間ではなく絶対時間でローテートさせたい

もとのlogback.xml

  <!-- appender部分抜粋 -->
  <appender name="Hoge" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>/var/log/application.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>/var/log/application-%d{yyyyMMddHHmm}.log</fileNamePattern>
    </rollingPolicy>
    <encoder>
      <charset>UTF-8</charset>
      <pattern>%date|%level|%message%n</pattern>
    </encoder>
  </appender>

TriggeringPoilicyを作成する

TimeBasedRollingPolicyはとくに指定しない限りDefaultTimeBasedFileNamingAndTriggeringPolicyというのが使われる。
これを継承したクラスを作成する。

• logback.xmlで設定できる値として、periodMinutes(ローテート間隔分)及びそのgetter,setterを定義。
• computeNextCheck()メソッドをオーバーライド。(ロールオーバー発生のトリガーかどうかのチェックに使用される、次回のロールオーバー時刻を計算するメソッド)

一旦、相対時間でローテートするやつを作成。

PeriodMinutesBasedFNATP.scala

package hoge

import java.util.Calendar

import ch.qos.logback.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy

class PeriodMinutesBasedFNATP[E] extends DefaultTimeBasedFileNamingAndTriggeringPolicy[E] {

  protected var periodMinutes: Int = 1 // ローテート間隔

  def getPeriodMinutes: Int = this.periodMinutes

  def setPeriodMinutes(minutes: Int): Unit = {
    if (minutes > 0) {
      this.periodMinutes = minutes
    }
  }

  override def computeNextCheck(): Unit = {
    // rcはローテートに使用されるRollingCalendar
    // 現在時刻+n分を過ぎたら次のロールオーバーが発生するように設定
    rc.setTime(dateInCurrentPeriod)
    rc.set(Calendar.SECOND, 0)
    rc.set(Calendar.MILLISECOND, 0)
    rc.add(Calendar.MINUTE, periodMinutes)

    nextCheck = rc.getTime.getTime  // nextCheckに次回ロールオーバー時刻をセット
  }

  override def toString: String = "hote.PeriodMinutesBasedFNATP"
}

これをさらに継承して、絶対時間でローテートするやつを作成。

• setDateInCurrentPeriodをオーバーライドしてファイル名に使用されたりする日時dateInCurrentPeriodフィールドをセットする。
  • アプリケーションの停止・起動で前回出力中だったログファイルに続けて出力するような場合、起動時にファイルの更新時刻をもとにローテート判定されるが、その際に呼ばれるのがsetDateInCurrentPeriod(Date)のほう。

AbsolutePeriodMinutesBasedFNATP.scala

package hoge

import java.util.Date

class AbsolutePeriodMinutesBasedFNATP[E] extends PeriodMinutesBasedFNATP[E] {

  override def setPeriodMinutes(minutes: Int): Unit = {
    if (minutes > 0 && 60 % minutes == 0) { // 一応、60分を割り切れる値しか設定できないようにしておく。
      this.periodMinutes = minutes
    }
  }

  private def roundTimestamp(time: Long) = {
    val periodTicks = periodMinutes * 60000 // 1分は60000ミリ秒
    periodTicks * (time / periodTicks) // 整数型の割り算で雑に切り捨て
  }

  override def setDateInCurrentPeriod(now: Long): Unit = {
    dateInCurrentPeriod.setTime(roundTimestamp(now))
  }

  override def setDateInCurrentPeriod(_dateInCurrentPeriod: Date): Unit = {
    dateInCurrentPeriod = new Date(roundTimestamp(_dateInCurrentPeriod.getTime))
  }

  override def toString: String = "models.log.AbsolutePeriodMinutesBasedFNATP"
}

失敗メモ

↓のドキュメント見ると、これでrollingPolicyの設定を以下のようにしたらいけるかな？と思ってやってみたけど上手くいかなかった。。。
http://logback.qos.ch/manual/appenders_ja.html#SizeAndTimeBasedFNATP

ダメだったlogback.xml

    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>/var/log/application-%d{yyyyMMddHHmm}.log</fileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy class="hoge.PeriodMinutesBasedFNATP">
        <periodMinutes>5</periodMinutes>
      </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>

なのでまだ続く。

RollingPolicyを作成する

自作したTriggeeringPoilicyを使用するためにRollingPolicyも作成。

• logback.xmlで設定できる値として、triggeringPolicyType(さっき作った2つのTriggeringPolicyのどっちを使うか)を定義。

PeriodMinutesBasedRollingPolicy.scala

package hoge

import ch.qos.logback.core.rolling.TimeBasedRollingPolicy

class PeriodMinutesBasedRollingPolicy[E] extends TimeBasedRollingPolicy[E]{
  private var periodMinutes: Int = _
  private var triggeringPolicyType: String = _

  def getPeriodMinutes: Int = this.periodMinutes

  def setPeriodMinutes(minutes: Int): Unit = {
    this.periodMinutes = minutes
  }

  def getTriggeringPolicyType: String = this.triggeringPolicyType

  def setTriggeringPolicyType(policyType: String): Unit = {
    this.triggeringPolicyType = policyType
  }

  override def start(): Unit = {
    val triggeringPolicy = if (triggeringPolicyType == "absolute") new AbsolutePeriodMinutesBasedFNATP[E] 
      else new PeriodMinutesBasedFNATP[E]
    triggeringPolicy.setPeriodMinutes(periodMinutes)
    setTimeBasedFileNamingAndTriggeringPolicy(triggeringPolicy)

    super.start()
  }

  override def toString: String = "hoge.PeriodTimeBasedRollingPolicy"
}

lobgack.xml

最後にlogback.xmlにはこんな感じに書いてやると、いいかんじに5分毎に出力されるようになりました。

lobgack.xml

  <!-- appender部分抜粋 -->
  <appender name="Hoge" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>/var/log/application.log</file>
    <rollingPolicy class="hoge.PeriodTimeBasedRollingPolicy">
      <periodMinutes>5</periodMinutes>
      <triggeringPolicyType>absolute</triggeringPolicyType>
      <fileNamePattern>/var/log/application-%d{yyyyMMddHHmm}.log</fileNamePattern>
    </rollingPolicy>
    <encoder>
      <charset>UTF-8</charset>
      <pattern>%date|%level|%message%n</pattern>
    </encoder>
  </appender>

例えばファイル名がapplication-201910011200.logのファイルに2019-10-01 12:00:00～2019-10-01 12:04:59の出力分が入る感じになります。

ちなみにplayframeworkのデバッグ(sbt run)だとクラスローダーの関係で使えないので、本番モード専用です。

---

長ったらしくなってしまった。。。
Qiita初めて投稿なので拙文お許しください(TдT)

もっといい方法あればコメントよろしくおねがいします！！