diff options
author | Stan Hu <stanhu@gmail.com> | 2018-04-01 10:46:52 +0300 |
---|---|---|
committer | Stan Hu <stanhu@gmail.com> | 2018-04-04 15:04:00 +0300 |
commit | 6415ac9e994640474eaa5b0fee3914934d85b35b (patch) | |
tree | 2640006fbc3745039799bb76bf8a654f5ce592c0 /spec/lib/gitlab/sidekiq_logging | |
parent | eaed588bf228c833cb666a61bc7d25cf21d5f94b (diff) |
Add support for Sidekiq JSON logging
Closes #20060
Diffstat (limited to 'spec/lib/gitlab/sidekiq_logging')
-rw-r--r-- | spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb | 31 | ||||
-rw-r--r-- | spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb | 101 |
2 files changed, 132 insertions, 0 deletions
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 |