Add error logging to Active Job

Active Job logging instrumentation is changed to log errors (with
backtrace) when a job raises an exception in #perform. This improves
debugging during development and test with the default configuration.

Prior to Rails 5, the default development configuration ran jobs with
InlineAdapter, which would raise exceptions to the caller and be
shown in the development log. In Rails 5, the default adapter was
changed to AsyncAdapter, which would silently swallow exceptions
and log a "Performed SomeJob from Async..." info message. This could
be confusing to a developer, as it would seem that the job was
performed successfully.

This patch removes the "Performed..." info message from the log
and adds an error-level "Error performing SomeJob..." log message
which includes the exception backtrace for jobs that raise an
exception within the #perform method. It provides this behavior for
all adapters.

activejob/CHANGELOG.md

@@ -1 +1,7 @@
+*   Change logging instrumentation to log errors when a job raises an exception.
+
+    Fixes #26848.
+
+    *Steven Bull*
+
 Please check [5-1-stable](https://github.com/rails/rails/blob/5-1-stable/activejob/CHANGELOG.md) for previous changes.

activejob/lib/active_job/logging.rb

@@ -74,9 +74,16 @@ module ActiveJob
         end
 
         def perform(event)
-          info do
-            job = event.payload[:job]
-            "Performed #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)} in #{event.duration.round(2)}ms"
+          job = event.payload[:job]
+          ex = event.payload[:exception_object]
+          if ex
+            error do
+              "Error performing #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)} in #{event.duration.round(2)}ms: #{ex.class} (#{ex.message}):\n" + Array(ex.backtrace).join("\n")
+            end
+          else
+            info do
+              "Performed #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)} in #{event.duration.round(2)}ms"
+            end
           end
         end
 

activejob/test/cases/logging_test.rb

@@ -124,4 +124,11 @@ class LoggingTest < ActiveSupport::TestCase
     set_logger ::Logger.new(nil)
     OverriddenLoggingJob.perform_later "Dummy"
   end
+
+  def test_job_error_logging
+    RescueJob.perform_later "other"
+  rescue RescueJob::OtherError
+    assert_match(/Performing RescueJob \(Job ID: .*?\) from .*? with arguments:.*other/, @logger.messages)
+    assert_match(/Error performing RescueJob \(Job ID: .*?\) from .*? in .*ms: RescueJob::OtherError \(Bad hair\):\n.*\brescue_job\.rb:\d+:in `perform'/, @logger.messages)
+  end
 end

activejob/test/jobs/rescue_job.rb

@@ -19,7 +19,7 @@ class RescueJob < ActiveJob::Base
     when "david"
       raise ArgumentError, "Hair too good"
     when "other"
-      raise OtherError
+      raise OtherError, "Bad hair"
     else
       JobBuffer.add("performed beautifully")
     end

activesupport/lib/active_support/notifications.rb

@@ -64,6 +64,8 @@ module ActiveSupport
   # If an exception happens during that particular instrumentation the payload will
   # have a key <tt>:exception</tt> with an array of two elements as value: a string with
   # the name of the exception class, and the exception message.
+  # The <tt>:exception_object</tt> key of the payload will have the exception
+  # itself as the value.
   #
   # As the previous example depicts, the class <tt>ActiveSupport::Notifications::Event</tt>
   # is able to take the arguments as they come and provide an object-oriented