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

```json: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":"xxx@gmail.com","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

```json: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追加

```rb:Gemfile
gem "lograge"
```

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

```rb:config/environments/develpment.rb
  config.lograge.enabled = true
```

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

```rb: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)
```

```rb: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形式で出力したい場合は以下を追加**

```rb:config/environments/develpment.rb
config.lograge.formatter = Lograge::Formatters::Json.new
```

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

```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追加

```rb: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を発生させる

```rb:static_pages_controller.rb
def home
    raise "error"
end

```

Root接続した後のローグ

```json: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```が追加された

```json: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に項目追加**

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

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

```json:追加後
{"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追加

```json:Gemfile
gem "lograge-sql"
```

2) require追加

```rb:config/initializers/lograge.rb
require 'lograge/sql/extension'
```

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

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

```json:結果
{"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