debian-mirror-gitlab/lib/gitlab/sidekiq_logging/structured_logger.rb

115 lines
3.7 KiB
Ruby
Raw Normal View History

2019-02-15 15:39:39 +05:30
# frozen_string_literal: true
2020-03-13 15:44:24 +05:30
require 'active_record'
require 'active_record/log_subscriber'
2022-03-02 08:16:31 +05:30
require 'sidekiq/job_logger'
require 'sidekiq/job_retry'
2020-03-13 15:44:24 +05:30
2018-05-09 12:01:36 +05:30
module Gitlab
module SidekiqLogging
2021-11-18 22:05:49 +05:30
class StructuredLogger < Sidekiq::JobLogger
2020-04-08 14:13:33 +05:30
include LogsJobs
2018-05-09 12:01:36 +05:30
def call(job, queue)
2019-12-04 20:38:33 +05:30
started_time = get_time
2018-05-09 12:01:36 +05:30
base_payload = parse_job(job)
2021-03-11 19:13:27 +05:30
2020-03-13 15:44:24 +05:30
ActiveRecord::LogSubscriber.reset_runtime
2018-05-09 12:01:36 +05:30
2021-03-11 19:13:27 +05:30
Sidekiq.logger.info log_job_start(job, base_payload)
2018-05-09 12:01:36 +05:30
yield
2019-12-04 20:38:33 +05:30
Sidekiq.logger.info log_job_done(job, started_time, base_payload)
2021-03-11 19:13:27 +05:30
rescue Sidekiq::JobRetry::Handled => job_exception
# Sidekiq::JobRetry::Handled is raised by the internal Sidekiq
# processor. It is a wrapper around real exception indicating an
# exception is already handled by the Job retrier. The real exception
# should be unwrapped before being logged.
#
# For more information:
# https://github.com/mperham/sidekiq/blob/v5.2.7/lib/sidekiq/processor.rb#L173
Sidekiq.logger.warn log_job_done(job, started_time, base_payload, job_exception.cause || job_exception)
raise
2021-06-08 01:23:25 +05:30
rescue StandardError => job_exception
2019-12-04 20:38:33 +05:30
Sidekiq.logger.warn log_job_done(job, started_time, base_payload, job_exception)
2018-05-09 12:01:36 +05:30
raise
end
private
2019-10-12 21:52:04 +05:30
def add_instrumentation_keys!(job, output_payload)
2021-06-08 01:23:25 +05:30
output_payload.merge!(job[:instrumentation].stringify_keys) if job[:instrumentation]
2019-10-12 21:52:04 +05:30
end
2020-05-24 23:13:21 +05:30
def add_logging_extras!(job, output_payload)
output_payload.merge!(
job.select { |key, _| key.to_s.start_with?("#{ApplicationWorker::LOGGING_EXTRA_KEY}.") }
)
end
2021-03-11 19:13:27 +05:30
def log_job_start(job, payload)
2018-05-09 12:01:36 +05:30
payload['message'] = "#{base_message(payload)}: start"
payload['job_status'] = 'start'
2019-12-26 22:10:19 +05:30
scheduling_latency_s = ::Gitlab::InstrumentationHelper.queue_duration_for_job(payload)
payload['scheduling_latency_s'] = scheduling_latency_s if scheduling_latency_s
2019-10-12 21:52:04 +05:30
2021-11-18 22:05:49 +05:30
enqueue_latency_s = ::Gitlab::InstrumentationHelper.enqueue_latency_for_scheduled_job(payload)
payload['enqueue_latency_s'] = enqueue_latency_s if enqueue_latency_s
2018-05-09 12:01:36 +05:30
payload
end
2019-12-04 20:38:33 +05:30
def log_job_done(job, started_time, payload, job_exception = nil)
2018-05-09 12:01:36 +05:30
payload = payload.dup
2019-10-12 21:52:04 +05:30
add_instrumentation_keys!(job, payload)
2020-05-24 23:13:21 +05:30
add_logging_extras!(job, payload)
2019-12-04 20:38:33 +05:30
elapsed_time = elapsed(started_time)
add_time_keys!(elapsed_time, payload)
2018-05-09 12:01:36 +05:30
message = base_message(payload)
2021-09-30 23:02:18 +05:30
payload['load_balancing_strategy'] = job['load_balancing_strategy'] if job['load_balancing_strategy']
2021-11-11 11:23:49 +05:30
payload['dedup_wal_locations'] = job['dedup_wal_locations'] if job['dedup_wal_locations'].present?
2021-06-08 01:23:25 +05:30
2018-05-09 12:01:36 +05:30
if job_exception
2020-04-22 19:07:51 +05:30
payload['message'] = "#{message}: fail: #{payload['duration_s']} sec"
2018-05-09 12:01:36 +05:30
payload['job_status'] = 'fail'
2022-07-23 23:45:48 +05:30
Gitlab::ExceptionLogFormatter.format!(job_exception, payload)
2018-05-09 12:01:36 +05:30
else
2020-04-22 19:07:51 +05:30
payload['message'] = "#{message}: done: #{payload['duration_s']} sec"
2018-05-09 12:01:36 +05:30
payload['job_status'] = 'done'
end
2020-04-22 19:07:51 +05:30
db_duration = ActiveRecord::LogSubscriber.runtime
payload['db_duration_s'] = Gitlab::Utils.ms_to_round_sec(db_duration)
2018-05-09 12:01:36 +05:30
payload
end
2019-12-04 20:38:33 +05:30
def add_time_keys!(time, payload)
2020-05-24 23:13:21 +05:30
payload['duration_s'] = time[:duration].round(Gitlab::InstrumentationHelper::DURATION_PRECISION)
2020-03-13 15:44:24 +05:30
payload['completed_at'] = Time.now.utc.to_f
2019-12-04 20:38:33 +05:30
end
def elapsed(t0)
t1 = get_time
2021-03-11 19:13:27 +05:30
{ duration: t1[:now] - t0[:now] }
2019-12-04 20:38:33 +05:30
end
def get_time
2021-03-11 19:13:27 +05:30
{ now: current_time }
2019-12-04 20:38:33 +05:30
end
2018-05-09 12:01:36 +05:30
def current_time
Gitlab::Metrics::System.monotonic_time
end
end
end
end