1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
|
require 'spec_helper'
describe Gitlab::SidekiqLogging::StructuredLogger do
describe '#call' do
let(:timestamp) { Time.new('2018-01-01 12:00:00').utc }
let(:job) do
{
"class" => "TestWorker",
"args" => [1234, 'hello'],
"retry" => false,
"queue" => "cronjob:test_queue",
"queue_namespace" => "cronjob",
"jid" => "da883554ee4fe414012f5f42",
"created_at" => timestamp.to_f,
"enqueued_at" => timestamp.to_f,
"correlation_id" => 'cid'
}
end
let(:logger) { double() }
let(:start_payload) do
job.merge(
'message' => 'TestWorker JID-da883554ee4fe414012f5f42: start',
'job_status' => 'start',
'pid' => Process.pid,
'created_at' => timestamp.iso8601(3),
'enqueued_at' => timestamp.iso8601(3)
)
end
let(:end_payload) do
start_payload.merge(
'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
'job_status' => 'done',
'duration' => 0.0,
"completed_at" => timestamp.iso8601(3)
)
end
let(:exception_payload) do
end_payload.merge(
'message' => 'TestWorker JID-da883554ee4fe414012f5f42: fail: 0.0 sec',
'job_status' => 'fail',
'error' => ArgumentError,
'error_message' => 'some exception'
)
end
before do
allow(Sidekiq).to receive(:logger).and_return(logger)
allow(subject).to receive(:current_time).and_return(timestamp.to_f)
end
subject { described_class.new }
context 'with SIDEKIQ_LOG_ARGUMENTS enabled' do
before do
stub_env('SIDEKIQ_LOG_ARGUMENTS', '1')
end
it 'logs start and end of job' do
Timecop.freeze(timestamp) do
expect(logger).to receive(:info).with(start_payload).ordered
expect(logger).to receive(:info).with(end_payload).ordered
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
subject.call(job, 'test_queue') { }
end
end
it 'logs an exception in job' do
Timecop.freeze(timestamp) do
expect(logger).to receive(:info).with(start_payload)
# This excludes the exception_backtrace
expect(logger).to receive(:warn).with(hash_including(exception_payload))
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
expect do
subject.call(job, 'test_queue') do
raise ArgumentError, _('some exception')
end
end.to raise_error(ArgumentError)
end
end
context 'when the job args are bigger than the maximum allowed' do
it 'keeps args from the front until they exceed the limit' do
Timecop.freeze(timestamp) do
job['args'] = [
1,
2,
'a' * (described_class::MAXIMUM_JOB_ARGUMENTS_LENGTH / 2),
'b' * (described_class::MAXIMUM_JOB_ARGUMENTS_LENGTH / 2),
3
]
expected_args = job['args'].take(3) + ['...']
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(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
subject.call(job, 'test_queue') { }
end
end
end
end
context 'with SIDEKIQ_LOG_ARGUMENTS disabled' do
it 'logs start and end of job without args' do
Timecop.freeze(timestamp) do
expect(logger).to receive(:info).with(start_payload.except('args')).ordered
expect(logger).to receive(:info).with(end_payload.except('args')).ordered
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
subject.call(job, 'test_queue') { }
end
end
end
end
end
|
