Provide context when logging unpermitted parameters

Currently, the payload of the unpermitted_parameters.action_controller
events emitted by StrongParameters does not provide enough information for
developers to understand which controller and action received the
unpermitted parameters. This PR modifies ActionController::Parameters to
allow callers to specify a "context" which is included in the logging
payload.

*Implementation Strategy*
Since the ActionController::Parameters class is only loosely coupled
with controllers and can technically be used in any context, this PR
expects the caller to provide logging context.

Since StrongParameters is caller in Rails and has access to the
request object I chose to provide a payload similar to the
start_processing.action_controller event.

Author: bbuchalter

actionpack/CHANGELOG.md

@@ -1,3 +1,8 @@
+*   Expand payload of `unpermitted_parameters.action_controller` instrumentation to allow subscribers to
+    know which controller action received unpermitted parameters.
+
+    *bbuchalter*
+
 *   Add `ActionController::Live#send_stream` that makes it more convenient to send generated streams:
 
     ```ruby

actionpack/lib/action_controller/log_subscriber.rb

@@ -56,7 +56,9 @@ def send_data(event)
     def unpermitted_parameters(event)
       debug do
         unpermitted_keys = event.payload[:keys]
-        color("Unpermitted parameter#{'s' if unpermitted_keys.size > 1}: #{unpermitted_keys.map { |e| ":#{e}" }.join(", ")}", RED)
+        display_unpermitted_keys = unpermitted_keys.map { |e| ":#{e}" }.join(", ")
+        context = event.payload[:context].map { |k, v| "#{k}: #{v}" }.join(", ")
+        color("Unpermitted parameter#{'s' if unpermitted_keys.size > 1}: #{display_unpermitted_keys}. Context: { #{context} }", RED)
       end
     end
 

actionpack/lib/action_controller/metal/strong_parameters.rb

@@ -106,11 +106,13 @@ def initialize # :nodoc:
   #
   # * +permit_all_parameters+ - If it's +true+, all the parameters will be
   #   permitted by default. The default is +false+.
-  # * +action_on_unpermitted_parameters+ - Allow to control the behavior when parameters
-  #   that are not explicitly permitted are found. The values can be +false+ to just filter them
-  #   out, <tt>:log</tt> to additionally write a message on the logger, or <tt>:raise</tt> to raise
-  #   ActionController::UnpermittedParameters exception. The default value is <tt>:log</tt>
-  #   in test and development environments, +false+ otherwise.
+  # * +action_on_unpermitted_parameters+ - Controls behavior when parameters that are not explicitly
+  #    permitted are found. The default value is <tt>:log</tt> in test and development environments,
+  #    +false+ otherwise. The values can be:
+  #   * +false+ to take no action.
+  #   * <tt>:log</tt> to emit an <tt>ActiveSupport::Notifications.instrument</tt> event on the
+  #     <tt>unpermitted_parameters.action_controller</tt> topic and log at the DEBUG level.
+  #   * <tt>:raise</tt> to raise a <tt>ActionController::UnpermittedParameters</tt> exception.
   #
   # Examples:
   #
@@ -277,8 +279,9 @@ def nested_attribute?(key, value) # :nodoc:
     #   params = ActionController::Parameters.new(name: "Francesco")
     #   params.permitted?  # => true
     #   Person.new(params) # => #<Person id: nil, name: "Francesco">
-    def initialize(parameters = {})
+    def initialize(parameters = {}, logging_context = {})
       @parameters = parameters.with_indifferent_access
+      @logging_context = logging_context
       @permitted = self.class.permit_all_parameters
     end
 
@@ -968,7 +971,7 @@ def unpermitted_parameters!(params)
           case self.class.action_on_unpermitted_parameters
           when :log
             name = "unpermitted_parameters.action_controller"
-            ActiveSupport::Notifications.instrument(name, keys: unpermitted_keys)
+            ActiveSupport::Notifications.instrument(name, keys: unpermitted_keys, context: @logging_context)
           when :raise
             raise ActionController::UnpermittedParameters.new(unpermitted_keys)
           end
@@ -1184,7 +1187,15 @@ module StrongParameters
     # Returns a new ActionController::Parameters object that
     # has been instantiated with the <tt>request.parameters</tt>.
     def params
-      @_params ||= Parameters.new(request.parameters)
+      @_params ||= begin
+        context = {
+          controller: self.class.name,
+          action: action_name,
+          request: request,
+          params: request.filtered_parameters
+        }
+        Parameters.new(request.parameters, context)
+      end
     end
 
     # Assigns the given +value+ to the +params+ hash. If +value+

actionpack/test/controller/parameters/log_on_unpermitted_params_test.rb

@@ -13,22 +13,21 @@ def teardown
   end
 
   test "logs on unexpected param" do
-    params = ActionController::Parameters.new(
-      book: { pages: 65 },
-      fishing: "Turnips")
+    request_params = { book: { pages: 65 }, fishing: "Turnips" }
+    context = { "action" => "my_action", "controller" => "my_controller" }
+    params = ActionController::Parameters.new(request_params, context)
 
-    assert_logged("Unpermitted parameter: :fishing") do
+    assert_logged("Unpermitted parameter: :fishing. Context: { action: my_action, controller: my_controller }") do
       params.permit(book: [:pages])
     end
   end
 
   test "logs on unexpected params" do
-    params = ActionController::Parameters.new(
-      book: { pages: 65 },
-      fishing: "Turnips",
-      car: "Mersedes")
+    request_params = { book: { pages: 65 }, fishing: "Turnips", car: "Mersedes" }
+    context = { "action" => "my_action", "controller" => "my_controller" }
+    params = ActionController::Parameters.new(request_params, context)
 
-    assert_logged("Unpermitted parameters: :fishing, :car") do
+    assert_logged("Unpermitted parameters: :fishing, :car. Context: { action: my_action, controller: my_controller }") do
       params.permit(book: [:pages])
     end
   end
@@ -37,7 +36,7 @@ def teardown
     params = ActionController::Parameters.new(
       book: { pages: 65, title: "Green Cats and where to find then." })
 
-    assert_logged("Unpermitted parameter: :title") do
+    assert_logged("Unpermitted parameter: :title. Context: {  }") do
       params.permit(book: [:pages])
     end
   end
@@ -46,7 +45,7 @@ def teardown
     params = ActionController::Parameters.new(
       book: { pages: 65, title: "Green Cats and where to find then.", author: "G. A. Dog" })
 
-    assert_logged("Unpermitted parameters: :title, :author") do
+    assert_logged("Unpermitted parameters: :title, :author. Context: {  }") do
       params.permit(book: [:pages])
     end
   end

guides/source/active_support_instrumentation.md

@@ -280,9 +280,10 @@ INFO. Additional keys may be added by the caller.
 
 ### unpermitted_parameters.action_controller
 
-| Key     | Value            |
-| ------- | ---------------- |
-| `:keys` | Unpermitted keys |
+| Key           | Value                                                                 |
+| ------------- | --------------------------------------------------------------------- |
+| `:key`        | The unpermitted keys                                                  |
+| `:context`    | Hash with the following keys: :controller, :action, :params, :request |
 
 Action Dispatch
 ---------------

guides/source/configuring.md

@@ -526,7 +526,10 @@ The schema dumper adds two additional configuration options:
 
 * `config.action_controller.permit_all_parameters` sets all the parameters for mass assignment to be permitted by default. The default value is `false`.
 
-* `config.action_controller.action_on_unpermitted_parameters` enables logging or raising an exception if parameters that are not explicitly permitted are found. Set to `:log` or `:raise` to enable. The default value is `:log` in development and test environments, and `false` in all other environments.
+* `config.action_controller.action_on_unpermitted_parameters` controls behavior when parameters that are not explicitly permitted are found. The default value is `:log` in test and development environments, `false` otherwise. The values can be:
+    * `false` to take no action
+    * `:log` to emit an `ActiveSupport::Notifications.instrument` event on the `unpermitted_parameters.action_controller` topic and log at the DEBUG level
+    * `:raise` to raise a `ActionController::UnpermittedParameters` exception
 
 * `config.action_controller.always_permitted_parameters` sets a list of permitted parameters that are permitted by default. The default values are `['controller', 'action']`.