Adds Sidekiq scheduling latency structured logging field

changelogs/unreleased/an-sidekiq-scheduling_latency.yml

+---
+title: Adds Sidekiq scheduling latency structured logging field
+merge_request: 30784
+author:
+type: other

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -32,6 +32,12 @@ module Gitlab
         payload['message'] = "#{base_message(payload)}: start"
         payload['job_status'] = 'start'
+        # Old gitlab-shell messages don't provide enqueued_at/created_at attributes
+        enqueued_at = payload['enqueued_at'] || payload['created_at']
+        if enqueued_at
+          payload['scheduling_latency_s'] = elapsed(Time.iso8601(enqueued_at).to_f)
+        end
+
         payload
       end

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