Merge branch 'store-correlation-logs' into 'master'

Log and pass correlation-id between Unicorn, Sidekiq and Gitaly

See merge request gitlab-org/gitlab-ce!22844

10 files changed, 246 insertions, 22 deletions

diff --git a/spec/controllers/application_controller_spec.rb b/spec/controllers/application_controller_spec.rb
index ac92b2ca657..c2bd7fd9808 100644
--- a/spec/controllers/application_controller_spec.rb
+++ b/spec/controllers/application_controller_spec.rb
@@ -460,6 +460,14 @@ describe ApplicationController do
       expect(controller.last_payload.has_key?(:response)).to be_falsey
     end
 
+    it 'does log correlation id' do
+      Gitlab::CorrelationId.use_id('new-id') do
+        get :index
+      end
+
+      expect(controller.last_payload).to include('correlation_id' => 'new-id')
+    end
+
     context '422 errors' do
       it 'logs a response with a string' do
         response = spy(ActionDispatch::Response, status: 422, body: 'Hello world', content_type: 'application/json', cookies: {})
diff --git a/spec/initializers/lograge_spec.rb b/spec/initializers/lograge_spec.rb
new file mode 100644
index 00000000000..af54a777373
--- /dev/null
+++ b/spec/initializers/lograge_spec.rb
@@ -0,0 +1,38 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe 'lograge', type: :request do
+  let(:headers) { { 'X-Request-ID' => 'new-correlation-id' } }
+
+  context 'for API requests' do
+    subject { get("/api/v4/endpoint", {}, headers) }
+
+    it 'logs to api_json log' do
+      # we assert receiving parameters by grape logger
+      expect_any_instance_of(Gitlab::GrapeLogging::Formatters::LogrageWithTimestamp).to receive(:call)
+        .with(anything, anything, anything, a_hash_including("correlation_id" => "new-correlation-id"))
+        .and_call_original
+
+      subject
+    end
+  end
+
+  context 'for Controller requests' do
+    subject { get("/", {}, headers) }
+
+    it 'logs to production_json log' do
+      # formatter receives a hash with correlation id
+      expect(Lograge.formatter).to receive(:call)
+        .with(a_hash_including("correlation_id" => "new-correlation-id"))
+        .and_call_original
+
+      # a log file receives a line with correlation id
+      expect(Lograge.logger).to receive(:send)
+        .with(anything, include('"correlation_id":"new-correlation-id"'))
+        .and_call_original
+
+      subject
+    end
+  end
+end
diff --git a/spec/lib/gitlab/correlation_id_spec.rb b/spec/lib/gitlab/correlation_id_spec.rb
new file mode 100644
index 00000000000..584d1f48386
--- /dev/null
+++ b/spec/lib/gitlab/correlation_id_spec.rb
@@ -0,0 +1,77 @@
+# frozen_string_literal: true
+
+require 'fast_spec_helper'
+
+describe Gitlab::CorrelationId do
+  describe '.use_id' do
+    it 'yields when executed' do
+      expect { |blk| described_class.use_id('id', &blk) }.to yield_control
+    end
+
+    it 'stacks correlation ids' do
+      described_class.use_id('id1') do
+        described_class.use_id('id2') do |current_id|
+          expect(current_id).to eq('id2')
+        end
+      end
+    end
+
+    it 'for missing correlation id it generates random one' do
+      described_class.use_id('id1') do
+        described_class.use_id(nil) do |current_id|
+          expect(current_id).not_to be_empty
+          expect(current_id).not_to eq('id1')
+        end
+      end
+    end
+  end
+
+  describe '.current_id' do
+    subject { described_class.current_id }
+
+    it 'returns last correlation id' do
+      described_class.use_id('id1') do
+        described_class.use_id('id2') do
+          is_expected.to eq('id2')
+        end
+      end
+    end
+  end
+
+  describe '.current_or_new_id' do
+    subject { described_class.current_or_new_id }
+
+    context 'when correlation id is set' do
+      it 'returns last correlation id' do
+        described_class.use_id('id1') do
+          is_expected.to eq('id1')
+        end
+      end
+    end
+
+    context 'when correlation id is missing' do
+      it 'returns a new correlation id' do
+        expect(described_class).to receive(:new_id)
+          .and_call_original
+
+        is_expected.not_to be_empty
+      end
+    end
+  end
+
+  describe '.ids' do
+    subject { described_class.send(:ids) }
+
+    it 'returns empty list if not correlation is used' do
+      is_expected.to be_empty
+    end
+
+    it 'returns list if correlation ids are used' do
+      described_class.use_id('id1') do
+        described_class.use_id('id2') do
+          is_expected.to eq(%w(id1 id2))
+        end
+      end
+    end
+  end
+end
diff --git a/spec/lib/gitlab/json_logger_spec.rb b/spec/lib/gitlab/json_logger_spec.rb
index 0a62785f880..cff7dd58c8c 100644
--- a/spec/lib/gitlab/json_logger_spec.rb
+++ b/spec/lib/gitlab/json_logger_spec.rb
@@ -7,6 +7,10 @@ describe Gitlab::JsonLogger do
   let(:now) { Time.now }
 
   describe '#format_message' do
+    before do
+      allow(Gitlab::CorrelationId).to receive(:current_id).and_return('new-correlation-id')
+    end
+
     it 'formats strings' do
       output = subject.format_message('INFO', now, 'test', 'Hello world')
       data = JSON.parse(output)
@@ -14,6 +18,7 @@ describe Gitlab::JsonLogger do
       expect(data['severity']).to eq('INFO')
       expect(data['time']).to eq(now.utc.iso8601(3))
       expect(data['message']).to eq('Hello world')
+      expect(data['correlation_id']).to eq('new-correlation-id')
     end
 
     it 'formats hashes' do
@@ -24,6 +29,7 @@ describe Gitlab::JsonLogger do
       expect(data['time']).to eq(now.utc.iso8601(3))
       expect(data['hello']).to eq(1)
       expect(data['message']).to be_nil
+      expect(data['correlation_id']).to eq('new-correlation-id')
     end
   end
 end
diff --git a/spec/lib/gitlab/sentry_spec.rb b/spec/lib/gitlab/sentry_spec.rb
index d3b41b27b80..1128eaf8560 100644
--- a/spec/lib/gitlab/sentry_spec.rb
+++ b/spec/lib/gitlab/sentry_spec.rb
@@ -19,14 +19,15 @@ describe Gitlab::Sentry do
     end
 
     it 'raises the exception if it should' do
-      expect(described_class).to receive(:should_raise?).and_return(true)
+      expect(described_class).to receive(:should_raise_for_dev?).and_return(true)
       expect { described_class.track_exception(exception) }
         .to raise_error(RuntimeError)
     end
 
     context 'when exceptions should not be raised' do
       before do
-        allow(described_class).to receive(:should_raise?).and_return(false)
+        allow(described_class).to receive(:should_raise_for_dev?).and_return(false)
+        allow(Gitlab::CorrelationId).to receive(:current_id).and_return('cid')
       end
 
       it 'logs the exception with all attributes passed' do
@@ -35,8 +36,14 @@ describe Gitlab::Sentry do
           issue_url: 'http://gitlab.com/gitlab-org/gitlab-ce/issues/1'
         }
 
+        expected_tags = {
+          correlation_id: 'cid'
+        }
+
         expect(Raven).to receive(:capture_exception)
-                           .with(exception, extra: a_hash_including(expected_extras))
+                           .with(exception,
+                            tags: a_hash_including(expected_tags),
+                            extra: a_hash_including(expected_extras))
 
         described_class.track_exception(
           exception,
@@ -58,6 +65,7 @@ describe Gitlab::Sentry do
 
     before do
       allow(described_class).to receive(:enabled?).and_return(true)
+      allow(Gitlab::CorrelationId).to receive(:current_id).and_return('cid')
     end
 
     it 'calls Raven.capture_exception' do
@@ -66,8 +74,14 @@ describe Gitlab::Sentry do
         issue_url: 'http://gitlab.com/gitlab-org/gitlab-ce/issues/1'
       }
 
+      expected_tags = {
+        correlation_id: 'cid'
+      }
+
       expect(Raven).to receive(:capture_exception)
-                         .with(exception, extra: a_hash_including(expected_extras))
+                         .with(exception,
+                          tags: a_hash_including(expected_tags),
+                          extra: a_hash_including(expected_extras))
 
       described_class.track_acceptable_exception(
         exception,
diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb
index 2421b1e5a1a..f773f370ee2 100644
--- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb
+++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb
@@ -12,7 +12,8 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         "queue_namespace" => "cronjob",
         "jid" => "da883554ee4fe414012f5f42",
         "created_at" => timestamp.to_f,
-        "enqueued_at" => timestamp.to_f
+        "enqueued_at" => timestamp.to_f,
+        "correlation_id" => 'cid'
       }
     end
     let(:logger) { double() }
diff --git a/spec/lib/gitlab/sidekiq_middleware/correlation_injector_spec.rb b/spec/lib/gitlab/sidekiq_middleware/correlation_injector_spec.rb
new file mode 100644
index 00000000000..a138ad7c910
--- /dev/null
+++ b/spec/lib/gitlab/sidekiq_middleware/correlation_injector_spec.rb
@@ -0,0 +1,47 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::SidekiqMiddleware::CorrelationInjector do
+  class TestWorker
+    include ApplicationWorker
+  end
+
+  before do |example|
+    Sidekiq.client_middleware do |chain|
+      chain.add described_class
+    end
+  end
+
+  after do |example|
+    Sidekiq.client_middleware do |chain|
+      chain.remove described_class
+    end
+
+    Sidekiq::Queues.clear_all
+  end
+
+  around do |example|
+    Sidekiq::Testing.fake! do
+      example.run
+    end
+  end
+
+  it 'injects into payload the correlation id' do
+    expect_any_instance_of(described_class).to receive(:call).and_call_original
+
+    Gitlab::CorrelationId.use_id('new-correlation-id') do
+      TestWorker.perform_async(1234)
+    end
+
+    expected_job_params = {
+      "class" => "TestWorker",
+      "args" => [1234],
+      "correlation_id" => "new-correlation-id"
+    }
+
+    expect(Sidekiq::Queues.jobs_by_worker).to a_hash_including(
+      "TestWorker" => a_collection_containing_exactly(
+        a_hash_including(expected_job_params)))
+  end
+end
diff --git a/spec/lib/gitlab/sidekiq_middleware/correlation_logger_spec.rb b/spec/lib/gitlab/sidekiq_middleware/correlation_logger_spec.rb
new file mode 100644
index 00000000000..94ae4ffa184
--- /dev/null
+++ b/spec/lib/gitlab/sidekiq_middleware/correlation_logger_spec.rb
@@ -0,0 +1,35 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::SidekiqMiddleware::CorrelationLogger do
+  class TestWorker
+    include ApplicationWorker
+  end
+
+  before do |example|
+    Sidekiq::Testing.server_middleware do |chain|
+      chain.add described_class
+    end
+  end
+
+  after do |example|
+    Sidekiq::Testing.server_middleware do |chain|
+      chain.remove described_class
+    end
+  end
+
+  it 'injects into payload the correlation id' do
+    expect_any_instance_of(described_class).to receive(:call).and_call_original
+
+    expect_any_instance_of(TestWorker).to receive(:perform).with(1234) do
+      expect(Gitlab::CorrelationId.current_id).to eq('new-correlation-id')
+    end
+
+    Sidekiq::Client.push(
+      'queue' => 'test',
+      'class' => TestWorker,
+      'args' => [1234],
+      'correlation_id' => 'new-correlation-id')
+  end
+end
diff --git a/spec/models/namespace_spec.rb b/spec/models/namespace_spec.rb
index 96561dab1c9..18b54cce834 100644
--- a/spec/models/namespace_spec.rb
+++ b/spec/models/namespace_spec.rb
@@ -249,7 +249,7 @@ describe Namespace do
 
               move_dir_result
             end
-            expect(Gitlab::Sentry).to receive(:should_raise?).and_return(false) # like prod
+            expect(Gitlab::Sentry).to receive(:should_raise_for_dev?).and_return(false) # like prod
 
             namespace.update(path: namespace.full_path + '_new')
           end
diff --git a/spec/requests/api/helpers_spec.rb b/spec/requests/api/helpers_spec.rb
index 2c40e266f5f..f7916441313 100644
--- a/spec/requests/api/helpers_spec.rb
+++ b/spec/requests/api/helpers_spec.rb
@@ -5,7 +5,6 @@ require_relative '../../../config/initializers/sentry'
 describe API::Helpers do
   include API::APIGuard::HelperMethods
   include described_class
-  include SentryHelper
   include TermsHelper
 
   let(:user) { create(:user) }
@@ -224,8 +223,15 @@ describe API::Helpers do
 
   describe '.handle_api_exception' do
     before do
-      allow_any_instance_of(self.class).to receive(:sentry_enabled?).and_return(true)
       allow_any_instance_of(self.class).to receive(:rack_response)
+      allow(Gitlab::Sentry).to receive(:enabled?).and_return(true)
+
+      stub_application_setting(
+        sentry_enabled: true,
+        sentry_dsn: "dummy://12345:67890@sentry.localdomain/sentry/42"
+      )
+      configure_sentry
+      Raven.client.configuration.encoding = 'json'
     end
 
     it 'does not report a MethodNotAllowed exception to Sentry' do
@@ -241,10 +247,13 @@ describe API::Helpers do
       exception = RuntimeError.new('test error')
       allow(exception).to receive(:backtrace).and_return(caller)
 
-      expect_any_instance_of(self.class).to receive(:sentry_context)
-      expect(Raven).to receive(:capture_exception).with(exception, extra: {})
+      expect(Raven).to receive(:capture_exception).with(exception, tags: {
+        correlation_id: 'new-correlation-id'
+      }, extra: {})
 
-      handle_api_exception(exception)
+      Gitlab::CorrelationId.use_id('new-correlation-id') do
+        handle_api_exception(exception)
+      end
     end
 
     context 'with a personal access token given' do
@@ -255,7 +264,6 @@ describe API::Helpers do
         # We need to stub at a lower level than #sentry_enabled? otherwise
         # Sentry is not enabled when the request below is made, and the test
         # would pass even without the fix
-        expect(Gitlab::Sentry).to receive(:enabled?).twice.and_return(true)
         expect(ProjectsFinder).to receive(:new).and_raise('Runtime Error!')
 
         get api('/projects', personal_access_token: token)
@@ -272,17 +280,7 @@ describe API::Helpers do
       # Sentry events are an array of the form [auth_header, data, options]
       let(:event_data) { Raven.client.transport.events.first[1] }
 
-      before do
-        stub_application_setting(
-          sentry_enabled: true,
-          sentry_dsn: "dummy://12345:67890@sentry.localdomain/sentry/42"
-        )
-        configure_sentry
-        Raven.client.configuration.encoding = 'json'
-      end
-
       it 'sends the params, excluding confidential values' do
-        expect(Gitlab::Sentry).to receive(:enabled?).twice.and_return(true)
         expect(ProjectsFinder).to receive(:new).and_raise('Runtime Error!')
 
         get api('/projects', user), password: 'dont_send_this', other_param: 'send_this'