debian-mirror-gitlab/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

436 lines
15 KiB
Ruby
Raw Normal View History

2019-12-04 20:38:33 +05:30
# frozen_string_literal: true
2020-03-13 15:44:24 +05:30
require 'spec_helper'
2018-05-09 12:01:36 +05:30
2020-07-28 23:09:34 +05:30
RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
2021-03-11 19:13:27 +05:30
before do
# We disable a memory instrumentation feature
# as this requires a special patched Ruby
allow(Gitlab::Memory::Instrumentation).to receive(:available?) { false }
end
describe '#call', :request_store do
2021-04-29 21:17:54 +05:30
include_context 'structured_logger'
2018-05-09 12:01:36 +05:30
context 'with SIDEKIQ_LOG_ARGUMENTS enabled' do
before do
stub_env('SIDEKIQ_LOG_ARGUMENTS', '1')
end
it 'logs start and end of job' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2018-05-09 12:01:36 +05:30
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
2021-03-11 19:13:27 +05:30
call_subject(job, 'test_queue') { }
end
end
it 'logs real job wrapped by active job worker' do
wrapped_job = job.merge(
"class" => "ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper",
"wrapped" => "TestWorker"
)
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-03-11 19:13:27 +05:30
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
call_subject(wrapped_job, 'test_queue') { }
2018-05-09 12:01:36 +05:30
end
end
it 'logs an exception in job' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2018-05-09 12:01:36 +05:30
expect(logger).to receive(:info).with(start_payload)
2021-03-11 19:13:27 +05:30
expect(logger).to receive(:warn).with(include(exception_payload))
2018-05-09 12:01:36 +05:30
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
expect do
2021-03-11 19:13:27 +05:30
call_subject(job, 'test_queue') do
raise ArgumentError, 'Something went wrong'
2018-05-09 12:01:36 +05:30
end
end.to raise_error(ArgumentError)
end
end
2019-03-02 22:35:43 +05:30
2021-03-11 19:13:27 +05:30
it 'logs the root cause of an Sidekiq::JobRetry::Skip exception in the job' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-03-11 19:13:27 +05:30
expect(logger).to receive(:info).with(start_payload)
expect(logger).to receive(:warn).with(include(exception_payload))
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
expect do
call_subject(job, 'test_queue') do
raise ArgumentError, 'Something went wrong'
2021-06-08 01:23:25 +05:30
rescue StandardError
2021-03-11 19:13:27 +05:30
raise Sidekiq::JobRetry::Skip
end
end.to raise_error(Sidekiq::JobRetry::Skip)
end
end
it 'logs the root cause of an Sidekiq::JobRetry::Handled exception in the job' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-03-11 19:13:27 +05:30
expect(logger).to receive(:info).with(start_payload)
expect(logger).to receive(:warn).with(include(exception_payload))
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
expect do
call_subject(job, 'test_queue') do
raise ArgumentError, 'Something went wrong'
2021-06-08 01:23:25 +05:30
rescue StandardError
2021-03-11 19:13:27 +05:30
raise Sidekiq::JobRetry::Handled
end
end.to raise_error(Sidekiq::JobRetry::Handled)
end
end
it 'keeps Sidekiq::JobRetry::Handled exception if the cause does not exist' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-03-11 19:13:27 +05:30
expect(logger).to receive(:info).with(start_payload)
expect(logger).to receive(:warn).with(
include(
'message' => 'TestWorker JID-da883554ee4fe414012f5f42: fail: 0.0 sec',
'job_status' => 'fail',
'error_class' => 'Sidekiq::JobRetry::Skip',
'error_message' => 'Sidekiq::JobRetry::Skip'
)
)
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
expect do
call_subject(job, 'test_queue') do
raise Sidekiq::JobRetry::Skip
end
end.to raise_error(Sidekiq::JobRetry::Skip)
end
end
2020-04-08 14:13:33 +05:30
it 'does not modify the job' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2020-04-08 14:13:33 +05:30
job_copy = job.deep_dup
allow(logger).to receive(:info)
allow(subject).to receive(:log_job_start).and_call_original
allow(subject).to receive(:log_job_done).and_call_original
2021-03-11 19:13:27 +05:30
call_subject(job, 'test_queue') do
2020-04-08 14:13:33 +05:30
expect(job).to eq(job_copy)
end
end
end
2021-03-11 19:13:27 +05:30
it 'does not modify the wrapped job' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-03-11 19:13:27 +05:30
wrapped_job = job.merge(
"class" => "ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper",
"wrapped" => "TestWorker"
)
job_copy = wrapped_job.deep_dup
allow(logger).to receive(:info)
allow(subject).to receive(:log_job_start).and_call_original
allow(subject).to receive(:log_job_done).and_call_original
call_subject(wrapped_job, 'test_queue') do
expect(wrapped_job).to eq(job_copy)
end
end
end
2018-05-09 12:01:36 +05:30
end
context 'with SIDEKIQ_LOG_ARGUMENTS disabled' do
2021-01-29 00:20:46 +05:30
before do
stub_env('SIDEKIQ_LOG_ARGUMENTS', '0')
end
2019-03-02 22:35:43 +05:30
it 'logs start and end of job without args' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2019-03-02 22:35:43 +05:30
expect(logger).to receive(:info).with(start_payload.except('args')).ordered
expect(logger).to receive(:info).with(end_payload.except('args')).ordered
2018-05-09 12:01:36 +05:30
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
2021-03-11 19:13:27 +05:30
call_subject(job, 'test_queue') { }
2018-05-09 12:01:36 +05:30
end
end
2019-10-12 21:52:04 +05:30
it 'logs without created_at and enqueued_at fields' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2019-10-12 21:52:04 +05:30
excluded_fields = %w(created_at enqueued_at args scheduling_latency_s)
expect(logger).to receive(:info).with(start_payload.except(*excluded_fields)).ordered
expect(logger).to receive(:info).with(end_payload.except(*excluded_fields)).ordered
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
2021-03-11 19:13:27 +05:30
call_subject(job.except("created_at", "enqueued_at"), 'test_queue') { }
2019-10-12 21:52:04 +05:30
end
end
end
context 'with latency' do
2020-03-13 15:44:24 +05:30
let(:created_at) { Time.iso8601('2018-01-01T10:00:00.000Z') }
2019-10-12 21:52:04 +05:30
let(:scheduling_latency_s) { 7200.0 }
it 'logs with scheduling latency' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-01-29 00:20:46 +05:30
expect(logger).to receive(:info).with(start_payload).ordered
expect(logger).to receive(:info).with(end_payload).ordered
2019-10-12 21:52:04 +05:30
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
2021-03-11 19:13:27 +05:30
call_subject(job, 'test_queue') { }
2019-10-12 21:52:04 +05:30
end
end
end
2021-11-18 22:05:49 +05:30
context 'with enqueue latency' do
let(:expected_start_payload) do
start_payload.merge(
'scheduled_at' => job['scheduled_at'],
'enqueue_latency_s' => 1.hour.to_f
)
end
let(:expected_end_payload) do
end_payload.merge('enqueue_latency_s' => 1.hour.to_f)
end
before do
# enqueued_at is set to created_at
job['scheduled_at'] = created_at - 1.hour
end
it 'logs with scheduling latency' do
travel_to(timestamp) do
expect(logger).to receive(:info).with(expected_start_payload).ordered
expect(logger).to receive(:info).with(expected_end_payload).ordered
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
call_subject(job, 'test_queue') { }
end
end
end
2020-04-22 19:07:51 +05:30
context 'with Gitaly, Rugged, and Redis calls' do
2019-10-12 21:52:04 +05:30
let(:timing_data) do
{
gitaly_calls: 10,
2020-04-22 19:07:51 +05:30
gitaly_duration_s: 10000,
2019-10-12 21:52:04 +05:30
rugged_calls: 1,
2020-04-22 19:07:51 +05:30
rugged_duration_s: 5000,
redis_calls: 3,
redis_duration_s: 1234
2019-10-12 21:52:04 +05:30
}
end
2020-04-22 19:07:51 +05:30
let(:expected_end_payload) do
2021-03-11 19:13:27 +05:30
end_payload.merge(timing_data.stringify_keys)
2019-10-12 21:52:04 +05:30
end
2021-04-29 21:17:54 +05:30
before do
allow(::Gitlab::InstrumentationHelper).to receive(:add_instrumentation_data).and_wrap_original do |method, values|
method.call(values)
values.merge!(timing_data)
end
end
it 'logs with Gitaly and Rugged timing data', :aggregate_failures do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-01-29 00:20:46 +05:30
expect(logger).to receive(:info).with(start_payload).ordered
2020-04-22 19:07:51 +05:30
expect(logger).to receive(:info).with(expected_end_payload).ordered
2019-10-12 21:52:04 +05:30
2021-04-29 21:17:54 +05:30
call_subject(job, 'test_queue') { }
2019-10-12 21:52:04 +05:30
end
end
2018-05-09 12:01:36 +05:30
end
2020-03-13 15:44:24 +05:30
context 'when the job performs database queries' do
before do
allow(Time).to receive(:now).and_return(timestamp)
allow(Process).to receive(:clock_gettime).and_call_original
end
2021-01-29 00:20:46 +05:30
let(:expected_start_payload) { start_payload }
2020-03-13 15:44:24 +05:30
let(:expected_end_payload) do
2021-01-29 00:20:46 +05:30
end_payload.merge('cpu_s' => a_value >= 0)
2020-03-13 15:44:24 +05:30
end
let(:expected_end_payload_with_db) do
expected_end_payload.merge(
2020-06-23 00:09:42 +05:30
'db_duration_s' => a_value >= 0.1,
2021-03-11 19:13:27 +05:30
'db_count' => a_value >= 1,
2022-01-26 12:08:38 +05:30
"db_#{db_config_name}_replica_count" => 0,
2021-11-18 22:05:49 +05:30
'db_replica_duration_s' => a_value >= 0,
'db_primary_count' => a_value >= 1,
2022-01-26 12:08:38 +05:30
"db_#{db_config_name}_count" => a_value >= 1,
2021-11-18 22:05:49 +05:30
'db_primary_duration_s' => a_value > 0,
2022-01-26 12:08:38 +05:30
"db_#{db_config_name}_duration_s" => a_value > 0
2021-11-18 22:05:49 +05:30
)
end
let(:end_payload) do
start_payload.merge(db_payload_defaults).merge(
'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
'job_status' => 'done',
'duration_s' => 0.0,
'completed_at' => timestamp.to_f,
'cpu_s' => 1.111112
2020-03-13 15:44:24 +05:30
)
end
2021-09-04 01:27:46 +05:30
shared_examples 'performs database queries' do
it 'logs the database time', :aggregate_errors do
expect(logger).to receive(:info).with(expected_start_payload).ordered
expect(logger).to receive(:info).with(expected_end_payload_with_db).ordered
2020-03-13 15:44:24 +05:30
2021-09-04 01:27:46 +05:30
call_subject(job, 'test_queue') do
2021-10-27 15:23:28 +05:30
ApplicationRecord.connection.execute('SELECT pg_sleep(0.1);')
2021-09-04 01:27:46 +05:30
end
end
it 'prevents database time from leaking to the next job', :aggregate_errors do
expect(logger).to receive(:info).with(expected_start_payload).ordered
expect(logger).to receive(:info).with(expected_end_payload_with_db).ordered
expect(logger).to receive(:info).with(expected_start_payload).ordered
expect(logger).to receive(:info).with(expected_end_payload).ordered
call_subject(job.dup, 'test_queue') do
2021-10-27 15:23:28 +05:30
ApplicationRecord.connection.execute('SELECT pg_sleep(0.1);')
2021-09-04 01:27:46 +05:30
end
Gitlab::SafeRequestStore.clear!
call_subject(job.dup, 'test_queue') { }
2021-03-11 19:13:27 +05:30
end
2020-03-13 15:44:24 +05:30
end
2021-11-18 22:05:49 +05:30
context 'when load balancing is enabled' do
let(:db_config_name) do
::Gitlab::Database.db_config_name(ApplicationRecord.retrieve_connection)
2021-09-04 01:27:46 +05:30
end
include_examples 'performs database queries'
end
end
context 'when the job uses load balancing capabilities' do
2021-09-30 23:02:18 +05:30
let(:expected_payload) { { 'load_balancing_strategy' => 'retry' } }
2021-09-04 01:27:46 +05:30
before do
allow(Time).to receive(:now).and_return(timestamp)
allow(Process).to receive(:clock_gettime).and_call_original
end
it 'logs the database chosen' do
expect(logger).to receive(:info).with(start_payload).ordered
expect(logger).to receive(:info).with(include(expected_payload)).ordered
2021-03-11 19:13:27 +05:30
2021-09-04 01:27:46 +05:30
call_subject(job, 'test_queue') do
2021-09-30 23:02:18 +05:30
job['load_balancing_strategy'] = 'retry'
2021-09-04 01:27:46 +05:30
end
2020-03-13 15:44:24 +05:30
end
end
2020-05-24 23:13:21 +05:30
context 'when there is extra metadata set for the done log' do
2021-01-29 00:20:46 +05:30
let(:expected_start_payload) { start_payload }
2020-05-24 23:13:21 +05:30
let(:expected_end_payload) do
2021-01-29 00:20:46 +05:30
end_payload.merge("#{ApplicationWorker::LOGGING_EXTRA_KEY}.key1" => 15, "#{ApplicationWorker::LOGGING_EXTRA_KEY}.key2" => 16)
2020-05-24 23:13:21 +05:30
end
it 'logs it in the done log' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2020-05-24 23:13:21 +05:30
expect(logger).to receive(:info).with(expected_start_payload).ordered
expect(logger).to receive(:info).with(expected_end_payload).ordered
2021-03-11 19:13:27 +05:30
call_subject(job, 'test_queue') do
2020-05-24 23:13:21 +05:30
job["#{ApplicationWorker::LOGGING_EXTRA_KEY}.key1"] = 15
job["#{ApplicationWorker::LOGGING_EXTRA_KEY}.key2"] = 16
job['key that will be ignored because it does not start with extra.'] = 17
end
end
end
end
2021-06-08 01:23:25 +05:30
context 'when instrumentation data is not loaded' do
before do
allow(logger).to receive(:info)
end
it 'does not raise exception' do
expect { subject.call(job.dup, 'test_queue') {} }.not_to raise_error
end
end
2021-09-04 01:27:46 +05:30
context 'when the job payload is compressed' do
let(:compressed_args) { "eJyLVspIzcnJV4oFAA88AxE=" }
let(:expected_start_payload) do
start_payload.merge(
'args' => ['[COMPRESSED]'],
'job_size_bytes' => Sidekiq.dump_json([compressed_args]).bytesize,
'compressed' => true
)
end
let(:expected_end_payload) do
end_payload.merge(
'args' => ['[COMPRESSED]'],
'job_size_bytes' => Sidekiq.dump_json([compressed_args]).bytesize,
'compressed' => true
)
end
it 'logs it in the done log' do
2021-11-18 22:05:49 +05:30
travel_to(timestamp) do
2021-09-04 01:27:46 +05:30
expect(logger).to receive(:info).with(expected_start_payload).ordered
expect(logger).to receive(:info).with(expected_end_payload).ordered
job['args'] = [compressed_args]
job['compressed'] = true
call_subject(job, 'test_queue') do
::Gitlab::SidekiqMiddleware::SizeLimiter::Compressor.decompress(job)
end
end
end
end
2019-12-21 20:55:43 +05:30
end
2019-12-04 20:38:33 +05:30
2019-12-21 20:55:43 +05:30
describe '#add_time_keys!' do
2021-03-11 19:13:27 +05:30
let(:time) { { duration: 0.1231234 } }
2019-12-21 20:55:43 +05:30
let(:payload) { { 'class' => 'my-class', 'message' => 'my-message', 'job_status' => 'my-job-status' } }
2020-03-13 15:44:24 +05:30
let(:current_utc_time) { Time.now.utc }
2021-03-11 19:13:27 +05:30
let(:payload_with_time_keys) do
{ 'class' => 'my-class',
'message' => 'my-message',
'job_status' => 'my-job-status',
'duration_s' => 0.123123,
2021-11-18 22:05:49 +05:30
'completed_at' => current_utc_time.to_i }
2021-03-11 19:13:27 +05:30
end
2019-12-04 20:38:33 +05:30
2019-12-21 20:55:43 +05:30
subject { described_class.new }
2019-12-04 20:38:33 +05:30
2019-12-21 20:55:43 +05:30
it 'update payload correctly' do
2021-11-18 22:05:49 +05:30
travel_to(current_utc_time) do
2020-03-13 15:44:24 +05:30
subject.send(:add_time_keys!, time, payload)
2019-12-04 20:38:33 +05:30
2020-03-13 15:44:24 +05:30
expect(payload).to eq(payload_with_time_keys)
end
2019-12-04 20:38:33 +05:30
end
2018-05-09 12:01:36 +05:30
end
end