Leave the input a params parser quotes out of error lines

When Rails can't parse a request's params, the parser's message quotes the input
where it stopped: JSON's "unexpected character: '<body>'", Rack's "invalid
%-encoding (<value>)". The error line copied it into cause_message, and Rails'
BadRequest wraps it in its own message ("Invalid request parameters: ..."), so a
password there was logged unfiltered, at any log level.

Error lines for Rails' ParseError (and its ParamErrors), Rack's params errors and
errors raised because of them keep the error and cause classes and Rails' words
before the input, without the parser's message.

Author: ndbroadbent

CHANGELOG.md

@@ -88,6 +88,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - **Security**: LogStruct no longer empties Rails' `filter_parameters` or loads ActiveRecord and the other frameworks before the app's initializers run, so `filter_attributes` and Rails' own parameter filtering keep working (GHSA-cpp6-p4hf-383g)
 - **Security**: Values nested deeper than the depth limit are summarized instead of logged raw, skipping filtering and scrubbing (#15)
 - **Security**: When Rails can't parse a request's body (malformed JSON), its debug line gives the body's size and type. Rails logged the whole body there, so a password in it was logged unfiltered
+- **Security**: The error line for params Rails can't parse (malformed JSON, a bad %-encoding) leaves out the input the parser's message quotes: it has no `cause_message`, and Rails' "Invalid request parameters: ..." stops before the input. A password where the parser stopped was logged unfiltered
 - **Security**: Structs, `ActionController::Parameters` and other objects in a log line are filtered and scrubbed like Hashes, instead of being serialized unfiltered
 - **Fix**: A value that refers back to itself (a Hash or Array containing its own parent) is logged once instead of being expanded up to the depth limit, which took seconds and produced very large lines
 - **ActiveRecord**: Verbose query logs (the "↳ caller" lines) are turned off as intended. The integration set them on `ActiveRecord::Base`, which loaded it early and never matched, because the setting is on the `ActiveRecord` module

docs/app/docs/integrations/security/page.tsx

@@ -269,9 +269,10 @@ export default function SecurityIntegrationPage() {
         <li>
           <code>config.integrations.enable_rack_error_handler</code> (default <code>true</code>):
           CSRF and IP spoofing lines, and the error lines for errors that get past Rails&apos;{' '}
-          <code>ShowExceptions</code>. With it on, when Rails can&apos;t parse a request&apos;s body
-          (malformed JSON), its debug line gives the body&apos;s size and type instead of the body,
-          which nothing would filter.
+          <code>ShowExceptions</code>. With it on, when Rails can&apos;t parse a request&apos;s
+          params (malformed JSON, a bad %-encoding), its debug line gives the body&apos;s size and
+          type instead of the body, and the error line leaves out the input the parser&apos;s
+          message quotes. Nothing could filter either.
         </li>
         <li>
           <code>config.error_handling_modes.security_errors</code> (default <code>Report</code>).

lib/log_struct/integrations/rack_error_handler/error_lines.rb

@@ -15,6 +15,24 @@ module ErrorLines
           T::Array[String]
         )
 
+        # Errors from parsing a request's params: Rails' ParseError (and its ParamErrors), and Rack's. Their messages,
+        # and those of errors raised because of them (Rails' "Invalid request parameters: ..."), quote the request's
+        # input: a JSON parser's excerpt of the body, Rack's "invalid %-encoding (<value>)". Nothing can filter a body
+        # that didn't parse, so their lines leave the input out.
+        PARAMS_ERROR_NAMES = T.let(
+          [
+            "ActionDispatch::Http::Parameters::ParseError",
+            "Rack::BadRequest",
+            "Rack::QueryParser::InvalidParameterError",
+            "Rack::QueryParser::ParameterTypeError",
+            "Rack::QueryParser::ParamsTooDeepError"
+          ].freeze,
+          T::Array[String]
+        )
+        # Rails' message for a ParseError
+        PARSE_ERROR_MESSAGE = "Error occurred while parsing request parameters"
+        PARAMS_ERROR_MESSAGE = "Invalid request parameters"
+
         sig { returns(T::Boolean) }
         def self.enabled?
           LogStruct.enabled? && LogStruct.config.integrations.enable_rack_error_handler
@@ -44,7 +62,7 @@ def self.log_escaped(request, error)
             Log::Error.new(
               source: Source::Rails,
               error_class: error.class,
-              message: error.message,
+              message: messages(error).first,
               backtrace: error.backtrace,
               path: request.path,
               http_method: request.method,
@@ -66,20 +84,20 @@ def self.log_unhandled(request, wrapper)
           LoggedErrors.mark(error)
           # Without a backtrace cleaner, Rails' trace is Thread::Backtrace::Locations
           trace = Array(wrapper.exception_trace).map(&:to_s)
-          cause = error.cause
+          message, cause_message = messages(error)
           line = Log::Error.new(
             source: Source::Rails,
             error_class: error.class,
-            message: error.message,
+            message: message,
             backtrace: trace.empty? ? error.backtrace : trace,
             path: request.path,
             http_method: request.method,
             source_ip: source_ip(request),
             user_agent: request.user_agent,
             referer: StringScrubber.without_query(request.referer),
             status: wrapper.status_code,
-            cause_class: cause&.class&.name,
-            cause_message: cause&.message
+            cause_class: error.cause&.class&.name,
+            cause_message: cause_message
           )
           case request.get_header("action_dispatch.debug_exception_log_level")
           when ::Logger::DEBUG then LogStruct.debug(line)
@@ -143,6 +161,25 @@ def self.source_ip(request)
           request.ip
         end
 
+        # The message and the cause's message for an error's line, without the input a params parser quoted
+        sig { params(error: Exception).returns([String, T.nilable(String)]) }
+        def self.messages(error)
+          cause = error.cause
+          if params_error?(error)
+            [error.instance_of?(::ActionDispatch::Http::Parameters::ParseError) ? PARSE_ERROR_MESSAGE : PARAMS_ERROR_MESSAGE, nil]
+          elsif cause && params_error?(cause)
+            message = error.message.sub(cause.message, "").sub(/[\s:]+\z/, "")
+            [message.empty? ? PARAMS_ERROR_MESSAGE : message, nil]
+          else
+            [error.message, cause&.message]
+          end
+        end
+
+        sig { params(error: Exception).returns(T::Boolean) }
+        def self.params_error?(error)
+          error.class.ancestors.any? { |ancestor| PARAMS_ERROR_NAMES.include?(ancestor.name) }
+        end
+
         sig { params(error: Exception).returns(T::Boolean) }
         def self.security_error?(error)
           ip_spoof_error?(error) || CSRF_ERROR_NAMES.include?(error.class.name)

rails_test_app/templates/app/controllers/logging_controller.rb

@@ -22,6 +22,11 @@ def test_basic
     render json: {status: "ok", message: "Basic logging completed"}
   end
 
+  # Reads the request's params
+  def test_params
+    render json: {keys: params.keys}
+  end
+
   # Error logging
   def test_error
     # Since the tests run in the test environment and Rails' test behavior may catch exceptions

rails_test_app/templates/config/routes.rb

@@ -13,6 +13,7 @@
   get "/logging/error_logging", to: "logging#test_error_logging"
   get "/logging/shrine_upload", to: "logging#test_shrine_upload"
   get "/logging/ams", to: "logging#test_ams_serialization"
+  post "/logging/params", to: "logging#test_params"
 
   post "/security/submit", to: "security#submit"
   get "/security/remote_ip", to: "security#remote_ip"

rails_test_app/templates/test/integration/unhandled_errors_test.rb

@@ -56,6 +56,21 @@ class UnhandledErrorsTest < ActionDispatch::IntegrationTest
     assert_not_includes @log_output.string, "synthetic-raw-secret"
   end
 
+  test "the error lines for params Rails can't parse leave out the input the parsers quote" do
+    post "/logging/params", params: '{"password":synthetic-raw-secret}', headers: {"CONTENT_TYPE" => "application/json"}
+
+    assert_response :bad_request
+    post "/logging/params", params: "password=%zz-synthetic-raw-secret", headers: {"CONTENT_TYPE" => "application/x-www-form-urlencoded"}
+
+    assert_response :bad_request
+    errors = lines.select { |line| line["evt"] == "error" }
+
+    assert_equal [["ActionDispatch::Http::Parameters::ParseError", "Error occurred while parsing request parameters", "JSON::ParserError"],
+      ["ActionController::BadRequest", "Invalid request parameters", "Rack::QueryParser::InvalidParameterError"]],
+      errors.map { |line| line.values_at("error_class", "msg", "cause_class") }
+    assert_not_includes @log_output.string, "synthetic-raw-secret"
+  end
+
   test "a routing error is an error line with its 404 status" do
     get "/no/such/route"
 

test/log_struct/integrations/rack_error_handler_test.rb

@@ -61,6 +61,41 @@ def test_a_body_rails_cant_parse_is_logged_as_its_size_not_its_contents
     refute_includes output.string, "synthetic-raw-secret"
   end
 
+  def test_errors_from_parsing_params_leave_out_the_input_the_parsers_quote
+    parse_error = raised do
+      JSON.parse('{"password":synthetic-raw-secret}')
+    rescue JSON::ParserError
+      raise ActionDispatch::Http::Parameters::ParseError, "Error occurred while parsing request parameters"
+    end
+    bad_request = raised do
+      Rack::Utils.parse_nested_query("password=%zz-synthetic-raw-secret")
+    rescue Rack::Utils::InvalidParameterError => e
+      raise ActionController::BadRequest, "Invalid request parameters: #{e.message}"
+    end
+    rack_error = raised { Rack::Utils.parse_nested_query("password=%zz-synthetic-raw-secret") }
+    request = ActionDispatch::Request.new(Rack::MockRequest.env_for("/sessions", method: "POST"))
+    lines = []
+
+    LogStruct.stub(:fatal, ->(line) { lines << line }) do
+      LogStruct.stub(:error, ->(line) { lines << line }) do
+        [parse_error, bad_request].each do |error|
+          ErrorLines.log_unhandled(request, ActionDispatch::ExceptionWrapper.new(ActiveSupport::BacktraceCleaner.new, error))
+        end
+        # From a middleware outside ShowExceptions that reads Rack's params
+        ErrorLines.log_escaped(request, rack_error)
+      end
+    end
+
+    expected = [
+      ["Error occurred while parsing request parameters", "JSON::ParserError", nil],
+      ["Invalid request parameters", "Rack::QueryParser::InvalidParameterError", nil],
+      ["Invalid request parameters", nil, nil]
+    ]
+
+    assert_equal expected, lines.map { |line| [line.message, line.cause_class, line.cause_message] }
+    refute_includes lines.map { |line| line.serialize.to_json }.join, "synthetic-raw-secret"
+  end
+
   def test_the_middleware_logs_an_escaped_error_once_and_raises_it_again
     io = StringIO.new
     logger = Logger.new(io)
@@ -83,4 +118,14 @@ def test_the_middleware_logs_an_escaped_error_once_and_raises_it_again
     assert_equal ["rails", "error", "RuntimeError", "boom", "/orders", "GET", "https://app.example.com/reset"],
       lines.first.values_at("src", "evt", "error_class", "msg", "path", "method", "referer")
   end
+
+  private
+
+  def raised
+    yield
+
+    flunk "Expected an error"
+  rescue => e
+    e
+  end
 end