From afde6fdd5ef3e6b0693a7e330777e85ef4cffddb Mon Sep 17 00:00:00 2001 From: David Heinemeier Hansson Date: Wed, 19 Oct 2011 12:59:33 -0500 Subject: Added X-Request-Id tracking and TaggedLogging to easily log that and other production concerns --- actionpack/CHANGELOG | 2 + actionpack/lib/action_dispatch.rb | 1 + actionpack/lib/action_dispatch/http/request.rb | 10 ++++ .../lib/action_dispatch/middleware/request_id.rb | 38 ++++++++++++ actionpack/test/dispatch/request_id_test.rb | 59 +++++++++++++++++++ activesupport/CHANGELOG | 7 +++ activesupport/lib/active_support.rb | 1 + activesupport/lib/active_support/tagged_logging.rb | 68 ++++++++++++++++++++++ activesupport/test/tagged_logging_test.rb | 34 +++++++++++ railties/CHANGELOG | 2 + .../config/environments/production.rb | 3 + railties/lib/rails/application.rb | 2 + railties/lib/rails/application/bootstrap.rb | 4 +- railties/lib/rails/application/configuration.rb | 2 +- railties/lib/rails/rack.rb | 1 + railties/lib/rails/rack/logger.rb | 4 +- railties/lib/rails/rack/tagged_logging.rb | 39 +++++++++++++ 17 files changed, 272 insertions(+), 5 deletions(-) create mode 100644 actionpack/lib/action_dispatch/middleware/request_id.rb create mode 100644 actionpack/test/dispatch/request_id_test.rb create mode 100644 activesupport/lib/active_support/tagged_logging.rb create mode 100644 activesupport/test/tagged_logging_test.rb create mode 100644 railties/lib/rails/rack/tagged_logging.rb 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 -- cgit v1.2.3