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: event.time.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で吐かれていく。（下記は整形してあるが、本来は改行なしで１行）　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