From 97f0d9a0dd12e7ad634815eecfeff866f64aad92 Mon Sep 17 00:00:00 2001
From: Yves Senn <yves.senn@gmail.com>
Date: Sat, 9 Nov 2013 11:09:20 +0100
Subject: [PATCH] log bind variables after they were type casted.

The log output used to be confusing in situation where type casting has
"unexpected" effects. For example when finding records with a `String`.

BEFORE:

irb(main):002:0> Event.find("im-no-integer")
D, [2013-11-09T11:10:28.998857 #1706] DEBUG -- :   Event Load (4.5ms)  SELECT "events".* FROM "events" WHERE "events"."id" = $1 LIMIT 1  [["id", "im-no-integer"]]

AFTER:

irb(main):002:0> Event.find("im-no-integer")
D, [2013-11-09T11:10:28.998857 #1706] DEBUG -- :   Event Load (4.5ms)  SELECT "events".* FROM "events" WHERE "events"."id" = $1 LIMIT 1  [["id", 0]]
---
 activerecord/CHANGELOG.md                             |  9 +++++++++
 .../connection_adapters/mysql_adapter.rb              |  8 ++++++--
 .../connection_adapters/postgresql_adapter.rb         |  9 +++++----
 .../connection_adapters/sqlite3_adapter.rb            |  9 +++++----
 activerecord/test/cases/bind_parameter_test.rb        | 11 +++++++++++
 5 files changed, 36 insertions(+), 10 deletions(-)

diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md
index 2006558ab2..14089b5c1d 100644
--- a/activerecord/CHANGELOG.md
+++ b/activerecord/CHANGELOG.md
@@ -1,3 +1,12 @@
+*   Log bind variables after they are type casted. This makes it more
+    transparent what values are actually sent to the database.
+
+        irb(main):002:0> Event.find("im-no-integer")
+        # Before: ... WHERE "events"."id" = $1 LIMIT 1  [["id", "im-no-integer"]]
+        # After: ... WHERE "events"."id" = $1 LIMIT 1  [["id", 0]]
+
+    *Yves Senn*
+
 *   Fix uninitialized constant TransactionState error when Marshall.load is used on an Active Record result.
     Fixes #12790
 
diff --git a/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb b/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb
index 88c9494fc6..fc37588f09 100644
--- a/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb
@@ -476,7 +476,11 @@ def begin_db_transaction #:nodoc:
 
       def exec_stmt(sql, name, binds)
         cache = {}
-        log(sql, name, binds) do
+        type_casted_binds = binds.map { |col, val|
+          [col, type_cast(val, col)]
+        }
+
+        log(sql, name, type_casted_binds) do
           if binds.empty?
             stmt = @connection.prepare(sql)
           else
@@ -487,7 +491,7 @@ def exec_stmt(sql, name, binds)
           end
 
           begin
-            stmt.execute(*binds.map { |col, val| type_cast(val, col) })
+            stmt.execute(*type_casted_binds.map(&:second))
           rescue Mysql::Error => e
             # Older versions of MySQL leave the prepared statement in a bad
             # place when an error occurs. To support older mysql versions, we
diff --git a/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb b/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
index 3668aecd4b..5fd322310f 100644
--- a/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
@@ -783,11 +783,12 @@ def exec_no_cache(sql, name, binds)
 
         def exec_cache(sql, name, binds)
           stmt_key = prepare_statement(sql)
+          type_casted_binds = binds.map { |col, val|
+            [col, type_cast(val, col)]
+          }
 
-          log(sql, name, binds, stmt_key) do
-            @connection.send_query_prepared(stmt_key, binds.map { |col, val|
-              type_cast(val, col)
-            })
+          log(sql, name, type_casted_binds, stmt_key) do
+            @connection.send_query_prepared(stmt_key, type_casted_binds.map(&:second))
             @connection.block
             @connection.get_last_result
           end
diff --git a/activerecord/lib/active_record/connection_adapters/sqlite3_adapter.rb b/activerecord/lib/active_record/connection_adapters/sqlite3_adapter.rb
index e5ad08b6b0..f09178c93b 100644
--- a/activerecord/lib/active_record/connection_adapters/sqlite3_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/sqlite3_adapter.rb
@@ -291,8 +291,11 @@ def pp(result) # :nodoc:
       end
 
       def exec_query(sql, name = nil, binds = [])
-        log(sql, name, binds) do
+        type_casted_binds = binds.map { |col, val|
+          [col, type_cast(val, col)]
+        }
 
+        log(sql, name, type_casted_binds) do
           # Don't cache statements if they are not prepared
           if without_prepared_statement?(binds)
             stmt    = @connection.prepare(sql)
@@ -307,9 +310,7 @@ def exec_query(sql, name = nil, binds = [])
             stmt = cache[:stmt]
             cols = cache[:cols] ||= stmt.columns
             stmt.reset!
-            stmt.bind_params binds.map { |col, val|
-              type_cast(val, col)
-            }
+            stmt.bind_params type_casted_binds.map(&:second)
           end
 
           ActiveRecord::Result.new(cols, stmt.to_a)
diff --git a/activerecord/test/cases/bind_parameter_test.rb b/activerecord/test/cases/bind_parameter_test.rb
index bc00364e85..291751c435 100644
--- a/activerecord/test/cases/bind_parameter_test.rb
+++ b/activerecord/test/cases/bind_parameter_test.rb
@@ -41,6 +41,17 @@ def test_binds_are_logged
         assert_equal binds, message[4][:binds]
       end
 
+      def test_binds_are_logged_after_type_cast
+        sub   = @connection.substitute_at(@pk, 0)
+        binds = [[@pk, "3"]]
+        sql   = "select * from topics where id = #{sub}"
+
+        @connection.exec_query(sql, 'SQL', binds)
+
+        message = @listener.calls.find { |args| args[4][:sql] == sql }
+        assert_equal [[@pk, 3]], message[4][:binds]
+      end
+
       def test_find_one_uses_binds
         Topic.find(1)
         binds = [[@pk, 1]]
-- 
GitLab