aboutsummaryrefslogtreecommitdiffstats
path: root/activejob/test/cases/logging_test.rb
blob: a1107a07fd30c41ecf7f13339d5ed8552a0463b0 (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
# 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