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

app/controllers/application_controller.rb

@@ -8,7 +8,6 @@ class ApplicationController < ActionController::Base
   include GitlabRoutingHelper
   include PageLayoutHelper
   include SafeParamsHelper
-  include SentryHelper
   include WorkhorseHelper
   include EnforcesTwoFactorAuthentication
   include WithPerformanceBar
@@ -129,6 +128,7 @@ class ApplicationController < ActionController::Base
 
     payload[:ua] = request.env["HTTP_USER_AGENT"]
     payload[:remote_ip] = request.remote_ip
+    payload[Gitlab::CorrelationId::LOG_KEY] = Gitlab::CorrelationId.current_id
 
     logged_user = auth_user
 
@@ -155,7 +155,7 @@ class ApplicationController < ActionController::Base
   end
 
   def log_exception(exception)
-    Raven.capture_exception(exception) if sentry_enabled?
+    Gitlab::Sentry.track_acceptable_exception(exception)
 
     backtrace_cleaner = Gitlab.rails5? ? request.env["action_dispatch.backtrace_cleaner"] : env
     application_trace = ActionDispatch::ExceptionWrapper.new(backtrace_cleaner, exception).application_trace
@@ -487,4 +487,8 @@ class ApplicationController < ActionController::Base
   def impersonator
     @impersonator ||= User.find(session[:impersonator_id]) if session[:impersonator_id]
   end
+
+  def sentry_context
+    Gitlab::Sentry.context(current_user)
+  end
 end

app/helpers/icons_helper.rb

@@ -42,7 +42,7 @@ module IconsHelper
   end
 
   def sprite_icon(icon_name, size: nil, css_class: nil)
-    if Gitlab::Sentry.should_raise?
+    if Gitlab::Sentry.should_raise_for_dev?
       unless known_sprites.include?(icon_name)
         exception = ArgumentError.new("#{icon_name} is not a known icon in @gitlab-org/gitlab-svg")
         raise exception

app/helpers/sentry_helper.rb

-# frozen_string_literal: true
-
-module SentryHelper
-  def sentry_enabled?
-    Gitlab::Sentry.enabled?
-  end
-
-  def sentry_context
-    Gitlab::Sentry.context(current_user)
-  end
-end

changelogs/unreleased/store-correlation-logs.yml

+---
+title: Log and pass correlation-id between Unicorn, Sidekiq and Gitaly
+merge_request:
+author:
+type: added

config/initializers/correlation_id.rb

+# frozen_string_literal: true
+
+Rails.application.config.middleware.use(Gitlab::Middleware::CorrelationId)

config/initializers/lograge.rb

@@ -29,6 +29,7 @@ unless Sidekiq.server?
       gitaly_calls = Gitlab::GitalyClient.get_request_count
       payload[:gitaly_calls] = gitaly_calls if gitaly_calls > 0
       payload[:response] = event.payload[:response] if event.payload[:response]
+      payload[Gitlab::CorrelationId::LOG_KEY] = Gitlab::CorrelationId.current_id
 
       payload
     end

config/initializers/sentry.rb

@@ -24,4 +24,4 @@ def configure_sentry
   end
 end
 
-configure_sentry if Rails.env.production?
+configure_sentry if Rails.env.production? || Rails.env.development?

config/initializers/sidekiq.rb

@@ -21,6 +21,7 @@ Sidekiq.configure_server do |config|
     chain.add Gitlab::SidekiqMiddleware::Shutdown
     chain.add Gitlab::SidekiqMiddleware::RequestStoreMiddleware unless ENV['SIDEKIQ_REQUEST_STORE'] == '0'
     chain.add Gitlab::SidekiqMiddleware::BatchLoader
+    chain.add Gitlab::SidekiqMiddleware::CorrelationLogger
     chain.add Gitlab::SidekiqStatus::ServerMiddleware
   end
 
@@ -31,6 +32,7 @@ Sidekiq.configure_server do |config|
 
   config.client_middleware do |chain|
     chain.add Gitlab::SidekiqStatus::ClientMiddleware
+    chain.add Gitlab::SidekiqMiddleware::CorrelationInjector
   end
 
   config.on :startup do
@@ -75,6 +77,7 @@ Sidekiq.configure_client do |config|
   config.redis = queues_config_hash
 
   config.client_middleware do |chain|
+    chain.add Gitlab::SidekiqMiddleware::CorrelationInjector
     chain.add Gitlab::SidekiqStatus::ClientMiddleware
   end
 end

lib/api/api.rb

@@ -20,7 +20,8 @@ module API
                     Gitlab::GrapeLogging::Loggers::RouteLogger.new,
                     Gitlab::GrapeLogging::Loggers::UserLogger.new,
                     Gitlab::GrapeLogging::Loggers::QueueDurationLogger.new,
-                    Gitlab::GrapeLogging::Loggers::PerfLogger.new
+                    Gitlab::GrapeLogging::Loggers::PerfLogger.new,
+                    Gitlab::GrapeLogging::Loggers::CorrelationIdLogger.new
                   ]
 
     allow_access_with_scope :api
@@ -84,7 +85,6 @@ module API
     content_type :txt, "text/plain"
 
     # Ensure the namespace is right, otherwise we might load Grape::API::Helpers
-    helpers ::SentryHelper
     helpers ::API::Helpers
     helpers ::API::Helpers::CommonHelpers
 

lib/api/helpers.rb

@@ -368,10 +368,10 @@ module API
     end
 
     def handle_api_exception(exception)
-      if sentry_enabled? && report_exception?(exception)
+      if report_exception?(exception)
         define_params_for_grape_middleware
-        sentry_context
-        Raven.capture_exception(exception, extra: params)
+        Gitlab::Sentry.context(current_user)
+        Gitlab::Sentry.track_acceptable_exception(exception, extra: params)
       end
 
       # lifted from https://github.com/rails/rails/blob/master/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb#L60

lib/gitlab/correlation_id.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module CorrelationId
+    LOG_KEY = 'correlation_id'.freeze
+
+    class << self
+      def use_id(correlation_id, &blk)
+        # always generate a id if null is passed
+        correlation_id ||= new_id
+
+        ids.push(correlation_id || new_id)
+
+        begin
+          yield(current_id)
+        ensure
+          ids.pop
+        end
+      end
+
+      def current_id
+        ids.last
+      end
+
+      def current_or_new_id
+        current_id || new_id
+      end
+
+      private
+
+      def ids
+        Thread.current[:correlation_id] ||= []
+      end
+
+      def new_id
+        SecureRandom.uuid
+      end
+    end
+  end
+end

lib/gitlab/gitaly_client.rb

@@ -193,6 +193,7 @@ module Gitlab
       feature = feature_stack && feature_stack[0]
       metadata['call_site'] = feature.to_s if feature
       metadata['gitaly-servers'] = address_metadata(remote_storage) if remote_storage
+      metadata['correlation_id'] = Gitlab::CorrelationId.current_id if Gitlab::CorrelationId.current_id
 
       metadata.merge!(server_feature_flags)
 

lib/gitlab/grape_logging/loggers/correlation_id_logger.rb

+# frozen_string_literal: true
+
+# This module adds additional correlation id the grape logger
+module Gitlab
+  module GrapeLogging
+    module Loggers
+      class CorrelationIdLogger < ::GrapeLogging::Loggers::Base
+        def parameters(_, _)
+          { Gitlab::CorrelationId::LOG_KEY => Gitlab::CorrelationId.current_id }
+        end
+      end
+    end
+  end
+end

lib/gitlab/json_logger.rb

@@ -10,6 +10,7 @@ module Gitlab
       data = {}
       data[:severity] = severity
       data[:time] = timestamp.utc.iso8601(3)
+      data[Gitlab::CorrelationId::LOG_KEY] = Gitlab::CorrelationId.current_id
 
       case message
       when String

lib/gitlab/middleware/correlation_id.rb

+# frozen_string_literal: true
+
+# A dumb middleware that steals correlation id
+# and sets it as a global context for the request
+module Gitlab
+  module Middleware
+    class CorrelationId
+      include ActionView::Helpers::TagHelper
+
+      def initialize(app)
+        @app = app
+      end
+
+      def call(env)
+        ::Gitlab::CorrelationId.use_id(correlation_id(env)) do
+          @app.call(env)
+        end
+      end
+
+      private
+
+      def correlation_id(env)
+        if Gitlab.rails5?
+          request(env).request_id
+        else
+          request(env).uuid
+        end
+      end
+
+      def request(env)
+        ActionDispatch::Request.new(env)
+      end
+    end
+  end
+end

lib/gitlab/sentry.rb

@@ -3,7 +3,8 @@
 module Gitlab
   module Sentry
     def self.enabled?
-      Rails.env.production? && Gitlab::CurrentSettings.sentry_enabled?
+      (Rails.env.production? || Rails.env.development?) &&
+        Gitlab::CurrentSettings.sentry_enabled?
     end
 
     def self.context(current_user = nil)
@@ -31,7 +32,7 @@ module Gitlab
     def self.track_exception(exception, issue_url: nil, extra: {})
       track_acceptable_exception(exception, issue_url: issue_url, extra: extra)
 
-      raise exception if should_raise?
+      raise exception if should_raise_for_dev?
     end
 
     # This should be used when you do not want to raise an exception in
@@ -43,7 +44,11 @@ module Gitlab
         extra[:issue_url] = issue_url if issue_url
         context # Make sure we've set everything we know in the context
 
-        Raven.capture_exception(exception, extra: extra)
+        tags = {
+          Gitlab::CorrelationId::LOG_KEY.to_sym => Gitlab::CorrelationId.current_id
+        }
+
+        Raven.capture_exception(exception, tags: tags, extra: extra)
       end
     end
 
@@ -55,7 +60,7 @@ module Gitlab
       end
     end
 
-    def self.should_raise?
+    def self.should_raise_for_dev?
       Rails.env.development? || Rails.env.test?
     end
   end

lib/gitlab/sidekiq_middleware/correlation_injector.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module SidekiqMiddleware
+    class CorrelationInjector
+      def call(worker_class, job, queue, redis_pool)
+        job[Gitlab::CorrelationId::LOG_KEY] ||=
+          Gitlab::CorrelationId.current_or_new_id
+
+        yield
+      end
+    end
+  end
+end

lib/gitlab/sidekiq_middleware/correlation_logger.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module SidekiqMiddleware
+    class CorrelationLogger
+      def call(worker, job, queue)
+        correlation_id = job[Gitlab::CorrelationId::LOG_KEY]
+
+        Gitlab::CorrelationId.use_id(correlation_id) do
+          yield
+        end
+      end
+    end
+  end
+end

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: {})

spec/initializers/lograge_spec.rb

+# 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

spec/lib/gitlab/correlation_id_spec.rb

+# 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

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

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,

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() }

spec/lib/gitlab/sidekiq_middleware/correlation_injector_spec.rb

+# 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

spec/lib/gitlab/sidekiq_middleware/correlation_logger_spec.rb

+# 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

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

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'