2019年4月27日土曜日

Sinatra のロギングを考える

概要
環境
準備
サンプルアプリ
普通にロギング
thin を使った場合は
フォーマットを変更する
Sinatra のデフォルトのログのフォーマットが違う
実はモンキーパッチを使えば無理矢理フォーマットを変えることができる
標準出力には独自の logger だけ出力してデフォルトの Rack::CommonLogger はファイルに出力する
最後に
参考サイト

概要

Sinatra で logger を扱う方法を考えます
普通に logger を使えばいいのですが少し考慮すべきことがあるのでその辺りを踏まえて使い方などを紹介したいと思います

環境

macOS 10.14.4
Ruby 2.6.2p47
- sinatra 2.0.5

準備

bundle init
vim Gemfile

gem "sinatra"

bundle install --path vendor

サンプルアプリ

vim config.ru

require './app.rb'
run MyApp

vim app.rb

require 'sinatra/base'

class MyApp < Sinatra::Base
  get '/' do
    logger.info 'ok'
    'ok'
  end
end

bundle exec rackup config.ru
curl 'localhost:9292'

で動作するアプリを考えます

普通にロギング

素直に logger を使ってロギングします
クラス内で logger を定義するのがポイントです

require 'sinatra/base'
require 'logger'

# logger = Logger.new(STDOUT) # ここはダメ

class MyApp < Sinatra::Base
  # set :logger, Logger.new(STDOUT) # これもダメ
  logger = Logger.new(STDOUT)

  get '/' do
    logger.info 'ok'
    'ok'
  end
end

I, [2019-04-24T12:42:03.457670 #11026]  INFO -- : ok

thin を使った場合は

vim Gemfile

gem "thin"

bundle install --path vendor
bundle exec rackup config.ru

で追加して普通に起動してもこれまで通りログがでます

フォーマットを変更する

logger.formatter を使うだけです

require 'sinatra/base'
require 'logger'

class MyApp < Sinatra::Base
  logger = Logger.new(STDOUT).tap do |logger|
    logger.formatter = proc do |severity, datetime, progname, msg|
      "[#{datetime} #{severity}] #{msg}\n"
    end
  end

  get '/' do
    logger.info 'ok'
    'ok'
  end
end

logger.info の部分がこんな感じで表示されるようになります

[2019-04-24 13:53:15 +0900 INFO] ok

Sinatra のデフォルトのログのフォーマットが違う

デフォルトの Sinatra では標準出力に特定のパスへのアクセスログを出してくれます

::1 - - [24/Apr/2019:12:48:00 +0900] "GET / HTTP/1.1" 200 2 0.0192

これが logger.info を使った場合とは違います
内部的には Rack::CommonLogger の FORMAT を使っておりこれが定数です
基本的にはフォーマットは変えられないので Rack::CommonLogger のログを抑制します

require 'sinatra/base'
require 'logger'

module Rack
  class CommonLogger
    def call(env)
      # do nothing
      @app.call(env)
    end
  end
end

class MyApp < Sinatra::Base
  logger = Logger.new(STDOUT).tap do |logger|
    logger.formatter = proc do |severity, datetime, progname, msg|
      "[#{datetime} #{severity}] #{msg}\n"
    end
  end

  get '/' do
    logger.info 'ok'
    'ok'
  end
end

という感じでモンキーパッチを当てるか起動時に抑制するオプションを付与します

bundle exec rackup -q config.ru

実はモンキーパッチを使えば無理矢理フォーマットを変えることができる

上記の仕組みを使えば Rack::CommonLogger::FORMAT を書き換えることができます

module Rack
  class CommonLogger
    FORMAT = %{%s - %s [%s] "%s %s%s %s" %d %s %0.4f\n}
  end
end

class MyApp < Sinatra::Base
  logger = Logger.new(STDOUT).tap do |logger|
    logger.formatter = proc do |severity, datetime, progname, msg|
      "[#{datetime} #{severity}] #{msg}\n"
    end
  end

  get '/' do
    logger.info 'ok'
    'ok'
  end
end

フォーマットは Apache httpd の Common ログに合わせてあります
ただこのフォーマットに合わないとログが表示されなくなるだけなのでもしやるとしたら特定の文字列をくっつけるくらいしかできないかなと思います

また定数のオーバーライドになるので Ruby の警告文も出るのでおすすめはしません
基本は抑制して独自の logger だけを使って出力するようにしたほうが良いと思います

標準出力には独自の logger だけ出力してデフォルトの Rack::CommonLogger はファイルに出力する

なんてこともできます
enable :logging を設定してしまうと標準出力に出てしまうので設定しないようにしてください

require 'sinatra/base'
require 'logger'

class MyApp < Sinatra::Base
  configure do
    # enable :logging
    file = File.new("rack.log", 'a+')
    file.sync = true
    use Rack::CommonLogger, file
  end

  logger = Logger.new(STDOUT).tap do |logger|
    logger.formatter = proc do |severity, datetime, progname, msg|
      "[#{datetime} #{severity}] #{msg}\n"
    end
  end

  get '/' do
    logger.info 'ok'
    'ok'
  end
end

あとは起動する際に -q で抑制すれば OK です
-q よりも enable :logging が優先されてしまうので設定しないでねという感じです

bundle exec rackup -q config.ru

最後に

Sinatra のロギング戦略を考えてみました
デフォルトの Rack のログをどうするかがポイントかなと思います
個人的にはデフォルトは抑制してすべて独自の logger による出力でいいかなと思います
また独自の logger もすべて標準出力でいいかなと思います
というのも基本は docker で動かすので docker 側でロギングドライバを使ってどこかに飛ばすなりファイルに落とすなりすればいいかなと

hawksnowlog