Created
October 24, 2024 19:29
-
-
Save fractaledmind/353699ed05fa1151e5b5fec6bccefadc to your computer and use it in GitHub Desktop.
This is a reproducible script to demonstrate a bug in ActiveJob related to tagged logging
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
# frozen_string_literal: true | |
require "bundler/inline" | |
gemfile(true) do | |
source "https://rubygems.org" | |
gem "rails", "8.0.0.rc1" | |
# If you want to test against edge Rails replace the previous line with this: | |
# gem "rails", github: "rails/rails", branch: "main" | |
end | |
require "active_job" | |
require "minitest/autorun" | |
$buffer = [] | |
class DefaultsError < StandardError; end | |
class RetryJob < ActiveJob::Base | |
retry_on DefaultsError, attempts: 2 | |
def perform(raising, *) | |
$buffer << [raising, executions] | |
raise raising | |
end | |
end | |
class BuggyJobTest < ActiveJob::TestCase | |
def test_stuff | |
out, err = capture_subprocess_io do | |
perform_enqueued_jobs do | |
assert_raises DefaultsError do | |
RetryJob.perform_later DefaultsError | |
end | |
end | |
end | |
# The logs show job performed twice before being stopped | |
lines = out.split("\n") | |
assert_match( | |
/Performing RetryJob \(Job ID: .{36}\)/, | |
lines[0] | |
) | |
assert_match( | |
/Performing RetryJob \(Job ID: .{36}\)/, | |
lines[1] | |
) | |
assert_match( | |
/Stopped retrying RetryJob \(Job ID: .{36}\)/, | |
lines[2] | |
) | |
assert_equal( | |
[[DefaultsError, 1], [DefaultsError, 2]], | |
$buffer | |
) | |
# However, the logs aren't appropriately tagged, as retried jobs duplicate the job tags | |
assert_match( | |
/\[ActiveJob\] \[RetryJob\] \[.{36}\] Performing RetryJob \(Job ID: .{36}\) from Test\(default\) enqueued at .{30} with arguments: DefaultsError/, | |
lines[0] | |
) | |
assert_match( | |
/\[ActiveJob\] \[RetryJob\] \[.{36}\] Performing RetryJob \(Job ID: .{36}\) from Test\(default\) enqueued at .{30} with arguments: DefaultsError/, | |
lines[1] | |
) | |
assert_match( | |
/\[ActiveJob\] \[RetryJob\] \[.{36}\] Stopped retrying RetryJob \(Job ID: .{36}\) due to a DefaultsError \(DefaultsError\), which reoccurred on 2 attempts/, | |
lines[2] | |
) | |
# logs look like this instead: | |
# [ActiveJob] [RetryJob] [{{job_id}}] Performing RetryJob (Job ID: {{job_id}}) from Test(default) enqueued at {{timestamp}} with arguments: DefaultsError | |
# [ActiveJob] [RetryJob] [{{job_id}}] [RetryJob] [{{job_id}}] Performing RetryJob (Job ID: {{job_id}}) from Test(default) enqueued at {{timestamp}} with arguments: DefaultsError | |
# [ActiveJob] [RetryJob] [{{job_id}}] [RetryJob] [{{job_id}}] [RetryJob] [{{job_id}}] [RetryJob] [{{job_id}}] [RetryJob] [{{job_id}}] Stopped retrying RetryJob (Job ID: {{job_id}}) due to a DefaultsError (DefaultsError), which reoccurred on 2 attempts. | |
end | |
end |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment