Skip to content

Instantly share code, notes, and snippets.

@fractaledmind
Created October 24, 2024 19:29
Show Gist options
  • Save fractaledmind/353699ed05fa1151e5b5fec6bccefadc to your computer and use it in GitHub Desktop.
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
# 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