* 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.

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.