Add latest changes from gitlab-org/gitlab@master

1 files changed, 42 insertions, 3 deletions

diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb
index 772b0168a2a..20adfe7091c 100644
--- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb
+++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb
@@ -1,6 +1,6 @@
 # frozen_string_literal: true
 
-require 'fast_spec_helper'
+require 'spec_helper'
 
 describe Gitlab::SidekiqLogging::StructuredLogger do
   describe '#call' do
@@ -40,8 +40,10 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
         'job_status' => 'done',
         'duration' => 0.0,
-        "completed_at" => timestamp.iso8601(3),
-        "cpu_s" => 1.111112
+        'completed_at' => timestamp.iso8601(3),
+        'cpu_s' => 1.111112,
+        'db_duration' => 0,
+        'db_duration_s' => 0
       )
     end
     let(:exception_payload) do
@@ -183,6 +185,43 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         end
       end
     end
+
+    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
+
+      let(:expected_start_payload) { start_payload.except('args') }
+
+      let(:expected_end_payload) do
+        end_payload.except('args').merge('cpu_s' => a_value > 0)
+      end
+
+      let(:expected_end_payload_with_db) do
+        expected_end_payload.merge(
+          'db_duration' => a_value >= 100,
+          'db_duration_s' => a_value >= 0.1
+        )
+      end
+
+      it 'logs the database time' do
+        expect(logger).to receive(:info).with(expected_start_payload).ordered
+        expect(logger).to receive(:info).with(expected_end_payload_with_db).ordered
+
+        subject.call(job, 'test_queue') { ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);') }
+      end
+
+      it 'prevents database time from leaking to the next job' 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
+
+        subject.call(job, 'test_queue') { ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);') }
+        subject.call(job, 'test_queue') { }
+      end
+    end
   end
 
   describe '#add_time_keys!' do