aboutsummaryrefslogtreecommitdiffstats
path: root/activesupport/test/buffered_logger_test.rb
blob: 386006677bece2999e422c76a6279573dd2a35a6 (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
require 'abstract_unit'
require 'multibyte_test_helpers'
require 'stringio'
require 'fileutils'
require 'tempfile'
require 'active_support/buffered_logger'

class BufferedLoggerTest < Test::Unit::TestCase
  include MultibyteTestHelpers

  Logger = ActiveSupport::BufferedLogger

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

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

    logger = Logger.new t.path
    logger.level = Logger::DEBUG

    str = "\x80"
    if str.respond_to?(:force_encoding)
      str.force_encoding("ASCII-8BIT")
    end

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

  def test_write_binary_data_create_file
    fname = File.join Dir.tmpdir, 'lol', 'rofl.log'
    logger = Logger.new fname
    logger.level = Logger::DEBUG

    str = "\x80"
    if str.respond_to?(:force_encoding)
      str.force_encoding("ASCII-8BIT")
    end

    logger.add Logger::DEBUG, str
    logger.flush
  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 @output.string.include?(@message)
  end

  def test_should_not_log_debug_messages_when_log_level_is_info
    @logger.level = Logger::INFO
    @logger.add(Logger::DEBUG, @message)
    assert ! @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 @output.string.include?(@message)
  end

  def test_should_add_message_passed_as_block_when_using_shortcut
    @logger.level = Logger::INFO
    @logger.info {@message}
    assert @output.string.include?(@message)
  end

  def test_should_convert_message_to_string
    @logger.level = Logger::INFO
    @logger.info @integer_message
    assert @output.string.include?(@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 @output.string.include?(@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


  [false, nil, 0].each do |disable|
    define_method "test_disabling_auto_flush_with_#{disable.inspect}_should_buffer_until_explicit_flush" do
      @logger.auto_flushing = disable

      4.times do
        @logger.info 'wait for it..'
        assert @output.string.empty?, "@output.string should be empty but it is #{@output.string}"
      end

      @logger.flush
      assert !@output.string.empty?, "@logger.send(:buffer).size.to_s should not be empty but it is empty"
    end

    define_method "test_disabling_auto_flush_with_#{disable.inspect}_should_flush_at_max_buffer_size_as_failsafe" do
      @logger.auto_flushing = disable
      assert_equal Logger::MAX_BUFFER_SIZE, @logger.auto_flushing

      (Logger::MAX_BUFFER_SIZE - 1).times do
        @logger.info 'wait for it..'
        assert @output.string.empty?, "@output.string should be empty but is #{@output.string}"
      end

      @logger.info 'there it is.'
      assert !@output.string.empty?, "@logger.send(:buffer).size.to_s should not be empty but it is empty"
    end
  end

  def test_should_know_if_its_loglevel_is_below_a_given_level
    Logger::Severity.constants.each do |level|
      @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_should_auto_flush_every_n_messages
    @logger.auto_flushing = 5

    4.times do
      @logger.info 'wait for it..'
      assert @output.string.empty?, "@output.string should be empty but it is #{@output.string}"
    end

    @logger.info 'there it is.'
    assert !@output.string.empty?, "@output.string should not be empty but it is empty"
  end

  def test_should_create_the_log_directory_if_it_doesnt_exist
    tmp_directory = File.join(File.dirname(__FILE__), "tmp")
    log_file = File.join(tmp_directory, "development.log")
    FileUtils.rm_rf(tmp_directory)
    @logger  = Logger.new(log_file)
    assert File.exist?(tmp_directory)
  end

  def test_logger_should_maintain_separate_buffers_for_each_thread
    @logger.auto_flushing = false

    a = Thread.new do
      @logger.info("a"); Thread.pass;
      @logger.info("b"); Thread.pass;
      @logger.info("c"); @logger.flush
    end

    b = Thread.new do
      @logger.info("x"); Thread.pass;
      @logger.info("y"); Thread.pass;
      @logger.info("z"); @logger.flush
    end

    a.join
    b.join

    assert @output.string.include?("a\nb\nc\n")
    assert @output.string.include?("x\ny\nz\n")
  end

  def test_flush_should_remove_empty_buffers
    @logger.send :buffer
    @logger.expects :clear_buffer
    @logger.flush
  end

  def test_buffer_multibyte
    @logger.auto_flushing = 2
    @logger.info(UNICODE_STRING)
    @logger.info(BYTE_STRING)
    assert @output.string.include?(UNICODE_STRING)
    byte_string = @output.string.dup
    if byte_string.respond_to?(:force_encoding)
      byte_string.force_encoding("ASCII-8BIT")
    end
    assert byte_string.include?(BYTE_STRING)
  end

  def test_silence_only_current_thread
    @logger.auto_flushing = true
    run_thread_a = false

    a = Thread.new do
      while !run_thread_a do
        sleep(0.001)
      end
      @logger.info("x")
      run_thread_a = false
    end

    @logger.silence do
      run_thread_a = true
      @logger.info("a")
      while run_thread_a do
        sleep(0.001)
      end
    end

    a.join

    assert @output.string.include?("x")
    assert !@output.string.include?("a")
  end

  def test_flush_dead_buffers
    @logger.auto_flushing = false

    a = Thread.new do
      @logger.info("a")
    end
    
    keep_running = true
    Thread.new do
      @logger.info("b")
      while keep_running
        sleep(0.001)
      end
    end

    @logger.info("x")
    a.join
    @logger.flush


    assert @output.string.include?("x")
    assert @output.string.include?("a")
    assert !@output.string.include?("b")
    
    keep_running = false
  end
end