From 452f9ee0bcca071cb520d3d640acebdc91f5e3ef Mon Sep 17 00:00:00 2001 From: Steven Bull Date: Mon, 27 Mar 2017 16:16:50 -0700 Subject: 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 | 6 ++++++ activejob/lib/active_job/logging.rb | 13 ++++++++++--- activejob/test/cases/logging_test.rb | 7 +++++++ activejob/test/jobs/rescue_job.rb | 2 +- 4 files changed, 24 insertions(+), 4 deletions(-) (limited to 'activejob') 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 -- cgit v1.2.3 From 8ae20e65827fb2670ca0aaf253247c5e0afc6021 Mon Sep 17 00:00:00 2001 From: "yuuji.yaginuma" Date: Fri, 21 Apr 2017 08:02:26 +0900 Subject: Add missing require Without this, unit test fails. ``` bundle exec ruby -w -Ilib:lib:test test/cases/logging_test.rb Using inline Run options: --seed 41246 # Running: SE......S.... Finished in 0.052938s, 245.5696 runs/s, 831.1585 assertions/s. 1) Error: LoggingTest#test_job_error_logging: NameError: uninitialized constant LoggingTest::RescueJob test/cases/logging_test.rb:130:in `rescue in test_job_error_logging' test/cases/logging_test.rb:129:in `test_job_error_logging' 13 runs, 44 assertions, 0 failures, 1 errors, 2 skips You have skipped tests. Run with --verbose for details. ``` --- activejob/test/cases/logging_test.rb | 1 + 1 file changed, 1 insertion(+) (limited to 'activejob') diff --git a/activejob/test/cases/logging_test.rb b/activejob/test/cases/logging_test.rb index e1b546fae7..d5ca0f385c 100644 --- a/activejob/test/cases/logging_test.rb +++ b/activejob/test/cases/logging_test.rb @@ -5,6 +5,7 @@ require "jobs/hello_job" require "jobs/logging_job" require "jobs/overridden_logging_job" require "jobs/nested_job" +require "jobs/rescue_job" require "models/person" class LoggingTest < ActiveSupport::TestCase -- cgit v1.2.3