More than 1 year has passed since last update.

rails_semantic_loggerをunicornで使う時に気をつけること

Last updated at 2022-06-20Posted at 2020-12-24

はじめに

rails_semantic_loggerをunicornで使おうとしたらログが全く出なくなり困ったので、その対処法と意識しておきたいことの記録。

rails_semantic_logger とは

Semantic LoggerをRails用にしたgem。
https://github.com/rocketjob/rails_semantic_logger
これを使うことで、Railsのデフォルトで設定されているLoggerを使ったログより、より詳細なログを出したり、ログに出す項目を増やすことができる。

ドキュメントに詳しい使い方があるので、基本的にはそれに従って使います。
https://logger.rocketjob.io/rails.html

使用するときの注意点

gem installした時点でLoggerを置き換える

Rails Semantic Logger replaces the Rails default logger with Semantic Logger

とGitHubにあるようにRails Semantic LoggerはRailのデフォルトのロガーをSemantic Loggerに置き換えるが、これは**gemをinstallするだけで行われる。**installするだけで使えるのは便利な反面、Railのデフォルトのロガーと使い分けたい時などは要注意。

Railsのデフォルトのログ

Started GET "/" for ::1 at 2020-12-24 16:52:32 +0900
   (3.9ms)  SELECT sqlite_version(*)
Processing by Rails::WelcomeController#index as HTML
  Rendering /Users/ruru8/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/railties-6.0.3.4/lib/rails/templates/rails/welcome/index.html.erb
  Rendered /Users/ruru8/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/railties-6.0.3.4/lib/rails/templates/rails/welcome/index.html.erb (Duration: 8.2ms | Allocations: 488)
Completed 200 OK in 29ms (Views: 16.8ms | ActiveRecord: 0.0ms | Allocations: 4092)

Semantic Loggerでのログ(gemをinstallしただけ)

2020-12-24 16:55:47.233165 D [94828:puma threadpool 003] Rack -- Started -- {:method=>"GET", :path=>"/", :ip=>"::1"}
2020-12-24 16:55:47.257578 D [94828:puma threadpool 003] (2.110ms) ActiveRecord -- {:sql=>"SELECT sqlite_version(*)"}
2020-12-24 16:55:47.339429 D [94828:puma threadpool 003] Rails::WelcomeController -- Processing #index
2020-12-24 16:55:47.349296 D [94828:puma threadpool 003] ActionView -- Rendering -- {:template=>"/Users/ruru8/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/railties-6.0.3.4/lib/rails/templates/rails/welcome/index.html.erb"}
2020-12-24 16:55:47.356769 D [94828:puma threadpool 003] (7.397ms) ActionView -- Rendered -- {:template=>"/Users/ruru8/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/railties-6.0.3.4/lib/rails/templates/rails/welcome/index.html.erb"}
2020-12-24 16:55:47.357033 I [94828:puma threadpool 003] (17.5ms) Rails::WelcomeController -- Completed #index -- {:controller=>"Rails::WelcomeController", :action=>"index", :format=>"HTML", :method=>"GET", :path=>"/", :status=>200, :view_runtime=>9.79, :db_runtime=>0.0, :status_message=>"OK"}

unicornで起動する場合は `SemanticLogger.reopen` をunicorn.rbに追加しないとログが出なくなる

After a process has forked SemanticLogger.reopen must be called to re-open files and re-start the appender thread. Otherwise, logging will appear to stop.
訳 > プロセスがフォークした後、SemanticLogger.reopenを呼び出してファイルを再度開き、アペンダースレッドを再開する必要があります。それ以外の場合、ロギングは停止しているように見えます。

ドキュメントに書いてある通りなのでそれに従うだけだが、
SemanticLogger.reopenを追加しないとunicornでは、起動後以降、アクセスログなど、全く出力されなくなる。
ので、unicorn.rbにて設定の追加が必要。

使用したunicorn.rb

unicorn.rb

worker_processes 2

# デフォルトは8080
listen 3000

app_path = File.expand_path('../', File.dirname(__FILE__))
pid "#{app_path}/tmp/pids/unicorn.pid"

# ここをtrueにしないと
# NoMethodError: undefined method `rails_semantic_logger' for 
# <Rails::Application::Configuration:0x00007fb4da158308>
# になる。デフォルトはfalse。
preload_app true

before_fork do |server, worker|
  SemanticLogger.reopen # 追加
  defined?(ActiveRecord::Base) &&
    ActiveRecord::Base.connection.disconnect!
end

after_fork do |server, worker|
  SemanticLogger.reopen # 追加
  defined?(ActiveRecord::Base) &&
    ActiveRecord::Base.establish_connection
end

Semantic Loggerで正しく出力されたunicornのログ

development.log

2020-12-24 17:34:27.606903 [32mD[0m [14389:70298057777160] [32mRack[0m -- Started -- {:method=>"GET", :path=>"/", :ip=>"127.0.0.1"}
2020-12-24 17:34:27.680679 [32mD[0m [14389:70298057777160] ([1m0.064ms[0m) [32mActiveRecord[0m -- {:sql=>"SELECT sqlite_version(*)"}
2020-12-24 17:34:27.712773 [32mD[0m [14389:70298057777160] [32mRails::WelcomeController[0m -- Processing #index
2020-12-24 17:34:27.721959 [32mD[0m [14389:70298057777160] [32mActionView[0m -- Rendering -- {:template=>"/Users/ruru8/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/railties-6.0.3.4/lib/rails/templates/rails/welcome/index.html.erb"}
2020-12-24 17:34:27.727841 [32mD[0m [14389:70298057777160] ([1m5.810ms[0m) [32mActionView[0m -- Rendered -- {:template=>"/Users/ruru8/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/railties-6.0.3.4/lib/rails/templates/rails/welcome/index.html.erb"}
2020-12-24 17:34:27.728014 [36mI[0m [14389:70298057777160] ([1m15.2ms[0m) [36mRails::WelcomeController[0m -- Completed #index -- {:controller=>"Rails::WelcomeController", :action=>"index", :format=>"HTML", :method=>"GET", :path=>"/", :status=>200, :view_runtime=>8.29, :db_runtime=>0.0, :status_message=>"OK"}

(補足)SemanticLoggerを使わずに出力されるunicornのログ