Merge branch 'christian/logrework'

lib/ddtrace/logger.rb

@@ -0,0 +1,34 @@
+require 'logger'
+
+module Datadog
+  LOG_PREFIX = 'ddtrace'.freeze
+
+  # A custom logger with minor enhancements:
+  # - progname defaults to ddtrace to clearly identify Datadog dd-trace-rb related messages
+  # - adds last caller stack-trace info to know where the message comes from
+  class Logger < ::Logger
+    def initialize(*args, &block)
+      super
+      self.progname = LOG_PREFIX
+    end
+
+    def add(severity, message = nil, progname = nil, &block)
+      return super unless debug?
+
+      # We are in debug mode, add stack trace to help debugging
+      where = ''
+      c = caller
+      where = "(#{c[1]}) " if c.length > 1
+
+      if block_given?
+        super(severity, message, progname) do
+          "#{where}#{yield}"
+        end
+      else
+        super(severity, message, "#{where}#{progname}")
+      end
+    end
+
+    alias log add
+  end
+end

lib/ddtrace/tracer.rb

@@ -4,6 +4,7 @@
 
 require 'ddtrace/span'
 require 'ddtrace/buffer'
+require 'ddtrace/logger'
 require 'ddtrace/writer'
 require 'ddtrace/sampler'
 
@@ -21,12 +22,27 @@ class Tracer
     # namespace. This logger outputs to +STDOUT+ by default, and is considered thread-safe.
     def self.log
       unless defined? @logger
-        @logger = Logger.new(STDOUT)
+        @logger = Datadog::Logger.new(STDOUT)
         @logger.level = Logger::WARN
       end
       @logger
     end
 
+    # Override the default logger with a custom one.
+    def self.log=(logger)
+      return unless logger
+      return unless logger.respond_to? :methods
+      return unless logger.respond_to? :error
+      if logger.respond_to? :methods
+        unimplemented = Logger.new(STDOUT).methods - logger.methods
+        unless unimplemented.empty?
+          logger.error("logger #{logger} does not implement #{unimplemented}")
+          return
+        end
+      end
+      @logger = logger
+    end
+
     # Activate the debug mode providing more information related to tracer usage
     def self.debug_logging=(value)
       log.level = value ? Logger::DEBUG : Logger::WARN

test/logger_test.rb

@@ -1,4 +1,5 @@
 require 'logger'
+require 'stringio'
 require 'helper'
 require 'ddtrace/span'
 
@@ -7,6 +8,7 @@ def test_tracer_logger
     # a logger must be available by default
     assert Datadog::Tracer.log
     Datadog::Tracer.log.debug('a logger is here!')
+    Datadog::Tracer.log.info() { 'flash info' } # &block syntax
   end
 
   def test_tracer_default_debug_mode
@@ -25,4 +27,102 @@ def test_tracer_set_debug_mode
     Datadog::Tracer.debug_logging = false
     assert_equal(logger.level, Logger::WARN)
   end
+
+  def test_tracer_logger_override
+    default_log = Datadog::Tracer.log
+
+    buf = StringIO.new
+
+    Datadog::Tracer.log = Datadog::Logger.new(buf)
+    Datadog::Tracer.log.level = ::Logger::WARN
+
+    assert_equal(false, Datadog::Tracer.log.debug?)
+    assert_equal(false, Datadog::Tracer.log.info?)
+    assert_equal(true, Datadog::Tracer.log.warn?)
+    assert_equal(true, Datadog::Tracer.log.error?)
+    assert_equal(true, Datadog::Tracer.log.fatal?)
+
+    Datadog::Tracer.log.debug('never to be seen')
+    Datadog::Tracer.log.warn('careful here')
+    Datadog::Tracer.log.error() { 'this does not work' }
+    Datadog::Tracer.log.error('mmm') { 'neither does this' }
+
+    lines = buf.string.lines
+
+    # Test below iterates on lines, this is required for Ruby 1.9 backward compatibility.
+    assert_equal(3, lines.length, 'there should be 3 log messages') if lines.respond_to? :length
+    i = 0
+    lines.each do |l|
+      case i
+      when 0
+        assert_match(/W,.*WARN -- ddtrace: careful here/, l)
+      when 1
+        assert_match(/E,.*ERROR -- ddtrace: this does not work/, l)
+      when 2
+        assert_match(/E,.*ERROR -- mmm: neither does this/, l)
+      end
+      i += 1
+    end
+
+    Datadog::Tracer.log = default_log
+  end
+
+  def test_tracer_logger_override_debug
+    default_log = Datadog::Tracer.log
+
+    buf = StringIO.new
+
+    Datadog::Tracer.log = Datadog::Logger.new(buf)
+    Datadog::Tracer.log.level = ::Logger::DEBUG
+
+    assert_equal(true, Datadog::Tracer.log.debug?)
+    assert_equal(true, Datadog::Tracer.log.info?)
+    assert_equal(true, Datadog::Tracer.log.warn?)
+    assert_equal(true, Datadog::Tracer.log.error?)
+    assert_equal(true, Datadog::Tracer.log.fatal?)
+
+    Datadog::Tracer.log.debug('detailed things')
+    Datadog::Tracer.log.info() { 'more detailed info' }
+
+    lines = buf.string.lines
+
+    # Test below iterates on lines, this is required for Ruby 1.9 backward compatibility.
+    assert_equal(2, lines.length, 'there should be 3 log messages') if lines.respond_to? :length
+    i = 0
+    lines.each do |l|
+      case i
+      when 0
+        assert_match(
+          /D,.*DEBUG -- ddtrace: \(.*logger_test.rb\:.*test_tracer_logger_override_debug.*\) detailed things/,
+          l
+        )
+      when 1
+        assert_match(
+          /I,.*INFO -- ddtrace: \(.*logger_test.rb\:.*test_tracer_logger_override_debug.*\) more detailed info/,
+          l
+        )
+      end
+      i += 1
+    end
+
+    Datadog::Tracer.log = default_log
+  end
+
+  def test_tracer_logger_override_refuse
+    default_log = Datadog::Tracer.log
+
+    buf = StringIO.new
+
+    buf_log = Datadog::Logger.new(buf)
+
+    Datadog::Tracer.log = buf_log
+    Datadog::Tracer.log.level = ::Logger::DEBUG
+
+    Datadog::Tracer.log = nil
+    assert_equal(buf_log, Datadog::Tracer.log)
+    Datadog::Tracer.log = "this won't work"
+    assert_equal(buf_log, Datadog::Tracer.log)
+
+    Datadog::Tracer.log = default_log
+  end
 end