Sinatra でアプリケーションログをファイルに書く方法。

Sinatra はじめて触ったんだけど、ログをファイルに書く方法がなかなかわからなかった。

ログを、ただファイルに書きたいのです。

結論

独自のミドルウェアで env['app.logger'] を設定し、アプリケーションのloggerメソッドをオーバーライドする。

参考

ruby - Use Rack::CommonLogger in Sinatra - Stack Overflow

これに書いてある通りだった。面倒くさいー。

サンプル

以下でログがファイルに出力される。アクセスログとアプリケーションログを別のファイルに出力することもできる。

config.ru

Loggerを作ってミドルウェアに渡す。

require 'logger'
require 'sampleapp'
require 'applog'

logdir = File.dirname(__FILE__) + "/logs"
logger = ::Logger.new(logdir + '/app.log')

# CommonLoggerに渡すのに必要。
def logger.write(msg)
  self << msg
end

use AppLog, logger

# rackup(rack/server.rb)が設定するCommonLoggerは$stderrに、
# sinatra(sinatra/base.rb) が設定するCommonLoggerはenv['rack.errors'] に
# 出力しようとする。ファイルに書くため、独自に use する。
use Rack::CommonLogger, logger

run SampleApp

applog.rb

env['app.logger'] を設定するミドルウェア。app.loggerは自分が適当につけた名前。

class AppLog

  def initialize(app, logger)
    @app, @logger = app, logger
  end

  def call(env)
    env["app.logger"] = @logger
    @app.call(env)
  end

end

sampleapp.rb

アプリケーション。loggerメソッドは元々、request.loggerを返していて、request.loggerはenv['rack.logger']を返している。app.logger があればそちらを優先するようにする。

require 'sinatra/base'

class SampleApp < Sinatra::Base

  def logger
    env['app.logger'] || env['rack.logger']
  end

  get '/' do
    logger.info "OK"
    'OK'
  end

end

Rackのしくみ

アプリケーションをラップするミドルウェアがタマネギ状になってて、外から call(env) が順によばれていく。コアにあるアプリがenvからリクエストを得てレスポンスを返す。

ミドルウェアが call(env) で env['rack.logger'] を設定している。アプリはこのロガーを使いたいのだが、なぜか標準エラーにしか出力してくれない。

三種の logger

Rack::CommonLogger
Rack::Logger
Rack::NullLogger

このうち、下の2つが env['rack.logger'] を設定していた。Rack::Loggerだと下のような感じ。

    def call(env)
      logger = ::Logger.new(env['rack.errors'])
      logger.level = @level

      env['rack.logger'] = logger
      @app.call(env)
    end

NullLogger は何も出力しないロガー。

Rack::CommonLogger とは

Rack::CommonLogger はアプリケーションの実行後に、Apache形式でアクセスログを書くロガー。アプリケーションログと関係ない。

sinatra/base.rb と rack/server.rb に CommonLogger を設定する処理があり、環境によって、どちらか一方が使われる。

Sinatra が足す CommonLogger

Sinatra は base.rb の setup_default_middleware というメソッドでロガーを足している。

-E オプションで指定できる環境が development や deployment の場合は設定しない。
CommonLogger に引数は渡されておらず、デフォルトの env['rack.errors'] が出力先。

Rack が足す CommonLogger

rackup を実行すると、 rack/server.rb の buildapp メソッドが CommonLogger を追加する。

-E オプションで指定できる環境が development や deployment の場合に設定する。
Sinatra と条件が逆。Rack が設定しないなら Sinatra が設定する。
CommonLogger の引数は $stderr 。env['rack.errors'] ではない。
rackup が足す、その他のミドルウェアは self.logging_middleware と self.middleware メソッドのソースを参照。

Sinatra と Rack 、どっちにしてもエラー出力にログを出力する。

Rack::Logger とは

Rack::Logger は、標準の Logger を env['rack.logger'] に設定するミドルウェア。Logger の引数は env['rack.errors'] で固定。エラー出力にログを出力する。

Rack::Logger は、 Sinatra が追加していた。setup_default_middleware メソッドから呼ばれる setup_logging → setup_custom_logger メソッドを参照。enable :logging をしても、出力先は env['rack.errors'] になってしまう。

env['rack.errors'] を設定するのは誰なのか

自分の環境だと Thin が設定してた。サーバが設定する値。

ruby - Use Rack::CommonLogger in Sinatra - Stack Overflow

の最後の回答で言われているように、標準エラー出力をファイルにリダイレクトする選択肢もあるようだが、もうちょっとマシな方法を探った。

CommonLogger が $stderr を使っているので、 evn['rack.errors'] を上書きするだけではダメだろうと思う。

ミドルウェアの呼ばれる順序とログ出力

独自のミドルウェアで env['rack.logger'] を入れ替えればいいのでは、と思ったのだが、config.ru にミドルウェアを足すと、call(env)される順序は、

rack/server.rb が設定した Rack::CommonLogger
config.ru が設定したミドルウェア
sinatra/base.rb が設定した Rack::Logger

になってしまう。自分が設定した rack.logger が Sinatra の Logger で上書きされてしまう。

結果として

アプリケーションでLoggerを直接使う。あるいは、上記サンプルのように、 app.logger を設定して loggerメソッドを上書きするのが、いくらかスマートだと思う。

CommonLogger はそのままだと使えないので、別に自前のをもう一個設定する。

追記

確認に使ったバージョンは以下のとおり。

Rack 1.4.1
Sinatra 1.3.2
Thin 1.3.1

やっぱり冷静に考えると rack.logger が使えないのはおかしいので、サーバで rack.errors を制御するのが、設計の意図なのかもしれない。ただ、現バージョンの rackup -D でデーモンとして起動する場合に、rack.errors を設定する方法はみつけられなかった。