2020 December 23rd, Wednesday

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

RailsSemantic Loggerunicorn

はじめに

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/chiharu.yasuda/.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/chiharu.yasuda/.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/chiharu.yasuda/.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/chiharu.yasuda/.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 に追加しないとログが出なくなる

https://logger.rocketjob.io/forking.html

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
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 のログ
2020-12-24 17:34:27.606903 D [14389:70298057777160] Rack -- Started -- {:method=>"GET", :path=>"/", :ip=>"127.0.0.1"}
2020-12-24 17:34:27.680679 D [14389:70298057777160] (0.064ms) ActiveRecord -- {:sql=>"SELECT sqlite_version(*)"}
2020-12-24 17:34:27.712773 D [14389:70298057777160] Rails::WelcomeController -- Processing #index
2020-12-24 17:34:27.721959 D [14389:70298057777160] ActionView -- Rendering -- {:template=>"/Users/chiharu.yasuda/.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 D [14389:70298057777160] (5.810ms) ActionView -- Rendered -- {:template=>"/Users/chiharu.yasuda/.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 I [14389:70298057777160] (15.2ms) Rails::WelcomeController -- 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 のログ
Started GET "/" for 127.0.0.1 at 2020-12-24 17:31:35 +0900
   (0.1ms)  SELECT sqlite_version(*)
Processing by Rails::WelcomeController#index as HTML
  Rendering /Users/chiharu.yasuda/.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/chiharu.yasuda/.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: 5.6ms | Allocations: 315)
Completed 200 OK in 13ms (Views: 8.0ms | ActiveRecord: 0.0ms | Allocations: 2017)