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 @@ module Sidekiq
     JSON.generate(object)
   end
 
-  def self.logger
+  class << self
-    Sidekiq::Logging.logger
+    attr_accessor :logger_formatter
   end
-  def self.logger=(log)
+
-    Sidekiq::Logging.logger = log
+  def self.logger
+    @logger ||= Sidekiq::Logger.new(STDOUT, level: Logger::INFO)
+  end
+
+  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 'erb'
 require 'fileutils'
 
 require 'sidekiq'
-require 'sidekiq/util'
 require 'sidekiq/launcher'
+require 'sidekiq/util'
 
 module Sidekiq
   class CLI
@@ -339,16 +339,11 @@ module Sidekiq
     end
 
     def initialize_logger
-      Sidekiq::Logging.initialize_logger
-
       Sidekiq.logger.level = ::Logger::DEBUG if options[:verbose]
     end
 
-    def parse_config(cfile)
+    def parse_config(path)
-      opts = {}
+      opts = YAML.load(ERB.new(File.read(path)).result) || {}
-      if File.exist?(cfile)
-        opts = YAML.load(ERB.new(IO.read(cfile)).result) || opts
-      end
 
       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/logging.rb

@@ -1,72 +0,0 @@
-# frozen_string_literal: true
-require 'time'
-require 'logger'
-
-module Sidekiq
-  module Logging
-
-    class Pretty < Logger::Formatter
-      SPACE = " "
-
-      # Provide a call() method that returns the formatted message.
-      def call(severity, time, program_name, message)
-        "#{time.utc.iso8601(3)} #{::Process.pid} TID-#{Sidekiq::Logging.tid}#{context} #{severity}: #{message}\n"
-      end
-
-      def context
-        c = Thread.current[:sidekiq_context]
-        " #{c.join(SPACE)}" if c && c.any?
-      end
-    end
-
-    class WithoutTimestamp < Pretty
-      def call(severity, time, program_name, message)
-        "#{::Process.pid} TID-#{Sidekiq::Logging.tid}#{context} #{severity}: #{message}\n"
-      end
-    end
-
-    def self.tid
-      Thread.current['sidekiq_tid'] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36)
-    end
-
-    def self.job_hash_context(job_hash)
-      # If we're using a wrapper class, like ActiveJob, use the "wrapped"
-      # attribute to expose the underlying thing.
-      klass = job_hash['wrapped'] || job_hash["class"]
-      bid = job_hash['bid']
-      "#{klass} JID-#{job_hash['jid']}#{" BID-#{bid}" if bid}"
-    end
-
-    def self.with_job_hash_context(job_hash, &block)
-      with_context(job_hash_context(job_hash), &block)
-    end
-
-    def self.with_context(msg)
-      Thread.current[:sidekiq_context] ||= []
-      Thread.current[:sidekiq_context] << msg
-      yield
-    ensure
-      Thread.current[:sidekiq_context].pop
-    end
-
-    def self.initialize_logger
-      return @logger if defined?(@logger)
-      @logger = Logger.new(STDOUT)
-      @logger.level = Logger::INFO
-      @logger.formatter = ENV['DYNO'] ? WithoutTimestamp.new : Pretty.new
-      @logger
-    end
-
-    def self.logger
-      defined?(@logger) ? @logger : initialize_logger
-    end
-
-    def self.logger=(log)
-      @logger = (log ? log : Logger.new(File::NULL))
-    end
-
-    def logger
-      Sidekiq::Logging.logger
-    end
-  end
-end

lib/sidekiq/processor.rb

@@ -37,7 +37,7 @@ module Sidekiq
       @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 @@ module Sidekiq
       # 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 @@ module Sidekiq
     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 @@ module Sidekiq
         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 @@ module Sidekiq
               # 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

test/test_cli.rb

@@ -4,368 +4,347 @@ require_relative 'helper'
 require 'sidekiq/cli'
 
 class TestCLI < Minitest::Test
-  describe '#parse' do
+  describe Sidekiq::CLI do
-    before do
+    subject { Sidekiq::CLI.new }
-      Sidekiq.options = Sidekiq::DEFAULTS.dup
-      @logger = Sidekiq.logger
-      @logdev = StringIO.new
-      Sidekiq.logger = Logger.new(@logdev)
-      @cli = Sidekiq::CLI.new
-    end
 
-    after do
+    let(:logdev) { StringIO.new }
-      Sidekiq.logger = @logger
-    end
 
-    describe 'options' do
+    around do |test|
-      describe 'require' do
+      Sidekiq.stub :options, Sidekiq::DEFAULTS.dup do
-        it 'accepts with -r' do
+        Sidekiq.stub :logger, Sidekiq::Logger.new(logdev) do
-          @cli.parse(%w[sidekiq -r ./test/fake_env.rb])
+          test.call
-
-          assert_equal './test/fake_env.rb', Sidekiq.options[:require]
         end
       end
+    end
 
-      describe 'concurrency' do
+    describe '#parse' do
-        it 'accepts with -c' do
+      describe 'options' do
-          @cli.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb])
+        describe 'require' do
+          it 'accepts with -r' do
+            subject.parse(%w[sidekiq -r ./test/fake_env.rb])
 
-          assert_equal 60, Sidekiq.options[:concurrency]
+            assert_equal './test/fake_env.rb', Sidekiq.options[:require]
+          end
         end
 
-        describe 'when concurrency is empty and RAILS_MAX_THREADS env var is set' do
+        describe 'concurrency' do
-          before do
+          it 'accepts with -c' do
-            ENV['RAILS_MAX_THREADS'] = '9'
+            subject.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb])
-          end
-
-          after do
-            ENV.delete('RAILS_MAX_THREADS')
-          end
-
-          it 'sets concurrency from RAILS_MAX_THREADS env var' do
-            @cli.parse(%w[sidekiq -r ./test/fake_env.rb])
-
-            assert_equal 9, Sidekiq.options[:concurrency]
-          end
-
-          it 'option overrides RAILS_MAX_THREADS env var' do
-            @cli.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb])
 
             assert_equal 60, Sidekiq.options[:concurrency]
           end
-        end
-      end
 
-      describe 'queues' do
+          describe 'when concurrency is empty and RAILS_MAX_THREADS env var is set' do
-        it 'accepts with -q' do
+            before do
-          @cli.parse(%w[sidekiq -q foo -r ./test/fake_env.rb])
+              ENV['RAILS_MAX_THREADS'] = '9'
+            end
 
-          assert_equal ['foo'], Sidekiq.options[:queues]
+            after do
-        end
+              ENV.delete('RAILS_MAX_THREADS')
+            end
 
-        describe 'when weights are not present' do
+            it 'sets concurrency from RAILS_MAX_THREADS env var' do
-          it 'accepts queues without weights' do
+              subject.parse(%w[sidekiq -r ./test/fake_env.rb])
-            @cli.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb])
 
-            assert_equal ['foo', 'bar'], Sidekiq.options[:queues]
+              assert_equal 9, Sidekiq.options[:concurrency]
-          end
+            end
 
-          it 'sets strictly ordered queues' do
+            it 'option overrides RAILS_MAX_THREADS env var' do
-            @cli.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb])
+              subject.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb])
 
-            assert_equal true, !!Sidekiq.options[:strict]
+              assert_equal 60, Sidekiq.options[:concurrency]
+            end
           end
         end
 
-        describe 'when weights are present' do
+        describe 'queues' do
-          it 'accepts queues with weights' do
+          it 'accepts with -q' do
-            @cli.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb])
+            subject.parse(%w[sidekiq -q foo -r ./test/fake_env.rb])
 
-            assert_equal ['foo', 'foo', 'foo', 'bar'], Sidekiq.options[:queues]
+            assert_equal ['foo'], Sidekiq.options[:queues]
           end
 
-          it 'does not set strictly ordered queues' do
+          describe 'when weights are not present' do
-            @cli.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb])
+            it 'accepts queues without weights' do
+              subject.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb])
 
-            assert_equal false, !!Sidekiq.options[:strict]
+              assert_equal ['foo', 'bar'], Sidekiq.options[:queues]
+            end
+
+            it 'sets strictly ordered queues' do
+              subject.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb])
+
+              assert_equal true, !!Sidekiq.options[:strict]
+            end
+          end
+
+          describe 'when weights are present' do
+            it 'accepts queues with weights' do
+              subject.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb])
+
+              assert_equal ['foo', 'foo', 'foo', 'bar'], Sidekiq.options[:queues]
+            end
+
+            it 'does not set strictly ordered queues' do
+              subject.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb])
+
+              assert_equal false, !!Sidekiq.options[:strict]
+            end
+          end
+
+          it 'accepts queues with multi-word names' do
+            subject.parse(%w[sidekiq -q queue_one -q queue-two -r ./test/fake_env.rb])
+
+            assert_equal ['queue_one', 'queue-two'], Sidekiq.options[:queues]
+          end
+
+          it 'accepts queues with dots in the name' do
+            subject.parse(%w[sidekiq -q foo.bar -r ./test/fake_env.rb])
+
+            assert_equal ['foo.bar'], Sidekiq.options[:queues]
+          end
+
+          describe 'when duplicate queue names' do
+            it 'raises an argument error' do
+              assert_raises(ArgumentError) { subject.parse(%w[sidekiq -q foo -q foo -r ./test/fake_env.rb]) }
+              assert_raises(ArgumentError) { subject.parse(%w[sidekiq -q foo,3 -q foo,1 -r ./test/fake_env.rb]) }
+            end
+          end
+
+          describe 'when queues are empty' do
+            it "sets 'default' queue" do
+              subject.parse(%w[sidekiq -r ./test/fake_env.rb])
+
+              assert_equal ['default'], Sidekiq.options[:queues]
+            end
           end
         end
 
-        it 'accepts queues with multi-word names' do
+        describe 'timeout' do
-          @cli.parse(%w[sidekiq -q queue_one -q queue-two -r ./test/fake_env.rb])
+          it 'accepts with -t' do
+            subject.parse(%w[sidekiq -t 30 -r ./test/fake_env.rb])
 
-          assert_equal ['queue_one', 'queue-two'], Sidekiq.options[:queues]
+            assert_equal 30, Sidekiq.options[:timeout]
-        end
-
-        it 'accepts queues with dots in the name' do
-          @cli.parse(%w[sidekiq -q foo.bar -r ./test/fake_env.rb])
-
-          assert_equal ['foo.bar'], Sidekiq.options[:queues]
-        end
-
-        describe 'when duplicate queue names' do
-          it 'raises an argument error' do
-            assert_raises(ArgumentError) { @cli.parse(%w[sidekiq -q foo -q foo -r ./test/fake_env.rb]) }
-            assert_raises(ArgumentError) { @cli.parse(%w[sidekiq -q foo,3 -q foo,1 -r ./test/fake_env.rb]) }
           end
         end
 
-        describe 'when queues are empty' do
+        describe 'verbose' do
-          it "sets 'default' queue" do
+          it 'accepts with -v' do
-            @cli.parse(%w[sidekiq -r ./test/fake_env.rb])
+            subject.parse(%w[sidekiq -v -r ./test/fake_env.rb])
 
-            assert_equal ['default'], Sidekiq.options[:queues]
+            assert_equal Logger::DEBUG, Sidekiq.logger.level
-          end
-        end
-      end
-
-      describe 'timeout' do
-        it 'accepts with -t' do
-          @cli.parse(%w[sidekiq -t 30 -r ./test/fake_env.rb])
-
-          assert_equal 30, Sidekiq.options[:timeout]
-        end
-      end
-
-      describe 'verbose' do
-        it 'accepts with -v' do
-          @cli.parse(%w[sidekiq -v -r ./test/fake_env.rb])
-
-          assert_equal Logger::DEBUG, Sidekiq.logger.level
-        end
-      end
-
-      describe 'config file' do
-        it 'accepts with -C' do
-          @cli.parse(%w[sidekiq -C ./test/config.yml])
-
-          assert_equal './test/config.yml', Sidekiq.options[:config_file]
-          refute Sidekiq.options[:verbose]
-          assert_equal './test/fake_env.rb', Sidekiq.options[:require]
-          assert_nil Sidekiq.options[:environment]
-          assert_equal 50, Sidekiq.options[:concurrency]
-          assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' }
-          assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' }
-        end
-
-        it 'accepts stringy keys' do
-          @cli.parse(%w[sidekiq -C ./test/config_string.yml])
-
-          assert_equal './test/config_string.yml', Sidekiq.options[:config_file]
-          refute Sidekiq.options[:verbose]
-          assert_equal './test/fake_env.rb', Sidekiq.options[:require]
-          assert_nil Sidekiq.options[:environment]
-          assert_equal 50, Sidekiq.options[:concurrency]
-          assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' }
-          assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' }
-        end
-
-        it 'accepts environment specific config' do
-          @cli.parse(%w[sidekiq -e staging -C ./test/config_environment.yml])
-
-          assert_equal './test/config_environment.yml', Sidekiq.options[:config_file]
-          refute Sidekiq.options[:verbose]
-          assert_equal './test/fake_env.rb', Sidekiq.options[:require]
-          assert_equal 'staging', Sidekiq.options[:environment]
-          assert_equal 50, Sidekiq.options[:concurrency]
-          assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' }
-          assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' }
-        end
-
-        describe 'when config file is empty' do
-          it 'sets default options' do
-            @cli.parse(%w[sidekiq -C ./test/config_empty.yml -r ./test/fake_env.rb])
-
-            assert_equal './test/config_empty.yml', Sidekiq.options[:config_file]
-            refute Sidekiq.options[:verbose]
-            assert_equal './test/fake_env.rb', Sidekiq.options[:require]
-            assert_nil Sidekiq.options[:environment]
-            assert_equal 10, Sidekiq.options[:concurrency]
-            assert_equal ['default'], Sidekiq.options[:queues]
           end
         end
 
-        describe 'when config file and flags' do
+        describe 'config file' do
-          it 'merges options' do
+          it 'accepts with -C' do
-            @cli.parse(%w[sidekiq -C ./test/config.yml
+            subject.parse(%w[sidekiq -C ./test/config.yml])
-                                  -e snoop
-                                  -c 100
-                                  -r ./test/fake_env.rb
-                                  -q often,7
-                                  -q seldom,3])
 
             assert_equal './test/config.yml', Sidekiq.options[:config_file]
             refute Sidekiq.options[:verbose]
             assert_equal './test/fake_env.rb', Sidekiq.options[:require]
-            assert_equal 'snoop', Sidekiq.options[:environment]
+            assert_nil Sidekiq.options[:environment]
-            assert_equal 100, Sidekiq.options[:concurrency]
+            assert_equal 50, Sidekiq.options[:concurrency]
-            assert_equal 7, Sidekiq.options[:queues].count { |q| q == 'often' }
+            assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' }
-            assert_equal 3, Sidekiq.options[:queues].count { |q| q == 'seldom' }
+            assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' }
           end
-        end
 
-        describe 'default config file' do
+          it 'accepts stringy keys' do
-          describe 'when required path is a directory' do
+            subject.parse(%w[sidekiq -C ./test/config_string.yml])
-            it 'tries config/sidekiq.yml' do
-              @cli.parse(%w[sidekiq -r ./test/dummy])
 
-              assert_equal 'sidekiq.yml', File.basename(Sidekiq.options[:config_file])
+            assert_equal './test/config_string.yml', Sidekiq.options[:config_file]
-              assert_equal 25, Sidekiq.options[:concurrency]
+            refute Sidekiq.options[:verbose]
+            assert_equal './test/fake_env.rb', Sidekiq.options[:require]
+            assert_nil Sidekiq.options[:environment]
+            assert_equal 50, Sidekiq.options[:concurrency]
+            assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' }
+            assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' }
+          end
+
+          it 'accepts environment specific config' do
+            subject.parse(%w[sidekiq -e staging -C ./test/config_environment.yml])
+
+            assert_equal './test/config_environment.yml', Sidekiq.options[:config_file]
+            refute Sidekiq.options[:verbose]
+            assert_equal './test/fake_env.rb', Sidekiq.options[:require]
+            assert_equal 'staging', Sidekiq.options[:environment]
+            assert_equal 50, Sidekiq.options[:concurrency]
+            assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' }
+            assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' }
+          end
+
+          describe 'when config file is empty' do
+            it 'sets default options' do
+              subject.parse(%w[sidekiq -C ./test/config_empty.yml -r ./test/fake_env.rb])
+
+              assert_equal './test/config_empty.yml', Sidekiq.options[:config_file]
+              refute Sidekiq.options[:verbose]
+              assert_equal './test/fake_env.rb', Sidekiq.options[:require]
+              assert_nil Sidekiq.options[:environment]
+              assert_equal 10, Sidekiq.options[:concurrency]
+              assert_equal ['default'], Sidekiq.options[:queues]
+            end
+          end
+
+          describe 'when config file and flags' do
+            it 'merges options' do
+              subject.parse(%w[sidekiq -C ./test/config.yml
+                                    -e snoop
+                                    -c 100
+                                    -r ./test/fake_env.rb
+                                    -q often,7
+                                    -q seldom,3])
+
+              assert_equal './test/config.yml', Sidekiq.options[:config_file]
+              refute Sidekiq.options[:verbose]
+              assert_equal './test/fake_env.rb', Sidekiq.options[:require]
+              assert_equal 'snoop', Sidekiq.options[:environment]
+              assert_equal 100, Sidekiq.options[:concurrency]
+              assert_equal 7, Sidekiq.options[:queues].count { |q| q == 'often' }
+              assert_equal 3, Sidekiq.options[:queues].count { |q| q == 'seldom' }
+            end
+          end
+
+          describe 'default config file' do
+            describe 'when required path is a directory' do
+              it 'tries config/sidekiq.yml' do
+                subject.parse(%w[sidekiq -r ./test/dummy])
+
+                assert_equal 'sidekiq.yml', File.basename(Sidekiq.options[:config_file])
+                assert_equal 25, Sidekiq.options[:concurrency]
+              end
             end
           end
         end
       end
-    end
 
-    describe 'validation' do
+      describe 'validation' do
-      describe 'when required application path does not exist' do
+        describe 'when required application path does not exist' do
-        it 'exits with status 1' do
+          it 'exits with status 1' do
-          exit = assert_raises(SystemExit) { @cli.parse(%w[sidekiq -r /non/existent/path]) }
+            exit = assert_raises(SystemExit) { subject.parse(%w[sidekiq -r /non/existent/path]) }
-          assert_equal 1, exit.status
+            assert_equal 1, exit.status
-        end
-      end
-
-      describe 'when required path is a directory without config/application.rb' do
-        it 'exits with status 1' do
-          exit = assert_raises(SystemExit) { @cli.parse(%w[sidekiq -r ./test/fixtures]) }
-          assert_equal 1, exit.status
-        end
-
-        describe 'when config file path does not exist' do
-          it 'raises argument error' do
-            assert_raises(ArgumentError) do
-              @cli.parse(%w[sidekiq -r ./test/fake_env.rb -C /non/existent/path])
-            end
           end
         end
-      end
-    end
-  end
 
-  describe '#run' do
+        describe 'when required path is a directory without config/application.rb' do
-    before do
+          it 'exits with status 1' do
-      Sidekiq.options = Sidekiq::DEFAULTS.dup
+            exit = assert_raises(SystemExit) { subject.parse(%w[sidekiq -r ./test/fixtures]) }
-      Sidekiq.options[:require] = './test/fake_env.rb'
+            assert_equal 1, exit.status
-      @logger = Sidekiq.logger
-      @logdev = StringIO.new
-      Sidekiq.logger = Logger.new(@logdev)
-      @cli = Sidekiq::CLI.new
-    end
-
-    after do
-      Sidekiq.logger = @logger
-    end
-
-    describe 'require workers' do
-      describe 'when path is a rails directory' do
-        before do
-          Sidekiq.options[:require] = './test/dummy'
-          @cli.environment = 'test'
-        end
-
-        it 'requires sidekiq railtie and rails application with environment' do
-          @cli.stub(:launch, nil) do
-            @cli.run
           end
 
-          assert defined?(Sidekiq::Rails)
+          describe 'when config file path does not exist' do
-          assert defined?(Dummy::Application)
+            it 'raises argument error' do
-        end
+              assert_raises(ArgumentError) do
-
+                subject.parse(%w[sidekiq -r ./test/fake_env.rb -C /non/existent/path])
-        it 'tags with the app directory name' do
-          @cli.stub(:launch, nil) do
-            @cli.run
-          end
-
-          assert_equal 'dummy', Sidekiq.options[:tag]
-        end
-      end
-
-      describe 'when path is file' do
-        it 'requires application' do
-          @cli.stub(:launch, nil) do
-            @cli.run
-          end
-
-          assert $LOADED_FEATURES.any? { |x| x =~ /test\/fake_env/ }
-        end
-      end
-    end
-
-    describe 'when development environment and stdout tty' do
-      it 'prints banner' do
-        @cli.stub(:environment, 'development') do
-          assert_output(/#{Regexp.escape(Sidekiq::CLI.banner)}/) do
-            $stdout.stub(:tty?, true) do
-              @cli.stub(:launch, nil) do
-                @cli.run
               end
             end
           end
         end
       end
     end
-  end
 
-  describe 'signal handling' do
+    describe '#run' do
-    before do
+      before do
-      @cli = Sidekiq::CLI.new
+        Sidekiq.options[:require] = './test/fake_env.rb'
-      Sidekiq.options = Sidekiq::DEFAULTS.dup
+      end
-      @logger = Sidekiq.logger
-      @logdev = StringIO.new
-      Sidekiq.logger = Logger.new(@logdev)
-    end
 
-    after do
+      describe 'require workers' do
-      Sidekiq.logger = @logger
+        describe 'when path is a rails directory' do
-    end
+          before do
+            Sidekiq.options[:require] = './test/dummy'
+            subject.environment = 'test'
+          end
 
-    %w(INT TERM).each do |sig|
+          it 'requires sidekiq railtie and rails application with environment' do
-      describe sig do
+            subject.stub(:launch, nil) do
-        it 'raises interrupt error' do
+              subject.run
-          assert_raises Interrupt do
+            end
-            @cli.handle_signal(sig)
+
+            assert defined?(Sidekiq::Rails)
+            assert defined?(Dummy::Application)
+          end
+
+          it 'tags with the app directory name' do
+            subject.stub(:launch, nil) do
+              subject.run
+            end
+
+            assert_equal 'dummy', Sidekiq.options[:tag]
+          end
+        end
+
+        describe 'when path is file' do
+          it 'requires application' do
+            subject.stub(:launch, nil) do
+              subject.run
+            end
+
+            assert $LOADED_FEATURES.any? { |x| x =~ /test\/fake_env/ }
+          end
+        end
+      end
+
+      describe 'when development environment and stdout tty' do
+        it 'prints banner' do
+          subject.stub(:environment, 'development') do
+            assert_output(/#{Regexp.escape(Sidekiq::CLI.banner)}/) do
+              $stdout.stub(:tty?, true) do
+                subject.stub(:launch, nil) do
+                  subject.run
+                end
+              end
+            end
           end
         end
       end
     end
 
-    %w(TSTP USR1).each do |sig|
+    describe 'signal handling' do
-      describe sig do
+      %w(INT TERM).each do |sig|
-        it 'quiets with a corresponding event' do
+        describe sig do
-          quiet = false
+          it 'raises interrupt error' do
-
+            assert_raises Interrupt do
-          Sidekiq.on(:quiet) do
+              subject.handle_signal(sig)
-            quiet = true
+            end
           end
-
-          @cli.parse(%w[sidekiq -r ./test/fake_env.rb])
-          @cli.launcher = Sidekiq::Launcher.new(Sidekiq.options)
-          @cli.handle_signal(sig)
-
-          assert_match(/Got #{sig} signal/, @logdev.string)
-          assert_equal true, quiet
         end
       end
-    end
 
-    describe 'TTIN' do
+      %w(TSTP USR1).each do |sig|
-      it 'prints backtraces for all threads in the process to the logfile' do
+        describe sig do
-        @cli.parse(%w[sidekiq -r ./test/fake_env.rb])
+          it 'quiets with a corresponding event' do
-        @cli.handle_signal('TTIN')
+            quiet = false
 
-        assert_match(/Got TTIN signal/, @logdev.string)
+            Sidekiq.on(:quiet) do
-        assert_match(/\bbacktrace\b/, @logdev.string)
+              quiet = true
+            end
+
+            subject.launcher = Sidekiq::Launcher.new(Sidekiq.options)
+            subject.handle_signal(sig)
+
+            assert_match(/Got #{sig} signal/, logdev.string)
+            assert_equal true, quiet
+          end
+        end
       end
-    end
 
-    describe 'UNKNOWN' do
+      describe 'TTIN' do
-      it 'logs about' do
+        it 'prints backtraces for all threads in the process to the logfile' do
-        @cli.parse(%w[sidekiq -r ./test/fake_env.rb])
+          subject.handle_signal('TTIN')
-        @cli.handle_signal('UNKNOWN')
 
-        assert_match(/Got UNKNOWN signal/, @logdev.string)
+          assert_match(/Got TTIN signal/, logdev.string)
-        assert_match(/No signal handler for UNKNOWN/, @logdev.string)
+          assert_match(/\bbacktrace\b/, logdev.string)
+        end
+      end
+
+      describe 'UNKNOWN' do
+        it 'logs about' do
+          # subject.parse(%w[sidekiq -r ./test/fake_env.rb])
+          subject.handle_signal('UNKNOWN')
+
+          assert_match(/Got UNKNOWN signal/, logdev.string)
+          assert_match(/No signal handler for UNKNOWN/, logdev.string)
+        end
       end
     end
   end

test/test_job_logger.rb

@@ -0,0 +1,56 @@
+# frozen_string_literal: true
+
+require_relative 'helper'
+require 'sidekiq/job_logger'
+
+class TestJobLogger < Minitest::Test
+  describe Sidekiq::JobLogger do
+    subject { Sidekiq::JobLogger.new }
+
+    let(:logdev) { StringIO.new }
+
+    around do |test|
+      Sidekiq.stub :logger, Sidekiq::Logger.new(logdev) do
+        Sidekiq.logger.stub :tid, 'ouy7z76mx' do
+          Process.stub :pid, 4710 do
+            Time.stub :now, Time.utc(2020, 1, 1) do
+              test.call
+            end
+          end
+        end
+      end
+    end
+
+    after do
+      Thread.current[:sidekiq_context] = nil
+    end
+
+    describe '#call' do
+      describe 'when pretty formatter' do
+        before do
+          Sidekiq.logger.formatter = Sidekiq::Logger::Formatters::Pretty.new
+        end
+
+        it 'logs elapsed time as context' do
+          subject.call('item', 'queue') {}
+
+          assert_match(/2020-01-01T00:00:00\.000Z 4710 TID-ouy7z76mx INFO: start/, logdev.string)
+          assert_match(/2020-01-01T00:00:00\.000Z 4710 TID-ouy7z76mx ELAPSED=.+ sec INFO: done/, logdev.string)
+        end
+      end
+
+      describe 'when json formatter' do
+        before do
+          Sidekiq.logger.formatter = Sidekiq::Logger::Formatters::JSON.new
+        end
+
+        it 'logs elapsed time as context' do
+          subject.call('item', 'queue') {}
+
+          assert_match(/ctx.+msg.+start/, logdev.string)
+          assert_match(/ctx.+elapsed.+sec.+msg.+done/, logdev.string)
+        end
+      end
+    end
+  end
+end

test/test_logger.rb

@@ -0,0 +1,235 @@
+# frozen_string_literal: true
+
+require_relative 'helper'
+require 'sidekiq/logger'
+
+class TestLogger < Minitest::Test
+  describe Sidekiq::Logger do
+    let(:logdev) { StringIO.new }
+
+    subject { Sidekiq::Logger.new(logdev) }
+
+    before do
+      Thread.current[:sidekiq_context] = nil
+      Thread.current[:sidekiq_tid] = nil
+    end
+
+    after do
+      Thread.current[:sidekiq_context] = nil
+      Thread.current[:sidekiq_tid] = nil
+    end
+
+    describe 'initialization' do
+      describe 'formatter' do
+        subject { Sidekiq::Logger.new(logdev).formatter }
+
+        describe 'default formatter' do
+          it 'sets pretty formatter' do
+            assert_kind_of Sidekiq::Logger::Formatters::Pretty, subject
+          end
+        end
+
+        describe 'when DYNO env var is present' do
+          around do |test|
+            ENV['DYNO'] = 'dyno identifier'
+            test.call
+            ENV['DYNO'] = nil
+          end
+
+          it 'sets without timestamp formatter' do
+            assert_kind_of Sidekiq::Logger::Formatters::WithoutTimestamp, subject
+          end
+        end
+
+        describe 'when logger formatter :json' do
+          around do |test|
+            Sidekiq.stub :logger_formatter, :json do
+              test.call
+            end
+          end
+
+          it 'sets json formatter' do
+            assert_kind_of Sidekiq::Logger::Formatters::JSON, subject
+          end
+        end
+      end
+    end
+
+    describe '#tid' do
+      describe 'default' do
+        it 'returns formatted thread id' do
+          Thread.current.stub :object_id, 70286338772540 do
+            Process.stub :pid, 6363 do
+              assert_equal 'owx3jd7mv', subject.tid
+            end
+          end
+        end
+      end
+
+      describe 'memoization' do
+        before do
+          Thread.current[:sidekiq_tid] = 'abcdefjhi'
+        end
+
+        it 'current thread :sidekiq_tid attribute reference' do
+          Thread.current.stub :object_id, 70286338772540 do
+            Process.stub :pid, 6363 do
+              assert_equal 'abcdefjhi', subject.tid
+            end
+          end
+        end
+      end
+    end
+
+    describe '#context' do
+      describe 'default' do
+        it 'returns empty hash' do
+          assert_equal({}, subject.context)
+        end
+      end
+
+      describe 'memoization' do
+        before do
+          Thread.current[:sidekiq_context] = { a: 1 }
+        end
+
+        it 'returns current thread :sidekiq_context attribute reference' do
+          assert_equal({ a: 1 }, subject.context)
+        end
+      end
+    end
+
+    describe '#with_context' do
+      it 'adds context to the current thread' do
+        assert_equal({}, subject.context)
+
+        subject.with_context(a: 1) do
+          assert_equal({ a: 1 }, subject.context)
+        end
+
+        assert_equal({}, subject.context)
+      end
+
+      describe 'nested contexts' do
+        it 'adds multiple contexts to the current thread' do
+          assert_equal({}, subject.context)
+
+          subject.with_context(a: 1) do
+            assert_equal({ a: 1 }, subject.context)
+
+            subject.with_context(b: 2, c: 3) do
+              assert_equal({ a: 1, b: 2, c: 3 }, subject.context)
+            end
+
+            assert_equal({ a: 1 }, subject.context)
+          end
+
+          assert_equal({}, subject.context)
+        end
+      end
+    end
+
+    describe 'formatters' do
+      let(:severity) { 'INFO' }
+      let(:utc_time) { Time.utc(2020, 1, 1) }
+      let(:prg) { 'sidekiq' }
+      let(:msg) { 'Old pond frog jumps in sound of water' }
+
+      around do |test|
+        Process.stub :pid, 4710 do
+          Sidekiq.logger.stub :tid, 'ouy7z76mx' do
+            test.call
+          end
+        end
+      end
+
+      describe 'with context' do
+        subject { Sidekiq::Logger::Formatters::Pretty.new.call(severity, utc_time, prg, msg) }
+
+        let(:context) { { class: 'HaikuWorker', bid: nil } }
+
+        around do |test|
+          Sidekiq.logger.stub :context, context do
+            test.call
+          end
+        end
+
+        it 'skips context with nil values' do
+          assert_equal "2020-01-01T00:00:00.000Z 4710 TID-ouy7z76mx CLASS=HaikuWorker INFO: Old pond frog jumps in sound of water\n", subject
+        end
+      end
+
+      describe Sidekiq::Logger::Formatters::Pretty do
+        describe '#call' do
+          subject { Sidekiq::Logger::Formatters::Pretty.new.call(severity, utc_time, prg, msg) }
+
+          it 'formats with timestamp, pid, tid, severity, message' do
+            assert_equal "2020-01-01T00:00:00.000Z 4710 TID-ouy7z76mx INFO: Old pond frog jumps in sound of water\n", subject
+          end
+
+          describe 'with context' do
+            let(:context) { { class: 'HaikuWorker', jid: 'dac39c70844dc0ee3f157ced' } }
+
+            around do |test|
+              Sidekiq.logger.stub :context, context do
+                test.call
+              end
+            end
+
+            it 'formats with timestamp, pid, tid, context, severity, message' do
+              assert_equal "2020-01-01T00:00:00.000Z 4710 TID-ouy7z76mx CLASS=HaikuWorker JID=dac39c70844dc0ee3f157ced INFO: Old pond frog jumps in sound of water\n", subject
+            end
+          end
+        end
+      end
+
+      describe Sidekiq::Logger::Formatters::WithoutTimestamp do
+        describe '#call' do
+          subject { Sidekiq::Logger::Formatters::WithoutTimestamp.new.call(severity, utc_time, prg, msg) }
+
+          it 'formats with pid, tid, severity, message' do
+            assert_equal "4710 TID-ouy7z76mx INFO: Old pond frog jumps in sound of water\n", subject
+          end
+
+          describe 'with context' do
+            let(:context) { { class: 'HaikuWorker', jid: 'dac39c70844dc0ee3f157ced' } }
+
+            around do |test|
+              Sidekiq.logger.stub :context, context do
+                test.call
+              end
+            end
+
+            it 'formats with pid, tid, context, severity, message' do
+              assert_equal "4710 TID-ouy7z76mx CLASS=HaikuWorker JID=dac39c70844dc0ee3f157ced INFO: Old pond frog jumps in sound of water\n", subject
+            end
+          end
+        end
+      end
+
+      describe Sidekiq::Logger::Formatters::JSON do
+        describe '#call' do
+          subject { Sidekiq::Logger::Formatters::JSON.new.call(severity, utc_time, prg, msg) }
+
+          it 'formats with pid, tid, severity, message' do
+            assert_equal %q|{"ts":"2020-01-01T00:00:00.000Z","pid":4710,"tid":"ouy7z76mx","ctx":{},"sev":"INFO","msg":"Old pond frog jumps in sound of water"}|, subject
+          end
+
+          describe 'with context' do
+            let(:context) { { class: 'HaikuWorker', jid: 'dac39c70844dc0ee3f157ced' } }
+
+            around do |test|
+              Sidekiq.logger.stub :context, context do
+                test.call
+              end
+            end
+
+            it 'formats with pid, tid, context, severity, message' do
+              assert_equal %q|{"ts":"2020-01-01T00:00:00.000Z","pid":4710,"tid":"ouy7z76mx","ctx":{"class":"HaikuWorker","jid":"dac39c70844dc0ee3f157ced"},"sev":"INFO","msg":"Old pond frog jumps in sound of water"}|, subject
+            end
+          end
+        end
+      end
+    end
+  end
+end

test/test_logging.rb

@@ -1,35 +0,0 @@
-# frozen_string_literal: true
-require_relative 'helper'
-require 'sidekiq/logging'
-
-class TestLogging < Minitest::Test
-  describe Sidekiq::Logging do
-    describe "#with_context" do
-      def ctx
-        Sidekiq::Logging.logger.formatter.context
-      end
-
-      it "has no context by default" do
-        assert_nil ctx
-      end
-
-      it "can add a context" do
-        Sidekiq::Logging.with_context "xx" do
-          assert_equal " xx", ctx
-        end
-        assert_nil ctx
-      end
-
-      it "can use multiple contexts" do
-        Sidekiq::Logging.with_context "xx" do
-          assert_equal " xx", ctx
-          Sidekiq::Logging.with_context "yy" do
-            assert_equal " xx yy", ctx
-          end
-          assert_equal " xx", ctx
-        end
-        assert_nil ctx
-      end
-    end
-  end
-end

test/test_processor.rb

@@ -338,7 +338,7 @@ class TestProcessor < Minitest::Test
     end
 
     describe 'custom job logger class' do
-      class CustomJobLogger
+      class CustomJobLogger < Sidekiq::JobLogger
         def call(item, queue)
           yield
         rescue Exception
@@ -348,9 +348,9 @@ class TestProcessor < Minitest::Test
 
       before do
         @mgr = Minitest::Mock.new
-        @mgr.expect(:options, {:queues => ['default'], :job_logger => CustomJobLogger})
+        @mgr.expect(:options, {:queues => ['default'], job_logger: CustomJobLogger})
-        @mgr.expect(:options, {:queues => ['default'], :job_logger => CustomJobLogger})
+        @mgr.expect(:options, {:queues => ['default'], job_logger: CustomJobLogger})
-        @mgr.expect(:options, {:queues => ['default'], :job_logger => CustomJobLogger})
+        @mgr.expect(:options, {:queues => ['default'], job_logger: CustomJobLogger})
         @processor = ::Sidekiq::Processor.new(@mgr)
       end