Redact bot key from request logs (#269)

The bot HTTP API carries 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 was written
verbatim to the request log (the "Started POST ..." line) and to any
log line echoing the pagination Link header.

Add a log formatter that redacts the bot-key path segment wherever it
appears in a formatted line, and wire it into the production logger.

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.

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

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: <https://campfire.example.com/rooms/42/7-Zt9QmK1xz3Ab/messages?before=99>; 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