Skip to content

Commit

Permalink
* ActiveSupport::BufferedLogger#silence is deprecated. If you want to…
Browse files Browse the repository at this point in the history
… 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.
  • Loading branch information
tenderlove committed Dec 10, 2011
1 parent f79b257 commit 04ef93d
Show file tree
Hide file tree
Showing 6 changed files with 96 additions and 241 deletions.
22 changes: 22 additions & 0 deletions activesupport/CHANGELOG.md
Expand Up @@ -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
Expand Down
112 changes: 33 additions & 79 deletions 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
Expand All @@ -25,40 +28,35 @@ module Severity
# 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)
Expand All @@ -67,20 +65,18 @@ def open_log(log, mode)
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:
Expand All @@ -104,62 +100,20 @@ def #{severity.downcase}? # def debug?
# 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
3 changes: 1 addition & 2 deletions activesupport/lib/active_support/tagged_logging.rb
Expand Up @@ -38,9 +38,8 @@ def #{severity}(progname = nil, &block)
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)
Expand Down
47 changes: 17 additions & 30 deletions activesupport/test/benchmarkable_test.rb
Expand Up @@ -3,8 +3,23 @@
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
Expand Down Expand Up @@ -40,35 +55,7 @@ def test_outside_level
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
Expand Down

8 comments on commit 04ef93d

@arunagw
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One test broken in ActiveSupport :-)

@josevalim
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed in cd7fbcb.

@cgriego
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One of the benefits provided by BufferredLogger was that log messages from one request would not interleave with log messages for different requests. Is there a replacement for this functionality?

@tenderlove
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It depends on what you want to achieve. If you just want to deal with production logs, then you should log the pid of your process. The default logger from stdlib will automatically log the PID for you, so you can use it instead:

log the pid

Maybe we should switch to use it by default.

@cgriego
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logging the PID would at least provide a way of sorting it out. The stdlib Logger's default format is pretty verbose and kinda haphazard. A syslog style for production, like the hodel_3000_compliant_logger gem uses, would make a nice core default. 👍

@codesnik
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I still don't get rationale behind all this. BufferedLogging with flushing after every request was really, I mean really useful. Much more useful than a little performance boost. Logging pids doesn't make it much more readable.

So, @tenderlove , was it simplifying things the point of that commit, or were there other concerns? I'm thinking about extracting old buffered logger (with autoflushing middleware) into separate gem. Is there something wrong with that idea you can warn me about?

@holli
Copy link
Contributor

@holli holli commented on 04ef93d Aug 29, 2012

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess there were some issues that if application would crash in the middle of the request you would lose all the logging.

With that in mind I would still appreciate a decent way of choosing if I want to flush log after every requetst.

Filesystem tuning didn't seem a simple thing.

I guess File.sync is now always true: https://github.com/rails/rails/blob/3-2-stable/railties/lib/rails/application/bootstrap.rb#L33

Couldn't BufferedLogger have something like def flush; log_dest.fsync; log_flushable_count = 0; end and also auto flushing after some log_count. The default could be with auto_flush = 0 but it would be easy to set some linecount like it used to be.

I'd rather have nicely outputted logs that I can use daily than the current way of having a mess that is useful with exception that happens once a year.

@shime
Copy link
Contributor

@shime shime commented on 04ef93d Sep 9, 2012

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@codesnik @holli +1

What's the point of deprecating this?

Please sign in to comment.