Refactor logging integrations

spec/raven/log_backend_spec.cr

@@ -0,0 +1,148 @@
+require "log"
+require "colorize"
+
+private def build_logger(source = nil, **opts)
+  opts = {
+    record_breadcrumbs: false,
+    capture_exceptions: false,
+    capture_all:        false,
+  }.merge(opts)
+
+  backend = Raven::LogBackend.new(**opts)
+
+  Log::Builder.new
+    .tap(&.bind("*", :trace, backend))
+    .for(source.to_s)
+end
+
+private def with_clean_configuration
+  prev_configuration = Raven.instance.configuration.dup
+  begin
+    Raven.instance.configuration = build_configuration
+    yield
+  ensure
+    Raven.instance.configuration = prev_configuration
+  end
+end
+
+describe Raven::LogBackend do
+  around_each do |example|
+    Raven::BreadcrumbBuffer.clear!
+    with_clean_configuration do
+      Raven.configuration.exclude_loggers.clear
+      example.run
+    end
+    Raven::BreadcrumbBuffer.clear!
+  end
+
+  context ":record_breadcrumbs" do
+    it "respects Raven.configuration.exclude_loggers setting" do
+      Raven.configuration.exclude_loggers = %w[spec.raven.*]
+
+      logger = build_logger("spec.raven.crumbs", record_breadcrumbs: true)
+      logger.trace { "foo" }
+
+      logger = build_logger("spec.raven", record_breadcrumbs: true)
+      logger.trace { "bar" }
+
+      Raven.breadcrumbs.should be_empty
+    end
+
+    context "with exception" do
+      it "records entries as breadcrumbs (true)" do
+        ex = build_exception
+
+        logger = build_logger("spec.raven", record_breadcrumbs: true)
+        logger.trace(exception: ex) { "foo".colorize(:green) }
+
+        crumbs = Raven.breadcrumbs
+        crumbs.size.should eq(1)
+
+        last = crumbs.peek.should_not be_nil
+        last.level.should eq(Raven::Breadcrumb::Severity::DEBUG)
+        last.category.should eq("spec.raven")
+        last.message.should eq("foo -- (%s): %s" % {ex.class, ex.message})
+      end
+    end
+
+    context "without exception" do
+      it "records entries as breadcrumbs (true)" do
+        logger = build_logger("spec.raven", record_breadcrumbs: true)
+        logger.trace { "foo".colorize(:green) }
+
+        crumbs = Raven.breadcrumbs
+        crumbs.size.should eq(1)
+
+        last = crumbs.peek.should_not be_nil
+        last.level.should eq(Raven::Breadcrumb::Severity::DEBUG)
+        last.category.should eq("spec.raven")
+        last.message.should eq("foo")
+      end
+    end
+
+    it "records entries as breadcrumbs (false)" do
+      logger = build_logger(record_breadcrumbs: false)
+      logger.trace { "boo!" }
+
+      Raven.breadcrumbs.should be_empty
+    end
+  end
+
+  context ":capture_exceptions" do
+    it "captures attached exception if present (true)" do
+      ex = build_exception
+
+      logger = build_logger(capture_exceptions: true)
+      logger.trace(exception: ex) { "boo!" }
+
+      Raven.captured_exception?(ex).should be_true
+    end
+
+    it "captures attached exception if present (false)" do
+      ex = build_exception
+
+      logger = build_logger(capture_exceptions: false)
+      logger.trace(exception: ex) { "boo!" }
+
+      Raven.captured_exception?(ex).should be_false
+    end
+  end
+
+  context ":capture_all" do
+    it "captures attached exception if present (true)" do
+      ex = build_exception
+
+      logger = build_logger(capture_all: true)
+      logger.trace(exception: ex) { "boo!" }
+
+      Raven.captured_exception?(ex).should be_true
+    end
+
+    it "captures attached exception if present (false)" do
+      ex = build_exception
+
+      logger = build_logger(capture_all: false)
+      logger.trace(exception: ex) { "boo!" }
+
+      Raven.captured_exception?(ex).should be_false
+    end
+
+    it "captures every entry (true)" do
+      prev_event_id = Raven.last_event_id
+
+      logger = build_logger(capture_all: true)
+      logger.trace { "boo!" }
+
+      Raven.last_event_id.should_not eq(prev_event_id)
+    end
+
+    it "captures every entry (false)" do
+      prev_event_id = Raven.last_event_id
+
+      logger = build_logger(capture_all: false)
+      logger.trace { "boo!" }
+
+      Raven.last_event_id.should eq(prev_event_id)
+    end
+  end
+end

src/raven/integrations/kernel/logger.cr

@@ -1,25 +1,25 @@
 require "logger"
-require "../shared/log_helper"
 
-class Logger
-  include Raven::LogHelper
+# TODO: remove after/if https://github.com/crystal-lang/crystal/pull/9570 is merged
+struct Log::Entry
+  def initialize(@source : String, @severity : Severity, @message : String, @data : Log::Metadata, @exception : Exception?, @timestamp : Time)
+  end
+end
 
-  private BREADCRUMB_LEVELS = {
-    :debug => :debug,
-    :info  => :info,
-    :warn  => :warning,
-    :error => :error,
-    :fatal => :critical,
-  } of ::Logger::Severity => Raven::Breadcrumb::Severity
+class Logger
+  property :__raven_log_backend { Raven::LogBackend.new }
 
   private def write(severity, datetime, progname, message)
-    level = BREADCRUMB_LEVELS[severity]?
+    level = Log::Severity.parse?(severity.to_s) || Log::Severity::Debug
+    data = Log::Metadata.new
 
-    record_breadcrumb(
-      message.to_s,
-      level,
-      datetime,
-      progname.to_s,
+    __raven_log_backend.write Log::Entry.new(
+      source: progname.to_s,
+      severity: level,
+      message: message.to_s,
+      data: data,
+      exception: nil,
+      timestamp: datetime,
     )
     previous_def
   end

src/raven/integrations/log.cr → src/raven/log_backend.cr

@@ -1,13 +1,7 @@
 require "log"
 require "log/json"
-require "./shared/log_helper"
 
 module Raven
-  # ```
-  # require "raven"
-  # require "raven/integrations/log"
-  # ```
-  #
   # `::Log::Backend` recording logged messages.
   #
   # ```
@@ -17,8 +11,6 @@ module Raven
   # end
   # ```
   class LogBackend < ::Log::Backend
-    include LogHelper
-
     private BREADCRUMB_LEVELS = {
       :trace  => :debug,
       :debug  => :debug,
@@ -62,6 +54,47 @@ module Raven
     )
     end
 
+    protected delegate :ignored_logger?,
+      to: Raven.configuration
+
+    protected def deansify(message : String?) : String?
+      message.try &.gsub(/\x1b[^m]*m/, "")
+    end
+
+    protected def record_breadcrumb(message, severity, timestamp, source, data = nil)
+      level = BREADCRUMB_LEVELS[severity]?
+
+      message = deansify(message).presence
+      logger = source.presence || "logger"
+
+      Raven.breadcrumbs.record do |crumb|
+        crumb.message = message
+        crumb.level = level if level
+        crumb.timestamp = timestamp if timestamp
+        crumb.category = logger
+        crumb.data = data if data
+      end
+    end
+
+    protected def capture_exception(exception, message, severity, timestamp, source, data = nil)
+      level = EXCEPTION_LEVELS[severity]?
+
+      if exception.is_a?(String)
+        exception = deansify(exception)
+      end
+
+      message = deansify(message).presence
+      logger = source.presence || "logger"
+
+      Raven.capture(exception) do |event|
+        event.culprit = message if message
+        event.level = level if level
+        event.timestamp = timestamp if timestamp
+        event.logger = logger
+        event.tags = data if data
+      end
+    end
+
     def active?
       record_breadcrumbs? || capture?
     end
@@ -70,35 +103,35 @@ module Raven
       capture_exceptions? || capture_all?
     end
 
+    # ameba:disable Metrics/CyclomaticComplexity
     def write(entry : ::Log::Entry)
       return unless active?
+      return if ignored_logger?(entry.source)
 
       data = entry.context.extend(entry.data.to_h)
-      data = data.empty? ? nil : JSON.parse(data.to_json).as_h
+      data = data.empty? ? nil : JSON.parse(data.to_json).as_h # FIXME
 
       message = entry.message
       ex = entry.exception
 
       if capture?
-        level = EXCEPTION_LEVELS[entry.severity]?
         capture_exception(
           ex ? ex : message,
           ex ? message : nil,
-          level,
+          entry.severity,
           entry.timestamp,
           entry.source,
           data,
         ) if ex || capture_all?
       end
 
       if record_breadcrumbs?
-        level = BREADCRUMB_LEVELS[entry.severity]?
         if ex
-          message += " –- (#{ex.class}): #{ex.message || "n/a"}"
+          message += " -- (#{ex.class}): #{ex.message || "n/a"}"
         end
         record_breadcrumb(
           message,
-          level,
+          entry.severity,
           entry.timestamp,
           entry.source,
           data,