Include JobID in all ActiveJob info logs

Currently we provide the Job ID in logs only related to enqueuing a job.

This adds the job id to the remaining ActiveJob logs when:
 - a job started performing
 - a job ended performing

Providing the job id in those logs will ease searching logs by job id.
This commit is contained in:
Bolek Kurowski 2017-02-22 16:09:17 -05:00
parent 2e0f7baef3
commit 85c62a2c3d
2 changed files with 8 additions and 8 deletions

View File

@ -69,14 +69,14 @@ module ActiveJob
def perform_start(event)
info do
job = event.payload[:job]
"Performing #{job.class.name} from #{queue_name(event)}" + args_info(job)
"Performing #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)}" + args_info(job)
end
end
def perform(event)
info do
job = event.payload[:job]
"Performed #{job.class.name} from #{queue_name(event)} in #{event.duration.round(2)}ms"
"Performed #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)} in #{event.duration.round(2)}ms"
end
end

View File

@ -89,21 +89,21 @@ class LoggingTest < ActiveSupport::TestCase
def test_perform_job_logging
LoggingJob.perform_later "Dummy"
assert_match(/Performing LoggingJob from .*? with arguments:.*Dummy/, @logger.messages)
assert_match(/Performing LoggingJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
assert_match(/Dummy, here is it: Dummy/, @logger.messages)
assert_match(/Performed LoggingJob from .*? in .*ms/, @logger.messages)
assert_match(/Performed LoggingJob \(Job ID: .*?\) from .*? in .*ms/, @logger.messages)
end
def test_perform_nested_jobs_logging
NestedJob.perform_later
assert_match(/\[LoggingJob\] \[.*?\]/, @logger.messages)
assert_match(/\[ActiveJob\] Enqueued NestedJob \(Job ID: .*\) to/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Performing NestedJob from/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Performing NestedJob \(Job ID: .*?\) from/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Enqueued LoggingJob \(Job ID: .*?\) to .* with arguments: "NestedJob"/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Performing LoggingJob from .* with arguments: "NestedJob"/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Performing LoggingJob \(Job ID: .*?\) from .* with arguments: "NestedJob"/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Dummy, here is it: NestedJob/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Performed LoggingJob from .* in/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Performed NestedJob from .* in/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Performed LoggingJob \(Job ID: .*?\) from .* in/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Performed NestedJob \(Job ID: .*?\) from .* in/, @logger.messages)
end
def test_enqueue_at_job_logging