Be careful when using rails_semantic_logger with unicorn

Introduction

When I tried to use rails_semantic_logger with unicorn, there was no log at all and I was in trouble, so a record of what to do and what I want to be aware of.

What is rails_semantic_logger?

A gem for Rails with Semantic Logger. https://github.com/rocketjob/rails_semantic_logger By using this, you can output more detailed logs and increase the number of items to be logged compared to the log using Logger which is set by default in Rails.

There is a detailed usage in the document, so basically follow it. https://logger.rocketjob.io/rails.html

Precautions when using

Replace Logger when gem install

Rails Semantic Logger replaces the Rails default logger with Semantic Logger

Rails Semantic Logger replaces Rail's default logger with Semantic Logger, as on GitHub, but this is done by simply installing the ** gem. ** It is convenient to use it just by installing it, but be careful when you want to use it properly with Rail's default logger.

--Rails default log

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)

--Log with Semantic Logger (just installed gem)

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"}

When starting with unicorn, the log will not be output unless SemanticLogger.reopen is added to 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. After the process forks, you need to call SemanticLogger.reopen to reopen the file and restart the appender thread. Otherwise, logging will appear to be stopped.

As it is written in the document, just follow it, ** If you do not add SemanticLogger.reopen, access log etc. will not be output at all in unicorn after startup. ** ** Therefore, it is necessary to add settings in unicorn.rb.

--Used unicorn.rb

unicorn.rb

worker_processes 2

#The default is 8080
listen 3000

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

#I have to set this to true
# NoMethodError: undefined method `rails_semantic_logger' for 
# <Rails::Application::Configuration:0x00007fb4da158308>
#become. The default is false.
preload_app true

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

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

--The unicorn log output correctly by Semantic Logger

development.log

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"}

-(Supplement) unicorn log output without using Semantic Logger

development.log

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)