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 cf0955a6..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 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 3.0 or later). 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-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 0aa4a7ef..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)', @@ -31,7 +30,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.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/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/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 93e595a9..57d88de6 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,13 +46,55 @@ 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 end - @thread_error_handler = T.let(nil, T.nilable(T.proc.params(exception: StandardError).void)) + # GoodJob::LogSubscriber logs errors as text with the whole backtrace in the message (over 10KB). + # 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_job_task(_event) + end + + sig { params(event: T.untyped).void } + 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) + end + end + + # 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. GoodJob passes any Exception its handled_exceptions setting lets + # through, not only StandardErrors. + module LogThreadErrors + extend T::Sig + + sig { params(exception: Exception).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 } @@ -78,40 +107,70 @@ 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") - 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. - 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, - process_id: ::Process.pid, - thread_id: Thread.current.object_id.to_s(36) - ) - goodjob_module.logger.error(log_entry) + # 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 - goodjob_module.on_thread_error = @thread_error_handler end + + configure_thread_error_handler end - # Subscribe to GoodJob's ActiveSupport notifications sig { void } - def self.subscribe_to_notifications + def self.configure_thread_error_handler return unless defined?(::GoodJob) - # Subscribe to our custom log subscriber for GoodJob events - LogStruct::Integrations::GoodJob::LogSubscriber.attach_to :good_job + # Not GoodJob, which here is this module + goodjob_singleton = ::GoodJob.singleton_class + return unless goodjob_singleton.method_defined?(:_on_thread_error) + + goodjob_singleton.prepend(LogThreadErrors) unless goodjob_singleton.ancestors.include?(LogThreadErrors) + end + + # 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, + 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 + + # 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 + return unless defined?(::GoodJob::LogSubscriber) + return unless ::GoodJob.singleton_class.ancestors.include?(LogThreadErrors) + + log_subscriber = ::GoodJob::LogSubscriber + log_subscriber.prepend(CompactErrorLines) unless log_subscriber.ancestors.include?(CompactErrorLines) end private_class_method :configure_logger - private_class_method :subscribe_to_notifications + private_class_method :compact_error_lines + private_class_method :configure_thread_error_handler 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/lib/log_struct/integrations/good_job/logger.rb b/lib/log_struct/integrations/good_job/logger.rb index 620ff49a..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 @@ -31,21 +27,13 @@ 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| - # 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 + # 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 + job_context = Logger.current_job_context + log_struct = Log::GoodJob::Log.new( message: message || (block ? block.call : ""), process_id: ::Process.pid, @@ -61,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/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/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/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/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/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/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/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi index 67195a4f..379872b4 100644 --- a/sorbet/rbi/shims/good_job.rbi +++ b/sorbet/rbi/shims/good_job.rbi @@ -10,10 +10,45 @@ 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: Exception).void } + def _on_thread_error(exception); end + end + + # Logs GoodJob's notifications as text + 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 + + # 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)) } + 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/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/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/logger_test.rb b/test/log_struct/integrations/good_job/logger_test.rb index add5b609..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 @@ -61,86 +73,73 @@ class LoggerTest < ActiveSupport::TestCase assert_equal "Job failed", log["msg"] end - test "extracts job context from thread local variables" do + test "logs a LogStruct log entry as it is" 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 + @logger.error( + Log::GoodJob::Error.new( + error_class: "RuntimeError", + error_message: "boom", + level: Level::Error, + process_id: Process.pid, + thread_id: "abc" + ) ) - - Thread.current[:good_job_execution] = mock_execution - - @logger.info("Processing job") + @logger.info({evt: "custom", note: "hash"}) ::SemanticLogger.flush - 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 log["scheduled_at"] - assert_equal 5, log["priority"] + lines = @io.string.lines.map { |line| JSON.parse(line) } - # Clean up - Thread.current[:good_job_execution] = nil + 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 "handles missing job context gracefully" 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) + 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 + ) - # Ensure no job context is set - Thread.current[:good_job_execution] = nil - - @logger.info("Regular log message") + 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) - - # 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 ["job_123", "TestJob", "default", 1, 5], log.values_at("job_id", "job_class", "queue_name", "executions", "priority") + assert log["scheduled_at"] end - test "handles execution context with missing methods 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" + ) - # 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(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 include available fields - assert_equal "partial_job_123", log["job_id"] + assert_equal %w[job_456 OlderJob low], log.values_at("job_id", "job_class", "queue_name") + refute log.key?("priority") + end - # Should not include unavailable fields - refute log.key?("job_class") + test "logs no job fields outside a job" do + clear_log_buffer(@io) - # Clean up - Thread.current[:good_job_execution] = nil + with_good_job_current_thread(job: nil) { @logger.info("Regular log message") } + @logger.info("Without GoodJob") + ::SemanticLogger.flush + 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 diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 26495169..65053c57 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 @@ -57,7 +64,7 @@ class GoodJobTest < ActiveSupport::TestCase 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 } @@ -66,18 +73,120 @@ 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" + assert_thread_error_logged_and_reported(fake, reported) + 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(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 + + # 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| + 2.times { GoodJob.setup(LogStruct.config) } + + reported = [] + fake.on_thread_error = ->(exception) { reported << exception.message } + + assert_thread_error_logged_and_reported(fake, reported) + end + end + + 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 + attr_reader :lines + + def initialize + @lines = [] + end + + 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.setup(LogStruct.config) } + + 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_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"], [: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.error_message }) do - fake.on_thread_error.call(RuntimeError.new("boom")) + fake.logger.stub(:error, ->(entry) { logged << entry }) do + fake._on_thread_error(error) end - assert_equal ["boom"], reported - assert_equal ["boom"], logged + assert_empty logged + assert_equal [error], reported end end - test "subscribe_to_notifications method exists and is private" do - assert_includes GoodJob.private_methods, :subscribe_to_notifications + # 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 @@ -100,13 +209,33 @@ class GoodJobTest < ActiveSupport::TestCase 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 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 + 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 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