Merge pull request #201 from TalentBox/183-handle-bound-variables-and…

…-prepared-statement

183 handle bound variables and prepared statement

lib/sequel_rails/railties/log_subscriber.rb

@@ -38,13 +38,7 @@ def sql(event)
 
         name = format('%s (%.1fms)', payload[:name], event.duration)
         sql  = payload[:sql].squeeze(' ')
-        binds = nil
-
-        unless (payload[:binds] || []).empty?
-          binds = '  ' + payload[:binds].map do |col, v|
-            [col.name, v]
-          end.inspect
-        end
+        binds = " #{payload[:binds].inspect}" unless (payload[:binds] || []).empty?
 
         if odd?
           name = color(name, :cyan, :bold => true)

spec/lib/sequel_rails/railties/log_subscriber_spec.rb

@@ -14,14 +14,6 @@ def set_logger(logger) # rubocop:disable AccessorMethodName
   end
   after { teardown }
 
-  it 'logs queries, runtime and count' do
-    expect(described_class.count).to eq 0
-    User.all
-    wait
-    expect(@logger.logged(:debug).last).to match(/SELECT \* FROM ("|`)users("|`)/)
-    expect(described_class.count).to be > 0
-  end
-
   it 'does not log query when logger level is not debug, but track runtime and count' do
     expect(described_class.count).to eq 0
     @logger.level = defined?(Logger::Severity) ? Logger::Severity::INFO : :info
@@ -30,4 +22,127 @@ def set_logger(logger) # rubocop:disable AccessorMethodName
     expect(@logger.logged(:debug).size).to eq 0
     expect(described_class.count).to be > 0
   end
+
+  describe 'for postgresql', :postgres do
+    it 'logs queries, runtime and count' do
+      expect(described_class.count).to eq 0
+      User.all
+      User.where(:id => 1).select_map(:id)
+      wait
+      expect(@logger.logged(:debug)[-2]).to match(/SELECT \* FROM "users"/)
+      expect(@logger.logged(:debug)[-1]).to match(/SELECT "id" FROM "users" WHERE \("id" = 1\)/)
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with bound variables' do
+      ds = Sequel::Model.db[:users].where(:id => :$id)
+      ds.call(:select, :id => 1)
+      wait
+      expect(@logger.logged(:debug).last).to match(
+        /SELECT \* FROM "users" WHERE \("id" = \$1\) \[1\]/
+      )
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with prepared statements' do
+      ds = Sequel::Model.db[:users].where(:id => :$id).prepare(:select, :users_by_id)
+      ds.call(:id => 1)
+      wait
+      expect(@logger.logged(:debug)[-2]).to match(
+        /PREPARE users_by_id AS SELECT \* FROM "users" WHERE \("id" = \$1\)/
+      )
+      expect(@logger.logged(:debug)[-1]).to match(
+        /EXECUTE users_by_id \[1\]/
+      )
+      expect(described_class.count).to be > 0
+    end
+  end
+
+  describe 'for mysql', :mysql do
+    it 'logs queries, runtime and count' do
+      expect(described_class.count).to eq 0
+      User.all
+      User.where(:id => 1).select_map(:id)
+      wait
+      expect(@logger.logged(:debug)[-2]).to match(/SELECT \* FROM `users`/)
+      expect(@logger.logged(:debug)[-1]).to match(/SELECT `id` FROM `users` WHERE \(`id` = 1\)/)
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with plain queries', :mysql do
+      Sequel::Model.db[:users].where(:id => 1).to_a
+      wait
+      expect(@logger.logged(:debug).last).to match(
+        /SELECT \* FROM `users` WHERE \(`id` = 1\)/
+      )
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with bound variables' do
+      ds = Sequel::Model.db[:users].where(:id => :$id)
+      ds.call(:select, :id => 1)
+      wait
+      expect(@logger.logged(:debug).last).to match(
+        /Executing SELECT \* FROM `users` WHERE \(`id` = \?\) \[1\]/
+      )
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with prepared statements' do
+      ds = Sequel::Model.db[:users].where(:id => :$id).prepare(:select, :users_by_id)
+      ds.call(:id => 1)
+      wait
+      expect(@logger.logged(:debug)[-2]).to match(
+        /Preparing users_by_id: SELECT \* FROM `users` WHERE \(`id` = \?\)/
+      )
+      expect(@logger.logged(:debug)[-1]).to match(
+        /Executing users_by_id \[1\]/
+      )
+      expect(described_class.count).to be > 0
+    end
+  end
+
+  describe 'for sqlite', :sqlite do
+    it 'logs queries, runtime and count' do
+      expect(described_class.count).to eq 0
+      User.all
+      User.where(:id => 1).select_map(:id)
+      wait
+      expect(@logger.logged(:debug)[-2]).to match(/SELECT \* FROM `users`/)
+      expect(@logger.logged(:debug)[-1]).to match(/SELECT `id` FROM `users` WHERE \(`id` = 1\)/)
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with plain queries', :mysql do
+      Sequel::Model.db[:users].where(:id => 1).to_a
+      wait
+      expect(@logger.logged(:debug).last).to match(
+        /SELECT \* FROM `users` WHERE \(`id` = 1\)/
+      )
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with bound variables' do
+      ds = Sequel::Model.db[:users].where(:id => :$id)
+      ds.call(:select, :id => 1)
+      wait
+      expect(@logger.logged(:debug).last).to match(
+        /SELECT \* FROM `users` WHERE \(`id` = :id\) {"id"=>1}/
+      )
+      expect(described_class.count).to be > 0
+    end
+
+    it 'works with prepared statements' do
+      ds = Sequel::Model.db[:users].where(:id => :$id).prepare(:select, :users_by_id)
+      ds.call(:id => 1)
+      wait
+      expect(@logger.logged(:debug)[-2]).to match(
+        /PREPARE users_by_id: SELECT \* FROM `users` WHERE \(`id` = :id\)/
+      )
+      expect(@logger.logged(:debug)[-1]).to match(
+        /EXECUTE users_by_id {"id"=>1}/
+      )
+      expect(described_class.count).to be > 0
+    end
+  end
 end