ログは、もっと立体的であるべきか。

slf4jとlogbackに、魂を売り渡す勢いであります。
と言うのは冗談としても、何だか使い方が分からないけど、
Loggerのメソッドには、引数として存在しているorg.slf4j.Markerについて、考えてみたり。

現段階では、slf4jとlogbackを使ってる大きめのOSSプロダクトにおいて、
どんな使われ方をしてるかちゃんと見てないので、妥当な使い方なのかは、微妙。
まぁ、僕なら、こんな風に使ってみるよ、と言う感じのエントリ。
slf4j使おうって人達が、使い方を考える時のとっかかりになればいいかな…とか。

まず、org.slf4j.Loggerの、Markerを引数に取るメソッドの宣言と、org.slf4j.Markerの宣言を抜粋してみるよ。

public interface Logger {
  public void debug(Marker marker, String format, Object[] argArray);
  public void debug(Marker marker, String msg, Throwable t);
}
public interface Marker extends Serializable {
  public String getName();
  public void add(Marker reference);
  public boolean remove(Marker reference);
  public boolean hasReferences();
  public Iterator iterator();
  public boolean contains(Marker other);
  public boolean contains(String name);
  public boolean equals(Object o);
  public int hashCode();
}

まぁ、これだけでは、正直良く分からないと言ったトコロ。
只、間違いなく言える事は、

• ロギング用メソッドは、全て最初の引数にMarkerを取るものがある。
• Markerはそれ自身のインスタンスによってツリー構造を構成出来得る。

と言う事。これ重要。テストに出るらしいよ。

まぁ、とりあえず、一番簡単だけど、全く意味の無いMarkerを使うログ出力コードを書いてみる。

• LogMain.java

package org.domain.library;
// import文は除外。
public class LogMain {
  public static void main(String[] args) {
    Logger l = LoggerFactory.getLogger(LogMain.class);
    Marker m = MarkerFactory.getMarker("MarkerExample");

    l.debug("debug log without marker.");
    l.debug(m, "debug log with marker.");
  }
}

• logback.xml
  • Patternタグで指定しちる、%markerが地味にポイント。

<configuration>
  <appender name="STDOUT1" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>STDOUT1 %d{HH:mm:ss.SSS} %-5level %marker %logger{10} - %msg%n</Pattern>
    </layout>
  </appender>
  <root level="DEBUG">
    <appender-ref ref="STDOUT1" />
  </root>
</configuration>

• 実行結果

STDOUT1 15:30:12.997 DEBUG  o.d.l.LogMain - debug log without marker.
STDOUT1 15:30:12.997 DEBUG MarkerExample o.d.l.LogMain - debug log with marker.

基本的な使い方は、分かった。でも、ログの出力項目が微妙に増えただけじゃね？とか。
使うFactoryクラスが一個増えただけ、単に手間ジャン。メンドーだなヲイ、とか。
それじゃあ、全然使い道がない。正直、僕も何かテキトーにドキュメント見た感じだと、意味不明であった。
ちと、有用な感じに、設定を変えてみる。
参考にしているのは、この辺。

• Chapter 6: Filter chains - TurboFilters

今度は、turboFilterタグなんちう見慣れない感じのが出てくるよ。

<configuration>
  <appender name="STDOUT1" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>STDOUT1 %d{HH:mm:ss.SSS} %-5level %marker %logger{10} - %msg%n</Pattern>
    </layout>
  </appender>
  <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>MarkerExample</Marker>
    <OnMatch>DENY</OnMatch>
  </turboFilter>
  <root level="DEBUG">
    <appender-ref ref="STDOUT1" />
  </root>
</configuration>

で、動かしてみる。

STDOUT1 15:34:36.851 DEBUG  o.d.l.LogMain - debug log without marker.

おおぅ、キエタ。。。いりゅーじょなりー！！

でも、ログが出ない様にするだけなら、こんなんでええやん。

<configuration>
  <appender name="STDOUT1" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>STDOUT1 %d{HH:mm:ss.SSS} %-5level %marker %logger{10} - %msg%n</Pattern>
    </layout>
  </appender>
  <logger name="org.domain.library.LogMain" level="INFO" />
  <root level="DEBUG">
    <appender-ref ref="STDOUT1" />
  </root>
</configuration>

実行。。。。

全部消えた。勿論。そりゃそうだ。と、ここまで実行して分かった事がある。

• log4jのLoggerには無かったMarkerが、slf4jで追加される事によって、ログの出力方式は、より多元的になった。

これ重要。凄く重要。とても重要。
slf4jのFilterは、まぁ、何というか物凄いリッチな機能*1を色々持っていて、
只、Marker以外は、ライブラリを使う側としては、設定ファイルを弄るけど、コードの変更は必要ない感じなのだよね。
と・こ・ろ・が、Markerは、ライブラリのコンシューマが意識的に使わないと、動かない。

今までのコーディングの習慣にちょっとした変更を加えるだけで、結構色んな事が変わる。
つまるところ、ここからが、今日の本題。

本題なのだけど、もう一つだけ、本題に入る前に、ログの在り方について、僕の考えている事を羅列しちみる。
まず、ここでいうログは、Javaによるユーザコードの中で、任意に出力されるナニか。
つまり、一般的に言うログよりも、相当に範囲が狭いものであります。
java.util.loggingと言うパッケージがありながら、JavaのCoreAPIでは、ほぼ全く出力していないアレ。
HibernateやSpringを使う時に、出力レベルをDEBUGにすると、大量に出過ぎて悶絶するアレ。
基本的には、文字列がどっかにテキストファイルやら標準出力やらに出力されるアレ。
文字列が、XMLだったり、スタックトレースだったり、まぁ何か見る人が見れば分かる色んな形をしているアレ。

まぁ、こんなもんか。じゃあ、このログはどんな目的で使うのだろ？

• コードの問題を発見する為
• コードの動作を確認する為
• 黒い背景に緑の文字で大量に出力して、サイバーパンクな感じを味わう為

3つ目は冗談としても、突き詰め過ぎちゃうと、あんま意味無い感じに。

もうちょっと言い方を変えると、ログは、
ナニかよく分からないけど、例外が飛んで、自分のコードやら使ってるライブラリやらが、期待通りに動いてない時、
一番最初のとっかかりとして、問題を切り分ける為に、まず使う。僕の場合。
勿論、ログを一目見れば、問題の原因まで分かっちゃう事もある、そういう時はラクでイイよね。

で、このログが格納されてるファイルってのが、やっかいなんだな。また。

• ログ出過ぎ
• ログ出てネェ

大体、どっちか。いや、どっちにも当てはまらないなら、それはシヤワセな事で問題は、そのまま解決スルヨネ、とか。

で、このログ出過ぎとか、出てネェとか、そういう事は何で起こるのかな…と考えてみる。
ここは論理飛躍がちとあるのだけど、そもそも、大抵のライブラリとかフレームワークって、
ログの出力制御をキチンと考慮したパッケージ構成になってんだっけ？なってなくね？とか。
そもそもログ出力は、アスペクトなのはみんなが認めるトコロなんだから、
通常のクラス構成と言うかパッケージ構成のみを前提に出力制御考えるとかなくね？とか。

log4jにしても、slf4jにしても、基本的には、
パッケージ単位もしくはクラス単位でログの出力を制御する様になってる事が、問題なのかな…と、フト思いついたりする訳。
つまり、物理的なファイル構成に、強く依存してログの出力制御しちる。
これ、なんかもっといいやり方がある様な…と。

ここは、どういう風にLoggerを使っているか…？と言う部分に強く依存するのだけど、
Loggerって、こんな風に、特定のクラスに依存する形で宣言して使ってるよね？

package org.domain.library.core.impl;
// import文は除外。
public class CoreInterfaceImpl implements CoreInterface {
  static final Logger LOG = LoggerFactory.getLogger(CoreInterfaceImpl.class);

  @Override
  public void execute() {
    if (LOG.isDebugEnabled()) {
      LOG.debug("execute is called.");
    }
  }
}

Loggerをこういう風に使ってないって事であれば、ここでの話は、全く状況が違うよん…と言う事になるます。
いや、メンバ変数名とか、微妙に違ってたりするだろうけどさ。

話がそれたけど、このファイルの物理構成を前提にしたログの出力制御って、結構やっかいなのだ。
どういう手順で出力制御してるかなぁ…と、考えると。
やり口としては、大体この3つかなぁ…と思う、僕の場合。

• コードを全部読んで理解した上で、必要な部分だけログを出す
• それっぽそうなパッケージ名で、フォースを感じるに任せてログを出して、多ければ削るし、足りなければ出力範囲を広げる。
• とりあえず、DEBUGレベルで全部出して、出したログからノイズを徐々に減らす

OSS使ったプロジェクトで、使おうとしてるライブラリなりフレームワークなりの挙動をつぶさに把握せずにやる、とか、
ある意味自殺行為に近いとは思うんだけど、一方で出てるログを見て、どの部分がどう動いていて、
例外なりエラーなりで死んだ時、一体何が悪いのか即座に把握できる程に理解してるか…と言うと、まぁ怪しいよね。

スタックトレースさえ出てるんなら、まぁ、関連がありそうなパッケージ名を洗い出すのは、
それ程難しい事でもない…と考える事も出来る。
ある程度、対象に対する理解があるのであれば、ザックリと関連するパッケージくらいは分かるかもね。
そういう意味で、殆どの人は、真ん中のアプローチでやってるんじゃないかなぁ…と思っているのだけど、どうだろう？
このやり方の問題点は、パッケージ構成に対する理解と、その実装が適切にかみ合ってる時は良いんだけど、
ログの出力制御を設定する側と、コードを実装する側の常識が微妙にズレてたりすると、
全く持って非効率かつ、問題解決までの時間が、見積もり不能な感じになっちゃうんだよねぇ…。

仕方がないので、「とりあえず全部出す」そして膨大なログの海を、気合いで泳ぐ。
と言う方法も無くは無い。大凡理知的なやり方とも思えないけど、堅実なやり方かもしれない。
特に、対象のコードに対する理解が足りない状況では、変に最初に絞っちゃうより、全部出して、
泣きながらログを読む方が確実に前に進めるケースもある。

コードを完全に把握していない場合には、余り賢いとは言えないやり方で、ログを解析せざるを得ないんだよね、現状。
ログ出力するコードを書く側としても、ログレベルだけで、そのログの読み手に、
どの様なコンテキストでログを読むべきなのか伝えるのは、正直難しいんじゃないかなぁ…とか、思ったりしている、今日この頃。

相当強引な引っ張り方なんだけど、と言う訳で、Markerでつよ。となる。
いや、文章が長くなってきて、正直飽きてきたとか、そういう事なんだけどさ…。

で、こんなコードを書いてみた、と言うトコロ。

package org.domain.library;
// import文は除外。
public class Markers {
  public static final String PREFIX_PKG = "org.domain.library";

  public static final Marker MARKER_ROOT = MarkerFactory
      .getMarker(PREFIX_PKG);

  // 設計判断を伴う処理に関連する項目。アドインやプラグインに関連する部分など。
  public static final Marker DESIGN = MarkerFactory.getMarker(PREFIX_PKG
      + ".design");

  // ファイルやネットワーク、他の依存ライブラリに対するインターフェースに関連する項目
  public static final Marker BOUNDARY = MarkerFactory.getMarker(PREFIX_PKG
      + ".boundary");

  // ライブラリ内に定義されているオブジェクトのライフサイクルに関連する項目
  public static final Marker LIFECYCLE = MarkerFactory.getMarker(PREFIX_PKG
      + ".lifecycle");

  // 処理の中で、詳細な情報を出力する為の項目
  // このマーカは、主にライブリやフレームワークの実装者が、バグの調査を目的として使う
  public static final Marker DETAIL = MarkerFactory.getMarker(PREFIX_PKG
      + ".detail");

  static {
    Marker[] markers = { DESIGN, BOUNDARY, LIFECYCLE, DETAIL };
    for (Marker m : markers) {
      MARKER_ROOT.add(m);
    }
  }
}

こんな風なコードでログ出力しる。

package org.domain.library;
// import文は除外。
public class LogMain {
  static final Logger LOG = LoggerFactory.getLogger(LogMain.class);

  public static void main(String[] args) {
    if (LOG.isDebugEnabled()) {
      LOG.info(Markers.BOUNDARY, "inputs are {}", args);
    }

    CoreInterface ci = create(args);
    ci.execute("C:\\temp\\hoge.log");
  }

  protected static CoreInterface create(String[] args) {
    CoreInterfaceImpl cii = new CoreInterfaceImpl();
    cii.initialize();
    return cii;
  }
}


package org.domain.library.core.impl;
// import文は除外。
public class CoreInterfaceImpl implements CoreInterface {
  static final Logger LOG = LoggerFactory.getLogger(CoreInterfaceImpl.class);

  public CoreInterfaceImpl() {
    if (LOG.isInfoEnabled()) {
      LOG.info(Markers.LIFECYCLE, "{} is created",
          CoreInterfaceImpl.class.getName());
    }
  }

  public void initialize() {
    if (LOG.isInfoEnabled()) {
      LOG.info(Markers.LIFECYCLE, "{} is initialized",
          CoreInterfaceImpl.class.getName());
    }
  }

  @Override
  public void execute(String path) {
    if (LOG.isDebugEnabled()) {
      LOG.debug(Markers.DETAIL, "execute is called.");
    }
    File f = new File(path);
    if (LOG.isDebugEnabled()) {
      LOG.debug(Markers.BOUNDARY, "read from {}", f.getAbsolutePath());
    }
    InputStream in = null;
    try {
      in = new FileInputStream(f);
    } catch (IOException e) {
      LOG.error(Markers.BOUNDARY, e.getMessage(), e);
    } finally {
      StreamUtil.close(in);
    }
  }

  @Override
  public void dispose() {
    if (LOG.isInfoEnabled()) {
      LOG.info(Markers.LIFECYCLE, "{} is disposed",
          CoreInterfaceImpl.class.getName());
    }
  }
}

static import を巧く使うと、もう少しコードが少なくなるかもぞ。

で、使うlogback.xmlはこんな感じ。

<configuration>
  <appender name="STDOUT1" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>STDOUT1 %d{HH:mm:ss.SSS} %-5level %marker %logger{10} - %msg%n</Pattern>
    </layout>
  </appender>
  <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>org.domain.library</Marker>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>
  <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>org.domain.library.boundary</Marker>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>
  <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>org.domain.library.lifecycle</Marker>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>
  <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>org.domain.library.detail</Marker>
    <OnMatch>DENY</OnMatch>
  </turboFilter>
  <root level="DEBUG">
    <appender-ref ref="STDOUT1" />
  </root>
</configuration>

実行結果は、こんな感じ。

STDOUT1 18:53:14.128 INFO  org.domain.library.boundary o.d.l.LogMain - inputs are {}
STDOUT1 18:53:14.143 INFO  org.domain.library.lifecycle o.d.l.c.i.CoreInterfaceImpl - org.domain.library.core.impl.CoreInterfaceImpl is created
STDOUT1 18:53:14.143 INFO  org.domain.library.lifecycle o.d.l.c.i.CoreInterfaceImpl - org.domain.library.core.impl.CoreInterfaceImpl is initialized
STDOUT1 18:53:14.143 DEBUG org.domain.library.detail o.d.l.c.i.CoreInterfaceImpl - execute is called.
STDOUT1 18:53:14.143 DEBUG org.domain.library.boundary o.d.l.c.i.CoreInterfaceImpl - read from C:\temp\hoge.log
STDOUT1 18:53:14.143 ERROR org.domain.library.boundary o.d.l.c.i.CoreInterfaceImpl - C:\temp\hoge.log (指定されたファイルが見つかりません。)
java.io.FileNotFoundException: C:\temp\hoge.log (指定されたファイルが見つかりません。)
	at java.io.FileInputStream.open(Native Method) [na:1.6.0_02]
	at java.io.FileInputStream.<init>(FileInputStream.java:106) [na:1.6.0_02]
	at org.domain.library.core.impl.CoreInterfaceImpl.execute(CoreInterfaceImpl.java:42) [bin/:na]
	at org.domain.library.LogMain.main(LogMain.java:18) [bin/:na]

Markerを使う事によって、ログを出力する側の意図をある程度明確に表現出来て、
かつ、それに合わせたログの出力制御をする事で、コードを完全に把握しなくても、
ログの出力制御が出来るんじゃないかなぁ…とか、思ったり思わなかったりした、と言う話。
ログを出力するコードも、今までと殆ど変らず、引数が一個増えるだけだし、どうかな？
但し、コードの変更は少ないけど、考える事は相応に増える感じなので、ログを出力するコード書く側の労力は、
間違いなく増える訳で、まぁ、それは大変。

で、Markerを使った出力制御をしちるフレームワークやライブラリの実装者の皆様におかれましては、
Filterの設定が全部入ってるサンプルの設定ファイルを配布物に含めてクダサシ、とか。

中途半端で、最後の最後で論理飛躍したけど、後はまぁ、フォース的な何かで埋めてクダサシ。

*1:ログの出力時に式言語でコンテキストを評価して、ログとして出すかどうか判断する…とか。正直、やり過ぎだと思う。