From bd8a8574220335a48d2592575ad6db97333c41af Mon Sep 17 00:00:00 2001 From: Kayla Reopelle Date: Mon, 9 Oct 2023 17:36:01 -0700 Subject: [PATCH 1/4] Update handling Rails broadcasted loggers Broadcasted loggers have unique outputs, but identical inputs. If our logger instrumentation receives logs from broadcasted loggers, it creates identical log events from each broadcast. In Rails versions below 7.1, the duplicated log events were avoided by adding an instance variable to skip instrumentation on broadcasted loggers by patching ActiveSupport::Logger.broadcast. That method has been refactored into the ActiveSupport::BroadcastLogger class in Rails 7.1. This delivers updates to prevent duplicate log events in ActiveSupport::BroadcastLogger and updates testing for ActiveSupport::Logger to test chain instrumentation. It also adds a test using Rails logger directly, so we can be notified of any regressions by testing future versions of Rails. --- CHANGELOG.md | 8 ++- .../agent/configuration/default_source.rb | 13 +++- .../active_support_broadcast_logger.rb | 23 +++++++ .../active_support_broadcast_logger/chain.rb | 69 +++++++++++++++++++ .../instrumentation.rb | 13 ++++ .../prepend.rb | 37 ++++++++++ .../instrumentation/active_support_logger.rb | 8 +-- test/multiverse/lib/multiverse/runner.rb | 2 +- .../active_support_broadcast_logger/Envfile | 19 +++++ .../active_support_broadcast_logger_test.rb | 63 +++++++++++++++++ .../config/newrelic.yml | 32 +++++++++ .../suites/active_support_logger/Envfile | 23 +++++++ .../active_support_logger_test.rb | 44 ++++++++++++ .../active_support_logger/config/newrelic.yml | 32 +++++++++ .../rails/active_support_logger_test.rb | 49 ------------- .../suites/rails/rails_logger_test.rb | 43 ++++++++++++ 16 files changed, 418 insertions(+), 60 deletions(-) create mode 100644 lib/new_relic/agent/instrumentation/active_support_broadcast_logger.rb create mode 100644 lib/new_relic/agent/instrumentation/active_support_broadcast_logger/chain.rb create mode 100644 lib/new_relic/agent/instrumentation/active_support_broadcast_logger/instrumentation.rb create mode 100644 lib/new_relic/agent/instrumentation/active_support_broadcast_logger/prepend.rb create mode 100644 test/multiverse/suites/active_support_broadcast_logger/Envfile create mode 100644 test/multiverse/suites/active_support_broadcast_logger/active_support_broadcast_logger_test.rb create mode 100644 test/multiverse/suites/active_support_broadcast_logger/config/newrelic.yml create mode 100644 test/multiverse/suites/active_support_logger/Envfile create mode 100644 test/multiverse/suites/active_support_logger/active_support_logger_test.rb create mode 100644 test/multiverse/suites/active_support_logger/config/newrelic.yml delete mode 100644 test/multiverse/suites/rails/active_support_logger_test.rb create mode 100644 test/multiverse/suites/rails/rails_logger_test.rb diff --git a/CHANGELOG.md b/CHANGELOG.md index e84d29d580..7086b76d51 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,7 +2,7 @@ ## dev -Version brings support for gleaning a Docker container id from cgroups v2 based containers and records additional synthetics attributes. +Version 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,12 @@ Version 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. + + Previously, the agent prevented broadcasted loggers from recording duplicate log events by skipping instrumentation for broadcasted loggers, identified by calling `ActiveSupport::Logger.broadcast`. In Rails 7.1, this method has been refactored into a class. The agent now records log events for only the first logger found in an `ActiveSupport::BroadcastLogger.broadcasts` array. + ## v9.5.0 diff --git a/lib/new_relic/agent/configuration/default_source.rb b/lib/new_relic/agent/configuration/default_source.rb index 1c4ff488c9..f95dae955a 100644 --- a/lib/new_relic/agent/configuration/default_source.rb +++ b/lib/new_relic/agent/configuration/default_source.rb @@ -1361,6 +1361,15 @@ 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', @@ -1368,7 +1377,7 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil) :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 }, diff --git a/lib/new_relic/agent/instrumentation/active_support_broadcast_logger.rb b/lib/new_relic/agent/instrumentation/active_support_broadcast_logger.rb new file mode 100644 index 0000000000..8505dd2d72 --- /dev/null +++ b/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 diff --git a/lib/new_relic/agent/instrumentation/active_support_broadcast_logger/chain.rb b/lib/new_relic/agent/instrumentation/active_support_broadcast_logger/chain.rb new file mode 100644 index 0000000000..8e63d2f278 --- /dev/null +++ b/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 diff --git a/lib/new_relic/agent/instrumentation/active_support_broadcast_logger/instrumentation.rb b/lib/new_relic/agent/instrumentation/active_support_broadcast_logger/instrumentation.rb new file mode 100644 index 0000000000..1e5c9c37db --- /dev/null +++ b/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 diff --git a/lib/new_relic/agent/instrumentation/active_support_broadcast_logger/prepend.rb b/lib/new_relic/agent/instrumentation/active_support_broadcast_logger/prepend.rb new file mode 100644 index 0000000000..7766e84e7b --- /dev/null +++ b/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 diff --git a/lib/new_relic/agent/instrumentation/active_support_logger.rb b/lib/new_relic/agent/instrumentation/active_support_logger.rb index bdcd7515f5..a89effca96 100644 --- a/lib/new_relic/agent/instrumentation/active_support_logger.rb +++ b/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 diff --git a/test/multiverse/lib/multiverse/runner.rb b/test/multiverse/lib/multiverse/runner.rb index b4b1b1be56..0ba27c3590 100644 --- a/test/multiverse/lib/multiverse/runner.rb +++ b/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], diff --git a/test/multiverse/suites/active_support_broadcast_logger/Envfile b/test/multiverse/suites/active_support_broadcast_logger/Envfile new file mode 100644 index 0000000000..af41d8e82e --- /dev/null +++ b/test/multiverse/suites/active_support_broadcast_logger/Envfile @@ -0,0 +1,19 @@ +# 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] +] + +def gem_list(activesupport_version = nil) + <<-RB + gem 'activesupport'#{activesupport_version} + RB +end + +create_gemfiles(ACTIVE_SUPPORT_VERSIONS) diff --git a/test/multiverse/suites/active_support_broadcast_logger/active_support_broadcast_logger_test.rb b/test/multiverse/suites/active_support_broadcast_logger/active_support_broadcast_logger_test.rb new file mode 100644 index 0000000000..3bcb62672b --- /dev/null +++ b/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 diff --git a/test/multiverse/suites/active_support_broadcast_logger/config/newrelic.yml b/test/multiverse/suites/active_support_broadcast_logger/config/newrelic.yml new file mode 100644 index 0000000000..349c572332 --- /dev/null +++ b/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 diff --git a/test/multiverse/suites/active_support_logger/Envfile b/test/multiverse/suites/active_support_logger/Envfile new file mode 100644 index 0000000000..4c4b656baa --- /dev/null +++ b/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) diff --git a/test/multiverse/suites/active_support_logger/active_support_logger_test.rb b/test/multiverse/suites/active_support_logger/active_support_logger_test.rb new file mode 100644 index 0000000000..7d6957ecdc --- /dev/null +++ b/test/multiverse/suites/active_support_logger/active_support_logger_test.rb @@ -0,0 +1,44 @@ +# 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 ActiveSupportLoggerTest < Minitest::Test + include MultiverseHelpers + setup_and_teardown_agent + + def setup + NewRelic::Agent.manual_start + @output = StringIO.new + @logger = Logger.new(@output) + @broadcasted_output = StringIO.new + @broadcasted_logger = ActiveSupport::Logger.new(@broadcasted_output) + @logger.extend(ActiveSupport::Logger.broadcast(@broadcasted_logger)) + + @aggregator = NewRelic::Agent.agent.log_event_aggregator + @aggregator.reset! + end + + def teardown + NewRelic::Agent.shutdown + end + + def test_broadcasted_logger_marked_skip_instrumenting + assert @broadcasted_logger.instance_variable_get(:@skip_instrumenting), 'Broadcasted logger not set with @skip_instrumenting' + assert_nil @logger.instance_variable_get(:@skip_instrumenting), 'Logger has @skip_instrumenting defined' + end + + def test_logs_not_forwarded_by_broadcasted_logger + message = 'Can you hear me, Major Tom?' + + @logger.add(Logger::DEBUG, message) + + assert_includes(@output.string, message) + assert_includes(@broadcasted_output.string, message) + + # LogEventAggregator sees the log only once + assert_equal 1, @aggregator.instance_variable_get(:@seen) + assert_equal({'DEBUG' => 1}, @aggregator.instance_variable_get(:@seen_by_severity)) + end +end diff --git a/test/multiverse/suites/active_support_logger/config/newrelic.yml b/test/multiverse/suites/active_support_logger/config/newrelic.yml new file mode 100644 index 0000000000..3cd1af4f22 --- /dev/null +++ b/test/multiverse/suites/active_support_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_logger <%= $instrumentation_method %> + +development: + <<: *default_settings + +test: + <<: *default_settings + +production: + <<: *default_settings + +staging: + <<: *default_settings diff --git a/test/multiverse/suites/rails/active_support_logger_test.rb b/test/multiverse/suites/rails/active_support_logger_test.rb deleted file mode 100644 index 34996faa4f..0000000000 --- a/test/multiverse/suites/rails/active_support_logger_test.rb +++ /dev/null @@ -1,49 +0,0 @@ -# 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 './app' - -if defined?(ActiveSupport::Logger) - class ActiveSupportLoggerTest < Minitest::Test - include MultiverseHelpers - setup_and_teardown_agent - - def rails_7_1? - Gem::Version.new(::Rails::VERSION::STRING) >= Gem::Version.new('7.1.0') - end - - def setup - @output = StringIO.new - @logger = Logger.new(@output) - @broadcasted_output = StringIO.new - @broadcasted_logger = ActiveSupport::Logger.new(@broadcasted_output) - @logger.extend(ActiveSupport::Logger.broadcast(@broadcasted_logger)) unless rails_7_1? - - @aggregator = NewRelic::Agent.agent.log_event_aggregator - @aggregator.reset! - end - - def test_broadcasted_logger_marked_skip_instrumenting - skip 'Rails 7.1. Active Support Logger instrumentation broken, see #2245' if rails_7_1? - - assert @broadcasted_logger.instance_variable_get(:@skip_instrumenting), 'Broadcasted logger not set with @skip_instrumenting' - assert_nil @logger.instance_variable_get(:@skip_instrumenting), 'Logger has @skip_instrumenting defined' - end - - def test_logs_not_forwarded_by_broadcasted_logger - skip 'Rails 7.1. Active Support Logger instrumentation broken, see #2245' if rails_7_1? - - message = 'Can you hear me, Major Tom?' - - @logger.add(Logger::DEBUG, message) - - assert_includes(@output.string, message) - assert_includes(@broadcasted_output.string, message) - - # LogEventAggregator sees the log only once - assert_equal 1, @aggregator.instance_variable_get(:@seen) - assert_equal({'DEBUG' => 1}, @aggregator.instance_variable_get(:@seen_by_severity)) - end - end -end diff --git a/test/multiverse/suites/rails/rails_logger_test.rb b/test/multiverse/suites/rails/rails_logger_test.rb new file mode 100644 index 0000000000..3958ff9dc9 --- /dev/null +++ b/test/multiverse/suites/rails/rails_logger_test.rb @@ -0,0 +1,43 @@ +# 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 './app' + +# Rails's broadcast system sends identical log events to multiple loggers. +# This test makes sure that our code doesn't send two log events to New Relic. +class RailsLoggerTest < Minitest::Test + include MultiverseHelpers + setup_and_teardown_agent + DEFAULT_LOG_PATH = 'log/development.log' + + def setup + # Make sure the default logger destination is empty before we test + File.truncate(DEFAULT_LOG_PATH, 0) + + @output = StringIO.new + broadcasted_logger = Logger.new(@output) + + if Gem::Version.new(Rails::VERSION::STRING) >= Gem::Version.new('7.1.0') + Rails.logger.broadcast_to(broadcasted_logger) + else + Rails.logger.extend(ActiveSupport::Logger.broadcast(broadcasted_logger)) + end + + @aggregator = NewRelic::Agent.agent.log_event_aggregator + @aggregator.reset! + end + + def test_duplicate_logs_not_forwarded_by_rails_logger + message = 'Can you hear me, Major Tom?' + Rails.logger.debug(message) + default_log_output = File.read(DEFAULT_LOG_PATH) + + assert_includes(@output.string, message, 'Broadcasted logger did not receive the message.') + assert_includes(default_log_output, message, 'Default logger did not receive the message.') + + # LogEventAggregator sees the log only once + assert_equal(1, @aggregator.instance_variable_get(:@seen)) + assert_equal({'DEBUG' => 1}, @aggregator.instance_variable_get(:@seen_by_severity)) + end +end From 2f398fd90494f57733567937e35bc495019481c5 Mon Sep 17 00:00:00 2001 From: Kayla Reopelle Date: Wed, 11 Oct 2023 15:29:50 -0700 Subject: [PATCH 2/4] Add unshift_rails_edge to broadcast Envfile --- test/multiverse/suites/active_support_broadcast_logger/Envfile | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/multiverse/suites/active_support_broadcast_logger/Envfile b/test/multiverse/suites/active_support_broadcast_logger/Envfile index af41d8e82e..597fe228bf 100644 --- a/test/multiverse/suites/active_support_broadcast_logger/Envfile +++ b/test/multiverse/suites/active_support_broadcast_logger/Envfile @@ -10,6 +10,8 @@ ACTIVE_SUPPORT_VERSIONS = [ [nil, 2.7] ] +unshift_rails_edge(ACTIVE_SUPPORT_VERSIONS) + def gem_list(activesupport_version = nil) <<-RB gem 'activesupport'#{activesupport_version} From 0f9ebe3eb1545bc8d5279f193e608134ed4e5478 Mon Sep 17 00:00:00 2001 From: Kayla Reopelle Date: Thu, 12 Oct 2023 12:43:36 -0700 Subject: [PATCH 3/4] Use require_relative instead of require --- test/multiverse/suites/rails/rails_logger_test.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/multiverse/suites/rails/rails_logger_test.rb b/test/multiverse/suites/rails/rails_logger_test.rb index 3958ff9dc9..adb5e9059e 100644 --- a/test/multiverse/suites/rails/rails_logger_test.rb +++ b/test/multiverse/suites/rails/rails_logger_test.rb @@ -2,7 +2,7 @@ # See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details. # frozen_string_literal: true -require './app' +require_relative 'app' # Rails's broadcast system sends identical log events to multiple loggers. # This test makes sure that our code doesn't send two log events to New Relic. From 9a5094e5b66fd9d8b8d7c063c98e2afb48670930 Mon Sep 17 00:00:00 2001 From: Kayla Reopelle Date: Thu, 12 Oct 2023 12:48:50 -0700 Subject: [PATCH 4/4] Remove one CHANGELOG paragraph --- CHANGELOG.md | 3 --- 1 file changed, 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7086b76d51..a0dc1681ad 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -24,9 +24,6 @@ Version brings support for gleaning a Docker container id from cgroups v2 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. - Previously, the agent prevented broadcasted loggers from recording duplicate log events by skipping instrumentation for broadcasted loggers, identified by calling `ActiveSupport::Logger.broadcast`. In Rails 7.1, this method has been refactored into a class. The agent now records log events for only the first logger found in an `ActiveSupport::BroadcastLogger.broadcasts` array. - - ## v9.5.0 Version 9.5.0 introduces Stripe instrumentation, allows the agent to record additional response information on a transaction when middleware instrumentation is disabled, introduces new `:'sidekiq.args.include'` and `:'sidekiq.args.exclude:` configuration options to permit capturing only certain Sidekiq job arguments, updates Elasticsearch datastore instance metrics, and fixes a bug in `NewRelic::Rack::AgentHooks.needed?`.