diff --git a/lib/sequel_rails/railties/log_subscriber.rb b/lib/sequel_rails/railties/log_subscriber.rb index 81ca0c6..f38d674 100644 --- a/lib/sequel_rails/railties/log_subscriber.rb +++ b/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) diff --git a/spec/lib/sequel_rails/railties/log_subscriber_spec.rb b/spec/lib/sequel_rails/railties/log_subscriber_spec.rb index 65486e7..64a702a 100644 --- a/spec/lib/sequel_rails/railties/log_subscriber_spec.rb +++ b/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