JRuby on Google App Engineでのログ出力
前置き
Google App Engine for Java（以下GAEJ）でJRubyスクリプトを書くにあたって、ログ出力をどうしたらいいのか、少し迷ってしまいませんか？
標準出力や標準エラー出力に書き出したデータは単に無視されるだけですし、書き込みモードでファイルを開けませんので、RubyのLoggerクラスをそのまま使うことも出来ません。かといって、ログ出力無しでは何かと不便です。
Javaでのログ出力
JRubyはJava上で動作しており、Javaのクラスを利用することができますので、Javaでどのようにログを出力するのかがわかれば解決したも同然です。
そこでGAEのデベロッパーガイドをざっと眺めてみました、が…。
どうにもそれっぽい項目が見当たりません。
よく探してみたら、全然関係なさそうな以下のページの下の方でさらっとログ出力について触れられていました。
ログ出力って結構重要な要素だと思うんですが、そうでもないんでしょうか…？
ともあれ、上のページによると、GAEJではjava.util.logging.Loggerクラスを利用してログ出力すれば良いそうです。つまり、JRubyからこのクラスを使わせてもらえばいいわけですね。
JRubyからjava.util.logging.Loggerを使う
インスタンス作成
java.util.logging.Loggerクラスのリファレンスを見てみると、どうやらLoggerクラスのインスタンスを取得するには複数の手段があるようです。
Rubyコードで書くと以下のような感じになります。
import java.util.logging.Logger global_logger = Logger.getLogger(Logger::GLOBAL_LOGGER_NAME) anonymous_logger = Logger.anonymous_logger my_logger = Logger.getLogger('MyName')
上から順にグローバルロガー、匿名ロガー、名前付きロガー…らしいですが、Javaに明るくない私にはどう使い分けたらいいのかよくわかりません。正しく使い分けておけば、ログのネームスペースによってフィルタリングできる…とかそんな感じでしょうか。
ちょっと調べてみた範囲では、「とりあえず使うだけ」ならどれを使ってもあまり差は無さそうです。
ログ出力メソッド
Loggerクラスにはたくさんのメソッドがありますが、まず必要なのはレベル別のログ出力メソッドですね。
ログレベルを定義しているjava.util.logging.Levelクラスでは、レベルは低い順にFINEST, FINER, FINE, CONFIG, INFO, WARNING, SEVEREとなっています。メソッドもそれぞれ同名のものが用意されているようです。
しかし、GAEダッシュボードのログ表示画面での表記はPython用のloggingモジュールで定義されているログレベルに合わせてあり、java.util.logging.Levelのそれとは名称が異なっています。
GAEJでは以下のような対応になっているようです。
my_logger.finest('hello') # = Debug my_logger.finer('hello') # = Debug my_logger.fine('hello') # = Debug my_logger.config('hello') # = Debug my_logger.info('hello') # = Info my_logger.warning('hello') # = Warning my_logger.severe('hello') # = Error
Criticalに対応するレベルは無いみたいです。とりあえずsevere, warning, info, あとはfine*1メソッド辺りがあれば十分、といったところでしょうか。
ログ出力レベルの変更
GAEではデフォルトのログ出力レベルはWARNING以上となっていますので、そのままではINFO以下のログは無視されてしまいます。*2
java.util.logging.Loggerクラスにはログ出力レベルを設定するsetLevelメソッドなどもありますので、それを利用しても良いのですが、設定ファイルによってアプリケーションのデフォルトログ出力レベルを指定できますので、今回はその方法をとることにします。
設定ファイルの書き方などは、先程も参照した以下のページに記載されています。
まずWEB-INF/appengine-web.xmlファイルを編集し、ログ設定ファイルの在り処をアプリケーションに教えてあげる記述を追加します。
$ vim WEB-INF/appengine-web.xml
<?xml version="1.0" encoding="utf-8"?> <appengine-web-app xmlns="http://appengine.google.com/ns/1.0"> …(略)… <system-properties> <property name="java.util.logging.config.file" value="WEB-INF/logging.properties" /> </system-properties> </appengine-web-app>
通常は既にsystem-properties要素が存在すると思いますので、その中に追加してやればOKです。
次に、上で指定したログ設定ファイルを作成します。1から書いてもいいのですが、SDK中にサンプルが用意されているようですので、そいつを持ってきます。
$ cp ../appengine-java-sdk-1.2.1/config/user/logging.properties WEB-INF
サンプルのままだとログ出力レベルがWARNINGのままですので、ここはひとまずFINEにでも変えておくとします。*3
$ vim WEB-INF/logging.properties
# Set the default logging level for all loggers to WARNING #.level = WARNING .level = FINE
これで全てのログが出力されるようになります。*4
その他のログ出力方法
実は、JRubyからログ出力するには、java.util.logging.Loggerクラスを使う方法の他に、もっと手軽な方法もあるみたいです。
$servlet_context.log('hello')
$servlet_contextというのはJRuby-Rackによって定義されるグローバル変数のようですね。名前からなんとなく役割は推測できますが、あまり詳しく調べてはいません。
この$servlet_contextを使ったログ出力は、logメソッド一つのみで、レベルの指定などもできません。このメソッドで出力したログは常にINFOレベルとして扱われるようです。
レベルに拘らず、ちょっとログに出したい…というようなときは、こちらのほうがお手軽で良いかもしれませんね。
GAEKit::Loggerを使う
あとはもう好きなようにログ出力すればいいだけなのですが、せっかくなのでこれもラッパークラスを書いてみました。前回紹介したGAE Toolkitに追加してあります。
GAEKitモジュール内のLoggerクラスがそれです。
ライブラリのインストール方法などは前回の記事を参照してください。
使い方
java.util.logging.Loggerクラスの三種類のインスタンスのうち、どれを使うようにすればいいのかよくわからなかったので、とりあえず全部呼び出せるようにしました。
引数を与えてGAEKit::Logger.newした場合は、通常の名前付きロガーが返ります。引数には自分のクラス名でも渡しておけばOKなんじゃないかと思います。*5
logger = GAEKit::Logger.new(self.class.name) logger.info('This is a named logger.')
引数を与えずにGAEKit::Logger.newした場合は、匿名ロガーが返ります。
logger = GAEKit::Logger.new logger.info('This is an anonymous logger.')
インスタンスを作らず、クラスメソッドでログ出力することもできます。この場合はグローバルロガーが使われます。
GAEKit::Logger.info('This is a global logger.')
また、レベル別ログ出力の各メソッド名は、RubyのLoggerクラスのそれに合わせてあります。java.util.logging.Levelとの対応は以下のようになります。
logger.debug('hello') # = FINE logger.info('hello') # = INFO logger.warn('hello') # = WARNING logger.error('hello') # = SEVERE logger.fatal('hello') # = SEVERE
基本的にfatal以外はGAEダッシュボードでの表記そのままと思ってもらって構いません。
java.util.logging.Level側に対応するレベルが無いために、fatalをCriticalとして扱えないのが残念ですが…。自分で勝手に定義できるものなのでしょうか。
そうそうそれと、java.util.logging.Loggerはメッセージに続く引数として例外オブジェクトを渡すと、そのスタックトレースをログに出力することができるようなので、それっぽいこともできるようにしました。
begin raise 'This is a dummy error.' rescue logger.error('Caught error', $!) end
ログを読みやすくする
ダウンロード
これで手軽にログ出力できるようになったわけですが、個人的にGAEダッシュボードのログ表示画面は若干使いにくいような気がします。
それに、やっぱりログはテキスト形式で扱えたほうが、色々加工しやすくて便利ですよね。
GAEドキュメントの以下のページによると、ログをテキスト形式でダウンロードする手段も用意されているようです。
こんな感じでコマンドを実行すると、全てのログを"mylogs.txt"としてダウンロードできます。
$ ../appengine-java-sdk-1.2.1/bin/appcfg.sh --num_days=0 --severity=0 request_logs . mylogs.txt
オプションの説明は上のページの"Command-Line Arguments"あたりを参照してください。
フォーマットの加工
ダウンロードできたはいいんですが、なんか妙に見難いフォーマットなんですよね…。リクエスト毎に、出力されたログが1行にまとめられているみたいです。
60.32.80.93 - - [16/Jul/2009:02:35:50 -0700] "GET / HTTP/1.1" 200 148 "http://appengine.g oogle.com/" "Mozilla/5.0 (Windows; U; Windows NT 5.1; ja; rv:1.9.1) Gecko/20090624 Firefo x/3.5 (.NET CLR 3.5.30729) AutoPager/0.5.2.2 (http://www.teesoft.info/),gzip(gfe)"^@0:124 7736950.569000 sun.reflect.NativeMethodAccessorImpl invoke0: hello^@: ^@1:1247736950.5720 00 sun.reflect.NativeMethodAccessorImpl invoke0: hello^@: ^@2:1247736950.573000 sun.refle ct.NativeMethodAccessorImpl invoke0: hello^@: ^@3:1247736950.573000 sun.reflect.NativeMet hodAccessorImpl invoke0: hello^@: ^@3:1247736950.573000 sun.reflect.NativeMethodAccessorI mpl invoke0: hello^@:
さすがにこのままでは読めないので、RubyのLoggerっぽいフォーマットに加工するスクリプトを書いてみました。*6
#!/usr/bin/env ruby # coding: utf-8 require 'time' class Formatter LEVELS = { '0' => [ 'D', 'DEBUG' ], '1' => [ 'I', ' INFO' ], '2' => [ 'W', ' WARN' ], '3' => [ 'E', 'ERROR' ], '4' => [ 'F', 'FATAL' ], } def filter(src = STDIN, dst = STDOUT) src.readlines.reverse_each do |line| @index = (@index || 0).succ @session = sprintf("#%05d", @index) line.split("\0")[1..-1].each do |log| dst.puts log if log = format(log) end end end def format(log) return nil unless log.match(/^(\d?): ?(.*)$/) message = $2 return nil if message.strip.empty? @level = LEVELS[$1] || @level if message.match(/^(\d+)\.(\d+)\ (?:javax\.servlet\.ServletContext\ log| sun\.reflect\.NativeMethodAccessorImpl\ invoke0| sun\.reflect\.GeneratedMethodAccessor11\ invoke):\ (.*)$/x) message = $3 time = Time.at($1.to_i, $2.to_i) @date = time.strftime('%Y-%m-%dT%H:%M:%S') + sprintf('.%06d', time.usec) end "#{@level[0]}, [#{@date} #{@session}] #{@level[1]} -- : #{message}" end end Formatter.new.filter(ARGF)
ログファイルを引数に渡すか、もしくは標準入力に流し込みます。
$ ./format_gaelog.rb mylogs.txt
D, [2009-07-16T18:35:50.569000 #00020] DEBUG -- : hello I, [2009-07-16T18:35:50.572000 #00020] INFO -- : hello W, [2009-07-16T18:35:50.573000 #00020] WARN -- : hello E, [2009-07-16T18:35:50.573000 #00020] ERROR -- : hello E, [2009-07-16T18:35:50.573000 #00020] ERROR -- : hello
こんな感じにフォーマットして出力されます。一応、ある程度は読み易くなるのではないかと。
ちなみに、日付・時刻の後の#から始まる数値は、プロセスIDではなくリクエスト番号（そのログ中に出現した何番目のリクエストか）を表しています。この数値が同じであれば、同一のリクエスト内で出力されたログだということになります。
