Fix missing trace.id/span.id in NewRelic logs

These let NewRelic tie log messages to specific transactions. They're thread-local, so trying to capture them from an async appender thread would return nil

Author: jdelStrother

CHANGELOG.md

@@ -5,6 +5,8 @@ This project adheres to [Semantic Versioning](http://semver.org/).
 
 ## [unreleased]
 
+- Fix missing trace.id/span.id in NewRelic logs
+
 ## [4.17.0]
 
 - Correct `source_code_uri` URL

lib/semantic_logger/formatters/new_relic_logs.rb

@@ -47,7 +47,7 @@ def call(log, logger)
         hash = super
 
         result = {
-          **newrelic_metadata,
+          **log.newrelic_metadata,
           message:       hash[:message].to_s,
           tags:          hash[:tags],
           metric:        hash[:metric],
@@ -112,15 +112,19 @@ def call(log, logger)
 
         result
       end
+    end
 
-      private
+    module NewRelicMetadata
+      attr_reader :newrelic_metadata
 
-      # NOTE: This function will already include trace.id and span.id if they
-      # are available so I believe the previous implementation of this is redundant
-      # https://rubydoc.info/gems/newrelic_rpm/NewRelic/Agent#linking_metadata-instance_method
-      def newrelic_metadata
-        NewRelic::Agent.linking_metadata.transform_keys(&:to_sym)
+      def initialize(*)
+        super
+        # Record NewRelic's "trace.id"/"entity.name"/"hostname"/etc, so we can include them later in the formatted output.
+        # These are thread-local, so need to be captured as soon as the log-message is created.
+        # https://rubydoc.info/gems/newrelic_rpm/NewRelic/Agent#linking_metadata-instance_method
+        @newrelic_metadata = NewRelic::Agent.linking_metadata
       end
     end
+    Log.prepend NewRelicMetadata
   end
 end

test/formatters/new_relic_logs_test.rb

@@ -174,19 +174,24 @@ class NewRelicLogsTest < Minitest::Test
 
         describe "metadata" do
           it "includes trace.id and span.id if present" do
+            # Simulate recording a log message within a Rails transaction, where trace.id has been set on the current thread
             NewRelic::Agent.stub(:linking_metadata, {"trace.id" => "trace123", "span.id" => "span456"}) do
-              result = formatted_log
-              assert_equal "trace123", result[:"trace.id"]
-              assert_equal "span456", result[:"span.id"]
+              log
             end
+            # ... which is then formatted on the async appender thread
+            result = formatted_log
+            assert_equal "trace123", result["trace.id"]
+            assert_equal "span456", result["span.id"]
           end
 
           it "omits trace.id and span.id if absent" do
             NewRelic::Agent.stub(:linking_metadata, {}) do
-              result = formatted_log
-              refute result.key?(:"trace.id")
-              refute result.key?(:"span.id")
+              log
             end
+
+            result = formatted_log
+            refute result.key?("trace.id")
+            refute result.key?("span.id")
           end
         end
       end