Fix how we detect the logging frame (#6)

* Fix how we detect the frame which initiated logging

* 🐛

* ✅

* 💄

* 📦

* 🐛 Fix compatibility with Truffle Ruby

* ⏪

* 🐛

Author: simonrozsival

CHANGELOG.md

@@ -14,3 +14,7 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 ## [0.1.2] - 2021-04-22
 
 - Fixed string encoding.
+
+## [0.1.3] - 2021-06-11
+
+- Fixed detection of the frame that calls the logger.

lib/logtail/log_entry.rb

@@ -12,7 +12,7 @@ class LogEntry #:nodoc:
     BINARY_LIMIT_THRESHOLD = 1_000.freeze
     DT_PRECISION = 6.freeze
     MESSAGE_MAX_BYTES = 8192.freeze
-    LOGTAIL_GEM_REGEX = /\/logtail(?:-ruby|-rails|-rack)?(?:-\d+(?:\.\d+)*)?\/lib$/.freeze
+    LOGGER_FILE = '/logtail/logger.rb'.freeze
 
     attr_reader :context_snapshot, :event, :level, :message, :progname, :tags, :time
 
@@ -39,6 +39,7 @@ def initialize(level, time, progname, message, context_snapshot, event, options
       @tags = options[:tags]
       @context_snapshot = context_snapshot
       @event = event
+      @runtime_context = current_runtime_context || {}
     end
 
     # Builds a hash representation containing simple objects, suitable for serialization (JSON).
@@ -64,7 +65,7 @@ def to_hash(options = {})
 
       hash[:context] ||= {}
       hash[:context][:runtime] ||= {}
-      hash[:context][:runtime].merge!(current_runtime_context || {})
+      hash[:context][:runtime].merge!(@runtime_context)
 
       if options[:only]
         hash.select do |key, _value|
@@ -114,32 +115,40 @@ def encode_string(string)
       end
 
       def current_runtime_context
-        index = caller_locations.rindex { |x| logtail_frame?(x) }
-        frame = caller_locations[index + 1] unless index.nil?
-        return convert_to_runtime_context(frame) unless frame.nil?
+        last_logger_invocation_index = caller_locations.rindex { |frame| logtail_logger_frame?(frame) }
+        return {} if last_logger_invocation_index.nil?
+
+        calling_frame_index = last_logger_invocation_index + 1
+        frame = caller_locations[calling_frame_index]
+
+        return convert_to_runtime_context(frame)
       end
 
       def convert_to_runtime_context(frame)
         {
-          file: relative_to_main_module(frame.absolute_path),
+          file: path_relative_to_app_root(frame),
           line: frame.lineno,
           frame_label: frame.label,
         }
       end
 
-      def logtail_frame?(frame)
-        return false if frame.absolute_path.nil? || logtail_gem_paths.empty?
-        logtail_gem_paths.any? { |path| frame.absolute_path.start_with?(path) }
+      def logtail_logger_frame?(frame)
+        !frame.absolute_path.nil? && frame.absolute_path.end_with?(LOGGER_FILE)
       end
 
-      def logtail_gem_paths
-        @logtail_gem_paths ||= $LOAD_PATH.select { |path| path.match(LOGTAIL_GEM_REGEX) }
+      def path_relative_to_app_root(frame)
+        Pathname.new(frame.absolute_path).relative_path_from(root_path).to_s
       end
 
-      def relative_to_main_module(path)
-        base_file = caller_locations.last.absolute_path
-        base_path = Pathname.new(File.dirname(base_file || '/'))
-        Pathname.new(path).relative_path_from(base_path).to_s
+      def root_path
+        if Object.const_defined?('Rails')
+          Rails.root.to_s
+        elsif Object.const_defined?('Rack::Directory')
+          Rack::Directory.new('').root
+        else
+          base_file = caller_locations.last.absolute_path
+          Pathname.new(File.dirname(base_file || '/'))
+        end
       end
   end
 end

lib/logtail/version.rb

@@ -1,3 +1,3 @@
 module Logtail
-  VERSION = "0.1.2"
+  VERSION = "0.1.3"
 end

spec/logtail/log_entry_spec.rb

@@ -1,7 +1,7 @@
 require "spec_helper"
 
 describe Logtail::LogEntry do
-  let(:time) { Time.utc(2016, 9, 1, 12, 0, 0) }
+  let(:time) { Time.utc(2021, 06, 11, 12, 0, 0) }
 
   describe "#to_msgpack" do
     it "should encode properly with an event and context" do
@@ -16,20 +16,19 @@
       context = {custom: {a: "b"}}
       log_entry = described_class.new("INFO", time, nil, "log message", context, event)
       msgpack = log_entry.to_msgpack
-      expect(msgpack).to start_with("\x85\xA5level\xA4INFO\xA2dt\xBB2016-09-01T12:00:00.000000Z".force_encoding("ASCII-8BIT"))
+      expect(msgpack).to start_with("\x85\xA5level\xA4INFO\xA2dt\xBB2021-06-11T12:00:00.000000Z".force_encoding("ASCII-8BIT"))
     end
   end
 
   describe "#to_hash" do
     it "should include runtime context information" do
-      $:.unshift(File.expand_path(__dir__ + '/../../lib'))
+      log_entry = Logtail::Logger::PassThroughFormatter.new.call("INFO", time, "", "log message")
 
-      log_entry = described_class.new("INFO", time, nil, "log message", {}, {})
       hash = log_entry.to_hash
       expect(hash[:context]).to_not be_nil
       expect(hash[:context][:runtime]).to_not be_nil
-      expect(hash[:context][:runtime][:file]).to_not be_nil
-      expect(hash[:context][:runtime][:line]).to_not be_nil
+      expect(hash[:context][:runtime][:file]).to end_with('/spec/logtail/log_entry_spec.rb')
+      expect(hash[:context][:runtime][:line]).to be(25)
       expect(hash[:context][:runtime][:frame_label]).to_not be_nil
     end
   end