Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

clean up remaining log flushing support #13651

Open
wants to merge 2 commits into from

2 participants

@cainlevy

Currently, ActiveSupport::TaggedLogging#flush will clear out any tags before trying to call flush on the wrapped Logger, which no longer happens. The tag clearing logic appears to have been intentional when it was originally committed but we have been unable to imagine the use case.

This seems like an odd coupling. The coupled behaviors (clearing tags + flushing buffered logging to file) no longer appear to benefit Rails' own code, but can cause bugs when other code attempts to use Rails.logger.tagged{...}.

Rails' Code

The only place where I can find Rails calling #flush is via ActiveSupport::LogSubscriber.flush_all!. And the only place where I can find Rails calling that is from Rails::Rack::Logger#call_app.

In this case, the #flush logic is redundant because the next operation after #call_app - when tags are in use - is to pop the request's tags back off the stack. That ends up being a noop because the stack was just emptied.

Our Bug

I added a tag to our Delayed::Job workers so I could associate output with specific processes. I noticed that the tag was disappearing shortly after the process started, and eventually tracked it down to a particular job using the urbanairship gem, which still flushes after logging.

The Cleanup

Minimally, I would like to remove ActiveSupport::TaggedLogging#flush.

But at that point, I think there is no remaining logger that will respond_to?(:flush), which means that ActiveSupport::LogSubscriber#flush_all! is no longer effective and can also be removed. So I've cleaned up all the tendrils.

cainlevy added some commits
@cainlevy cainlevy keep logger tags on flush
clearing tags on flush is an oddly coupled side effect, and flushing
isn't really even used by current code.
0726a4c
@cainlevy cainlevy remove remaining support for manual log flushing e382b3d
@jeremy
Owner

Agree that clearing tags on flush doesn't (and didn't) make sense.

Removing #flush calls entirely is probably premature. Folks may still set Rails.logger to a logger that expects to be flushed, so that expectation would need to be properly deprecated.

@cainlevy

thanks @jeremy. should i add the deprecation? if that's a bigger decision, i'm happy to just update the tagging behavior.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on Jan 9, 2014
  1. @cainlevy

    keep logger tags on flush

    cainlevy authored
    clearing tags on flush is an oddly coupled side effect, and flushing
    isn't really even used by current code.
  2. @cainlevy
This page is out of date. Refresh to see the latest.
View
9 activesupport/lib/active_support/log_subscriber.rb
@@ -30,10 +30,6 @@ module ActiveSupport
# After configured, whenever a "sql.active_record" notification is published,
# it will properly dispatch the event (ActiveSupport::Notifications::Event) to
# the sql method.
- #
- # Log subscriber also has some helpers to deal with logging and automatically
- # flushes all logs when the request finishes (via action_dispatch.callback
- # notification) in a Rails environment.
class LogSubscriber < Subscriber
# Embed in a String to clear all previous ANSI sequences.
CLEAR = "\e[0m"
@@ -64,11 +60,6 @@ def logger
def log_subscribers
subscribers
end
-
- # Flush all log_subscribers' logger.
- def flush_all!
- logger.flush if logger.respond_to?(:flush)
- end
end
def logger
View
6 activesupport/lib/active_support/log_subscriber/test_helper.rb
@@ -52,11 +52,9 @@ def teardown
class MockLogger
include ActiveSupport::Logger::Severity
- attr_reader :flush_count
attr_accessor :level
def initialize(level = DEBUG)
- @flush_count = 0
@level = level
@logged = Hash.new { |h,k| h[k] = [] }
end
@@ -73,10 +71,6 @@ def logged(level)
@logged[level].compact.map { |l| l.to_s.strip }
end
- def flush
- @flush_count += 1
- end
-
ActiveSupport::Logger::Severity.constants.each do |severity|
class_eval <<-EOT, __FILE__, __LINE__ + 1
def #{severity.downcase}?
View
5 activesupport/lib/active_support/tagged_logging.rb
@@ -67,10 +67,5 @@ def self.new(logger)
def tagged(*tags)
formatter.tagged(*tags) { yield self }
end
-
- def flush
- clear_tags!
- super if defined?(super)
- end
end
end
View
14 activesupport/test/log_subscriber_test.rb
@@ -94,20 +94,6 @@ def test_does_not_fail_with_non_namespaced_events
wait
end
- def test_flushes_loggers
- ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
- ActiveSupport::LogSubscriber.flush_all!
- assert_equal 1, @logger.flush_count
- end
-
- def test_flushes_the_same_logger_just_once
- ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
- ActiveSupport::LogSubscriber.attach_to :another, @log_subscriber
- ActiveSupport::LogSubscriber.flush_all!
- wait
- assert_equal 1, @logger.flush_count
- end
-
def test_logging_does_not_die_on_failures
ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
instrument "puke.my_log_subscriber"
View
20 activesupport/test/tagged_logging_test.rb
@@ -3,15 +3,9 @@
require 'active_support/tagged_logging'
class TaggedLoggingTest < ActiveSupport::TestCase
- class MyLogger < ::ActiveSupport::Logger
- def flush(*)
- info "[FLUSHED]"
- end
- end
-
setup do
@output = StringIO.new
- @logger = ActiveSupport::TaggedLogging.new(MyLogger.new(@output))
+ @logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(@output))
end
test 'sets logger.formatter if missing and extends it with a tagging API' do
@@ -79,18 +73,6 @@ def flush(*)
assert_equal "[OMG] Cool story bro\n[BCX] Funky time\n", @output.string
end
- test "cleans up the taggings on flush" do
- @logger.tagged("BCX") do
- Thread.new do
- @logger.tagged("OMG") do
- @logger.flush
- @logger.info "Cool story bro"
- end
- end.join
- end
- assert_equal "[FLUSHED]\nCool story bro\n", @output.string
- end
-
test "mixed levels of tagging" do
@logger.tagged("BCX") do
@logger.tagged("Jason") { @logger.info "Funky time" }
View
4 railties/lib/rails/rack/logger.rb
@@ -6,7 +6,7 @@
module Rails
module Rack
- # Sets log tags, logs the request, calls the app, and flushes the logs.
+ # Sets log tags, logs the request, and calls the app.
class Logger < ActiveSupport::LogSubscriber
def initialize(app, taggers = nil)
@app = app
@@ -41,8 +41,6 @@ def call_app(request, env)
rescue Exception
finish(request)
raise
- ensure
- ActiveSupport::LogSubscriber.flush_all!
end
# Started GET "/session/new" for 127.0.0.1 at 2012-09-26 14:51:42 -0700
Something went wrong with that request. Please try again.