Commit b15dd5df authored by Sean McGivern's avatar Sean McGivern

Merge branch 'sh-gitlab-sidekiq-logger' into 'master'

Add support for Sidekiq JSON logging

Closes #20060

See merge request gitlab-org/gitlab-ce!18121
parents 873a1d93 6415ac9e
---
title: Add support for Sidekiq JSON logging
merge_request:
author:
type: added
......@@ -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
......
......@@ -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
#
......
......@@ -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
......
......@@ -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
......
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
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
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
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
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment