Log Sidekiq exceptions properly in JSON format

As mentioned in https://github.com/mperham/sidekiq/wiki/Error-Handling,
Sidekiq can be configured with an exception handler. We use this to log
the exception in a structured way so that `corrrelation_id`, `class`,
and other useful fields are available.

The previous error backtrace in the `StructuredLogger` class did not
provide useful information because Sidekiq swallows the exception and
raises a `JobRetry::Skip` exception.

Closes https://gitlab.com/gitlab-org/gitlab/issues/29425

changelogs/unreleased/sh-handle-exceptions-sidekiq.yml

+---
+title: Log Sidekiq exceptions properly in JSON format
+merge_request: 17412
+author:
+type: fixed

config/initializers/sidekiq.rb

@@ -50,6 +50,10 @@ Sidekiq.configure_server do |config|
   if enable_json_logs
     Sidekiq.logger.formatter = Gitlab::SidekiqLogging::JSONFormatter.new
     config.options[:job_logger] = Gitlab::SidekiqLogging::StructuredLogger
+
+    # Remove the default-provided handler
+    config.error_handlers.reject! { |handler| handler.is_a?(Sidekiq::ExceptionHandler::Logger) }
+    config.error_handlers << Gitlab::SidekiqLogging::ExceptionHandler.new
   end
 
   config.client_middleware do |chain|

lib/gitlab/sidekiq_logging/exception_handler.rb

+# 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] = Gitlab::Profiler.clean_backtrace(job_exception.backtrace) if job_exception.backtrace.present?
+
+        Sidekiq.logger.warn(data)
+      end
+    end
+  end
+end

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -58,8 +58,7 @@ module Gitlab
           payload['message'] = "#{message}: fail: #{payload['duration']} sec"
           payload['job_status'] = 'fail'
           payload['error_message'] = job_exception.message
-          payload['error'] = job_exception.class
-          payload['error_backtrace'] = backtrace_cleaner.clean(job_exception.backtrace)
+          payload['error_class'] = job_exception.class.name
         else
           payload['message'] = "#{message}: done: #{payload['duration']} sec"
           payload['job_status'] = 'done'
@@ -127,10 +126,6 @@ module Gitlab
         Gitlab::Metrics::System.monotonic_time
       end
 
-      def backtrace_cleaner
-        @backtrace_cleaner ||= ActiveSupport::BacktraceCleaner.new
-      end
-
       def format_time(timestamp)
         return timestamp if timestamp.is_a?(String)
 

spec/lib/gitlab/sidekiq_logging/exception_handler_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::SidekiqLogging::ExceptionHandler do
+  describe '#call' do
+    let(:job) do
+      {
+        "class" => "TestWorker",
+        "args" => [1234, 'hello'],
+        "retry" => false,
+        "queue" => "cronjob:test_queue",
+        "queue_namespace" => "cronjob",
+        "jid" => "da883554ee4fe414012f5f42",
+        "correlation_id" => 'cid'
+      }
+    end
+
+    let(:exception_message) { 'An error was thrown' }
+    let(:backtrace) { caller }
+    let(:exception) { RuntimeError.new(exception_message) }
+    let(:logger) { double }
+
+    before do
+      allow(Sidekiq).to receive(:logger).and_return(logger)
+      allow(exception).to receive(:backtrace).and_return(backtrace)
+    end
+
+    subject { described_class.new.call(exception, { context: 'Test', job: job }) }
+
+    it 'logs job data into root tree' do
+      expected_data = job.merge(
+        error_class: 'RuntimeError',
+        error_message: exception_message,
+        context: 'Test',
+        error_backtrace: Gitlab::Profiler.clean_backtrace(backtrace)
+      )
+
+      expect(logger).to receive(:warn).with(expected_data)
+
+      subject
+    end
+  end
+end

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -47,7 +47,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
       end_payload.merge(
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: fail: 0.0 sec',
         'job_status' => 'fail',
-        'error' => ArgumentError,
+        'error_class' => 'ArgumentError',
         'error_message' => 'some exception'
       )
     end
@@ -86,7 +86,6 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
       it 'logs an exception in job' do
         Timecop.freeze(timestamp) do
           expect(logger).to receive(:info).with(start_payload)
-          # This excludes the exception_backtrace
           expect(logger).to receive(:warn).with(hash_including(exception_payload))
           expect(subject).to receive(:log_job_start).and_call_original
           expect(subject).to receive(:log_job_done).and_call_original