Commit 6c041a61 authored by Craig Furman's avatar Craig Furman

Stringify sidekiq job args in logs

If these logs are sent to Elasticsearch, it will not be able to process
nested object fields, as this causes a type mismatch with scalar
elements in the same array across log lines.

This is a second attempt, as the first (reverted) one modified the
actual job object that was used by sidekiq.
parent 6b006eba
...@@ -85,7 +85,7 @@ module Gitlab ...@@ -85,7 +85,7 @@ module Gitlab
job['pid'] = ::Process.pid job['pid'] = ::Process.pid
job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS'] job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS']
job['args'] = Gitlab::Utils::LogLimitedArray.log_limited_array(job['args']) if job['args'] job['args'] = Gitlab::Utils::LogLimitedArray.log_limited_array(job['args'].map(&:to_s)) if job['args']
job job
end end
......
...@@ -11,7 +11,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do ...@@ -11,7 +11,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
let(:job) do let(:job) do
{ {
"class" => "TestWorker", "class" => "TestWorker",
"args" => [1234, 'hello'], "args" => [1234, 'hello', { 'key' => 'value' }],
"retry" => false, "retry" => false,
"queue" => "cronjob:test_queue", "queue" => "cronjob:test_queue",
"queue_namespace" => "cronjob", "queue_namespace" => "cronjob",
...@@ -30,6 +30,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do ...@@ -30,6 +30,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
let(:clock_thread_cputime_end) { 1.333333799 } let(:clock_thread_cputime_end) { 1.333333799 }
let(:start_payload) do let(:start_payload) do
job.except('error_backtrace', 'error_class', 'error_message').merge( job.except('error_backtrace', 'error_class', 'error_message').merge(
'args' => %w(1234 hello {"key"=>"value"}),
'message' => 'TestWorker JID-da883554ee4fe414012f5f42: start', 'message' => 'TestWorker JID-da883554ee4fe414012f5f42: start',
'job_status' => 'start', 'job_status' => 'start',
'pid' => Process.pid, 'pid' => Process.pid,
...@@ -99,13 +100,27 @@ describe Gitlab::SidekiqLogging::StructuredLogger do ...@@ -99,13 +100,27 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
end end
end end
it 'does not modify the job' do
Timecop.freeze(timestamp) do
job_copy = job.deep_dup
allow(logger).to receive(:info)
allow(subject).to receive(:log_job_start).and_call_original
allow(subject).to receive(:log_job_done).and_call_original
subject.call(job, 'test_queue') do
expect(job).to eq(job_copy)
end
end
end
context 'when the job args are bigger than the maximum allowed' do context 'when the job args are bigger than the maximum allowed' do
it 'keeps args from the front until they exceed the limit' do it 'keeps args from the front until they exceed the limit' do
Timecop.freeze(timestamp) do Timecop.freeze(timestamp) do
half_limit = Gitlab::Utils::LogLimitedArray::MAXIMUM_ARRAY_LENGTH / 2 half_limit = Gitlab::Utils::LogLimitedArray::MAXIMUM_ARRAY_LENGTH / 2
job['args'] = [1, 2, 'a' * half_limit, 'b' * half_limit, 3] job['args'] = [1, 2, 'a' * half_limit, 'b' * half_limit, 3]
expected_args = job['args'].take(3) + ['...'] expected_args = job['args'].take(3).map(&:to_s) + ['...']
expect(logger).to receive(:info).with(start_payload.merge('args' => expected_args)).ordered expect(logger).to receive(:info).with(start_payload.merge('args' => expected_args)).ordered
expect(logger).to receive(:info).with(end_payload.merge('args' => expected_args)).ordered expect(logger).to receive(:info).with(end_payload.merge('args' => expected_args)).ordered
......
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