疑問メモ: logbackで同一レベルの複数ログを異なる出力先に出したい

Java Tool

（追記） この記事の解決編はこちら。http://d.hatena.ne.jp/torazuka/20120619/logback

logback（http://logback.qos.ch/）でやりたいことができなくて困っているので、ちょっと整理します。

logbackは、Javaのロギングライブラリです。次のログレベルがあります。

  • TRACE
  • DEBUG
  • INFO
  • WARN
  • ERROR

今回やりたいのは、単に、「同一のログレベルだが、意味や用途の異なる複数のログを、それぞれ別の出力先に出す」というもの。

具体的にいうと、出力先は、ファイルとコンソールの2種類です。

作っているのはCUIのプログラムなので、ユーザがコンソールを目にします。ユーザにとって意味のある情報は、ログレベルINFOにまとめてあります。これらは、コンソールに出したいです。

一方、開発のためのDEBUGレベルのログや、WARNレベル以上のログは、ファイルにこっそり出力したいとします。

ロギングライブラリでは、「あるレベル以上のログを出力する」といった設定方法がよくありますが、logbackには、幸いLevelFilterというものがあります。なので、次のような設定ならカンタンにできます。

つまり、こういう設定ならカンタンです。# TRACEは、今回使わないことにしたので、無視しています。

出力先 出す 出さない
コンソール INFO DEBUG, WARN, ERROR
ファイル DEBUG, WARN, ERROR INFO

設定ファイル logback.xml は、こうなります。

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<appender name="FILE" class="ch.qos.logback.core.FileAppender">
		<filter class="ch.qos.logback.classic.filter.LevelFilter">
			<level>INFO</level>
			<onMatch>DENY</onMatch>
			<onMismatch>ACCEPT</onMismatch>
		</filter>
		<File>sample.log</File>
		<Append>true</Append>
		<encoder>
			<pattern>%d %5p %c{1} - %m%n</pattern>
		</encoder>
	</appender>
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<filter class="ch.qos.logback.classic.filter.LevelFilter">
			<level>INFO</level>
			<onMatch>ACCEPT</onMatch>
			<onMismatch>DENY</onMismatch>
		</filter>
		<encoder>
			<Pattern>%msg%n</Pattern>
		</encoder>
	</appender>
	<root level="DEBUG">
		<appender-ref ref="STDOUT" />
 		<appender-ref ref="FILE" />
	</root>
</configuration>


たとえば、こういうJavaプログラムを動かしたら・・・

package xxx.yyy.zzz;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import xxx.yyy.zzz.impl.Foo;

public class Main {

	private static final Logger logger = LoggerFactory.getLogger(Main.class);
	
	public static void main(String[] args) {

		QQQ foo = new Foo("foo");
		logger.info("hello!");
		foo.execute();
		logger.info("bye!");
		
		// for sample
		logger.debug("Main debug hogehoge");
		logger.warn("Main warn hogehoge");
		logger.error("Main error hogehoge");
	}
}

package xxx.yyy.zzz;

public interface QQQ {
	public void execute();
}

package xxx.yyy.zzz.impl;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import xxx.yyy.zzz.QQQ;

public class Foo implements QQQ {

	private final Logger logger = LoggerFactory.getLogger(Foo.class);

	String msg;

	public Foo(String str) {
		msg = str;
	}

	public void execute() {
		logger.debug("Foo#execute done.");
		logger.info("Foo info hogehoge");
		logger.warn("Foo warn hogehoge");
		logger.error("Foo error hogehoge");
	}
}

コンソールの出力結果はこうなります。

hello!
Foo info hogehoge
bye!

ファイルの出力結果はこうなります。

2012-06-17 22:39:26,980 DEBUG x.y.z.i.Foo - Foo#execute done.
2012-06-17 22:39:26,981  WARN x.y.z.i.Foo - Foo warn hogehoge
2012-06-17 22:39:26,982 ERROR x.y.z.i.Foo - Foo error hogehoge
2012-06-17 22:39:26,982 DEBUG x.y.z.Main - Main debug hogehoge
2012-06-17 22:39:26,982  WARN x.y.z.Main - Main warn hogehoge
2012-06-17 22:39:26,982 ERROR x.y.z.Main - Main error hogehoge

上の表の内容は、実現できています。

しかし、「同一のログレベルだが、意味や用途の異なる複数のログ」に対しては、レベルだけのフィルタリングでは当然対応できません。

本当にやりたいのは、こういうことです。

出力先 出す 出さない
コンソール INFOのユーザ向けログ DEBUG, INFOの開発者向けログ，WARN, ERROR
ファイル DEBUG, INFOの開発者向けログ，WARN, ERROR INFOのユーザ向けログ

この場合、INFOレベルの2種類のログを、どうやって出し分ければよいでしょうか。

ところで、logbackには、Markerというものがあります。これにturboFilterという機構を使うと、Markerに応じてマッチ/ミスマッチ時の挙動を設定できます。

ここで、MESSAGEとDETAILというMarkerを定義し、それぞれをユーザ向けログと開発者向けに使うことにします。

package xxx.yyy.zzz;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

import xxx.yyy.zzz.impl.Foo;

public class Main {

	private static final Logger logger = LoggerFactory.getLogger(Main.class);
	private static Marker msg = MarkerFactory.getMarker("MESSAGE");
	private static Marker detail = MarkerFactory.getMarker("DETAIL");

	public static void main(String[] args) {

		QQQ foo = new Foo("foo");
		logger.info(msg, "hello!");
		logger.info(detail, "mogamoga(for developers)");
		foo.execute();
		logger.info(msg, "bye!");
	}
}

で、先ほどの設定ファイルに、次のような記述を追加します。

	<turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
		<Marker>MESSAGE</Marker>
		<OnMatch>ACCEPT</OnMatch>
	</turboFilter>
	<turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
		<Marker>DETAIL</Marker>
		<OnMatch>DENY</OnMatch>
	</turboFilter>

何だか、いけそう……？

しかし、上記を実行しても、「mogamoga(for developers)」がDENYの憂き目に遭い、亜空間に消えるだけの結果になります。これは、turboFilterの設定が、すべてのAppenderに適用されるためです。「MESSAGEだから出す、DETAILだから出さない」という設定はできても、「MESSAGEだからコンソールに出す、DETAILだからコンソールに出さない」という設定はできません。

実際、turboFilterは、configurationの直接の子要素として書く必要があります。LevelFilterのように、Appenderの子要素として書くことができません。

Appenderが1つならMarkerで一件落着ですが、複数ある場合はどうしたらよいかが分かりません。というわけで、Markerを使ったフィルタをAppenderとマッピングする方法を探しています。何か見落としてるのかな・・・。（もちろん、今回の文脈なら、ログレベルを見直して、開発者向けログをINFOでなくDEBUGにしてしまった方が、話が早い。でも、ツールでの解決策を見つけられないときに、ログのレベル設計をとっとと変えるのは、ちょっと気が引けるというか、何というか）

ちなみに、loggerは、パッケージを指定して定義することができて、loggerにはAppenderを関連づけることができます。

なので、実際の処理を行うクラスが属するパッケージには、開発者向けログを出力させ、抽象度の高い処理を行うクラスが属するパッケージには、ユーザ向けログを出力させる、といった方向の別解が、もしかしたらあるのかもしれません。

しかし、そもそもそんなことが可能な形でパッケージ切ってないし、という問題が別途ありまして……ぐぬぬ。

もうちょっと調べます。（まとまらないまま終わる）

（追記） この記事の解決編はこちら。http://d.hatena.ne.jp/torazuka/20120619/logback