Permalink
Browse files

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]]
  • Loading branch information...
1 parent 3cc64df commit 97f0d9a0dd12e7ad634815eecfeff866f64aad92 @senny senny committed Nov 9, 2013
@@ -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
@@ -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
@@ -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
@@ -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)
@@ -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]]

3 comments on commit 97f0d9a

Member

senny replied Nov 9, 2013

@rafaelfranca as discussed.

/cc @tenderlove

Owner

tenderlove replied Nov 9, 2013

Owner

rafaelfranca replied Nov 9, 2013

👍 But this broke postgresql tests 😢

Please sign in to comment.