Use Sidekiq configuration where possible to override Sidekiq logging

.github/workflows/ci.yml

@@ -31,6 +31,8 @@ jobs:
 
           - rails: "7.1"
             ruby: "3.1"
+          - rails: "7.1b"
+            ruby: "3.1"
           - rails: "7.1.1"
             ruby: "3.2"
           - rails: "7.1"

lib/rails_semantic_logger.rb

@@ -31,6 +31,12 @@ module DelayedJob
     autoload :Plugin, "rails_semantic_logger/delayed_job/plugin"
   end
 
+  module Sidekiq
+    autoload :Defaults, "rails_semantic_logger/sidekiq/defaults"
+    autoload :JobLogger, "rails_semantic_logger/sidekiq/job_logger"
+    autoload :Loggable, "rails_semantic_logger/sidekiq/loggable"
+  end
+
   autoload :Options, "rails_semantic_logger/options"
 
   # Swap an existing subscriber with a new one

lib/rails_semantic_logger/engine.rb

@@ -108,12 +108,31 @@ class Engine < ::Rails::Engine
       Resque.logger        = SemanticLogger[Resque] if defined?(Resque) && Resque.respond_to?(:logger=)
 
       # Replace the Sidekiq logger
-      if defined?(Sidekiq)
-        if Sidekiq.respond_to?(:logger=)
-          Sidekiq.logger = SemanticLogger[Sidekiq]
-        elsif Sidekiq::VERSION[0..1] == "7."
-          method = Sidekiq.server? ? :configure_server : :configure_client
-          Sidekiq.public_send(method) { |cfg| cfg.logger = SemanticLogger[Sidekiq] }
+      if defined?(::Sidekiq)
+        ::Sidekiq.configure_client do |config|
+          config.logger = ::SemanticLogger[::Sidekiq]
+        end
+
+        ::Sidekiq.configure_server do |config|
+          config.logger = ::SemanticLogger[::Sidekiq]
+          if config.respond_to?(:options)
+            config.options[:job_logger] = RailsSemanticLogger::Sidekiq::JobLogger
+          else
+            config[:job_logger] = RailsSemanticLogger::Sidekiq::JobLogger
+          end
+
+          # Add back the default console logger unless already added
+          SemanticLogger.add_appender(io: $stdout, formatter: :color) unless SemanticLogger.appenders.console_output?
+
+          # Replace default error handler when present
+          existing = RailsSemanticLogger::Sidekiq::Defaults.delete_default_error_handler(config.error_handlers)
+          config.error_handlers << RailsSemanticLogger::Sidekiq::Defaults::ERROR_HANDLER if existing
+        end
+
+        if defined?(::Sidekiq::Job) && (::Sidekiq::VERSION.to_i != 5)
+          ::Sidekiq::Job.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
+        else
+          ::Sidekiq::Worker.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
         end
       end
 
@@ -154,15 +173,15 @@ class Engine < ::Rails::Engine
 
       if config.rails_semantic_logger.semantic
         # Active Job
-        if defined?(::ActiveJob) && defined?(::ActiveJob::Logging::LogSubscriber)
+        if defined?(::ActiveJob::Logging::LogSubscriber)
           RailsSemanticLogger.swap_subscriber(
             ::ActiveJob::Logging::LogSubscriber,
             RailsSemanticLogger::ActiveJob::LogSubscriber,
             :active_job
           )
         end
 
-        if defined?(::ActiveJob) && defined?(::ActiveJob::LogSubscriber)
+        if defined?(::ActiveJob::LogSubscriber)
           RailsSemanticLogger.swap_subscriber(
             ::ActiveJob::LogSubscriber,
             RailsSemanticLogger::ActiveJob::LogSubscriber,

lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb

@@ -1,90 +1,14 @@
 # Sidekiq patches
-#
-# To re-enable stdout logging for sidekiq server processes, add the following snippet to config/initializers/sidekiq.rb:
-#   Sidekiq.configure_server do |config|
-#     SemanticLogger.add_appender(io: $stdout, level: :debug, formatter: :color)
-#   end
 if Sidekiq::VERSION.to_i == 4
-  require "sidekiq/exception_handler"
   require "sidekiq/logging"
   require "sidekiq/middleware/server/logging"
   require "sidekiq/processor"
-  require "sidekiq/worker"
 elsif Sidekiq::VERSION.to_i == 5
-  require "sidekiq/exception_handler"
-  require "sidekiq/job_logger"
   require "sidekiq/logging"
-  require "sidekiq/worker"
-elsif Sidekiq::VERSION.to_i == 6 && Sidekiq::VERSION.to_f < 6.5
-  require "sidekiq/exception_handler"
-  require "sidekiq/job_logger"
-  require "sidekiq/worker"
-elsif Sidekiq::VERSION.to_i == 6
-  require "sidekiq/job_logger"
-  require "sidekiq/worker"
-else
-  require "sidekiq/component"
-  require "sidekiq/config"
-  require "sidekiq/job_logger"
-  require "sidekiq/job"
 end
 
 module Sidekiq
-  # Sidekiq > v4
-  if defined?(::Sidekiq::JobLogger)
-    # Let Semantic Logger handle duration logging
-    class JobLogger
-      def call(item, queue, &block)
-        klass  = item["wrapped"] || item["class"]
-        logger = klass ? SemanticLogger[klass] : Sidekiq.logger
-
-        SemanticLogger.tagged(queue: queue) do
-          # Latency is the time between when the job was enqueued and when it started executing.
-          logger.info(
-            "Start #perform",
-            metric:        "sidekiq.queue.latency",
-            metric_amount: job_latency_ms(item)
-          )
-
-          # Measure the duration of running the job
-          logger.measure_info(
-            "Completed #perform",
-            on_exception_level: :error,
-            log_exception:      :full,
-            metric:             "sidekiq.job.perform",
-            &block
-          )
-        end
-      end
-
-      def prepare(job_hash, &block)
-        level = job_hash["log_level"]
-        if level
-          SemanticLogger.silence(level) do
-            SemanticLogger.tagged(job_hash_context(job_hash), &block)
-          end
-        else
-          SemanticLogger.tagged(job_hash_context(job_hash), &block)
-        end
-      end
-
-      def job_hash_context(job_hash)
-        h         = {jid: job_hash["jid"]}
-        h[:bid]   = job_hash["bid"] if job_hash["bid"]
-        h[:tags]  = job_hash["tags"] if job_hash["tags"]
-        h[:queue] = job_hash["queue"] if job_hash["queue"]
-        h
-      end
-
-      def job_latency_ms(job)
-        return unless job && job["enqueued_at"]
-
-        (Time.now.to_f - job["enqueued_at"].to_f) * 1000
-      end
-    end
-  end
-
-  # Sidekiq <= v6
+  # Sidekiq v4 & v5
   if defined?(::Sidekiq::Logging)
     # Replace Sidekiq logging context
     module Logging
@@ -101,106 +25,8 @@ def self.job_hash_context(job_hash)
     end
   end
 
-  # Exception is already logged by Semantic Logger during the perform call
-  if defined?(::Sidekiq::ExceptionHandler)
-    # Sidekiq <= v6.5
-    module ExceptionHandler
-      class Logger
-        def call(_exception, ctx)
-          return if ctx.empty?
-
-          job_hash = ctx[:job] || {}
-          klass    = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
-          logger   = klass ? SemanticLogger[klass] : Sidekiq.logger
-          ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
-        end
-      end
-    end
-  elsif defined?(::Sidekiq::Config)
-    # Sidekiq >= v7
-    class Config
-      remove_const :ERROR_HANDLER
-
-      ERROR_HANDLER = ->(ex, ctx, cfg = Sidekiq.default_configuration) do
-        unless ctx.empty?
-          job_hash = ctx[:job] || {}
-          klass    = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
-          logger   = klass ? SemanticLogger[klass] : Sidekiq.logger
-          ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
-        end
-      end
-    end
-  elsif Sidekiq.error_handlers.delete(Sidekiq::DEFAULT_ERROR_HANDLER)
-    # Sidekiq >= 6.5
-    # Replace default error handler if present
-    Sidekiq.error_handlers << ->(ex, ctx) do
-      unless ctx.empty?
-        job_hash = ctx[:job] || {}
-        klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
-        logger = klass ? SemanticLogger[klass] : Sidekiq.logger
-        ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
-      end
-    end
-  end
-
-  # Logging within each worker should use its own logger
-  case Sidekiq::VERSION.to_i
-  when 4
-    module Worker
-      def self.included(base)
-        if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
-          raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}"
-        end
-
-        base.extend(ClassMethods)
-        base.include(SemanticLogger::Loggable)
-        base.class_attribute :sidekiq_options_hash
-        base.class_attribute :sidekiq_retry_in_block
-        base.class_attribute :sidekiq_retries_exhausted_block
-      end
-    end
-  when 5
-    module Worker
-      def self.included(base)
-        if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
-          raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}"
-        end
-
-        base.extend(ClassMethods)
-        base.include(SemanticLogger::Loggable)
-        base.sidekiq_class_attribute :sidekiq_options_hash
-        base.sidekiq_class_attribute :sidekiq_retry_in_block
-        base.sidekiq_class_attribute :sidekiq_retries_exhausted_block
-      end
-    end
-  when 6
-    module Worker
-      def self.included(base)
-        if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
-          raise ArgumentError, "Sidekiq::Worker cannot be included in an ActiveJob: #{base.name}"
-        end
-
-        base.include(Options)
-        base.extend(ClassMethods)
-        base.include(SemanticLogger::Loggable)
-      end
-    end
-  else
-    module Job
-      def self.included(base)
-        if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
-          raise ArgumentError, "Sidekiq::Job cannot be included in an ActiveJob: #{base.name}"
-        end
-
-        base.include(Options)
-        base.extend(ClassMethods)
-        base.include(SemanticLogger::Loggable)
-      end
-    end
-  end
-
+  # Sidekiq v4
   if defined?(::Sidekiq::Middleware::Server::Logging)
-    # Sidekiq v4
     # Convert string to machine readable format
     class Processor
       def log_context(job_hash)
@@ -215,6 +41,7 @@ def log_context(job_hash)
     module Middleware
       module Server
         class Logging
+          # rubocop:disable Style/ExplicitBlockArgument
           def call(worker, item, queue)
             SemanticLogger.tagged(queue: queue) do
               worker.logger.info(

lib/rails_semantic_logger/sidekiq/defaults.rb

@@ -0,0 +1,40 @@
+module RailsSemanticLogger
+  module Sidekiq
+    module Defaults
+      # Prevent exception logging during standard error handling since the Job Logger below already logs the exception.
+      ERROR_HANDLER =
+        if ::Sidekiq::VERSION.to_f < 7.1 ||
+           (::Sidekiq::VERSION.to_f == 7.1 && ::Sidekiq::VERSION.split(".").last.to_i < 6)
+          lambda do |_ex, ctx|
+            unless ctx.empty?
+              job_hash = ctx[:job] || {}
+              klass    = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
+              logger   = klass ? SemanticLogger[klass] : Sidekiq.logger
+              ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
+            end
+          end
+        else
+          lambda do |_ex, ctx, _default_configuration|
+            unless ctx.empty?
+              job_hash = ctx[:job] || {}
+              klass    = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
+              logger   = klass ? SemanticLogger[klass] : Sidekiq.logger
+              ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
+            end
+          end
+        end
+
+      # Returns the default logger after removing from the supplied list.
+      # Returns [nil] when the default logger was not present.
+      def self.delete_default_error_handler(error_handlers)
+        return error_handlers.delete(::Sidekiq::Config::ERROR_HANDLER) if defined?(::Sidekiq::Config::ERROR_HANDLER)
+        return error_handlers.delete(::Sidekiq::DEFAULT_ERROR_HANDLER) if defined?(::Sidekiq::DEFAULT_ERROR_HANDLER)
+
+        return unless defined?(::Sidekiq::ExceptionHandler)
+
+        existing = error_handlers.find { |handler| handler.is_a?(::Sidekiq::ExceptionHandler::Logger) }
+        error_handlers.delete(existing) if existing
+      end
+    end
+  end
+end

lib/rails_semantic_logger/sidekiq/job_logger.rb

@@ -0,0 +1,59 @@
+module RailsSemanticLogger
+  module Sidekiq
+    class JobLogger
+      # Sidekiq 6.5 does not take any arguments, whereas v7 is given a logger
+      def initialize(*_args)
+      end
+
+      def call(item, queue, &block)
+        klass  = item["wrapped"] || item["class"]
+        logger = klass ? SemanticLogger[klass] : Sidekiq.logger
+
+        SemanticLogger.tagged(queue: queue) do
+          # Latency is the time between when the job was enqueued and when it started executing.
+          logger.info(
+            "Start #perform",
+            metric:        "sidekiq.queue.latency",
+            metric_amount: job_latency_ms(item)
+          )
+
+          # Measure the duration of running the job
+          logger.measure_info(
+            "Completed #perform",
+            on_exception_level: :error,
+            log_exception:      :full,
+            metric:             "sidekiq.job.perform",
+            &block
+          )
+        end
+      end
+
+      def prepare(job_hash, &block)
+        level = job_hash["log_level"]
+        if level
+          SemanticLogger.silence(level) do
+            SemanticLogger.tagged(job_hash_context(job_hash), &block)
+          end
+        else
+          SemanticLogger.tagged(job_hash_context(job_hash), &block)
+        end
+      end
+
+      private
+
+      def job_hash_context(job_hash)
+        h         = {jid: job_hash["jid"]}
+        h[:bid]   = job_hash["bid"] if job_hash["bid"]
+        h[:tags]  = job_hash["tags"] if job_hash["tags"]
+        h[:queue] = job_hash["queue"] if job_hash["queue"]
+        h
+      end
+
+      def job_latency_ms(job)
+        return unless job && job["enqueued_at"]
+
+        (Time.now.to_f - job["enqueued_at"].to_f) * 1000
+      end
+    end
+  end
+end

lib/rails_semantic_logger/sidekiq/loggable.rb

@@ -0,0 +1,10 @@
+module RailsSemanticLogger
+  module Sidekiq
+    module Loggable
+      def included(base)
+        super
+        base.include(SemanticLogger::Loggable)
+      end
+    end
+  end
+end