Permalink
Browse files

Merge pull request #367 from mongodb/log-instrumentation

Adding logging and loggable infrastructure
  • Loading branch information...
2 parents 5df6311 + fafc5e8 commit 2ce15cbbf48a4280a7da5ffda266131d38128cce @durran durran committed Feb 23, 2014
Showing with 335 additions and 0 deletions.
  1. +2 −0 lib/mongo.rb
  2. +56 −0 lib/mongo/loggable.rb
  3. +130 −0 lib/mongo/logger.rb
  4. +62 −0 spec/mongo/loggable_spec.rb
  5. +85 −0 spec/mongo/logger_spec.rb
View
2 lib/mongo.rb
@@ -5,6 +5,8 @@
require 'mongo/collection'
require 'mongo/database'
require 'mongo/event'
+require 'mongo/loggable'
+require 'mongo/logger'
require 'mongo/pool'
require 'mongo/protocol'
require 'mongo/scope'
View
56 lib/mongo/loggable.rb
@@ -0,0 +1,56 @@
+# Copyright (C) 2009-2014 MongoDB, Inc.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+module Mongo
+
+ # Allows objects to easily log operations.
+ #
+ # @since 3.0.0
+ module Loggable
+
+ # Log the operations. If a block is provided it will be yielded to,
+ # otherwise only the logging will take place.
+ #
+ # @example Log a query operation.
+ # loggable.log(:debug, "MONGO.query", operations)
+ #
+ # @param [ Symbol ] level The log level.
+ # @param [ String ] prefix The prefix for the log line.
+ # @param [ Array<Object> ] operations The operations to log. The must
+ # respond to #log_message.
+ #
+ # @return [ Object ] The result of the block or nil if no block given.
+ #
+ # @since 3.0.0
+ def log(level, prefix, operations)
+ started = Time.new
+ begin
+ yield if block_given?
+ rescue Exception => e
+ raise e
+ ensure
+ runtime = ("%.4fms" % (1000 * (Time.now.to_f - started.to_f)))
+ operations.each do |operation|
+ Logger.send(level, prefix, log_inspect(operation), runtime)
+ end
+ end
+ end
+
+ private
+
+ def log_inspect(operation)
+ operation.respond_to?(:log_message) ? operation.log_message : operation
+ end
+ end
+end
View
130 lib/mongo/logger.rb
@@ -0,0 +1,130 @@
+# Copyright (C) 2009-2014 MongoDB, Inc.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+module Mongo
+
+ # Provides ability to log messages.
+ #
+ # @since 3.0.0
+ class Logger
+
+ class << self
+
+ # Log a debug level message.
+ #
+ # @example Log a debug level message.
+ # Logger.debug('mongo', 'message', '10ms')
+ #
+ # @param [ String ] prefix The category prefix.
+ # @param [ String ] message The log message.
+ # @param [ String ] runtime The time of the operation.
+ #
+ # @since 3.0.0
+ def debug(prefix, message, runtime)
+ logger.debug("#{prefix} | #{message} | runtime: #{runtime}")
+ end
+
+ # Log a error level message.
+ #
+ # @example Log a error level message.
+ # Logger.error('mongo', 'message', '10ms')
+ #
+ # @param [ String ] prefix The category prefix.
+ # @param [ String ] message The log message.
+ # @param [ String ] runtime The time of the operation.
+ #
+ # @since 3.0.0
+ def error(prefix, message, runtime)
+ logger.error("#{prefix} | #{message} | runtime: #{runtime}")
+ end
+
+ # Log a fatal level message.
+ #
+ # @example Log a fatal level message.
+ # Logger.fatal('mongo', 'message', '10ms')
+ #
+ # @param [ String ] prefix The category prefix.
+ # @param [ String ] message The log message.
+ # @param [ String ] runtime The time of the operation.
+ #
+ # @since 3.0.0
+ def fatal(prefix, message, runtime)
+ logger.fatal("#{prefix} | #{message} | runtime: #{runtime}")
+ end
+
+ # Log a info level message.
+ #
+ # @example Log a info level message.
+ # Logger.info('mongo', 'message', '10ms')
+ #
+ # @param [ String ] prefix The category prefix.
+ # @param [ String ] message The log message.
+ # @param [ String ] runtime The time of the operation.
+ #
+ # @since 3.0.0
+ def info(prefix, message, runtime)
+ logger.info("#{prefix} | #{message} | runtime: #{runtime}")
+ end
+
+ # Log a warn level message.
+ #
+ # @example Log a warn level message.
+ # Logger.warn('mongo', 'message', '10ms')
+ #
+ # @param [ String ] prefix The category prefix.
+ # @param [ String ] message The log message.
+ # @param [ String ] runtime The time of the operation.
+ #
+ # @since 3.0.0
+ def warn(prefix, message, runtime)
+ logger.warn("#{prefix} | #{message} | runtime: #{runtime}")
+ end
+
+ # Get the wrapped logger. If none was set will return a default debug
+ # level logger.
+ #
+ # @example Get the wrapped logger.
+ # Mongo::Logger.logger
+ #
+ # @return [ ::Logger ] The wrapped logger.
+ #
+ # @since 3.0.0
+ def logger
+ @logger ||= default_logger
+ end
+
+ # Set the logger.
+ #
+ # @example Set the wrapped logger.
+ # Mongo::Logger.logger = logger
+ #
+ # @param [ ::Logger ] other The logger to set.
+ #
+ # @return [ ::Logger ] The wrapped logger.
+ #
+ # @since 3.0.0
+ def logger=(other)
+ @logger = other
+ end
+
+ private
+
+ def default_logger
+ logger = ::Logger.new($stdout)
+ logger.level = ::Logger::DEBUG
+ logger
+ end
+ end
+ end
+end
View
62 spec/mongo/loggable_spec.rb
@@ -0,0 +1,62 @@
+require 'spec_helper'
+
+describe Mongo::Loggable do
+
+ let(:operation) do
+ Class.new do
+ def log_message
+ 'test'
+ end
+ end.new
+ end
+
+ describe '#log' do
+
+ let(:loggable) do
+ Class.new do
+ include Mongo::Loggable
+ end.new
+ end
+
+ let(:operation) do
+ double('operation')
+ end
+
+ before do
+ expect(operation).to receive(:log_message).and_return('test')
+ expect(Mongo::Logger).to receive(:debug).with('MONGO', 'test', anything())
+ end
+
+ context 'when a block is provided' do
+
+ context 'when an exception occurs' do
+
+ it 'logs the message' do
+ expect {
+ loggable.log(:debug, 'MONGO', [ operation ]) do
+ raise RuntimeError
+ end
+ }.to raise_error(RuntimeError)
+ end
+ end
+
+ context 'when no exception occurs' do
+
+ it 'executes the block and logs the message' do
+ expect(
+ loggable.log(:debug, 'MONGO', [ operation ]) do
+ 'testing'
+ end
+ ).to eq('testing')
+ end
+ end
+ end
+
+ context 'when no block is provided' do
+
+ it 'logs the message' do
+ expect(loggable.log(:debug, 'MONGO', [ operation ])).to be_nil
+ end
+ end
+ end
+end
View
85 spec/mongo/logger_spec.rb
@@ -0,0 +1,85 @@
+require 'spec_helper'
+
+describe Mongo::Logger do
+
+ let(:logger) do
+ described_class.logger
+ end
+
+ describe '.debug' do
+
+ it 'logs a debug message' do
+ expect(logger).to receive(:debug).with("mongo.query | message | runtime: 10ms")
+ described_class.debug('mongo.query', 'message', '10ms')
+ end
+ end
+
+ describe '.error' do
+
+ it 'logs a error message' do
+ expect(logger).to receive(:error).with("mongo.query | message | runtime: 10ms")
+ described_class.error('mongo.query', 'message', '10ms')
+ end
+ end
+
+ describe '.fatal' do
+
+ it 'logs a fatal message' do
+ expect(logger).to receive(:fatal).with("mongo.query | message | runtime: 10ms")
+ described_class.fatal('mongo.query', 'message', '10ms')
+ end
+ end
+
+ describe '.info' do
+
+ it 'logs a info message' do
+ expect(logger).to receive(:info).with("mongo.query | message | runtime: 10ms")
+ described_class.info('mongo.query', 'message', '10ms')
+ end
+ end
+
+ describe '.logger' do
+
+ context 'when no logger has been set' do
+
+ it 'returns the default logger' do
+ expect(logger.level).to eq(Logger::DEBUG)
+ end
+ end
+
+ context 'when a logger has been set' do
+
+ let(:info) do
+ Logger.new($stdout).tap do |log|
+ log.level = Logger::INFO
+ end
+ end
+
+ let(:debug) do
+ Logger.new($stdout).tap do |log|
+ log.level = Logger::DEBUG
+ end
+ end
+
+ before do
+ described_class.logger = info
+ end
+
+ after do
+ described_class.logger = debug
+ end
+
+ it 'returns the provided logger' do
+ expect(logger.level).to eq(Logger::INFO)
+ end
+ end
+ end
+
+ describe '.warn' do
+
+ it 'logs a warn message' do
+ expect(logger).to receive(:warn).with("mongo.query | message | runtime: 10ms")
+ described_class.warn('mongo.query', 'message', '10ms')
+ end
+ end
+end

0 comments on commit 2ce15cb

Please sign in to comment.