aboutsummaryrefslogtreecommitdiffstats
path: root/activejob/test/cases/logging_test.rb
blob: 6154ba301da2ba7d363b153ba94ef9d6f4d3c11e (plain) (blame)
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
# 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(/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