2018-03-15 12:00:53 -04:00
|
|
|
# frozen_string_literal: true
|
2018-12-28 18:05:51 -05:00
|
|
|
|
2017-01-17 17:58:08 -05:00
|
|
|
module Sidekiq
|
|
|
|
class JobLogger
|
|
|
|
|
2018-12-29 10:54:05 -05:00
|
|
|
def initialize(logger=Sidekiq.logger)
|
|
|
|
@logger = logger
|
|
|
|
end
|
|
|
|
|
2017-01-17 17:58:08 -05:00
|
|
|
def call(item, queue)
|
2018-10-18 16:51:58 -04:00
|
|
|
start = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
|
2018-12-29 10:54:05 -05:00
|
|
|
@logger.info("start")
|
2018-12-28 18:05:51 -05:00
|
|
|
|
2017-05-08 15:50:36 -04:00
|
|
|
yield
|
2018-12-28 18:05:51 -05:00
|
|
|
|
|
|
|
with_elapsed_time_context(start) do
|
2018-12-29 10:54:05 -05:00
|
|
|
@logger.info("done")
|
2018-12-28 18:05:51 -05:00
|
|
|
end
|
2017-05-08 15:50:36 -04:00
|
|
|
rescue Exception
|
2018-12-28 18:05:51 -05:00
|
|
|
with_elapsed_time_context(start) do
|
2018-12-29 10:54:05 -05:00
|
|
|
@logger.info("fail")
|
2018-12-28 18:05:51 -05:00
|
|
|
end
|
|
|
|
|
2017-05-08 15:50:36 -04:00
|
|
|
raise
|
2017-01-17 17:58:08 -05:00
|
|
|
end
|
|
|
|
|
2018-12-28 18:05:51 -05:00
|
|
|
def with_job_hash_context(job_hash, &block)
|
2018-12-29 10:54:05 -05:00
|
|
|
@logger.with_context(job_hash_context(job_hash), &block)
|
2018-12-28 18:05:51 -05:00
|
|
|
end
|
|
|
|
|
|
|
|
def job_hash_context(job_hash)
|
|
|
|
# If we're using a wrapper class, like ActiveJob, use the "wrapped"
|
|
|
|
# attribute to expose the underlying thing.
|
2018-12-29 10:54:05 -05:00
|
|
|
h = {
|
2018-12-28 18:05:51 -05:00
|
|
|
class: job_hash['wrapped'] || job_hash["class"],
|
|
|
|
jid: job_hash['jid'],
|
|
|
|
}
|
2018-12-29 10:54:05 -05:00
|
|
|
h[:bid] = job_hash['bid'] if job_hash['bid']
|
|
|
|
h
|
2018-12-28 18:05:51 -05:00
|
|
|
end
|
|
|
|
|
|
|
|
def with_elapsed_time_context(start, &block)
|
2018-12-29 10:54:05 -05:00
|
|
|
@logger.with_context(elapsed_time_context(start), &block)
|
2018-12-28 18:05:51 -05:00
|
|
|
end
|
|
|
|
|
|
|
|
def elapsed_time_context(start)
|
2018-12-29 10:54:05 -05:00
|
|
|
{ elapsed: "#{elapsed(start)}" }
|
2018-12-28 18:05:51 -05:00
|
|
|
end
|
|
|
|
|
2017-01-17 17:58:08 -05:00
|
|
|
private
|
|
|
|
|
|
|
|
def elapsed(start)
|
2018-10-18 16:51:58 -04:00
|
|
|
(::Process.clock_gettime(::Process::CLOCK_MONOTONIC) - start).round(3)
|
2017-01-17 17:58:08 -05:00
|
|
|
end
|
|
|
|
end
|
|
|
|
end
|