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

kaylareopelle · 2023-10-10T20:04:50Z

In Rails, you have one central logger, Rails.logger, but often want those messages to be output to multiple destinations. In a development environment, this includes STDOUT and development.log by default. This works by having one central logger that creates the logs, and "broadcasts" those logs to multiple destinations.

This posed a problem when we added APM automatic log forwarding, because New Relic emitted an identical log event for each broadcast, often causing duplicate events to appear in the UI.

In earlier versions of Rails, we leverage ActiveSupport::Logger.broadcast to set the @skip_instrumenting instance variable to true to avoid recording duplicated logs. This was a private method, prone to change at any time.

Rails 7.1 replaced the ActiveSupport::Logger.broadcast method with a new public class, ActiveSupport::BroadcastLogger. This class operates in largely the same way as the old method, but since it is a class and no longer a method, we cannot monkey-patch it in the same way. However, since it is public, we can have greater faith in the stability of our instrumentation.

This POC provides one option to prevent duplicate log records from being sent to New Relic when using ActiveSupport::BroadcastLogger. Logs emitted by debug, info, or add methods set @skip_instrumenting to true for all but the first logger in the broadcasts array. At the end of the method, all loggers in the broadcasts array have @skip_instrumenting set to false.

Some things to consider:

The loggers included in ActiveSupport::BroadcastLogger#broadcasts can change after startup. New loggers may be added or removed from the array.
The add method in ActiveSupport::BroadcastLogger calls the add method on each individual logger. This means the BroadcastLogger version of the method doesn't call the severity method (ex. debug) like it does in the Ruby logger.
If we decide this POC is on the right track, we'll need to monkey-patch all the severity methods to get our desired behavior (error, warn, etc.)

Closes: #2245

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

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.

kaylareopelle · 2023-10-11T21:56:58Z

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.


I'd love to have suggestions on how to improve this and the statement below, especially if we want to turn it into a more general statement about the agent supporting Rails 7.1.

I also noticed the active_support_logger instrumentation wasn't specifically called out in the changelog when we released logs functionality, so what we reveal here may not need to be so specific.

kaylareopelle · 2023-10-11T21:58:19Z

lib/new_relic/agent/instrumentation/active_support_broadcast_logger.rb

+DependencyDetection.defer do
+  named :'active_support_broadcast_logger'
+
+  depends_on { defined?(ActiveSupport::BroadcastLogger) }


This should prevent the BroadcastLogger instrumentation from being installed on Rails versions below 7.1.

kaylareopelle · 2023-10-11T21:59:57Z

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

+      ::ActiveSupportBroadcastLogger.class_eval do
+        include NewRelic::Agent::Instrumentation::ActiveSupportBroadcastLogger
+
+        alias_method(:add_without_new_relic, :add)


In both chain and prepend, I tried to use iteration and define_method to reduce duplication in the files. Unfortuantely, super can't be called within define_method.

example prepend attempt:

LOG_RECORD_METHODS = %w[add debug info warn error fatal unknown] LOG_RECORD_METHODS.each do |method| define_method "#{method}" do |*args| skip_broadcasts_with_new_relic(*args) { super } end end

For others who might come across this with curiosity... define_method works fine with super if the arguments are fixed. But the splatted *args needed here won't work:

implicit argument passing of super from method defined by define_method() is not supported. Specify all arguments explicitly. (RuntimeError)

Thank you for clarifying, @fallwith!

kaylareopelle · 2023-10-11T22:01:03Z

lib/new_relic/agent/instrumentation/active_support_logger.rb

-      # 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)


ActiveSupport::Logger is still defined in Rails 7.1, but the method we instrument, ActiveSupport::Logger.broadcast is not. This seemed more precise than using a Rails version.

kaylareopelle · 2023-10-11T22:11:54Z

test/multiverse/suites/active_support_logger/Envfile

@@ -0,0 +1,23 @@
+# This file is distributed under New Relic's license terms.


I realized our chain instrumentation for ActiveSupport::Logger was never being tested, so I created a multiverse suite to make sure it gets checked.

kaylareopelle · 2023-10-11T22:12:47Z

test/multiverse/suites/rails/rails_logger_test.rb

@@ -0,0 +1,43 @@
+# This file is distributed under New Relic's license terms.


Hopefully, this test will give us a heads-up if something changes with the Rails logger that causes the duplication issue to resurface.

fallwith · 2023-10-11T23:31:23Z

test/multiverse/suites/rails/rails_logger_test.rb

+# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
+# frozen_string_literal: true
+
+require './app'


Equivalent to require_relative 'app' with fewer keystrokes?

Great catch! I prefer require_relative. This was a copy/paste carryover.

Updated in: 0f9ebe3

CHANGELOG.md

github-actions · 2023-10-12T19:59:52Z

SimpleCov Report

	Coverage	Threshold
Line	94.06%	94%
Branch	85.65%	85%

nathan-appere · 2024-03-14T10:53:40Z

@kaylareopelle this causes an exception for us on:

NoMethodError
undefined method `each' for nil:NilClass (NoMethodError)

      broadcasts[1..-1].each { |broadcasted_logger| broadcasted_logger.instance_variable_set(:@skip_instrumenting, true) }

With:

newrelic_rpm (9.7.1)
rails (7.1.3.2)

I have no idea how broadcasts can be nil (should be an Array looking at the implementation of ActiveSupportBroadcastLogger)

Only happens in production with low volume (1 failure every 10000 calls), so tricky to identify the cause (the volume makes me think it could be somehow thread related?)

kaylareopelle requested review from fallwith, hannahramadan and tannalynn as code owners October 10, 2023 20:04

kaylareopelle marked this pull request as draft October 10, 2023 20:06

kaylareopelle commented Oct 10, 2023

View reviewed changes

lib/new_relic/agent/instrumentation/active_support_broadcast_logger/instrumentation.rb Outdated Show resolved Hide resolved

kaylareopelle force-pushed the fix-active-support-logger-instrumentation branch from 8d55b4e to bd8a857 Compare October 11, 2023 22:10

kaylareopelle commented Oct 11, 2023

View reviewed changes

kaylareopelle changed the title ~~WIP: Ignore all broadcasts except one~~ Rails 7.1: Record only one copy of a broadcasted log message Oct 11, 2023

kaylareopelle marked this pull request as ready for review October 11, 2023 22:13

fallwith previously approved these changes Oct 11, 2023

View reviewed changes

Add unshift_rails_edge to broadcast Envfile

2f398fd

kaylareopelle dismissed fallwith’s stale review via 2f398fd October 11, 2023 22:29

fallwith previously approved these changes Oct 11, 2023

View reviewed changes

fallwith reviewed Oct 11, 2023

View reviewed changes

kaylareopelle commented Oct 12, 2023

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

Use require_relative instead of require

0f9ebe3

kaylareopelle dismissed fallwith’s stale review via 0f9ebe3 October 12, 2023 19:43

Remove one CHANGELOG paragraph

9a5094e

fallwith approved these changes Oct 12, 2023

View reviewed changes

kaylareopelle merged commit 67565e8 into dev Oct 13, 2023
26 checks passed

kaylareopelle deleted the fix-active-support-logger-instrumentation branch October 13, 2023 19:35

kaylareopelle mentioned this pull request May 14, 2024

feat: 🚧 WIP: Logger instrumentation open-telemetry/opentelemetry-ruby-contrib#983

Draft

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

kaylareopelle commented Oct 10, 2023

kaylareopelle Oct 11, 2023

kaylareopelle Oct 11, 2023

kaylareopelle Oct 11, 2023

fallwith Oct 11, 2023

kaylareopelle Oct 12, 2023

kaylareopelle Oct 11, 2023

kaylareopelle Oct 11, 2023

kaylareopelle Oct 11, 2023

fallwith Oct 11, 2023

kaylareopelle Oct 12, 2023

kaylareopelle Oct 12, 2023

github-actions bot commented Oct 12, 2023

nathan-appere commented Mar 14, 2024 •

edited

Loading

		@@ -0,0 +1,23 @@
		# This file is distributed under New Relic's license terms.

		@@ -0,0 +1,43 @@
		# This file is distributed under New Relic's license terms.

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

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

Conversation

kaylareopelle commented Oct 10, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Oct 12, 2023

SimpleCov Report

nathan-appere commented Mar 14, 2024 • edited Loading

nathan-appere commented Mar 14, 2024 •

edited

Loading