Added X-Request-Id tracking and TaggedLogging to easily log that and other production concerns

4 files changed, 110 insertions, 0 deletions

diff --git a/activesupport/CHANGELOG b/activesupport/CHANGELOG
index 63f406cd9f..d3a838cff0 100644
--- a/activesupport/CHANGELOG
+++ b/activesupport/CHANGELOG
@@ -1,5 +1,12 @@
 *Rails 3.2.0 (unreleased)*
 
+* Added ActiveSupport:TaggedLogging that can wrap any standard Logger class to provide tagging capabilities [DHH]
+
+    Logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
+    Logger.tagged("BCX") { Logger.info "Stuff" }                            # Logs "[BCX] Stuff"
+    Logger.tagged("BCX", "Jason") { Logger.info "Stuff" }                   # Logs "[BCX] [Jason] Stuff"
+    Logger.tagged("BCX") { Logger.tagged("Jason") { Logger.info "Stuff" } } # Logs "[BCX] [Jason] Stuff"
+  
 * Added safe_constantize that constantizes a string but returns nil instead of an exception if the constant (or part of it) does not exist [Ryan Oblak]
 
 * ActiveSupport::OrderedHash is now marked as extractable when using Array#extract_options! [Prem Sichanugrist]
diff --git a/activesupport/lib/active_support.rb b/activesupport/lib/active_support.rb
index cc9ea5cffa..ff78e718f2 100644
--- a/activesupport/lib/active_support.rb
+++ b/activesupport/lib/active_support.rb
@@ -71,6 +71,7 @@ module ActiveSupport
     autoload :OrderedOptions
     autoload :Rescuable
     autoload :StringInquirer
+    autoload :TaggedLogging
     autoload :XmlMini
   end
 
diff --git a/activesupport/lib/active_support/tagged_logging.rb b/activesupport/lib/active_support/tagged_logging.rb
new file mode 100644
index 0000000000..0d8504bc1f
--- /dev/null
+++ b/activesupport/lib/active_support/tagged_logging.rb
@@ -0,0 +1,68 @@
+module ActiveSupport
+  # Wraps any standard Logger class to provide tagging capabilities. Examples:
+  #
+  #   Logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
+  #   Logger.tagged("BCX") { Logger.info "Stuff" }                            # Logs "[BCX] Stuff"
+  #   Logger.tagged("BCX", "Jason") { Logger.info "Stuff" }                   # Logs "[BCX] [Jason] Stuff"
+  #   Logger.tagged("BCX") { Logger.tagged("Jason") { Logger.info "Stuff" } } # Logs "[BCX] [Jason] Stuff"
+  #
+  # This is used by the default Rails.logger as configured by Railties to make it easy to stamp log lines
+  # with subdomains, request ids, and anything else to aid debugging of multi-user production applications.
+  class TaggedLogging
+    def initialize(logger)
+      @logger = logger
+      @tags   = []
+    end
+
+    def tagged(*tags)
+      new_tags = Array.wrap(tags).flatten
+      @tags += new_tags
+      yield
+    ensure
+      new_tags.size.times { @tags.pop }
+    end
+
+
+    def add(severity, message = nil, progname = nil, &block)
+      @logger.add(severity, "#{tags}#{message}", progname, &block)
+    end
+
+
+    def fatal(progname = nil, &block)
+      add(@logger.class::FATAL, progname, &block)
+    end
+
+    def error(progname = nil, &block)
+      add(@logger.class::ERROR, progname, &block)
+    end
+
+    def warn(progname = nil, &block)
+      add(@logger.class::WARN, progname, &block)
+    end
+
+    def info(progname = nil, &block)
+      add(@logger.class::INFO, progname, &block)
+    end
+
+    def debug(progname = nil, &block)
+      add(@logger.class::DEBUG, progname, &block)
+    end
+
+    def unknown(progname = nil, &block)
+      add(@logger.class::UNKNOWN, progname, &block)
+    end
+
+
+    def method_missing(method, *args)
+      @logger.send(method, *args)
+    end
+    
+
+    private
+      def tags
+        if @tags.any?
+          @tags.collect { |tag| "[#{tag}]" }.join(" ") + " "
+        end
+      end
+  end
+end
diff --git a/activesupport/test/tagged_logging_test.rb b/activesupport/test/tagged_logging_test.rb
new file mode 100644
index 0000000000..a1504c6ce4
--- /dev/null
+++ b/activesupport/test/tagged_logging_test.rb
@@ -0,0 +1,34 @@
+require 'abstract_unit'
+require 'active_support/core_ext/logger'
+require 'active_support/tagged_logging'
+
+class TaggedLoggingTest < ActiveSupport::TestCase
+  setup do
+    @output = StringIO.new
+    @logger = ActiveSupport::TaggedLogging.new(Logger.new(@output))
+  end
+
+  test "tagged once" do
+    @logger.tagged("BCX") { @logger.info "Funky time" }
+    assert_equal "[BCX] Funky time\n", @output.string
+  end
+  
+  test "tagged twice" do
+    @logger.tagged("BCX") { @logger.tagged("Jason") { @logger.info "Funky time" } }
+    assert_equal "[BCX] [Jason] Funky time\n", @output.string
+  end
+
+  test "tagged thrice at once" do
+    @logger.tagged("BCX", "Jason", "New") { @logger.info "Funky time" }
+    assert_equal "[BCX] [Jason] [New] Funky time\n", @output.string
+  end
+
+  test "mixed levels of tagging" do
+    @logger.tagged("BCX") do
+      @logger.tagged("Jason") { @logger.info "Funky time" }
+      @logger.info "Junky time!"
+    end
+
+    assert_equal "[BCX] [Jason] Funky time\n[BCX] Junky time!\n", @output.string
+  end
+end