Skip to content
This repository
Browse code

Added X-Request-Id tracking and TaggedLogging to easily log that and …

…other production concerns
  • Loading branch information...
commit afde6fdd5ef3e6b0693a7e330777e85ef4cffddb 1 parent 3a746f7
David Heinemeier Hansson authored October 19, 2011
2  actionpack/CHANGELOG
... ...
@@ -1,5 +1,7 @@
1 1
 *Rails 3.2.0 (unreleased)*
2 2
 
  3
+* 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]
  4
+
3 5
 * Limit the number of options for select_year to 1000.
4 6
 
5 7
   Pass the :max_years_allowed option to set your own limit.
1  actionpack/lib/action_dispatch.rb
@@ -47,6 +47,7 @@ module ActionDispatch
47 47
   end
48 48
 
49 49
   autoload_under 'middleware' do
  50
+    autoload :RequestId
50 51
     autoload :BestStandardsSupport
51 52
     autoload :Callbacks
52 53
     autoload :Cookies
10  actionpack/lib/action_dispatch/http/request.rb
@@ -177,6 +177,16 @@ def remote_ip
177 177
       @remote_ip ||= (@env["action_dispatch.remote_ip"] || ip).to_s
178 178
     end
179 179
 
  180
+    # Returns the unique request id, which is based off either the X-Request-Id header that can
  181
+    # be generated by a firewall, load balancer, or web server or by the RequestId middleware
  182
+    # (which sets the action_dispatch.request_id environment variable).
  183
+    #
  184
+    # This unique ID is useful for tracing a request from end-to-end as part of logging or debugging.
  185
+    # This relies on the rack variable set by the ActionDispatch::RequestId middleware.
  186
+    def uuid
  187
+      @uuid ||= env["action_dispatch.request_id"]
  188
+    end
  189
+
180 190
     # Returns the lowercase name of the HTTP server software.
181 191
     def server_software
182 192
       (@env['SERVER_SOFTWARE'] && /^([a-zA-Z]+)/ =~ @env['SERVER_SOFTWARE']) ? $1.downcase : nil
38  actionpack/lib/action_dispatch/middleware/request_id.rb
... ...
@@ -0,0 +1,38 @@
  1
+require 'digest/md5'
  2
+
  3
+module ActionDispatch
  4
+  # Makes a unique request id available to the action_dispatch.request_id env variable (which is then accessible through
  5
+  # ActionDispatch::Request#uuid) and sends the same id to the client via the X-Request-Id header.
  6
+  #
  7
+  # The unique request id is either based off the X-Request-Id header in the request, which would typically be generated
  8
+  # by a firewall, load balancer, or the web server, or, if this header is not available, a random uuid. If the
  9
+  # header is accepted from the outside world, we sanitize it to a max of 255 chars and alphanumeric and dashes only.
  10
+  #
  11
+  # The unique request id can be used to trace a request end-to-end and would typically end up being part of log files
  12
+  # from multiple pieces of the stack.
  13
+  class RequestId
  14
+    def initialize(app)
  15
+      @app = app
  16
+    end
  17
+
  18
+    def call(env)
  19
+      env["action_dispatch.request_id"] = external_request_id(env) || internal_request_id
  20
+
  21
+      status, headers, body = @app.call(env)
  22
+
  23
+      headers["X-Request-Id"] = env["action_dispatch.request_id"]
  24
+      [ status, headers, body ]
  25
+    end
  26
+    
  27
+    private
  28
+      def external_request_id(env)
  29
+        if env["HTTP_X_REQUEST_ID"].present?
  30
+          env["HTTP_X_REQUEST_ID"].gsub(/[^\w\d\-]/, "").first(255)
  31
+        end
  32
+      end
  33
+    
  34
+      def internal_request_id
  35
+        SecureRandom.uuid
  36
+      end
  37
+  end
  38
+end
59  actionpack/test/dispatch/request_id_test.rb
... ...
@@ -0,0 +1,59 @@
  1
+require 'abstract_unit'
  2
+
  3
+class RequestIdTest < ActiveSupport::TestCase
  4
+  test "passing on the request id from the outside" do
  5
+    assert_equal "external-uu-rid", stub_request('HTTP_X_REQUEST_ID' => 'external-uu-rid').uuid
  6
+  end
  7
+
  8
+  test "ensure that only alphanumeric uurids are accepted" do
  9
+    assert_equal "X-Hacked-HeaderStuff", stub_request('HTTP_X_REQUEST_ID' => '; X-Hacked-Header: Stuff').uuid
  10
+  end
  11
+  
  12
+  test "ensure that 255 char limit on the request id is being enforced" do
  13
+    assert_equal "X" * 255, stub_request('HTTP_X_REQUEST_ID' => 'X' * 500).uuid
  14
+  end
  15
+  
  16
+  test "generating a request id when none is supplied" do
  17
+    assert_match /\w+-\w+-\w+-\w+-\w+/, stub_request.uuid
  18
+  end
  19
+
  20
+  private
  21
+    def stub_request(env = {})
  22
+      ActionDispatch::RequestId.new(->(env) { [ 200, env, [] ] }).call(env)
  23
+      ActionDispatch::Request.new(env)
  24
+    end
  25
+end
  26
+
  27
+# FIXME: Testing end-to-end doesn't seem to work
  28
+# 
  29
+# class RequestIdResponseTest < ActionDispatch::IntegrationTest
  30
+#   class TestController < ActionController::Base
  31
+#     def index
  32
+#       head :ok
  33
+#     end
  34
+#   end
  35
+# 
  36
+#   test "request id is passed all the way to the response" do
  37
+#     with_test_route_set do
  38
+#       get '/'
  39
+#       puts @response.headers.inspect
  40
+#       assert_equal "internal-uu-rid", @response.headers["X-Request-Id"]
  41
+#     end
  42
+#   end  
  43
+# 
  44
+# 
  45
+#   private
  46
+#     def with_test_route_set
  47
+#       with_routing do |set|
  48
+#         set.draw do
  49
+#           match ':action', to: ::RequestIdResponseTest::TestController
  50
+#         end
  51
+# 
  52
+#         @app = self.class.build_app(set) do |middleware|
  53
+#           middleware.use ActionDispatch::RequestId
  54
+#         end
  55
+# 
  56
+#         yield
  57
+#       end
  58
+#     end
  59
+# end
7  activesupport/CHANGELOG
... ...
@@ -1,5 +1,12 @@
1 1
 *Rails 3.2.0 (unreleased)*
2 2
 
  3
+* Added ActiveSupport:TaggedLogging that can wrap any standard Logger class to provide tagging capabilities [DHH]
  4
+
  5
+    Logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
  6
+    Logger.tagged("BCX") { Logger.info "Stuff" }                            # Logs "[BCX] Stuff"
  7
+    Logger.tagged("BCX", "Jason") { Logger.info "Stuff" }                   # Logs "[BCX] [Jason] Stuff"
  8
+    Logger.tagged("BCX") { Logger.tagged("Jason") { Logger.info "Stuff" } } # Logs "[BCX] [Jason] Stuff"
  9
+  
3 10
 * 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]
4 11
 
5 12
 * ActiveSupport::OrderedHash is now marked as extractable when using Array#extract_options! [Prem Sichanugrist]
1  activesupport/lib/active_support.rb
@@ -71,6 +71,7 @@ module ActiveSupport
71 71
     autoload :OrderedOptions
72 72
     autoload :Rescuable
73 73
     autoload :StringInquirer
  74
+    autoload :TaggedLogging
74 75
     autoload :XmlMini
75 76
   end
76 77
 
68  activesupport/lib/active_support/tagged_logging.rb
... ...
@@ -0,0 +1,68 @@
  1
+module ActiveSupport
  2
+  # Wraps any standard Logger class to provide tagging capabilities. Examples:
  3
+  #
  4
+  #   Logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
  5
+  #   Logger.tagged("BCX") { Logger.info "Stuff" }                            # Logs "[BCX] Stuff"
  6
+  #   Logger.tagged("BCX", "Jason") { Logger.info "Stuff" }                   # Logs "[BCX] [Jason] Stuff"
  7
+  #   Logger.tagged("BCX") { Logger.tagged("Jason") { Logger.info "Stuff" } } # Logs "[BCX] [Jason] Stuff"
  8
+  #
  9
+  # This is used by the default Rails.logger as configured by Railties to make it easy to stamp log lines
  10
+  # with subdomains, request ids, and anything else to aid debugging of multi-user production applications.
  11
+  class TaggedLogging
  12
+    def initialize(logger)
  13
+      @logger = logger
  14
+      @tags   = []
  15
+    end
  16
+
  17
+    def tagged(*tags)
  18
+      new_tags = Array.wrap(tags).flatten
  19
+      @tags += new_tags
  20
+      yield
  21
+    ensure
  22
+      new_tags.size.times { @tags.pop }
  23
+    end
  24
+
  25
+
  26
+    def add(severity, message = nil, progname = nil, &block)
  27
+      @logger.add(severity, "#{tags}#{message}", progname, &block)
  28
+    end
  29
+
  30
+
  31
+    def fatal(progname = nil, &block)
  32
+      add(@logger.class::FATAL, progname, &block)
  33
+    end
  34
+
  35
+    def error(progname = nil, &block)
  36
+      add(@logger.class::ERROR, progname, &block)
  37
+    end
  38
+
  39
+    def warn(progname = nil, &block)
  40
+      add(@logger.class::WARN, progname, &block)
  41
+    end
  42
+
  43
+    def info(progname = nil, &block)
  44
+      add(@logger.class::INFO, progname, &block)
  45
+    end
  46
+
  47
+    def debug(progname = nil, &block)
  48
+      add(@logger.class::DEBUG, progname, &block)
  49
+    end
  50
+
  51
+    def unknown(progname = nil, &block)
  52
+      add(@logger.class::UNKNOWN, progname, &block)
  53
+    end
  54
+
  55
+
  56
+    def method_missing(method, *args)
  57
+      @logger.send(method, *args)
  58
+    end
  59
+    
  60
+
  61
+    private
  62
+      def tags
  63
+        if @tags.any?
  64
+          @tags.collect { |tag| "[#{tag}]" }.join(" ") + " "
  65
+        end
  66
+      end
  67
+  end
  68
+end
34  activesupport/test/tagged_logging_test.rb
... ...
@@ -0,0 +1,34 @@
  1
+require 'abstract_unit'
  2
+require 'active_support/core_ext/logger'
  3
+require 'active_support/tagged_logging'
  4
+
  5
+class TaggedLoggingTest < ActiveSupport::TestCase
  6
+  setup do
  7
+    @output = StringIO.new
  8
+    @logger = ActiveSupport::TaggedLogging.new(Logger.new(@output))
  9
+  end
  10
+
  11
+  test "tagged once" do
  12
+    @logger.tagged("BCX") { @logger.info "Funky time" }
  13
+    assert_equal "[BCX] Funky time\n", @output.string
  14
+  end
  15
+  
  16
+  test "tagged twice" do
  17
+    @logger.tagged("BCX") { @logger.tagged("Jason") { @logger.info "Funky time" } }
  18
+    assert_equal "[BCX] [Jason] Funky time\n", @output.string
  19
+  end
  20
+
  21
+  test "tagged thrice at once" do
  22
+    @logger.tagged("BCX", "Jason", "New") { @logger.info "Funky time" }
  23
+    assert_equal "[BCX] [Jason] [New] Funky time\n", @output.string
  24
+  end
  25
+
  26
+  test "mixed levels of tagging" do
  27
+    @logger.tagged("BCX") do
  28
+      @logger.tagged("Jason") { @logger.info "Funky time" }
  29
+      @logger.info "Junky time!"
  30
+    end
  31
+
  32
+    assert_equal "[BCX] [Jason] Funky time\n[BCX] Junky time!\n", @output.string
  33
+  end
  34
+end
2  railties/CHANGELOG
... ...
@@ -1,5 +1,7 @@
1 1
 *Rails 3.2.0 (unreleased)*
2 2
 
  3
+* 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]
  4
+
3 5
 * Default options to `rails new` can be set in ~/.railsrc [Guillermo Iguaran]
4 6
 
5 7
 * Added destroy alias to Rails engines. [Guillermo Iguaran]
3  railties/guides/code/getting_started/config/environments/production.rb
@@ -33,6 +33,9 @@
33 33
   # See everything in the log (default is :info)
34 34
   # config.log_level = :debug
35 35
 
  36
+  # Prepend all log lines with the following tags
  37
+  # config.log_tags = [ :subdomain, :uuid ]
  38
+
36 39
   # Use a different logger for distributed setups
37 40
   # config.logger = SyslogLogger.new
38 41
 
2  railties/lib/rails/application.rb
@@ -164,6 +164,8 @@ def default_middleware_stack
164 164
         middleware.use ::Rack::Lock unless config.allow_concurrency
165 165
         middleware.use ::Rack::Runtime
166 166
         middleware.use ::Rack::MethodOverride
  167
+        middleware.use ::ActionDispatch::RequestId
  168
+        middleware.use ::Rails::Rack::TaggedLogging, config.log_tags
167 169
         middleware.use ::Rails::Rack::Logger # must come after Rack::MethodOverride to properly log overridden methods
168 170
         middleware.use ::ActionDispatch::ShowExceptions, config.consider_all_requests_local
169 171
         middleware.use ::ActionDispatch::RemoteIp, config.action_dispatch.ip_spoofing_check, config.action_dispatch.trusted_proxies
4  railties/lib/rails/application/bootstrap.rb
@@ -24,12 +24,12 @@ module Bootstrap
24 24
       initializer :initialize_logger, :group => :all do
25 25
         Rails.logger ||= config.logger || begin
26 26
           path = config.paths["log"].first
27  
-          logger = ActiveSupport::BufferedLogger.new(path)
  27
+          logger = ActiveSupport::TaggedLogging.new(ActiveSupport::BufferedLogger.new(path))
28 28
           logger.level = ActiveSupport::BufferedLogger.const_get(config.log_level.to_s.upcase)
29 29
           logger.auto_flushing = false if Rails.env.production?
30 30
           logger
31 31
         rescue StandardError
32  
-          logger = ActiveSupport::BufferedLogger.new(STDERR)
  32
+          logger = ActiveSupport::TaggedLogging.new(ActiveSupport::BufferedLogger.new(STDERR))
33 33
           logger.level = ActiveSupport::BufferedLogger::WARN
34 34
           logger.warn(
35 35
             "Rails Error: Unable to access log file. Please ensure that #{path} exists and is chmod 0666. " +
2  railties/lib/rails/application/configuration.rb
@@ -8,7 +8,7 @@ class Configuration < ::Rails::Engine::Configuration
8 8
       attr_accessor :allow_concurrency, :asset_host, :asset_path, :assets,
9 9
                     :cache_classes, :cache_store, :consider_all_requests_local,
10 10
                     :dependency_loading, :filter_parameters,
11  
-                    :force_ssl, :helpers_paths, :logger, :preload_frameworks,
  11
+                    :force_ssl, :helpers_paths, :logger, :log_tags, :preload_frameworks,
12 12
                     :reload_plugins, :secret_token, :serve_static_assets,
13 13
                     :ssl_options, :static_cache_control, :session_options, 
14 14
                     :time_zone, :whiny_nils
1  railties/lib/rails/rack.rb
@@ -3,5 +3,6 @@ module Rack
3 3
     autoload :Debugger,      "rails/rack/debugger"
4 4
     autoload :Logger,        "rails/rack/logger"
5 5
     autoload :LogTailer,     "rails/rack/log_tailer"
  6
+    autoload :TaggedLogging, "rails/rack/tagged_logging"
6 7
   end
7 8
 end
4  railties/lib/rails/rack/logger.rb
@@ -21,8 +21,8 @@ def before_dispatch(env)
21 21
         request = ActionDispatch::Request.new(env)
22 22
         path = request.filtered_path
23 23
 
24  
-        info "\n\nStarted #{request.request_method} \"#{path}\" " \
25  
-             "for #{request.ip} at #{Time.now.to_default_s}"
  24
+        info "\n\n"
  25
+        info "Started #{request.request_method} \"#{path}\" for #{request.ip} at #{Time.now.to_default_s}"
26 26
       end
27 27
 
28 28
       def after_dispatch(env)
39  railties/lib/rails/rack/tagged_logging.rb
... ...
@@ -0,0 +1,39 @@
  1
+module Rails
  2
+  module Rack
  3
+    # Enables easy tagging of any logging activity that occurs within the Rails request cycle. The tags are configured via the
  4
+    # config.log_tags setting. The tags can either be strings, procs taking a request argument, or the symbols :uuid or :subdomain.
  5
+    # The latter two are then automatically expanded to request.uuid and request.subdaomins.first -- the two most common tags
  6
+    # desired in production logs.
  7
+    class TaggedLogging
  8
+      def initialize(app, tags = nil)
  9
+        @app, @tags = app, tags
  10
+      end
  11
+
  12
+      def call(env)
  13
+        if @tags
  14
+          Rails.logger.tagged(compute_tags(env)) { @app.call(env) }
  15
+        else
  16
+          @app.call(env)
  17
+        end
  18
+      end
  19
+      
  20
+      private
  21
+        def compute_tags(env)
  22
+          request = ActionDispatch::Request.new(env)
  23
+
  24
+          @tags.collect do |tag|
  25
+            case tag
  26
+            when Proc
  27
+              tag.call(request)
  28
+            when :uuid
  29
+              request.uuid
  30
+            when :subdomain
  31
+              request.subdomains.first
  32
+            else
  33
+              tag
  34
+            end
  35
+          end
  36
+        end
  37
+    end
  38
+  end
  39
+end

5 notes on commit afde6fd

José Valim

I believe we have a :subdomain method in the request (if not, we could add it). That said, this could probably be something like:

when Symbol
  request.send(tag)
José Valim

This is not thread safe. We should probably keep a hash where the key is the thread id and the tags the values.

Daniel Schierbeck

So Rails 3.2 is going to be Ruby 1.9 only?

Vijay Dev

No, it won't be. This needs to change to the 1.8.7 syntax.

Jason Morrison

Would it be useful to default to including this header in XHR calls initiated from the page too, or should that be counted as a new request stack? E.g. an addition to jquery_ujs.js

José Valim
Owner

This is to identify all logging for the same request. It does not intend to identity a user across requests.

Erik Peterson

This is quite useful...off to see if an F5 can generate the uuid.

Marc Bowes

Doesn't \w include [a-zA-Z0-9_], thus making the \d unnecessary?

José Valim

Yup. Pull request please? OR do you prefer if I change it myself (faster)?

Tim Pease

Use a thread local variable to store the tags, and provide an accessor method. All access to the tags would be through the accessor - any code that references @tags would need to be modified.

def tags
  Thread.current[:tagged_logging] ||= []
end

def formatted_tags
  if tags.any?
    tags.collect { |tag| "#{tag}" }.join(" ") + " "
  end
end
Jeremy Kemper
Owner

Build red! Need to update Railties' test/application/rack/logger_test.rb

Aaron Patterson
Owner

Seems like a good candidate for reverting. :heart:

Paul Donohue

My organization has been doing exactly what your patch here does for a few years now (and amusingly enough, I was literally just updating our Rails-related documentation on it when I stumbled across this commit). However, our header is "X-Request-ID", and that case-sensitive name has ended up in a large number of applications (using a large number of different languages and frameworks, not just Rails), so it would not be trivial for me to change the case of my header name, and as currently written, this particular line of code won't work for me.

Any chance you could change this to X-Request-ID? If not, is there a way to make this more generic? Perhaps allow the application developer to specify the name of the header instead of hard-coding it here?

José Valim

We could make it configurable. The header key could be a parameter given to the middleware on initialization here: afde6fd#L11R167

The configuration name could be config.action_dispatch.request_id_header and the default could be set here:

https://github.com/rails/rails/blob/master/actionpack/lib/action_dispatch/railtie.rb#L5

A patch with tests would be welcome.

Pascal Hurni

This is only available on MRI 1.9, not on 1.8.7, don't known for other rubies.
Maybe should be wrapped behind ActiveSupport

Steve Klabnik

Rails only supports 1.9.3. (on master)

Pascal Hurni

Maybe rails4 but master is still rails 3.2, no?
I just looked at the guides and even edge guides (http://edgeguides.rubyonrails.org/getting_started.html#guide-assumptions), they still set the minimum to 1.8.7.

Rafael Mendonça França

@phurni also master is 4.0. So we need to change that guide. Doing now.

Paul Donohue

Why are other characters stripped out? My load balancers seem to be including @ characters in the request ID sometimes, and the fact that this code strips that out ends up breaking things. Would it hurt anything to leave it there?

Please sign in to comment.
Something went wrong with that request. Please try again.