RubyOnRailsでlograge/lograge-sqlを使ってJson形式のログ出力

lograge/lograge-sqlについて

lograge/lograge-sqlを使うとRailsのログや実行SQLなどの複数行のログをJsonなどの形式でログを簡単に見やすくして出力可能

lograge

logrageはRailsの基本Logggerの複数ラインのログを必要な情報だけにして1行のLog（例：json）を出力できるGemです。
https://github.com/roidrage/lograge

lograge

{"method":"GET","path":"/xxxxx","format":"html","controller":"Test::TestController","action":"index","status":200,"duration":109.04,"view":80.24,"db":0.0,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007faac342cd70>","view_runtime":80.24499999919499,"db_runtime":0,"custom_payload":{"timestamp":"2020-06-17 08:43:23 +0900","request_id":"25e160cb-1dcb-4b19-8eb2-9253f35b4f93","remote_ip":"127.0.0.1"},"operator_name":"Tester","email":"[e-mail]","timestamp":"2020-06-17 08:43:23 +0900","request_id":"25e160cb-1dcb-4b19-8eb2-9253f35b4f93","remote_ip":"127.0.0.1"}

lograge-sql

lograge-sqlはログにSQLを出力するlogrageの拡張Gem
https://github.com/iMacTia/lograge-sql

lograge-sql

{
    "sql_queries": "name1 ({duration1}) {query1}\nname2 ({duration2}) query2 ...",
    "sql_queries_count": 3
}

使い方

Rails Tutorialのソースからやってみます。
https://github.com/yasslab/sample_app

lograge

1) Gemfileにlograge追加

Gemfile

gem "lograge"

2) 以下のどちらかにlograge設定

config/environments/develpment.rb

  config.lograge.enabled = true

3) bundel installでGem設置
4) rails sサーバー起動

lograge使用前

Started GET "/" for 127.0.0.1 at 2020-06-17 15:01:01 +0900
   (0.1ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
  ↳ /Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
Processing by StaticPagesController#home as HTML
  User Load (0.3ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?  [["id", 101], ["LIMIT", 1]]
  ↳ app/helpers/sessions_helper.rb:13
  Rendering static_pages/home.html.erb within layouts/application
   (0.6ms)  SELECT COUNT(*) FROM "microposts" WHERE "microposts"."user_id" = ?  [["user_id", 101]]
  ↳ app/views/shared/_user_info.html.erb:4
  Rendered shared/_user_info.html.erb (3.3ms)
   (0.5ms)  SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."followed_id" WHERE "relationships"."follower_id" = ?  [["follower_id", 101]]
  ↳ app/views/shared/_stats.html.erb:5
   (0.5ms)  SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."follower_id" WHERE "relationships"."followed_id" = ?  [["followed_id", 101]]
  ↳ app/views/shared/_stats.html.erb:11
  Rendered shared/_stats.html.erb (16.1ms)
  Rendered shared/_error_messages.html.erb (0.6ms)
  Rendered shared/_micropost_form.html.erb (13.9ms)
   (0.2ms)  SELECT COUNT(*) FROM "microposts" WHERE (user_id = 101)
  ↳ app/views/shared/_feed.html.erb:1
  Rendered shared/_feed.html.erb (1.3ms)
  Rendered static_pages/home.html.erb within layouts/application (46.9ms)
  Rendered layouts/_shim.html.erb (0.4ms)
  Rendered layouts/_header.html.erb (1.0ms)
  Rendered layouts/_footer.html.erb (0.4ms)
Completed 200 OK in 610ms (Views: 543.5ms | ActiveRecord: 3.2ms)

lograge使用後

   (0.2ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
  ↳ /Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
  User Load (0.2ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?  [["id", 101], ["LIMIT", 1]]
  ↳ app/helpers/sessions_helper.rb:13
   (7.0ms)  SELECT COUNT(*) FROM "microposts" WHERE "microposts"."user_id" = ?  [["user_id", 101]]
  ↳ app/views/shared/_user_info.html.erb:4
   (0.4ms)  SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."followed_id" WHERE "relationships"."follower_id" = ?  [["follower_id", 101]]
  ↳ app/views/shared/_stats.html.erb:5
   (0.4ms)  SELECT COUNT(*) FROM "users" INNER JOIN "relationships" ON "users"."id" = "relationships"."follower_id" WHERE "relationships"."followed_id" = ?  [["followed_id", 101]]
  ↳ app/views/shared/_stats.html.erb:11
   (0.1ms)  SELECT COUNT(*) FROM "microposts" WHERE (user_id = 101)
  ↳ app/views/shared/_feed.html.erb:1
method=GET path=/ format=html controller=StaticPagesController action=home status=200 duration=663.54 view=564.69 db=9.17

最後行にRootパースの接続結果が1行で出力されている

---

Json形式で出力したい場合は以下を追加

config/environments/develpment.rb

config.lograge.formatter = Lograge::Formatters::Json.new

Rootに接続した結果がJson形式で表示される。

Json形式

{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":200,"duration":694.98,"view":592.73,"db":3.04}

---

Hookを追加してログをカスタマイズ

config.lograge.custom_options追加

config/environments/develpment.rb

config.lograge.custom_options = ->(event) {
    exceptions = %w(controller action format authenticity_token)
    payload = event.payload
    payload[:params] = payload[:params].except(*exceptions) #controller, action名を排除

    # exceptionが発生された場合、Exceptionとbacktraceを出力
    if payload[:exception]
      payload[:exception] = payload[:exception]
      payload[:exception_backtrace] = payload[:exception_object].backtrace[0..6]
    end
    payload
  }

controllerにraiseでExceptionを発生させる

static_pages_controller.rb

def home
    raise "error"
end

Root接続した後のローグ

Hook追加前（StaticPagesController）

{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":500,"error":"RuntimeError: error","duration":6.77,"view":0.0,"db":0.0,"sql_queries":"' (0.13) SELECT \"schema_migrations\".\"version\" FROM \"schema_migrations\" ORDER BY \"schema_migrations\".\"version\" ASC'","sql_queries_count":1}

Hookを追加したので、exceptionとexception_backtraceが追加された

Hook追加後

{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":500,"error":"RuntimeError: error","duration":0.51,"view":0.0,"db":0.0,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007f8ed7971e78>","view_runtime":null,"db_runtime":0,"exception":["RuntimeError","error"],"exception_object":"error","exception_backtrace":["/Users/xxxx/Desktop/ruby/sample_app/app/controllers/static_pages_controller.rb:9:in `home'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:194:in `process_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/action_controller/metal/rendering.rb:30:in `process_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:132:in `run_callbacks'","/Users/xxxx/.rbenv/versions/2.3.7/lib/ruby/gems/2.3.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:41:in `process_action'"]}

---

Controllerにappend_info_to_payload関数をOverridingすることでPayloadに項目追加

StaticPagesController

class StaticPagesController < ApplicationController
  def append_info_to_payload(payload)
    super
    payload[:host] = request.host
  end
end

Host情報が追加されている"host":"localhost"

追加後

{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":200,"duration":1321.96,"view":1148.47,"db":3.28,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007fc6e8869d98>","view_runtime":1148.4679999998662,"db_runtime":3.281999999217078,"host":"localhost","sql_queries":"' (0.27) SELECT \"schema_migrations\".\"version\" FROM \"schema_migrations\" ORDER BY \"schema_migrations\".\"version\" ASC\nUser Load (0.51) SELECT  \"users\".* FROM \"users\" WHERE \"users\".\"id\" = ? LIMIT ?\n (0.4) SELECT COUNT(*) FROM \"microposts\" WHERE \"microposts\".\"user_id\" = ?\n (0.51) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"followed_id\" WHERE \"relationships\".\"follower_id\" = ?\n (0.42) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"follower_id\" WHERE \"relationships\".\"followed_id\" = ?\n (0.15) SELECT COUNT(*) FROM \"microposts\" WHERE (user_id = 101)'","sql_queries_count":6}

lograge-sql

1) Gemfileにlograge-sql追加

Gemfile

gem "lograge-sql"

2) require追加

config/initializers/lograge.rb

require 'lograge/sql/extension'

3) bundel installでGem設置
4) rails sサーバー起動

sql_queriesとsql_queries_countが追加されていることが確認できました。

結果

{"method":"GET","path":"/","format":"html","controller":"StaticPagesController","action":"home","status":200,"duration":93.2,"view":84.45,"db":0.76,"params":{},"headers":"#<ActionDispatch::Http::Headers:0x00007fedb15158a0>","view_runtime":84.45099999994454,"db_runtime":0.7550000000264845,"sql_queries":"'User Load (0.13) SELECT  \"users\".* FROM \"users\" WHERE \"users\".\"id\" = ? LIMIT ?\n (0.14) SELECT COUNT(*) FROM \"microposts\" WHERE \"microposts\".\"user_id\" = ?\n (0.14) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"followed_id\" WHERE \"relationships\".\"follower_id\" = ?\n (0.18) SELECT COUNT(*) FROM \"users\" INNER JOIN \"relationships\" ON \"users\".\"id\" = \"relationships\".\"follower_id\" WHERE \"relationships\".\"followed_id\" = ?\n (0.16) SELECT COUNT(*) FROM \"microposts\" WHERE (user_id = 101)'","sql_queries_count":5}

直接Json形式のログを標準出力に出力したい場合は以下を追加

develpment.rb

  config.lograge.logger = ActiveSupport::Logger.new(STDOUT)

ログ出力

出力

Lograge.logger.info({ type: 'type', exception: 'exception'}.to_json)

logrageソース参照
https://github.com/roidrage/lograge/blob/1729eab7956bb95c5992e4adab251e4f93ff9280/lib/lograge.rb#L185