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
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
|
# frozen_string_literal: true
require "helper"
require "active_support/log_subscriber/test_helper"
require "active_support/core_ext/numeric/time"
require "jobs/hello_job"
require "jobs/logging_job"
require "jobs/overridden_logging_job"
require "jobs/nested_job"
require "jobs/rescue_job"
require "jobs/retry_job"
require "models/person"
class LoggingTest < ActiveSupport::TestCase
include ActiveJob::TestHelper
include ActiveSupport::LogSubscriber::TestHelper
include ActiveSupport::Logger::Severity
class TestLogger < ActiveSupport::Logger
def initialize
@file = StringIO.new
super(@file)
end
def messages
@file.rewind
@file.read
end
end
def setup
super
JobBuffer.clear
@old_logger = ActiveJob::Base.logger
@logger = ActiveSupport::TaggedLogging.new(TestLogger.new)
set_logger @logger
ActiveJob::Logging::LogSubscriber.attach_to :active_job
end
def teardown
super
ActiveJob::Logging::LogSubscriber.log_subscribers.pop
set_logger @old_logger
end
def set_logger(logger)
ActiveJob::Base.logger = logger
end
def subscribed
[].tap do |events|
ActiveSupport::Notifications.subscribed(-> (*args) { events << args }, /enqueue.*\.active_job/) do
yield
end
end
end
def test_uses_active_job_as_tag
HelloJob.perform_later "Cristian"
assert_match(/\[ActiveJob\]/, @logger.messages)
end
def test_uses_job_name_as_tag
perform_enqueued_jobs do
LoggingJob.perform_later "Dummy"
assert_match(/\[LoggingJob\]/, @logger.messages)
end
end
def test_uses_job_id_as_tag
perform_enqueued_jobs do
LoggingJob.perform_later "Dummy"
assert_match(/\[LOGGING-JOB-ID\]/, @logger.messages)
end
end
def test_logs_correct_queue_name
original_queue_name = LoggingJob.queue_name
LoggingJob.queue_as :php_jobs
LoggingJob.perform_later("Dummy")
assert_match(/to .*?\(php_jobs\).*/, @logger.messages)
ensure
LoggingJob.queue_name = original_queue_name
end
def test_globalid_parameter_logging
perform_enqueued_jobs do
person = Person.new(123)
LoggingJob.perform_later person
assert_match(%r{Enqueued.*gid://aj/Person/123}, @logger.messages)
assert_match(%r{Dummy, here is it: #<Person:.*>}, @logger.messages)
assert_match(%r{Performing.*gid://aj/Person/123}, @logger.messages)
end
end
def test_globalid_nested_parameter_logging
perform_enqueued_jobs do
person = Person.new(123)
LoggingJob.perform_later(person: person)
assert_match(%r{Enqueued.*gid://aj/Person/123}, @logger.messages)
assert_match(%r{Dummy, here is it: .*#<Person:.*>}, @logger.messages)
assert_match(%r{Performing.*gid://aj/Person/123}, @logger.messages)
end
end
def test_enqueue_job_logging
events = subscribed { HelloJob.perform_later "Cristian" }
assert_match(/Enqueued HelloJob \(Job ID: .*?\) to .*?:.*Cristian/, @logger.messages)
assert_equal(events.count, 1)
key, * = events.first
assert_equal(key, "enqueue.active_job")
end
def test_perform_job_logging
perform_enqueued_jobs do
LoggingJob.perform_later "Dummy"
assert_match(/Performing LoggingJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
assert_match(/enqueued at /, @logger.messages)
assert_match(/Dummy, here is it: Dummy/, @logger.messages)
assert_match(/Performed LoggingJob \(Job ID: .*?\) from .*? in .*ms/, @logger.messages)
end
end
def test_perform_nested_jobs_logging
perform_enqueued_jobs do
NestedJob.perform_later
assert_match(/\[LoggingJob\] \[.*?\]/, @logger.messages)
assert_match(/\[ActiveJob\] Enqueued NestedJob \(Job ID: .*\) to/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Performing NestedJob \(Job ID: .*?\) from/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Enqueued LoggingJob \(Job ID: .*?\) to .* with arguments: "NestedJob"/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Performing LoggingJob \(Job ID: .*?\) from .* with arguments: "NestedJob"/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Dummy, here is it: NestedJob/, @logger.messages)
assert_match(/\[ActiveJob\].*\[LoggingJob\] \[LOGGING-JOB-ID\] Performed LoggingJob \(Job ID: .*?\) from .* in/, @logger.messages)
assert_match(/\[ActiveJob\] \[NestedJob\] \[NESTED-JOB-ID\] Performed NestedJob \(Job ID: .*?\) from .* in/, @logger.messages)
end
end
def test_enqueue_at_job_logging
events = subscribed { HelloJob.set(wait_until: 24.hours.from_now).perform_later "Cristian" }
assert_match(/Enqueued HelloJob \(Job ID: .*\) to .*? at.*Cristian/, @logger.messages)
assert_equal(events.count, 1)
key, * = events.first
assert_equal(key, "enqueue_at.active_job")
rescue NotImplementedError
skip
end
def test_enqueue_in_job_logging
events = subscribed { HelloJob.set(wait: 2.seconds).perform_later "Cristian" }
assert_match(/Enqueued HelloJob \(Job ID: .*\) to .*? at.*Cristian/, @logger.messages)
assert_equal(events.count, 1)
key, * = events.first
assert_equal(key, "enqueue_at.active_job")
rescue NotImplementedError
skip
end
def test_for_tagged_logger_support_is_consistent
set_logger ::Logger.new(nil)
OverriddenLoggingJob.perform_later "Dummy"
end
def test_job_error_logging
perform_enqueued_jobs { RescueJob.perform_later "other" }
rescue RescueJob::OtherError
assert_match(/Performing RescueJob \(Job ID: .*?\) from .*? with arguments:.*other/, @logger.messages)
assert_match(/Error performing RescueJob \(Job ID: .*?\) from .*? in .*ms: RescueJob::OtherError \(Bad hair\):\n.*\brescue_job\.rb:\d+:in `perform'/, @logger.messages)
end
def test_enqueue_retry_logging
perform_enqueued_jobs do
RetryJob.perform_later "DefaultsError", 2
assert_match(/Retrying RetryJob in 3 seconds, due to a DefaultsError\./, @logger.messages)
end
end
def test_enqueue_retry_logging_on_retry_job
perform_enqueued_jobs { RescueJob.perform_later "david" }
assert_match(/Retrying RescueJob in 0 seconds\./, @logger.messages)
end
def test_retry_stopped_logging
perform_enqueued_jobs do
RetryJob.perform_later "CustomCatchError", 6
assert_match(/Stopped retrying RetryJob due to a CustomCatchError, which reoccurred on \d+ attempts\./, @logger.messages)
end
end
def test_retry_stopped_logging_without_block
perform_enqueued_jobs do
RetryJob.perform_later "DefaultsError", 6
rescue DefaultsError
assert_match(/Stopped retrying RetryJob due to a DefaultsError, which reoccurred on \d+ attempts\./, @logger.messages)
end
end
def test_discard_logging
perform_enqueued_jobs do
RetryJob.perform_later "DiscardableError", 2
assert_match(/Discarded RetryJob due to a DiscardableError\./, @logger.messages)
end
end
end
|
