require File.expand_path('../setup', File.dirname(__FILE__)) module TestLogging module TestAppenders class TestRollingFile < Test::Unit::TestCase include LoggingTestCase NAME = 'roller' def setup super Logging.init @fn = File.expand_path('test.log', @tmpdir) @fn_fmt = File.expand_path('test.%d.log', @tmpdir) @glob = File.expand_path('*.log', @tmpdir) end def test_factory_method_validates_input assert_raise(ArgumentError) do Logging.appenders.rolling_file end end def test_initialize assert_equal [], Dir.glob(@glob) # create a new appender ap = Logging.appenders.rolling_file(NAME, :filename => @fn) assert_equal @fn, ap.filename assert File.exist?(@fn) assert_equal 0, File.size(@fn) ap << "Just a line of text\n" # 20 bytes ap.flush assert_equal 20, File.size(@fn) cleanup # make sure we append to the current file (not truncate) ap = Logging.appenders.rolling_file(NAME, :filename => @fn) assert_equal @fn, ap.filename assert_equal [@fn], Dir.glob(@glob) assert_equal 20, File.size(@fn) ap << "Just another line of text\n" # 26 bytes ap.flush assert_equal 46, File.size(@fn) cleanup # setting the truncate option to true should roll the current log file # and create a new one ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :truncate => true) log1 = sprintf(@fn_fmt, 1) assert_equal [log1, @fn], Dir.glob(@glob).sort assert_equal 0, File.size(@fn) assert_equal 46, File.size(log1) ap << "Some more text in the new file\n" # 31 bytes ap.flush assert_equal 31, File.size(@fn) cleanup end def test_keep assert_equal [], Dir.glob(@glob) (1..12).each do |cnt| name = sprintf(@fn_fmt, cnt) File.open(name,'w') {|fd| fd.write 'X'*cnt} end FileUtils.touch(@fn) # keep only five files ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :keep => 5) # we still have 13 files because we did not truncate the log file, # and hence, we did not roll all the log files assert_equal 13, Dir.glob(@glob).length # force the appender to roll the files ap.send :copy_truncate ap.instance_variable_get(:@roller).roll_files assert_equal 6, Dir.glob(@glob).length (1..5).each do |cnt| name = sprintf(@fn_fmt, cnt) assert_equal cnt-1, File.size(name) end cleanup end def test_age d_glob = File.join(@tmpdir, 'test.*.log') dt_glob = File.join(@tmpdir, 'test.*-*.log') age_fn = @fn + '.age' assert_equal [], Dir.glob(@glob) assert_raise(ArgumentError) do Logging.appenders.rolling_file(NAME, :filename => @fn, :age => 'bob') end ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :age => 1) ap << "random message\n" assert_equal 1, Dir.glob(@glob).length now = ::File.mtime(age_fn) start = now - 42 ::File.utime(start, start, age_fn) ap.instance_variable_set(:@age_fn_mtime, nil) ap << "another random message\n" assert_equal 1, Dir.glob(dt_glob).length Dir.glob(d_glob).each {|fn| ::File.delete fn} cleanup ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :age => 'daily') ap << "random message\n" assert_equal 1, Dir.glob(@glob).length now = ::File.mtime(age_fn) start = now - 3600 * 24 ::File.utime(start, start, age_fn) ap.instance_variable_set(:@age_fn_mtime, nil) sleep 0.250 ap << "yet another random message\n" assert_equal 0, Dir.glob(dt_glob).length assert_equal 1, Dir.glob(d_glob).length Dir.glob(d_glob).each {|fn| ::File.delete fn} cleanup ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :age => 'weekly') ap << "random message\n" assert_equal 1, Dir.glob(@glob).length start = now - 3600 * 24 * 7 ::File.utime(start, start, age_fn) ap.instance_variable_set(:@age_fn_mtime, nil) sleep 0.250 ap << "yet another random message\n" assert_equal 0, Dir.glob(dt_glob).length assert_equal 1, Dir.glob(d_glob).length Dir.glob(d_glob).each {|fn| ::File.delete fn} cleanup ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :age => 'monthly') ap << "random message\n" assert_equal 1, Dir.glob(@glob).length start = now - 3600 * 24 * 31 ::File.utime(start, start, age_fn) ap.instance_variable_set(:@age_fn_mtime, nil) sleep 0.250 ap << "yet another random message\n" assert_equal 0, Dir.glob(dt_glob).length assert_equal 1, Dir.glob(d_glob).length end def test_size assert_equal [], Dir.glob(@glob) ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :size => 100) ap << 'X' * 100; ap.flush assert_equal 1, Dir.glob(@glob).length assert_equal 100, File.size(@fn) # this character is appended to the log file (bringing its size to 101) # and THEN the file is rolled resulting in a new, empty log file ap << 'X' assert_equal 2, Dir.glob(@glob).length assert_equal 0, File.size(@fn) ap << 'X' * 100; ap.flush assert_equal 2, Dir.glob(@glob).length assert_equal 100, File.size(@fn) ap << 'X' assert_equal 3, Dir.glob(@glob).length assert_equal 0, File.size(@fn) cleanup end def test_file_removed assert_equal [], Dir.glob(@glob) ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :size => 100) ap << 'X' * 100; ap.flush assert_equal 1, Dir.glob(@glob).length assert_equal 100, File.size(@fn) end def test_changing_directories ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :size => 100) begin pwd = Dir.pwd Dir.chdir @tmpdir ap << 'X' * 100; ap.flush assert_equal 1, Dir.glob(@glob).length ap << 'X'; ap.flush assert_equal 2, Dir.glob(@glob).length ensure Dir.chdir pwd end end def test_stale_copy_file ap = Logging.appenders.rolling_file(NAME, :filename => @fn, :size => 100) fn_copy = @fn + '._copy_' File.open(fn_copy, 'w') { |copy| copy.puts 'stale copy file' } ap << 'X' * 100; ap.flush assert_equal 1, Dir.glob(@glob).length assert_equal 100, File.size(@fn) # this character is appended to the log file (bringing its size to 101) # but the file is NOT ROLLED because the _copy_ file is in the way ap << 'X' assert_equal 1, Dir.glob(@glob).length assert_equal 101, File.size(@fn) assert_equal 16, File.size(fn_copy) # if the _copy_ file is older than three minutes, it will be # concatenated to and moved out of the way time = Time.now - 200 ::File.utime(time, time, fn_copy) ap << 'X' assert_equal 2, Dir.glob(@glob).length assert_equal 0, File.size(@fn) assert_equal 118, File.size(Dir.glob(@glob).sort.first) assert !File.exist?(fn_copy), '_copy_ file should not exist' cleanup end def test_custom_numberd_filename fn = File.expand_path('test.log{{.%d}}', @tmpdir) filename = File.expand_path('test.log', @tmpdir) glob = File.expand_path('test.log.*', @tmpdir) assert_equal [], Dir.glob(glob) ap = Logging.appenders.rolling_file(NAME, :filename => fn, :size => 100, :keep => 2) ap << 'X' * 100; ap.flush assert_equal 0, Dir.glob(glob).length assert_equal 100, File.size(filename) # this character is appended to the log file (bringing its size to 101) # and THEN the file is rolled resulting in a new, empty log file ap << 'X' assert_equal 1, Dir.glob(glob).length assert_equal 0, File.size(filename) ap << 'Y' * 100; ap.flush assert_equal 1, Dir.glob(glob).length assert_equal 100, File.size(filename) ap << 'Y' assert_equal 2, Dir.glob(glob).length assert_equal 0, File.size(filename) # now make sure we prune the correct file ap << 'Z' * 101; ap.flush files = Dir.glob(glob).sort assert_equal 2, files.length assert_equal 'Z'*101, ::File.read(files.first) assert_equal 'Y'*101, ::File.read(files.last) cleanup end def test_custom_timestamp_filename fn = File.expand_path('test{{.%S:%M}}.log', @tmpdir) filename = File.expand_path('test.log', @tmpdir) age_file = filename + '.age' glob = File.expand_path('test.*.log', @tmpdir) assert_equal [], Dir.glob(glob) ap = Logging.appenders.rolling_file(NAME, :filename => fn, :age => 1, :keep => 2) ap << "random message\n" assert_equal 0, Dir.glob(glob).length now = ::File.mtime(age_file) start = now - 42 ::File.utime(start, start, age_file) ap.instance_variable_set(:@age_fn_mtime, nil) ap << "another random message\n" files = Dir.glob(glob) assert_equal 1, files.length assert_match %r/test\.\d{2}:\d{2}\.log\z/, files.first cleanup end private def cleanup unless Logging.appenders[NAME].nil? Logging.appenders[NAME].close false Logging.appenders[NAME] = nil end end end # TestRollingFile end # TestAppenders end # TestLogging