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.

1 files changed, 10 insertions, 3 deletions

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