Edited at

Railsのログをなんとかしたい人生だった


Railsのログ問題

便利なことにRailsは特に設定しなくてもproduction.logにログを吐いてくれる。エラーメッセージやSQL文も出力してくれるので助かる反面、以下のような問題点がある。


  • 1リクエストで複数行流れるので、エラー調査や緊急対応時にgrepできない

  • デフォルトだと若干冗長すぎる

  • Fluentd等のログの活用を考えた際にパースが非常に面倒

Rails.loggerをオレオレカスタマイズするのも無くはないが、メンテナンスのことも考えて、ログ出力用ライブラリLogrageを使ってJSON形式のログをスマートに出力するようにした。


Logrageとは

Railsのログのいい感じに出力してくれるライブラリ

https://github.com/roidrage/lograge

ちなみにLogrageの説明ではRailsのデフォルトログを「noisy and unusable, unparsable(騒々しい、使えない、パースできない)」とめっちゃDisってた。


インストール

Gemfileに以下を追記してbundle installするだけ

gem 'lograge'


設定

まず、Application Controllerにappend_info_to_payload()メソッドを追加する。


/app/controllers/application_controller.rb

def append_info_to_payload(payload)

super
payload[:ip] = request.remote_ip
payload[:referer] = request.referer
payload[:user_agent] = request.user_agent

payload[:login_id] = session[:login_id]
end


受け取ったpayloadにログに付けたい情報を格納していく。ここでは調査時に役立ちそうなIP、リファラー、ユーザーエージェントを入れてある。また、session[:login_id]のようにセッション情報も入れることができる。

そして、initializers以下にファイルを作成し、以下を記述


/config/initializers/logging.rb

Rails.application.configure do

config.lograge.enabled = true
config.lograge.keep_original_rails_log = true
config.lograge.logger = ActiveSupport::Logger.new "#{Rails.root}/log/lograge_#{Rails.env}.log"
config.lograge.formatter = Lograge::Formatters::Json.new

config.lograge.custom_options = lambda do |event|
exceptions = %w(controller action format authenticity_token)
data = {
level: 'info',
login_id: event.payload[:login_id],
ip: event.payload[:ip],
referer: event.payload[:referer],
user_agent: event.payload[:user_agent],
time: Time.now.iso8601,
params: event.payload[:params].except(*exceptions)
}
if event.payload[:exception]
data[:level] = 'fatal'
data[:exception] = event.payload[:exception]
data[:exception_backtrace] = event.payload[:exception_object].backtrace[0..6]
end
data
end
end


ポイントはいくつかあって、



  • config.lograge.keep_original_rails_log をtrueしてデフォルトのproduction.logも吐くように

  • さっきpayloadで格納したデータはevent.payloadで取得できるのでhash形式で入れていく

  • GETパラメータも調査時には十分役立つのでevent.payload[:params]で取得.except(*exceptions)しているのは好み

  • 例外が発生したとき自動的にevent.payload[:exception]にexceptionの内容が入る


    • その時はevent.payload[:exception_object].backtrace[0..6]でbacktrace(配列)を格納している。

    • 別に6個で切り捨てる必要はないが、多すぎるとログが読みづらくなるのである程度絞ったほうが吉




ログの出力

設定後にRailsを再起動してアクセスすると、 /log/lograge_#{Rails.env}.log に以下のようなJSONで吐かれていく。(下記は整形してあるが、本来は改行なしで1行) durationでリクエストにどのくらい時間が掛かったのかも自動で出力してくれる。

{

"method": "GET",
"path": "/posts",
"format": "html",
"controller": "PostsController",
"action": "index",
"status": 200,
"duration": 219.77,
"view": 213.64,
"db": 1.64,
"level": "info",
"login_id": null,
"ip": "127.0.0.1",
"referer": null,
"user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36",
"time": "2017-11-29T18:50:20+09:00",
"params": {
"author": "taro"
}
}

例外が発生した場合もしっかりexceptionとexception_backtraceが入る。

{

"method": "GET",
"path": "/posts",
"format": "html",
"controller": "PostsController",
"action": "index",
"status": 500,
"error": "ActionView::Template::Error: Mysql2::Error: Unknown column 'posts.author' in 'where clause': SELECT `posts`.* FROM `posts` WHERE `posts`.`author` = 'taro'",
"duration": 11.15,
"view": 0,
"db": 1.12,
"level": "fatal",
"login_id": null,
"ip": "127.0.0.1",
"referer": null,
"user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36",
"time": "2017-11-29T18:49:27+09:00",
"params": {
"author": "taro"
},
"exception": [
"ActionView::Template::Error",
"Mysql2::Error: Unknown column 'posts.author' in 'where clause': SELECT `posts`.* FROM `posts` WHERE `posts`.`author` = 'taro'"
],
"exception_backtrace": [
"/Users/hoge/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:120:in `_query'",
"/Users/hoge/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:120:in `block in query'",
"/Users/hoge/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:119:in `handle_interrupt'",
"/Users/hoge/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:119:in `query'",
"/Users/hoge/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:214:in `block (2 levels) in execute'",
"/Users/hoge/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/dependencies/interlock.rb:46:in `block in permit_concurrent_loads'",
"/Users/hoge/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activesupport-5.1.4/lib/active_support/concurrency/share_lock.rb:185:in `yield_shares'"
]
}


だがしかし

最初は自分もこれで満足していた。が、肝心なときにログを見返すとexceptionの内容がない。なぜなら

begin

response = RestClient.get 'http://example.com/not_found.json', {params: {id: 334} }
result = JSON.parse response.body
puts result
rescue => e
# エラー
Rails.logger.error("#{e.class} #{e.message}")
end

のようにbeginで囲ってしまっているからである。これではエラーログは結局production.logに吐かれるだけで、Logrageの恩恵を受けることができない。


対策

そこでLograge同様のJSON形式でログを吐くLoggerクラスを作ることに。。。


/config/initializers/logging.rb

class MyLogger

class << self
def run(attr, **options)
new.log(attr, **options)
end

def logger
@logger ||= MessageOnlyLogger.new(file)
end

def file
"#{Rails.root}/log/lograge_#{Rails.env}.log"
end

end

def log(attr, **options)
self.class.logger.debug log_attr(attr, **options)
end

private

def default_params
{ time: Time.zone.now }
end

def log_attr(attr, **options)
option = { level: "fatal" }
e = options[:error]
if e && e.is_a?(StandardError)
option[:exception] = [e.class.name, e.message]
option[:exception_backtrace] = e.backtrace[0..6]
end
default_params
.merge(payload_at_controller)
.merge(option)
.merge(attr)
.to_json
end

def payload_at_controller
i = binding.callers.index { |b| b.receiver.is_a?(ApplicationController) }
current_controller = binding.of_caller(i).receiver

payload = current_controller.instance_eval do
{}.tap { |h| append_info_to_payload(h) }
end
raw_payload = current_controller.instance_eval do
exceptions = %w(controller action format authenticity_token)
{
controller: self.class.name,
action: self.action_name,
params: request.filtered_parameters.except(*exceptions),
format: request.format.try(:ref),
method: request.request_method,
path: (request.fullpath rescue "unknown"),
ip: request.remote_ip
}
end
payload.merge(raw_payload)
rescue
{}
end
end

class MessageOnlyLogger < ActiveSupport::Logger
def call(_severity, _timestamp, _progname, message)
message
end
end


で、さっきの箇所を

begin

response = RestClient.get 'http://example.com/not_found.json', {params: {id: 334} }
result = JSON.parse response.body
puts result
rescue => e
MyLogger.run({ message: "JSONの読み込みに失敗した" }, error: e)
end

に変更するとLograge同様のJSONログが吐かれる。(本末転倒な気もするが

もっとよいRailsのロギングあったら教えてください。