Skip to content

Commit 025131f

Browse files
authored
Merge pull request #20 from DocSpring/nathan/good-job-workers
Log GoodJob workers as JSON, and each GoodJob error once
2 parents f4d9ffd + 6b28d56 commit 025131f

29 files changed

Lines changed: 502 additions & 1117 deletions

‎INTEGRATIONS.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -113,7 +113,7 @@
113113

114114
- GoodJob:
115115
- Log type: `lib/log_struct/log/good_job.rb`
116-
- Integration: `lib/log_struct/integrations/good_job.rb` (+ `logger.rb`, `log_subscriber.rb`)
116+
- Integration: `lib/log_struct/integrations/good_job.rb` (+ `logger.rb`)
117117
- Toggle: `enable_goodjob`
118118
- SQL (ActiveRecord):
119119
- Log type: `lib/log_struct/log/sql.rb`

‎docs/lib/integration-helpers.ts‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -88,7 +88,7 @@ export function getLogTypeInfo(logType: LogType): {
8888
return {
8989
title: 'GoodJob',
9090
description:
91-
'The GoodJob integration logs job lifecycle events (enqueue, start, finish, error) with execution context and performance metrics.',
91+
"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.",
9292
};
9393

9494
case LogType.SQL:
@@ -150,7 +150,7 @@ export function getEventsForLogType(logType: LogType): Event[] {
150150
case LogType.CARRIERWAVE:
151151
return [Event.Upload, Event.Delete];
152152
case LogType.GOODJOB:
153-
return [Event.Enqueue, Event.Start, Event.Finish, Event.Error, Event.Log];
153+
return [Event.Error, Event.Log];
154154
case LogType.SQL:
155155
return [Event.Database];
156156
case LogType.ACTIVEMODELSERIALIZERS:

‎docs/lib/log-generation/log-generator.ts‎

Lines changed: 1 addition & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -171,16 +171,7 @@ export class LogGenerator extends RandomDataGenerator {
171171
}
172172

173173
case LogType.GOODJOB: {
174-
switch (
175-
evt ??
176-
this.sample([Event.Enqueue, Event.Start, Event.Finish, Event.Error, Event.Log])
177-
) {
178-
case Event.Enqueue:
179-
return GoodJob.GoodJobEnqueue.random(this).serialize();
180-
case Event.Start:
181-
return GoodJob.GoodJobStart.random(this).serialize();
182-
case Event.Finish:
183-
return GoodJob.GoodJobFinish.random(this).serialize();
174+
switch (evt ?? this.sample([Event.Error, Event.Log])) {
184175
case Event.Error:
185176
return GoodJob.GoodJobError.random(this).serialize();
186177
default:

‎docs/lib/log-structure-descriptions.ts‎

Lines changed: 5 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -10,11 +10,10 @@ export const LOG_STRUCTURE_DESCRIPTIONS: Record<string, string> = {
1010
Delivered: 'ActionMailer callback emitted after a message is delivered',
1111
Delivery: 'ActionMailer event capturing when a mailer sends a message',
1212
ActiveJob: 'For background job execution',
13-
Enqueue: 'Background job enqueued event (ActiveJob or GoodJob scheduling a job for execution)',
14-
Finish: 'Background job completion event indicating success (ActiveJob/GoodJob)',
15-
Schedule:
16-
'Deferred background job scheduling event (ActiveJob or GoodJob scheduling with a run_at time)',
17-
Start: 'Lifecycle start event for jobs or services (ActiveJob, GoodJob, or Puma boot)',
13+
Enqueue: 'Background job enqueued event (ActiveJob scheduling a job for execution)',
14+
Finish: 'Background job completion event indicating success (ActiveJob)',
15+
Schedule: 'Deferred background job scheduling event (ActiveJob scheduling with a run_at time)',
16+
Start: 'Lifecycle start event for jobs or services (ActiveJob or Puma boot)',
1817
ActiveStorage: 'For file storage operations',
1918
Delete: 'Deletion of a persisted attachment (ActiveStorage, CarrierWave, or Shrine)',
2019
Download: 'File download event (ActiveStorage, CarrierWave, or Shrine)',
@@ -31,7 +30,7 @@ export const LOG_STRUCTURE_DESCRIPTIONS: Record<string, string> = {
3130
'Request blocked by ActionDispatch::HostAuthorization (host not on the allowed list)',
3231
CSRFViolation: 'Request rejected due to a CSRF token violation',
3332
IPSpoof: 'Request rejected because the IP address spoofing check failed',
34-
GoodJob: 'For GoodJob background job lifecycle events',
33+
GoodJob: "For GoodJob's own log lines and thread errors",
3534
Log: 'Structured GoodJob log output captured from the worker process',
3635
SQL: 'For ActiveRecord SQL query events and performance metrics',
3736
ActiveModelSerializers:

‎lib/log_struct.rb‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
require "log_struct/enums"
88
require "log_struct/configuration"
99
require "log_struct/formatter"
10+
require "log_struct/logged_errors"
1011
require "log_struct/railtie"
1112
require "log_struct/concerns/error_handling"
1213
require "log_struct/concerns/configuration"

‎lib/log_struct/concerns/configuration.rb‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -156,6 +156,7 @@ def server_process?
156156
return true if defined?(::Falcon::Server)
157157
return true if defined?(::Rails::Server)
158158
return true if sidekiq_server?
159+
return true if good_job_cli?
159160

160161
false
161162
end
@@ -176,6 +177,12 @@ def sidekiq_server?
176177
!!(defined?(::Sidekiq) && ::Sidekiq.respond_to?(:server?) && ::Sidekiq.server?)
177178
end
178179

180+
# GoodJob's executable (`good_job start`) sets within_exe before it loads the app
181+
sig { returns(T::Boolean) }
182+
def good_job_cli?
183+
!!(defined?(::GoodJob::CLI) && ::GoodJob::CLI.respond_to?(:within_exe?) && ::GoodJob::CLI.within_exe?)
184+
end
185+
179186
sig { returns(T::Boolean) }
180187
def logstruct_server_mode?
181188
::LogStruct.server_mode?

‎lib/log_struct/integrations/active_job/log_subscriber.rb‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -89,14 +89,17 @@ def build_base_fields(job)
8989
)
9090
end
9191

92-
sig { params(exception: StandardError, job: ::ActiveJob::Base, _event: ::ActiveSupport::Notifications::Event).void }
92+
# perform_now lets any Exception through, not only StandardErrors
93+
sig { params(exception: Exception, job: ::ActiveJob::Base, _event: ::ActiveSupport::Notifications::Event).void }
9394
def log_exception(exception, job, _event)
9495
base_fields = build_base_fields(job)
9596
job_context = base_fields.to_kwargs
9697

9798
log_data = Log.from_exception(Source::Job, exception, job_context)
9899

99100
logger.error(log_data)
101+
# So a backend that reports the same exception (GoodJob's on_thread_error) doesn't log it again
102+
LogStruct::LoggedErrors.mark(exception)
100103
end
101104

102105
sig { returns(T.untyped) }

‎lib/log_struct/integrations/good_job.rb‎

Lines changed: 104 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -8,29 +8,17 @@
88
end
99

1010
require_relative "good_job/logger" if defined?(::GoodJob)
11-
require_relative "good_job/log_subscriber" if defined?(::GoodJob)
1211

1312
module LogStruct
1413
module Integrations
1514
# GoodJob integration for structured logging
1615
#
17-
# GoodJob is a PostgreSQL-based ActiveJob backend that provides reliable,
18-
# scalable job processing for Rails applications. This integration provides
19-
# structured logging for all GoodJob operations.
16+
# GoodJob is a PostgreSQL-based ActiveJob backend. Its jobs are logged by the ActiveJob
17+
# integration (enqueued, started, finished, failed), so this integration covers GoodJob itself:
2018
#
21-
# ## Features:
22-
# - Structured logging for job execution lifecycle
23-
# - Error tracking and retry logging
24-
# - Performance metrics and timing data
25-
# - Database operation logging
26-
# - Thread and process tracking
27-
# - Custom GoodJob logger with LogStruct formatting
28-
#
29-
# ## Integration Points:
30-
# - Replaces GoodJob.logger with LogStruct-compatible logger
31-
# - Subscribes to GoodJob's ActiveSupport notifications
32-
# - Captures job execution events, errors, and performance metrics
33-
# - Logs database operations and connection information
19+
# - Replaces GoodJob.logger with a LogStruct logger, so GoodJob's own messages are JSON lines
20+
# - Logs each thread error as a structured error line, then calls the app's `on_thread_error`
21+
# - Stops GoodJob's own log subscriber logging those errors again with the whole backtrace
3422
#
3523
# ## Configuration:
3624
# The integration is automatically enabled when GoodJob is detected and
@@ -45,8 +33,7 @@ module GoodJob
4533

4634
# Set up GoodJob structured logging
4735
#
48-
# This method configures GoodJob to use LogStruct's structured logging
49-
# by replacing the default logger and subscribing to job events.
36+
# This method replaces GoodJob's logger and logs its thread errors as structured lines.
5037
#
5138
# @param config [LogStruct::Configuration] The LogStruct configuration
5239
# @return [Boolean, nil] Returns true if setup was successful, nil if skipped
@@ -59,13 +46,55 @@ def self.setup(config)
5946
# Replace GoodJob's logger with our structured logger
6047
configure_logger
6148

62-
# Subscribe to GoodJob's ActiveSupport notifications
63-
subscribe_to_notifications
49+
compact_error_lines
6450

6551
true
6652
end
6753

68-
@thread_error_handler = T.let(nil, T.nilable(T.proc.params(exception: StandardError).void))
54+
# GoodJob::LogSubscriber logs errors as text with the whole backtrace in the message (over 10KB).
55+
# GoodJob passes every error its job tasks raise, every systemd watchdog error and every notifier
56+
# error except connection errors to `on_thread_error`, which LogThreadErrors logs as a structured
57+
# line, so GoodJob's own lines for those are off. The notifier passes connection errors on only
58+
# once they repeat, so its line for them is kept, without the backtrace.
59+
module CompactErrorLines
60+
extend T::Sig
61+
extend T::Helpers
62+
63+
requires_ancestor { ::GoodJob::LogSubscriber }
64+
65+
sig { params(_event: T.untyped).void }
66+
def finished_job_task(_event)
67+
end
68+
69+
sig { params(event: T.untyped).void }
70+
def notifier_notify_error(event)
71+
exception = event.payload[:error]
72+
return unless exception
73+
return unless LogStruct::Integrations::GoodJob.notifier_connection_error?(exception)
74+
75+
error { "Notifier errored: #{exception.class}: #{exception}" }
76+
end
77+
78+
sig { params(_event: T.untyped).void }
79+
def systemd_watchdog_error(_event)
80+
end
81+
end
82+
83+
# Logs each thread error as a structured line, then calls the handler the app set as
84+
# `on_thread_error` (GoodJob's README sets one to report errors to an error tracker). Every
85+
# GoodJob component passes its thread errors to `GoodJob._on_thread_error`, so this works
86+
# whenever the app sets its handler: GoodJob's engine applies config.good_job.on_thread_error
87+
# after LogStruct's setup. GoodJob passes any Exception its handled_exceptions setting lets
88+
# through, not only StandardErrors.
89+
module LogThreadErrors
90+
extend T::Sig
91+
92+
sig { params(exception: Exception).void }
93+
def _on_thread_error(exception)
94+
LogStruct::Integrations::GoodJob.log_thread_error(exception)
95+
super
96+
end
97+
end
6998

7099
# Configure GoodJob to use LogStruct's structured logger
71100
sig { void }
@@ -78,40 +107,70 @@ def self.configure_logger
78107
# Replace GoodJob.logger with our structured logger if GoodJob is available
79108
if goodjob_module.respond_to?(:logger=)
80109
goodjob_module.logger = LogStruct::Integrations::GoodJob::Logger.new("GoodJob")
81-
end
82110

83-
# Log thread errors, after calling the handler the app set (GoodJob's README sets one
84-
# to report them to an error tracker). Setting up again keeps the one handler.
85-
if goodjob_module.respond_to?(:on_thread_error=)
86-
app_handler = goodjob_module.on_thread_error
87-
return if app_handler&.equal?(@thread_error_handler)
88-
89-
@thread_error_handler = ->(exception) do
90-
app_handler&.call(exception)
91-
log_entry = LogStruct::Log::GoodJob::Error.new(
92-
error_class: exception.class.name,
93-
error_message: exception.message,
94-
backtrace: exception.backtrace,
95-
process_id: ::Process.pid,
96-
thread_id: Thread.current.object_id.to_s(36)
97-
)
98-
goodjob_module.logger.error(log_entry)
111+
# GoodJob's executable adds a plain text STDOUT logger unless GoodJob.logger already writes
112+
# to STDOUT, which it can't tell for this logger
113+
if defined?(::GoodJob::CLI) && ::GoodJob::CLI.respond_to?(:log_to_stdout=)
114+
::GoodJob::CLI.log_to_stdout = false
99115
end
100-
goodjob_module.on_thread_error = @thread_error_handler
101116
end
117+
118+
configure_thread_error_handler
102119
end
103120

104-
# Subscribe to GoodJob's ActiveSupport notifications
105121
sig { void }
106-
def self.subscribe_to_notifications
122+
def self.configure_thread_error_handler
107123
return unless defined?(::GoodJob)
108124

109-
# Subscribe to our custom log subscriber for GoodJob events
110-
LogStruct::Integrations::GoodJob::LogSubscriber.attach_to :good_job
125+
# Not GoodJob, which here is this module
126+
goodjob_singleton = ::GoodJob.singleton_class
127+
return unless goodjob_singleton.method_defined?(:_on_thread_error)
128+
129+
goodjob_singleton.prepend(LogThreadErrors) unless goodjob_singleton.ancestors.include?(LogThreadErrors)
130+
end
131+
132+
# A failed job's exception was already logged by the ActiveJob integration, with the job's
133+
# ID and class, so it isn't logged again here
134+
sig { params(exception: Exception).void }
135+
def self.log_thread_error(exception)
136+
return if LogStruct::LoggedErrors.logged?(exception)
137+
138+
::GoodJob.logger.error(
139+
LogStruct::Log::GoodJob::Error.new(
140+
error_class: exception.class.name || exception.class.to_s,
141+
error_message: exception.message,
142+
backtrace: exception.backtrace,
143+
level: LogStruct::Level::Error,
144+
process_id: ::Process.pid,
145+
thread_id: Thread.current.object_id.to_s(36)
146+
)
147+
)
148+
end
149+
150+
# The errors GoodJob's notifier holds back until they repeat (GoodJob::Notifier::CONNECTION_ERRORS)
151+
sig { params(exception: Exception).returns(T::Boolean) }
152+
def self.notifier_connection_error?(exception)
153+
return true unless defined?(::GoodJob::Notifier::CONNECTION_ERRORS)
154+
155+
::GoodJob::Notifier::CONNECTION_ERRORS.any? do |error_name|
156+
error_class = error_name.safe_constantize
157+
error_class.is_a?(Class) && exception.is_a?(error_class)
158+
end
159+
end
160+
161+
# Only when LogThreadErrors logs thread errors instead
162+
sig { void }
163+
def self.compact_error_lines
164+
return unless defined?(::GoodJob::LogSubscriber)
165+
return unless ::GoodJob.singleton_class.ancestors.include?(LogThreadErrors)
166+
167+
log_subscriber = ::GoodJob::LogSubscriber
168+
log_subscriber.prepend(CompactErrorLines) unless log_subscriber.ancestors.include?(CompactErrorLines)
111169
end
112170

113171
private_class_method :configure_logger
114-
private_class_method :subscribe_to_notifications
172+
private_class_method :compact_error_lines
173+
private_class_method :configure_thread_error_handler
115174
end
116175
end
117176
end

0 commit comments

Comments
 (0)