diff --git a/config/environments/production.rb b/config/environments/production.rb index d58644a..369bb5b 100644 --- a/config/environments/production.rb +++ b/config/environments/production.rb @@ -1,5 +1,6 @@ require "active_support/core_ext/integer/time" require "active_support/core_ext/numeric/bytes" +require_relative "../../lib/rails_ext/log_scrubbing_formatter" Rails.application.configure do # Settings specified here will take precedence over those in config/application.rb. @@ -50,7 +51,7 @@ Rails.application.configure do # Log to STDOUT by default config.logger = ActiveSupport::Logger.new(STDOUT) - .tap { |logger| logger.formatter = ::Logger::Formatter.new } + .tap { |logger| logger.formatter = LogScrubbingFormatter.new } .then { |logger| ActiveSupport::TaggedLogging.new(logger) } # Prepend all log lines with the following tags. diff --git a/lib/rails_ext/log_scrubbing_formatter.rb b/lib/rails_ext/log_scrubbing_formatter.rb new file mode 100644 index 0000000..231fae9 --- /dev/null +++ b/lib/rails_ext/log_scrubbing_formatter.rb @@ -0,0 +1,16 @@ +# Bot requests carry the bot key as a URL path segment (/rooms/:room_id/:bot_key/...). +# config.filter_parameters redacts query and form parameters but never path segments, +# so the key would otherwise be written verbatim to the request log. Redact it wherever +# it appears in a formatted log line. +class LogScrubbingFormatter < ::Logger::Formatter + BOT_KEY_IN_PATH = %r{(/rooms/\d+/)\d+-[A-Za-z0-9]+} + + def call(severity, time, progname, message) + scrub(super) + end + + private + def scrub(line) + line.gsub(BOT_KEY_IN_PATH, '\1[FILTERED]') + end +end diff --git a/test/lib/rails_ext/log_scrubbing_formatter_test.rb b/test/lib/rails_ext/log_scrubbing_formatter_test.rb new file mode 100644 index 0000000..307e126 --- /dev/null +++ b/test/lib/rails_ext/log_scrubbing_formatter_test.rb @@ -0,0 +1,54 @@ +require "test_helper" + +class LogScrubbingFormatterTest < ActiveSupport::TestCase + setup { @formatter = LogScrubbingFormatter.new } + + test "redacts the bot key path segment from a request log line" do + line = format(%(Started POST "/rooms/1/5-Ab3xK9mQz1Rt/messages" for 203.0.113.10)) + assert_includes line, "/rooms/1/[FILTERED]/messages" + assert_not_includes line, "Ab3xK9mQz1Rt" + end + + test "redacts the bot key reflected in a pagination Link header" do + line = format(%(Link: ; rel="next")) + assert_includes line, "/rooms/42/[FILTERED]/messages?before=99" + assert_not_includes line, "Zt9QmK1xz3Ab" + end + + test "redacts every occurrence on a line" do + line = format("/rooms/1/5-Ab3xK9mQz1Rt/messages and /rooms/2/6-Cd4yL0nR2St7/messages/9/boosts") + assert_not_includes line, "Ab3xK9mQz1Rt" + assert_not_includes line, "Cd4yL0nR2St7" + assert_equal 2, line.scan("[FILTERED]").length + end + + test "leaves non-bot room paths untouched" do + line = format(%(Started GET "/rooms/1/messages" for 203.0.113.10)) + assert_includes line, "/rooms/1/messages" + assert_not_includes line, "[FILTERED]" + end + + test "preserves surrounding log content" do + line = format("hello") + assert_includes line, "hello" + end + + test "scrubs through the TaggedLogging + STDOUT logger stack as production wires it" do + io = StringIO.new + logger = ActiveSupport::Logger.new(io) + .tap { |logger| logger.formatter = LogScrubbingFormatter.new } + .then { |logger| ActiveSupport::TaggedLogging.new(logger) } + + logger.tagged("req-123") { logger.info(%(Started POST "/rooms/1/5-Ab3xK9mQz1Rt/messages")) } + + output = io.string + assert_includes output, "[req-123]" + assert_includes output, "/rooms/1/[FILTERED]/messages" + assert_not_includes output, "Ab3xK9mQz1Rt" + end + + private + def format(message) + @formatter.call("INFO", Time.now, "app", message) + end +end