Add support for Sidekiq JSON logging

changelogs/unreleased/sh-gitlab-sidekiq-logger.yml

+---
+title: Add support for Sidekiq JSON logging
+merge_request:
+author:
+type: added

config/gitlab.yml.example

@@ -226,6 +226,10 @@ production: &base
     # plain_url: "http://..."     # default: https://www.gravatar.com/avatar/%{hash}?s=%{size}&d=identicon
     # ssl_url:   "https://..."    # default: https://secure.gravatar.com/avatar/%{hash}?s=%{size}&d=identicon
 
+  ## Sidekiq
+  sidekiq:
+    log_format: default # (json is also supported)
+
   ## Auxiliary jobs
   # Periodically executed jobs, to self-heal GitLab, do external synchronizations, etc.
   # Please read here for more information: https://github.com/ondrejbartas/sidekiq-cron#adding-cron-job

config/initializers/1_settings.rb

@@ -454,6 +454,12 @@ Settings.cron_jobs['pages_domain_verification_cron_worker']['cron'] ||= '*/15 *
 Settings.cron_jobs['pages_domain_verification_cron_worker']['job_class'] = 'PagesDomainVerificationCronWorker'
 
 #
+# Sidekiq
+#
+Settings['sidekiq'] ||= Settingslogic.new({})
+Settings['sidekiq']['log_format'] ||= 'default'
+
+#
 # GitLab Shell
 #
 Settings['gitlab_shell'] ||= Settingslogic.new({})

config/initializers/sidekiq.rb

@@ -5,16 +5,23 @@ queues_config_hash[:namespace] = Gitlab::Redis::Queues::SIDEKIQ_NAMESPACE
 # Default is to retry 25 times with exponential backoff. That's too much.
 Sidekiq.default_worker_options = { retry: 3 }
 
+enable_json_logs = Gitlab.config.sidekiq.log_format == 'json'
+
 Sidekiq.configure_server do |config|
   config.redis = queues_config_hash
 
   config.server_middleware do |chain|
-    chain.add Gitlab::SidekiqMiddleware::ArgumentsLogger if ENV['SIDEKIQ_LOG_ARGUMENTS']
+    chain.add Gitlab::SidekiqMiddleware::ArgumentsLogger if ENV['SIDEKIQ_LOG_ARGUMENTS'] && !enable_json_logs
     chain.add Gitlab::SidekiqMiddleware::Shutdown
     chain.add Gitlab::SidekiqMiddleware::RequestStoreMiddleware unless ENV['SIDEKIQ_REQUEST_STORE'] == '0'
     chain.add Gitlab::SidekiqStatus::ServerMiddleware
   end
 
+  if enable_json_logs
+    Sidekiq.logger.formatter = Gitlab::SidekiqLogging::JSONFormatter.new
+    config.options[:job_logger] = Gitlab::SidekiqLogging::StructuredLogger
+  end
+
   config.client_middleware do |chain|
     chain.add Gitlab::SidekiqStatus::ClientMiddleware
   end

doc/administration/logs.md

@@ -146,6 +146,28 @@ this file. For example:
 2014-06-10T18:18:26Z 14299 TID-55uqo INFO: Booting Sidekiq 3.0.0 with redis options {:url=>"redis://localhost:6379/0", :namespace=>"sidekiq"}
 ```
 
+Instead of the format above, you can opt to generate JSON logs for
+Sidekiq. For example:
+
+```json
+{"severity":"INFO","time":"2018-04-03T22:57:22.071Z","queue":"cronjob:update_all_mirrors","args":[],"class":"UpdateAllMirrorsWorker","retry":false,"queue_namespace":"cronjob","jid":"06aeaa3b0aadacf9981f368e","created_at":"2018-04-03T22:57:21.930Z","enqueued_at":"2018-04-03T22:57:21.931Z","pid":10077,"message":"UpdateAllMirrorsWorker JID-06aeaa3b0aadacf9981f368e: done: 0.139 sec","job_status":"done","duration":0.139,"completed_at":"2018-04-03T22:57:22.071Z"}
+```
+
+For Omnibus GitLab installations, add the configuration option:
+
+```ruby
+sidekiq['log_format'] = 'json'
+```
+
+For source installations, edit the `gitlab.yml` and set the Sidekiq
+`log_format` configuration option:
+
+```yaml
+  ## Sidekiq
+  sidekiq:
+    log_format: json
+```
+
 ## `gitlab-shell.log`
 
 This file lives in `/var/log/gitlab/gitlab-shell/gitlab-shell.log` for

lib/gitlab/sidekiq_logging/json_formatter.rb

+module Gitlab
+  module SidekiqLogging
+    class JSONFormatter
+      def call(severity, timestamp, progname, data)
+        output = {
+          severity: severity,
+          time: timestamp.utc.iso8601(3)
+        }
+
+        case data
+        when String
+          output[:message] = data
+        when Hash
+          output.merge!(data)
+        end
+
+        output.to_json + "\n"
+      end
+    end
+  end
+end

lib/gitlab/sidekiq_logging/structured_logger.rb

+module Gitlab
+  module SidekiqLogging
+    class StructuredLogger
+      START_TIMESTAMP_FIELDS = %w[created_at enqueued_at].freeze
+      DONE_TIMESTAMP_FIELDS = %w[started_at retried_at failed_at completed_at].freeze
+
+      def call(job, queue)
+        started_at = current_time
+        base_payload = parse_job(job)
+
+        Sidekiq.logger.info log_job_start(started_at, base_payload)
+
+        yield
+
+        Sidekiq.logger.info log_job_done(started_at, base_payload)
+      rescue => job_exception
+        Sidekiq.logger.warn log_job_done(started_at, base_payload, job_exception)
+
+        raise
+      end
+
+      private
+
+      def base_message(payload)
+        "#{payload['class']} JID-#{payload['jid']}"
+      end
+
+      def log_job_start(started_at, payload)
+        payload['message'] = "#{base_message(payload)}: start"
+        payload['job_status'] = 'start'
+
+        payload
+      end
+
+      def log_job_done(started_at, payload, job_exception = nil)
+        payload = payload.dup
+        payload['duration'] = elapsed(started_at)
+        payload['completed_at'] = Time.now.utc
+
+        message = base_message(payload)
+
+        if job_exception
+          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)
+        else
+          payload['message'] = "#{message}: done: #{payload['duration']} sec"
+          payload['job_status'] = 'done'
+        end
+
+        convert_to_iso8601(payload, DONE_TIMESTAMP_FIELDS)
+
+        payload
+      end
+
+      def parse_job(job)
+        job = job.dup
+
+        # Add process id params
+        job['pid'] = ::Process.pid
+
+        job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS']
+
+        convert_to_iso8601(job, START_TIMESTAMP_FIELDS)
+
+        job
+      end
+
+      def convert_to_iso8601(payload, keys)
+        keys.each do |key|
+          payload[key] = format_time(payload[key]) if payload[key]
+        end
+      end
+
+      def elapsed(start)
+        (current_time - start).round(3)
+      end
+
+      def current_time
+        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)
+
+        Time.at(timestamp).utc.iso8601(3)
+      end
+    end
+  end
+end

spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb

+require 'spec_helper'
+
+describe Gitlab::SidekiqLogging::JSONFormatter do
+  let(:hash_input) { { foo: 1, bar: 'test' } }
+  let(:message) { 'This is a test' }
+  let(:timestamp) { Time.now }
+
+  it 'wraps a Hash' do
+    result = subject.call('INFO', timestamp, 'my program', hash_input)
+
+    data = JSON.parse(result)
+    expected_output = hash_input.stringify_keys
+    expected_output['severity'] = 'INFO'
+    expected_output['time'] = timestamp.utc.iso8601(3)
+
+    expect(data).to eq(expected_output)
+  end
+
+  it 'wraps a String' do
+    result = subject.call('DEBUG', timestamp, 'my string', message)
+
+    data = JSON.parse(result)
+    expected_output = {
+      severity: 'DEBUG',
+      time: timestamp.utc.iso8601(3),
+      message: message
+    }
+
+    expect(data).to eq(expected_output.stringify_keys)
+  end
+end

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

+require 'spec_helper'
+
+describe Gitlab::SidekiqLogging::StructuredLogger do
+  describe '#call' do
+    let(:timestamp) { Time.new('2018-01-01 12:00:00').utc }
+    let(:job) do
+      {
+        "class" => "TestWorker",
+        "args" => [1234, 'hello'],
+        "retry" => false,
+        "queue" => "cronjob:test_queue",
+        "queue_namespace" => "cronjob",
+        "jid" => "da883554ee4fe414012f5f42",
+        "created_at" => timestamp.to_f,
+        "enqueued_at" => timestamp.to_f
+      }
+    end
+    let(:logger) { double() }
+    let(:start_payload) do
+      job.merge(
+        'message' => 'TestWorker JID-da883554ee4fe414012f5f42: start',
+        'job_status' => 'start',
+        'pid' => Process.pid,
+        'created_at' => timestamp.iso8601(3),
+        'enqueued_at' => timestamp.iso8601(3)
+      )
+    end
+    let(:end_payload) do
+      start_payload.merge(
+        'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
+        'job_status' => 'done',
+        'duration' => 0.0,
+        "completed_at" => timestamp.iso8601(3)
+      )
+    end
+    let(:exception_payload) do
+      end_payload.merge(
+        'message' => 'TestWorker JID-da883554ee4fe414012f5f42: fail: 0.0 sec',
+        'job_status' => 'fail',
+        'error' => ArgumentError,
+        'error_message' => 'some exception'
+      )
+    end
+
+    before do
+      allow(Sidekiq).to receive(:logger).and_return(logger)
+
+      allow(subject).to receive(:current_time).and_return(timestamp.to_f)
+    end
+
+    subject { described_class.new }
+
+    context 'with SIDEKIQ_LOG_ARGUMENTS enabled' do
+      before do
+        stub_env('SIDEKIQ_LOG_ARGUMENTS', '1')
+      end
+
+      it 'logs start and end of job' do
+        Timecop.freeze(timestamp) do
+          expect(logger).to receive(:info).with(start_payload).ordered
+          expect(logger).to receive(:info).with(end_payload).ordered
+          expect(subject).to receive(:log_job_start).and_call_original
+          expect(subject).to receive(:log_job_done).and_call_original
+
+          subject.call(job, 'test_queue') { }
+        end
+      end
+
+      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
+
+          expect do
+            subject.call(job, 'test_queue') do
+              raise ArgumentError, 'some exception'
+            end
+          end.to raise_error(ArgumentError)
+        end
+      end
+    end
+
+    context 'with SIDEKIQ_LOG_ARGUMENTS disabled' do
+      it 'logs start and end of job' do
+        Timecop.freeze(timestamp) do
+          start_payload.delete('args')
+
+          expect(logger).to receive(:info).with(start_payload).ordered
+          expect(logger).to receive(:info).with(end_payload).ordered
+          expect(subject).to receive(:log_job_start).and_call_original
+          expect(subject).to receive(:log_job_done).and_call_original
+
+          subject.call(job, 'test_queue') { }
+        end
+      end
+    end
+  end
+end