bind parameters are logged to debug log

2 files changed, 48 insertions, 6 deletions

diff --git a/activerecord/lib/active_record/log_subscriber.rb b/activerecord/lib/active_record/log_subscriber.rb
index c7ae12977a..a08b3562d0 100644
--- a/activerecord/lib/active_record/log_subscriber.rb
+++ b/activerecord/lib/active_record/log_subscriber.rb
@@ -22,8 +22,16 @@ module ActiveRecord
       self.class.runtime += event.duration
       return unless logger.debug?
 
-      name = '%s (%.1fms)' % [event.payload[:name], event.duration]
-      sql  = event.payload[:sql].squeeze(' ')
+      payload = event.payload
+      name    = '%s (%.1fms)' % [payload[:name], event.duration]
+      sql     = payload[:sql].squeeze(' ')
+      binds   = nil
+
+      unless (payload[:binds] || []).empty?
+        binds = " {" + payload[:binds].map { |col,v|
+          "#{col.name.inspect} => #{v.inspect}"
+        }.join(", ") + "}"
+      end
 
       if odd?
         name = color(name, CYAN, true)
@@ -32,7 +40,7 @@ module ActiveRecord
         name = color(name, MAGENTA, true)
       end
 
-      debug "  #{name}  #{sql}"
+      debug "  #{name}  #{sql}#{binds}"
     end
 
     def odd?
@@ -45,4 +53,4 @@ module ActiveRecord
   end
 end
 
-ActiveRecord::LogSubscriber.attach_to :active_record
\ No newline at end of file
+ActiveRecord::LogSubscriber.attach_to :active_record
diff --git a/activerecord/test/cases/bind_parameter_test.rb b/activerecord/test/cases/bind_parameter_test.rb
index 4532ab6213..83001f44f9 100644
--- a/activerecord/test/cases/bind_parameter_test.rb
+++ b/activerecord/test/cases/bind_parameter_test.rb
@@ -3,6 +3,8 @@ require 'models/topic'
 
 module ActiveRecord
   class BindParameterTest < ActiveRecord::TestCase
+    fixtures :topics
+
     class LogListener
       attr_accessor :calls
 
@@ -15,8 +17,6 @@ module ActiveRecord
       end
     end
 
-    fixtures :topics
-
     def setup
       super
       @connection = ActiveRecord::Base.connection
@@ -52,5 +52,39 @@ module ActiveRecord
       message = @listener.calls.find { |args| args[4][:binds] == binds }
       assert message, 'expected a message with binds'
     end
+
+    def test_logs_bind_vars
+      # FIXME: use skip with minitest
+      return unless @connection.supports_statement_cache?
+
+      pk = Topic.columns.find { |x| x.primary }
+
+      payload = {
+        :name  => 'SQL',
+        :sql   => 'select * from topics where id = ?',
+        :binds => [[pk, 10]]
+      }
+      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("{#{pk.name.inspect} => #{10.inspect}}", logger.debugs.first)
+    end
   end
 end