From 04ef93dae6d9cec616973c1110a33894ad4ba6ed Mon Sep 17 00:00:00 2001 From: Aaron Patterson Date: Fri, 9 Dec 2011 16:03:18 -0800 Subject: * ActiveSupport::BufferedLogger#silence is deprecated. If you want to squelch logs for a certain block, change the log level for that block. * ActiveSupport::BufferedLogger#open_log is deprecated. This method should not have been public in the first place. * ActiveSupport::BufferedLogger's behavior of automatically creating the directory for your log file is deprecated. Please make sure to create the directory for your log file before instantiating. * ActiveSupport::BufferedLogger#auto_flushing is deprecated. Either set the sync level on the underlying file handle like this: f = File.open('foo.log', 'w') f.sync = true ActiveSupport::BufferedLogger.new f Or tune your filesystem. The FS cache is now what controls flushing. * ActiveSupport::BufferedLogger#flush is deprecated. Set sync on your filehandle, or tune your filesystem. --- activesupport/CHANGELOG.md | 22 ++++ .../lib/active_support/buffered_logger.rb | 112 +++++------------ activesupport/lib/active_support/tagged_logging.rb | 3 +- activesupport/test/benchmarkable_test.rb | 47 +++---- activesupport/test/buffered_logger_test.rb | 139 ++------------------- railties/lib/rails/application/bootstrap.rb | 14 ++- 6 files changed, 96 insertions(+), 241 deletions(-) diff --git a/activesupport/CHANGELOG.md b/activesupport/CHANGELOG.md index 7f1103a6d7..1516472fed 100644 --- a/activesupport/CHANGELOG.md +++ b/activesupport/CHANGELOG.md @@ -47,6 +47,28 @@ * ActiveSupport::OrderedHash now has different behavior for #each and \#each_pair when given a block accepting its parameters with a splat. *Andrew Radev* +* ActiveSupport::BufferedLogger#silence is deprecated. If you want to squelch + logs for a certain block, change the log level for that block. + +* ActiveSupport::BufferedLogger#open_log is deprecated. This method should + not have been public in the first place. + +* ActiveSupport::BufferedLogger's behavior of automatically creating the + directory for your log file is deprecated. Please make sure to create the + directory for your log file before instantiating. + +* ActiveSupport::BufferedLogger#auto_flushing is deprecated. Either set the + sync level on the underlying file handle like this: + + f = File.open('foo.log', 'w') + f.sync = true + ActiveSupport::BufferedLogger.new f + + Or tune your filesystem. The FS cache is now what controls flushing. + +* ActiveSupport::BufferedLogger#flush is deprecated. Set sync on your + filehandle, or tune your filesystem. + ## Rails 3.1.0 (August 30, 2011) ## * ActiveSupport::Dependencies#load and ActiveSupport::Dependencies#require now diff --git a/activesupport/lib/active_support/buffered_logger.rb b/activesupport/lib/active_support/buffered_logger.rb index 136e245859..fc01225966 100644 --- a/activesupport/lib/active_support/buffered_logger.rb +++ b/activesupport/lib/active_support/buffered_logger.rb @@ -1,5 +1,8 @@ require 'thread' +require 'logger' require 'active_support/core_ext/class/attribute_accessors' +require 'active_support/deprecation' +require 'fileutils' module ActiveSupport # Inspired by the buffered logger idea by Ezra @@ -25,40 +28,35 @@ module ActiveSupport # Silences the logger for the duration of the block. def silence(temporary_level = ERROR) if silencer - old_logger_level = @tmp_levels[Thread.current] begin - @tmp_levels[Thread.current] = temporary_level - yield self + logger = self.class.new @log_dest, temporary_level + yield logger ensure - if old_logger_level - @tmp_levels[Thread.current] = old_logger_level - else - @tmp_levels.delete(Thread.current) - end + logger.close end else yield self end end + deprecate :silence - attr_writer :level attr_reader :auto_flushing + deprecate :auto_flushing def initialize(log, level = DEBUG) @level = level - @tmp_levels = {} - @buffer = Hash.new { |h,k| h[k] = [] } - @auto_flushing = 1 - @guard = Mutex.new - - if log.respond_to?(:write) - @log = log - elsif File.exist?(log) - @log = open_log(log, (File::WRONLY | File::APPEND)) - else - FileUtils.mkdir_p(File.dirname(log)) - @log = open_log(log, (File::WRONLY | File::APPEND | File::CREAT)) + @log_dest = log + + unless log.respond_to?(:write) + unless File.exist?(File.dirname(log)) + ActiveSupport::Deprecation.warn(<<-eowarn) +Automatic directory creation for '#{log}' is deprecated. Please make sure the directory for your log file exists before creating the logger. + eowarn + FileUtils.mkdir_p(File.dirname(log)) + end end + + @log = open_logfile log end def open_log(log, mode) @@ -67,20 +65,18 @@ module ActiveSupport open_log.sync = true end end + deprecate :open_log def level - @tmp_levels[Thread.current] || @level + @log.level + end + + def level=(l) + @log.level = l end def add(severity, message = nil, progname = nil, &block) - return if level > severity - message = (message || (block && block.call) || progname).to_s - # If a newline is necessary then create a new message ending with a newline. - # Ensures that the original message is not mutated. - message = "#{message}\n" unless message[-1] == ?\n - buffer << message - auto_flush - message + @log.add(severity, message, progname, &block) end # Dynamically add methods such as: @@ -104,62 +100,20 @@ module ActiveSupport # never auto-flush. If you turn auto-flushing off, be sure to regularly # flush the log yourself -- it will eat up memory until you do. def auto_flushing=(period) - @auto_flushing = - case period - when true; 1 - when false, nil, 0; MAX_BUFFER_SIZE - when Integer; period - else raise ArgumentError, "Unrecognized auto_flushing period: #{period.inspect}" - end end + deprecate :auto_flushing= def flush - @guard.synchronize do - write_buffer(buffer) - - # Important to do this even if buffer was empty or else @buffer will - # accumulate empty arrays for each request where nothing was logged. - clear_buffer - - # Clear buffers associated with dead threads or else spawned threads - # that don't call flush will result in a memory leak. - flush_dead_buffers - end end + deprecate :flush def close - flush - @log.close if @log.respond_to?(:close) - @log = nil + @log.close end - protected - def auto_flush - flush if buffer.size >= @auto_flushing - end - - def buffer - @buffer[Thread.current] - end - - def clear_buffer - @buffer.delete(Thread.current) - end - - # Find buffers created by threads that are no longer alive and flush them to the log - # in order to prevent memory leaks from spawned threads. - def flush_dead_buffers #:nodoc: - @buffer.keys.reject{|thread| thread.alive?}.each do |thread| - buffer = @buffer[thread] - write_buffer(buffer) - @buffer.delete(thread) - end - end - - def write_buffer(buffer) - buffer.each do |content| - @log.write(content) - end - end + private + def open_logfile(log) + Logger.new log + end end end diff --git a/activesupport/lib/active_support/tagged_logging.rb b/activesupport/lib/active_support/tagged_logging.rb index 63e8837a07..c3c61e178e 100644 --- a/activesupport/lib/active_support/tagged_logging.rb +++ b/activesupport/lib/active_support/tagged_logging.rb @@ -38,9 +38,8 @@ module ActiveSupport EOM end - def flush(*args) + def flush @tags.delete(Thread.current) - @logger.flush(*args) if @logger.respond_to?(:flush) end def method_missing(method, *args) diff --git a/activesupport/test/benchmarkable_test.rb b/activesupport/test/benchmarkable_test.rb index 06f5172e1f..24b5b5bee1 100644 --- a/activesupport/test/benchmarkable_test.rb +++ b/activesupport/test/benchmarkable_test.rb @@ -3,8 +3,23 @@ require 'abstract_unit' class BenchmarkableTest < ActiveSupport::TestCase include ActiveSupport::Benchmarkable - def teardown - logger.send(:clear_buffer) + attr_reader :buffer, :logger + + class Buffer + include Enumerable + + def initialize; @lines = []; end + def each(&block); @lines.each(&block); end + def write(x); @lines << x; end + def close; end + def last; @lines.last; end + def size; @lines.size; end + def empty?; @lines.empty?; end + end + + def setup + @buffer = Buffer.new + @logger = ActiveSupport::BufferedLogger.new(@buffer) end def test_without_block @@ -40,35 +55,7 @@ class BenchmarkableTest < ActiveSupport::TestCase logger.level = ActiveSupport::BufferedLogger::DEBUG end - def test_without_silencing - benchmark('debug_run', :silence => false) do - logger.info "not silenced!" - end - - assert_equal 2, buffer.size - end - - def test_with_silencing - benchmark('debug_run', :silence => true) do - logger.info "silenced!" - end - - assert_equal 1, buffer.size - end - private - def logger - @logger ||= begin - logger = ActiveSupport::BufferedLogger.new(StringIO.new) - logger.auto_flushing = false - logger - end - end - - def buffer - logger.send(:buffer) - end - def assert_last_logged(message = 'Benchmarking') assert_match(/^#{message} \(.*\)$/, buffer.last) end diff --git a/activesupport/test/buffered_logger_test.rb b/activesupport/test/buffered_logger_test.rb index 386006677b..c818235fc0 100644 --- a/activesupport/test/buffered_logger_test.rb +++ b/activesupport/test/buffered_logger_test.rb @@ -7,6 +7,7 @@ require 'active_support/buffered_logger' class BufferedLoggerTest < Test::Unit::TestCase include MultibyteTestHelpers + include ActiveSupport::Testing::Deprecation Logger = ActiveSupport::BufferedLogger @@ -23,7 +24,10 @@ class BufferedLoggerTest < Test::Unit::TestCase t.write 'hi mom!' t.close - logger = Logger.new t.path + f = File.open(t.path, 'w') + f.binmode + + logger = Logger.new f logger.level = Logger::DEBUG str = "\x80" @@ -32,7 +36,6 @@ class BufferedLoggerTest < Test::Unit::TestCase end logger.add Logger::DEBUG, str - logger.flush ensure logger.close t.close true @@ -40,7 +43,10 @@ class BufferedLoggerTest < Test::Unit::TestCase def test_write_binary_data_create_file fname = File.join Dir.tmpdir, 'lol', 'rofl.log' - logger = Logger.new fname + f = File.open(fname, 'w') + f.binmode + + logger = Logger.new f logger.level = Logger::DEBUG str = "\x80" @@ -49,7 +55,6 @@ class BufferedLoggerTest < Test::Unit::TestCase end logger.add Logger::DEBUG, str - logger.flush ensure logger.close File.unlink fname @@ -104,34 +109,6 @@ class BufferedLoggerTest < Test::Unit::TestCase 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 @@ -139,56 +116,17 @@ class BufferedLoggerTest < Test::Unit::TestCase 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 + assert_deprecated do + @logger = Logger.new(log_file) 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 + assert File.exist?(tmp_directory) end def test_buffer_multibyte - @logger.auto_flushing = 2 @logger.info(UNICODE_STRING) @logger.info(BYTE_STRING) assert @output.string.include?(UNICODE_STRING) @@ -198,57 +136,4 @@ class BufferedLoggerTest < Test::Unit::TestCase 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 diff --git a/railties/lib/rails/application/bootstrap.rb b/railties/lib/rails/application/bootstrap.rb index c2cb121e42..1ae90056d9 100644 --- a/railties/lib/rails/application/bootstrap.rb +++ b/railties/lib/rails/application/bootstrap.rb @@ -24,9 +24,18 @@ module Rails initializer :initialize_logger, :group => :all do Rails.logger ||= config.logger || begin path = config.paths["log"].first - logger = ActiveSupport::TaggedLogging.new(ActiveSupport::BufferedLogger.new(path)) + unless File.exist? File.dirname path + FileUtils.mkdir_p File.dirname path + end + + f = File.open path, 'w' + f.binmode + f.sync = !Rails.env.production? # make sure every write flushes + + logger = ActiveSupport::TaggedLogging.new( + ActiveSupport::BufferedLogger.new(f) + ) logger.level = ActiveSupport::BufferedLogger.const_get(config.log_level.to_s.upcase) - logger.auto_flushing = false if Rails.env.production? logger rescue StandardError logger = ActiveSupport::TaggedLogging.new(ActiveSupport::BufferedLogger.new(STDERR)) @@ -37,7 +46,6 @@ module Rails ) logger end - at_exit { Rails.logger.flush if Rails.logger.respond_to?(:flush) } end # Initialize cache early in the stack so railties can make use of it. -- cgit v1.2.3