From 6415ac9e994640474eaa5b0fee3914934d85b35b Mon Sep 17 00:00:00 2001 From: Stan Hu Date: Sun, 1 Apr 2018 00:46:52 -0700 Subject: [PATCH] Add support for Sidekiq JSON logging Closes #20060 --- .../unreleased/sh-gitlab-sidekiq-logger.yml | 5 + config/gitlab.yml.example | 4 + config/initializers/1_settings.rb | 6 ++ config/initializers/sidekiq.rb | 9 +- doc/administration/logs.md | 22 ++++ lib/gitlab/sidekiq_logging/json_formatter.rb | 21 ++++ .../sidekiq_logging/structured_logger.rb | 96 +++++++++++++++++ .../sidekiq_logging/json_formatter_spec.rb | 31 ++++++ .../sidekiq_logging/structured_logger_spec.rb | 101 ++++++++++++++++++ 9 files changed, 294 insertions(+), 1 deletion(-) create mode 100644 changelogs/unreleased/sh-gitlab-sidekiq-logger.yml create mode 100644 lib/gitlab/sidekiq_logging/json_formatter.rb create mode 100644 lib/gitlab/sidekiq_logging/structured_logger.rb create mode 100644 spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb create mode 100644 spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb diff --git a/changelogs/unreleased/sh-gitlab-sidekiq-logger.yml b/changelogs/unreleased/sh-gitlab-sidekiq-logger.yml new file mode 100644 index 00000000000..f68d45d2f38 --- /dev/null +++ b/changelogs/unreleased/sh-gitlab-sidekiq-logger.yml @@ -0,0 +1,5 @@ +--- +title: Add support for Sidekiq JSON logging +merge_request: +author: +type: added diff --git a/config/gitlab.yml.example b/config/gitlab.yml.example index 8db66037d61..126a9b8b803 100644 --- a/config/gitlab.yml.example +++ b/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 diff --git a/config/initializers/1_settings.rb b/config/initializers/1_settings.rb index 69b59b26d8c..187e70868ea 100644 --- a/config/initializers/1_settings.rb +++ b/config/initializers/1_settings.rb @@ -453,6 +453,12 @@ Settings.cron_jobs['pages_domain_verification_cron_worker'] ||= Settingslogic.ne 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 # diff --git a/config/initializers/sidekiq.rb b/config/initializers/sidekiq.rb index 161fb185c9b..f6803eb0b5a 100644 --- a/config/initializers/sidekiq.rb +++ b/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 diff --git a/doc/administration/logs.md b/doc/administration/logs.md index cd107a5b39c..c8a3ef80e8f 100644 --- a/doc/administration/logs.md +++ b/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 diff --git a/lib/gitlab/sidekiq_logging/json_formatter.rb b/lib/gitlab/sidekiq_logging/json_formatter.rb new file mode 100644 index 00000000000..98f8222fd03 --- /dev/null +++ b/lib/gitlab/sidekiq_logging/json_formatter.rb @@ -0,0 +1,21 @@ +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 diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb new file mode 100644 index 00000000000..9a89ae70b98 --- /dev/null +++ b/lib/gitlab/sidekiq_logging/structured_logger.rb @@ -0,0 +1,96 @@ +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 diff --git a/spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb b/spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb new file mode 100644 index 00000000000..fed9aeba30c --- /dev/null +++ b/spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb @@ -0,0 +1,31 @@ +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 diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb new file mode 100644 index 00000000000..2421b1e5a1a --- /dev/null +++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb @@ -0,0 +1,101 @@ +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