RUBY-306 clean up logging.

lib/mongo.rb

@@ -56,6 +56,7 @@ require 'bson'
 require 'mongo/util/conversions'
 require 'mongo/util/support'
 require 'mongo/util/core_ext'
+require 'mongo/util/logging'
 require 'mongo/util/node'
 require 'mongo/util/pool'
 require 'mongo/util/pool_manager'

lib/mongo/collection.rb

@@ -19,6 +19,7 @@ module Mongo
 
   # A named collection of documents in a database.
   class Collection
+    include Mongo::Logging
 
     attr_reader :db, :name, :pk_factory, :hint, :safe
 
@@ -377,7 +378,7 @@ module Mongo
       message.put_int(0)
       message.put_binary(BSON::BSON_CODER.serialize(selector, false, true, @connection.max_bson_size).to_s)
 
-      @connection.instrument(:remove, :database => @db.name, :collection => @name, :selector => selector) do
+      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
@@ -424,7 +425,7 @@ module Mongo
       message.put_binary(BSON::BSON_CODER.serialize(selector, false, true).to_s)
       message.put_binary(BSON::BSON_CODER.serialize(document, false, true, @connection.max_bson_size).to_s)
 
-      @connection.instrument(:update, :database => @db.name, :collection => @name, :selector => selector, :document => document) do
+      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
@@ -936,7 +937,7 @@ module Mongo
       end
       raise InvalidOperation, "Exceded maximum insert size of 16,000,000 bytes" if message.size > 16_000_000
 
-      @connection.instrument(:insert, :database => @db.name, :collection => collection_name, :documents => documents) do
+      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

lib/mongo/connection.rb

@@ -24,6 +24,8 @@ module Mongo
 
   # Instantiates and manages connections to MongoDB.
   class Connection
+    include Mongo::Logging
+
     TCPSocket = ::TCPSocket
     Mutex = ::Mutex
     ConditionVariable = ::ConditionVariable
@@ -625,32 +627,6 @@ module Mongo
       end
     end
 
-    # Log a message with the given level.
-    def log(level, message)
-      return unless @logger
-      case level
-        when :debug then
-          @logger.debug "MONGODB [DEBUG] #{msg}"
-        when :warn then
-          @logger.warn "MONGODB [WARNING] #{msg}"
-        when :error then
-          @logger.error "MONGODB [ERROR] #{msg}"
-        when :fatal then
-          @logger.fatal "MONGODB [FATAL] #{msg}"
-        else
-          @logger.info "MONGODB [INFO] #{msg}"
-      end
-    end
-
-    # Execute the block and log the operation described by name
-    # and payload.
-    # TODO: Not sure if this should take a block.
-    def instrument(name, payload = {}, &blk)
-      res = yield
-      log_operation(name, payload)
-      res
-    end
-
     protected
 
     # Generic initialization code.
@@ -731,18 +707,6 @@ 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[:order]})"  if payload[:order]
-      @logger.debug "MONGODB #{msg}"
-    end
-
     private
 
     ## Methods for establishing a connection:
@@ -787,7 +751,7 @@ module Mongo
 
     ## Low-level connection methods.
 
-    def receive(sock, cursor_id, exhaust)
+    def receive(sock, cursor_id, exhaust=false)
       begin
         if exhaust
           docs = []

lib/mongo/cursor.rb

@@ -21,6 +21,7 @@ module Mongo
     include Enumerable
     include Mongo::Constants
     include Mongo::Conversions
+    include Mongo::Logging
 
     attr_reader :collection, :selector, :fields,
       :order, :hint, :snapshot, :timeout,
@@ -332,7 +333,7 @@ module Mongo
         message = BSON::ByteBuffer.new([0, 0, 0, 0])
         message.put_int(1)
         message.put_long(@cursor_id)
-        @logger.debug("MONGODB cursor.close #{@cursor_id}") if @logger
+        log(:debug, "Cursor#close #{@cursor_id}")
         @connection.send_message(Mongo::Constants::OP_KILL_CURSORS, message, :connection => :reader)
       end
       @cursor_id = 0
@@ -458,8 +459,8 @@ module Mongo
 
     def send_initial_query
       message = construct_query_message
-      payload = instrument_payload if @connection.logger
+      payload = instrument_payload if @logger
-      @connection.instrument(:find, payload) do
+      instrument(:find, payload) do
         results, @n_received, @cursor_id = @connection.receive_message(
           Mongo::Constants::OP_QUERY, message, nil, @socket, @command,
           @read_preference, @options & OP_QUERY_EXHAUST != 0)
@@ -489,7 +490,7 @@ module Mongo
 
       # Cursor id.
       message.put_long(@cursor_id)
-      @logger.debug("MONGODB cursor.refresh() for cursor #{@cursor_id}") if @logger
+      log(:debug, "cursor.refresh() for cursor #{@cursor_id}") if @logger
       results, @n_received, @cursor_id = @connection.receive_message(
           Mongo::Constants::OP_GET_MORE, message, nil, @socket, @command, @read_preference)
       @returned += @n_received

test/unit/collection_test.rb

@@ -15,7 +15,7 @@ class CollectionTest < Test::Unit::TestCase
       @conn.expects(:send_message).with do |op, msg, log|
         op == 2001
       end
-      @conn.stubs(:log_operation)
+      @coll.stubs(:log_operation)
       @coll.update({}, {:title => 'Moby Dick'})
     end
 
@@ -26,7 +26,7 @@ class CollectionTest < Test::Unit::TestCase
       @conn.expects(:send_message).with do |op, msg, log|
         op == 2002
       end
-      @conn.expects(:log_operation).with do |name, payload|
+      @coll.expects(:log_operation).with do |name, payload|
         (name == :insert) && payload[:documents][0][:title].include?('Moby')
       end
       @coll.insert({:title => 'Moby Dick'})
@@ -39,9 +39,7 @@ class CollectionTest < Test::Unit::TestCase
       @conn.expects(:receive_message).with do |op, msg, log, sock|
         op == 2004
       end.returns([[], 0, 0])
-      @conn.expects(:log_operation).with do |name, payload|
+      @logger.expects(:debug)
-        (name == :find) && payload[:selector][:title].include?('Moby')
-      end
       @coll.find({:title => 'Moby Dick'}).sort([['title', 1], ['author', 1]]).next_document
     end
 
@@ -53,7 +51,7 @@ class CollectionTest < Test::Unit::TestCase
       @conn.expects(:send_message).with do |op, msg, log|
         op == 2002
       end
-      @conn.expects(:log_operation).with do |name, payload|
+      @coll.expects(:log_operation).with do |name, payload|
         (name == :insert) && payload[:documents][0][:data].inspect.include?('Binary')
       end
       @coll.insert({:data => data})
@@ -66,7 +64,7 @@ class CollectionTest < Test::Unit::TestCase
       @conn.expects(:send_message_with_safe_check).with do |op, msg, db_name, log|
         op == 2001
       end
-      @conn.expects(:log_operation).with do |name, payload|
+      @coll.expects(:log_operation).with do |name, payload|
         (name == :update) && payload[:document][:title].include?('Moby')
       end
       @coll.update({}, {:title => 'Moby Dick'}, :safe => true)
@@ -79,7 +77,7 @@ class CollectionTest < Test::Unit::TestCase
       @conn.expects(:send_message_with_safe_check).with do |op, msg, db_name, log|
         op == 2001
       end
-      @conn.stubs(:log_operation)
+      @coll.stubs(:log_operation)
       @coll.update({}, {:title => 'Moby Dick'}, :safe => true)
     end