Rails console parameters not filtered when using a block

[Beartech]

Steps to reproduce

Add an initiator with the following code as given in the documentation (https://api.rubyonrails.org/v8.0/classes/ActiveSupport/ParameterFilter.html )
Restart the server.
Save a record to the DB.
Check the server log and see that it does not filter the params value as expected.

#custom_logging_filter.rb
 ActiveSupport::ParameterFilter.new([-> (k, v) do
   v.reverse! if /test_field/i.match?(k)
 end])

Expected behavior

Params value for the hash key test_field should be reversed.

Actual behavior

They are untouched in both the http request log and in the DB save log.

System configuration

Rails version:
8.0.1
Ruby version:
ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-darwin24]

I removed the custom_logging_filter.rb and added the Proc to the filter_parameter_logging.rb initializer:

Rails.application.config.filter_parameters += [
  :passw, :email, :secret, :token, :_key, :crypt, :salt, :certificate, :otp, :ssn, :cvv, :cvc, -> (k, v) do
     v.reverse! if /test_field/i.match?(k)
   end
]

On submitting the form with the value "goodbye" you get the filtering in the request log:

Processing by TestModelsController#update as TURBO_STREAM
  Parameters: {"authenticity_token"=>"[FILTERED]", "test_model"=>{"test_field"=>"eybdoog"}, "commit"...

But the DB log still shows:

TRANSACTION (0.1ms)  BEGIN immediate TRANSACTION /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:40:in `block in update'
  TestModel Update (3.4ms)  UPDATE "test_models" SET "test_field" = 'goodbye', "updated_at" = '2025-01-02 ...

Strangely I used this same code in a new Rails 7.0.8.7 app with ruby 3.2.4 (2024-04-23 revision af471c0e01) [x86_64-darwin23] and the results are that the filtering happens in the DB call but NOT the browser request. So the opposite of what is happening with Rails 8.

[fatkodima]

Can you provide a sample app, that reproduces the issue?

[Beartech]

https://github.com/Beartech/filtering_test

[kiku1705]

Hi @Beartech, I ran the below script and below are the logs i am seeing

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  gem "rails", '8.0.1'
  # If you want to test against edge Rails replace the previous line with this:
  # gem "rails", github: "rails/rails", branch: "main"

  gem "sqlite3"
end

require "active_record/railtie"
require "minitest/autorun"
require "action_controller/railtie"
require "rack/test"

# This connection will do for database-independent bug reports.
ENV["DATABASE_URL"] = "sqlite3::memory:"

class TestApp < Rails::Application
  config.root = __dir__
  config.hosts << "example.org"
  config.session_store :cookie_store, key: "cookie_store_key"
  config.secret_key_base = "secret_key_base"

  config.logger = Logger.new($stdout)
  Rails.logger  = config.logger

  config.load_defaults Rails::VERSION::STRING.to_f
  
  config.filter_parameters += [
    :passw, :email, :secret, :token, :_key, :crypt, :salt, :certificate, :otp, :ssn, :cvv, :cvc, -> (k, v) do
     v.reverse! if /test_field/i.match?(k)
   end
  ]
end
Rails.application.initialize!

Rails.application.routes.draw do
  resources :test_models
end

ActiveRecord::Schema.define do
  create_table :test_models, force: true do |t|
    t.string :test_field
  end
end

class TestModel < ActiveRecord::Base
 
end

class TestModelsController < ActionController::Base
  skip_before_action :verify_authenticity_token
  include Rails.application.routes.url_helpers
  def create
      TestModel.create(test_models_params)
  end

  def update
    puts params(:test_models)
  end

  def test_models_params
    params.require(:test_models).permit(:test_field)
  end
end
class BugTest < ActiveSupport::TestCase
  include Rack::Test::Methods

  def test_test_models_created_success
    post "/test_models", { test_models: { test_field: 'goodbye' } }
    puts last_response.inspect
  end

  private
    def app
      Rails.application
    end
end

logs ------

 -----------------------------------------
I, [2025-01-02T13:44:24.139476 #79852]  INFO -- : BugTest: test_test_models_created_success
I, [2025-01-02T13:44:24.139482 #79852]  INFO -- : -----------------------------------------
I, [2025-01-02T13:44:24.142271 #79852]  INFO -- : Started POST "/test_models" for 127.0.0.1 at 2025-01-02 13:44:24 -0500
I, [2025-01-02T13:44:24.149014 #79852]  INFO -- : Processing by TestModelsController#create as HTML
I, [2025-01-02T13:44:24.149038 #79852]  INFO -- :   Parameters: {"test_models"=>{"test_field"=>"eybdoog"}}
D, [2025-01-02T13:44:24.151484 #79852] DEBUG -- :   TRANSACTION (0.0ms)  BEGIN immediate TRANSACTION
D, [2025-01-02T13:44:24.151569 #79852] DEBUG -- :   TestModel Create (0.1ms)  INSERT INTO "test_models" ("test_field") VALUES (?) RETURNING "id"  [["test_field", "eybdoog"]]
D, [2025-01-02T13:44:24.151654 #79852] DEBUG -- :   TRANSACTION (0.0ms)  COMMIT TRANSACTION
I, [2025-01-02T13:44:24.152232 #79852]  INFO -- : No template found for TestModelsController#create, rendering head :no_content
I, [2025-01-02T13:44:24.152291 #79852]  INFO -- : Completed 204 No Content in 3ms (ActiveRecord: 0.3ms (1 query, 0 cached) | GC: 0.3ms)

and it saved the reverse field in db and showing reverse in logs too, can you please confirm or am i missing something else.

[Beartech]

OK, your last line is unclear; Are you saying that the actual value saved in the DB is REVERSED? Because that is NOT the expected behavior (and not the behavior I am seeing). This is params logs filtering. The normal behavior is to just use a symbol and get [FILTERED] in the logs. This is exactly the process used to filter passwords from the logs for security reasons. But the documentation states that rather than just a filter substitution, you can transform the value that is SHOWN in the logs, but not the actual value that is saved in the DB.

[Beartech]

Another use case would be something like a credit card number. Rather than just seeing "[FILTERED]" in the logs you might want to see the params in their original format but no numbers like: "test_model"=>{"test_field"=>"*** *** *** ***"}

I can see from your test script that you are getting the correct logs, so as long as the DB save is NOT reversed then all is good and I have more troubleshooting to do. Also can you provide your platform if it was different than mine?

Can you add puts TestModel.last.inspect to your code to confirm the DB is doing what is expected behavior.

[kiku1705]

I wanted to reproduce your issues and confirming if the script is doing what you are facing.

System configuration

• ruby 3.3.6 (2024-11-05 revision 75015d4c1f) [arm64-darwin21]
• rails 8.0.1

Nope it is saving the reversed results in the db as well. Here is the output

-----------------------------------------
I, [2025-01-02T14:29:21.575589 #80922]  INFO -- : BugTest: test_test_models_created_success
I, [2025-01-02T14:29:21.575595 #80922]  INFO -- : -----------------------------------------
I, [2025-01-02T14:29:21.578146 #80922]  INFO -- : Started POST "/test_models" for 127.0.0.1 at 2025-01-02 14:29:21 -0500
I, [2025-01-02T14:29:21.584295 #80922]  INFO -- : Processing by TestModelsController#create as HTML
I, [2025-01-02T14:29:21.584312 #80922]  INFO -- :   Parameters: {"test_models"=>{"test_field"=>"eybdoog"}}
D, [2025-01-02T14:29:21.586487 #80922] DEBUG -- :   TRANSACTION (0.0ms)  BEGIN immediate TRANSACTION
D, [2025-01-02T14:29:21.586571 #80922] DEBUG -- :   TestModel Create (0.1ms)  INSERT INTO "test_models" ("test_field") VALUES (?) RETURNING "id"  [["test_field", "eybdoog"]]
D, [2025-01-02T14:29:21.586657 #80922] DEBUG -- :   TRANSACTION (0.0ms)  COMMIT TRANSACTION
I, [2025-01-02T14:29:21.587049 #80922]  INFO -- : No template found for TestModelsController#create, rendering head :no_content
I, [2025-01-02T14:29:21.587105 #80922]  INFO -- : Completed 204 No Content in 3ms (ActiveRecord: 0.3ms (1 query, 0 cached) | GC: 0.0ms)


D, [2025-01-02T14:29:21.590049 #80922] DEBUG -- :   TestModel Load (0.0ms)  SELECT "test_models".* FROM "test_models" ORDER BY "test_models"."id" DESC LIMIT ?  [["LIMIT", 1]]
#<TestModel id: 1, test_field: "eybdoog">

[Beartech]

OK. so I tried your script in a new directory with Rails 8.0.1 and Ruby 3.3.0 and it does exactly what you show here. AND it saves the value to the DB REVERSED.

Is that the expected behavior of ActtiveSupport::ParameterFilter? To modify the actual value? Then I have misunderstood. BUT if I add that code to the Rails.application.config.filter_parameters then I get what I believe to be the expected behavior, in that the logs get filtered and replaced (but only in the initial log of the params as passed to the controller, NOT in the DB call). The point here is to alter JUST the value as it is represented in the console logs. I say this because if you use a symbol to do a straight filtering you get [FILTERED] in both parts of the logs because THAT is the expected behavior.

[Beartech]

Can you try the sample app I uploaded and post your results?

[Beartech]

I fell like I'm loosing my mind... LOL

In using my current app with filtering happening in the filter_parameter_logging.rb file as

Rails.application.config.filter_parameters += [
  :passw, :email, :secret, :token, :_key, :crypt, :salt, :certificate, :otp, :ssn, :cvv, :cvc, ->(k, v) do
      v.reverse! if /test_field/i.match?(k)
   end
]

I get this in the console:

Started PATCH "/test_models/12" for ::1 at 2025-01-02 12:09:46 -0800
Processing by TestModelsController#update as TURBO_STREAM
  Parameters: {"authenticity_token"=>"[FILTERED]", "test_model"=>{"test_field"=>"##***!!olleh"}, "commit"=>"Update Test model", "id"=>"12"}
  TestModel Load (0.1ms)  SELECT "test_models".* FROM "test_models" WHERE "test_models"."id" = 12 LIMIT 1 /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:63:in `set_test_model'
  TRANSACTION (0.1ms)  BEGIN immediate TRANSACTION /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:40:in `block in update'
  TestModel Update (0.9ms)  UPDATE "test_models" SET "test_field" = 'hello!!***##', "updated_at" = '2025-01-02 20:09:46.405855' WHERE "test_models"."id" = 12 /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:40:in `block in update'
  TRANSACTION (0.2ms)  COMMIT TRANSACTION /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:40:in `block in update'
Redirected to http://localhost:3000/test_models/12

So filtering happens in the params log but not in the DB call.
If I open the Rails console and do TestModel.last I get:

TestModel Load (1.3ms)  SELECT "test_models".* FROM "test_models" ORDER BY "test_models"."id" DESC LIMIT 1 /*application='FilteringTest'*/
=> #<TestModel:0x0000000125fe0508 id: 12, test_field: "##***!!olleh", created_at: "2025-01-02 06:11:55.506824000 +0000", updated_at: "2025-01-02 20:09:46.405855000 +0000">

But when I do TestModel.last.test_field I get:

TestModel Load (0.5ms)  SELECT "test_models".* FROM "test_models" ORDER BY "test_models"."id" DESC LIMIT 1 /*application='FilteringTest'*/
=> "hello!!***##"

So it is actually working almost exactly as expected! It's always filtering the value BUT if you open the DB file and look at the value directly, it is "correct" in that it is NOT reversed. Which is why my app works correctly in the browser, saving the non-reversed value as expected.

So the only thing I am having issue with is my webserver console still showing:

Parameters: {"authenticity_token"=>"[FILTERED]", "test_model"=>{"test_field"=>"##***!!olleh"}, "commit"=>"Update Test model", "id"=>"12"}

but also:

TestModel Update (0.9ms)  UPDATE "test_models" SET "test_field" = 'hello!!***##', "updated_at" = '2025-01-02 20:09:46.405855' WHERE "test_models"."id" = 12 /*action='update',application='FilteringTest',controller='test_models'*/

So I guess my issue is just that in my app it doesn't filter in the DB call in the console (like it does in your test script). So is that expected? If the issue is NOT reproduced by installing the app I uploaded, then I will close this as it is something weird on my system. That is is literally just a fresh Rails app that I created to test this.

[kiku1705]

Let me check it one more time.

[kiku1705]

@Beartech

I think it is working correctly, check the output

Started PATCH "/test_models/2" for ::1 at 2025-01-02 15:49:50 -0500
Processing by TestModelsController#update as TURBO_STREAM
  Parameters: {"authenticity_token"=>"[FILTERED]", "test_model"=>{"test_field"=>"1eybdoog"}, "commit"=>"Update Test model", "id"=>"2"}
  TestModel Load (0.1ms)  SELECT "test_models".* FROM "test_models" WHERE "test_models"."id" = 2 LIMIT 1 /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:63:in `set_test_model'
  TRANSACTION (0.0ms)  BEGIN immediate TRANSACTION /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:40:in `block in update'
  TestModel Update (0.4ms)  UPDATE "test_models" SET "test_field" = 'goodbye1', "updated_at" = '2025-01-02 20:49:50.883560' WHERE "test_models"."id" = 2 /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:40:in `block in update'
  TRANSACTION (0.2ms)  COMMIT TRANSACTION /*action='update',application='FilteringTest',controller='test_models'*/
  ↳ app/controllers/test_models_controller.rb:40:in `block in update'
Redirected to http://localhost:3000/test_models/2
Completed 302 Found in 21ms (ActiveRecord: 0.7ms (2 queries, 0 cached) | GC: 1.5ms)

^C- Gracefully stopping, waiting for requests to finish
=== puma shutdown: 2025-01-02 15:50:38 -0500 ===
- Goodbye!
Exiting
MacBook-Air filtering_test % rails c
Loading development environment (Rails 8.0.1)
3.3.0 :001 > TestModel.last
  TestModel Load (0.2ms)  SELECT "test_models".* FROM "test_models" ORDER BY "test_models"."id" DESC LIMIT 1 /*application='FilteringTest'*/
 => 
#<TestModel:0x000000012bf59110
 id: 2,
 test_field: "1eybdoog",
 created_at: "2025-01-02 20:48:10.210258000 +0000",
 updated_at: "2025-01-02 20:49:50.883560000 +0000"> 
3.3.0 :002 > TestModel.last.test_field
  TestModel Load (0.2ms)  SELECT "test_models".* FROM "test_models" ORDER BY "test_models"."id" DESC LIMIT 1 /*application='FilteringTest'*/
 => "goodbye1" 
3.3.0 :003 > 

[Beartech]

I agree that is seems to be working as stated but the difference is:
Your test script:

D, [2025-01-02T14:29:21.586571 #80922] DEBUG -- :   TestModel Create (0.1ms)  INSERT INTO "test_models" ("test_field") VALUES (?) RETURNING "id"  [["test_field", "eybdoog"]]

when you run an actual app:

  TestModel Update (0.4ms)  UPDATE "test_models" SET "test_field" = 'goodbye1', "updated_at" = '2025-01-02 20:49:50.883560' WHERE "test_models"."id" = 2 /*action='update',application='FilteringTest',controller='test_models'*/

Why is it filtered everywhere but that one call?

[Edouard-chin]

👋

I read your comments and gave your reproduction a try and everything works as expected. Hopefully this will help clarify your questions:

1. Parameter filtering will not modify the value for the database. You may think that it has, because calling Post.last will pretty print all post attributes value after filtering, if you call Post.last.test_field you will get the original value.
2. The difference between your script and a vanilla Rails application is that the filtering occurs only when prepared statements are enabled. In development it is turned off by default.
3. As you have both pointed out, the filtering works correctly in the logs related to the request.

I'll close this ticket as there is nothing actionable on our side. Thanks!