タダです.

Ruby on Rails で触れていてログを標準出力から JSON 形式にして user_id をログに組み込む検証をする機会があったので,備忘録としてこの記事にまとめておきます.

Rails の標準出力ログについて

Rails では標準出力ログは下記のように出力されますが,1つの URI パスでアクセスすると下記のようなログがでてきますが,見づらいので logrageとlograge-sqlを使っていい感じにしてみます.

Started GET "/" for 106.72.0.34 at 2021-12-16 11:18:32 +0000
Cannot render console from 106.72.0.34! Allowed networks: 127.0.0.0/127.255.255.255, ::1
  [1m[35m (1.5ms)[0m  [1m[34mSELECT sqlite_version(*)[0m
Processing by Rails::WelcomeController#index as HTML
  Rendering /home/ubuntu/.rvm/gems/ruby-2.6.3/gems/railties-6.0.4.4/lib/rails/templates/rails/welcome/index.html.erb
  Rendered /home/ubuntu/.rvm/gems/ruby-2.6.3/gems/railties-6.0.4.4/lib/rails/templates/rails/welcome/index.html.erb (Duration: 19.5ms | Allocations: 477)
Completed 200 OK in 41ms (Views: 27.2ms | ActiveRecord: 0.0ms | Allocations: 2866)

`lograge`と`lograge-sql` について

lograge は Rails の標準出力を見やすく解析しやすくするためのものです.

Lograge is an attempt to bring sanity to Rails' noisy and unusable, unparsable and, in the context of running multiple processes and servers, unreadable default logging output. Rails' default approach to log everything is great during development, it's terrible when running it in production. It pretty much renders Rails logs useless to me.

github.com

ログ例

※lograge 導入前
Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
  Rendered text template within layouts/application (0.0ms)
  Rendered layouts/_assets.html.erb (2.0ms)
  Rendered layouts/_top.html.erb (2.6ms)
  Rendered layouts/_about.html.erb (0.3ms)
  Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)

※lograge 導入後
method=GET path=/jobs/833552.json format=json controller=JobsController  action=show status=200 duration=58.33 view=40.43 db=15.26

lograge-sql は logrageの拡張で lograge のログの中に SQL クエリを追加してくれるものです.

Lograge::Sql is an extension to the famous Lograge gem, which adds SQL queries to the Lograge Event and disable default ActiveRecord logging. This is extremely useful if you're using Lograge together with the ELK stack.

github.com

ログ例

※lograge-sql 導入後
method=GET path=/jobs/833552.json format=json controller=JobsController  action=show status=200 duration=58.33 view=40.43 db=15.26 user_id=1 sql_queries='User Load (2.97) SELECT "users".* FROM "users" WHERE "users"."id" = ? ORDER BY "users"."id" ASC LIMIT ?' sql_queries_count=1

実装してみる

logrageとlograge-sql を組み込んでみます.いじったのは Gemfile,config/initializers/lograge.rb,config/environment/development.rbで,変更は下記のとおりです.

Gemfile

gem "lograge"
gem "lograge-sql"

config/initializers/lograge.rb

require "lograge/sql/extension"

Rails.application.configure do 
  config.lograge.enabled = true
  config.lograge.formatter = Lograge::Formatters::Json.new
  config.lograge.keep_original_rails_log = true
  config.lograge_sql.keep_default_active_record_log = true

  config.lograge.custom_payload do |controller|
    {
      user_id: controller.try(:current_user).try(:id)
    }
  end
end

config/environment/development.rb

  STDOUT.sync = true
  logger = ActiveSupport::Logger.new(STDOUT)
  config.logger = ActiveSupport::TaggedLogging.new(logger)
  config.logger = Logger.new('log/development.log')

動作確認

上記の設定後に再度 rails server で起動してみてログの表示がどう変わるかを確認してみます.アプリケーションで処理されている部分を抜粋していますが,標準出力で複数行にわたって表示されていたのが1行にまとまって JSON 形式のログになり可読性が個人的に上がったと思います.

I, [2021-12-30T06:07:00.477727 #21473]  INFO -- : {"method":"GET","path":"/","format":"html","controller":"Rails::WelcomeController","action":"index","status":200,"duration":9.59,"view":3.29,"db":0.0,"user_id":1,"sql_queries":"'User Load (3.09) SELECT \"users\".* FROM \"users\" WHERE \"users\".\"id\" = ? ORDER BY \"users\".\"id\" ASC LIMIT ?'","sql_queries_count":1}