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.

4 files changed, 24 insertions, 4 deletions

diff --git a/activejob/CHANGELOG.md b/activejob/CHANGELOG.md
index 6b4f93df8b..ddfb926e02 100644
--- a/activejob/CHANGELOG.md
+++ b/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.
diff --git a/activejob/lib/active_job/logging.rb b/activejob/lib/active_job/logging.rb
index d7e2cd03e3..f46d5c68a8 100644
--- a/activejob/lib/active_job/logging.rb
+++ b/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
 
diff --git a/activejob/test/cases/logging_test.rb b/activejob/test/cases/logging_test.rb
index b37736f859..e1b546fae7 100644
--- a/activejob/test/cases/logging_test.rb
+++ b/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
diff --git a/activejob/test/jobs/rescue_job.rb b/activejob/test/jobs/rescue_job.rb
index ef8f777437..62add4271a 100644
--- a/activejob/test/jobs/rescue_job.rb
+++ b/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