diff options
Diffstat (limited to 'spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb')
-rw-r--r-- | spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb | 107 |
1 files changed, 101 insertions, 6 deletions
diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb index 7bc4599e20f..1b89c094a6b 100644 --- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb +++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb @@ -1,8 +1,13 @@ +# frozen_string_literal: true + require 'spec_helper' describe Gitlab::SidekiqLogging::StructuredLogger do describe '#call' do - let(:timestamp) { Time.new('2018-01-01 12:00:00').utc } + let(:timestamp) { Time.iso8601('2018-01-01T12:00:00Z') } + let(:created_at) { timestamp - 1.second } + let(:scheduling_latency_s) { 1.0 } + let(:job) do { "class" => "TestWorker", @@ -11,19 +16,21 @@ describe Gitlab::SidekiqLogging::StructuredLogger do "queue" => "cronjob:test_queue", "queue_namespace" => "cronjob", "jid" => "da883554ee4fe414012f5f42", - "created_at" => timestamp.to_f, - "enqueued_at" => timestamp.to_f, + "created_at" => created_at.to_f, + "enqueued_at" => created_at.to_f, "correlation_id" => 'cid' } 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) + 'created_at' => created_at.iso8601(3), + 'enqueued_at' => created_at.iso8601(3), + 'scheduling_latency_s' => scheduling_latency_s ) end let(:end_payload) do @@ -31,7 +38,9 @@ describe Gitlab::SidekiqLogging::StructuredLogger do 'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec', 'job_status' => 'done', 'duration' => 0.0, - "completed_at" => timestamp.iso8601(3) + "completed_at" => timestamp.iso8601(3), + "system_s" => 0.0, + "user_s" => 0.0 ) end let(:exception_payload) do @@ -47,6 +56,13 @@ describe Gitlab::SidekiqLogging::StructuredLogger do allow(Sidekiq).to receive(:logger).and_return(logger) allow(subject).to receive(:current_time).and_return(timestamp.to_f) + + allow(Process).to receive(:times).and_return( + stime: 0.0, + utime: 0.0, + cutime: 0.0, + cstime: 0.0 + ) end subject { described_class.new } @@ -118,6 +134,85 @@ describe Gitlab::SidekiqLogging::StructuredLogger do subject.call(job, 'test_queue') { } end end + + it 'logs without created_at and enqueued_at fields' do + Timecop.freeze(timestamp) do + 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 + + subject.call(job.except("created_at", "enqueued_at"), 'test_queue') { } + end + end + end + + context 'with latency' do + let(:created_at) { Time.iso8601('2018-01-01T10:00:00Z') } + let(:scheduling_latency_s) { 7200.0 } + + it 'logs with scheduling latency' do + Timecop.freeze(timestamp) do + expect(logger).to receive(:info).with(start_payload.except('args')).ordered + expect(logger).to receive(:info).with(end_payload.except('args')).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 + + context 'with Gitaly and Rugged calls' do + let(:timing_data) do + { + gitaly_calls: 10, + gitaly_duration: 10000, + rugged_calls: 1, + rugged_duration_ms: 5000 + } + end + + before do + job.merge!(timing_data) + end + + it 'logs with Gitaly and Rugged timing data' do + Timecop.freeze(timestamp) do + expect(logger).to receive(:info).with(start_payload.except('args')).ordered + expect(logger).to receive(:info).with(end_payload.except('args')).ordered + + subject.call(job, 'test_queue') { } + end + end + end + + def ctime(times) + times[:cstime] + times[:cutime] + end + + context 'with ctime value greater than 0' do + let(:times_start) { { stime: 0.04999, utime: 0.0483, cstime: 0.0188, cutime: 0.0188 } } + let(:times_end) { { stime: 0.0699, utime: 0.0699, cstime: 0.0399, cutime: 0.0399 } } + + before do + end_payload['system_s'] = 0.02 + end_payload['user_s'] = 0.022 + end_payload['child_s'] = 0.042 + + allow(Process).to receive(:times).and_return(times_start, times_end) + end + + it 'logs with ctime data and other cpu data' do + Timecop.freeze(timestamp) do + expect(logger).to receive(:info).with(start_payload.except('args')).ordered + expect(logger).to receive(:info).with(end_payload.except('args')).ordered + + subject.call(job, 'test_queue') { } + end + end end end end |