Filter attributes in SQL logs

SQL queries are logged when :debug option is used.

Previously, filter attributes were not masked in the logs.
For e.g.
    select "foos".* from foos where "foos"."passw" = ?
      LIMIT ?  [["passw", "hello"]

`password` being one of the filter attributes is written to
disk.

With this change, filter attributes will be masked as
[FILTERED] in the logs.

    select "foos".* from foos where "foos"."passw" = ?
      "foos"."passw" = ? LIMIT ?  [["passw", "[FILTERED]"]

Author: Aishwarya Subramanian

activerecord/CHANGELOG.md

@@ -1,3 +1,19 @@
+*   Filter attributes in SQL logs
+
+    Previously, SQL queries in logs containing `ActiveRecord::Base.filter_attributes` were not filtered.
+
+    Now, the filter attributes will be masked `[FILTERED]` in the logs when `prepared_statement` is enabled.
+
+    ```
+    # Before:
+      Foo Load (0.2ms)  SELECT "foos".* FROM "foos" WHERE "foos"."passw" = ? LIMIT ?  [["passw", "hello"], ["LIMIT", 1]]
+
+    # After:
+      Foo Load (0.5ms)  SELECT "foos".* FROM "foos" WHERE "foos"."passw" = ? LIMIT ?  [["passw", "[FILTERED]"], ["LIMIT", 1]]
+    ```
+
+    *Aishwarya Subramanian*
+
 *   Add database config option `database_tasks`
 
     If you would like to connect to an external database without any database

activerecord/lib/active_record/log_subscriber.rb

@@ -51,7 +51,10 @@ def sql(event)
 
         binds = []
         payload[:binds].each_with_index do |attr, i|
-          binds << render_bind(attr, casted_params[i])
+          attribute_name = attr.respond_to?(:name) ? attr.name : attr[i].name
+          filtered_params = filter(attribute_name, casted_params[i])
+
+          binds << render_bind(attr, filtered_params)
         end
         binds = binds.inspect
         binds.prepend("  ")
@@ -135,6 +138,10 @@ def log_query_source
       def extract_query_source_location(locations)
         backtrace_cleaner.clean(locations.lazy).first
       end
+
+      def filter(name, value)
+        ActiveRecord::Base.inspection_filter.filter_param(name, value)
+      end
   end
 end
 

activerecord/test/cases/bind_parameter_test.rb

@@ -189,6 +189,16 @@ def test_nested_unprepared_statements
         assert_predicate @connection, :prepared_statements?
       end
 
+      def test_binds_with_filtered_attributes
+        ActiveRecord::Base.filter_attributes = [:auth]
+
+        binds = [Relation::QueryAttribute.new("auth_token", "abcd", Type::String.new)]
+
+        assert_filtered_log_binds(binds)
+
+        ActiveRecord::Base.filter_attributes = []
+      end
+
       private
         def assert_bind_params_to_sql
           table = Author.quoted_table_name
@@ -277,6 +287,38 @@ def debug(str)
           logger.sql(event)
           assert_match %r(\[\["id", 10\]\]\z), logger.debugs.first
         end
+
+        def assert_filtered_log_binds(binds)
+          payload = {
+              name: "SQL",
+              sql: "select * from users where auth_token = ?",
+              binds: binds,
+              type_casted_binds: @connection.send(:type_casted_binds, binds)
+          }
+
+          event = ActiveSupport::Notifications::Event.new(
+              "foo",
+              Time.now,
+              Time.now,
+              123,
+              payload)
+
+          logger = Class.new(ActiveRecord::LogSubscriber) {
+            attr_reader :debugs
+
+            def initialize
+              super
+              @debugs = []
+            end
+
+            def debug(str)
+              @debugs << str
+            end
+          }.new
+
+          logger.sql(event)
+          assert_match %r([[auth_token, [FILTERED]]]), logger.debugs.first
+        end
     end
   end
 end