Sinatraのロギング機構について調べてみた

Sinatraのloggerヘルパーを使ったところ、なぜか標準エラーの出力先にログが吐かれており、標準出力の出力先にはログが吐かれない。
標準出力先にログを吐くものだと思っていたのだが、自分が想定していた挙動と違うので調べてみた。

まずは、Sinatraのloggerヘルパーのソースコードを確認してみる。

1
2
3
def logger
  request.logger
end

https://github.com/sinatra/sinatra/blob/939ce04c1b77d24dd78285ba0836768ad57aff6c/lib/sinatra/base.rb#L327

request.loggerを返している。
レシーバであるrequestは rack::requestなので、rack::request#loggerは何を返しているかを確認する。

1
def logger; get_header(RACK_LOGGER) end

https://github.com/rack/rack/blob/master/lib/rack/request.rb#L136

get_headerは@envから引数に与えられた値を返すだけのメソッド。

1
2
3
def get_header(name)
  @env[name]
end

RACK_LOGGERは以下のように定義されている。

1
RACK_LOGGER = 'rack.logger'.freeze

https://github.com/rack/rack/blob/9073125f71afd615091f575d74ec468a0b1b79bf/lib/rack.rb#L64

ここまでで、loggerヘルパーはenv['rack.logger’]を取得していることがわかった。

では、rack.loggerには何が設定されているのかという疑問が湧いてくる。
rackには3つのロガーがある。

  • CommonLogger
  • Logger
  • NullLogger

このうち、LoggerとNullLoggerがRACK_LOGGERにセットしていた。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
# Rack::Logger
require 'logger'

module Rack
  # Sets up rack.logger to write to rack.errors stream
  class Logger
    def initialize(app, level = ::Logger::INFO)
      @app, @level = app, level
    end

    def call(env)
      logger = ::Logger.new(env[RACK_ERRORS])
      logger.level = @level

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

# Rack::NullLogger
module Rack
  class NullLogger
    def initialize(app)
      @app = app
    end

    def call(env)
      env[RACK_LOGGER] = self
      @app.call(env)
    end
    ...........

通常、Rack::Loggerが使われる。
Rack::LoggerはRubyのloggerライブラリのラッパーで、log deviceにenv[RACK_ERRORS]をセットしている。
env[RACK_ERRORS]が何かを調べたところ、基本的には$stderrがセットされるようだ。

(例)webrickの場合は、$stderrがセットされている。

1
2
3
4
5
6
7
8
9
10
11
12
env.update(
  RACK_VERSION => Rack::VERSION,
  RACK_INPUT => rack_input,
  RACK_ERRORS => $stderr,
  RACK_MULTITHREAD => true,
  RACK_MULTIPROCESS => false,
  RACK_RUNONCE => false,
  RACK_URL_SCHEME => ["yes", "on", "1"].include?(env[HTTPS]) ? "https" : "http",
  RACK_IS_HIJACK => true,
  RACK_HIJACK => lambda { raise NotImplementedError, "only partial hijack is supported."},
  RACK_HIJACK_IO => nil
)

https://github.com/rack/rack/blob/95172a60fe5c2a3850163fc75e0981fe440c064e/lib/rack/handler/webrick.rb#L68

ということで、結果的にSinatraのloggerは標準エラーに出力されることになる。

アプリケーションログを任意のファイルに出力するには

任意のファイルにログを出力したい場合は、自前でloggerを定義してやればよい。

1
2
3
4
5
6
7
8
def logger
  return @logger unless @logger.nil?
  file = File.new("#{settings.root}/log/#{settings.environment}.log", 'a+')
  file.sync = true
  @logger = ::Logger.new(file)
end

logger.info "Hello"

参考リンク

Guardでrspecのテストを自動化する

自動化ツールのGuardの紹介をします。
Guardはファイルを監視して、ファイルになんらかの変更がされたら、指定した処理を実行するツールです。
この機能を使ってファイルが変更されたらテストを自動で実行させたり、シンタックスチェックをすることができます。
今回はrspecで自動的にテストを実行する方法を紹介します。

まずはGuardのinstallをします。
Gemfileに定義してインストールします。

Gemfile

1
2
3
4
group :development do
  gem 'guard'
  gem 'guard-rspec', require: false
end

bundle installして、Guardfileを作成します。
GuardfileはGuardの設定を定義するファイルです。

1
2
$ bundle install
$ bundle exec guard init rspec

guard init rspecを実行するとrspecの設定が書かれたGuardfileが作成されます。
Railsを想定した設定が書かれていますので、Railsの場合はそのままでOKです。

ファイルが実行されたらrspecを実行する

ファイルが実行されたらrspecを実行するようにしましょう。
別でウィンドウを開いてguardを実行します。 

1
$ bundle exec guard

ファイルを変更するとそのファイルのテストが実行され、テスト結果が表示されます。

Guard-rspecのDSL

Guardの設定はGuardのDSLを用いて設定します。

1
2
3
4
5
6
7
# rspecのグループを定義し、監視しているファイルに変更があった場合は"bundle exec rspec""を実行する。
guard :rspec, cmd: "bundle exec rspec" do
  # Guard::RspecのDSLのインスタンスを作成
  dsl = Guard::RSpec::Dsl.new(self)
  rspec = dsl.rspec
  watch(rspec.spec_helper) { rspec.spec_dir }
end

watchで監視するファイルを設定します。
watchの引数は以下です。 

1
watch(監視するファイル) { コマンドに渡される引数 }

ここででてきた、rspec.spec_helper と rspec.spec_dir はどんな値を返すのでしょうか。
pryで覗いてみましょう。

1
2
3
4
5
6
7
8
$ pry
> require 'guard/rspec/dsl'
> dsl = Guard::RSpec::Dsl.new(self)
> rspec = dsl.rspec
> rspec.spec_helper
=> "spec/spec_helper.rb"
> rspec.spec_dir
=> "spec"

ソースを少し見てみましょう。

1
2
3
4
5
6
7
8
9
def rspec
  @rspec ||= OpenStruct.new(to_s: "spec").tap do |rspec|
    rspec.spec_dir = "spec"
    rspec.spec = -(m) { Dsl.detect_spec_file_for(rspec, m) }
    rspec.spec_helper = "#{rspec.spec_dir}/spec_helper.rb"
    rspec.spec_files = %r{^#{rspec.spec_dir}/.+_spec\.rb$}
    rspec.spec_support = %r{^#{rspec.spec_dir}/support/(.+)\.rb$}
  end
end

https://github.com/guard/guard-rspec/blob/master/lib/guard/rspec/dsl.rb#L28

実装にはOpenStructが使われています。
OpenStructとは要素を動的に追加・削除できる手軽な構造体を提供するクラスです
http://docs.ruby-lang.org/ja/2.1.0/class/OpenStruct.html

要素を追加するためにtapメソッドを使っています。
OpenStructとtapメソッドをうまく使っていますね。

実は、というか当たり前なのですがOpenStructなので値の上書きも簡単にできてしまいます。

1
2
3
4
5
6
> rspec.spec_helper
=> "spec/spec_helper.rb"
> rspec.spec_helper = 'hoge'
=> "hoge"
> rspec.spec_helper
=> "hoge"

Guardのカスタマイズ

Guardの様々なプラグインが開発されています。
プラグインは以下のページで参照できます。
https://github.com/guard/guard/wiki/Guard-Plugins

ちなみに、今回使ったguard-rspecもGuardのプラグインです。
他にも様々なプラグインが用意されています。

関連記事

Chefのworkerが詰まって処理が進まなくなった

chefを実行したらこんなメッセージがでた。

1
WARN: Chef client 24431 is running, will wait for it to finish and then run.

前回実行したChefが途中で詰まってしまい、ウンともスンとも言わなくなったので Ctrl + Cでとめたが、プロセス自体は残ってしまっている。

こんな感じで2つchef-clientのworkerが立ち上がっている状態。

1
2
3
4
5
6
7
[shoyan@server01 ~]$ ps aux | grep chef
root     24373  0.0  0.1 178168  2992 ?        Ss   10:22   0:00 sudo -p knife sudo password:  chef-client -S http://127.0.0.1:18889
root     24426  0.0  3.1 262164 61072 ?        Sl   10:22   0:01 /opt/chef/embedded/bin/ruby /usr/bin/chef-client -S http://127.0.0.1:18889
root     24431  0.0  7.1 1078932 138052 ?      Sl   10:22   0:03 chef-client worker: ppid=24426;start=10:22:49;
root     26701  0.0  0.1 178168  2996 pts/3    Ss+  10:50   0:00 sudo -p knife sudo password:  chef-client -S http://127.0.0.1:18889
root     26754  0.0  3.1 261996 60896 pts/3    Sl+  10:50   0:01 /opt/chef/embedded/bin/ruby /usr/bin/chef-client -S http://127.0.0.1:18889
root     26759  0.0  3.0 261996 57760 pts/3    Sl+  10:50   0:00 chef-client worker: ppid=26754;start=10:50:38;

1時間ほど経過しても何も進まないので、プロセスをkillしてみた。

TERMシグナルを送ってみたが、反応なし。

1
# kill -s TERM 24431

killシグナルを送るとプロセスが終了し、ペンディング状態となっていたChefが実行された。

1
# kill -s KILL 24431

マカレルでサーバーを監視する

サーバーの監視にマカレルを導入してみました。
使ってみた感想としては、難しい設定もなく簡単に導入することができて、とてもよくできているなぁと関心しました。

マカレルエージェントのインストール

マカレルでサーバーを監視をするには監視対象のサーバーにマカレルエージェントをインストールする必要があります。
また、事前に申し込みをして、apikeyを発行しておく必要があります。

マカレルエージェントのインストールはChefを使って行います。
cookbook-mackerel-agentを使いました。

metadata.rb

1
depends 'mackerel-agent'

recipes/default.rb

1
2
3
include_recipe 'mackerel-agent'
include_recipe 'mackerel-agent::plugins'
yum_package 'mackerel-check-plugins'

cookbook-mackerel-agentだけだとcheckプラグインが入らなかったのでyum_packageリソースを使ってインストールしています。

attributes/default.rb

1
2
3
default['mackerel-agent']['package-action'] = 'upgrade'
default['mackerel-agent']['conf']['apikey'] = ‘API KEYをかく'
default['mackerel-agent']['conf']['plugins'] = true

サーバーにレシピを適用するとマカレルの管理画面にサーバーがでてくるのでロールを設定します。
これでサーバーのメトリクスを見ることができます。

プラグインを使う

マカレルには様々なプラグインが用意されています。
使い方はgithubのREADMEに書いてあります。
https://github.com/mackerelio/mackerel-agent-plugins

自分はプラグインを使って以下のことを行っています。

linuxマカレルプラグインを使って様々なメトリクスをだす

linuxマカレルプラグインを使えばswapやnetstat、Disk read time 等のグラフを表示することができます。

attributes/default.rb に以下を定義します。

1
default['mackerel-agent']['conf']['plugin.metrics.linux']['command'] = '/usr/local/bin/mackerel-plugin-linux'

Unicornマカレルプラグインを使ってUnicornのメトリクスをだす

Unicornマカレルプラグインを使えばダッシュボードにUnicornのメモリとワーカ数のグラフが表示されます。

attributes/default.rb に以下を定義します。

1
default['mackerel-agent']['conf']['plugin.metrics.unicorn']['command'] = "/usr/local/bin/mackerel-plugin-unicorn -pidfile=/var/www/app/shared/tmp/pids/unicorn.pid"

httpの監視

httpのレスポンスをチェックして監視を行います。
細かい設定を行いたい場合は、check-tcpがよいですが、単純なチェックでよいのであればhttpのほうが設定が簡単です。

attributes/default.rb に以下を定義します。

1
default['mackerel-agent']['conf']['plugin.checks.http']['command'] = "/usr/bin/check-http -u http://localhost"

ログファイルの監視

nginxのログファイルを監視し、500系のエラーが頻発したときは通知するようにします。

attributes/default.rb に以下を定義します。

1
/usr/bin/check-log --file /var/log/nginx/access.log --pattern 'HTTP/1\.[01]" [5][0-9][0-9] ' --warning-over 3 --critical-over 10 --return

監視ルールの設定

監視ルールを設定することで閾値を超えた際に通知をすることができます。
CPU、メモリ、ロードアベレージ、ディスク容量等の監視を管理画面より設定できます。
詳しい設定方法については以下を参照ください。

Slackに通知する

何か異常が起きた場合はSlackに通知をするようにします。
こちらも管理画面から設定できます。
具体的な設定方法については、ドキュメントを参照ください。

参考リンク

Google spreadsheetsを使ってデータの分析をする

データの分析によく使われるエクセルですが、Google Spreadsheetsでも様々な関数が用意されています。
関数を使えば日付の差分を調べたり、特定の条件に一致するデータをカウントすることができます。
Google Spreadsheetsを使ってデータの集計、分析をするためのTipsの紹介をします。

日付の差分を調べる

例えばユーザーの契約日数を調べたいとしましょう。
DATEVALUEを使って以下のように計算できます。

1
=DATEVALUE("2016/05/17") - DATEVALUE("2016/05/01")

セルを指定することもできます。

1
=DATEVALUE(A2) - DATEVALUE(A1)

月で表示したい場合は30で割ります。
FLOORは小数点を切り捨てるために使っています。

1
=FLOOR((DATEVALUE("2016/05/17") - DATEVALUE("2015/05/01"))/30, 0.1)

特定の条件をカウントする

例えば、契約期間が1年未満のユーザーをカウントする場合はCOUNTIFSを使います。

1
=COUNTIFS(A1:A1000, "<365")

COUNTIFSは複数条件を指定できます。
契約期間が1年以上〜2年未満のユーザーをカウントするということができます。

1
=COUNTIFS(A1:A1000, ">=365", I3:I1009, "<730")

点数を分析する

平均点を求めることは AVERAGE を使えばできます。
平均だけでなくばらつきを求めると違った角度でデータを捉えることができます。
ばらつきは標準偏差を求める関数 STDEVPで求めることができます。

1
= STDEVP(A1:E1)

例えばそれぞれの項目にたいして点数をつけるアンケートがあるとします。
以下の2つの項目は平均点は同じですが、標準偏差を求めるとばらつきがあることがわかります。
標準偏差を使えばこのようなデータを見つけることができます。

点数 平均点 標準偏差
6 7 9 7 6 7 1.095445115
8 5 10 7 5 7 1.897366596

サンプルを用意しました。参考にどうぞ。
https://docs.google.com/spreadsheets/d/1bOc3s8ikFcbBPGuzxDbRzd8KVT00lgQUDz275TJAIoE/edit#gid=0