JSON Logger Formatter (#4050)

* Check Config File Existence (#4054)

* Check config file existence

* Eager config file check

* Parse expanded path to default sidekiq.yml config file in Rails app

* Cleanup

* Add minitest-around

* Extract context from formatter

* Add JSON logger formatter

* Adjust job logger to handle elapsed time within context

* Add tid test

* Rename processor logger

* Enforce global state reset in logging tests

* Add warning about upcoming refactoring to Sidekiq::Logging

* Replace around hook with explicit stub inside test

It's implemented with fibers, which means Thread.current returns different values in JRuby.

* Fix typo

* Concise JSON formatter keys

* Add logger_formatter option

* Shift context from array of strings to hash

Allows more flexibly format context in the different formatters.

* Adjust warning message regarding context type change

* Add "Formatter" suffix to classes

* Fix CLI specs

* Replace Sidekiq::Logging with Sidekiq::Logger

* Namespace logger formatters

* Remove rails 4 appraisal

Appraisals

@@ -1,8 +1,3 @@
-appraise "rails-4" do
-  gem "rails", "~> 4.2"
-  gem 'activerecord-jdbcsqlite3-adapter', '< 50', platforms: :jruby
-end
-
 appraise "rails-5" do
   gem "rails", "~> 5.2"
   gem 'activerecord-jdbcsqlite3-adapter', '>= 50', platforms: :jruby

Gemfile

@@ -14,6 +14,7 @@ end
 
 group :test do
   gem 'minitest'
+  gem 'minitest-around'
   gem 'minitest-focus'
   gem 'minitest-reporters'
   gem 'simplecov'

gemfiles/rails_5.gemfile

@@ -14,6 +14,7 @@ end
 
 group :test do
   gem "minitest"
+  gem "minitest-around"
   gem "minitest-focus"
   gem "minitest-reporters"
   gem "simplecov"

lib/sidekiq.rb

@@ -3,7 +3,7 @@
 require 'sidekiq/version'
 fail "Sidekiq #{Sidekiq::VERSION} does not support Ruby versions below 2.4.0." if RUBY_PLATFORM != 'java' && Gem::Version.new(RUBY_VERSION) < Gem::Version.new('2.4.0')
 
-require 'sidekiq/logging'
+require 'sidekiq/logger'
 require 'sidekiq/client'
 require 'sidekiq/worker'
 require 'sidekiq/redis_connection'
@@ -178,11 +178,16 @@ def self.dump_json(object)
     JSON.generate(object)
   end
 
+  class << self
+    attr_accessor :logger_formatter
+  end
+
   def self.logger
-    Sidekiq::Logging.logger
+    @logger ||= Sidekiq::Logger.new(STDOUT, level: Logger::INFO)
   end
-  def self.logger=(log)
-    Sidekiq::Logging.logger = log
+
+  def self.logger=(logger)
+    @logger = logger
   end
 
   # How frequently Redis should be checked by a random Sidekiq process for

lib/sidekiq/cli.rb

@@ -8,8 +8,8 @@
 require 'fileutils'
 
 require 'sidekiq'
-require 'sidekiq/util'
 require 'sidekiq/launcher'
+require 'sidekiq/util'
 
 module Sidekiq
   class CLI
@@ -339,16 +339,11 @@ def parse_options(argv)
     end
 
     def initialize_logger
-      Sidekiq::Logging.initialize_logger
-
       Sidekiq.logger.level = ::Logger::DEBUG if options[:verbose]
     end
 
-    def parse_config(cfile)
-      opts = {}
-      if File.exist?(cfile)
-        opts = YAML.load(ERB.new(IO.read(cfile)).result) || opts
-      end
+    def parse_config(path)
+      opts = YAML.load(ERB.new(File.read(path)).result) || {}
 
       if opts.respond_to? :deep_symbolize_keys!
         opts.deep_symbolize_keys!

lib/sidekiq/job_logger.rb

@@ -1,25 +1,52 @@
 # frozen_string_literal: true
+
 module Sidekiq
   class JobLogger
 
     def call(item, queue)
       start = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
-      logger.info("start")
+
+      Sidekiq.logger.info("start")
+
       yield
-      logger.info("done: #{elapsed(start)} sec")
+
+      with_elapsed_time_context(start) do
+        Sidekiq.logger.info("done")
+      end
     rescue Exception
-      logger.info("fail: #{elapsed(start)} sec")
+      with_elapsed_time_context(start) do
+        Sidekiq.logger.info("fail")
+      end
+
       raise
     end
 
+    def with_job_hash_context(job_hash, &block)
+      Sidekiq.logger.with_context(job_hash_context(job_hash), &block)
+    end
+
+    def job_hash_context(job_hash)
+      # If we're using a wrapper class, like ActiveJob, use the "wrapped"
+      # attribute to expose the underlying thing.
+      {
+        class: job_hash['wrapped'] || job_hash["class"],
+        jid: job_hash['jid'],
+        bid: job_hash['bid']
+      }
+    end
+
+    def with_elapsed_time_context(start, &block)
+      Sidekiq.logger.with_context(elapsed_time_context(start), &block)
+    end
+
+    def elapsed_time_context(start)
+      { elapsed: "#{elapsed(start)} sec" }
+    end
+
     private
 
     def elapsed(start)
       (::Process.clock_gettime(::Process::CLOCK_MONOTONIC) - start).round(3)
     end
-
-    def logger
-      Sidekiq.logger
-    end
   end
 end

lib/sidekiq/logger.rb

@@ -0,0 +1,70 @@
+# frozen_string_literal: true
+
+require 'logger'
+require 'time'
+
+module Sidekiq
+  class Logger < ::Logger
+
+    def initialize(*args)
+      super
+
+      formatter_class = case Sidekiq.logger_formatter
+      when :json
+        Formatters::JSON
+      else
+        ENV['DYNO'] ? Formatters::WithoutTimestamp : Formatters::Pretty
+      end
+
+      self.formatter = formatter_class.new
+    end
+
+    def tid
+      Thread.current['sidekiq_tid'] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36)
+    end
+
+    def context
+      Thread.current[:sidekiq_context] ||= {}
+    end
+
+    def with_context(hash)
+      context.merge!(hash)
+      yield
+    ensure
+      hash.keys.each { |key| context.delete(key) }
+    end
+
+    module Formatters
+      class Pretty < Logger::Formatter
+        def call(severity, time, program_name, message)
+          "#{time.utc.iso8601(3)} #{::Process.pid} TID-#{Sidekiq.logger.tid}#{format_context(Sidekiq.logger.context)} #{severity}: #{message}\n"
+        end
+
+        private
+
+        def format_context(context)
+          ' ' + context.compact.map { |k, v| "#{k.upcase}=#{v}" }.join(' ') if context.any?
+        end
+      end
+
+      class WithoutTimestamp < Pretty
+        def call(severity, time, program_name, message)
+          "#{::Process.pid} TID-#{Sidekiq.logger.tid}#{format_context(Sidekiq.logger.context)} #{severity}: #{message}\n"
+        end
+      end
+
+      class JSON < Logger::Formatter
+        def call(severity, time, program_name, message)
+          Sidekiq.dump_json(
+            ts: time.utc.iso8601(3),
+            pid: ::Process.pid,
+            tid: Sidekiq.logger.tid,
+            ctx: Sidekiq.logger.context,
+            sev: severity,
+            msg: message
+          )
+        end
+      end
+    end
+  end
+end

lib/sidekiq/processor.rb

@@ -37,7 +37,7 @@ def initialize(mgr)
       @thread = nil
       @strategy = (mgr.options[:fetch] || Sidekiq::BasicFetch).new(mgr.options)
       @reloader = Sidekiq.options[:reloader]
-      @logging = (mgr.options[:job_logger] || Sidekiq::JobLogger).new
+      @job_logger = (mgr.options[:job_logger] || Sidekiq::JobLogger).new
       @retrier = Sidekiq::JobRetry.new
     end
 
@@ -121,9 +121,9 @@ def dispatch(job_hash, queue)
       # job structure to the Web UI
       pristine = cloned(job_hash)
 
-      Sidekiq::Logging.with_job_hash_context(job_hash) do
+      @job_logger.with_job_hash_context(job_hash) do
         @retrier.global(pristine, queue) do
-          @logging.call(job_hash, queue) do
+          @job_logger.call(job_hash, queue) do
             stats(pristine, queue) do
               # Rails 5 requires a Reloader to wrap code execution.  In order to
               # constantize the worker and instantiate an instance, we have to call
@@ -236,7 +236,8 @@ def clear
     WORKER_STATE = SharedWorkerState.new
 
     def stats(job_hash, queue)
-      tid = Sidekiq::Logging.tid
+      tid = Sidekiq.logger.tid
+
       WORKER_STATE.set(tid, {:queue => queue, :payload => job_hash, :run_at => Time.now.to_i })
 
       begin
@@ -267,6 +268,5 @@ def constantize(str)
         constant.const_defined?(name, false) ? constant.const_get(name, false) : constant.const_missing(name)
       end
     end
-
   end
 end

lib/sidekiq/scheduled.rb

@@ -24,7 +24,7 @@ def enqueue_jobs(now=Time.now.to_f.to_s, sorted_sets=SETS)
               # next one.
               if conn.zrem(sorted_set, job)
                 Sidekiq::Client.push(Sidekiq.load_json(job))
-                Sidekiq::Logging.logger.debug { "enqueued #{sorted_set}: #{job}" }
+                Sidekiq.logger.debug { "enqueued #{sorted_set}: #{job}" }
               end
             end
           end