diff --git a/lib/mongo/collection.rb b/lib/mongo/collection.rb index d67baed..be6718f 100644 --- a/lib/mongo/collection.rb +++ b/lib/mongo/collection.rb @@ -79,7 +79,6 @@ module Mongo @db, @name = db, name @connection = @db.connection - @logger = @connection.logger @cache_time = @db.cache_time @cache = Hash.new(0) unless pk_factory @@ -322,12 +321,13 @@ module Mongo message.put_int(0) message.put_binary(BSON::BSON_CODER.serialize(selector, false, true).to_s) - @logger.debug("MONGODB #{@db.name}['#{@name}'].remove(#{selector.inspect})") if @logger - if safe - @connection.send_message_with_safe_check(Mongo::Constants::OP_DELETE, message, @db.name, nil, safe) - else - @connection.send_message(Mongo::Constants::OP_DELETE, message) - true + @connection.instrument( :remove, :database => @db.name, :collection => @name, :selector => selector ) do + if safe + @connection.send_message_with_safe_check(Mongo::Constants::OP_DELETE, message, @db.name, nil, safe) + else + @connection.send_message(Mongo::Constants::OP_DELETE, message) + true + end end end @@ -367,11 +367,13 @@ module Mongo message.put_int(update_options) message.put_binary(BSON::BSON_CODER.serialize(selector, false, true).to_s) message.put_binary(BSON::BSON_CODER.serialize(document, false, true).to_s) - @logger.debug("MONGODB #{@db.name}['#{@name}'].update(#{selector.inspect}, #{document.inspect})") if @logger - if safe - @connection.send_message_with_safe_check(Mongo::Constants::OP_UPDATE, message, @db.name, nil, safe) - else - @connection.send_message(Mongo::Constants::OP_UPDATE, message, nil) + + @connection.instrument( :update, :database => @db.name, :collection => @name, :selector => selector, :document => document ) do + if safe + @connection.send_message_with_safe_check(Mongo::Constants::OP_UPDATE, message, @db.name, nil, safe) + else + @connection.send_message(Mongo::Constants::OP_UPDATE, message, nil) + end end end @@ -838,11 +840,12 @@ module Mongo end raise InvalidOperation, "Exceded maximum insert size of 16,000,000 bytes" if message.size > 16_000_000 - @logger.debug("MONGODB #{@db.name}['#{collection_name}'].insert(#{documents.inspect})") if @logger - if safe - @connection.send_message_with_safe_check(Mongo::Constants::OP_INSERT, message, @db.name, nil, safe) - else - @connection.send_message(Mongo::Constants::OP_INSERT, message, nil) + @connection.instrument( :insert, :database => @db.name, :collection => collection_name, :documents => documents ) do + if safe + @connection.send_message_with_safe_check(Mongo::Constants::OP_INSERT, message, @db.name, nil, safe) + else + @connection.send_message(Mongo::Constants::OP_INSERT, message, nil) + end end documents.collect { |o| o[:_id] || o['_id'] } end diff --git a/lib/mongo/connection.rb b/lib/mongo/connection.rb index 8da2b00..489145a 100644 --- a/lib/mongo/connection.rb +++ b/lib/mongo/connection.rb @@ -534,6 +534,13 @@ module Mongo end end + # execute the block and log the operation as described by name/payload + def instrument( name, payload = {}, &blk ) + res = yield + log_operation(name, payload) + res + end + protected # Generic initialization code. @@ -587,6 +594,18 @@ module Mongo end end + ## Logging methods + + def log_operation( name, payload ) + return unless @logger + msg = "#{payload[:database]}['#{payload[:collection]}'].#{name}(" + msg += payload.values_at(:selector, :document, :documents, :fields ).compact.map(&:inspect).join(', ') + ")" + msg += ".skip(#{payload[:skip]})" if payload[:skip] + msg += ".limit(#{payload[:limit]})" if payload[:limit] + msg += ".sort(#{payload[:sort]})" if payload[:sort] + @logger.debug "MONGODB #{msg}" + end + private ## Methods for establishing a connection: diff --git a/lib/mongo/cursor.rb b/lib/mongo/cursor.rb index f372009..71a8ea3 100644 --- a/lib/mongo/cursor.rb +++ b/lib/mongo/cursor.rb @@ -378,13 +378,14 @@ module Mongo false else message = construct_query_message - @logger.debug query_log_message if @logger - results, @n_received, @cursor_id = @connection.receive_message( - Mongo::Constants::OP_QUERY, message, nil, @socket, @command) - @returned += @n_received - @cache += results - @query_run = true - close_cursor_if_query_complete + @connection.instrument( :find, instrument_payload ) do + results, @n_received, @cursor_id = @connection.receive_message( + Mongo::Constants::OP_QUERY, message, nil, @socket, @command) + @returned += @n_received + @cache += results + @query_run = true + close_cursor_if_query_complete + end true end end @@ -401,10 +402,13 @@ module Mongo message end - def query_log_message - "#{@db.name}['#{@collection.name}'].find(#{@selector.inspect}, #{@fields ? @fields.inspect : '{}'})" + - "#{@skip != 0 ? ('.skip(' + @skip.to_s + ')') : ''}#{@limit != 0 ? ('.limit(' + @limit.to_s + ')') : ''}" + - "#{@order ? ('.sort(' + @order.inspect + ')') : ''}" + def instrument_payload + log = { :database => @db.name, :collection => @collection.name, :selector => selector } + log[:fields] = @fields if @fields + log[:skip] = @skip if @skip && (@skip > 0) + log[:limit] = @limit if @limit && (@limit > 0) + log[:order] = @order if @order + log end def construct_query_spec diff --git a/test/unit/collection_test.rb b/test/unit/collection_test.rb index 45d0bed..f305d9d 100644 --- a/test/unit/collection_test.rb +++ b/test/unit/collection_test.rb @@ -14,7 +14,7 @@ class CollectionTest < Test::Unit::TestCase @conn.expects(:send_message).with do |op, msg, log| op == 2001 end - @logger.stubs(:debug) + @conn.stubs(:log_operation) @coll.update({}, {:title => 'Moby Dick'}) end @@ -25,8 +25,8 @@ class CollectionTest < Test::Unit::TestCase @conn.expects(:send_message).with do |op, msg, log| op == 2002 end - @logger.expects(:debug).with do |msg| - msg.include?("Moby") + @conn.expects(:log_operation).with do |name, payload| + (name == :insert) && payload[:documents][0][:title].include?('Moby') end @coll.insert({:title => 'Moby Dick'}) end @@ -38,8 +38,8 @@ class CollectionTest < Test::Unit::TestCase @conn.expects(:receive_message).with do |op, msg, log, sock| op == 2004 end.returns([[], 0, 0]) - @logger.expects(:debug).with do |msg| - msg.include?('Moby') + @conn.expects(:log_operation).with do |name, payload| + (name == :find) && payload[:selector][:title].include?('Moby') end @coll.find({:title => 'Moby Dick'}).sort([['title', 1], ['author', 1]]).next_document end @@ -52,8 +52,8 @@ class CollectionTest < Test::Unit::TestCase @conn.expects(:send_message).with do |op, msg, log| op == 2002 end - @logger.expects(:debug).with do |msg| - msg.include?("Binary") + @conn.expects(:log_operation).with do |name, payload| + (name == :insert) && payload[:documents][0][:data].inspect.include?('Binary') end @coll.insert({:data => data}) end @@ -65,8 +65,8 @@ class CollectionTest < Test::Unit::TestCase @conn.expects(:send_message_with_safe_check).with do |op, msg, db_name, log| op == 2001 end - @logger.expects(:debug).with do |msg| - msg.include?("testing['books'].update") + @conn.expects(:log_operation).with do |name, payload| + (name == :update) && payload[:document][:title].include?('Moby') end @coll.update({}, {:title => 'Moby Dick'}, :safe => true) end @@ -78,7 +78,7 @@ class CollectionTest < Test::Unit::TestCase @conn.expects(:send_message_with_safe_check).with do |op, msg, db_name, log| op == 2001 end - @logger.stubs(:debug) + @conn.stubs(:log_operation) @coll.update({}, {:title => 'Moby Dick'}, :safe => true) end