Expose Lorekeeper::BacktraceCleaner (#37)

CHANGELOG.md

@@ -1,3 +1,6 @@
+# 2.6.0
+* Expose Lorekeeper::BacktraceCleaner
+
 # 2.5.0
 * Update the backtrace cleaner in JSONLogger to remove web server and stdlib lines, and to strip the Rails.root prefix
 

README.md

@@ -10,7 +10,7 @@ When used without extra fields it outputs 20% faster than the standard Logger fo
 Add this line to your application's Gemfile:
 
 ```ruby
-gem 'lorekeeper', '~> 1.7'
+gem 'lorekeeper', '~> 2.0'
 ```
 
 And then execute:
@@ -210,6 +210,14 @@ end
 ```
 
 
+### Backtrace Cleaner
+
+The backtrace cleaner can be used independently:
+
+```ruby
+Lorekeeper::BacktraceCleaner.instance.clean(backtrace)
+```
+
 
 ## License
 

lib/lorekeeper.rb

@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require 'lorekeeper/version'
+require 'lorekeeper/backtrace_cleaner'
 require 'lorekeeper/fast_logger'
 require 'lorekeeper/simple_logger'
 require 'lorekeeper/json_logger'

lib/lorekeeper/backtrace_cleaner.rb

@@ -0,0 +1,61 @@
+# frozen_string_literal: true
+
+require 'singleton'
+
+module Lorekeeper
+  class BacktraceCleaner
+    include Singleton
+
+    def initialize
+      @backtrace_cleaner = set_backtrace_cleaner
+      @rails_root = defined?(Rails.root) ? Rails.root.to_s : nil
+      @rails_root_size = @rails_root.to_s.size
+      @gem_path = defined?(Gem.path) ? Gem.path : []
+      @denylisted_fingerprint = denylisted_fingerprint
+    end
+
+    def clean(backtrace)
+      backtrace = filter_rails_root_backtrace(backtrace)
+      @backtrace_cleaner&.clean(backtrace) || backtrace
+    end
+
+    private
+
+    DENYLISTED_FINGERPRINT =
+      %r{newrelic_rpm|active_support/callbacks.rb|zipkin-tracer|puma|phusion_passenger|opentelemetry}.freeze
+
+    def denylisted_fingerprint
+      return DENYLISTED_FINGERPRINT unless ENV.key?('LOREKEEPER_DENYLIST')
+
+      /#{ENV.fetch('LOREKEEPER_DENYLIST').split(',').map(&:strip).join('|')}/
+    end
+
+    def filter_rails_root_backtrace(backtrace)
+      return backtrace unless @rails_root
+
+      last_index = nil
+      result = []
+      backtrace.each_with_index do |line, idx|
+        if line.start_with?(@rails_root) && @gem_path.none? { |path| line.start_with?(path) }
+          result << line[@rails_root_size..]
+          last_index = idx
+        else
+          result << line
+        end
+      end
+
+      last_index ? result[..last_index] : result
+    end
+
+    def set_backtrace_cleaner
+      return nil unless defined?(ActiveSupport::BacktraceCleaner)
+
+      cleaner = ActiveSupport::BacktraceCleaner.new
+      cleaner.remove_silencers!
+      cleaner.add_silencer do |line|
+        line.match?(@denylisted_fingerprint) || line.start_with?(RbConfig::CONFIG['rubylibdir'])
+      end
+      cleaner
+    end
+  end
+end

lib/lorekeeper/json_logger.rb

@@ -9,11 +9,6 @@ class JSONLogger < FastLogger
     def initialize(file)
       reset_state
       @base_fields = { TIMESTAMP => '', MESSAGE => '', LEVEL => '' }
-      @backtrace_cleaner = set_backtrace_cleaner
-      @rails_root = defined?(Rails.root) ? Rails.root.to_s : nil
-      @rails_root_size = @rails_root.to_s.size
-      @gem_path = defined?(Gem.path) ? Gem.path : []
-      @denylisted_fingerprint = denylisted_fingerprint
 
       super(file)
     end
@@ -121,36 +116,7 @@ def json_message(message)
     # Cleaner defaults to newrelic, active_support/callbacks, zipkin-tracer, opentelemetry, web servers,
     # and stdlib now but can be configured by using LOREKEEPER_DENYLIST env var.
     def clean_backtrace(backtrace)
-      backtrace = filter_rails_root_backtrace(backtrace)
-      @backtrace_cleaner&.clean(backtrace) || backtrace
-    end
-
-    def filter_rails_root_backtrace(backtrace)
-      return backtrace unless @rails_root
-
-      last_index = nil
-      result = []
-      backtrace.each_with_index do |line, idx|
-        if line.start_with?(@rails_root) && @gem_path.none? { |path| line.start_with?(path) }
-          result << line[@rails_root_size..]
-          last_index = idx
-        else
-          result << line
-        end
-      end
-
-      last_index ? result[..last_index] : result
-    end
-
-    def set_backtrace_cleaner
-      return nil unless defined?(ActiveSupport::BacktraceCleaner)
-
-      cleaner = ActiveSupport::BacktraceCleaner.new
-      cleaner.remove_silencers!
-      cleaner.add_silencer do |line|
-        line.match?(@denylisted_fingerprint) || line.start_with?(RbConfig::CONFIG['rubylibdir'])
-      end
-      cleaner
+      Lorekeeper::BacktraceCleaner.instance.clean(backtrace)
     end
 
     THREAD_KEY = 'lorekeeper_jsonlogger_key' # Shared by all threads but unique by thread
@@ -161,14 +127,6 @@ def set_backtrace_cleaner
     EXCEPTION = 'exception'
     STACK = 'stack'
     DATA = 'data'
-    DENYLISTED_FINGERPRINT =
-      %r{newrelic_rpm|active_support/callbacks.rb|zipkin-tracer|puma|phusion_passenger|opentelemetry}.freeze
-
-    def denylisted_fingerprint
-      return DENYLISTED_FINGERPRINT unless ENV.key?('LOREKEEPER_DENYLIST')
-
-      /#{ENV.fetch('LOREKEEPER_DENYLIST').split(',').map(&:strip).join('|')}/
-    end
 
     def with_extra_fields(fields)
       state[:extra_fields] = fields

lib/lorekeeper/version.rb

@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 module Lorekeeper
-  VERSION = '2.5.0'
+  VERSION = '2.6.0'
 end

spec/lib/lorekeeper/backtrace_cleaner_spec.rb

@@ -0,0 +1,139 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+require 'active_support'
+
+RSpec.describe Lorekeeper do
+  describe Lorekeeper::BacktraceCleaner do
+    let(:instance) { described_class.instance }
+
+    around(:example) do |ex|
+      described_class.instance_variable_set(:@singleton__instance__, nil)
+      ex.run
+      described_class.instance_variable_set(:@singleton__instance__, nil)
+    end
+
+    describe 'clean' do
+      let(:new_backtrace) do
+        [
+          "/home/app/web/app/controllers/api/v2/users_controller.rb:39:in `show'",
+          "/ruby/2.5.0/gems/activesupport-4.2.11/lib/active_support/callbacks.rb:121:in `instance_exec'",
+          "/ruby/2.5.0/gems/activesupport-4.2.11/lib/active_support/callbacks.rb:121:in `block in run_callbacks'",
+          "/ruby/2.5.0/gems/newrelic_rpm-5.7.0.350/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in
+          `call'",
+          "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/cookies.rb:560:in `call'",
+          '/ruby/2.5.0/gems/newrelic_rpm-5.7.0.350/lib/new_relic/agent/instrumentation/middleware_tracing.rb' \
+          ":92:in`call'",
+          "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'",
+          "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:27:in `call'",
+          '/ruby/2.5.0/gems/newrelic_rpm-5.7.0.350/lib/new_relic/agent/instrumentation/middleware_tracing.rb' \
+          ":92:in `call'",
+          "/usr/local/rvm/rubies/ruby-2.7.6/lib/ruby/2.7.0/benchmark.rb:308:in `realtime'",
+          '/ruby/2.5.0/gems/zipkin-tracer-0.47.3/lib/zipkin-tracer/rack/zipkin-tracer.rb:29' \
+          ":in `block (3 levels) in call'",
+          "/ruby/2.5.0/gems/zipkin-tracer-0.47.3/lib/zipkin-tracer/rack/zipkin-tracer.rb:51:in `trace!'",
+          '/ruby/2.5.0/gems/zipkin-tracer-0.47.3/lib/zipkin-tracer/rack/zipkin-tracer.rb:29' \
+          ":in `block (2 levels) incall'",
+          "/ruby/2.5.0/gems/zipkin-tracer-0.47.3/lib/zipkin-tracer/zipkin_sender_base.rb:17:in `with_new_span'",
+          "/ruby/2.5.0/gems/zipkin-tracer-0.47.3/lib/zipkin-tracer/rack/zipkin-tracer.rb:27:in `block in call'",
+          "/ruby/2.5.0/gems/puma-5.3.2/lib/puma/configuration.rb:249:in `call'",
+          "/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'",
+          "/ruby/2.5.0/gems/opentelemetry-api-1.0.1/lib/opentelemetry/trace/tracer.rb:29:in `block in in_span'",
+          "/home/app/web/app/controllers/api/v2/users_controller.rb:39:in `show'",
+          "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'",
+          "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:27:in `call'",
+          "/home/app/web/vendor/bundle/ruby/2.7.0/bin/rake:25:in `load'"
+        ]
+      end
+
+      before do
+        allow(Gem).to receive(:path).and_return(['/ruby/2.5.0', '/home/app/web/vendor/bundle/ruby/2.7.0'])
+        stub_const('RbConfig::CONFIG', { 'rubylibdir' => '/usr/local/rvm/rubies/ruby-2.7.6/lib/ruby/2.7.0' })
+        stub_const('Rails', double(root: '/home/app/web'))
+      end
+
+      context 'Logging just an exception' do
+        let(:active_support_exception_v6) do
+          [
+            "/app/controllers/api/v2/users_controller.rb:39:in `show'",
+            "actionpack (4.2.11) lib/action_dispatch/middleware/cookies.rb:560:in `call'",
+            "actionpack (4.2.11) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'",
+            "actionpack (4.2.11) lib/action_dispatch/middleware/callbacks.rb:27:in `call'",
+            "/app/controllers/api/v2/users_controller.rb:39:in `show'"
+          ]
+        end
+        let(:active_support_exception_less_than_v6) do
+          [
+            "/app/controllers/api/v2/users_controller.rb:39:in `show'",
+            "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/cookies.rb:560:in `call'",
+            "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'",
+            "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:27:in `call'",
+            "/app/controllers/api/v2/users_controller.rb:39:in `show'"
+          ]
+        end
+        let(:no_noise_backtrace) do
+          ActiveSupport::VERSION::MAJOR < 6 ? active_support_exception_less_than_v6 : active_support_exception_v6
+        end
+
+        it 'Does not log the lines matched with the denylist' do
+          expect(instance.clean(new_backtrace)).to eq(no_noise_backtrace)
+        end
+
+        it 'Logs all backtraces when ActiveSupport::BacktraceCleaner and Rails.root are not defined' do
+          hide_const('ActiveSupport::BacktraceCleaner')
+          hide_const('Rails')
+
+          expect(instance.clean(new_backtrace)).to eq(new_backtrace)
+        end
+
+        it 'drops backtrace lines after the last line of Rails app logs' do
+          hide_const('ActiveSupport::BacktraceCleaner')
+
+          expect(instance.clean([
+            "/ruby/2.5.0/gems/activesupport-4.2.11/lib/active_support/callbacks.rb:121:in `instance_exec'",
+            "/home/app/web/app/controllers/api/v2/users_controller.rb:39:in `show'",
+            "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:27:in `call'",
+            "/home/app/web/vendor/bundle/ruby/2.7.0/bin/rake:25:in `load'"
+          ])).to eq([
+            "/ruby/2.5.0/gems/activesupport-4.2.11/lib/active_support/callbacks.rb:121:in `instance_exec'",
+            "/app/controllers/api/v2/users_controller.rb:39:in `show'"
+          ])
+        end
+
+        context 'with LOREKEEPER_DENYLIST env var' do
+          before do
+            allow(ENV).to receive(:key?).with('LOREKEEPER_DENYLIST').and_return(true)
+            allow(ENV).to receive(:fetch).with('LOREKEEPER_DENYLIST').and_return(lorekeeper_denylist)
+          end
+          let(:lorekeeper_denylist) { 'newrelic_rpm, active_support/callbacks.rb, zipkin-tracer, puma' }
+          let(:active_support_exception_v6) do
+            [
+              "/app/controllers/api/v2/users_controller.rb:39:in `show'",
+              "actionpack (4.2.11) lib/action_dispatch/middleware/cookies.rb:560:in `call'",
+              "actionpack (4.2.11) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'",
+              "actionpack (4.2.11) lib/action_dispatch/middleware/callbacks.rb:27:in `call'",
+              "/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'",
+              "opentelemetry-api (1.0.1) lib/opentelemetry/trace/tracer.rb:29:in `block in in_span'",
+              "/app/controllers/api/v2/users_controller.rb:39:in `show'"
+            ]
+          end
+          let(:active_support_exception_less_than_v6) do
+            [
+              "/app/controllers/api/v2/users_controller.rb:39:in `show'",
+              "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/cookies.rb:560:in `call'",
+              "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'",
+              "/ruby/2.5.0/gems/actionpack-4.2.11/lib/action_dispatch/middleware/callbacks.rb:27:in `call'",
+              "/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'",
+              "/ruby/2.5.0/gems/opentelemetry-api-1.0.1/lib/opentelemetry/trace/tracer.rb:29:in `block in in_span'",
+              "/app/controllers/api/v2/users_controller.rb:39:in `show'"
+            ]
+          end
+
+          it 'Does not log the lines matched with the denylist' do
+            expect(instance.clean(new_backtrace)).to eq(no_noise_backtrace)
+          end
+        end
+      end
+    end
+  end
+end