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
|
# 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 "models/person"
class LoggingTest < ActiveSupport::TestCase
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
LoggingJob.perform_later "Dummy"
assert_match(/\[LoggingJob\]/, @logger.messages)
end
def test_uses_job_id_as_tag
LoggingJob.perform_later "Dummy"
assert_match(/\[LOGGING-JOB-ID\]/, @logger.messages)
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
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
def test_globalid_nested_parameter_logging
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
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
LoggingJob.perform_later "Dummy"
assert_match(/Performing LoggingJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
assert_match(/Dummy, here is it: Dummy/, @logger.messages)
assert_match(/Performed LoggingJob \(Job ID: .*?\) from .*? in .*ms/, @logger.messages)
end
def test_perform_nested_jobs_logging
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
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
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
end
|
