Refactored logging of DB operations to use Connection#instrument.

This allows for easy overriding, e.g. to ActiveSupport notifications.
This commit is contained in:
Steve Sloan 2011-01-28 22:20:41 -08:00 committed by Kyle Banker
parent 7c4740c47c
commit 8a7296599b
4 changed files with 64 additions and 38 deletions

View File

@ -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

View File

@ -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:

View File

@ -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

View File

@ -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