Use Sidekiq configuration where possible to override Sidekiq logging

reidmorrison · reidmorrison · commit 121464a19126 · 2024-07-03T15:23:18.000-04:00
diff --git a/lib/rails_semantic_logger.rb b/lib/rails_semantic_logger.rb
@@ -31,6 +31,11 @@ module DelayedJob
     autoload :Plugin, "rails_semantic_logger/delayed_job/plugin"
   end
 
+  module Sidekiq
+    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
diff --git a/lib/rails_semantic_logger/engine.rb b/lib/rails_semantic_logger/engine.rb
@@ -108,12 +108,61 @@ 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
+
+          SemanticLogger.add_appender(io: $stdout, formatter: :color) unless SemanticLogger.appenders.console_output?
+
+          # Replace default error handler if present
+          # Prevent exception logging since the Job Logger already logged the exception.
+          # Only log the context that was not available during the job_logger call.
+          if defined?(::Sidekiq::ExceptionHandler)
+            existing = ::Sidekiq.error_handlers.find { |handler| handler.is_a?(::Sidekiq::ExceptionHandler::Logger) }
+            if existing && config.error_handlers.delete(existing)
+              config.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
+          elsif defined?(::Sidekiq::DEFAULT_ERROR_HANDLER) && config.error_handlers.delete(::Sidekiq::DEFAULT_ERROR_HANDLER)
+            config.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
+          elsif defined?(::Sidekiq::Config::ERROR_HANDLER) && config.error_handlers.delete(::Sidekiq::Config::ERROR_HANDLER)
+            config.error_handlers << ->(ex, ctx, _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
+        end
+
+        if defined?(::Sidekiq::Job)
+          ::Sidekiq::Job.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
+        else
+          ::Sidekiq::Worker.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
         end
       end
 
@@ -154,15 +203,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,
diff --git a/lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb b/lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb
@@ -1,89 +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/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
@@ -100,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)
diff --git a/lib/rails_semantic_logger/sidekiq/job_logger.rb b/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
diff --git a/lib/rails_semantic_logger/sidekiq/loggable.rb b/lib/rails_semantic_logger/sidekiq/loggable.rb
@@ -0,0 +1,10 @@
+module RailsSemanticLogger
+  module Sidekiq
+    module Loggable
+      def included(base)
+        base.include(SemanticLogger::Loggable)
+        super
+      end
+    end
+  end
+end
diff --git a/test/sidekiq_test.rb b/test/sidekiq_test.rb
@@ -1,5 +1,4 @@
 require_relative "test_helper"
-require "sidekiq/processor"
 
 class SidekiqTest < Minitest::Test
   # Cannot use inline testing since it bypasses the Sidekiq logging calls.
@@ -16,7 +15,7 @@ class SidekiqTest < Minitest::Test
     end
 
     describe "#perform" do
-      let(:config) { Sidekiq::Config.new(error_handlers: []) }
+      let(:config) { Sidekiq.default_configuration }
       let(:msg) { Sidekiq.dump_json({"class" => job.to_s, "args" => args, "enqueued_at" => 1.minute.ago}) }
       let(:uow) { Sidekiq::BasicFetch::UnitOfWork.new("queue:default", msg) }
       if Sidekiq::VERSION.to_i == 6 && Sidekiq::VERSION.to_f < 6.5
diff --git a/test/test_helper.rb b/test/test_helper.rb
@@ -1,5 +1,7 @@
 ENV["RAILS_ENV"] ||= "test"
 ENV["DISABLE_DATABASE_ENVIRONMENT_CHECK"] = "1"
+# Load first so Sidekiq thinks it is running as a server instance
+require "sidekiq/cli"
 require_relative "dummy/config/environment"
 
 require "rails/test_help"
