2008-01-05 08:31:04 -05:00
|
|
|
require 'abstract_unit'
|
2007-09-25 12:48:50 -04:00
|
|
|
require 'stringio'
|
2008-03-30 21:09:19 -04:00
|
|
|
require 'fileutils'
|
2007-09-25 12:48:50 -04:00
|
|
|
|
|
|
|
class BufferedLoggerTest < Test::Unit::TestCase
|
|
|
|
def setup
|
|
|
|
@message = "A debug message"
|
2007-09-28 10:09:35 -04:00
|
|
|
@integer_message = 12345
|
2007-09-25 12:48:50 -04:00
|
|
|
@output = StringIO.new
|
|
|
|
@logger = ActiveSupport::BufferedLogger.new(@output)
|
|
|
|
end
|
2007-10-03 19:43:12 -04:00
|
|
|
|
2007-09-25 12:48:50 -04:00
|
|
|
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
|
2007-10-03 19:43:12 -04:00
|
|
|
|
2007-09-25 12:48:50 -04:00
|
|
|
def test_should_add_message_passed_as_block_when_using_shortcut
|
|
|
|
@logger.level = Logger::INFO
|
|
|
|
@logger.info {@message}
|
|
|
|
assert @output.string.include?(@message)
|
|
|
|
end
|
2007-10-03 19:43:12 -04:00
|
|
|
|
2007-09-28 10:09:35 -04:00
|
|
|
def test_should_convert_message_to_string
|
|
|
|
@logger.level = Logger::INFO
|
|
|
|
@logger.info @integer_message
|
|
|
|
assert @output.string.include?(@integer_message.to_s)
|
|
|
|
end
|
2007-10-03 19:43:12 -04:00
|
|
|
|
2007-09-28 10:09:35 -04:00
|
|
|
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
|
2007-10-03 19:43:12 -04:00
|
|
|
|
2007-09-25 12:48:50 -04:00
|
|
|
def test_should_not_evaluate_block_if_message_wont_be_logged
|
|
|
|
@logger.level = Logger::INFO
|
|
|
|
evaluated = false
|
|
|
|
@logger.add(Logger::DEBUG) {evaluated = true}
|
2007-10-03 19:43:12 -04:00
|
|
|
assert evaluated == false
|
2007-09-25 12:48:50 -04:00
|
|
|
end
|
2007-10-03 19:43:12 -04:00
|
|
|
|
2007-09-27 00:50:58 -04:00
|
|
|
def test_should_not_mutate_message
|
|
|
|
message_copy = @message.dup
|
|
|
|
@logger.info @message
|
|
|
|
assert_equal message_copy, @message
|
|
|
|
end
|
2007-10-03 19:43:12 -04:00
|
|
|
|
|
|
|
|
|
|
|
[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
|
|
|
|
end
|
|
|
|
|
|
|
|
@logger.flush
|
2008-08-19 00:33:46 -04:00
|
|
|
assert !@output.string.empty?, @logger.send(:buffer).size
|
2007-10-03 19:43:12 -04:00
|
|
|
end
|
2007-10-04 15:52:10 -04:00
|
|
|
|
|
|
|
define_method "test_disabling_auto_flush_with_#{disable.inspect}_should_flush_at_max_buffer_size_as_failsafe" do
|
|
|
|
@logger.auto_flushing = disable
|
|
|
|
assert_equal ActiveSupport::BufferedLogger::MAX_BUFFER_SIZE, @logger.auto_flushing
|
|
|
|
|
|
|
|
(ActiveSupport::BufferedLogger::MAX_BUFFER_SIZE - 1).times do
|
|
|
|
@logger.info 'wait for it..'
|
|
|
|
assert @output.string.empty?, @output.string
|
|
|
|
end
|
|
|
|
|
|
|
|
@logger.info 'there it is.'
|
2008-08-19 00:33:46 -04:00
|
|
|
assert !@output.string.empty?, @logger.send(:buffer).size
|
2007-10-04 15:52:10 -04:00
|
|
|
end
|
2007-10-03 19:43:12 -04:00
|
|
|
end
|
2008-08-19 00:33:46 -04:00
|
|
|
|
2007-10-07 14:54:36 -04:00
|
|
|
def test_should_know_if_its_loglevel_is_below_a_given_level
|
|
|
|
ActiveSupport::BufferedLogger::Severity.constants.each do |level|
|
|
|
|
@logger.level = ActiveSupport::BufferedLogger::Severity.const_get(level) - 1
|
|
|
|
assert @logger.send("#{level.downcase}?"), "didn't know if it was #{level.downcase}? or below"
|
|
|
|
end
|
|
|
|
end
|
2007-10-03 19:43:12 -04:00
|
|
|
|
|
|
|
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
|
|
|
|
end
|
|
|
|
|
|
|
|
@logger.info 'there it is.'
|
|
|
|
assert !@output.string.empty?, @output.string
|
|
|
|
end
|
2008-08-19 00:33:46 -04:00
|
|
|
|
2008-03-12 21:54:34 -04:00
|
|
|
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")
|
|
|
|
assert !File.exist?(tmp_directory)
|
|
|
|
@logger = ActiveSupport::BufferedLogger.new(log_file)
|
|
|
|
assert File.exist?(tmp_directory)
|
|
|
|
ensure
|
|
|
|
FileUtils.rm_rf(tmp_directory)
|
|
|
|
end
|
2008-08-19 00:33:46 -04:00
|
|
|
|
|
|
|
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
|
|
|
|
|
2008-08-29 18:59:56 -04:00
|
|
|
assert @output.string.include?("a\nb\nc\n")
|
|
|
|
assert @output.string.include?("x\ny\nz\n")
|
2008-08-19 00:33:46 -04:00
|
|
|
end
|
2008-12-10 17:36:58 -05:00
|
|
|
|
|
|
|
def test_flush_should_remove_empty_buffers
|
|
|
|
@logger.send :buffer
|
|
|
|
@logger.expects :clear_buffer
|
|
|
|
@logger.flush
|
|
|
|
end
|
2007-09-25 12:48:50 -04:00
|
|
|
end
|