2018-12-05 15:54:40 -05:00
|
|
|
# frozen_string_literal: true
|
|
|
|
|
|
|
|
require 'spec_helper'
|
|
|
|
|
2020-06-24 05:08:32 -04:00
|
|
|
RSpec.describe 'lograge', type: :request do
|
2018-12-05 15:54:40 -05:00
|
|
|
let(:headers) { { 'X-Request-ID' => 'new-correlation-id' } }
|
|
|
|
|
2020-02-14 19:08:48 -05:00
|
|
|
let(:large_params) do
|
|
|
|
half_limit = Gitlab::Utils::LogLimitedArray::MAXIMUM_ARRAY_LENGTH / 2
|
|
|
|
|
|
|
|
{
|
|
|
|
a: 'a',
|
|
|
|
b: 'b' * half_limit,
|
|
|
|
c: 'c' * half_limit,
|
|
|
|
d: 'd'
|
|
|
|
}
|
|
|
|
end
|
|
|
|
|
|
|
|
let(:limited_params) do
|
2020-02-19 10:09:09 -05:00
|
|
|
large_params.slice(:a, :b).map { |k, v| { key: k.to_s, value: v } } + [{ key: 'truncated', value: '...' }]
|
2020-02-14 19:08:48 -05:00
|
|
|
end
|
2018-12-05 15:54:40 -05:00
|
|
|
|
2020-02-14 19:08:48 -05:00
|
|
|
context 'for API requests' do
|
2018-12-05 15:54:40 -05:00
|
|
|
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)
|
2018-12-06 15:46:31 -05:00
|
|
|
.with(anything, anything, anything, a_hash_including("correlation_id" => "new-correlation-id"))
|
2018-12-05 15:54:40 -05:00
|
|
|
.and_call_original
|
|
|
|
|
2020-02-14 19:08:48 -05:00
|
|
|
get("/api/v4/endpoint", params: {}, headers: headers)
|
|
|
|
end
|
|
|
|
|
|
|
|
it 'limits param size' do
|
|
|
|
expect(Lograge.formatter).to receive(:call)
|
|
|
|
.with(a_hash_including(params: limited_params))
|
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
get("/api/v4/endpoint", params: large_params, headers: headers)
|
2018-12-05 15:54:40 -05:00
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
context 'for Controller requests' do
|
2018-12-17 17:52:17 -05:00
|
|
|
subject { get("/", params: {}, headers: headers) }
|
2018-12-05 15:54:40 -05:00
|
|
|
|
|
|
|
it 'logs to production_json log' do
|
|
|
|
# formatter receives a hash with correlation id
|
|
|
|
expect(Lograge.formatter).to receive(:call)
|
2018-12-06 15:46:31 -05:00
|
|
|
.with(a_hash_including("correlation_id" => "new-correlation-id"))
|
2018-12-05 15:54:40 -05:00
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
# a log file receives a line with correlation id
|
|
|
|
expect(Lograge.logger).to receive(:send)
|
2018-12-06 15:46:31 -05:00
|
|
|
.with(anything, include('"correlation_id":"new-correlation-id"'))
|
2018-12-05 15:54:40 -05:00
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
subject
|
|
|
|
end
|
2019-10-17 14:08:05 -04:00
|
|
|
|
|
|
|
it 'logs cpu_s on supported platform' do
|
|
|
|
allow(Gitlab::Metrics::System).to receive(:thread_cpu_time)
|
|
|
|
.and_return(
|
|
|
|
0.111222333,
|
|
|
|
0.222333833
|
|
|
|
)
|
|
|
|
|
|
|
|
expect(Lograge.formatter).to receive(:call)
|
2020-04-21 11:21:10 -04:00
|
|
|
.with(a_hash_including(cpu_s: 0.11))
|
2019-10-17 14:08:05 -04:00
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
expect(Lograge.logger).to receive(:send)
|
2020-04-21 11:21:10 -04:00
|
|
|
.with(anything, include('"cpu_s":0.11'))
|
2019-10-17 14:08:05 -04:00
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
subject
|
|
|
|
end
|
|
|
|
|
|
|
|
it 'does not log cpu_s on unsupported platform' do
|
|
|
|
allow(Gitlab::Metrics::System).to receive(:thread_cpu_time)
|
|
|
|
.and_return(nil)
|
|
|
|
|
|
|
|
expect(Lograge.formatter).to receive(:call)
|
|
|
|
.with(hash_not_including(:cpu_s))
|
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
expect(Lograge.logger).not_to receive(:send)
|
|
|
|
.with(anything, include('"cpu_s":'))
|
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
subject
|
|
|
|
end
|
2020-02-14 19:08:48 -05:00
|
|
|
|
|
|
|
it 'limits param size' do
|
|
|
|
expect(Lograge.formatter).to receive(:call)
|
|
|
|
.with(a_hash_including(params: limited_params))
|
|
|
|
.and_call_original
|
|
|
|
|
|
|
|
get("/", params: large_params, headers: headers)
|
|
|
|
end
|
2018-12-05 15:54:40 -05:00
|
|
|
end
|
2019-11-18 13:06:53 -05:00
|
|
|
|
|
|
|
context 'with a log subscriber' do
|
2020-06-23 02:08:52 -04:00
|
|
|
include_context 'parsed logs'
|
|
|
|
|
2020-06-01 14:08:07 -04:00
|
|
|
let(:subscriber) { Lograge::LogSubscribers::ActionController.new }
|
2019-11-18 13:06:53 -05:00
|
|
|
|
|
|
|
let(:event) do
|
|
|
|
ActiveSupport::Notifications::Event.new(
|
|
|
|
'process_action.action_controller',
|
|
|
|
Time.now,
|
|
|
|
Time.now,
|
|
|
|
2,
|
|
|
|
status: 200,
|
|
|
|
controller: 'HomeController',
|
|
|
|
action: 'index',
|
|
|
|
format: 'application/json',
|
|
|
|
method: 'GET',
|
|
|
|
path: '/home?foo=bar',
|
|
|
|
params: {},
|
|
|
|
db_runtime: 0.02,
|
|
|
|
view_runtime: 0.01
|
|
|
|
)
|
|
|
|
end
|
|
|
|
|
|
|
|
describe 'with an exception' do
|
|
|
|
let(:exception) { RuntimeError.new('bad request') }
|
|
|
|
let(:backtrace) { caller }
|
|
|
|
|
|
|
|
before do
|
|
|
|
allow(exception).to receive(:backtrace).and_return(backtrace)
|
|
|
|
event.payload[:exception_object] = exception
|
|
|
|
end
|
|
|
|
|
|
|
|
it 'adds exception data to log' do
|
|
|
|
subscriber.process_action(event)
|
|
|
|
|
2019-11-21 22:06:14 -05:00
|
|
|
expect(log_data['exception.class']).to eq('RuntimeError')
|
|
|
|
expect(log_data['exception.message']).to eq('bad request')
|
2019-12-27 10:08:16 -05:00
|
|
|
expect(log_data['exception.backtrace']).to eq(Gitlab::BacktraceCleaner.clean_backtrace(backtrace))
|
2019-11-18 13:06:53 -05:00
|
|
|
end
|
|
|
|
end
|
2020-01-23 19:08:51 -05:00
|
|
|
|
|
|
|
describe 'with etag_route' do
|
|
|
|
let(:etag_route) { 'etag route' }
|
|
|
|
|
|
|
|
before do
|
|
|
|
event.payload[:etag_route] = etag_route
|
|
|
|
end
|
|
|
|
|
|
|
|
it 'adds etag_route to log' do
|
|
|
|
subscriber.process_action(event)
|
|
|
|
|
|
|
|
expect(log_data['etag_route']).to eq(etag_route)
|
|
|
|
end
|
|
|
|
end
|
2020-06-25 14:08:50 -04:00
|
|
|
|
|
|
|
context 'with transaction' do
|
|
|
|
let(:transaction) { Gitlab::Metrics::WebTransaction.new({}) }
|
|
|
|
|
|
|
|
before do
|
|
|
|
allow(Gitlab::Metrics::Transaction).to receive(:current).and_return(transaction)
|
|
|
|
end
|
|
|
|
|
|
|
|
context 'when RequestStore is enabled', :request_store do
|
|
|
|
context 'with db payload' do
|
|
|
|
it 'includes db counters', :request_store do
|
|
|
|
ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
|
|
|
|
subscriber.process_action(event)
|
|
|
|
|
|
|
|
expect(log_data).to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0)
|
|
|
|
end
|
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
context 'when RequestStore is disabled' do
|
|
|
|
context 'with db payload' do
|
|
|
|
it 'does not include db counters' do
|
|
|
|
ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
|
|
|
|
subscriber.process_action(event)
|
|
|
|
|
|
|
|
expect(log_data).not_to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0)
|
|
|
|
end
|
|
|
|
end
|
|
|
|
end
|
|
|
|
end
|
2019-11-18 13:06:53 -05:00
|
|
|
end
|
2018-12-05 15:54:40 -05:00
|
|
|
end
|