Skip to content

Commit 70722e4

Browse files
reidmorrisonreidmorrison
committed
Refine metrics that are generated
1 parent 114f914 commit 70722e4

File tree

5 files changed

+121
-83
lines changed

5 files changed

+121
-83
lines changed

‎.gitignore‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,3 +16,4 @@ Gemfile.lock
1616
TODO.md
1717

1818
.tool-versions
19+
test/dummy/db/test.sqlite3

‎lib/rails_semantic_logger.rb‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@ def self.subscriber_patterns(subscriber)
6969
require("rails_semantic_logger/extensions/active_support/log_subscriber") if defined?(ActiveSupport::LogSubscriber)
7070

7171
begin
72-
require 'rackup'
72+
require "rackup"
7373
rescue LoadError
7474
# No need to do anything, will fall back to Rack
7575
end

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

Lines changed: 90 additions & 59 deletions
Original file line numberDiff line numberDiff line change
@@ -33,18 +33,26 @@ module Sidekiq
3333
if defined?(::Sidekiq::JobLogger)
3434
# Let Semantic Logger handle duration logging
3535
class JobLogger
36-
def call(item, queue)
36+
def call(item, queue, &block)
3737
klass = item["wrapped"] || item["class"]
38-
metric = "Sidekiq/#{klass}/perform" if klass
3938
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
40-
logger.info("Start #perform")
41-
logger.measure_info(
42-
"Completed #perform",
43-
on_exception_level: :error,
44-
log_exception: :full,
45-
metric: metric
46-
) do
47-
yield
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+
)
4856
end
4957
end
5058

@@ -60,14 +68,18 @@ def prepare(job_hash, &block)
6068
end
6169

6270
def job_hash_context(job_hash)
63-
h = {
64-
class: job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"],
65-
jid: job_hash["jid"]
66-
}
67-
h[:bid] = job_hash["bid"] if job_hash["bid"]
68-
h[:tags] = job_hash["tags"] if job_hash["tags"]
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"]
6975
h
7076
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
7183
end
7284
end
7385

@@ -80,10 +92,10 @@ def self.with_context(msg, &block)
8092
end
8193

8294
def self.job_hash_context(job_hash)
83-
klass = job_hash["wrapped"] || job_hash["class"]
84-
event = { class: klass, jid: job_hash["jid"] }
85-
event[:bid] = job_hash["bid"] if job_hash["bid"]
86-
event
95+
h = {jid: job_hash["jid"]}
96+
h[:bid] = job_hash["bid"] if job_hash["bid"]
97+
h[:queue] = job_hash["queue"] if job_hash["queue"]
98+
h
8799
end
88100
end
89101
end
@@ -93,49 +105,51 @@ def self.job_hash_context(job_hash)
93105
if defined?(::Sidekiq::ExceptionHandler)
94106
module ExceptionHandler
95107
class Logger
96-
def call(ex, ctx)
97-
unless ctx.empty?
98-
job_hash = ctx[:job] || {}
99-
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
100-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
101-
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
102-
end
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)
103115
end
104116
end
105117
end
106-
# Sidekiq >= v7
118+
# Sidekiq >= v7
107119
elsif defined?(::Sidekiq::Config)
108120
class Config
109121
remove_const :ERROR_HANDLER
110122

111-
ERROR_HANDLER = ->(ex, ctx, cfg = Sidekiq.default_configuration) {
123+
ERROR_HANDLER = lambda { |_ex, ctx, _cfg = Sidekiq.default_configuration|
112124
unless ctx.empty?
113125
job_hash = ctx[:job] || {}
114-
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
115-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
126+
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
127+
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
116128
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
117129
end
118130
}
119131
end
120132
else
121133
# Sidekiq >= 6.5
122134
# TODO: Not taking effect. See test/sidekiq_test.rb
123-
def self.default_error_handler(ex, ctx)
124-
binding.irb
125-
unless ctx.empty?
126-
job_hash = ctx[:job] || {}
127-
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
128-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
129-
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
130-
end
135+
def self.default_error_handler(_exception, ctx)
136+
return if ctx.empty?
137+
138+
job_hash = ctx[:job] || {}
139+
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
140+
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
141+
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
131142
end
132143
end
133144

134145
# Logging within each worker should use its own logger
135-
if Sidekiq::VERSION.to_i == 4
146+
case Sidekiq::VERSION.to_i
147+
when 4
136148
module Worker
137149
def self.included(base)
138-
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}" if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
150+
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}" if base.ancestors.any? do |c|
151+
c.name == "ActiveJob::Base"
152+
end
139153

140154
base.extend(ClassMethods)
141155
base.include(SemanticLogger::Loggable)
@@ -144,10 +158,12 @@ def self.included(base)
144158
base.class_attribute :sidekiq_retries_exhausted_block
145159
end
146160
end
147-
elsif Sidekiq::VERSION.to_i == 5
161+
when 5
148162
module Worker
149163
def self.included(base)
150-
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}" if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
164+
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}" if base.ancestors.any? do |c|
165+
c.name == "ActiveJob::Base"
166+
end
151167

152168
base.extend(ClassMethods)
153169
base.include(SemanticLogger::Loggable)
@@ -156,10 +172,12 @@ def self.included(base)
156172
base.sidekiq_class_attribute :sidekiq_retries_exhausted_block
157173
end
158174
end
159-
elsif Sidekiq::VERSION.to_i == 6
175+
when 6
160176
module Worker
161177
def self.included(base)
162-
raise ArgumentError, "Sidekiq::Worker cannot be included in an ActiveJob: #{base.name}" if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
178+
raise ArgumentError, "Sidekiq::Worker cannot be included in an ActiveJob: #{base.name}" if base.ancestors.any? do |c|
179+
c.name == "ActiveJob::Base"
180+
end
163181

164182
base.include(Options)
165183
base.extend(ClassMethods)
@@ -169,7 +187,9 @@ def self.included(base)
169187
else
170188
module Job
171189
def self.included(base)
172-
raise ArgumentError, "Sidekiq::Job cannot be included in an ActiveJob: #{base.name}" if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
190+
raise ArgumentError, "Sidekiq::Job cannot be included in an ActiveJob: #{base.name}" if base.ancestors.any? do |c|
191+
c.name == "ActiveJob::Base"
192+
end
173193

174194
base.include(Options)
175195
base.extend(ClassMethods)
@@ -182,28 +202,39 @@ def self.included(base)
182202
# Convert string to machine readable format
183203
class Processor
184204
def log_context(job_hash)
185-
klass = job_hash["wrapped"] || job_hash["class"]
186-
event = { class: klass, jid: job_hash["jid"] }
187-
event[:bid] = job_hash["bid"] if job_hash["bid"]
188-
event
205+
h = {jid: job_hash["jid"]}
206+
h[:bid] = job_hash["bid"] if job_hash["bid"]
207+
h[:queue] = job_hash["queue"] if job_hash["queue"]
208+
h
189209
end
190210
end
191211

192212
# Let Semantic Logger handle duration logging
193213
module Middleware
194214
module Server
195215
class Logging
196-
def call(worker, item, queue)
197-
worker.logger.info("Start #perform")
198-
worker.logger.measure_info(
199-
"Completed #perform",
200-
on_exception_level: :error,
201-
log_exception: :full,
202-
metric: "Sidekiq/#{worker.class.name}/perform"
203-
) do
204-
yield
216+
def call(worker, item, queue, &block)
217+
SemanticLogger.named_tags(queue: queue) do
218+
worker.logger.info(
219+
"Start #perform",
220+
metric: "sidekiq.queue.latency",
221+
metric_amount: job_latency_ms(item)
222+
)
223+
worker.logger.measure_info(
224+
"Completed #perform",
225+
on_exception_level: :error,
226+
log_exception: :full,
227+
metric: "sidekiq.job.perform",
228+
&block
229+
)
205230
end
206231
end
232+
233+
def job_latency_ms(job)
234+
return unless job && job["enqueued_at"]
235+
236+
(Time.now.to_f - job["enqueued_at"]) * 1000
237+
end
207238
end
208239
end
209240
end

‎test/dummy/config/application.rb‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -6,9 +6,7 @@
66

77
module Dummy
88
class Application < Rails::Application
9-
if config.respond_to?(:load_defaults)
10-
config.load_defaults "#{Rails::VERSION::MAJOR}.#{Rails::VERSION::MINOR}"
11-
end
9+
config.load_defaults "#{Rails::VERSION::MAJOR}.#{Rails::VERSION::MINOR}" if config.respond_to?(:load_defaults)
1210

1311
# Configure sensitive parameters which will be filtered from the log file.
1412
config.filter_parameters += [:password]

‎test/sidekiq_test.rb‎

Lines changed: 28 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -17,37 +17,37 @@ class SidekiqTest < Minitest::Test
1717

1818
describe "#perform" do
1919
let(:config) { Sidekiq::Config.new(error_handlers: []) }
20-
let(:msg) { Sidekiq.dump_json({ "class" => job.to_s, "args" => args }) }
20+
let(:msg) { Sidekiq.dump_json({"class" => job.to_s, "args" => args, "enqueued_at" => 1.minute.ago}) }
2121
let(:uow) { Sidekiq::BasicFetch::UnitOfWork.new("queue:default", msg) }
2222
if Sidekiq::VERSION.to_i == 6 && Sidekiq::VERSION.to_f < 6.5
2323
let(:processor) do
24-
mgr = Minitest::Mock.new
25-
opts = {:queues => ['default']}
24+
mgr = Minitest::Mock.new
25+
opts = {queues: ["default"]}
2626
opts[:fetch] = Sidekiq::BasicFetch.new(opts)
2727
Sidekiq::Processor.new(mgr, opts)
2828
end
2929
elsif Sidekiq::VERSION.to_i == 6
3030
let(:processor) do
3131
# TODO: Sidekiq 6.5 default handler is not accepting the patch
32-
handler = ->(ex, ctx) {
32+
handler = lambda { |_ex, ctx|
3333
unless ctx.empty?
3434
job_hash = ctx[:job] || {}
35-
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
36-
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
35+
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
36+
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
3737
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
3838
end
3939
}
40-
config = Sidekiq
40+
config = Sidekiq
4141
config[:error_handlers] = [handler]
42-
config[:fetch] = Sidekiq::BasicFetch.new(config)
42+
config[:fetch] = Sidekiq::BasicFetch.new(config)
4343
Sidekiq::Processor.new(config) { |*args| }
4444
end
4545
elsif Sidekiq::VERSION.to_i < 7
4646
let(:processor) do
4747
mgr = Minitest::Mock.new
48-
mgr.expect(:options, {:queues => ['default']})
49-
mgr.expect(:options, {:queues => ['default']})
50-
mgr.expect(:options, {:queues => ['default']})
48+
mgr.expect(:options, {queues: ["default"]})
49+
mgr.expect(:options, {queues: ["default"]})
50+
mgr.expect(:options, {queues: ["default"]})
5151
Sidekiq::Processor.new(mgr)
5252
end
5353
else
@@ -67,17 +67,20 @@ class SidekiqTest < Minitest::Test
6767
level: :info,
6868
name: "SimpleJob",
6969
message_includes: "Start #perform",
70-
named_tags: { class: "SimpleJob", jid: nil }
70+
metric: "sidekiq.queue.latency",
71+
named_tags: {jid: nil, queue: "default"}
7172
)
73+
assert messages[0].metric_amount.is_a?(Float)
7274

7375
assert_semantic_logger_event(
7476
messages[1],
7577
level: :info,
7678
name: "SimpleJob",
7779
message_includes: "Completed #perform",
78-
metric: "Sidekiq/SimpleJob/perform",
79-
named_tags: { class: "SimpleJob", jid: nil }
80+
metric: "sidekiq.job.perform",
81+
named_tags: {jid: nil, queue: "default"}
8082
)
83+
assert messages[1].duration.is_a?(Float)
8184
end
8285

8386
describe "with Bad Job" do
@@ -98,27 +101,32 @@ class SidekiqTest < Minitest::Test
98101
level: :info,
99102
name: "BadJob",
100103
message: "Start #perform",
101-
named_tags: { class: "BadJob", jid: nil }
104+
metric: "sidekiq.queue.latency",
105+
named_tags: {jid: nil, queue: "default"}
102106
)
107+
assert messages[0].metric_amount.is_a?(Float)
103108

104109
assert_semantic_logger_event(
105110
messages[1],
106111
level: :error,
107112
name: "BadJob",
108113
message: "Completed #perform",
109-
metric: "Sidekiq/BadJob/perform",
110-
named_tags: { class: "BadJob", jid: nil }
111-
# exception: { name: "ArgumentError", message: "This is a bad job" }
114+
metric: "sidekiq.job.perform",
115+
named_tags: {jid: nil, queue: "default"}
116+
# exception: { name: "ArgumentError", message: "This is a bad job" }
112117
)
118+
assert messages[1].duration.is_a?(Float)
113119

114120
assert_semantic_logger_event(
115121
messages[2],
116122
level: :warn,
117123
name: "BadJob",
118124
message: "Job raised exception",
119-
payload_includes: { context: "Job raised exception", job: { "class" => "BadJob", "args" => [] } }
120-
# exception: { name: "ArgumentError", message: "This is a bad job" }
125+
payload_includes: {context: "Job raised exception"}
126+
# exception: { name: "ArgumentError", message: "This is a bad job" }
121127
)
128+
assert_equal messages[2].payload[:job]["class"], "BadJob"
129+
assert_equal messages[2].payload[:job]["args"], []
122130
end
123131
end
124132
end

0 commit comments

Comments
 (0)