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

17 files changed, 272 insertions, 5 deletions

diff --git a/actionpack/CHANGELOG b/actionpack/CHANGELOG
index 29992a36b1..e7886facb9 100644
--- a/actionpack/CHANGELOG
+++ b/actionpack/CHANGELOG
@@ -1,5 +1,7 @@
 *Rails 3.2.0 (unreleased)*
 
+* Added ActionDispatch::RequestId middleware that'll make a unique X-Request-Id header available to the response and enables the ActionDispatch::Request#uuid method. This makes it easy to trace requests from end-to-end in the stack and to identify individual requests in mixed logs like Syslog [DHH]
+
 * Limit the number of options for select_year to 1000.
 
   Pass the :max_years_allowed option to set your own limit.
diff --git a/actionpack/lib/action_dispatch.rb b/actionpack/lib/action_dispatch.rb
index 7f972fc281..c13850f378 100644
--- a/actionpack/lib/action_dispatch.rb
+++ b/actionpack/lib/action_dispatch.rb
@@ -47,6 +47,7 @@ module ActionDispatch
   end
 
   autoload_under 'middleware' do
+    autoload :RequestId
     autoload :BestStandardsSupport
     autoload :Callbacks
     autoload :Cookies
diff --git a/actionpack/lib/action_dispatch/http/request.rb b/actionpack/lib/action_dispatch/http/request.rb
index 37d0a3e0b8..7a5237dcf3 100644
--- a/actionpack/lib/action_dispatch/http/request.rb
+++ b/actionpack/lib/action_dispatch/http/request.rb
@@ -177,6 +177,16 @@ module ActionDispatch
       @remote_ip ||= (@env["action_dispatch.remote_ip"] || ip).to_s
     end
 
+    # Returns the unique request id, which is based off either the X-Request-Id header that can
+    # be generated by a firewall, load balancer, or web server or by the RequestId middleware
+    # (which sets the action_dispatch.request_id environment variable).
+    #
+    # This unique ID is useful for tracing a request from end-to-end as part of logging or debugging.
+    # This relies on the rack variable set by the ActionDispatch::RequestId middleware.
+    def uuid
+      @uuid ||= env["action_dispatch.request_id"]
+    end
+
     # Returns the lowercase name of the HTTP server software.
     def server_software
       (@env['SERVER_SOFTWARE'] && /^([a-zA-Z]+)/ =~ @env['SERVER_SOFTWARE']) ? $1.downcase : nil
diff --git a/actionpack/lib/action_dispatch/middleware/request_id.rb b/actionpack/lib/action_dispatch/middleware/request_id.rb
new file mode 100644
index 0000000000..968ad6c28d
--- /dev/null
+++ b/actionpack/lib/action_dispatch/middleware/request_id.rb
@@ -0,0 +1,38 @@
+require 'digest/md5'
+
+module ActionDispatch
+  # Makes a unique request id available to the action_dispatch.request_id env variable (which is then accessible through
+  # ActionDispatch::Request#uuid) and sends the same id to the client via the X-Request-Id header.
+  #
+  # The unique request id is either based off the X-Request-Id header in the request, which would typically be generated
+  # by a firewall, load balancer, or the web server, or, if this header is not available, a random uuid. If the
+  # header is accepted from the outside world, we sanitize it to a max of 255 chars and alphanumeric and dashes only.
+  #
+  # The unique request id can be used to trace a request end-to-end and would typically end up being part of log files
+  # from multiple pieces of the stack.
+  class RequestId
+    def initialize(app)
+      @app = app
+    end
+
+    def call(env)
+      env["action_dispatch.request_id"] = external_request_id(env) || internal_request_id
+
+      status, headers, body = @app.call(env)
+
+      headers["X-Request-Id"] = env["action_dispatch.request_id"]
+      [ status, headers, body ]
+    end
+    
+    private
+      def external_request_id(env)
+        if env["HTTP_X_REQUEST_ID"].present?
+          env["HTTP_X_REQUEST_ID"].gsub(/[^\w\d\-]/, "").first(255)
+        end
+      end
+    
+      def internal_request_id
+        SecureRandom.uuid
+      end
+  end
+end
diff --git a/actionpack/test/dispatch/request_id_test.rb b/actionpack/test/dispatch/request_id_test.rb
new file mode 100644
index 0000000000..bdadbf6644
--- /dev/null
+++ b/actionpack/test/dispatch/request_id_test.rb
@@ -0,0 +1,59 @@
+require 'abstract_unit'
+
+class RequestIdTest < ActiveSupport::TestCase
+  test "passing on the request id from the outside" do
+    assert_equal "external-uu-rid", stub_request('HTTP_X_REQUEST_ID' => 'external-uu-rid').uuid
+  end
+
+  test "ensure that only alphanumeric uurids are accepted" do
+    assert_equal "X-Hacked-HeaderStuff", stub_request('HTTP_X_REQUEST_ID' => '; X-Hacked-Header: Stuff').uuid
+  end
+  
+  test "ensure that 255 char limit on the request id is being enforced" do
+    assert_equal "X" * 255, stub_request('HTTP_X_REQUEST_ID' => 'X' * 500).uuid
+  end
+  
+  test "generating a request id when none is supplied" do
+    assert_match /\w+-\w+-\w+-\w+-\w+/, stub_request.uuid
+  end
+
+  private
+    def stub_request(env = {})
+      ActionDispatch::RequestId.new(->(env) { [ 200, env, [] ] }).call(env)
+      ActionDispatch::Request.new(env)
+    end
+end
+
+# FIXME: Testing end-to-end doesn't seem to work
+# 
+# class RequestIdResponseTest < ActionDispatch::IntegrationTest
+#   class TestController < ActionController::Base
+#     def index
+#       head :ok
+#     end
+#   end
+# 
+#   test "request id is passed all the way to the response" do
+#     with_test_route_set do
+#       get '/'
+#       puts @response.headers.inspect
+#       assert_equal "internal-uu-rid", @response.headers["X-Request-Id"]
+#     end
+#   end  
+# 
+# 
+#   private
+#     def with_test_route_set
+#       with_routing do |set|
+#         set.draw do
+#           match ':action', to: ::RequestIdResponseTest::TestController
+#         end
+# 
+#         @app = self.class.build_app(set) do |middleware|
+#           middleware.use ActionDispatch::RequestId
+#         end
+# 
+#         yield
+#       end
+#     end
+# end
\ No newline at end of file
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
diff --git a/railties/CHANGELOG b/railties/CHANGELOG
index 187dd2428f..181019f851 100644
--- a/railties/CHANGELOG
+++ b/railties/CHANGELOG
@@ -1,5 +1,7 @@
 *Rails 3.2.0 (unreleased)*
 
+* Added Rails::Rack::TaggedLogging middleware by default that will apply any tags set in config.log_tags to the newly ActiveSupport::TaggedLogging Rails.logger. This makes it easy to tag log lines with debug information like subdomain and request id -- both very helpful in debugging multi-user production applications [DHH]
+
 * Default options to `rails new` can be set in ~/.railsrc [Guillermo Iguaran]
 
 * Added destroy alias to Rails engines. [Guillermo Iguaran]
diff --git a/railties/guides/code/getting_started/config/environments/production.rb b/railties/guides/code/getting_started/config/environments/production.rb
index 6ab63d30a6..4618191d6b 100644
--- a/railties/guides/code/getting_started/config/environments/production.rb
+++ b/railties/guides/code/getting_started/config/environments/production.rb
@@ -33,6 +33,9 @@ Blog::Application.configure do
   # See everything in the log (default is :info)
   # config.log_level = :debug
 
+  # Prepend all log lines with the following tags
+  # config.log_tags = [ :subdomain, :uuid ]
+
   # Use a different logger for distributed setups
   # config.logger = SyslogLogger.new
 
diff --git a/railties/lib/rails/application.rb b/railties/lib/rails/application.rb
index cbb2d23238..a097cfd1be 100644
--- a/railties/lib/rails/application.rb
+++ b/railties/lib/rails/application.rb
@@ -164,6 +164,8 @@ module Rails
         middleware.use ::Rack::Lock unless config.allow_concurrency
         middleware.use ::Rack::Runtime
         middleware.use ::Rack::MethodOverride
+        middleware.use ::ActionDispatch::RequestId
+        middleware.use ::Rails::Rack::TaggedLogging, config.log_tags
         middleware.use ::Rails::Rack::Logger # must come after Rack::MethodOverride to properly log overridden methods
         middleware.use ::ActionDispatch::ShowExceptions, config.consider_all_requests_local
         middleware.use ::ActionDispatch::RemoteIp, config.action_dispatch.ip_spoofing_check, config.action_dispatch.trusted_proxies
diff --git a/railties/lib/rails/application/bootstrap.rb b/railties/lib/rails/application/bootstrap.rb
index 0aff05b681..c2cb121e42 100644
--- a/railties/lib/rails/application/bootstrap.rb
+++ b/railties/lib/rails/application/bootstrap.rb
@@ -24,12 +24,12 @@ module Rails
       initializer :initialize_logger, :group => :all do
         Rails.logger ||= config.logger || begin
           path = config.paths["log"].first
-          logger = ActiveSupport::BufferedLogger.new(path)
+          logger = ActiveSupport::TaggedLogging.new(ActiveSupport::BufferedLogger.new(path))
           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::BufferedLogger.new(STDERR)
+          logger = ActiveSupport::TaggedLogging.new(ActiveSupport::BufferedLogger.new(STDERR))
           logger.level = ActiveSupport::BufferedLogger::WARN
           logger.warn(
             "Rails Error: Unable to access log file. Please ensure that #{path} exists and is chmod 0666. " +
diff --git a/railties/lib/rails/application/configuration.rb b/railties/lib/rails/application/configuration.rb
index 448521d2f0..8f5b28faf8 100644
--- a/railties/lib/rails/application/configuration.rb
+++ b/railties/lib/rails/application/configuration.rb
@@ -8,7 +8,7 @@ module Rails
       attr_accessor :allow_concurrency, :asset_host, :asset_path, :assets,
                     :cache_classes, :cache_store, :consider_all_requests_local,
                     :dependency_loading, :filter_parameters,
-                    :force_ssl, :helpers_paths, :logger, :preload_frameworks,
+                    :force_ssl, :helpers_paths, :logger, :log_tags, :preload_frameworks,
                     :reload_plugins, :secret_token, :serve_static_assets,
                     :ssl_options, :static_cache_control, :session_options, 
                     :time_zone, :whiny_nils
diff --git a/railties/lib/rails/rack.rb b/railties/lib/rails/rack.rb
index d1ee96f7fd..b78293e570 100644
--- a/railties/lib/rails/rack.rb
+++ b/railties/lib/rails/rack.rb
@@ -3,5 +3,6 @@ module Rails
     autoload :Debugger,      "rails/rack/debugger"
     autoload :Logger,        "rails/rack/logger"
     autoload :LogTailer,     "rails/rack/log_tailer"
+    autoload :TaggedLogging, "rails/rack/tagged_logging"
   end
 end
diff --git a/railties/lib/rails/rack/logger.rb b/railties/lib/rails/rack/logger.rb
index 3be262de08..4d388c4d10 100644
--- a/railties/lib/rails/rack/logger.rb
+++ b/railties/lib/rails/rack/logger.rb
@@ -21,8 +21,8 @@ module Rails
         request = ActionDispatch::Request.new(env)
         path = request.filtered_path
 
-        info "\n\nStarted #{request.request_method} \"#{path}\" " \
-             "for #{request.ip} at #{Time.now.to_default_s}"
+        info "\n\n"
+        info "Started #{request.request_method} \"#{path}\" for #{request.ip} at #{Time.now.to_default_s}"
       end
 
       def after_dispatch(env)
diff --git a/railties/lib/rails/rack/tagged_logging.rb b/railties/lib/rails/rack/tagged_logging.rb
new file mode 100644
index 0000000000..7980319b37
--- /dev/null
+++ b/railties/lib/rails/rack/tagged_logging.rb
@@ -0,0 +1,39 @@
+module Rails
+  module Rack
+    # Enables easy tagging of any logging activity that occurs within the Rails request cycle. The tags are configured via the
+    # config.log_tags setting. The tags can either be strings, procs taking a request argument, or the symbols :uuid or :subdomain.
+    # The latter two are then automatically expanded to request.uuid and request.subdaomins.first -- the two most common tags
+    # desired in production logs.
+    class TaggedLogging
+      def initialize(app, tags = nil)
+        @app, @tags = app, tags
+      end
+
+      def call(env)
+        if @tags
+          Rails.logger.tagged(compute_tags(env)) { @app.call(env) }
+        else
+          @app.call(env)
+        end
+      end
+      
+      private
+        def compute_tags(env)
+          request = ActionDispatch::Request.new(env)
+
+          @tags.collect do |tag|
+            case tag
+            when Proc
+              tag.call(request)
+            when :uuid
+              request.uuid
+            when :subdomain
+              request.subdomains.first
+            else
+              tag
+            end
+          end
+        end
+    end
+  end
+end