From b1768de62f2a5c63b143774715efcfbfa02a6c29 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 18:36:40 +1300 Subject: [PATCH 01/10] Log GoodJob's executable as JSON LogStruct turned itself on in Puma, Rails servers and Sidekiq, but not in `good_job start` workers, which kept writing Rails' plain text logs. Treat GoodJob's executable as a server process: it sets GoodJob::CLI.within_exe before it loads the app. GoodJob's executable also adds a plain text STDOUT logger to its log subscriber unless GoodJob.logger already writes to STDOUT, which it can't tell for LogStruct's logger, so every GoodJob line would be written twice. Turn that off when LogStruct replaces GoodJob's logger. --- lib/log_struct/concerns/configuration.rb | 7 ++++ lib/log_struct/integrations/good_job.rb | 6 +++ sorbet/rbi/shims/good_job.rbi | 10 +++++ test/log_struct/configuration_test.rb | 38 +++++++++++++++++++ test/log_struct/integrations/good_job_test.rb | 10 +++++ 5 files changed, 71 insertions(+) diff --git a/lib/log_struct/concerns/configuration.rb b/lib/log_struct/concerns/configuration.rb index 7e611b8d..ff92bac6 100644 --- a/lib/log_struct/concerns/configuration.rb +++ b/lib/log_struct/concerns/configuration.rb @@ -156,6 +156,7 @@ def server_process? return true if defined?(::Falcon::Server) return true if defined?(::Rails::Server) return true if sidekiq_server? + return true if good_job_cli? false end @@ -176,6 +177,12 @@ def sidekiq_server? !!(defined?(::Sidekiq) && ::Sidekiq.respond_to?(:server?) && ::Sidekiq.server?) end + # GoodJob's executable (`good_job start`) sets within_exe before it loads the app + sig { returns(T::Boolean) } + def good_job_cli? + !!(defined?(::GoodJob::CLI) && ::GoodJob::CLI.respond_to?(:within_exe?) && ::GoodJob::CLI.within_exe?) + end + sig { returns(T::Boolean) } def logstruct_server_mode? ::LogStruct.server_mode? diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 93e595a9..75cdfd29 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -78,6 +78,12 @@ def self.configure_logger # Replace GoodJob.logger with our structured logger if GoodJob is available if goodjob_module.respond_to?(:logger=) goodjob_module.logger = LogStruct::Integrations::GoodJob::Logger.new("GoodJob") + + # GoodJob's executable adds a plain text STDOUT logger unless GoodJob.logger already writes + # to STDOUT, which it can't tell for this logger + if defined?(::GoodJob::CLI) && ::GoodJob::CLI.respond_to?(:log_to_stdout=) + ::GoodJob::CLI.log_to_stdout = false + end end # Log thread errors, after calling the handler the app set (GoodJob's README sets one diff --git a/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi index 67195a4f..214d715c 100644 --- a/sorbet/rbi/shims/good_job.rbi +++ b/sorbet/rbi/shims/good_job.rbi @@ -16,4 +16,14 @@ module GoodJob sig { params(handler: T.nilable(T.proc.params(exception: StandardError).void)).void } def on_thread_error=(handler); end end + + class CLI + class << self + sig { returns(T.nilable(T::Boolean)) } + def within_exe?; end + + sig { params(value: T.nilable(T::Boolean)).void } + def log_to_stdout=(value); end + end + end end diff --git a/test/log_struct/configuration_test.rb b/test/log_struct/configuration_test.rb index df215913..aac4e594 100644 --- a/test/log_struct/configuration_test.rb +++ b/test/log_struct/configuration_test.rb @@ -5,6 +5,14 @@ module LogStruct class ConfigurationTest < ActiveSupport::TestCase + # Stands in for GoodJob::CLI (GoodJob isn't installed for the tests) + class FakeGoodJobCLI + class << self + attr_accessor :within_exe + alias_method :within_exe?, :within_exe + end + end + setup do # Save original configuration @original_config = LogStruct.config.dup @@ -303,6 +311,36 @@ def test_enabled_for_server_process_in_production ::Rails.send(:remove_const, :Server) if defined?(::Rails::Server) end + def test_enabled_for_good_job_executable_in_production + original_server_mode = LogStruct.server_mode? + had_rails_server = defined?(::Rails::Server) + LogStruct.server_mode = false + ::Rails.send(:remove_const, :Server) if defined?(::Rails::Server) + LogStruct.config.enabled = false + LogStruct.config.enabled_environments = [:production] + + # GoodJob loads its CLI class in every process; only its executable sets within_exe + raise "GoodJob is loaded in the tests, so this test can't stand in for it" if defined?(::GoodJob) + FakeGoodJobCLI.within_exe = nil + Object.const_set(:GoodJob, Module.new) + ::GoodJob.const_set(:CLI, FakeGoodJobCLI) + + Rails.stub(:env, ActiveSupport::StringInquirer.new("production")) do + LogStruct.set_enabled_from_rails_env! + + assert_not LogStruct.config.enabled, "LogStruct should stay disabled when GoodJob is loaded outside its executable" + + FakeGoodJobCLI.within_exe = true + LogStruct.set_enabled_from_rails_env! + + assert LogStruct.config.enabled, "LogStruct should be enabled in GoodJob's executable in production" + end + ensure + LogStruct.server_mode = T.must(original_server_mode) + ::Rails.const_set(:Server, Class.new) if had_rails_server && !defined?(::Rails::Server) + Object.send(:remove_const, :GoodJob) if defined?(::GoodJob) + end + def test_disabled_for_console_in_production LogStruct.config.enabled = false LogStruct.config.enabled_environments = [:production] diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 26495169..c1046383 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -7,6 +7,13 @@ module LogStruct module Integrations class GoodJobTest < ActiveSupport::TestCase + # Stands in for GoodJob::CLI + class FakeGoodJobCLI + class << self + attr_accessor :log_to_stdout + end + end + setup do @original_config = LogStruct.config LogStruct.configuration = LogStruct::Configuration.new @@ -66,6 +73,7 @@ class GoodJobTest < ActiveSupport::TestCase GoodJob.send(:configure_logger) assert_instance_of GoodJob::Logger, fake.logger + assert_same false, FakeGoodJobCLI.log_to_stdout, "GoodJob's executable shouldn't add a plain text STDOUT logger" logged = [] fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do fake.on_thread_error.call(RuntimeError.new("boom")) @@ -107,6 +115,8 @@ class << self attr_accessor :logger, :on_thread_error end end + FakeGoodJobCLI.log_to_stdout = nil + fake.const_set(:CLI, FakeGoodJobCLI) Object.const_set(:GoodJob, fake) yield fake ensure From 05251dd033e59dc91b781ebc34adfaac9ef00bdf Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 10:40:54 +1300 Subject: [PATCH 02/10] Keep logging GoodJob thread errors when the app sets on_thread_error GoodJob applies config.good_job (logger, on_thread_error) in an after_initialize block. An app that sets on_thread_error there, as GoodJob's README does to report thread errors to an error tracker, replaced LogStruct's handler, so thread errors were reported but no longer logged. LogStruct now wraps the handler again after initialization. --- lib/log_struct/integrations/good_job.rb | 21 ++++++++++++++-- test/log_struct/integrations/good_job_test.rb | 24 +++++++++++++++++++ 2 files changed, 43 insertions(+), 2 deletions(-) diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 75cdfd29..97484cdd 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -59,6 +59,12 @@ def self.setup(config) # Replace GoodJob's logger with our structured logger configure_logger + # GoodJob applies config.good_job in an after_initialize block, so an app that sets + # `on_thread_error` there (as GoodJob's README does) replaces the handler set above + if defined?(::Rails) && ::Rails.application && !::Rails.application.initialized? + ::Rails.application.config.after_initialize { configure_thread_error_handler } + end + # Subscribe to GoodJob's ActiveSupport notifications subscribe_to_notifications @@ -86,8 +92,18 @@ def self.configure_logger end end - # Log thread errors, after calling the handler the app set (GoodJob's README sets one - # to report them to an error tracker). Setting up again keeps the one handler. + configure_thread_error_handler + end + + # Log thread errors, after calling the handler the app set (GoodJob's README sets one + # to report them to an error tracker). Setting up again keeps the one handler. + sig { void } + def self.configure_thread_error_handler + return unless defined?(::GoodJob) + + # Not GoodJob, which here is this module + goodjob_module = ::GoodJob + if goodjob_module.respond_to?(:on_thread_error=) app_handler = goodjob_module.on_thread_error return if app_handler&.equal?(@thread_error_handler) @@ -117,6 +133,7 @@ def self.subscribe_to_notifications end private_class_method :configure_logger + private_class_method :configure_thread_error_handler private_class_method :subscribe_to_notifications end end diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index c1046383..23d22c73 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -84,6 +84,30 @@ class << self end end + test "still logs thread errors when GoodJob applies the app's on_thread_error after initialization" do + with_fake_goodjob do |fake| + after_initialize = [] + ::Rails.application.stub(:initialized?, false) do + ::Rails.application.config.stub(:after_initialize, ->(&block) { after_initialize << block }) do + GoodJob.stub(:subscribe_to_notifications, nil) { GoodJob.setup(LogStruct.config) } + end + end + + # What GoodJob's own after_initialize does with config.good_job.on_thread_error + reported = [] + fake.on_thread_error = ->(exception) { reported << exception.message } + after_initialize.each(&:call) + + logged = [] + fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do + fake.on_thread_error.call(RuntimeError.new("boom")) + end + + assert_equal ["boom"], reported + assert_equal ["boom"], logged + end + end + test "subscribe_to_notifications method exists and is private" do assert_includes GoodJob.private_methods, :subscribe_to_notifications end From 79fa9b435404c5aa490c5b16dbb1001a287a8009 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 16:50:39 +1300 Subject: [PATCH 03/10] Leave GoodJob's thread errors to the structured line GoodJob calls on_thread_error for every error its job and timer tasks raise, and its own log subscriber then logs the same error as "GoodJob error: ..." text with the whole backtrace in the message (over 10KB). LogStruct's thread error handler already logs each one as a structured line, so GoodJob's finished_job_task and finished_timer_task lines are turned off when that handler is in place. --- lib/log_struct/integrations/good_job.rb | 29 ++++++++++++++++++ sorbet/rbi/shims/good_job.rbi | 3 ++ test/log_struct/integrations/good_job_test.rb | 30 +++++++++++++++++++ 3 files changed, 62 insertions(+) diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 97484cdd..d765b87e 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -68,9 +68,27 @@ def self.setup(config) # Subscribe to GoodJob's ActiveSupport notifications subscribe_to_notifications + silence_thread_error_lines + true end + # GoodJob calls `on_thread_error` for every error its job and timer tasks raise, then sends the + # finished_job_task and finished_timer_task notifications. GoodJob::LogSubscriber logs those as + # "GoodJob error: ..." text with the whole backtrace in the message (over 10KB). The thread error + # handler already logs each error as a structured line, so these methods log nothing. + module SilenceThreadErrorLines + extend T::Sig + + sig { params(_event: T.untyped).void } + def finished_timer_task(_event) + end + + sig { params(_event: T.untyped).void } + def finished_job_task(_event) + end + end + @thread_error_handler = T.let(nil, T.nilable(T.proc.params(exception: StandardError).void)) # Configure GoodJob to use LogStruct's structured logger @@ -123,6 +141,16 @@ def self.configure_thread_error_handler end end + # Only when the thread error handler logs these errors instead + sig { void } + def self.silence_thread_error_lines + return unless defined?(::GoodJob::LogSubscriber) + return unless ::GoodJob.respond_to?(:on_thread_error=) + + log_subscriber = ::GoodJob::LogSubscriber + log_subscriber.prepend(SilenceThreadErrorLines) unless log_subscriber.ancestors.include?(SilenceThreadErrorLines) + end + # Subscribe to GoodJob's ActiveSupport notifications sig { void } def self.subscribe_to_notifications @@ -133,6 +161,7 @@ def self.subscribe_to_notifications end private_class_method :configure_logger + private_class_method :silence_thread_error_lines private_class_method :configure_thread_error_handler private_class_method :subscribe_to_notifications end diff --git a/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi index 214d715c..5106162f 100644 --- a/sorbet/rbi/shims/good_job.rbi +++ b/sorbet/rbi/shims/good_job.rbi @@ -17,6 +17,9 @@ module GoodJob def on_thread_error=(handler); end end + # Logs GoodJob's notifications as text + class LogSubscriber; end + class CLI class << self sig { returns(T.nilable(T::Boolean)) } diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 23d22c73..fdb3e15f 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -108,6 +108,36 @@ class << self end end + test "GoodJob's own text lines for thread errors are left to the thread error handler" do + with_fake_goodjob do |fake| + # Like GoodJob::LogSubscriber: these two only log errors, as text with the backtrace in the message + log_subscriber = Class.new do + attr_reader :lines + + def initialize + @lines = [] + end + + def finished_timer_task(event) = @lines << [:timer, event] + + def finished_job_task(event) = @lines << [:job, event] + + def scheduler_create_pool(event) = @lines << [:pool, event] + end + fake.const_set(:LogSubscriber, log_subscriber) + + 2.times { GoodJob.stub(:subscribe_to_notifications, nil) { GoodJob.setup(LogStruct.config) } } + + subscriber = log_subscriber.new + subscriber.finished_timer_task(:event) + subscriber.finished_job_task(:event) + subscriber.scheduler_create_pool(:event) + + assert_equal [[:pool, :event]], subscriber.lines + assert_equal 1, log_subscriber.ancestors.count(GoodJob::SilenceThreadErrorLines) + end + end + test "subscribe_to_notifications method exists and is private" do assert_includes GoodJob.private_methods, :subscribe_to_notifications end From 64030be0614de9bc655b380f9745da0a00ee7297 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 16:57:23 +1300 Subject: [PATCH 04/10] Log GoodJob thread errors through LogStruct's GoodJob logger The thread error handler passes a LogStruct::Log::GoodJob::Error entry to GoodJob.logger, and LogStruct's GoodJob logger wrapped every message in a Log::GoodJob::Log, whose message must be a String. Every thread error raised a TypeError (outside production) or logged a Sorbet error instead of the thread error. The logger now logs LogStruct entries and Hashes as they are, and the thread error line has level error. The tests stubbed the logger, so they never ran this path. --- lib/log_struct/integrations/good_job.rb | 1 + .../integrations/good_job/logger.rb | 5 +++++ .../integrations/good_job/logger_test.rb | 22 +++++++++++++++++++ test/log_struct/integrations/good_job_test.rb | 21 ++++++++++++++++++ 4 files changed, 49 insertions(+) diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index d765b87e..e05a65d8 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -132,6 +132,7 @@ def self.configure_thread_error_handler error_class: exception.class.name, error_message: exception.message, backtrace: exception.backtrace, + level: LogStruct::Level::Error, process_id: ::Process.pid, thread_id: Thread.current.object_id.to_s(36) ) diff --git a/lib/log_struct/integrations/good_job/logger.rb b/lib/log_struct/integrations/good_job/logger.rb index 620ff49a..64bb7a4c 100644 --- a/lib/log_struct/integrations/good_job/logger.rb +++ b/lib/log_struct/integrations/good_job/logger.rb @@ -31,6 +31,11 @@ class Logger < LogStruct::SemanticLogger::Logger # Override log methods to create GoodJob-specific log structs %i[debug info warn error fatal].each do |level| define_method(level) do |message = nil, payload = nil, &block| + # LogStruct log entries and Hashes (like the thread error handler's) are logged as they are + unless message.nil? || message.is_a?(String) + next super(message, payload, &block) + end + # Extract basic job context from thread-local variables job_context = {} diff --git a/test/log_struct/integrations/good_job/logger_test.rb b/test/log_struct/integrations/good_job/logger_test.rb index add5b609..6c64ca0b 100644 --- a/test/log_struct/integrations/good_job/logger_test.rb +++ b/test/log_struct/integrations/good_job/logger_test.rb @@ -61,6 +61,28 @@ class LoggerTest < ActiveSupport::TestCase assert_equal "Job failed", log["msg"] end + test "logs a LogStruct log entry as it is" do + clear_log_buffer(@io) + + @logger.error( + Log::GoodJob::Error.new( + error_class: "RuntimeError", + error_message: "boom", + level: Level::Error, + process_id: Process.pid, + thread_id: "abc" + ) + ) + @logger.info({evt: "custom", note: "hash"}) + ::SemanticLogger.flush + + lines = @io.string.lines.map { |line| JSON.parse(line) } + + assert_equal 2, lines.length + assert_equal %w[error error RuntimeError boom], lines[0].values_at("evt", "lvl", "error_class", "error_message") + assert_equal %w[custom hash], lines[1].values_at("evt", "note") + end + test "extracts job context from thread local variables" do clear_log_buffer(@io) diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index fdb3e15f..b43a5bbe 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -84,6 +84,27 @@ class << self end end + test "a thread error is one structured error line from GoodJob's logger" do + io = setup_isolated_logger + with_fake_goodjob do |fake| + GoodJob.send(:configure_logger) + clear_log_buffer(io) + + error = RuntimeError.new("boom") + error.set_backtrace(["app/jobs/example_job.rb:3:in 'perform'"]) + fake.on_thread_error.call(error) + ::SemanticLogger.flush + + lines = io.string.lines.map { |line| JSON.parse(line) } + + assert_equal 1, lines.length + assert_equal %w[job error error RuntimeError boom], + lines[0].values_at("src", "evt", "lvl", "error_class", "error_message") + end + ensure + teardown_isolated_logger + end + test "still logs thread errors when GoodJob applies the app's on_thread_error after initialization" do with_fake_goodjob do |fake| after_initialize = [] From c970834656d4b5160e94aa82b87c98094f638d57 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 16:58:13 +1300 Subject: [PATCH 05/10] Log GoodJob's notifier and systemd errors without the backtrace GoodJob::LogSubscriber also logs the notifier's and systemd's thread errors as text with the whole backtrace. The notifier only calls on_thread_error after repeated connection errors, so these lines are still logged, with the error class and message only. --- lib/log_struct/integrations/good_job.rb | 40 ++++++++++++++----- sorbet/rbi/shims/good_job.rbi | 5 ++- test/log_struct/integrations/good_job_test.rb | 28 ++++++++++--- 3 files changed, 56 insertions(+), 17 deletions(-) diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index e05a65d8..d6586548 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -68,17 +68,21 @@ def self.setup(config) # Subscribe to GoodJob's ActiveSupport notifications subscribe_to_notifications - silence_thread_error_lines + compact_error_lines true end - # GoodJob calls `on_thread_error` for every error its job and timer tasks raise, then sends the - # finished_job_task and finished_timer_task notifications. GoodJob::LogSubscriber logs those as - # "GoodJob error: ..." text with the whole backtrace in the message (over 10KB). The thread error - # handler already logs each error as a structured line, so these methods log nothing. - module SilenceThreadErrorLines + # GoodJob::LogSubscriber logs errors as text with the whole backtrace in the message (over 10KB). + # GoodJob calls `on_thread_error` for every error its job and timer tasks raise, and the thread + # error handler logs each one as a structured line, so finished_job_task and finished_timer_task + # log nothing. The notifier only calls `on_thread_error` after repeated connection errors, so its + # errors (and systemd's) are still logged, without the backtrace. + module CompactErrorLines extend T::Sig + extend T::Helpers + + requires_ancestor { ::GoodJob::LogSubscriber } sig { params(_event: T.untyped).void } def finished_timer_task(_event) @@ -87,6 +91,22 @@ def finished_timer_task(_event) sig { params(_event: T.untyped).void } def finished_job_task(_event) end + + sig { params(event: T.untyped).void } + def notifier_notify_error(event) + exception = event.payload[:error] + return unless exception + + error { "Notifier errored: #{exception.class}: #{exception}" } + end + + sig { params(event: T.untyped).void } + def systemd_watchdog_error(event) + exception = event.payload[:error] + return unless exception + + error { "Error pinging systemd: #{exception.class}: #{exception}" } + end end @thread_error_handler = T.let(nil, T.nilable(T.proc.params(exception: StandardError).void)) @@ -142,14 +162,14 @@ def self.configure_thread_error_handler end end - # Only when the thread error handler logs these errors instead + # Only when the thread error handler logs thread errors instead sig { void } - def self.silence_thread_error_lines + def self.compact_error_lines return unless defined?(::GoodJob::LogSubscriber) return unless ::GoodJob.respond_to?(:on_thread_error=) log_subscriber = ::GoodJob::LogSubscriber - log_subscriber.prepend(SilenceThreadErrorLines) unless log_subscriber.ancestors.include?(SilenceThreadErrorLines) + log_subscriber.prepend(CompactErrorLines) unless log_subscriber.ancestors.include?(CompactErrorLines) end # Subscribe to GoodJob's ActiveSupport notifications @@ -162,7 +182,7 @@ def self.subscribe_to_notifications end private_class_method :configure_logger - private_class_method :silence_thread_error_lines + private_class_method :compact_error_lines private_class_method :configure_thread_error_handler private_class_method :subscribe_to_notifications end diff --git a/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi index 5106162f..69bf708a 100644 --- a/sorbet/rbi/shims/good_job.rbi +++ b/sorbet/rbi/shims/good_job.rbi @@ -18,7 +18,10 @@ module GoodJob end # Logs GoodJob's notifications as text - class LogSubscriber; end + class LogSubscriber + sig { params(progname: T.untyped, tags: T::Array[T.untyped], block: T.nilable(T.proc.returns(String))).void } + def error(progname = nil, tags: [], &block); end + end class CLI class << self diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index b43a5bbe..a2d1be23 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -129,9 +129,9 @@ class << self end end - test "GoodJob's own text lines for thread errors are left to the thread error handler" do + test "GoodJob's own error lines have no backtrace, and thread errors are left to the thread error handler" do with_fake_goodjob do |fake| - # Like GoodJob::LogSubscriber: these two only log errors, as text with the backtrace in the message + # Like GoodJob::LogSubscriber: it logs errors as text with the whole backtrace in the message log_subscriber = Class.new do attr_reader :lines @@ -143,19 +143,35 @@ def finished_timer_task(event) = @lines << [:timer, event] def finished_job_task(event) = @lines << [:job, event] + def notifier_notify_error(event) = error { "Notifier errored: #{event.payload[:error].backtrace}" } + + def systemd_watchdog_error(event) = error { "Error pinging systemd: #{event.payload[:error].backtrace}" } + def scheduler_create_pool(event) = @lines << [:pool, event] + + def error(progname = nil, tags: [], &block) = @lines << [:error, block ? yield : progname] end fake.const_set(:LogSubscriber, log_subscriber) 2.times { GoodJob.stub(:subscribe_to_notifications, nil) { GoodJob.setup(LogStruct.config) } } + error = IOError.new("connection lost") + error.set_backtrace(["lib/good_job/notifier.rb:1:in 'listen'"]) + event = Struct.new(:payload).new({error: error}) subscriber = log_subscriber.new - subscriber.finished_timer_task(:event) - subscriber.finished_job_task(:event) + subscriber.finished_timer_task(event) + subscriber.finished_job_task(event) + subscriber.notifier_notify_error(event) + subscriber.systemd_watchdog_error(event) subscriber.scheduler_create_pool(:event) - assert_equal [[:pool, :event]], subscriber.lines - assert_equal 1, log_subscriber.ancestors.count(GoodJob::SilenceThreadErrorLines) + assert_equal [ + [:error, "Notifier errored: IOError: connection lost"], + [:error, "Error pinging systemd: IOError: connection lost"], + [:pool, :event] + ], + subscriber.lines + assert_equal 1, log_subscriber.ancestors.count(GoodJob::CompactErrorLines) end end From c9803bc3b419da3a00011e3ae2073c9d165478aa Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 18:18:46 +1300 Subject: [PATCH 06/10] Log GoodJob thread errors whenever the app sets its handler LogStruct logged thread errors by replacing GoodJob.on_thread_error with a handler that called the app's. In a Rails app, GoodJob's engine applies config.good_job.on_thread_error in an after_initialize block that runs after LogStruct's, so it replaced LogStruct's handler and thread errors were reported but not logged. The test stubbed after_initialize, so it never ran the real order. LogStruct now prepends GoodJob._on_thread_error, which every GoodJob component calls with its thread errors: it logs the structured line, then calls whatever handler the app set, whenever it was set. --- lib/log_struct/integrations/good_job.rb | 63 ++++++++++--------- sorbet/rbi/shims/good_job.rbi | 4 ++ test/log_struct/integrations/good_job_test.rb | 26 ++++---- 3 files changed, 50 insertions(+), 43 deletions(-) diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index d6586548..6453e6c0 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -59,12 +59,6 @@ def self.setup(config) # Replace GoodJob's logger with our structured logger configure_logger - # GoodJob applies config.good_job in an after_initialize block, so an app that sets - # `on_thread_error` there (as GoodJob's README does) replaces the handler set above - if defined?(::Rails) && ::Rails.application && !::Rails.application.initialized? - ::Rails.application.config.after_initialize { configure_thread_error_handler } - end - # Subscribe to GoodJob's ActiveSupport notifications subscribe_to_notifications @@ -109,7 +103,20 @@ def systemd_watchdog_error(event) end end - @thread_error_handler = T.let(nil, T.nilable(T.proc.params(exception: StandardError).void)) + # Logs each thread error as a structured line, then calls the handler the app set as + # `on_thread_error` (GoodJob's README sets one to report errors to an error tracker). Every + # GoodJob component passes its thread errors to `GoodJob._on_thread_error`, so this works + # whenever the app sets its handler: GoodJob's engine applies config.good_job.on_thread_error + # after LogStruct's setup. + module LogThreadErrors + extend T::Sig + + sig { params(exception: StandardError).void } + def _on_thread_error(exception) + LogStruct::Integrations::GoodJob.log_thread_error(exception) + super + end + end # Configure GoodJob to use LogStruct's structured logger sig { void } @@ -133,40 +140,36 @@ def self.configure_logger configure_thread_error_handler end - # Log thread errors, after calling the handler the app set (GoodJob's README sets one - # to report them to an error tracker). Setting up again keeps the one handler. sig { void } def self.configure_thread_error_handler return unless defined?(::GoodJob) # Not GoodJob, which here is this module - goodjob_module = ::GoodJob + goodjob_singleton = ::GoodJob.singleton_class + return unless goodjob_singleton.method_defined?(:_on_thread_error) - if goodjob_module.respond_to?(:on_thread_error=) - app_handler = goodjob_module.on_thread_error - return if app_handler&.equal?(@thread_error_handler) - - @thread_error_handler = ->(exception) do - app_handler&.call(exception) - log_entry = LogStruct::Log::GoodJob::Error.new( - error_class: exception.class.name, - error_message: exception.message, - backtrace: exception.backtrace, - level: LogStruct::Level::Error, - process_id: ::Process.pid, - thread_id: Thread.current.object_id.to_s(36) - ) - goodjob_module.logger.error(log_entry) - end - goodjob_module.on_thread_error = @thread_error_handler - end + goodjob_singleton.prepend(LogThreadErrors) unless goodjob_singleton.ancestors.include?(LogThreadErrors) + end + + sig { params(exception: StandardError).void } + def self.log_thread_error(exception) + ::GoodJob.logger.error( + LogStruct::Log::GoodJob::Error.new( + error_class: exception.class.name || exception.class.to_s, + error_message: exception.message, + backtrace: exception.backtrace, + level: LogStruct::Level::Error, + process_id: ::Process.pid, + thread_id: Thread.current.object_id.to_s(36) + ) + ) end - # Only when the thread error handler logs thread errors instead + # Only when LogThreadErrors logs thread errors instead sig { void } def self.compact_error_lines return unless defined?(::GoodJob::LogSubscriber) - return unless ::GoodJob.respond_to?(:on_thread_error=) + return unless ::GoodJob.singleton_class.ancestors.include?(LogThreadErrors) log_subscriber = ::GoodJob::LogSubscriber log_subscriber.prepend(CompactErrorLines) unless log_subscriber.ancestors.include?(CompactErrorLines) diff --git a/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi index 69bf708a..a36e0305 100644 --- a/sorbet/rbi/shims/good_job.rbi +++ b/sorbet/rbi/shims/good_job.rbi @@ -15,6 +15,10 @@ module GoodJob sig { params(handler: T.nilable(T.proc.params(exception: StandardError).void)).void } def on_thread_error=(handler); end + + # Every GoodJob component passes its thread errors here; it calls on_thread_error + sig { params(exception: StandardError).void } + def _on_thread_error(exception); end end # Logs GoodJob's notifications as text diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index a2d1be23..5d5abb4a 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -64,7 +64,7 @@ class << self assert_includes GoodJob.private_methods, :configure_logger end - test "replaces GoodJob's logger and logs thread errors after the app's own handler" do + test "replaces GoodJob's logger, and logs thread errors as well as passing them to the app's handler" do with_fake_goodjob do |fake| reported = [] fake.on_thread_error = ->(exception) { reported << exception.message } @@ -76,7 +76,7 @@ class << self assert_same false, FakeGoodJobCLI.log_to_stdout, "GoodJob's executable shouldn't add a plain text STDOUT logger" logged = [] fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do - fake.on_thread_error.call(RuntimeError.new("boom")) + fake._on_thread_error(RuntimeError.new("boom")) end assert_equal ["boom"], reported @@ -92,7 +92,7 @@ class << self error = RuntimeError.new("boom") error.set_backtrace(["app/jobs/example_job.rb:3:in 'perform'"]) - fake.on_thread_error.call(error) + fake._on_thread_error(error) ::SemanticLogger.flush lines = io.string.lines.map { |line| JSON.parse(line) } @@ -105,23 +105,18 @@ class << self teardown_isolated_logger end - test "still logs thread errors when GoodJob applies the app's on_thread_error after initialization" do + # In a Rails app, GoodJob's engine sets config.good_job.on_thread_error in an after_initialize + # block that runs after LogStruct's setup + test "logs thread errors when the app sets its handler after LogStruct's setup" do with_fake_goodjob do |fake| - after_initialize = [] - ::Rails.application.stub(:initialized?, false) do - ::Rails.application.config.stub(:after_initialize, ->(&block) { after_initialize << block }) do - GoodJob.stub(:subscribe_to_notifications, nil) { GoodJob.setup(LogStruct.config) } - end - end + 2.times { GoodJob.stub(:subscribe_to_notifications, nil) { GoodJob.setup(LogStruct.config) } } - # What GoodJob's own after_initialize does with config.good_job.on_thread_error reported = [] fake.on_thread_error = ->(exception) { reported << exception.message } - after_initialize.each(&:call) logged = [] fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do - fake.on_thread_error.call(RuntimeError.new("boom")) + fake._on_thread_error(RuntimeError.new("boom")) end assert_equal ["boom"], reported @@ -204,6 +199,11 @@ def with_fake_goodjob fake = Module.new do class << self attr_accessor :logger, :on_thread_error + + # Like GoodJob: every thread error goes through here + def _on_thread_error(exception) + on_thread_error.call(exception) if on_thread_error.respond_to?(:call) + end end end FakeGoodJobCLI.log_to_stdout = nil From 09d622ea1d0235e727a025f1736aee81772f8565 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 18:33:49 +1300 Subject: [PATCH 07/10] Remove the GoodJob log subscriber, which listened for events GoodJob doesn't send It handled enqueue, start, finish, error and schedule events, but GoodJob's events are enqueue_job, perform_job and the scheduler, notifier and cron events, so none of its methods ever ran. GoodJob's jobs are already logged by the ActiveJob integration, so subscribing to GoodJob's real events would log every job twice. The docs now say what the integration logs: GoodJob's own messages and its thread errors. --- docs/lib/integration-helpers.ts | 4 +- docs/lib/log-structure-descriptions.ts | 2 +- lib/log_struct/integrations/good_job.rb | 38 +- .../integrations/good_job/log_subscriber.rb | 189 --------- .../good_job/log_subscriber_test.rb | 399 ------------------ test/log_struct/integrations/good_job_test.rb | 8 +- 6 files changed, 11 insertions(+), 629 deletions(-) delete mode 100644 lib/log_struct/integrations/good_job/log_subscriber.rb delete mode 100644 test/log_struct/integrations/good_job/log_subscriber_test.rb diff --git a/docs/lib/integration-helpers.ts b/docs/lib/integration-helpers.ts index cf0955a6..7706c80e 100644 --- a/docs/lib/integration-helpers.ts +++ b/docs/lib/integration-helpers.ts @@ -88,7 +88,7 @@ export function getLogTypeInfo(logType: LogType): { return { title: 'GoodJob', description: - 'The GoodJob integration logs job lifecycle events (enqueue, start, finish, error) with execution context and performance metrics.', + "The GoodJob integration logs GoodJob's own messages and its thread errors as structured lines. GoodJob's jobs are logged by the ActiveJob integration.", }; case LogType.SQL: @@ -150,7 +150,7 @@ export function getEventsForLogType(logType: LogType): Event[] { case LogType.CARRIERWAVE: return [Event.Upload, Event.Delete]; case LogType.GOODJOB: - return [Event.Enqueue, Event.Start, Event.Finish, Event.Error, Event.Log]; + return [Event.Error, Event.Log]; case LogType.SQL: return [Event.Database]; case LogType.ACTIVEMODELSERIALIZERS: diff --git a/docs/lib/log-structure-descriptions.ts b/docs/lib/log-structure-descriptions.ts index 0aa4a7ef..757ec764 100644 --- a/docs/lib/log-structure-descriptions.ts +++ b/docs/lib/log-structure-descriptions.ts @@ -31,7 +31,7 @@ export const LOG_STRUCTURE_DESCRIPTIONS: Record = { 'Request blocked by ActionDispatch::HostAuthorization (host not on the allowed list)', CSRFViolation: 'Request rejected due to a CSRF token violation', IPSpoof: 'Request rejected because the IP address spoofing check failed', - GoodJob: 'For GoodJob background job lifecycle events', + GoodJob: "For GoodJob's own log lines and thread errors", Log: 'Structured GoodJob log output captured from the worker process', SQL: 'For ActiveRecord SQL query events and performance metrics', ActiveModelSerializers: diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 6453e6c0..76cd90b0 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -8,29 +8,17 @@ end require_relative "good_job/logger" if defined?(::GoodJob) -require_relative "good_job/log_subscriber" if defined?(::GoodJob) module LogStruct module Integrations # GoodJob integration for structured logging # - # GoodJob is a PostgreSQL-based ActiveJob backend that provides reliable, - # scalable job processing for Rails applications. This integration provides - # structured logging for all GoodJob operations. + # GoodJob is a PostgreSQL-based ActiveJob backend. Its jobs are logged by the ActiveJob + # integration (enqueued, started, finished, failed), so this integration covers GoodJob itself: # - # ## Features: - # - Structured logging for job execution lifecycle - # - Error tracking and retry logging - # - Performance metrics and timing data - # - Database operation logging - # - Thread and process tracking - # - Custom GoodJob logger with LogStruct formatting - # - # ## Integration Points: - # - Replaces GoodJob.logger with LogStruct-compatible logger - # - Subscribes to GoodJob's ActiveSupport notifications - # - Captures job execution events, errors, and performance metrics - # - Logs database operations and connection information + # - Replaces GoodJob.logger with a LogStruct logger, so GoodJob's own messages are JSON lines + # - Logs each thread error as a structured error line, then calls the app's `on_thread_error` + # - Stops GoodJob's own log subscriber logging those errors again with the whole backtrace # # ## Configuration: # The integration is automatically enabled when GoodJob is detected and @@ -45,8 +33,7 @@ module GoodJob # Set up GoodJob structured logging # - # This method configures GoodJob to use LogStruct's structured logging - # by replacing the default logger and subscribing to job events. + # This method replaces GoodJob's logger and logs its thread errors as structured lines. # # @param config [LogStruct::Configuration] The LogStruct configuration # @return [Boolean, nil] Returns true if setup was successful, nil if skipped @@ -59,9 +46,6 @@ def self.setup(config) # Replace GoodJob's logger with our structured logger configure_logger - # Subscribe to GoodJob's ActiveSupport notifications - subscribe_to_notifications - compact_error_lines true @@ -175,19 +159,9 @@ def self.compact_error_lines log_subscriber.prepend(CompactErrorLines) unless log_subscriber.ancestors.include?(CompactErrorLines) end - # Subscribe to GoodJob's ActiveSupport notifications - sig { void } - def self.subscribe_to_notifications - return unless defined?(::GoodJob) - - # Subscribe to our custom log subscriber for GoodJob events - LogStruct::Integrations::GoodJob::LogSubscriber.attach_to :good_job - end - private_class_method :configure_logger private_class_method :compact_error_lines private_class_method :configure_thread_error_handler - private_class_method :subscribe_to_notifications end end end diff --git a/lib/log_struct/integrations/good_job/log_subscriber.rb b/lib/log_struct/integrations/good_job/log_subscriber.rb deleted file mode 100644 index e63fa261..00000000 --- a/lib/log_struct/integrations/good_job/log_subscriber.rb +++ /dev/null @@ -1,189 +0,0 @@ -# typed: strict -# frozen_string_literal: true - -begin - require "active_support/log_subscriber" -rescue LoadError - # ActiveSupport is not available, log subscriber will be skipped -end - -require_relative "../../log/good_job" -require_relative "../../enums/event" -require_relative "../../enums/level" -require_relative "../event_time" - -module LogStruct - module Integrations - module GoodJob - # LogSubscriber for GoodJob ActiveSupport notifications - # - # This subscriber captures GoodJob's ActiveSupport notifications and converts - # them into structured LogStruct::Log::GoodJob entries. It provides detailed - # logging for job lifecycle events, performance metrics, and error tracking. - # - # ## Supported Events: - # - job.enqueue - Job queued for execution - # - job.start - Job execution started - # - job.finish - Job completed successfully - # - job.error - Job failed with error - # - job.retry - Job retry initiated - # - job.schedule - Job scheduled for future execution - # - # ## Event Data Captured: - # - Job identification (ID, class, queue) - # - Execution context (arguments, priority, scheduled time) - # - Performance metrics (execution time, wait time) - # - Error information (class, message, backtrace) - # - Process and thread information - class LogSubscriber < ::ActiveSupport::LogSubscriber - extend T::Sig - - # Job enqueued event - sig { params(event: ::ActiveSupport::Notifications::Event).void } - def enqueue(event) - payload = T.let(event.payload, T::Hash[Symbol, T.untyped]) - job = payload[:job] - base_fields = build_base_fields(job, payload) - ts = EventTime.coerce_event_time(event.time) - - logger.info(Log::GoodJob::Enqueue.new( - **base_fields.to_kwargs, - scheduled_at: (job&.scheduled_at ? Time.at(job.scheduled_at.to_i) : nil), - duration_ms: event.duration.to_f, - enqueue_caller: job&.enqueue_caller_location, - timestamp: ts - )) - end - - # Job execution started event - sig { params(event: ::ActiveSupport::Notifications::Event).void } - def start(event) - payload = T.let(event.payload, T::Hash[Symbol, T.untyped]) - job = payload[:job] - execution = payload[:execution] || payload[:good_job_execution] - base_fields = build_base_fields(job, payload) - ts = EventTime.coerce_event_time(event.time) - - logger.info(Log::GoodJob::Start.new( - **base_fields.to_kwargs, - wait_ms: begin - wt = execution&.wait_time || calculate_wait_time(execution) - wt ? (wt.to_f * 1000.0) : nil - end, - scheduled_at: (job&.scheduled_at ? Time.at(job.scheduled_at.to_i) : nil), - process_id: ::Process.pid, - thread_id: Thread.current.object_id.to_s(36), - timestamp: ts - )) - end - - # Job completed successfully event - sig { params(event: ::ActiveSupport::Notifications::Event).void } - def finish(event) - payload = T.let(event.payload, T::Hash[Symbol, T.untyped]) - job = payload[:job] - base_fields = build_base_fields(job, payload) - start_ts = EventTime.coerce_event_time(event.time) - end_ts = EventTime.coerce_event_time(event.end) - - logger.info(Log::GoodJob::Finish.new( - **base_fields.to_kwargs, - duration_ms: event.duration.to_f, - finished_at: end_ts, - process_id: ::Process.pid, - thread_id: Thread.current.object_id.to_s(36), - result: payload[:result]&.to_s, - timestamp: start_ts - )) - end - - # Job failed with error event - sig { params(event: ::ActiveSupport::Notifications::Event).void } - def error(event) - payload = T.let(event.payload, T::Hash[Symbol, T.untyped]) - job = payload[:job] - execution = payload[:execution] || payload[:good_job_execution] - exception = payload[:exception] || payload[:error] - ts = EventTime.coerce_event_time(event.time) - base_fields = build_base_fields(job, payload) - - logger.error(Log::GoodJob::Error.new( - **base_fields.to_kwargs, - exception_executions: execution&.exception_executions, - error_class: exception&.class&.name, - error_message: exception&.message, - backtrace: exception&.backtrace, - duration_ms: event.duration.to_f, - process_id: ::Process.pid, - thread_id: Thread.current.object_id.to_s(36), - timestamp: ts - )) - end - - # Job scheduled for future execution event - sig { params(event: ::ActiveSupport::Notifications::Event).void } - def schedule(event) - payload = T.let(event.payload, T::Hash[Symbol, T.untyped]) - job = payload[:job] - base_fields = build_base_fields(job, payload) - ts = EventTime.coerce_event_time(event.time) - - logger.info(Log::GoodJob::Schedule.new( - **base_fields.to_kwargs, - scheduled_at: (job&.scheduled_at ? Time.at(job.scheduled_at.to_i) : nil), - priority: job&.priority, - cron_key: job&.cron_key, - duration_ms: event.duration.to_f, - timestamp: ts - )) - end - - private - - # Build BaseFields from job + payload (execution) - sig { params(job: T.untyped, payload: T::Hash[Symbol, T.untyped]).returns(Log::GoodJob::BaseFields) } - def build_base_fields(job, payload) - execution = payload[:execution] || payload[:good_job_execution] - Log::GoodJob::BaseFields.new( - job_id: job&.job_id, - job_class: job&.job_class, - queue_name: job&.queue_name&.to_sym, - arguments: safe_arguments(job), - executions: execution&.executions - ) - end - - # Respect log_arguments? setting on job classes (consistent with ActiveJob behavior). - # Arguments are logged by default but can be opted-out per job class. - # When logged, sensitive keys are filtered by Formatter.process_values. - sig { params(job: T.untyped).returns(T.nilable(T::Array[T.untyped])) } - def safe_arguments(job) - return nil unless job - return job.arguments unless job.class.respond_to?(:log_arguments?) - job.class.log_arguments? ? job.arguments : nil - end - - # Calculate wait time from job creation to execution start - sig { params(execution: T.untyped).returns(T.nilable(Float)) } - def calculate_wait_time(execution) - return nil unless execution.respond_to?(:created_at) - return nil unless execution.respond_to?(:performed_at) - return nil unless execution.created_at && execution.performed_at - - (execution.performed_at - execution.created_at).to_f - rescue - # Return nil if calculation fails - nil - end - - # Get the appropriate logger for GoodJob events - sig { returns(T.untyped) } - def logger - # Always use Rails.logger - in production it will be configured by the integration setup, - # in tests it will be set up by the test harness - Rails.logger - end - end - end - end -end diff --git a/test/log_struct/integrations/good_job/log_subscriber_test.rb b/test/log_struct/integrations/good_job/log_subscriber_test.rb deleted file mode 100644 index b0b31459..00000000 --- a/test/log_struct/integrations/good_job/log_subscriber_test.rb +++ /dev/null @@ -1,399 +0,0 @@ -# typed: true -# frozen_string_literal: true - -require "test_helper" -require "log_struct/integrations/good_job/log_subscriber" -require "active_support/notifications" -require "stringio" - -module LogStruct - module Integrations - module GoodJob - class LogSubscriberTest < ActiveSupport::TestCase - setup do - @original_logger = Rails.logger - @log_output = setup_isolated_logger - Rails.logger = LogStruct::SemanticLogger::Logger.new("TestLogger") - @subscriber = LogSubscriber.new - end - - teardown do - Rails.logger = @original_logger - teardown_isolated_logger - end - - test "extends ActiveSupport LogSubscriber" do - assert_kind_of ::ActiveSupport::LogSubscriber, @subscriber - end - - test "responds to job event methods" do - assert_respond_to @subscriber, :enqueue - assert_respond_to @subscriber, :start - assert_respond_to @subscriber, :finish - assert_respond_to @subscriber, :error - assert_respond_to @subscriber, :schedule - end - - test "enqueue event creates proper log entry" do - clear_log_buffer(@log_output) - - event_data = create_test_event({ - job: create_mock_job("UserNotificationJob", "job_123", "default"), - duration: 0.1 - }) - - @subscriber.enqueue(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - assert_equal "job", log["src"] - assert_equal "enqueue", log["evt"] - assert_equal "info", log["lvl"] - assert_equal "job_123", log["job_id"] - assert_equal "UserNotificationJob", log["job_class"] - assert_equal "default", log["queue_name"] - assert_in_delta(100.0, log["duration_ms"]) - end - - test "start event creates proper log entry" do - clear_log_buffer(@log_output) - - event_data = create_test_event({ - job: create_mock_job("TestJob", "job_456", "priority"), - execution: create_mock_execution(executions: 1, wait_time: 0.5) - }) - - @subscriber.start(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - assert_equal "start", log["evt"] - assert_equal "job_456", log["job_id"] - assert_equal "TestJob", log["job_class"] - assert_equal "priority", log["queue_name"] - assert_equal 1, log["executions"] - assert_in_delta(500.0, log["wait_ms"]) - assert_equal Process.pid, log["pid"] - assert log["tid"] - end - - test "finish event creates proper log entry" do - clear_log_buffer(@log_output) - - event_data = create_test_event({ - job: create_mock_job("CompletedJob", "job_789", "default"), - execution: create_mock_execution(executions: 1), - duration: 2.5, - result: "success" - }) - - @subscriber.finish(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - assert_equal "finish", log["evt"] - assert_equal "job_789", log["job_id"] - assert_equal "CompletedJob", log["job_class"] - assert_equal 1, log["executions"] - assert_in_delta(2500.0, log["duration_ms"]) - assert log["finished_at"] - assert_equal "success", log["result"] - end - - test "converts monotonic event times to wall clock" do - clear_log_buffer(@log_output) - - start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) - finish_time = start_time + 0.25 - event_data = create_test_event({ - job: create_mock_job("CompletedJob", "job_789", "default"), - execution: create_mock_execution(executions: 1), - duration: 0.25, - result: "success" - }, - start_time: start_time, - finish_time: finish_time) - - @subscriber.finish(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - now = ::Time.now - ts = ::Time.iso8601(log["ts"]) - finished_at = ::Time.iso8601(log["finished_at"]) - - assert_in_delta now.to_f, ts.to_f, 5.0 - assert_in_delta now.to_f, finished_at.to_f, 5.0 - end - - test "error event creates proper log entry" do - clear_log_buffer(@log_output) - - exception = StandardError.new("Job processing failed") - exception.set_backtrace(["file1.rb:10", "file2.rb:20", "file3.rb:30"]) - - event_data = create_test_event({ - job: create_mock_job("FailedJob", "job_error", "critical"), - execution: create_mock_execution(executions: 2, exception_executions: 1), - exception: exception, - duration: 1.2 - }) - - @subscriber.error(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - assert_equal "error", log["evt"] - assert_equal "error", log["lvl"] - assert_equal "job_error", log["job_id"] - assert_equal "FailedJob", log["job_class"] - assert_equal 2, log["executions"] - assert_equal 1, log["exception_executions"] - assert_equal "StandardError", log["error_class"] - assert_equal "Job processing failed", log["error_message"] - assert_equal ["file1.rb:10", "file2.rb:20", "file3.rb:30"], log["backtrace"] - assert_in_delta(1200.0, log["duration_ms"]) - end - - test "schedule event creates proper log entry" do - clear_log_buffer(@log_output) - - scheduled_time = Time.now + 1.hour - event_data = create_test_event({ - job: create_mock_job("ScheduledJob", - "job_scheduled", - "later", - { - scheduled_at: scheduled_time, - priority: 10, - cron_key: "daily_cleanup" - }), - duration: 0.05 - }) - - @subscriber.schedule(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - assert_equal "schedule", log["evt"] - assert_equal "job_scheduled", log["job_id"] - assert_equal "ScheduledJob", log["job_class"] - assert_equal "later", log["queue_name"] - assert_equal scheduled_time.iso8601, log["scheduled_at"] - assert_equal 10, log["priority"] - assert_equal "daily_cleanup", log["cron_key"] - assert_in_delta(50.0, log["duration_ms"]) - end - - test "handles missing job data gracefully" do - clear_log_buffer(@log_output) - - # Event with minimal data - event_data = create_test_event({}) - - @subscriber.enqueue(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - # Should still create a valid log entry - assert_equal "enqueue", log["evt"] - assert_equal "job", log["src"] - - # Missing fields should not be present - refute log.key?("job_id") - refute log.key?("job_class") - end - - test "truncates long backtraces" do - clear_log_buffer(@log_output) - - exception = StandardError.new("Test error") - # Create a very long backtrace (more than 20 lines) - long_backtrace = (1..30).map { |i| "file#{i}.rb:#{i}" } - exception.set_backtrace(long_backtrace) - - event_data = create_test_event({ - job: create_mock_job("TestJob", "job_123", "default"), - exception: exception - }) - - @subscriber.error(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - # Should limit backtrace to 5 lines (done in Error#to_h) - assert_equal 5, log["backtrace"].length - assert_equal "file1.rb:1", log["backtrace"].first - assert_equal "file5.rb:5", log["backtrace"].last - end - - test "calculates wait_time correctly" do - created_at = Time.now - 5.0 # 5 seconds ago - performed_at = Time.now - - execution = create_mock_execution({ - created_at: created_at, - performed_at: performed_at - }) - - wait_time = @subscriber.send(:calculate_wait_time, execution) - - assert_in_delta 5.0, wait_time, 0.1 # Allow small timing differences - end - - test "handles missing timestamps in wait_time calculation" do - # Execution without timestamps - execution = create_mock_execution({created_at: nil, performed_at: nil}) - - wait_time = @subscriber.send(:calculate_wait_time, execution) - - assert_nil wait_time - end - - test "respects log_arguments? when job class opts out" do - clear_log_buffer(@log_output) - - # Create a job class that opts out of logging arguments - job_class = Class.new do - def self.log_arguments? - false - end - end - Object.const_set(:NoLogArgsJob, job_class) - - begin - log = run_enqueue_with_job_class(:NoLogArgsJob) - - refute log.key?("arguments") - ensure - Object.send(:remove_const, :NoLogArgsJob) - end - end - - test "logs arguments by default when job class does not define log_arguments?" do - clear_log_buffer(@log_output) - - # Standard job without log_arguments? defined - should log arguments - job = create_mock_job("StandardJob", "job_123", "default") - event_data = create_test_event({ - job: job, - duration: 0.1 - }) - - @subscriber.enqueue(event_data) - ::SemanticLogger.flush - - output = @log_output.string - log = JSON.parse(output.lines.first.strip) - - # Arguments should be present by default - assert log.key?("arguments") - assert_equal ["arg1", "arg2"], log["arguments"] - end - - test "logs arguments when job class log_arguments? returns true" do - clear_log_buffer(@log_output) - - job_class = Class.new do - def self.log_arguments? - true - end - end - Object.const_set(:LogArgsJob, job_class) - - begin - log = run_enqueue_with_job_class(:LogArgsJob) - - assert log.key?("arguments") - assert_equal ["arg1", "arg2"], log["arguments"] - ensure - Object.send(:remove_const, :LogArgsJob) - end - end - - private - - def create_test_event(payload_data, start_time: nil, finish_time: nil) - duration = payload_data[:duration] || 0.0 - start = start_time || Time.now.to_f - finish = finish_time || start + duration - ActiveSupport::Notifications::Event.new( - "good_job.test", - start, - finish, - "test", - payload_data - ) - end - - def create_mock_job(job_class, job_id, queue_name, extra_attributes = {}) - OpenStruct.new({ - job_class: job_class, - job_id: job_id, - queue_name: queue_name, - arguments: ["arg1", "arg2"], - priority: 0, - scheduled_at: nil, - enqueue_caller_location: nil - }.merge(extra_attributes)) - end - - # Create a mock job where job.class returns the actual job class (for testing log_arguments?) - def create_mock_job_with_class(klass, job_id, queue_name, extra_attributes = {}) - mock = Object.new - mock.define_singleton_method(:class) { klass } - mock.define_singleton_method(:job_class) { klass.name } - mock.define_singleton_method(:job_id) { job_id } - mock.define_singleton_method(:queue_name) { queue_name } - mock.define_singleton_method(:arguments) { ["arg1", "arg2"] } - mock.define_singleton_method(:priority) { 0 } - mock.define_singleton_method(:scheduled_at) { nil } - mock.define_singleton_method(:enqueue_caller_location) { nil } - extra_attributes.each do |key, value| - mock.define_singleton_method(key) { value } - end - mock - end - - # Run an enqueue event with a job class that has log_arguments? method and return the parsed log - def run_enqueue_with_job_class(job_class) - # rubocop:disable Sorbet/ConstantsFromStrings - klass = Object.const_get(job_class) - # rubocop:enable Sorbet/ConstantsFromStrings - job = create_mock_job_with_class(klass, "job_123", "default") - event_data = create_test_event({job: job, duration: 0.1}) - @subscriber.enqueue(event_data) - ::SemanticLogger.flush - JSON.parse(@log_output.string.lines.first.strip) - end - - def create_mock_execution(attributes = {}) - OpenStruct.new({ - executions: 1, - exception_executions: 0, - created_at: Time.now - 1, - performed_at: Time.now, - batch_id: nil, - cron_key: nil - }.merge(attributes)) - end - end - end - end -end diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 5d5abb4a..80990db5 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -109,7 +109,7 @@ class << self # block that runs after LogStruct's setup test "logs thread errors when the app sets its handler after LogStruct's setup" do with_fake_goodjob do |fake| - 2.times { GoodJob.stub(:subscribe_to_notifications, nil) { GoodJob.setup(LogStruct.config) } } + 2.times { GoodJob.setup(LogStruct.config) } reported = [] fake.on_thread_error = ->(exception) { reported << exception.message } @@ -148,7 +148,7 @@ def error(progname = nil, tags: [], &block) = @lines << [:error, block ? yield : end fake.const_set(:LogSubscriber, log_subscriber) - 2.times { GoodJob.stub(:subscribe_to_notifications, nil) { GoodJob.setup(LogStruct.config) } } + 2.times { GoodJob.setup(LogStruct.config) } error = IOError.new("connection lost") error.set_backtrace(["lib/good_job/notifier.rb:1:in 'listen'"]) @@ -170,10 +170,6 @@ def error(progname = nil, tags: [], &block) = @lines << [:error, block ? yield : end end - test "subscribe_to_notifications method exists and is private" do - assert_includes GoodJob.private_methods, :subscribe_to_notifications - end - test "integration is included in automatic setup" do # Check that GoodJob is required in integrations.rb integrations_file = File.read( From e9a315647491615fe6953fab602d15a9f18a3d3c Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 21:05:32 +1300 Subject: [PATCH 08/10] Log each GoodJob error once, including exceptions that aren't StandardErrors GoodJob passes every unhandled job exception to on_thread_error, after the ActiveJob integration has already logged it with the job's ID and class, so each failed job was logged as two job error lines. The ActiveJob integration now records the exceptions it logs (LogStruct::LoggedErrors, which holds them weakly), and the thread error line skips them. The app's handler still gets every error. GoodJob's notifier passes every error except connection errors to on_thread_error straight away, and systemd watchdog errors always, so GoodJob's own lines for those are off too. The notifier's line for connection errors is kept, since it passes those on only once they repeat. The finished_timer_task override is gone: GoodJob instruments that event without the .good_job suffix, so its log subscriber never receives it. GoodJob passes any Exception that its handled_exceptions setting lets through, and ActiveJob's perform_now lets any Exception through. Both handlers' signatures only accepted StandardError, so outside production a NotImplementedError raised a TypeError and the app's handler was skipped. Log::Error's error_class is now any Exception class. --- lib/log_struct.rb | 1 + .../integrations/active_job/log_subscriber.rb | 5 +- lib/log_struct/integrations/good_job.rb | 43 +++++---- lib/log_struct/log.rb | 2 +- lib/log_struct/log/error.rb | 2 +- lib/log_struct/logged_errors.rb | 25 +++++ schemas/log_sources/error.yml | 2 +- schemas/meta/log-source-schema.json | 1 + sorbet/rbi/shims/good_job.rbi | 21 ++++- .../active_job/log_subscriber_test.rb | 27 ++++++ test/log_struct/integrations/good_job_test.rb | 92 +++++++++++++------ 11 files changed, 167 insertions(+), 54 deletions(-) create mode 100644 lib/log_struct/logged_errors.rb diff --git a/lib/log_struct.rb b/lib/log_struct.rb index c1832cf3..39079282 100644 --- a/lib/log_struct.rb +++ b/lib/log_struct.rb @@ -7,6 +7,7 @@ require "log_struct/enums" require "log_struct/configuration" require "log_struct/formatter" +require "log_struct/logged_errors" require "log_struct/railtie" require "log_struct/concerns/error_handling" require "log_struct/concerns/configuration" diff --git a/lib/log_struct/integrations/active_job/log_subscriber.rb b/lib/log_struct/integrations/active_job/log_subscriber.rb index 534b2d4e..a5176679 100644 --- a/lib/log_struct/integrations/active_job/log_subscriber.rb +++ b/lib/log_struct/integrations/active_job/log_subscriber.rb @@ -89,7 +89,8 @@ def build_base_fields(job) ) end - sig { params(exception: StandardError, job: ::ActiveJob::Base, _event: ::ActiveSupport::Notifications::Event).void } + # perform_now lets any Exception through, not only StandardErrors + sig { params(exception: Exception, job: ::ActiveJob::Base, _event: ::ActiveSupport::Notifications::Event).void } def log_exception(exception, job, _event) base_fields = build_base_fields(job) job_context = base_fields.to_kwargs @@ -97,6 +98,8 @@ def log_exception(exception, job, _event) log_data = Log.from_exception(Source::Job, exception, job_context) logger.error(log_data) + # So a backend that reports the same exception (GoodJob's on_thread_error) doesn't log it again + LogStruct::LoggedErrors.mark(exception) end sig { returns(T.untyped) } diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 76cd90b0..57d88de6 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -52,20 +52,16 @@ def self.setup(config) end # GoodJob::LogSubscriber logs errors as text with the whole backtrace in the message (over 10KB). - # GoodJob calls `on_thread_error` for every error its job and timer tasks raise, and the thread - # error handler logs each one as a structured line, so finished_job_task and finished_timer_task - # log nothing. The notifier only calls `on_thread_error` after repeated connection errors, so its - # errors (and systemd's) are still logged, without the backtrace. + # GoodJob passes every error its job tasks raise, every systemd watchdog error and every notifier + # error except connection errors to `on_thread_error`, which LogThreadErrors logs as a structured + # line, so GoodJob's own lines for those are off. The notifier passes connection errors on only + # once they repeat, so its line for them is kept, without the backtrace. module CompactErrorLines extend T::Sig extend T::Helpers requires_ancestor { ::GoodJob::LogSubscriber } - sig { params(_event: T.untyped).void } - def finished_timer_task(_event) - end - sig { params(_event: T.untyped).void } def finished_job_task(_event) end @@ -74,16 +70,13 @@ def finished_job_task(_event) def notifier_notify_error(event) exception = event.payload[:error] return unless exception + return unless LogStruct::Integrations::GoodJob.notifier_connection_error?(exception) error { "Notifier errored: #{exception.class}: #{exception}" } end - sig { params(event: T.untyped).void } - def systemd_watchdog_error(event) - exception = event.payload[:error] - return unless exception - - error { "Error pinging systemd: #{exception.class}: #{exception}" } + sig { params(_event: T.untyped).void } + def systemd_watchdog_error(_event) end end @@ -91,11 +84,12 @@ def systemd_watchdog_error(event) # `on_thread_error` (GoodJob's README sets one to report errors to an error tracker). Every # GoodJob component passes its thread errors to `GoodJob._on_thread_error`, so this works # whenever the app sets its handler: GoodJob's engine applies config.good_job.on_thread_error - # after LogStruct's setup. + # after LogStruct's setup. GoodJob passes any Exception its handled_exceptions setting lets + # through, not only StandardErrors. module LogThreadErrors extend T::Sig - sig { params(exception: StandardError).void } + sig { params(exception: Exception).void } def _on_thread_error(exception) LogStruct::Integrations::GoodJob.log_thread_error(exception) super @@ -135,8 +129,12 @@ def self.configure_thread_error_handler goodjob_singleton.prepend(LogThreadErrors) unless goodjob_singleton.ancestors.include?(LogThreadErrors) end - sig { params(exception: StandardError).void } + # A failed job's exception was already logged by the ActiveJob integration, with the job's + # ID and class, so it isn't logged again here + sig { params(exception: Exception).void } def self.log_thread_error(exception) + return if LogStruct::LoggedErrors.logged?(exception) + ::GoodJob.logger.error( LogStruct::Log::GoodJob::Error.new( error_class: exception.class.name || exception.class.to_s, @@ -149,6 +147,17 @@ def self.log_thread_error(exception) ) end + # The errors GoodJob's notifier holds back until they repeat (GoodJob::Notifier::CONNECTION_ERRORS) + sig { params(exception: Exception).returns(T::Boolean) } + def self.notifier_connection_error?(exception) + return true unless defined?(::GoodJob::Notifier::CONNECTION_ERRORS) + + ::GoodJob::Notifier::CONNECTION_ERRORS.any? do |error_name| + error_class = error_name.safe_constantize + error_class.is_a?(Class) && exception.is_a?(error_class) + end + end + # Only when LogThreadErrors logs thread errors instead sig { void } def self.compact_error_lines diff --git a/lib/log_struct/log.rb b/lib/log_struct/log.rb index 4d918457..4ede48b8 100644 --- a/lib/log_struct/log.rb +++ b/lib/log_struct/log.rb @@ -23,7 +23,7 @@ module Log sig do params( source: Source, - ex: StandardError, + ex: Exception, additional_data: T::Hash[T.any(String, Symbol), T.untyped], timestamp: Time ).returns(LogStruct::Log::Error) diff --git a/lib/log_struct/log/error.rb b/lib/log_struct/log/error.rb index 163ca044..23603912 100644 --- a/lib/log_struct/log/error.rb +++ b/lib/log_struct/log/error.rb @@ -29,7 +29,7 @@ class Error < T::Struct const :level, Level, default: Level::Info # Event-specific fields - const :error_class, T.class_of(StandardError) + const :error_class, T.class_of(Exception) const :message, String const :backtrace, T.nilable(T::Array[String]), default: nil diff --git a/lib/log_struct/logged_errors.rb b/lib/log_struct/logged_errors.rb new file mode 100644 index 00000000..2b2d4523 --- /dev/null +++ b/lib/log_struct/logged_errors.rb @@ -0,0 +1,25 @@ +# typed: strict +# frozen_string_literal: true + +module LogStruct + # Exceptions LogStruct has already logged as a structured line, so an integration that sees the same + # exception again doesn't log it twice. GoodJob passes a failed job's exception to on_thread_error after + # the ActiveJob integration has logged it, for example. Exceptions are held weakly, so a mark doesn't keep + # one alive. + module LoggedErrors + extend T::Sig + + @logged = T.let(ObjectSpace::WeakMap.new, ObjectSpace::WeakMap) + @mutex = T.let(Mutex.new, Mutex) + + sig { params(error: Exception).void } + def self.mark(error) + @mutex.synchronize { @logged[error] = true } + end + + sig { params(error: Exception).returns(T::Boolean) } + def self.logged?(error) + @mutex.synchronize { @logged.key?(error) } + end + end +end diff --git a/schemas/log_sources/error.yml b/schemas/log_sources/error.yml index 6a818e7e..4193b66a 100644 --- a/schemas/log_sources/error.yml +++ b/schemas/log_sources/error.yml @@ -9,7 +9,7 @@ additional_data: true events: Error: fields: - ErrorClass: 'T.class_of(StandardError)' + ErrorClass: 'T.class_of(Exception)' Message: String Backtrace: type: 'T::Array[String]' diff --git a/schemas/meta/log-source-schema.json b/schemas/meta/log-source-schema.json index 96482305..f11157ca 100644 --- a/schemas/meta/log-source-schema.json +++ b/schemas/meta/log-source-schema.json @@ -61,6 +61,7 @@ "T::Array[T::Boolean]", "T::Array[Time]", "T.class_of(StandardError)", + "T.class_of(Exception)", "T.untyped" ] }, diff --git a/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi index a36e0305..379872b4 100644 --- a/sorbet/rbi/shims/good_job.rbi +++ b/sorbet/rbi/shims/good_job.rbi @@ -10,14 +10,14 @@ module GoodJob sig { params(logger: T.untyped).void } def logger=(logger); end - sig { returns(T.nilable(T.proc.params(exception: StandardError).void)) } + sig { returns(T.nilable(T.proc.params(exception: Exception).void)) } def on_thread_error; end - sig { params(handler: T.nilable(T.proc.params(exception: StandardError).void)).void } + sig { params(handler: T.nilable(T.proc.params(exception: Exception).void)).void } def on_thread_error=(handler); end # Every GoodJob component passes its thread errors here; it calls on_thread_error - sig { params(exception: StandardError).void } + sig { params(exception: Exception).void } def _on_thread_error(exception); end end @@ -27,6 +27,21 @@ module GoodJob def error(progname = nil, tags: [], &block); end end + # The job running on the current thread: `job` in GoodJob 4, `execution` in GoodJob 3 + module CurrentThread + class << self + sig { returns(T.untyped) } + def job; end + + sig { returns(T.untyped) } + def execution; end + end + end + + class Notifier + CONNECTION_ERRORS = T.let([], T::Array[String]) + end + class CLI class << self sig { returns(T.nilable(T::Boolean)) } diff --git a/test/log_struct/integrations/active_job/log_subscriber_test.rb b/test/log_struct/integrations/active_job/log_subscriber_test.rb index 25dab707..3ea35a85 100644 --- a/test/log_struct/integrations/active_job/log_subscriber_test.rb +++ b/test/log_struct/integrations/active_job/log_subscriber_test.rb @@ -61,6 +61,33 @@ def perform assert_equal "2905", parse_first_log(@log_output)["provider_job_id"] end + # GoodJob passes the same exception to on_thread_error, and shouldn't log it again + test "marks the exceptions it logs" do + error = RuntimeError.new("boom") + start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + event = build_event("perform.active_job", start_time, start_time + 0.1, {job: TestActiveJob.new, exception_object: error}) + + refute LogStruct::LoggedErrors.logged?(error) + @subscriber.perform(event) + + assert LogStruct::LoggedErrors.logged?(error) + end + + # perform_now lets any Exception through + test "logs a failed job's exception that isn't a StandardError" do + clear_log_buffer(@log_output) + error = NotImplementedError.new("not yet") + start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + event = build_event("perform.active_job", start_time, start_time + 0.1, {job: TestActiveJob.new, exception_object: error}) + + @subscriber.perform(event) + ::SemanticLogger.flush + + log = parse_first_log(@log_output) + + assert_equal %w[job error NotImplementedError], log.values_at("src", "evt", "error_class") + end + private def build_event(name, start_time, finish_time, payload) diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 80990db5..65053c57 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -74,13 +74,7 @@ class << self assert_instance_of GoodJob::Logger, fake.logger assert_same false, FakeGoodJobCLI.log_to_stdout, "GoodJob's executable shouldn't add a plain text STDOUT logger" - logged = [] - fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do - fake._on_thread_error(RuntimeError.new("boom")) - end - - assert_equal ["boom"], reported - assert_equal ["boom"], logged + assert_thread_error_logged_and_reported(fake, reported) end end @@ -114,17 +108,11 @@ class << self reported = [] fake.on_thread_error = ->(exception) { reported << exception.message } - logged = [] - fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do - fake._on_thread_error(RuntimeError.new("boom")) - end - - assert_equal ["boom"], reported - assert_equal ["boom"], logged + assert_thread_error_logged_and_reported(fake, reported) end end - test "GoodJob's own error lines have no backtrace, and thread errors are left to the thread error handler" do + test "GoodJob's own error lines are off for the errors it passes to the thread error handler" do with_fake_goodjob do |fake| # Like GoodJob::LogSubscriber: it logs errors as text with the whole backtrace in the message log_subscriber = Class.new do @@ -134,8 +122,6 @@ def initialize @lines = [] end - def finished_timer_task(event) = @lines << [:timer, event] - def finished_job_task(event) = @lines << [:job, event] def notifier_notify_error(event) = error { "Notifier errored: #{event.payload[:error].backtrace}" } @@ -150,26 +136,59 @@ def error(progname = nil, tags: [], &block) = @lines << [:error, block ? yield : 2.times { GoodJob.setup(LogStruct.config) } - error = IOError.new("connection lost") - error.set_backtrace(["lib/good_job/notifier.rb:1:in 'listen'"]) - event = Struct.new(:payload).new({error: error}) + connection_error = IOError.new("connection lost") + connection_error.set_backtrace(["lib/good_job/notifier.rb:1:in 'listen'"]) + other_error = RuntimeError.new("listen failed") + event = ->(error) { Struct.new(:payload).new({error: error}) } subscriber = log_subscriber.new - subscriber.finished_timer_task(event) - subscriber.finished_job_task(event) - subscriber.notifier_notify_error(event) - subscriber.systemd_watchdog_error(event) + subscriber.finished_job_task(event.call(other_error)) + # The notifier passes connection errors on only once they repeat, and every other error straight away + subscriber.notifier_notify_error(event.call(connection_error)) + subscriber.notifier_notify_error(event.call(other_error)) + # GoodJob passes every systemd watchdog error on + subscriber.systemd_watchdog_error(event.call(other_error)) subscriber.scheduler_create_pool(:event) - assert_equal [ - [:error, "Notifier errored: IOError: connection lost"], - [:error, "Error pinging systemd: IOError: connection lost"], - [:pool, :event] - ], - subscriber.lines + assert_equal [[:error, "Notifier errored: IOError: connection lost"], [:pool, :event]], subscriber.lines assert_equal 1, log_subscriber.ancestors.count(GoodJob::CompactErrorLines) end end + test "doesn't log a failed job's exception the ActiveJob integration logged, and still passes it on" do + with_fake_goodjob do |fake| + GoodJob.setup(LogStruct.config) + reported = [] + fake.on_thread_error = ->(exception) { reported << exception } + error = RuntimeError.new("job failed") + LogStruct::LoggedErrors.mark(error) + + logged = [] + fake.logger.stub(:error, ->(entry) { logged << entry }) do + fake._on_thread_error(error) + end + + assert_empty logged + assert_equal [error], reported + end + end + + # GoodJob passes any Exception its handled_exceptions setting lets through + test "logs a thread error that isn't a StandardError, and still passes it on" do + with_fake_goodjob do |fake| + GoodJob.setup(LogStruct.config) + reported = [] + fake.on_thread_error = ->(exception) { reported << exception.class } + + logged = [] + fake.logger.stub(:error, ->(entry) { logged << entry.error_class }) do + fake._on_thread_error(NotImplementedError.new("not yet")) + end + + assert_equal ["NotImplementedError"], logged + assert_equal [NotImplementedError], reported + end + end + test "integration is included in automatic setup" do # Check that GoodJob is required in integrations.rb integrations_file = File.read( @@ -190,6 +209,17 @@ def error(progname = nil, tags: [], &block) = @lines << [:error, block ? yield : private + # A thread error reaches the app's handler (which adds to reported) and GoodJob's logger once + def assert_thread_error_logged_and_reported(fake, reported) + logged = [] + fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do + fake._on_thread_error(RuntimeError.new("boom")) + end + + assert_equal ["boom"], reported + assert_equal ["boom"], logged + end + # Stands in for the GoodJob gem, which isn't installed for the tests def with_fake_goodjob fake = Module.new do @@ -204,6 +234,8 @@ def _on_thread_error(exception) end FakeGoodJobCLI.log_to_stdout = nil fake.const_set(:CLI, FakeGoodJobCLI) + # GoodJob's list names database connection errors; IOError stands in for them here + fake.const_set(:Notifier, Module.new.tap { |notifier| notifier.const_set(:CONNECTION_ERRORS, %w[IOError]) }) Object.const_set(:GoodJob, fake) yield fake ensure From 573ebb4140967c86f57c97f86f3e0a51d12acf77 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 21:05:37 +1300 Subject: [PATCH 09/10] Fill GoodJob log lines' job fields from GoodJob::CurrentThread The GoodJob logger read the running job from Thread.current[:good_job_execution], which GoodJob never sets, so its lines never had the job's ID, class or queue. It now reads GoodJob::CurrentThread.job (GoodJob 4) or .execution (GoodJob 3). The tests set that thread variable themselves, so they passed. --- .../integrations/good_job/logger.rb | 44 ++++---- .../integrations/good_job/logger_test.rb | 103 +++++++----------- 2 files changed, 64 insertions(+), 83 deletions(-) diff --git a/lib/log_struct/integrations/good_job/logger.rb b/lib/log_struct/integrations/good_job/logger.rb index 64bb7a4c..b13a43b7 100644 --- a/lib/log_struct/integrations/good_job/logger.rb +++ b/lib/log_struct/integrations/good_job/logger.rb @@ -14,12 +14,8 @@ module GoodJob # performance while creating structured log entries specifically for GoodJob # operations and events. # - # ## Benefits: - # - High-performance logging with SemanticLogger backend - # - Structured GoodJob-specific log entries - # - Automatic job context capture - # - Thread and process information - # - Performance metrics and timing data + # GoodJob's own messages are logged as Log::GoodJob::Log lines with the process and thread, + # and, during a job, the job's ID, class, queue, execution count, scheduled time and priority. # # ## Usage: # This logger is automatically configured when the GoodJob integration @@ -36,20 +32,7 @@ class Logger < LogStruct::SemanticLogger::Logger next super(message, payload, &block) end - # Extract basic job context from thread-local variables - job_context = {} - - if Thread.current[:good_job_execution] - execution = Thread.current[:good_job_execution] - if execution.respond_to?(:job_id) - job_context[:job_id] = execution.job_id - job_context[:job_class] = execution.job_class if execution.respond_to?(:job_class) - job_context[:queue_name] = execution.queue_name if execution.respond_to?(:queue_name) - job_context[:executions] = execution.executions if execution.respond_to?(:executions) - job_context[:scheduled_at] = execution.scheduled_at if execution.respond_to?(:scheduled_at) - job_context[:priority] = execution.priority if execution.respond_to?(:priority) - end - end + job_context = Logger.current_job_context log_struct = Log::GoodJob::Log.new( message: message || (block ? block.call : ""), @@ -66,6 +49,27 @@ class Logger < LogStruct::SemanticLogger::Logger super(log_struct, payload, &nil) end end + + # The job GoodJob is running on this thread: CurrentThread.job (a GoodJob::Job) in GoodJob 4, + # CurrentThread.execution in GoodJob 3 + sig { returns(T::Hash[Symbol, T.untyped]) } + def self.current_job_context + return {} unless defined?(::GoodJob::CurrentThread) + + current = ::GoodJob::CurrentThread + job = (current.job if current.respond_to?(:job)) || (current.execution if current.respond_to?(:execution)) + return {} unless job + + job_class = job.try(:job_class) || job.try(:serialized_params)&.dig("job_class") + { + job_id: job.try(:active_job_id)&.to_s, + job_class: job_class&.to_s, + queue_name: job.try(:queue_name)&.to_sym, + executions: job.try(:executions_count) || job.try(:executions), + scheduled_at: job.try(:scheduled_at), + priority: job.try(:priority) + } + end end end end diff --git a/test/log_struct/integrations/good_job/logger_test.rb b/test/log_struct/integrations/good_job/logger_test.rb index 6c64ca0b..978695a3 100644 --- a/test/log_struct/integrations/good_job/logger_test.rb +++ b/test/log_struct/integrations/good_job/logger_test.rb @@ -19,6 +19,18 @@ class LoggerTest < ActiveSupport::TestCase teardown_isolated_logger end + # Stands in for GoodJob::CurrentThread (GoodJob isn't installed for the tests) + def with_good_job_current_thread(**accessors) + current_thread = Module.new + accessors.each { |name, value| current_thread.define_singleton_method(name) { value } } + good_job = Module.new + good_job.const_set(:CurrentThread, current_thread) + Object.const_set(:GoodJob, good_job) + yield + ensure + Object.send(:remove_const, :GoodJob) if Object.const_defined?(:GoodJob, false) + end + test "extends LogStruct SemanticLogger Logger" do assert_kind_of LogStruct::SemanticLogger::Logger, @logger end @@ -83,86 +95,51 @@ class LoggerTest < ActiveSupport::TestCase assert_equal %w[custom hash], lines[1].values_at("evt", "note") end - test "extracts job context from thread local variables" do + # GoodJob 4: CurrentThread.job is the GoodJob::Job being run + test "logs the running job's fields from GoodJob::CurrentThread.job" do clear_log_buffer(@io) - - # Simulate GoodJob setting thread-local execution context - mock_execution = OpenStruct.new( - job_id: "job_123", - job_class: "TestJob", - queue_name: :default, - executions: 1, - scheduled_at: Time.now, - priority: 5 + job = Struct.new(:active_job_id, :job_class, :queue_name, :executions_count, :scheduled_at, :priority, keyword_init: true).new( + active_job_id: "job_123", job_class: "TestJob", queue_name: "default", executions_count: 1, scheduled_at: Time.now, priority: 5 ) - Thread.current[:good_job_execution] = mock_execution - - @logger.info("Processing job") + with_good_job_current_thread(job: job) { @logger.info("Processing job") } ::SemanticLogger.flush + log = JSON.parse(@io.string.lines.first.strip) - output = @io.string - log = JSON.parse(output.lines.first.strip) - - assert_equal "job_123", log["job_id"] - assert_equal "TestJob", log["job_class"] - assert_equal "default", log["queue_name"] - assert_equal 1, log["executions"] + assert_equal ["job_123", "TestJob", "default", 1, 5], log.values_at("job_id", "job_class", "queue_name", "executions", "priority") assert log["scheduled_at"] - assert_equal 5, log["priority"] - - # Clean up - Thread.current[:good_job_execution] = nil end - test "handles missing job context gracefully" do + # GoodJob 3: CurrentThread.execution, with the job class in its serialized params + test "logs the running job's fields from GoodJob::CurrentThread.execution" do clear_log_buffer(@io) + execution = Struct.new(:active_job_id, :serialized_params, :queue_name, keyword_init: true).new( + active_job_id: "job_456", serialized_params: {"job_class" => "OlderJob"}, queue_name: "low" + ) - # Ensure no job context is set - Thread.current[:good_job_execution] = nil - - @logger.info("Regular log message") + with_good_job_current_thread(execution: execution) { @logger.info("Processing job") } ::SemanticLogger.flush + log = JSON.parse(@io.string.lines.first.strip) - output = @io.string - log = JSON.parse(output.lines.first.strip) - - # Should still log successfully - assert_equal "job", log["src"] - assert_equal "Regular log message", log["msg"] - - # Job-specific fields should be absent - refute log.key?("job_id") - refute log.key?("job_class") - refute log.key?("queue_name") + assert_equal %w[job_456 OlderJob low], log.values_at("job_id", "job_class", "queue_name") + refute log.key?("priority") end - test "handles execution context with missing methods gracefully" do + test "logs no job fields outside a job" do clear_log_buffer(@io) - # Create a mock execution that doesn't respond to some methods - mock_execution = Object.new - mock_execution.define_singleton_method(:job_id) do - "partial_job_123" - end - # job_class method intentionally missing - - Thread.current[:good_job_execution] = mock_execution - - @logger.info("Partial context job") + with_good_job_current_thread(job: nil) { @logger.info("Regular log message") } + @logger.info("Without GoodJob") ::SemanticLogger.flush - - output = @io.string - log = JSON.parse(output.lines.first.strip) - - # Should include available fields - assert_equal "partial_job_123", log["job_id"] - - # Should not include unavailable fields - refute log.key?("job_class") - - # Clean up - Thread.current[:good_job_execution] = nil + logs = @io.string.lines.map { |line| JSON.parse(line) } + + assert_equal ["Regular log message", "Without GoodJob"], logs.map { |log| log["msg"] } + logs.each do |log| + assert_equal "job", log["src"] + refute log.key?("job_id") + refute log.key?("job_class") + refute log.key?("queue_name") + end end test "supports all log levels" do From 6b28d56295190c1576d9d88a3fa840519cd1da42 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 21:05:42 +1300 Subject: [PATCH 10/10] Remove the GoodJob log types nothing logs GoodJob::Enqueue, Start, Finish and Schedule were only built by the removed GoodJob log subscriber. GoodJob's jobs are logged by the ActiveJob integration, whose lines have the same src and evt. The Terraform provider's catalog now lists only error and log for GoodJob, and the docs no longer describe GoodJob lifecycle events. The docs say the integration needs GoodJob 3.0 or later (GoodJob._on_thread_error). --- INTEGRATIONS.md | 2 +- docs/lib/integration-helpers.ts | 2 +- docs/lib/log-generation/log-generator.ts | 11 +-- docs/lib/log-structure-descriptions.ts | 9 ++- lib/log_struct/log/good_job.rb | 4 -- lib/log_struct/log/good_job/enqueue.rb | 63 ----------------- lib/log_struct/log/good_job/finish.rb | 67 ------------------ lib/log_struct/log/good_job/schedule.rb | 65 ------------------ lib/log_struct/log/good_job/start.rb | 65 ------------------ schemas/log_sources/good_job.yml | 42 ------------ scripts/export_provider_catalog.rb | 3 +- test/log_struct/log/good_job_test.rb | 87 ++++++------------------ 12 files changed, 30 insertions(+), 390 deletions(-) delete mode 100644 lib/log_struct/log/good_job/enqueue.rb delete mode 100644 lib/log_struct/log/good_job/finish.rb delete mode 100644 lib/log_struct/log/good_job/schedule.rb delete mode 100644 lib/log_struct/log/good_job/start.rb diff --git a/INTEGRATIONS.md b/INTEGRATIONS.md index 183623ee..360a03c7 100644 --- a/INTEGRATIONS.md +++ b/INTEGRATIONS.md @@ -113,7 +113,7 @@ - GoodJob: - Log type: `lib/log_struct/log/good_job.rb` - - Integration: `lib/log_struct/integrations/good_job.rb` (+ `logger.rb`, `log_subscriber.rb`) + - Integration: `lib/log_struct/integrations/good_job.rb` (+ `logger.rb`) - Toggle: `enable_goodjob` - SQL (ActiveRecord): - Log type: `lib/log_struct/log/sql.rb` diff --git a/docs/lib/integration-helpers.ts b/docs/lib/integration-helpers.ts index 7706c80e..3ac7ce7b 100644 --- a/docs/lib/integration-helpers.ts +++ b/docs/lib/integration-helpers.ts @@ -88,7 +88,7 @@ export function getLogTypeInfo(logType: LogType): { return { title: 'GoodJob', description: - "The GoodJob integration logs GoodJob's own messages and its thread errors as structured lines. GoodJob's jobs are logged by the ActiveJob integration.", + "The GoodJob integration logs GoodJob's own messages and its thread errors as structured lines (GoodJob 3.0 or later). GoodJob's jobs are logged by the ActiveJob integration.", }; case LogType.SQL: diff --git a/docs/lib/log-generation/log-generator.ts b/docs/lib/log-generation/log-generator.ts index 1e0290d2..b65f9981 100644 --- a/docs/lib/log-generation/log-generator.ts +++ b/docs/lib/log-generation/log-generator.ts @@ -171,16 +171,7 @@ export class LogGenerator extends RandomDataGenerator { } case LogType.GOODJOB: { - switch ( - evt ?? - this.sample([Event.Enqueue, Event.Start, Event.Finish, Event.Error, Event.Log]) - ) { - case Event.Enqueue: - return GoodJob.GoodJobEnqueue.random(this).serialize(); - case Event.Start: - return GoodJob.GoodJobStart.random(this).serialize(); - case Event.Finish: - return GoodJob.GoodJobFinish.random(this).serialize(); + switch (evt ?? this.sample([Event.Error, Event.Log])) { case Event.Error: return GoodJob.GoodJobError.random(this).serialize(); default: diff --git a/docs/lib/log-structure-descriptions.ts b/docs/lib/log-structure-descriptions.ts index 757ec764..373ad195 100644 --- a/docs/lib/log-structure-descriptions.ts +++ b/docs/lib/log-structure-descriptions.ts @@ -10,11 +10,10 @@ export const LOG_STRUCTURE_DESCRIPTIONS: Record = { Delivered: 'ActionMailer callback emitted after a message is delivered', Delivery: 'ActionMailer event capturing when a mailer sends a message', ActiveJob: 'For background job execution', - Enqueue: 'Background job enqueued event (ActiveJob or GoodJob scheduling a job for execution)', - Finish: 'Background job completion event indicating success (ActiveJob/GoodJob)', - Schedule: - 'Deferred background job scheduling event (ActiveJob or GoodJob scheduling with a run_at time)', - Start: 'Lifecycle start event for jobs or services (ActiveJob, GoodJob, or Puma boot)', + Enqueue: 'Background job enqueued event (ActiveJob scheduling a job for execution)', + Finish: 'Background job completion event indicating success (ActiveJob)', + Schedule: 'Deferred background job scheduling event (ActiveJob scheduling with a run_at time)', + Start: 'Lifecycle start event for jobs or services (ActiveJob or Puma boot)', ActiveStorage: 'For file storage operations', Delete: 'Deletion of a persisted attachment (ActiveStorage, CarrierWave, or Shrine)', Download: 'File download event (ActiveStorage, CarrierWave, or Shrine)', diff --git a/lib/log_struct/log/good_job.rb b/lib/log_struct/log/good_job.rb index edf0052b..9762e6ee 100644 --- a/lib/log_struct/log/good_job.rb +++ b/lib/log_struct/log/good_job.rb @@ -7,11 +7,7 @@ # Template: tools/codegen/templates/sorbet/source_parent.rb.erb require_relative "good_job/log" -require_relative "good_job/enqueue" -require_relative "good_job/start" -require_relative "good_job/finish" require_relative "good_job/error" -require_relative "good_job/schedule" module LogStruct module Log diff --git a/lib/log_struct/log/good_job/enqueue.rb b/lib/log_struct/log/good_job/enqueue.rb deleted file mode 100644 index 8372da74..00000000 --- a/lib/log_struct/log/good_job/enqueue.rb +++ /dev/null @@ -1,63 +0,0 @@ -# typed: strict -# frozen_string_literal: true - -# AUTO-GENERATED: DO NOT EDIT -# Generated by scripts/generate_structs.rb -# Schemas dir: schemas/log_sources/ -# Template: tools/codegen/templates/sorbet/event.rb.erb - -require "log_struct/shared/interfaces/common_fields" -require "log_struct/shared/interfaces/additional_data_field" -require "log_struct/shared/interfaces/request_fields" -require "log_struct/shared/serialize_common" -require "log_struct/shared/merge_additional_data_fields" -require "log_struct/shared/add_request_fields" -require_relative "../../enums/source" -require_relative "../../enums/event" -require_relative "../../enums/level" -require_relative "../../enums/log_field" - -module LogStruct - module Log - class GoodJob - class Enqueue < T::Struct - extend T::Sig - - # Shared/common fields - const :source, Source::Job, default: Source::Job - const :event, Event, default: Event::Enqueue - const :timestamp, Time, factory: -> { Time.now } - const :level, Level, default: Level::Info - - const :job_id, T.nilable(String), default: nil - const :job_class, T.nilable(String), default: nil - const :queue_name, T.nilable(Symbol), default: nil - const :arguments, T.nilable(T::Array[T.untyped]), default: nil - const :executions, T.nilable(Integer), default: nil - - # Event-specific fields - const :duration_ms, Float - const :scheduled_at, T.nilable(Time), default: nil - const :enqueue_caller, T.nilable(String), default: nil - - # Serialize shared fields - include LogStruct::Log::Interfaces::CommonFields - include LogStruct::Log::Shared::SerializeCommon - - sig { returns(T::Hash[LogStruct::LogField, T.untyped]) } - def to_h - h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) - h[LogField::JobId] = job_id unless job_id.nil? - h[LogField::JobClass] = job_class unless job_class.nil? - h[LogField::QueueName] = queue_name unless queue_name.nil? - h[LogField::Arguments] = arguments unless arguments.nil? - h[LogField::Executions] = executions unless executions.nil? - h[LogField::DurationMs] = duration_ms - h[LogField::ScheduledAt] = scheduled_at unless scheduled_at.nil? - h[LogField::EnqueueCaller] = enqueue_caller unless enqueue_caller.nil? - h - end - end - end - end -end diff --git a/lib/log_struct/log/good_job/finish.rb b/lib/log_struct/log/good_job/finish.rb deleted file mode 100644 index 0b6cf34d..00000000 --- a/lib/log_struct/log/good_job/finish.rb +++ /dev/null @@ -1,67 +0,0 @@ -# typed: strict -# frozen_string_literal: true - -# AUTO-GENERATED: DO NOT EDIT -# Generated by scripts/generate_structs.rb -# Schemas dir: schemas/log_sources/ -# Template: tools/codegen/templates/sorbet/event.rb.erb - -require "log_struct/shared/interfaces/common_fields" -require "log_struct/shared/interfaces/additional_data_field" -require "log_struct/shared/interfaces/request_fields" -require "log_struct/shared/serialize_common" -require "log_struct/shared/merge_additional_data_fields" -require "log_struct/shared/add_request_fields" -require_relative "../../enums/source" -require_relative "../../enums/event" -require_relative "../../enums/level" -require_relative "../../enums/log_field" - -module LogStruct - module Log - class GoodJob - class Finish < T::Struct - extend T::Sig - - # Shared/common fields - const :source, Source::Job, default: Source::Job - const :event, Event, default: Event::Finish - const :timestamp, Time, factory: -> { Time.now } - const :level, Level, default: Level::Info - - const :job_id, T.nilable(String), default: nil - const :job_class, T.nilable(String), default: nil - const :queue_name, T.nilable(Symbol), default: nil - const :arguments, T.nilable(T::Array[T.untyped]), default: nil - const :executions, T.nilable(Integer), default: nil - - # Event-specific fields - const :duration_ms, Float - const :finished_at, Time - const :process_id, Integer - const :thread_id, String - const :result, T.nilable(String), default: nil - - # Serialize shared fields - include LogStruct::Log::Interfaces::CommonFields - include LogStruct::Log::Shared::SerializeCommon - - sig { returns(T::Hash[LogStruct::LogField, T.untyped]) } - def to_h - h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) - h[LogField::JobId] = job_id unless job_id.nil? - h[LogField::JobClass] = job_class unless job_class.nil? - h[LogField::QueueName] = queue_name unless queue_name.nil? - h[LogField::Arguments] = arguments unless arguments.nil? - h[LogField::Executions] = executions unless executions.nil? - h[LogField::DurationMs] = duration_ms - h[LogField::FinishedAt] = finished_at - h[LogField::ProcessId] = process_id - h[LogField::ThreadId] = thread_id - h[LogField::Result] = result unless result.nil? - h - end - end - end - end -end diff --git a/lib/log_struct/log/good_job/schedule.rb b/lib/log_struct/log/good_job/schedule.rb deleted file mode 100644 index 8bbc8188..00000000 --- a/lib/log_struct/log/good_job/schedule.rb +++ /dev/null @@ -1,65 +0,0 @@ -# typed: strict -# frozen_string_literal: true - -# AUTO-GENERATED: DO NOT EDIT -# Generated by scripts/generate_structs.rb -# Schemas dir: schemas/log_sources/ -# Template: tools/codegen/templates/sorbet/event.rb.erb - -require "log_struct/shared/interfaces/common_fields" -require "log_struct/shared/interfaces/additional_data_field" -require "log_struct/shared/interfaces/request_fields" -require "log_struct/shared/serialize_common" -require "log_struct/shared/merge_additional_data_fields" -require "log_struct/shared/add_request_fields" -require_relative "../../enums/source" -require_relative "../../enums/event" -require_relative "../../enums/level" -require_relative "../../enums/log_field" - -module LogStruct - module Log - class GoodJob - class Schedule < T::Struct - extend T::Sig - - # Shared/common fields - const :source, Source::Job, default: Source::Job - const :event, Event, default: Event::Schedule - const :timestamp, Time, factory: -> { Time.now } - const :level, Level, default: Level::Info - - const :job_id, T.nilable(String), default: nil - const :job_class, T.nilable(String), default: nil - const :queue_name, T.nilable(Symbol), default: nil - const :arguments, T.nilable(T::Array[T.untyped]), default: nil - const :executions, T.nilable(Integer), default: nil - - # Event-specific fields - const :duration_ms, Float - const :scheduled_at, Time - const :priority, T.nilable(Integer), default: nil - const :cron_key, T.nilable(String), default: nil - - # Serialize shared fields - include LogStruct::Log::Interfaces::CommonFields - include LogStruct::Log::Shared::SerializeCommon - - sig { returns(T::Hash[LogStruct::LogField, T.untyped]) } - def to_h - h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) - h[LogField::JobId] = job_id unless job_id.nil? - h[LogField::JobClass] = job_class unless job_class.nil? - h[LogField::QueueName] = queue_name unless queue_name.nil? - h[LogField::Arguments] = arguments unless arguments.nil? - h[LogField::Executions] = executions unless executions.nil? - h[LogField::DurationMs] = duration_ms - h[LogField::ScheduledAt] = scheduled_at - h[LogField::Priority] = priority unless priority.nil? - h[LogField::CronKey] = cron_key unless cron_key.nil? - h - end - end - end - end -end diff --git a/lib/log_struct/log/good_job/start.rb b/lib/log_struct/log/good_job/start.rb deleted file mode 100644 index 938423fb..00000000 --- a/lib/log_struct/log/good_job/start.rb +++ /dev/null @@ -1,65 +0,0 @@ -# typed: strict -# frozen_string_literal: true - -# AUTO-GENERATED: DO NOT EDIT -# Generated by scripts/generate_structs.rb -# Schemas dir: schemas/log_sources/ -# Template: tools/codegen/templates/sorbet/event.rb.erb - -require "log_struct/shared/interfaces/common_fields" -require "log_struct/shared/interfaces/additional_data_field" -require "log_struct/shared/interfaces/request_fields" -require "log_struct/shared/serialize_common" -require "log_struct/shared/merge_additional_data_fields" -require "log_struct/shared/add_request_fields" -require_relative "../../enums/source" -require_relative "../../enums/event" -require_relative "../../enums/level" -require_relative "../../enums/log_field" - -module LogStruct - module Log - class GoodJob - class Start < T::Struct - extend T::Sig - - # Shared/common fields - const :source, Source::Job, default: Source::Job - const :event, Event, default: Event::Start - const :timestamp, Time, factory: -> { Time.now } - const :level, Level, default: Level::Info - - const :job_id, T.nilable(String), default: nil - const :job_class, T.nilable(String), default: nil - const :queue_name, T.nilable(Symbol), default: nil - const :arguments, T.nilable(T::Array[T.untyped]), default: nil - const :executions, T.nilable(Integer), default: nil - - # Event-specific fields - const :process_id, Integer - const :thread_id, String - const :wait_ms, T.nilable(Float), default: nil - const :scheduled_at, T.nilable(Time), default: nil - - # Serialize shared fields - include LogStruct::Log::Interfaces::CommonFields - include LogStruct::Log::Shared::SerializeCommon - - sig { returns(T::Hash[LogStruct::LogField, T.untyped]) } - def to_h - h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) - h[LogField::JobId] = job_id unless job_id.nil? - h[LogField::JobClass] = job_class unless job_class.nil? - h[LogField::QueueName] = queue_name unless queue_name.nil? - h[LogField::Arguments] = arguments unless arguments.nil? - h[LogField::Executions] = executions unless executions.nil? - h[LogField::ProcessId] = process_id - h[LogField::ThreadId] = thread_id - h[LogField::WaitMs] = wait_ms unless wait_ms.nil? - h[LogField::ScheduledAt] = scheduled_at unless scheduled_at.nil? - h - end - end - end - end -end diff --git a/schemas/log_sources/good_job.yml b/schemas/log_sources/good_job.yml index 16b3a419..347bc812 100644 --- a/schemas/log_sources/good_job.yml +++ b/schemas/log_sources/good_job.yml @@ -25,37 +25,6 @@ events: Priority: type: Integer required: false - Enqueue: - fields: - DurationMs: Float - ScheduledAt: - type: Time - required: false - EnqueueCaller: - type: String - required: false - - Start: - fields: - ProcessId: Integer - ThreadId: String - WaitMs: - type: Float - required: false - ScheduledAt: - type: Time - required: false - - Finish: - fields: - DurationMs: Float - FinishedAt: Time - ProcessId: Integer - ThreadId: String - Result: - type: String - required: false - Error: fields: ErrorClass: String @@ -71,14 +40,3 @@ events: Backtrace: type: 'T::Array[String]' required: false - - Schedule: - fields: - DurationMs: Float - ScheduledAt: Time - Priority: - type: Integer - required: false - CronKey: - type: String - required: false diff --git a/scripts/export_provider_catalog.rb b/scripts/export_provider_catalog.rb index a4dac4fe..0936fbff 100755 --- a/scripts/export_provider_catalog.rb +++ b/scripts/export_provider_catalog.rb @@ -155,10 +155,9 @@ def check(condition, message) check(structs.key?("GoodJob"), "Struct catalog missing GoodJob") good_job = structs["GoodJob"] -check(good_job["allowed_events"].include?("enqueue"), "GoodJob missing enqueue event") +check(good_job["allowed_events"].sort == %w[error log], "GoodJob events should be error and log only") check(good_job["fixed_source"] == "job", "GoodJob fixed source incorrect") go_contents = File.read(gen_path) check(go_contents.include?("\"GoodJob\": {Name: \"GoodJob\""), "catalog_gen.go missing GoodJob entry") -check(go_contents.include?("AllowedEvents: []string{\"enqueue\""), "catalog_gen.go missing enqueue event") diff --git a/test/log_struct/log/good_job_test.rb b/test/log_struct/log/good_job_test.rb index 70294eda..5a961d37 100644 --- a/test/log_struct/log/good_job_test.rb +++ b/test/log_struct/log/good_job_test.rb @@ -7,20 +7,22 @@ module LogStruct module Log class GoodJobTest < ActiveSupport::TestCase - test "initializes Start with required fields" do - log_entry = GoodJob::Start.new( + test "initializes Log with required fields" do + log_entry = GoodJob::Log.new( + message: "starting", process_id: Process.pid, thread_id: Thread.current.object_id.to_s(36) ) assert_equal Source::Job, log_entry.source - assert_equal Event::Start, log_entry.event + assert_equal Event::Log, log_entry.event assert_equal Level::Info, log_entry.level assert_instance_of Time, log_entry.timestamp end test "accepts job identification fields" do - log_entry = GoodJob::Start.new( + log_entry = GoodJob::Log.new( + message: "m", process_id: Process.pid, thread_id: Thread.current.object_id.to_s(36), job_id: "job_123", @@ -35,7 +37,8 @@ class GoodJobTest < ActiveSupport::TestCase test "accepts execution context fields" do scheduled_time = Time.now + 1.hour - log_entry = GoodJob::Start.new( + log_entry = GoodJob::Log.new( + message: "m", process_id: Process.pid, thread_id: Thread.current.object_id.to_s(36), arguments: ["user_123", {notify: true}], @@ -65,38 +68,9 @@ class GoodJobTest < ActiveSupport::TestCase assert_equal backtrace, log_entry.backtrace end - test "accepts GoodJob-specific metadata" do - log_entry = GoodJob::Schedule.new( - scheduled_at: Time.now + 60, - duration_ms: 10.0, - priority: 10, - cron_key: "daily_cleanup" - ) - - assert_equal 10, log_entry.priority - assert_equal "daily_cleanup", log_entry.cron_key - end - - test "accepts performance metrics" do - finished_time = Time.now - log_entry = GoodJob::Finish.new( - process_id: Process.pid, - thread_id: Thread.current.object_id.to_s(36), - duration_ms: 2500.0, - finished_at: finished_time - ) - - assert_in_delta(2500.0, log_entry.duration_ms) - assert_equal finished_time, log_entry.finished_at - end - - test "serializes to hash with all fields" do - Time.now - 1.hour - finished_time = Time.now - - log_entry = GoodJob::Finish.new( - level: Level::Info, + test "serializes an error with all fields" do + log_entry = GoodJob::Error.new( + level: Level::Error, job_id: "job_123", job_class: "UserNotificationJob", queue_name: :default, @@ -104,42 +78,28 @@ class GoodJobTest < ActiveSupport::TestCase executions: 1, process_id: 1234, thread_id: "thread_abc", + error_class: "RuntimeError", + error_message: "boom", duration_ms: 2500.0, - finished_at: finished_time, - result: "success" + exception_executions: 3 ) hash = log_entry.serialize - # Check common fields assert_equal "job", hash[:src] - assert_equal "finish", hash[:evt] - assert_equal "info", hash[:lvl] + assert_equal "error", hash[:evt] + assert_equal "error", hash[:lvl] assert hash[:ts] - - # Check job identification assert_equal "job_123", hash[:job_id] assert_equal "UserNotificationJob", hash[:job_class] assert_equal :default, hash[:queue_name] - # Removed batch_id and job_label fields from schema - - # Check execution context assert_equal ["user_123"], hash[:arguments] assert_equal 1, hash[:executions] - refute hash.key?(:exception_executions) - refute hash.key?(:scheduled_at) - - # Check GoodJob metadata + assert_equal 3, hash[:exception_executions] assert_equal 1234, hash[:pid] assert_equal "thread_abc", hash[:tid] - # Priority/cron_key only on Schedule events - - # Check performance metrics assert_in_delta(2500.0, hash[:duration_ms]) - assert_equal finished_time.iso8601, hash[:finished_at] - - # Check result field - assert_equal "success", hash[:result] + assert_equal "RuntimeError", hash[:error_class] end test "serializes with only present fields" do @@ -161,16 +121,13 @@ class GoodJobTest < ActiveSupport::TestCase refute hash.key?(:job_class) refute hash.key?(:queue_name) refute hash.key?(:error_message) - refute hash.key?(:finished_at) + refute hash.key?(:scheduled_at) end test "handles all valid event types" do assert_equal Event::Log, GoodJob::Log.new(message: "m", process_id: 1, thread_id: "t").event - assert_equal Event::Enqueue, GoodJob::Enqueue.new(duration_ms: 1.0).event - assert_equal Event::Start, GoodJob::Start.new(process_id: 1, thread_id: "t").event - assert_equal Event::Finish, GoodJob::Finish.new(process_id: 1, thread_id: "t", duration_ms: 1.0, finished_at: Time.now).event assert_equal Event::Error, GoodJob::Error.new(process_id: 1, thread_id: "t", error_class: "E", error_message: "m").event - assert_equal Event::Schedule, GoodJob::Schedule.new(duration_ms: 1.0, scheduled_at: Time.now).event + refute defined?(GoodJob::Enqueue), "GoodJob jobs' enqueue, start and finish lines come from the ActiveJob integration" end test "scheduled_at and priority fields work correctly" do @@ -191,7 +148,7 @@ class GoodJobTest < ActiveSupport::TestCase test "timestamp is automatically set" do before_time = Time.now - log_entry = GoodJob::Enqueue.new(duration_ms: 1.0) + log_entry = GoodJob::Log.new(message: "m", process_id: 1, thread_id: "t") after_time = Time.now assert_operator log_entry.timestamp, :>=, before_time @@ -199,7 +156,7 @@ class GoodJobTest < ActiveSupport::TestCase end test "includes proper interfaces" do - klass = GoodJob::Start + klass = GoodJob::Log assert_includes klass.included_modules, Interfaces::CommonFields assert_includes klass.included_modules, Shared::SerializeCommon