Merge pull request reidmorrison#133 from kml/log-payload-when-active_job-performs-with-exception

Log payload when ActiveJob performs with exception

Author: reidmorrison

lib/rails_semantic_logger/active_job/log_subscriber.rb

@@ -5,29 +5,34 @@ module ActiveJob
     class LogSubscriber < ::ActiveSupport::LogSubscriber
       def enqueue(event)
         log_with_formatter event: event do |fmt|
-          "Enqueued #{fmt.job_info}"
+          {message: "Enqueued #{fmt.job_info}"}
         end
       end
 
       def enqueue_at(event)
         log_with_formatter event: event do |fmt|
-          "Enqueued #{fmt.job_info} at #{fmt.scheduled_at}"
+          {message: "Enqueued #{fmt.job_info} at #{fmt.scheduled_at}"}
         end
       end
 
       def perform_start(event)
         log_with_formatter event: event do |fmt|
-          "Performing #{fmt.job_info}"
+          {message: "Performing #{fmt.job_info}"}
         end
       end
 
       def perform(event)
         ex = event.payload[:exception_object]
         if ex
-          logger.error ex
+          log_with_formatter event: event, log_duration: true, level: :error do |fmt|
+            {
+              message: "Error performing #{fmt.job_info} in #{event.duration.round(2)}ms",
+              exception: ex
+            }
+          end
         else
           log_with_formatter event: event, log_duration: true do |fmt|
-            "Performed #{fmt.job_info} in #{event.duration.round(2)}ms"
+            {message: "Performed #{fmt.job_info} in #{event.duration.round(2)}ms"}
           end
         end
       end
@@ -107,10 +112,10 @@ def log_duration?
         end
       end
 
-      def log_with_formatter(**kw_args)
+      def log_with_formatter(level: :info, **kw_args)
         fmt = EventFormatter.new(**kw_args)
         msg = yield fmt
-        logger.info msg, fmt.payload
+        logger.public_send(level, **msg, payload: fmt.payload)
       end
 
       def logger

test/active_job_test.rb

@@ -38,6 +38,12 @@ def id
   describe "ActiveJob" do
     before do
       skip "Older rails does not support ActiveJob" unless defined?(ActiveJob)
+      @mock_logger = MockLogger.new
+      @appender    = SemanticLogger.add_appender(logger: @mock_logger, formatter: :raw)
+    end
+
+    after do
+      SemanticLogger.remove_appender(@appender)
     end
 
     describe ".perform_now" do
@@ -58,12 +64,20 @@ def id
       let(:subscriber) { RailsSemanticLogger::ActiveJob::LogSubscriber.new }
 
       let(:event) do
-        ActiveSupport::Notifications::Event.new "enqueue.active_job",
+        ActiveSupport::Notifications::Event.new event_name,
                                                 5.seconds.ago,
                                                 Time.zone.now,
                                                 SecureRandom.uuid,
-                                                adapter: ActiveJob::QueueAdapters::InlineAdapter.new,
-                                                job:     job
+                                                payload
+      end
+
+      let(:event_name) { "enqueue.active_job" }
+
+      let(:payload) do
+        {
+          adapter: ActiveJob::QueueAdapters::InlineAdapter.new,
+          job:     job
+        }
       end
 
       let(:job) do
@@ -81,19 +95,34 @@ def id
         end
       end
 
+      describe "#perform with exception object" do
+        let(:event_name) { "perform.active_job" }
+
+        let(:payload) do
+          {
+            adapter:          ActiveJob::QueueAdapters::InlineAdapter.new,
+            job:              job,
+            exception_object: ArgumentError.new("error")
+          }
+        end
+
+        specify do
+          subscriber.perform(event)
+
+          SemanticLogger.flush
+          actual = @mock_logger.message
+
+          assert_equal({name: "ArgumentError", message: "error", stack_trace: nil}, actual[:exception])
+          assert_equal("ActiveJobTest::MyJob", actual[:payload][:job_class])
+        end
+      end
+
       describe "ActiveJob::Logging::LogSubscriber::EventFormatter" do
         let(:formatter) do
           RailsSemanticLogger::ActiveJob::LogSubscriber::EventFormatter.new(event: event, log_duration: true)
         end
 
-        let(:event) do
-          ActiveSupport::Notifications::Event.new "perform.active_job",
-                                                  5.seconds.ago,
-                                                  Time.zone.now,
-                                                  "transaction_id",
-                                                  adapter: ActiveJob::QueueAdapters::InlineAdapter.new,
-                                                  job: job
-        end
+        let(:event_name) { "perform.active_job" }
 
         describe "#payload" do
           specify do