Grails1.1でのログ設定まわりのあれこれ
はじめに
Grails1.1からログの設定方法が変わりました。
というか、変わりすぎです。これ。
以前は、単なるドット区切りのプロパティキーをもうちょっと構造化してかけますよ、ぐらいのDSLでしたが、Grails1.1からは完全にLog4J用のDSLが導入されました。
その結果として、以前よりもすっきりとかけるようにはなったんですが、なったんですが、なったんですが、また、問題もありまして・・・・というお話。
公式ドキュメント
一応この辺に公式ドキュメントがあります。
ただ、部分的に抜き出したサンプルコードしかないので、微妙にわかりづらい。
しかも、後述するSanitizing StackTraceの説明があっさりしすぎてて困ります。
非常に困ります。
Sanitizing StackTrace
Grails1.1から、例外のスタックトレースの一部を省略表示する機能が追加されてました。
ドキュメントによると、
When exceptions occur, there can be an awful lot of noise in the stacktrace from Java and Groovy internals. Grails filters these typically irrelevant details and restricts traces to non-core Grails/Groovy class packages.
(適当な意訳)
例外がおきたとき、スタックトレースにはJavaとかGroovyの内部に起因する大量のノイズがはいるよね。
Grailsは、これらのたいていは無意味な詳細情報をフィルタリングして、できるだけスタックトレースを自前クラス系のものに絞り込むようにしたよ。
ということらしい。
うーん。便利なのか余計なお世話なのか・・・・。
実験してみる
というわけで、実験してみます。
デフォルトでは、このSanitizing StackTrace機能がONになっています。
まずは見慣れたスタックトレースを確認したいので、これをOFFにして試してみます。
Sanitizing StackTrace=OFFの場合
公式ドキュメントにあるとおり、
grails -Dgrails.full.stacktrace=true run-app
と起動オプションを指定して起動するとOFFにできます。
余談ですが、最初はオプション名で気持ち悪さを感じました。が、よくよく考えてみると、SanitizingをやめてFullモードにするんだよ、という意味でこの名前にこの値なんですな。
どっちにしろ気持ち悪い・・・。
個人的な好みで言えば、そもそもデフォルトでONになってるのがキモいし、特殊機能なんだからそれがONになっていることをtrueとするようなオプション名がいいんじゃないかと思うんだけどなぁ。-Dgrails.sanitaizing.stacktrace=true がデフォで、falseにするとOFFにできる、みたいな。イヤむしろデフォでOFFになっててくれるのが一番なんだけど・・・。
ま、それはおいといて、上記の起動オプションを起動して、単に例外をthrowするだけの適当なダミーコントローラ(HogeController)にアクセスすると・・・・。
〜 標準出力に出力されたスタックトレースのCaused byのところだけ抜粋。それ以前の部分はSanitizingされてないっぽいので、省略。〜
Caused by: java.lang.Exception: 強制的に例外発生！
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:494)
at org.codehaus.groovy.reflection.CachedConstructor.invoke(CachedConstructor.java:70)
at org.codehaus.groovy.runtime.callsite.ConstructorSite$ConstructorSiteNoUnwrapNoCoerce.callConstructor(ConstructorSite.java:102)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallConstructor(CallSiteArray.java:55)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:191)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:199)
at HogeController$_closure2.doCall(HogeController.groovy:11)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:266)
at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:51)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:47)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:142)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:150)
at HogeController$_closure2.doCall(HogeController.groovy)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:86)
... 65 more
まあ、いつもよく見ているわかりやすいスタックトレースです。
ちょっとウザいけど、しっくりきます。
さて、SanitizingをONにすると、一体コレがどうなるのでしょうか？
Sanitizing StackTraceがONの場合
余計な起動オプションなしで素直に起動します。
さて、同じようにHogeControllerにアクセスすると・・・・。
〜 標準出力に出力されたスタックトレースのCaused byのところだけ抜粋。それ以前の部分はSanitizingされてないっぽいので、省略。〜
Caused by: java.lang.Exception: 強制的に例外発生！
at HogeController$_closure2.doCall(HogeController.groovy:11)
at HogeController$_closure2.doCall(HogeController.groovy)
なんと！
色々余計なものがそぎ落とされて、すっきりとHogeControllerなログだけになっています。
ちょっとすっきりしすぎです。
正直これに慣れるとは思えない・・・・。
このとき、アプリケーションルート直下にはstacktrace.logというファイルが作成されていて、その内容は・・・・
2009-03-22 22:42:14,548 [10117283@qtp0-0] ERROR StackTrace - Sanitizing stacktrace: java.lang.Exception: 強制的に例外発生！ at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) at java.lang.reflect.Constructor.newInstance(Constructor.java:494) at org.codehaus.groovy.reflection.CachedConstructor.invoke(CachedConstructor.java:70) at org.codehaus.groovy.runtime.callsite.ConstructorSite$ConstructorSiteNoUnwrapNoCoerce.callConstructor(ConstructorSite.java:102) at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallConstructor(CallSiteArray.java:55) at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:191) at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:199) at HogeController$_closure2.doCall(HogeController.groovy:11) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:266) at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:51) at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:47) at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:142) at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:150) at HogeController$_closure2.doCall(HogeController.groovy) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:86) at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:234) at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1061) at groovy.lang.ExpandoMetaClass.invokeMethod(ExpandoMetaClass.java:910) at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:892) at groovy.lang.Closure.call(Closure.java:279) at groovy.lang.Closure.call(Closure.java:274) at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.handleAction(SimpleGrailsControllerHelper.java:363) at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.executeAction(SimpleGrailsControllerHelper.java:243) at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.handleURI(SimpleGrailsControllerHelper.java:203) at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.handleURI(SimpleGrailsControllerHelper.java:138) at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsController.handleRequest(SimpleGrailsController.java:88) at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48) 〜ずっときまじめに出力されてるので中略〜 at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403) at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409) at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522) 2009-03-22 22:42:14,553 [10117283@qtp0-0] ERROR StackTrace - Sanitizing stacktrace: java.lang.Exception: 強制的に例外発生！ at HogeController$_closure2.doCall(HogeController.groovy:11) at HogeController$_closure2.doCall(HogeController.groovy)
というわけで、サニタイジングなしバージョンとサニタイジングバージョンのログがそのまま出力されているようです。
解析したかったらこっちをみればよい、ということのようです。
うーん。これってどうよ？
さて、この機能どうなんでしょ。
個人的には、ナシだと思ってます。今のところ。
こんなところで余計なことして複雑性をあげる必要なんてないのに。と思います。
Java技術者なんだから、素直にスタックトレースを読めばいいだけなのに、と思います。
しかもOFFにするために起動オプションを要求するなんてどうよ。と思います。
なんというか残念な気持ちでいっぱいです。
Sanitizing StackTraceをOFFにできるのか？
というわけで、ばっさりとOFFにしたいと思います。
OFFにするには、例の起動オプション
grails -Dgrails.full.stacktrace=true run-app
を指定すればOK・・・だとちょっと足りないようです。
実は、必要もないのにアプリケーションルート直下のstacktrace.logファイルは作成されてしまうんですね。
サイズ0のままなんですが、これは気持ち悪い。
ってことで、stacktrace.logファイルの生成を抑止する方法を調べました。
Grailsのソースをみると
[grails-1.1/src/groovy/org/codehaus/groovy/grails/plugins/logging/Log4jConfig.groovy] private createFullstackTraceAppender() { if(appenders.stacktrace) { return appenders.stacktrace } else { def fileAppender = new FileAppender(layout:DEFAULT_PATTERN_LAYOUT, name:"stacktraceLog") fileAppender.file = "stacktrace.log" fileAppender.activateOptions() appenders.stacktrace = fileAppender return fileAppender } }
となっており、"stacktrace"という名前のappenderを定義してやればそっちが優先されるため、stacktrace.logファイルが作成されなくなるようです。
Sanitizing StackTraceを完全にOFFにする方法 (ちょっとリスキー版)
というわけで、
grails-app/conf/Config.groovyで、
appenders {
'null' name:'stacktrace' // disabled unwanted "StackTrace" log
}
のように何も出力しないNullApenderを指定しておいて、
grails -Dgrails.full.stacktrace=true run-app
でアプリケーションを起動するようにしておけば、今まで通りとなりそうです。
しかし、この方法では起動オプションを忘れると真のスタックトレースが闇に葬り去られてしまうことになり、非常にリスキーです。
もっと良い方法はないものでしょうか・・・・。
Sanitizing処理の実装箇所をのぞいてみる
どうやら、grails-1.1/src/commons/grails/util/GrailsUtil.java で実装されているようです。
public static Throwable sanitize(Throwable t) { // Note that this getProperty access may well be synced... if (!Boolean.valueOf(System.getProperty("grails.full.stacktrace")).booleanValue()) { StackTraceElement[] trace = t.getStackTrace(); List newTrace = new ArrayList(); for (int i = 0; i < trace.length; i++) { StackTraceElement stackTraceElement = trace[i]; if (isApplicationClass(stackTraceElement.getClassName())) { newTrace.add( stackTraceElement); } } // Only trim the trace if there was some application trace on the stack // if not we will just skip sanitizing and leave it as is if (newTrace.size() > 0) { // We don't want to lose anything, so log it STACK_LOG.error("Sanitizing stacktrace:", t); StackTraceElement[] clean = new StackTraceElement[newTrace.size()]; newTrace.toArray(clean); t.setStackTrace(clean); } } return t; }
うーん。まさにSystemプロパティの値をそのまんま使ってるので、Systemプロパティを指定する以外に回避方法はないですね・・・。
しかし、毎回起動パラメータってのもやっぱり危ないので自動でSystemプロパティを指定する方法を考えてみました。
Sanitizing StackTraceを完全にOFFにする方法 (おすすめ版)
とりあえずは、其の一と同じく、grails-app/conf/Config.groovyで、
appenders {
'null' name:'stacktrace' // disabled unwanted "StackTrace" log
}
のように何も出力しないNullApenderを指定しておきます。
更に、grails-app/conf/BootStrap.groovyで、
def init = { servletContext -> System.setProperty("grails.full.stacktrace", "true") }
と書いておけば・・・
grails run-app
とすっきりした起動コマンドで、OKになります。
残念な感じの手間が増えますが、これで一応元通りに使えます。
Sanitizing StackTraceをOFFにするのをあきらめる場合の妥協案
とはいえ、新しい機能の食わず嫌いもどうかなという気もします。
とりあえず、アプリケーションルート直下にだらだらとログファイルが作られるというのは、個人的に許せないので、
grails-app/conf/Config.groovyで、
appenders {
rollingFile name:"stacktrace", file:"log/stacktrace.log", maxFileSize:1024, layout:pattern(conversionPattern: '%d{yyyy-MMM-dd HH:mm:ss,SSS} [%p] (%c{2}) %m%n')
}
のようにとりあえずは微妙な位置に出力されるstacktrace.logの位置を自分でコントロールしつつ、Sanitizingと付き合うというのも妥協案としてはありなのかなぁ。どうかなぁ。
ログ設定部分全体
さて、参考までに、まだ全然自信も実績もないのですが、3/23現時点においてこれでどうだろうか、と思っているログ設定をさらしておきます。何かあっても責任は持てませんが。
// log4 log4j = { appenders { console name:'stdout', layout:pattern(conversionPattern: '%d{yyyy-MMM-dd HH:mm:ss,SSS} [%p] (%c{2}) %m%n') rollingFile name:'file', file:'log/irclog.log', maxFileSize:'10MB', maxBackupIndex:5, layout:pattern(conversionPattern: '%d{yyyy-MMM-dd HH:mm:ss,SSS} [%p] (%c{2}) %m%n') rollingFile name:'stacktrace', file:'log/stacktrace.log', maxFileSize:'10MB', maxBackupIndex:5, layout:pattern(conversionPattern: '%d{yyyy-MMM-dd HH:mm:ss,SSS} [%p] (%c{2}) %m%n') } root { info 'stdout', 'file' additivity = false } error 'org.codehaus.groovy.grails.web.servlet' // controllers error 'org.codehaus.groovy.grails.web.pages' // GSP error 'org.codehaus.groovy.grails.web.sitemesh' // layouts error 'org.codehaus.groovy.grails."web.mapping.filter' // URL mapping error 'org.codehaus.groovy.grails."web.mapping' // URL mapping error 'org.codehaus.groovy.grails.commons' // core / classloading error 'org.codehaus.groovy.grails.plugins' // plugins error 'org.codehaus.groovy.grails.orm.hibernate' // hibernate integration error 'org.springframework' info 'org.springframework.security' // Acegi plugin error 'org.hibernate' warn 'org.mortbay.log' // for My application info "grails.app.controller" info "grails.app.service" info "grails.app.task" // おまけ:下のように書くとadditivityも指定できるっぽい。 //warn ( // additivity: false, // stdout: 'org.mortbay.log' // stdout: 'foo.bar' //) }
修正 3/27
- rollingFileのmaxFileSizeを1024byte→10MBに変更した。
- rollingFileのmaxBackupIndexを追加してバックアップ世代を5にした(デフォルトではバックアップ1世代)。
まとめ
- Grails1.1の新しいログ設定DSL自体はそんなに悪くはないと思う
- しかし、Sanitizingがうざい
- パッケージごとのadditivityの設定方法がドキュメントに明示されていない (ソースを読めばわかるが・・・)
- Grails1.1はすてきな機能も追加されてるけど、微妙に余計なことも追加されてる感が強まってきた(以前に書いたデフォルト命名規約の改悪(hogeInstance)とか。)
ということで、総合的には微妙な感じなのでした。
