Merge pull request #2252 from newrelic/fix-active-support-logger-inst…

…rumentation

Rails 7.1: Record only one copy of a broadcasted log message

CHANGELOG.md

@@ -2,7 +2,7 @@
 
 ## dev
 
-Version <dev> brings support for gleaning a Docker container id from cgroups v2 based containers and records additional synthetics attributes.
+Version <dev> brings support for gleaning a Docker container id from cgroups v2 based containers, records additional synthetics attributes, and fixes an issue with Rails 7.1 that could cause duplicate log records to be sent to New Relic.
 
 - **Feature: Prevent the agent from starting in rails commands in Rails 7**
 
@@ -20,6 +20,9 @@ Version <dev> brings support for gleaning a Docker container id from cgroups v2
 
   For compatibility with Ruby 3.4 and to silence compatibility warnings present in Ruby 3.3, declare a dependency on the `base64` gem. The New Relic Ruby agent uses the native Ruby `base64` gem for Base 64 encoding/decoding. The agent is joined by Ruby on Rails ([rails/rails@3e52adf](https://github.com/rails/rails/commit/3e52adf28e90af490f7e3bdc4bcc85618a4e0867)) and others in making this change in preparation for Ruby 3.3/3.4.
 
+- **Fix: Stop sending duplicate log events for Rails 7.1 users**
+
+  Rails 7.1 introduced the public API [`ActiveSupport::BroadcastLogger`](https://api.rubyonrails.org/classes/ActiveSupport/BroadcastLogger.html). This logger replaces a private API, `ActiveSupport::Logger.broadcast`. In Rails versions below 7.1, the agent uses the `broadcast` method to stop duplicate logs from being recoded by broadcasted loggers. Now, we've updated the code to provide a similar duplication fix with the new `ActiveSupport::BroadcastLogger` class.
 
 ## v9.5.0
 

lib/new_relic/agent/configuration/default_source.rb

@@ -1361,14 +1361,23 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil)
           :description => 'Configures the TCP/IP port for the trace observer Host'
         },
         # Instrumentation
+        :'instrumentation.active_support_broadcast_logger' => {
+          :default => instrumentation_value_from_boolean(:'application_logging.enabled'),
+          :documentation_default => 'auto',
+          :dynamic_name => true,
+          :public => true,
+          :type => String,
+          :allowed_from_server => false,
+          :description => 'Controls auto-instrumentation of `ActiveSupport::BroadcastLogger` at start up. May be one of: `auto`, `prepend`, `chain`, `disabled`. Used in Rails versions >= 7.1.'
+        },
         :'instrumentation.active_support_logger' => {
           :default => instrumentation_value_from_boolean(:'application_logging.enabled'),
           :documentation_default => 'auto',
           :dynamic_name => true,
           :public => true,
           :type => String,
           :allowed_from_server => false,
-          :description => 'Controls auto-instrumentation of `ActiveSupport::Logger` at start-up. May be one of: `auto`, `prepend`, `chain`, `disabled`.'
+          :description => 'Controls auto-instrumentation of `ActiveSupport::Logger` at start up. May be one of: `auto`, `prepend`, `chain`, `disabled`. Used in Rails versions below 7.1.'
         },
         :'instrumentation.bunny' => {
           :default => 'auto',
@@ -1646,7 +1655,7 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil)
             An array of strings to specify which keys and/or values inside a Stripe event's `user_data` hash should
             not be reported to New Relic. Each string in this array will be turned into a regular expression via
             `Regexp.new` to permit advanced matching. For each hash pair, if either the key or value is matched the
-            pair will not be reported. By default, no `user_data` is reported, so this option should only be used if 
+            pair will not be reported. By default, no `user_data` is reported, so this option should only be used if
             the `stripe.user_data.include` option is being used.
           DESCRIPTION
         },

lib/new_relic/agent/instrumentation/active_support_broadcast_logger.rb

@@ -0,0 +1,23 @@
+# This file is distributed under New Relic's license terms.
+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+require_relative 'active_support_broadcast_logger/instrumentation'
+require_relative 'active_support_broadcast_logger/chain'
+require_relative 'active_support_broadcast_logger/prepend'
+
+DependencyDetection.defer do
+  named :'active_support_broadcast_logger'
+
+  depends_on { defined?(ActiveSupport::BroadcastLogger) }
+
+  executes do
+    NewRelic::Agent.logger.info('Installing ActiveSupport::BroadcastLogger instrumentation')
+
+    if use_prepend?
+      prepend_instrument ActiveSupport::BroadcastLogger, NewRelic::Agent::Instrumentation::ActiveSupportBroadcastLogger::Prepend
+    else
+      chain_instrument NewRelic::Agent::Instrumentation::ActiveSupportBroadcastLogger::Chain
+    end
+  end
+end

lib/new_relic/agent/instrumentation/active_support_broadcast_logger/chain.rb

@@ -0,0 +1,69 @@
+# This file is distributed under New Relic's license terms.
+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+module NewRelic::Agent::Instrumentation
+  module ActiveSupportBroadcastLogger::Chain
+    def self.instrument!
+      ::ActiveSupportBroadcastLogger.class_eval do
+        include NewRelic::Agent::Instrumentation::ActiveSupportBroadcastLogger
+
+        alias_method(:add_without_new_relic, :add)
+
+        def add(*args, &task)
+          record_one_broadcast_with_new_relic(*args) do
+            add_without_new_relic(*args, &traced_task)
+          end
+        end
+
+        alias_method(:debug_without_new_relic, :debug)
+
+        def debug(*args, &task)
+          record_one_broadcast_with_new_relic(*args) do
+            debug_without_new_relic(*args, &traced_task)
+          end
+        end
+
+        alias_method(:info_without_new_relic, :info)
+
+        def info(*args, &task)
+          record_one_broadcast_with_new_relic(*args) do
+            info_without_new_relic(*args, &traced_task)
+          end
+        end
+
+        alias_method(:warn_without_new_relic, :warn)
+
+        def warn(*args, &task)
+          record_one_broadcast_with_new_relic(*args) do
+            warn_without_new_relic(*args, &traced_task)
+          end
+        end
+
+        alias_method(:error_without_new_relic, :error)
+
+        def error(*args, &task)
+          record_one_broadcast_with_new_relic(*args) do
+            error_without_new_relic(*args, &traced_task)
+          end
+        end
+
+        alias_method(:fatal_without_new_relic, :fatal)
+
+        def fatal(*args, &task)
+          record_one_broadcast_with_new_relic(*args) do
+            fatal_without_new_relic(*args, &traced_task)
+          end
+        end
+      end
+
+      alias_method(:unknown_without_new_relic, :unknown)
+
+      def unknown(*args, &task)
+        record_one_broadcast_with_new_relic(*args) do
+          unknown_without_new_relic(*args, &traced_task)
+        end
+      end
+    end
+  end
+end

lib/new_relic/agent/instrumentation/active_support_broadcast_logger/instrumentation.rb

@@ -0,0 +1,13 @@
+# This file is distributed under New Relic's license terms.
+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+module NewRelic::Agent::Instrumentation
+  module ActiveSupportBroadcastLogger
+    def record_one_broadcast_with_new_relic(*args)
+      broadcasts[1..-1].each { |broadcasted_logger| broadcasted_logger.instance_variable_set(:@skip_instrumenting, true) }
+      yield
+      broadcasts.each { |broadcasted_logger| broadcasted_logger.instance_variable_set(:@skip_instrumenting, false) }
+    end
+  end
+end

lib/new_relic/agent/instrumentation/active_support_broadcast_logger/prepend.rb

@@ -0,0 +1,37 @@
+# This file is distributed under New Relic's license terms.
+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+module NewRelic::Agent::Instrumentation
+  module ActiveSupportBroadcastLogger::Prepend
+    include NewRelic::Agent::Instrumentation::ActiveSupportBroadcastLogger
+
+    def add(*args)
+      record_one_broadcast_with_new_relic(*args) { super }
+    end
+
+    def debug(*args)
+      record_one_broadcast_with_new_relic(*args) { super }
+    end
+
+    def info(*args)
+      record_one_broadcast_with_new_relic(*args) { super }
+    end
+
+    def warn(*args)
+      record_one_broadcast_with_new_relic(*args) { super }
+    end
+
+    def error(*args)
+      record_one_broadcast_with_new_relic(*args) { super }
+    end
+
+    def fatal(*args)
+      record_one_broadcast_with_new_relic(*args) { super }
+    end
+
+    def unknown(*args)
+      record_one_broadcast_with_new_relic(*args) { super }
+    end
+  end
+end

lib/new_relic/agent/instrumentation/active_support_logger.rb

@@ -10,13 +10,7 @@
   named :active_support_logger
 
   depends_on do
-    defined?(ActiveSupport::Logger) &&
-      # TODO: Rails 7.1 - ActiveSupport::Logger#broadcast method removed
-      # APM logs-in-context automatic forwarding still works, but sends
-      # log events for each broadcasted logger, often causing duplicates
-      # Issue #2245
-      defined?(Rails::VERSION::STRING) &&
-      Gem::Version.new(Rails::VERSION::STRING) < Gem::Version.new('7.1.0')
+    defined?(ActiveSupport::Logger) && defined?(ActiveSupport::Logger.broadcast)
   end
 
   executes do

test/multiverse/lib/multiverse/runner.rb

@@ -102,7 +102,7 @@ def execute_suites(filter, opts)
       'background' => %w[delayed_job sidekiq resque],
       'background_2' => ['rake'],
       'database' => %w[elasticsearch mongo redis sequel],
-      'rails' => %w[active_record active_record_pg rails rails_prepend activemerchant],
+      'rails' => %w[active_record active_record_pg active_support_broadcast_logger active_support_logger rails rails_prepend activemerchant],
       'frameworks' => %w[grape padrino roda sinatra],
       'httpclients' => %w[curb excon httpclient],
       'httpclients_2' => %w[typhoeus net_http httprb],

test/multiverse/suites/active_support_broadcast_logger/Envfile

@@ -0,0 +1,21 @@
+# This file is distributed under New Relic's license terms.
+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+instrumentation_methods :chain, :prepend
+
+# ActiveSupport::BroadcastLogger introduced in Rails 7.1.
+# Rails 7.1 is the latest version at the time of writing.
+ACTIVE_SUPPORT_VERSIONS = [
+  [nil, 2.7]
+]
+
+unshift_rails_edge(ACTIVE_SUPPORT_VERSIONS)
+
+def gem_list(activesupport_version = nil)
+  <<-RB
+    gem 'activesupport'#{activesupport_version}
+  RB
+end
+
+create_gemfiles(ACTIVE_SUPPORT_VERSIONS)

test/multiverse/suites/active_support_broadcast_logger/active_support_broadcast_logger_test.rb

@@ -0,0 +1,63 @@
+# This file is distributed under New Relic's license terms.
+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+require 'active_support'
+
+class ActiveSupportBroadcastLoggerTest < Minitest::Test
+  include MultiverseHelpers
+
+  MESSAGE = 'Can you hear me, Major Tom?'
+
+  def setup
+    NewRelic::Agent.manual_start
+
+    @output = StringIO.new
+    @io_logger = Logger.new(@output)
+    @output2 = StringIO.new
+    @io_logger2 = Logger.new(@output2)
+    @broadcast = ActiveSupport::BroadcastLogger.new(@io_logger, @io_logger2)
+    @aggregator = NewRelic::Agent.agent.log_event_aggregator
+
+    @aggregator.reset!
+  end
+
+  def teardown
+    NewRelic::Agent.shutdown
+  end
+
+  def test_broadcasted_logger_sends_one_log_event_per_add_call
+    @broadcast.add(Logger::DEBUG, MESSAGE)
+
+    assert_log_broadcasted_to_both_outputs
+    assert_log_seen_once_by_new_relic('DEBUG')
+  end
+
+  def test_broadcasted_logger_sends_one_log_event_per_unknown_call
+    @broadcast.unknown(MESSAGE)
+
+    assert_log_broadcasted_to_both_outputs
+    assert_log_seen_once_by_new_relic('ANY')
+  end
+
+  %w[debug info warn error fatal].each do |method|
+    define_method("test_broadcasted_logger_sends_one_log_event_per_#{method}_call") do
+      @broadcast.send(method.to_sym, MESSAGE)
+
+      assert_log_broadcasted_to_both_outputs
+      assert_log_seen_once_by_new_relic(method.upcase)
+    end
+  end
+
+  private
+
+  def assert_log_broadcasted_to_both_outputs
+    assert_includes(@output.string, MESSAGE)
+    assert_includes(@output2.string, MESSAGE)
+  end
+
+  def assert_log_seen_once_by_new_relic(severity)
+    assert_equal(1, @aggregator.instance_variable_get(:@seen))
+    assert_equal({severity => 1}, @aggregator.instance_variable_get(:@seen_by_severity))
+  end
+end

test/multiverse/suites/active_support_broadcast_logger/config/newrelic.yml

@@ -0,0 +1,32 @@
+common: &default_settings
+  license_key: 'bd0e1d52adade840f7ca727d29a86249e89a6f1c'
+  ca_bundle_path: ../../../config/test.cert.crt
+  host: localhost
+  api_host: localhost
+  port: <%= $collector && $collector.port %>
+  app_name: Rails multiverse test app
+  enabled: true
+  apdex_t: 1.0
+  capture_params: true
+  transaction_tracer:
+    enabled: true
+    transaction_threshold: apdex_f
+    record_sql: obfuscated
+    stack_trace_threshold: 0.500
+  error_collector:
+    enabled: true
+    ignore_classes: NewRelic::TestHelpers::Exceptions::IgnoredError
+  instrumentation:
+    active_support_broadcast_logger <%= $instrumentation_method %>
+
+development:
+  <<: *default_settings
+
+test:
+  <<: *default_settings
+
+production:
+  <<: *default_settings
+
+staging:
+  <<: *default_settings

test/multiverse/suites/active_support_logger/Envfile

@@ -0,0 +1,23 @@
+# This file is distributed under New Relic's license terms.
+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+instrumentation_methods :chain, :prepend
+
+ACTIVE_SUPPORT_VERSIONS = [
+  ['7.0.4', 2.7],
+  ['6.1.7', 2.5],
+  ['6.0.6', 2.5, 2.7],
+  ['5.2.8', 2.4, 2.7],
+  ['5.1.7', 2.4, 2.7],
+  ['5.0.7', 2.4, 2.7],
+  ['4.2.11', 2.4, 2.4]
+]
+
+def gem_list(activesupport_version = nil)
+  <<-RB
+    gem 'activesupport'#{activesupport_version}
+  RB
+end
+
+create_gemfiles(ACTIVE_SUPPORT_VERSIONS)