Skip to content

Commit

Permalink
Concise logging format for the binds of casted values
Browse files Browse the repository at this point in the history
Related issue rails#41133.

In rails#39106, I've allowed binds of casted values as an alternative of the
legacy binds (an array of `[column || nil, value]`) to deprecate and
remove the legacy binds support in a future version of Rails.

At that time, I've respected the existing logging format for binds.

i.e.

```ruby
# legacy binds
conn.select_all("SELECT * FROM events WHERE id IN (?, ?)", nil, [[nil, 1], [nil, 2]])
# (0.1ms)  SELECT * FROM events WHERE id IN (?, ?)  [[nil, 1], [nil, 2]]

# casted binds
conn.select_all("SELECT * FROM events WHERE id IN (?, ?)", nil, [1, 2])
# (0.1ms)  SELECT * FROM events WHERE id IN (?, ?)  [[nil, 1], [nil, 2]]
```

To improve the performance of generating IN clause, 72fd0ba avoids
`build_bind_attribute` for each values, so now binds has become casted
values.

```ruby
conn.select_all(Event.where(id: [1, 2]))
# (0.1ms)  SELECT * FROM events WHERE id IN (?, ?)  [[nil, 1], [nil, 2]]
```

Regardless of whether 72fd0ba avoids `build_bind_attribute` or not, the
logging format for the binds of casted values is odd (at least not
pretty to me).

I'd like to concise the logging format to just use casted values.

```ruby
conn.select_all("SELECT * FROM events WHERE id IN (?, ?)", nil, [1, 2])
# (0.1ms)  SELECT * FROM events WHERE id IN (?, ?)  [1, 2]

conn.select_all(Event.where(id: [1, 2]))
# (0.1ms)  SELECT * FROM events WHERE id IN (?, ?)  [1, 2]
```
  • Loading branch information
kamipo committed Jan 16, 2021
1 parent f250208 commit dd2cb97
Show file tree
Hide file tree
Showing 2 changed files with 56 additions and 4 deletions.
7 changes: 3 additions & 4 deletions activerecord/lib/active_record/log_subscriber.rb
Original file line number Diff line number Diff line change
Expand Up @@ -70,13 +70,12 @@ def render_bind(attr, value)
if attr.type.binary? && attr.value
value = "<#{attr.value_for_database.to_s.bytesize} bytes of binary data>"
end
[attr.name, value]
when Array
attr = attr.first
[attr.first&.name, value]
else
attr = nil
value
end

[attr&.name, value]
end

def colorize_payload_name(name, payload_name)
Expand Down
53 changes: 53 additions & 0 deletions activerecord/test/cases/adapter_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -238,74 +238,127 @@ def test_select_all_always_return_activerecord_result
end

if ActiveRecord::Base.connection.prepared_statements
require "active_support/log_subscriber/test_helper"

def test_select_all_insert_update_delete_with_legacy_binds
old_logger = ActiveRecord::Base.logger
logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new

ActiveRecord::Base.logger = logger

binds = [[Event.column_for_attribute("id"), 1]]
bind_param = Arel::Nodes::BindParam.new(nil)

assert_deprecated do
id = @connection.insert("INSERT INTO events(id) VALUES (#{bind_param.to_sql})", nil, nil, nil, nil, binds)
assert_equal 1, id
# (0.1ms) INSERT INTO events(id) VALUES (?) [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last
end

assert_deprecated do
updated = @connection.update("UPDATE events SET title = 'foo' WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal 1, updated
# (0.1ms) UPDATE events SET title = 'foo' WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last
end

assert_deprecated do
result = @connection.select_all("SELECT * FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal({ "id" => 1, "title" => "foo" }, result.first)
# (0.1ms) SELECT * FROM events WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last
end

assert_deprecated do
deleted = @connection.delete("DELETE FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal 1, deleted
# (0.1ms) DELETE FROM events WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last
end

assert_deprecated do
result = @connection.select_all("SELECT * FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_nil result.first
# (0.1ms) SELECT * FROM events WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last
end
ensure
ActiveRecord::Base.logger = old_logger
end

def test_select_all_insert_update_delete_with_casted_binds
old_logger = ActiveRecord::Base.logger
logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new

ActiveRecord::Base.logger = logger

binds = [Event.type_for_attribute("id").serialize(1)]
bind_param = Arel::Nodes::BindParam.new(nil)

id = @connection.insert("INSERT INTO events(id) VALUES (#{bind_param.to_sql})", nil, nil, nil, nil, binds)
assert_equal 1, id
# (0.1ms) INSERT INTO events(id) VALUES (?) [1]
assert_match %r( \[1\]\z), logger.logged(:debug).last

updated = @connection.update("UPDATE events SET title = 'foo' WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal 1, updated
# (0.1ms) UPDATE events SET title = 'foo' WHERE id = ? [1]
assert_match %r( \[1\]\z), logger.logged(:debug).last

result = @connection.select_all("SELECT * FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal({ "id" => 1, "title" => "foo" }, result.first)
# (0.1ms) SELECT * FROM events WHERE id = ? [1]
assert_match %r( \[1\]\z), logger.logged(:debug).last

deleted = @connection.delete("DELETE FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal 1, deleted
# (0.1ms) DELETE FROM events WHERE id = ? [1]
assert_match %r( \[1\]\z), logger.logged(:debug).last

result = @connection.select_all("SELECT * FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_nil result.first
# (0.1ms) SELECT * FROM events WHERE id = ? [1]
assert_match %r( \[1\]\z), logger.logged(:debug).last
ensure
ActiveRecord::Base.logger = old_logger
end

def test_select_all_insert_update_delete_with_binds
old_logger = ActiveRecord::Base.logger
logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new

ActiveRecord::Base.logger = logger

binds = [Relation::QueryAttribute.new("id", 1, Event.type_for_attribute("id"))]
bind_param = Arel::Nodes::BindParam.new(nil)

id = @connection.insert("INSERT INTO events(id) VALUES (#{bind_param.to_sql})", nil, nil, nil, nil, binds)
assert_equal 1, id
# (0.1ms) INSERT INTO events(id) VALUES (?) [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last

updated = @connection.update("UPDATE events SET title = 'foo' WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal 1, updated
# (0.1ms) UPDATE events SET title = 'foo' WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last

result = @connection.select_all("SELECT * FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal({ "id" => 1, "title" => "foo" }, result.first)
# (0.1ms) SELECT * FROM events WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last

deleted = @connection.delete("DELETE FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_equal 1, deleted
# (0.1ms) DELETE FROM events WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last

result = @connection.select_all("SELECT * FROM events WHERE id = #{bind_param.to_sql}", nil, binds)
assert_nil result.first
# (0.1ms) SELECT * FROM events WHERE id = ? [["id", 1]]
assert_match %r( \[\["id", 1\]\]\z), logger.logged(:debug).last
ensure
ActiveRecord::Base.logger = old_logger
end
end

Expand Down

0 comments on commit dd2cb97

Please sign in to comment.