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
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
|
require 'spec_helper'
describe Gitlab::SidekiqLogging::StructuredLogger do
describe '#call' do
let(:timestamp) { Time.iso8601('2018-01-01T12:00:00Z') }
let(:created_at) { timestamp }
let(:scheduling_latency_s) { 0.0 }
let(:job) do
{
"class" => "TestWorker",
"args" => [1234, 'hello'],
"retry" => false,
"queue" => "cronjob:test_queue",
"queue_namespace" => "cronjob",
"jid" => "da883554ee4fe414012f5f42",
"created_at" => created_at.to_f,
"enqueued_at" => created_at.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' => created_at.iso8601(3),
'enqueued_at' => created_at.iso8601(3),
'scheduling_latency_s' => scheduling_latency_s
)
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
it 'logs without created_at and enqueued_at fields' do
Timecop.freeze(timestamp) do
excluded_fields = %w(created_at enqueued_at args scheduling_latency_s)
expect(logger).to receive(:info).with(start_payload.except(*excluded_fields)).ordered
expect(logger).to receive(:info).with(end_payload.except(*excluded_fields)).ordered
expect(subject).to receive(:log_job_start).and_call_original
expect(subject).to receive(:log_job_done).and_call_original
subject.call(job.except("created_at", "enqueued_at"), 'test_queue') { }
end
end
end
context 'with latency' do
let(:created_at) { Time.iso8601('2018-01-01T10:00:00Z') }
let(:scheduling_latency_s) { 7200.0 }
it 'logs with scheduling latency' 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
|
