Hatena::ブログ(Diary)

しばそんノート

2009-07-16

JRuby on Google App Engineでのログ出力

前置き

Google App Engine for Java(以下GAEJ)でJRubyスクリプトを書くにあたって、ログ出力をどうしたらいいのか、少し迷ってしまいませんか?

標準出力や標準エラー出力に書き出したデータは単に無視されるだけですし、書き込みモードでファイルを開けませんので、RubyLoggerクラスをそのまま使うことも出来ません。かといって、ログ出力無しでは何かと不便です。

ということで、GAEJ上のJRubyスクリプトでログ出力する方法を調べてみました。

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ではなくリクエスト番号(そのログ中に出現した何番目のリクエストか)を表しています。この数値が同じであれば、同一のリクエスト内で出力されたログだということになります。

*1:config〜finestの間ならなんでも

*2:ここでいうログ出力レベルは、GAEダッシュボードのログ表示画面における"Minimum Severity"とは別のものです。

*3:DEBUGレベルをFINESTに割り当てるのならFINEST、もしくはALLにします。

*4:今回はグローバルなログレベルを編集してしまいましたが、名前付きロガーで正しくログを分類している場合は、個別にデフォルトログレベルを指定したほうが良いのかもしれません。

*5:Javaではそんな感じのルールになってるみたい?

*6:sun.reflect.〜などの出力が邪魔なので無理矢理削ってますが、これって消せないんでしょうか。

2009-07-04

Google App EngineデータストアをRubyから簡単に使う

前置き

前回前々回あたりでとりあえずGoogle App Engine for Java(以下GAEJ*1)上でRubyスクリプトを動作させることができるようになりました。

が、どうしてもいつものRubyスクリプトとは勝手が違って、いまいちやりにくい気がします。

例えばデータの記録なんかも、両手で数え足りるような数のデータを記録するだけであれば、O/Rマッパー的な仕組みを使ってモデルを定義して…という作業も面倒です。もっと手軽に行いたいものですよね。

大人しくフレームワークでも使っておけ、という話もありますが、まぁそれはそれ…。

GAE Toolkit

そんなこんなで、あまり「GAEのデータストア」という存在を意識せずに手軽にデータの保存・取得を行えるように、簡単なラッパーを書いてみました。GitHubリポジトリに置いてあります。

"Tiny toolkit for JRuby on Google App Engine"などと銘打っていますが、まだデータストアにアクセスするためのクラスしかありません。このくらいのライブラリなら探せば他にいくらでもありそうですが、あともういくつか個人的に用意したい機能もある*2ので、後々追加していけたらな…と思います。

簡単な使い方

例えば次のようにしてGAEデータストア上にデータを保存できます。

GAEKit::Store.put(:name, 'Tanaka Tarou')
GAEKit::Store.put('age', 20) # キーは文字列でもシンボルでも同じ扱い
GAEKit::Store.put(:friends, [ 'Ichiro', 'Hanako', 'John' ])
GAEKit::Store[:location] = 'Tokyo/Japan' # putメソッドの別名

データの取り出しは次のような感じです。

GAEKit::Store.get(:name)
GAEKit::Store.get('age')
GAEKit::Store.get(:friends)
GAEKit::Store[:location] # getメソッドの別名

GAEデータストア上に記録されていますので、もちろんセッションをまたいで永続的に利用できます。

GAEKitモジュールをincludeしてしまえば、もっと手軽にアクセスできます。

include GAEKit
Store[:foo] = 'bar'
value = Store[:name]

その他のメソッドをさらっと。

Store.has_key?(:name) # 引数で指定したプロパティの存在確認
Store.include?(:name) # has_key?メソッドの別名
Store.delete(:name) # 引数で指定したプロパティの削除
Store.keys # 全プロパティの名前を配列で取得
Store.values # 全プロパティの値を配列で取得

インストール方法

gitをインストール済みの場合は

$ git clone git://github.com/shibason/rb-gaekit.git

でチェックアウトできます。

gitがインストールされていない場合は、下のページの"download"ボタンからダウンロードして適当な場所に展開してください。

必要なのはrb-gaekit/gaekit.rbファイル1つだけですので、これをWEB-INFディレクトリ以下の適当な場所に放り込みます。

$ cp rb-gaekit/gaekit.rb sample-application/WEB-INF

あとは上記のファイルをrequireすれば使えるようになります。

require 'gaekit'

もう少し詳しい説明

格納できるデータ

数値や文字列、nil/true/falseなどの基本的な値はもちろん、配列も格納できます。

ただしネストした配列は格納できません。また、ハッシュを始めとしたその他のオブジェクトも格納不可です。*3

サブクラスの活用

GAEKit::Storeクラスはそれ自身がGAEデータストアの一つのエンティティと対応しており、エンティティの識別子として自身のクラス名を使っています。

つまり、GAEKit::Storeを継承したサブクラスを作成すると、それをもう一つの別のエンティティとして利用することができます。

include GAEKit

class MyStore < Store; end

Store[:name] = 'Tanaka Tarou'
MyStore[:name] = 'Suzuki Ichiro'

[ Store[:name], MyStore[:name] ] # => ["Tanaka Tarou", "Suzuki Ichiro"]

なお、GAEKit::Storeクラス及びそのサブクラスに対応するエンティティのkind値は"GAEKit::Datastore"となっています。

GAEデータストアの制限

データの実体はGAEデータストアに保存されますので、GAEKit::Storeに格納可能なデータについても、当然GAEデータストアが持つ各種制限をそのまま受け継ぎます。

GAEデータストアの制限は以下のページなどを参考にしてください。

GAEKit::Storeでは一つのエンティティに全てのデータを突っ込みますので、大量のデータ、もしくはサイズの大きなデータを保存する場合は、きちんとモデルを定義して使うタイプの他のライブラリを利用することをお勧めします。

また、APIの呼び出し回数制限にも注意が必要です。GAEKit::Store#[]=やGAEKit::Store#deleteなどの書き込みメソッドは、その呼出し毎に内部でGAEデータストアのAPIを呼んでいますので、例えばループの中でこれらのメソッドを呼んでいると、APIの呼び出し回数が嵩むばかりでなく、処理速度にも大きな影響を及ぼします。

ループで処理する際は一時変数に退避して、全ての処理が完了してからデータストアに反映する、といった処理を行うようにした方が安全です。

参考資料

GAEデータストアの基本的な使い方はGoogleのドキュメントを参照しました。

JRubyからJavaクラスを呼ぶときの約束事や、オブジェクトの型変換などについては以下のサイトを参考にさせて頂きました。

GitHubの使い方については以下のサイトを参考にさせて頂きました。

*1:GAEjのほうが一般的な表記でしょうか?

*2:むしろそっちが本命だったりもするのですが

*3:Marshal.dumpとMarshal.loadを使えばある程度はいけるかも。

Connection: close