Prefer Sidekiq.logger, inject message context into all working logging

lib/sidekiq.rb

@@ -1,5 +1,5 @@
 require 'sidekiq/version'
-require 'sidekiq/logger'
+require 'sidekiq/logging'
 require 'sidekiq/client'
 require 'sidekiq/worker'
 require 'sidekiq/redis_connection'
@@ -91,4 +91,8 @@ module Sidekiq
     MultiJson.encode(object)
   end
 
+  def self.logger
+    Sidekiq::Logging.logger
+  end
+
 end

lib/sidekiq/cli.rb

@@ -10,7 +10,7 @@ trap 'TERM' do
 end
 
 trap 'USR1' do
-  Sidekiq::Logger.logger.info "Received USR1, no longer accepting new work"
+  Sidekiq.logger.info "Received USR1, no longer accepting new work"
   mgr = Sidekiq::CLI.instance.manager
   mgr.stop! if mgr
 end
@@ -47,13 +47,13 @@ module Sidekiq
 
     def parse(args=ARGV)
       @code = nil
-      Sidekiq::Logger.logger
+      Sidekiq.logger
 
       cli = parse_options(args)
       config = parse_config(cli)
       options.merge!(config.merge(cli))
 
-      Sidekiq::Logger.logger.level = ::Logger::DEBUG if options[:verbose]
+      Sidekiq.logger.level = Logger::DEBUG if options[:verbose]
       Celluloid.logger = nil
 
       validate!
@@ -134,7 +134,7 @@ module Sidekiq
         end
 
         o.on "-v", "--verbose", "Print more verbose output" do
-          Sidekiq::Logger.logger.level = ::Logger::DEBUG
+          Sidekiq.logger.level = ::Logger::DEBUG
         end
 
         o.on '-e', '--environment ENV', "Application environment" do |arg|

lib/sidekiq/logger.rb

@@ -1,32 +0,0 @@
-require 'time'
-require 'logger'
-
-module Sidekiq
-  module Logger
-
-    class Pretty < ::Logger::Formatter
-      # Provide a call() method that returns the formatted message.
-      def call(severity, time, program_name, message)
-        "#{time.utc.iso8601} #{Process.pid} TID-#{Thread.current.object_id.to_s(36)} #{severity}: #{message}\n"
-      end
-    end
-
-    def self.logger
-      @logger ||= begin
-        log = ::Logger.new(STDOUT)
-        log.level = ::Logger::INFO
-        log.formatter = Pretty.new
-        log
-      end
-    end
-
-    def self.logger=(log)
-      @logger = (log ? log : ::Logger.new('/dev/null'))
-    end
-
-    def logger
-      Sidekiq::Logger.logger
-    end
-
-  end
-end

lib/sidekiq/logging.rb

@@ -0,0 +1,46 @@
+require 'time'
+require 'logger'
+
+module Sidekiq
+  module Logging
+
+    class Pretty < Logger::Formatter
+      # Provide a call() method that returns the formatted message.
+      def call(severity, time, program_name, message)
+        "#{time.utc.iso8601} #{Process.pid} TID-#{Thread.current.object_id.to_s(36)}#{context} #{severity}: #{message}\n"
+      end
+
+      def context
+        c = Thread.current[:sidekiq_context]
+        c ? " #{c}" : ''
+      end
+    end
+
+    def self.with_context(msg)
+      begin
+        Thread.current[:sidekiq_context] = msg
+        yield
+      ensure
+        Thread.current[:sidekiq_context] = nil
+      end
+    end
+
+    def self.logger
+      @logger ||= begin
+        log = Logger.new(STDOUT)
+        log.level = Logger::INFO
+        log.formatter = Pretty.new
+        log
+      end
+    end
+
+    def self.logger=(log)
+      @logger = (log ? log : Logger.new('/dev/null'))
+    end
+
+    def logger
+      Sidekiq::Logging.logger
+    end
+
+  end
+end

lib/sidekiq/middleware/server/logging.rb

@@ -4,14 +4,17 @@ module Sidekiq
       class Logging
 
         def call(*args)
-          static = "#{args[0].class.to_s} MSG-#{args[0].object_id.to_s(36)}" if logger.info?
-          start = Time.now
-          logger.info { "#{static} start" }
-          yield
-          logger.info { "#{static} done: #{elapsed(start)} sec" }
-        rescue
-          logger.info { "#{static} fail: #{elapsed(start)} sec" }
-          raise
+          Sidekiq::Logging.with_context("#{args[0].class.to_s} MSG-#{args[0].object_id.to_s(36)}") do
+            begin
+              start = Time.now
+              logger.info { "start" }
+              yield
+              logger.info { "done: #{elapsed(start)} sec" }
+            rescue
+              logger.info { "fail: #{elapsed(start)} sec" }
+              raise
+            end
+          end
         end
 
         def elapsed(start)
@@ -19,7 +22,7 @@ module Sidekiq
         end
 
         def logger
-          Sidekiq::Logger.logger
+          Sidekiq.logger
         end
       end
     end

lib/sidekiq/util.rb

@@ -26,7 +26,7 @@ module Sidekiq
     end
 
     def logger
-      Sidekiq::Logger.logger
+      Sidekiq.logger
     end
 
     def redis(&block)

lib/sidekiq/worker.rb

@@ -25,7 +25,7 @@ module Sidekiq
     end
 
     def logger
-      Sidekiq::Logger.logger
+      Sidekiq.logger
     end
 
     module ClassMethods

test/helper.rb

@@ -10,7 +10,7 @@ require 'minitest/autorun'
 
 require 'sidekiq'
 require 'sidekiq/util'
-Sidekiq::Logger.logger.level = Logger::ERROR
+Sidekiq.logger.level = Logger::ERROR
 
 require 'sidekiq/redis_connection'
 REDIS = Sidekiq::RedisConnection.create(:url => "redis://localhost/15", :namespace => 'testy')

test/test_cli.rb

@@ -51,11 +51,11 @@ class TestCli < MiniTest::Unit::TestCase
     end
 
     it 'sets verbose' do
-      old = Sidekiq::Logger.logger.level
+      old = Sidekiq.logger.level
       @cli.parse(['sidekiq', '-v', '-r', './test/fake_env.rb'])
-      assert_equal ::Logger::DEBUG, Sidekiq::Logger.logger.level
+      assert_equal Logger::DEBUG, Sidekiq.logger.level
       # If we leave the logger at DEBUG it'll add a lot of noise to the test output
-      Sidekiq::Logger.logger.level = old
+      Sidekiq.logger.level = old
     end
 
     describe 'with pidfile' do