aboutsummaryrefslogtreecommitdiffstats
path: root/activesupport/test/logger_test.rb
blob: 6f7a18602233487514faba7c74f72c9a96a309fb (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
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
# frozen_string_literal: true

require "abstract_unit"
require "multibyte_test_helpers"
require "stringio"
require "fileutils"
require "tempfile"
require "tmpdir"
require "concurrent/atomics"

class LoggerTest < ActiveSupport::TestCase
  include MultibyteTestHelpers

  Logger = ActiveSupport::Logger

  def setup
    @message = "A debug message"
    @integer_message = 12345
    @output  = StringIO.new
    @logger  = Logger.new(@output)
  end

  def test_log_outputs_to
    assert Logger.logger_outputs_to?(@logger, @output),            "Expected logger_outputs_to? @output to return true but was false"
    assert Logger.logger_outputs_to?(@logger, @output, STDOUT),    "Expected logger_outputs_to? @output or STDOUT to return true but was false"

    assert_not Logger.logger_outputs_to?(@logger, STDOUT),         "Expected logger_outputs_to? to STDOUT to return false, but was true"
    assert_not Logger.logger_outputs_to?(@logger, STDOUT, STDERR), "Expected logger_outputs_to? to STDOUT or STDERR to return false, but was true"
  end

  def test_write_binary_data_to_existing_file
    t = Tempfile.new ["development", "log"]
    t.binmode
    t.write "hi mom!"
    t.close

    f = File.open(t.path, "w")
    f.binmode

    logger = Logger.new f
    logger.level = Logger::DEBUG

    str = +"\x80"
    str.force_encoding("ASCII-8BIT")

    logger.add Logger::DEBUG, str
  ensure
    logger.close
    t.close true
  end

  def test_write_binary_data_create_file
    fname = File.join Dir.tmpdir, "lol", "rofl.log"
    FileUtils.mkdir_p File.dirname(fname)
    f = File.open(fname, "w")
    f.binmode

    logger = Logger.new f
    logger.level = Logger::DEBUG

    str = +"\x80"
    str.force_encoding("ASCII-8BIT")

    logger.add Logger::DEBUG, str
  ensure
    logger.close
    File.unlink fname
  end

  def test_should_log_debugging_message_when_debugging
    @logger.level = Logger::DEBUG
    @logger.add(Logger::DEBUG, @message)
    assert_includes @output.string, @message
  end

  def test_should_not_log_debug_messages_when_log_level_is_info
    @logger.level = Logger::INFO
    @logger.add(Logger::DEBUG, @message)
    assert_not @output.string.include?(@message)
  end

  def test_should_add_message_passed_as_block_when_using_add
    @logger.level = Logger::INFO
    @logger.add(Logger::INFO) { @message }
    assert_includes @output.string, @message
  end

  def test_should_add_message_passed_as_block_when_using_shortcut
    @logger.level = Logger::INFO
    @logger.info { @message }
    assert_includes @output.string, @message
  end

  def test_should_convert_message_to_string
    @logger.level = Logger::INFO
    @logger.info @integer_message
    assert_includes @output.string, @integer_message.to_s
  end

  def test_should_convert_message_to_string_when_passed_in_block
    @logger.level = Logger::INFO
    @logger.info { @integer_message }
    assert_includes @output.string, @integer_message.to_s
  end

  def test_should_not_evaluate_block_if_message_wont_be_logged
    @logger.level = Logger::INFO
    evaluated = false
    @logger.add(Logger::DEBUG) { evaluated = true }
    assert evaluated == false
  end

  def test_should_not_mutate_message
    message_copy = @message.dup
    @logger.info @message
    assert_equal message_copy, @message
  end

  def test_should_know_if_its_loglevel_is_below_a_given_level
    Logger::Severity.constants.each do |level|
      next if level.to_s == "UNKNOWN"
      @logger.level = Logger::Severity.const_get(level) - 1
      assert @logger.send("#{level.downcase}?"), "didn't know if it was #{level.downcase}? or below"
    end
  end

  def test_buffer_multibyte
    @logger.level = Logger::INFO
    @logger.info(UNICODE_STRING)
    @logger.info(BYTE_STRING)
    assert_includes @output.string, UNICODE_STRING
    byte_string = @output.string.dup
    byte_string.force_encoding("ASCII-8BIT")
    assert_includes byte_string, BYTE_STRING
  end

  def test_silencing_everything_but_errors
    @logger.silence do
      @logger.debug "NOT THERE"
      @logger.error "THIS IS HERE"
    end

    assert_not @output.string.include?("NOT THERE")
    assert_includes @output.string, "THIS IS HERE"
  end

  def test_logger_silencing_works_for_broadcast
    another_output  = StringIO.new
    another_logger  = ActiveSupport::Logger.new(another_output)

    @logger.extend ActiveSupport::Logger.broadcast(another_logger)

    @logger.debug "CORRECT DEBUG"
    @logger.silence do |logger|
      assert_kind_of ActiveSupport::Logger, logger
      @logger.debug "FAILURE"
      @logger.error "CORRECT ERROR"
    end

    assert_includes @output.string, "CORRECT DEBUG"
    assert_includes @output.string, "CORRECT ERROR"
    assert_not @output.string.include?("FAILURE")

    assert_includes another_output.string, "CORRECT DEBUG"
    assert_includes another_output.string, "CORRECT ERROR"
    assert_not another_output.string.include?("FAILURE")
  end

  def test_broadcast_silencing_does_not_break_plain_ruby_logger
    another_output  = StringIO.new
    another_logger  = ::Logger.new(another_output)

    @logger.extend ActiveSupport::Logger.broadcast(another_logger)

    @logger.debug "CORRECT DEBUG"
    @logger.silence do |logger|
      assert_kind_of ActiveSupport::Logger, logger
      @logger.debug "FAILURE"
      @logger.error "CORRECT ERROR"
    end

    assert_includes @output.string, "CORRECT DEBUG"
    assert_includes @output.string, "CORRECT ERROR"
    assert_not @output.string.include?("FAILURE")

    assert_includes another_output.string, "CORRECT DEBUG"
    assert_includes another_output.string, "CORRECT ERROR"
    assert_includes another_output.string, "FAILURE"
    # We can't silence plain ruby Logger cause with thread safety
    # but at least we don't break it
  end

  def test_logger_level_per_object_thread_safety
    logger1 = Logger.new(StringIO.new)
    logger2 = Logger.new(StringIO.new)

    level = Logger::DEBUG
    assert_equal level, logger1.level, "Expected level #{level_name(level)}, got #{level_name(logger1.level)}"
    assert_equal level, logger2.level, "Expected level #{level_name(level)}, got #{level_name(logger2.level)}"

    logger1.level = Logger::ERROR
    assert_equal level, logger2.level, "Expected level #{level_name(level)}, got #{level_name(logger2.level)}"
  end

  def test_logger_level_main_thread_safety
    @logger.level = Logger::INFO
    assert_level(Logger::INFO)

    latch  = Concurrent::CountDownLatch.new
    latch2 = Concurrent::CountDownLatch.new

    t = Thread.new do
      latch.wait
      assert_level(Logger::INFO)
      latch2.count_down
    end

    @logger.silence(Logger::ERROR) do
      assert_level(Logger::ERROR)
      latch.count_down
      latch2.wait
    end

    t.join
  end

  def test_logger_level_local_thread_safety
    @logger.level = Logger::INFO
    assert_level(Logger::INFO)

    thread_1_latch = Concurrent::CountDownLatch.new
    thread_2_latch = Concurrent::CountDownLatch.new

    threads = (1..2).collect do |thread_number|
      Thread.new do
        # force thread 2 to wait until thread 1 is already in @logger.silence
        thread_2_latch.wait if thread_number == 2

        @logger.silence(Logger::ERROR) do
          assert_level(Logger::ERROR)
          @logger.silence(Logger::DEBUG) do
            # allow thread 2 to finish but hold thread 1
            if thread_number == 1
              thread_2_latch.count_down
              thread_1_latch.wait
            end
            assert_level(Logger::DEBUG)
          end
        end

        # allow thread 1 to finish
        assert_level(Logger::INFO)
        thread_1_latch.count_down if thread_number == 2
      end
    end

    threads.each(&:join)
    assert_level(Logger::INFO)
  end

  def test_logger_level_main_fiber_safety
    @logger.level = Logger::INFO
    assert_level(Logger::INFO)

    fiber = Fiber.new do
      assert_level(Logger::INFO)
    end

    @logger.silence(Logger::ERROR) do
      assert_level(Logger::ERROR)
      fiber.resume
    end
  end

  def test_logger_level_local_fiber_safety
    @logger.level = Logger::INFO
    assert_level(Logger::INFO)

    another_fiber = Fiber.new do
      @logger.silence(Logger::ERROR) do
        assert_level(Logger::ERROR)
        @logger.silence(Logger::DEBUG) do
          assert_level(Logger::DEBUG)
        end
      end

      assert_level(Logger::INFO)
    end

    Fiber.new do
      @logger.silence(Logger::ERROR) do
        assert_level(Logger::ERROR)
        @logger.silence(Logger::DEBUG) do
          another_fiber.resume
          assert_level(Logger::DEBUG)
        end
      end

      assert_level(Logger::INFO)
    end.resume

    assert_level(Logger::INFO)
  end

  private
    def level_name(level)
      ::Logger::Severity.constants.find do |severity|
        Logger.const_get(severity) == level
      end.to_s
    end

    def assert_level(level)
      assert_equal level, @logger.level, "Expected level #{level_name(level)}, got #{level_name(@logger.level)}"
    end
end