Commit 39c1731a authored by Kamil Trzciński's avatar Kamil Trzciński

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

The Correlation ID is taken or generated from received X-Request-ID.
Then it is being passed to all executed services (sidekiq workers
or gitaly calls).

The Correlation ID is logged in all structured logs as `correlation_id`.
parent cfe48479
......@@ -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
......@@ -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
......
# frozen_string_literal: true
module SentryHelper
def sentry_enabled?
Gitlab::Sentry.enabled?
end
def sentry_context
Gitlab::Sentry.context(current_user)
end
end
---
title: Log and pass correlation-id between Unicorn, Sidekiq and Gitaly
merge_request:
author:
type: added
# frozen_string_literal: true
Rails.application.config.middleware.use(Gitlab::Middleware::CorrelationId)
......@@ -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
......
......@@ -24,4 +24,4 @@ def configure_sentry
end
end
configure_sentry if Rails.env.production?
configure_sentry if Rails.env.production? || Rails.env.development?
......@@ -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
......@@ -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
......
......@@ -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
......
# 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
......@@ -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)
......
# 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
......@@ -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
......
# 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
......@@ -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
......
# 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
# 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
......@@ -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: {})
......
# 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
# 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
......@@ -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
......@@ -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,
......
......@@ -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() }
......
# 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
# 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
......@@ -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
......
......@@ -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,11 +247,14 @@ 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: {})
Gitlab::CorrelationId.use_id('new-correlation-id') do
handle_api_exception(exception)
end
end
context 'with a personal access token given' do
let(:token) { create(:personal_access_token, scopes: ['api'], user: user) }
......@@ -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'
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment