diff options
author | Andrew Newdigate <andrew@gitlab.com> | 2019-07-31 15:07:47 +0300 |
---|---|---|
committer | Kamil TrzciĆski <ayufan@ayufan.eu> | 2019-07-31 15:07:47 +0300 |
commit | ee828f09bfb063280695f8c3066e7906d5b13769 (patch) | |
tree | ecbb7e950c5fcde54f39934567972e648a8916e8 /spec/lib/gitlab/sidekiq_logging | |
parent | dbd1b0b1e3fe976847b3455a16e3809924c33067 (diff) |
Adds Sidekiq scheduling latency structured logging field
Diffstat (limited to 'spec/lib/gitlab/sidekiq_logging')
-rw-r--r-- | spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb | 44 |
1 files changed, 39 insertions, 5 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..98286eb432d 100644 --- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb +++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb @@ -2,7 +2,10 @@ 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 } + let(:scheduling_latency_s) { 0.0 } + let(:job) do { "class" => "TestWorker", @@ -11,19 +14,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 @@ -118,6 +123,35 @@ 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 end end |