Sinatra (Rack) のアクセスログをMongoDBに吐き出してみる

はじめに

昨日はExpressのアクセスログをMongoDBに吐き出してみる実験をしたわけですが、Sinatraで動いてるホストも10以上ありまして。インスタンス的にはExpressの方が多いのですが、ホスト的にはSinatraが一番多いんですね（Sinatraにvirtual host対応させてます）。なので、引き続きSinatraのアクセスログについて調査、MongoDBに吐き出せるようにしてみました。GitHubにてRamologで公開してあります。

Sinatraのアクセスログ介入

概要

SinatraのアクセスログはRack側で対処するのが正しそうです。RackにはCommonLoggerというのがあって、クラシックスタイルではこいつがデフォルトで動いています。モジュールスタイルでもenable :loggingで動き出すのがこれ。

Rackの層で置き換えれば良いのだな、とわかって検索すると、一行入魂さんのMongoDBにアクセスログを取るRack Middlewareというエントリを見つけました。そのものズバリで基本的な流れはそのまま使えそうです。フォーマットだけ前回作ったExpress/Node.js版のmomologに揃えて、最終的にはRubygems化する事にしました。クラウドで運用してると、どうでも良いコードでもパッケージ化するモチベーションが湧くのが面倒なところでもあり、またメリットでもありますね。

実装

call(env)を適切に実装してあげればOK。実際のリクエストはコンストラクタの第一引数に渡ってくるインスタンスが処理するので、そいつを呼んでstatus、header、bodyを取得します。こいつらは自分自身も呼び出し元にそっくりそのまま返してあげる必要があります。

class MyLogger
  def initialize(app)
    @app = app
  end

  def call(env)
    status, header, body = @app.call(env)
    # ここで好き勝手ログを書き出す
    [status, header, body]
  end
end

あとは

require 'sinatra'

configure do
  use MyLogger
end

これだけで置き換えられる。楽ちん。

ハマり場所

Rack::Request or env

一行入魂さんのようにreq = Rack::Request.new(env)してしまってreq経由で情報を集めるのも手なのですが、Rack::Request#accept_languageなんかはパースされた結果が配列で格納されてたりするのですが、すでにExpressの方では生データを吐き出していたので、それだったらとenv['HTTP_ACCEPT_LANGUAGE']をそのまま使う事にしました。

Content-Length

レスポンス系の情報は@app.call(env)から返ってきたheaderを使うことになります。header['Content-Length']で取れるんですが、ないこともあるのでheader['Content-Length'] or '-'とかする必要があります。僕の場合はContent-Lengthは数値として格納していたので(header['Content-Length'] or '-1').to_iで存在しない時は-1です。

REMOTE_ADDR

HerokuとかCloud9で実行してるとREMOTE_ADDRにはフロントエンドサーバのインターナルアドレスなんかが入ってたりしますね。なので、HTTP_X_FORWARDED_FORを使ってオリジナルのREMOTE_ADDRを辿る処理を追加しました。これ、Express版では対処できてなかったかも。後で対策考えないと……。

HTTP_X_FORWARDED_FORは複数回ルーティングされてきた場合にはカンマ区切りで複数のアドレスが入ってくるのでenv['HTTP_X_FORWARDED_FOR'].split(',')[-1]です。

RubyGems化

gems化についてはクラスメソッドさんのRubygemsでライブラリを公開したので、手順をまとめてみたを参考にしました。

credentialをcurlで取ってくる方法が紹介されてたんですが、情報が最新かわからなかったので、別の方法を取ることにしました。とりあえず気にせずにリリースを試みます。

toyoshim:~/workspace/thnet/ramolog (master) $ bundle exec rake release
gem build -V '/home/ubuntu/workspace/thnet/ramolog/ramolog.gemspec' 2>&1
ramolog 0.1.0 built to pkg/ramolog-0.1.0.gem.
git diff --exit-code 2>&1
git diff-index --quiet --cached HEAD 2>&1
git tag 2>&1
git tag -a -m "Version 0.1.0" v0.1.0 2>&1
Tagged v0.1.0.
git push  2>&1
git push  --tags 2>&1
Pushed git commits and tags.
rake aborted!
Your rubygems.org credentials aren't set. Run `gem push` to set them.
/usr/local/rvm/gems/ruby-2.2.1@global/gems/bundler-1.8.4/lib/bundler/gem_helper.rb:92:in `rubygem_push'
/usr/local/rvm/gems/ruby-2.2.1@global/gems/bundler-1.8.4/lib/bundler/gem_helper.rb:62:in `block in install'
Tasks: TOP => release => release:rubygem_push
(See full trace by running task with --trace)

ローカルにコミットしてないファイルがあると、ここで止まります。また、ログにあるように適切なtag付けやGitHubへのpushは勝手にやってくれます。

Gemfileの妥当性もチェックされるので、ポカミスとか見つけてくれる可能性もあります。私の場合、残念なtypoを指摘されて恥ずかしいcommitが入りました。

ここで油断してたんですが、gemspecの方のdependencyはチェックされないんですね（両方に定義が必要なことに気づいておらず、忘れたまま0.1.0をreleaseしてしまい、慌てて修正版の0.1.1をpushした）。

で、最後のabort。gem pushで設定できると言っているので従います。

toyoshim:~/workspace/thnet/ramolog (master) $ gem push
Enter your RubyGems.org credentials.
Don't have an account yet? Create one at https://rubygems.org/sign_up
   Email:   [e-mail]
Password:   

Signed in.
ERROR:  While executing gem ... (Gem::CommandLineError)
    Please specify a gem name on the command line (e.g. gem build GEMNAME)

最後はエラーですがSigned in.なのでOKでしょう（この辺り、いつも雑です）。もう一度releaseを実行してみます。

toyoshim:~/workspace/thnet/ramolog (master) $ bundle exec rake release
gem build -V '/home/ubuntu/workspace/thnet/ramolog/ramolog.gemspec' 2>&1
ramolog 0.1.0 built to pkg/ramolog-0.1.0.gem.
git diff --exit-code 2>&1
git diff-index --quiet --cached HEAD 2>&1
git tag 2>&1
Tag v0.1.0 has already been created.
gem push '/home/ubuntu/workspace/thnet/ramolog/pkg/ramolog-0.1.0.gem' 2>&1
Pushed ramolog 0.1.0 to rubygems.org.

成功。dependencyの記述が不完全だった0.1.0はgem yank ramolog -v 0.1.0で公開停止。これで一段落かな？

まとめ

Sinatraを含めたRackベースのフレームワークから、アクセスログをMongoDBに向けて吐き出すモジュールを作り、Rubygemsに登録してみました。それなりに使われているフレームワークでも、意外に小さくまとまっていて、ログの置き換えくらいだったら数十行のコードでできちゃうのは嬉しいです。気軽にRubygems化しちゃえば、後はHerokuの各インスタンスに対して数行の修正を入れるだけで済みますし。

追記：おまけ

Rack層で仕込むのでRailsでもそのまま動きますね。

Gemfile

...
gem "ramolog", "0.1.1"
...

config.ru

require 'ramolog'
use Ramolog::Logger, ENV['MONGOLAB_URI'], 'log'

# 以下、自分で使ってるRedMineの元々の設定
require ::File.expand_path('../config/environment',  __FILE__)
run RedmineApp::Application