Groovy/Gaelykでのロギング

GroovyでJDKの標準ロギングユーティリティ(java.util.logging)を特にカスタマイズせずにこんな風に使うと：

import java.util.logging.Logger
logger = Logger.getLogger(this.class.name)
logger.warning("You have the right to remain silent.")

出力は以下のようになります：

2010/05/18 0:31:27 sun.reflect.NativeMethodAccessorImpl invoke0
警告: You have the right to remain silent.

Javaなら適当に見つけてくれる、クラス名とメソッド名が何だか変です。

これは、特にロギングが重要なデバッグの手段であるGaelykでの開発ではちょっと困った問題です。いちいち毎回手動でクラス名やメソッド名書くのもいやだしね。

調べてみると、どうやら原因はGroovyの内部処理のためスタックが「汚れる」ことのようです。Groovyのさまざまな便利さ・優雅さを実現するための水面下の処理が、スタックにもろもろの余計なエントリを混入してしまうので、適切なクラス名やメソッド名が見つけられないわけです。

Javaでは次のようにして現在実行中のクラスやメソッド名が取得できますが：

// 実行中のクラス・メソッド名を取得：Java版（一部）
StackTraceElement current = Thread.currentThread().getStackTrace()[1];
System.out.println(current.getClassName());
System.out.println(current.getMethodName());

Groovyでは同じ方法だと、クラス名は sun.reflect.NativeMethodAccessorImpl 、メソッド名は invoke0 とかになってしまいます。

さらに調査していくと、汚れたスタックを清めて(sanitize)見やすくするための org.codehaus.groovy.runtime.StackTraceUtils というクラスを発見！これを使えば正しいクラス名とメソッド名が取得できることがわかりました：

// 実行中のクラス・メソッド名を取得：Groovy版
import org.codehaus.groovy.runtime.StackTraceUtils
current = StackTraceUtils.sanitize(new Throwable()).getStackTrace()[0]
println current.className
println current.methodName

これでいけるかと思いきや、StackTraceUtilsの内部実装で使われている java.util.logging.LogManager はGAE/Jではrestricted classなので、この方法はGaelykでは使えないことが判明...

仕方なくStackTraceUtilsソースのsanitize処理を眺めてみたところ、これが案外単純だったので、sanitizeのエッセンスだけ実装したLoggerラッパーを自作してみることに。でっちあげたのがこれ：

思えばStackTraceUtilsを使うより、自然で効率もよくなった気も（いちいちThrowableをnewしたりしなくてすむし）。こんな感じで使います：

logger = new GroovyLogger(this.class.name)
logger.warning("You have the right to remain silent.")

あんまりしっかりとはテストしてませんが、Gaelykでもちゃんと期待通りに動きました。めでたしめでたし。