diff options
author | GitLab Bot <gitlab-bot@gitlab.com> | 2021-02-18 13:34:06 +0300 |
---|---|---|
committer | GitLab Bot <gitlab-bot@gitlab.com> | 2021-02-18 13:34:06 +0300 |
commit | 859a6fb938bb9ee2a317c46dfa4fcc1af49608f0 (patch) | |
tree | d7f2700abe6b4ffcb2dcfc80631b2d87d0609239 /lib/gitlab/sidekiq_logging | |
parent | 446d496a6d000c73a304be52587cd9bbc7493136 (diff) |
Add latest changes from gitlab-org/gitlab@13-9-stable-eev13.9.0-rc42
Diffstat (limited to 'lib/gitlab/sidekiq_logging')
-rw-r--r-- | lib/gitlab/sidekiq_logging/exception_handler.rb | 27 | ||||
-rw-r--r-- | lib/gitlab/sidekiq_logging/logs_jobs.rb | 1 | ||||
-rw-r--r-- | lib/gitlab/sidekiq_logging/structured_logger.rb | 48 |
3 files changed, 29 insertions, 47 deletions
diff --git a/lib/gitlab/sidekiq_logging/exception_handler.rb b/lib/gitlab/sidekiq_logging/exception_handler.rb deleted file mode 100644 index 8ae6addc2c6..00000000000 --- a/lib/gitlab/sidekiq_logging/exception_handler.rb +++ /dev/null @@ -1,27 +0,0 @@ -# frozen_string_literal: true - -module Gitlab - module SidekiqLogging - class ExceptionHandler - def call(job_exception, context) - data = { - error_class: job_exception.class.name, - error_message: job_exception.message - } - - if context.is_a?(Hash) - data.merge!(context) - # correlation_id, jid, and class are available inside the job - # Hash, so promote these arguments to the root tree so that - # can be searched alongside other Sidekiq log messages. - job_data = data.delete(:job) - data.merge!(job_data) if job_data.present? - end - - data[:error_backtrace] = Rails.backtrace_cleaner.clean(job_exception.backtrace) if job_exception.backtrace.present? - - Sidekiq.logger.warn(data) - end - end - end -end diff --git a/lib/gitlab/sidekiq_logging/logs_jobs.rb b/lib/gitlab/sidekiq_logging/logs_jobs.rb index dc81c34c4d0..6f8cc1c60e9 100644 --- a/lib/gitlab/sidekiq_logging/logs_jobs.rb +++ b/lib/gitlab/sidekiq_logging/logs_jobs.rb @@ -12,6 +12,7 @@ module Gitlab # Error information from the previous try is in the payload for # displaying in the Sidekiq UI, but is very confusing in logs! job = job.except('error_backtrace', 'error_class', 'error_message') + job['class'] = job.delete('wrapped') if job['wrapped'].present? # Add process id params job['pid'] = ::Process.pid diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb index eb845c5ff8d..654b17c5740 100644 --- a/lib/gitlab/sidekiq_logging/structured_logger.rb +++ b/lib/gitlab/sidekiq_logging/structured_logger.rb @@ -11,13 +11,25 @@ module Gitlab def call(job, queue) started_time = get_time base_payload = parse_job(job) + ActiveRecord::LogSubscriber.reset_runtime - Sidekiq.logger.info log_job_start(base_payload) + Sidekiq.logger.info log_job_start(job, base_payload) yield Sidekiq.logger.info log_job_done(job, started_time, base_payload) + 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 rescue => job_exception Sidekiq.logger.warn log_job_done(job, started_time, base_payload, job_exception) @@ -27,7 +39,9 @@ module Gitlab private def add_instrumentation_keys!(job, output_payload) - output_payload.merge!(job.slice(*::Gitlab::InstrumentationHelper.keys)) + instrumentation_values = job.slice(*::Gitlab::InstrumentationHelper.keys).stringify_keys + + output_payload.merge!(instrumentation_values) end def add_logging_extras!(job, output_payload) @@ -36,17 +50,15 @@ module Gitlab ) end - def add_db_counters!(job, output_payload) - output_payload.merge!(job.slice(*::Gitlab::Metrics::Subscribers::ActiveRecord::DB_COUNTERS)) - end - - def log_job_start(payload) + def log_job_start(job, payload) payload['message'] = "#{base_message(payload)}: start" payload['job_status'] = 'start' scheduling_latency_s = ::Gitlab::InstrumentationHelper.queue_duration_for_job(payload) payload['scheduling_latency_s'] = scheduling_latency_s if scheduling_latency_s + payload['job_size_bytes'] = Sidekiq.dump_json(job).bytesize + payload end @@ -54,7 +66,6 @@ module Gitlab payload = payload.dup add_instrumentation_keys!(job, payload) add_logging_extras!(job, payload) - add_db_counters!(job, payload) elapsed_time = elapsed(started_time) add_time_keys!(elapsed_time, payload) @@ -66,6 +77,7 @@ module Gitlab payload['job_status'] = 'fail' payload['error_message'] = job_exception.message payload['error_class'] = job_exception.class.name + add_exception_backtrace!(job_exception, payload) else payload['message'] = "#{message}: done: #{payload['duration_s']} sec" payload['job_status'] = 'done' @@ -79,26 +91,22 @@ module Gitlab def add_time_keys!(time, payload) payload['duration_s'] = time[:duration].round(Gitlab::InstrumentationHelper::DURATION_PRECISION) - - # ignore `cpu_s` if the platform does not support Process::CLOCK_THREAD_CPUTIME_ID (time[:cputime] == 0) - # supported OS version can be found at: https://www.rubydoc.info/stdlib/core/2.1.6/Process:clock_gettime - payload['cpu_s'] = time[:cputime].round(Gitlab::InstrumentationHelper::DURATION_PRECISION) if time[:cputime] > 0 payload['completed_at'] = Time.now.utc.to_f end + def add_exception_backtrace!(job_exception, payload) + return if job_exception.backtrace.blank? + + payload['error_backtrace'] = Rails.backtrace_cleaner.clean(job_exception.backtrace) + end + def elapsed(t0) t1 = get_time - { - duration: t1[:now] - t0[:now], - cputime: t1[:thread_cputime] - t0[:thread_cputime] - } + { duration: t1[:now] - t0[:now] } end def get_time - { - now: current_time, - thread_cputime: defined?(Process::CLOCK_THREAD_CPUTIME_ID) ? Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID) : 0 - } + { now: current_time } end def current_time |