/activejob/test/cases/logging_test.rb
Ruby | 300 lines | 257 code | 42 blank | 1 comment | 2 complexity | 541f1bf0881ce309720b0b2db042b5f3 MD5 | raw file
- # frozen_string_literal: true
- require "helper"
- require "active_support/log_subscriber/test_helper"
- require "active_support/core_ext/numeric/time"
- require "jobs/hello_job"
- require "jobs/logging_job"
- require "jobs/overridden_logging_job"
- require "jobs/nested_job"
- require "jobs/rescue_job"
- require "jobs/retry_job"
- require "jobs/disable_log_job"
- require "jobs/abort_before_enqueue_job"
- require "models/person"
- class LoggingTest < ActiveSupport::TestCase
- include ActiveJob::TestHelper
- include ActiveSupport::LogSubscriber::TestHelper
- include ActiveSupport::Logger::Severity
- class TestLogger < ActiveSupport::Logger
- def initialize
- @file = StringIO.new
- super(@file)
- end
- def messages
- @file.rewind
- @file.read
- end
- end
- def setup
- super
- JobBuffer.clear
- @old_logger = ActiveJob::Base.logger
- @logger = ActiveSupport::TaggedLogging.new(TestLogger.new)
- set_logger @logger
- ActiveJob::LogSubscriber.attach_to :active_job
- end
- def teardown
- super
- ActiveJob::LogSubscriber.log_subscribers.pop
- set_logger @old_logger
- end
- def set_logger(logger)
- ActiveJob::Base.logger = logger
- end
- def subscribed(&block)
- [].tap do |events|
- ActiveSupport::Notifications.subscribed(-> (*args) { events << args }, /enqueue.*\.active_job/, &block)
- end
- end
- def test_uses_active_job_as_tag
- HelloJob.perform_later "Cristian"
- assert_match(/\[ActiveJob\]/, @logger.messages)
- end
- def test_uses_job_name_as_tag
- perform_enqueued_jobs do
- LoggingJob.perform_later "Dummy"
- assert_match(/\[LoggingJob\]/, @logger.messages)
- end
- end
- def test_uses_job_id_as_tag
- perform_enqueued_jobs do
- LoggingJob.perform_later "Dummy"
- assert_match(/\[LOGGING-JOB-ID\]/, @logger.messages)
- end
- end
- def test_logs_correct_queue_name
- original_queue_name = LoggingJob.queue_name
- LoggingJob.queue_as :php_jobs
- LoggingJob.perform_later("Dummy")
- assert_match(/to .*?\(php_jobs\).*/, @logger.messages)
- ensure
- LoggingJob.queue_name = original_queue_name
- end
- def test_globalid_parameter_logging
- perform_enqueued_jobs do
- person = Person.new(123)
- LoggingJob.perform_later person
- assert_match(%r{Enqueued.*gid://aj/Person/123}, @logger.messages)
- assert_match(%r{Dummy, here is it: #<Person:.*>}, @logger.messages)
- assert_match(%r{Performing.*gid://aj/Person/123}, @logger.messages)
- end
- end
- def test_globalid_nested_parameter_logging
- perform_enqueued_jobs do
- person = Person.new(123)
- LoggingJob.perform_later(person: person)
- assert_match(%r{Enqueued.*gid://aj/Person/123}, @logger.messages)
- assert_match(%r{Dummy, here is it: .*#<Person:.*>}, @logger.messages)
- assert_match(%r{Performing.*gid://aj/Person/123}, @logger.messages)
- end
- end
- def test_enqueue_job_logging
- events = subscribed { HelloJob.perform_later "Cristian" }
- assert_match(/Enqueued HelloJob \(Job ID: .*?\) to .*?:.*Cristian/, @logger.messages)
- assert_equal(events.count, 1)
- key, * = events.first
- assert_equal(key, "enqueue.active_job")
- end
- def test_enqueue_job_log_error_when_callback_chain_is_halted
- events = subscribed { AbortBeforeEnqueueJob.perform_later }
- assert_match(/Failed enqueuing AbortBeforeEnqueueJob.* a before_enqueue callback halted/, @logger.messages)
- assert_equal(events.count, 1)
- key, * = events.first
- assert_equal(key, "enqueue.active_job")
- end
- def test_enqueue_job_log_error_when_error_is_raised_during_callback_chain
- events = subscribed do
- assert_raises(AbortBeforeEnqueueJob::MyError) do
- AbortBeforeEnqueueJob.perform_later(:raise)
- end
- end
- assert_match(/Failed enqueuing AbortBeforeEnqueueJob/, @logger.messages)
- assert_equal(events.count, 1)
- key, * = events.first
- assert_equal(key, "enqueue.active_job")
- end
- def test_perform_job_logging
- perform_enqueued_jobs do
- LoggingJob.perform_later "Dummy"
- assert_match(/Performing LoggingJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
- assert_match(/enqueued at /, @logger.messages)
- assert_match(/Dummy, here is it: Dummy/, @logger.messages)
- assert_match(/Performed LoggingJob \(Job ID: .*?\) from .*? in .*ms/, @logger.messages)
- end
- end
- def test_perform_job_log_error_when_callback_chain_is_halted
- subscribed { AbortBeforeEnqueueJob.perform_now }
- assert_match(/Error performing AbortBeforeEnqueueJob.* a before_perform callback halted/, @logger.messages)
- end
- def test_perform_job_doesnt_log_error_when_job_returns_falsy_value
- job = Class.new(ActiveJob::Base) do
- def perform
- nil
- end
- end
- subscribed { job.perform_now }
- assert_no_match(/Error performing AbortBeforeEnqueueJob.* a before_perform callback halted/, @logger.messages)
- end
- def test_perform_job_doesnt_log_error_when_job_is_performed_multiple_times_and_fail_the_first_time
- job = Class.new(ActiveJob::Base) do
- before_perform do
- throw(:abort) if arguments[0].pop == :abort
- end
- def perform(_)
- end
- end.new([:dont_abort, :abort])
- subscribed do
- job.perform_now
- job.perform_now
- end
- assert_equal(1, @logger.messages.scan(/a before_perform callback halted the job execution/).size)
- end
- def test_perform_disabled_job_logging
- perform_enqueued_jobs do
- DisableLogJob.perform_later "Dummy"
- assert_no_match(/Enqueued DisableLogJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
- assert_no_match(/Performing DisableLogJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
- assert_match(/enqueued at /, @logger.messages)
- assert_match(/Dummy, here is it: Dummy/, @logger.messages)
- assert_match(/Performed DisableLogJob \(Job ID: .*?\) from .*? in .*ms/, @logger.messages)
- end
- end
- def test_perform_nested_jobs_logging
- perform_enqueued_jobs do
- 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 \(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 \(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 \(Job ID: .*?\) from .* in/, @logger.messages)
- assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Performed NestedJob \(Job ID: .*?\) from .* in/, @logger.messages)
- end
- end
- def test_enqueue_at_job_logging
- events = subscribed { HelloJob.set(wait_until: 24.hours.from_now).perform_later "Cristian" }
- assert_match(/Enqueued HelloJob \(Job ID: .*\) to .*? at.*Cristian/, @logger.messages)
- assert_equal(events.count, 1)
- key, * = events.first
- assert_equal(key, "enqueue_at.active_job")
- rescue NotImplementedError
- skip
- end
- def test_enqueue_at_job_log_error_when_callback_chain_is_halted
- events = subscribed { AbortBeforeEnqueueJob.set(wait: 1.second).perform_later }
- assert_match(/Failed enqueuing AbortBeforeEnqueueJob.* a before_enqueue callback halted/, @logger.messages)
- assert_equal(events.count, 1)
- key, * = events.first
- assert_equal(key, "enqueue_at.active_job")
- end
- def test_enqueue_at_job_log_error_when_error_is_raised_during_callback_chain
- events = subscribed do
- assert_raises(AbortBeforeEnqueueJob::MyError) do
- AbortBeforeEnqueueJob.set(wait: 1.second).perform_later(:raise)
- end
- end
- assert_match(/Failed enqueuing AbortBeforeEnqueueJob/, @logger.messages)
- assert_equal(events.count, 1)
- key, * = events.first
- assert_equal(key, "enqueue_at.active_job")
- end
- def test_enqueue_in_job_logging
- events = subscribed { HelloJob.set(wait: 2.seconds).perform_later "Cristian" }
- assert_match(/Enqueued HelloJob \(Job ID: .*\) to .*? at.*Cristian/, @logger.messages)
- assert_equal(events.count, 1)
- key, * = events.first
- assert_equal(key, "enqueue_at.active_job")
- rescue NotImplementedError
- skip
- end
- def test_for_tagged_logger_support_is_consistent
- set_logger ::Logger.new(nil)
- OverriddenLoggingJob.perform_later "Dummy"
- end
- def test_job_error_logging
- perform_enqueued_jobs do
- 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
- def test_job_no_error_logging_on_rescuable_job
- perform_enqueued_jobs { RescueJob.perform_later "david" }
- assert_match(/Performing RescueJob \(Job ID: .*?\) from .*? with arguments:.*david/, @logger.messages)
- assert_no_match(/Error performing RescueJob \(Job ID: .*?\) from .*? in .*ms: ArgumentError \(Hair too good\):\n.*\brescue_job\.rb:\d+:in `perform'/, @logger.messages)
- end
- def test_enqueue_retry_logging
- perform_enqueued_jobs do
- RetryJob.perform_later "DefaultsError", 2
- assert_match(/Retrying RetryJob \(Job ID: .*?\) after \d+ attempts in 3 seconds, due to a DefaultsError.*\./, @logger.messages)
- end
- end
- def test_enqueue_retry_logging_on_retry_job
- perform_enqueued_jobs { RescueJob.perform_later "david" }
- assert_match(/Retrying RescueJob \(Job ID: .*?\) after \d+ attempts in 0 seconds\./, @logger.messages)
- end
- def test_retry_stopped_logging
- perform_enqueued_jobs do
- RetryJob.perform_later "CustomCatchError", 6
- assert_match(/Stopped retrying RetryJob \(Job ID: .*?\) due to a CustomCatchError.*, which reoccurred on \d+ attempts\./, @logger.messages)
- end
- end
- def test_retry_stopped_logging_without_block
- perform_enqueued_jobs do
- RetryJob.perform_later "DefaultsError", 6
- rescue DefaultsError
- assert_match(/Stopped retrying RetryJob \(Job ID: .*?\) due to a DefaultsError.*, which reoccurred on \d+ attempts\./, @logger.messages)
- end
- end
- def test_discard_logging
- perform_enqueued_jobs do
- RetryJob.perform_later "DiscardableError", 2
- assert_match(/Discarded RetryJob \(Job ID: .*?\) due to a DiscardableError.*\./, @logger.messages)
- end
- end
- end