Skip to content

Commit 121464a

Browse files
reidmorrisonreidmorrison
committed
Use Sidekiq configuration where possible to override Sidekiq logging
1 parent 58c7cce commit 121464a

File tree

7 files changed

+136
-185
lines changed

7 files changed

+136
-185
lines changed

‎lib/rails_semantic_logger.rb‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,11 @@ module DelayedJob
3131
autoload :Plugin, "rails_semantic_logger/delayed_job/plugin"
3232
end
3333

34+
module Sidekiq
35+
autoload :JobLogger, "rails_semantic_logger/sidekiq/job_logger"
36+
autoload :Loggable, "rails_semantic_logger/sidekiq/loggable"
37+
end
38+
3439
autoload :Options, "rails_semantic_logger/options"
3540

3641
# Swap an existing subscriber with a new one

‎lib/rails_semantic_logger/engine.rb‎

Lines changed: 57 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -108,12 +108,61 @@ class Engine < ::Rails::Engine
108108
Resque.logger = SemanticLogger[Resque] if defined?(Resque) && Resque.respond_to?(:logger=)
109109

110110
# Replace the Sidekiq logger
111-
if defined?(Sidekiq)
112-
if Sidekiq.respond_to?(:logger=)
113-
Sidekiq.logger = SemanticLogger[Sidekiq]
114-
elsif Sidekiq::VERSION[0..1] == "7."
115-
method = Sidekiq.server? ? :configure_server : :configure_client
116-
Sidekiq.public_send(method) { |cfg| cfg.logger = SemanticLogger[Sidekiq] }
111+
if defined?(::Sidekiq)
112+
::Sidekiq.configure_client do |config|
113+
config.logger = ::SemanticLogger[::Sidekiq]
114+
end
115+
116+
::Sidekiq.configure_server do |config|
117+
config.logger = ::SemanticLogger[::Sidekiq]
118+
if config.respond_to?(:options)
119+
config.options[:job_logger] = RailsSemanticLogger::Sidekiq::JobLogger
120+
else
121+
config[:job_logger] = RailsSemanticLogger::Sidekiq::JobLogger
122+
end
123+
124+
SemanticLogger.add_appender(io: $stdout, formatter: :color) unless SemanticLogger.appenders.console_output?
125+
126+
# Replace default error handler if present
127+
# Prevent exception logging since the Job Logger already logged the exception.
128+
# Only log the context that was not available during the job_logger call.
129+
if defined?(::Sidekiq::ExceptionHandler)
130+
existing = ::Sidekiq.error_handlers.find { |handler| handler.is_a?(::Sidekiq::ExceptionHandler::Logger) }
131+
if existing && config.error_handlers.delete(existing)
132+
config.error_handlers << ->(ex, ctx) do
133+
unless ctx.empty?
134+
job_hash = ctx[:job] || {}
135+
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
136+
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
137+
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
138+
end
139+
end
140+
end
141+
elsif defined?(::Sidekiq::DEFAULT_ERROR_HANDLER) && config.error_handlers.delete(::Sidekiq::DEFAULT_ERROR_HANDLER)
142+
config.error_handlers << ->(ex, ctx) do
143+
unless ctx.empty?
144+
job_hash = ctx[:job] || {}
145+
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
146+
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
147+
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
148+
end
149+
end
150+
elsif defined?(::Sidekiq::Config::ERROR_HANDLER) && config.error_handlers.delete(::Sidekiq::Config::ERROR_HANDLER)
151+
config.error_handlers << ->(ex, ctx, _default_configuration) do
152+
unless ctx.empty?
153+
job_hash = ctx[:job] || {}
154+
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
155+
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
156+
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
157+
end
158+
end
159+
end
160+
end
161+
162+
if defined?(::Sidekiq::Job)
163+
::Sidekiq::Job.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
164+
else
165+
::Sidekiq::Worker.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
117166
end
118167
end
119168

@@ -154,15 +203,15 @@ class Engine < ::Rails::Engine
154203

155204
if config.rails_semantic_logger.semantic
156205
# Active Job
157-
if defined?(::ActiveJob) && defined?(::ActiveJob::Logging::LogSubscriber)
206+
if defined?(::ActiveJob::Logging::LogSubscriber)
158207
RailsSemanticLogger.swap_subscriber(
159208
::ActiveJob::Logging::LogSubscriber,
160209
RailsSemanticLogger::ActiveJob::LogSubscriber,
161210
:active_job
162211
)
163212
end
164213

165-
if defined?(::ActiveJob) && defined?(::ActiveJob::LogSubscriber)
214+
if defined?(::ActiveJob::LogSubscriber)
166215
RailsSemanticLogger.swap_subscriber(
167216
::ActiveJob::LogSubscriber,
168217
RailsSemanticLogger::ActiveJob::LogSubscriber,

‎lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb‎

Lines changed: 2 additions & 175 deletions
Original file line numberDiff line numberDiff line change
@@ -1,89 +1,14 @@
11
# Sidekiq patches
2-
#
3-
# To re-enable stdout logging for sidekiq server processes, add the following snippet to config/initializers/sidekiq.rb:
4-
# Sidekiq.configure_server do |config|
5-
# SemanticLogger.add_appender(io: $stdout, level: :debug, formatter: :color)
6-
# end
72
if Sidekiq::VERSION.to_i == 4
8-
require "sidekiq/exception_handler"
93
require "sidekiq/logging"
104
require "sidekiq/middleware/server/logging"
115
require "sidekiq/processor"
12-
require "sidekiq/worker"
136
elsif Sidekiq::VERSION.to_i == 5
14-
require "sidekiq/exception_handler"
15-
require "sidekiq/job_logger"
167
require "sidekiq/logging"
17-
require "sidekiq/worker"
18-
elsif Sidekiq::VERSION.to_i == 6 && Sidekiq::VERSION.to_f < 6.5
19-
require "sidekiq/exception_handler"
20-
require "sidekiq/job_logger"
21-
require "sidekiq/worker"
22-
elsif Sidekiq::VERSION.to_i == 6
23-
require "sidekiq/job_logger"
24-
require "sidekiq/worker"
25-
else
26-
require "sidekiq/config"
27-
require "sidekiq/job_logger"
28-
require "sidekiq/job"
298
end
309

3110
module Sidekiq
32-
# Sidekiq > v4
33-
if defined?(::Sidekiq::JobLogger)
34-
# Let Semantic Logger handle duration logging
35-
class JobLogger
36-
def call(item, queue, &block)
37-
klass = item["wrapped"] || item["class"]
38-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
39-
40-
SemanticLogger.tagged(queue: queue) do
41-
# Latency is the time between when the job was enqueued and when it started executing.
42-
logger.info(
43-
"Start #perform",
44-
metric: "sidekiq.queue.latency",
45-
metric_amount: job_latency_ms(item)
46-
)
47-
48-
# Measure the duration of running the job
49-
logger.measure_info(
50-
"Completed #perform",
51-
on_exception_level: :error,
52-
log_exception: :full,
53-
metric: "sidekiq.job.perform",
54-
&block
55-
)
56-
end
57-
end
58-
59-
def prepare(job_hash, &block)
60-
level = job_hash["log_level"]
61-
if level
62-
SemanticLogger.silence(level) do
63-
SemanticLogger.tagged(job_hash_context(job_hash), &block)
64-
end
65-
else
66-
SemanticLogger.tagged(job_hash_context(job_hash), &block)
67-
end
68-
end
69-
70-
def job_hash_context(job_hash)
71-
h = {jid: job_hash["jid"]}
72-
h[:bid] = job_hash["bid"] if job_hash["bid"]
73-
h[:tags] = job_hash["tags"] if job_hash["tags"]
74-
h[:queue] = job_hash["queue"] if job_hash["queue"]
75-
h
76-
end
77-
78-
def job_latency_ms(job)
79-
return unless job && job["enqueued_at"]
80-
81-
(Time.now.to_f - job["enqueued_at"].to_f) * 1000
82-
end
83-
end
84-
end
85-
86-
# Sidekiq <= v6
11+
# Sidekiq v4 & v5
8712
if defined?(::Sidekiq::Logging)
8813
# Replace Sidekiq logging context
8914
module Logging
@@ -100,106 +25,8 @@ def self.job_hash_context(job_hash)
10025
end
10126
end
10227

103-
# Exception is already logged by Semantic Logger during the perform call
104-
if defined?(::Sidekiq::ExceptionHandler)
105-
# Sidekiq <= v6.5
106-
module ExceptionHandler
107-
class Logger
108-
def call(_exception, ctx)
109-
return if ctx.empty?
110-
111-
job_hash = ctx[:job] || {}
112-
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
113-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
114-
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
115-
end
116-
end
117-
end
118-
elsif defined?(::Sidekiq::Config)
119-
# Sidekiq >= v7
120-
class Config
121-
remove_const :ERROR_HANDLER
122-
123-
ERROR_HANDLER = ->(ex, ctx, cfg = Sidekiq.default_configuration) do
124-
unless ctx.empty?
125-
job_hash = ctx[:job] || {}
126-
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
127-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
128-
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
129-
end
130-
end
131-
end
132-
elsif Sidekiq.error_handlers.delete(Sidekiq::DEFAULT_ERROR_HANDLER)
133-
# Sidekiq >= 6.5
134-
# Replace default error handler if present
135-
Sidekiq.error_handlers << ->(ex, ctx) do
136-
unless ctx.empty?
137-
job_hash = ctx[:job] || {}
138-
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
139-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
140-
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
141-
end
142-
end
143-
end
144-
145-
# Logging within each worker should use its own logger
146-
case Sidekiq::VERSION.to_i
147-
when 4
148-
module Worker
149-
def self.included(base)
150-
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
151-
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}"
152-
end
153-
154-
base.extend(ClassMethods)
155-
base.include(SemanticLogger::Loggable)
156-
base.class_attribute :sidekiq_options_hash
157-
base.class_attribute :sidekiq_retry_in_block
158-
base.class_attribute :sidekiq_retries_exhausted_block
159-
end
160-
end
161-
when 5
162-
module Worker
163-
def self.included(base)
164-
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
165-
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}"
166-
end
167-
168-
base.extend(ClassMethods)
169-
base.include(SemanticLogger::Loggable)
170-
base.sidekiq_class_attribute :sidekiq_options_hash
171-
base.sidekiq_class_attribute :sidekiq_retry_in_block
172-
base.sidekiq_class_attribute :sidekiq_retries_exhausted_block
173-
end
174-
end
175-
when 6
176-
module Worker
177-
def self.included(base)
178-
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
179-
raise ArgumentError, "Sidekiq::Worker cannot be included in an ActiveJob: #{base.name}"
180-
end
181-
182-
base.include(Options)
183-
base.extend(ClassMethods)
184-
base.include(SemanticLogger::Loggable)
185-
end
186-
end
187-
else
188-
module Job
189-
def self.included(base)
190-
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
191-
raise ArgumentError, "Sidekiq::Job cannot be included in an ActiveJob: #{base.name}"
192-
end
193-
194-
base.include(Options)
195-
base.extend(ClassMethods)
196-
base.include(SemanticLogger::Loggable)
197-
end
198-
end
199-
end
200-
28+
# Sidekiq v4
20129
if defined?(::Sidekiq::Middleware::Server::Logging)
202-
# Sidekiq v4
20330
# Convert string to machine readable format
20431
class Processor
20532
def log_context(job_hash)

‎lib/rails_semantic_logger/sidekiq/job_logger.rb‎

Lines changed: 59 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,59 @@
1+
module RailsSemanticLogger
2+
module Sidekiq
3+
class JobLogger
4+
# Sidekiq 6.5 does not take any arguments, whereas v7 is given a logger
5+
def initialize(*_args)
6+
end
7+
8+
def call(item, queue, &block)
9+
klass = item["wrapped"] || item["class"]
10+
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
11+
12+
SemanticLogger.tagged(queue: queue) do
13+
# Latency is the time between when the job was enqueued and when it started executing.
14+
logger.info(
15+
"Start #perform",
16+
metric: "sidekiq.queue.latency",
17+
metric_amount: job_latency_ms(item)
18+
)
19+
20+
# Measure the duration of running the job
21+
logger.measure_info(
22+
"Completed #perform",
23+
on_exception_level: :error,
24+
log_exception: :full,
25+
metric: "sidekiq.job.perform",
26+
&block
27+
)
28+
end
29+
end
30+
31+
def prepare(job_hash, &block)
32+
level = job_hash["log_level"]
33+
if level
34+
SemanticLogger.silence(level) do
35+
SemanticLogger.tagged(job_hash_context(job_hash), &block)
36+
end
37+
else
38+
SemanticLogger.tagged(job_hash_context(job_hash), &block)
39+
end
40+
end
41+
42+
private
43+
44+
def job_hash_context(job_hash)
45+
h = {jid: job_hash["jid"]}
46+
h[:bid] = job_hash["bid"] if job_hash["bid"]
47+
h[:tags] = job_hash["tags"] if job_hash["tags"]
48+
h[:queue] = job_hash["queue"] if job_hash["queue"]
49+
h
50+
end
51+
52+
def job_latency_ms(job)
53+
return unless job && job["enqueued_at"]
54+
55+
(Time.now.to_f - job["enqueued_at"].to_f) * 1000
56+
end
57+
end
58+
end
59+
end

‎lib/rails_semantic_logger/sidekiq/loggable.rb‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
module RailsSemanticLogger
2+
module Sidekiq
3+
module Loggable
4+
def included(base)
5+
base.include(SemanticLogger::Loggable)
6+
super
7+
end
8+
end
9+
end
10+
end

‎test/sidekiq_test.rb‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,4 @@
11
require_relative "test_helper"
2-
require "sidekiq/processor"
32

43
class SidekiqTest < Minitest::Test
54
# Cannot use inline testing since it bypasses the Sidekiq logging calls.
@@ -16,7 +15,7 @@ class SidekiqTest < Minitest::Test
1615
end
1716

1817
describe "#perform" do
19-
let(:config) { Sidekiq::Config.new(error_handlers: []) }
18+
let(:config) { Sidekiq.default_configuration }
2019
let(:msg) { Sidekiq.dump_json({"class" => job.to_s, "args" => args, "enqueued_at" => 1.minute.ago}) }
2120
let(:uow) { Sidekiq::BasicFetch::UnitOfWork.new("queue:default", msg) }
2221
if Sidekiq::VERSION.to_i == 6 && Sidekiq::VERSION.to_f < 6.5

‎test/test_helper.rb‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
ENV["RAILS_ENV"] ||= "test"
22
ENV["DISABLE_DATABASE_ENVIRONMENT_CHECK"] = "1"
3+
# Load first so Sidekiq thinks it is running as a server instance
4+
require "sidekiq/cli"
35
require_relative "dummy/config/environment"
46

57
require "rails/test_help"

0 commit comments

Comments
 (0)