Add Active Support instrumentation

Active Support has notifications built in to instrument
caching-related activities, including:
* cache_read
* cache_generate
* cache_fetch_hit
* cache_write
* cache_delete
* cache_exist?

The payload always includes the key and the name of the
store class. cache_read also includes whether the read
is a hit, and :super_operation when a read is used with

https://guides.rubyonrails.org/active_support_instrumentation.html#active-support

When these operations are executed, a new segment will
be started that includes the payload within the params
attribute.

CHANGELOG.md

@@ -1,5 +1,17 @@
 # New Relic Ruby Agent Release Notes
 
+## Upcoming Release
+
+This upcoming release of the agent adds instrumentation for Active Support caching operations.
+
+- **Add Active Support Instrumentation**
+
+  Active Support instruments caching-related operations. This change includes the instrumentation in the agent. A new segment is created when one of the operations is called. The key, store, and other attributes will be included on the segment as params. [PR#1742](https://github.com/newrelic/newrelic-ruby-agent/pull/1742)
+
+  | Configuration name | Default | Behavior |
+  | ----- | ----- | ----- |
+  | `disable_active_support` | `false` | If `true`, disables ActiveSupport instrumentation. |
+
 ## 8.15.0
 
 Version 8.15.0 of the agent confirms compatibility with Ruby 3.2.0, adds instrumentation for concurrent-ruby, and confirms Sinatra 3 compatibility with Padrino 0.15.2. It also enables batching and compression for Infinite Tracing.

lib/new_relic/agent/configuration/default_source.rb

@@ -1157,6 +1157,14 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil)
           :allowed_from_server => false,
           :description => 'If `true`, disables ActiveStorage instrumentation.'
         },
+        :disable_active_support => {
+          :default => false,
+          :public => true,
+          :type => Boolean,
+          :dynamic_name => true,
+          :allowed_from_server => false,
+          :description => 'If `true`, disables ActiveSupport instrumentation.'
+        },
         :disable_activerecord_instrumentation => {
           :default => value_of(:skip_ar_instrumentation),
           :documentation_default => false,

lib/new_relic/agent/instrumentation/active_support.rb

@@ -2,11 +2,22 @@
 # See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details.
 # frozen_string_literal: true
 
-# This is a helper file that will allow apps using ActiveSupport without Rails
-# to still leverage all ActiveSupport based instrumentation functionality
-# offered by the agent that would otherwise be gated by the detection of Rails.
+require 'new_relic/agent/instrumentation/active_support_subscriber'
 
-# ActiveSupport notifications custom events
-if !defined?(Rails) && defined?(ActiveSupport::Notifications) && defined?(ActiveSupport::IsolatedExecutionState)
-  require_relative 'rails_notifications/custom_events'
+DependencyDetection.defer do
+  named :active_support
+
+  depends_on do
+    defined?(ActiveSupport) &&
+      !NewRelic::Agent::Instrumentation::ActiveSupportSubscriber.subscribed?
+  end
+
+  executes do
+    NewRelic::Agent.logger.info('Installing ActiveSupport instrumentation')
+  end
+
+  executes do
+    ActiveSupport::Notifications.subscribe(/\.active_support$/,
+      NewRelic::Agent::Instrumentation::ActiveSupportSubscriber.new)
+  end
 end

lib/new_relic/agent/instrumentation/active_support_subscriber.rb

@@ -0,0 +1,74 @@
+# 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 'new_relic/agent/instrumentation/notifications_subscriber'
+
+module NewRelic
+  module Agent
+    module Instrumentation
+      class ActiveSupportSubscriber < NotificationsSubscriber
+        def start(name, id, payload)
+          return unless state.is_execution_traced?
+
+          start_segment(name, id, payload)
+        rescue => e
+          log_notification_error(e, name, 'start')
+        end
+
+        def finish(name, id, payload)
+          return unless state.is_execution_traced?
+
+          finish_segment(id, payload)
+        rescue => e
+          log_notification_error(e, name, 'finish')
+        end
+
+        def start_segment(name, id, payload)
+          segment = Tracer.start_segment(name: metric_name(name, payload))
+
+          add_segment_params(segment, payload)
+          push_segment(id, segment)
+        end
+
+        def add_segment_params(segment, payload)
+          segment.params[:key] = payload[:key]
+          segment.params[:store] = payload[:store]
+          segment.params[:hit] = payload[:hit] if payload.key?(:hit)
+          segment.params[:super_operation] = payload[:super_operation] if payload.key?(:super_operation)
+          segment
+        end
+
+        def finish_segment(id, payload)
+          if segment = pop_segment(id)
+            if exception = exception_object(payload)
+              segment.notice_error(exception)
+            end
+            segment.finish
+          end
+        end
+
+        def metric_name(name, payload)
+          store = payload[:store]
+          method = method_from_name(name)
+          "Ruby/ActiveSupport/#{store}/#{method}"
+        end
+
+        PATTERN = /\Acache_([^\.]*)\.active_support\z/
+        UNKNOWN = "unknown".freeze
+
+        METHOD_NAME_MAPPING = Hash.new do |h, k|
+          if PATTERN =~ k
+            h[k] = $1
+          else
+            h[k] = UNKNOWN
+          end
+        end
+
+        def method_from_name(name)
+          METHOD_NAME_MAPPING[name]
+        end
+      end
+    end
+  end
+end

lib/new_relic/agent/instrumentation/custom_events.rb

@@ -0,0 +1,12 @@
+# 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
+
+# This is a helper file that will allow apps using ActiveSupport without Rails
+# to still leverage all ActiveSupport based instrumentation functionality
+# offered by the agent that would otherwise be gated by the detection of Rails.
+
+# ActiveSupport notifications custom events
+if !defined?(Rails) && defined?(ActiveSupport::Notifications) && defined?(ActiveSupport::IsolatedExecutionState)
+  require_relative 'rails_notifications/custom_events'
+end

newrelic.yml

@@ -175,6 +175,9 @@ common: &default_settings
   # If true, disables Active Storage instrumentation.
   # disable_active_storage: false
 
+  # If true, disables Active Support instrumentation.
+  # disable_active_support: false
+
   # If true, disables Active Job instrumentation.
   # disable_activejob: false
 

test/new_relic/agent/instrumentation/active_support_subscriber_test.rb

@@ -0,0 +1,12 @@
+# 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 '../../../test_helper'
+require 'new_relic/agent/instrumentation/active_support_subscriber'
+
+if defined?(ActiveSupport)
+  require_relative 'rails/active_support_subscriber'
+else
+  puts "Skipping tests in #{__FILE__} because Active Support is unavailable"
+end

test/new_relic/agent/instrumentation/rails/active_support_subscriber.rb

@@ -0,0 +1,213 @@
+# 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 '../../../../test_helper'
+
+module NewRelic
+  module Agent
+    module Instrumentation
+      class ActiveSupportSubscriberTest < Minitest::Test
+        DEFAULT_STORE = 'MemCacheStore'
+        METRIC_PREFIX = 'Ruby/ActiveSupport/'
+        DEFAULT_PARAMS = {key: fake_guid(32), store: DEFAULT_STORE}
+        DEFAULT_EVENT = 'cache_read.active_support'
+
+        def setup
+          nr_freeze_process_time
+          @subscriber = ActiveSupportSubscriber.new
+          @id = fake_guid(32)
+
+          NewRelic::Agent.drop_buffered_data
+        end
+
+        def teardown
+          NewRelic::Agent.drop_buffered_data
+        end
+
+        def test_start_when_not_traced
+          @subscriber.state.stub :is_execution_traced?, false do
+            in_transaction do |txn|
+              @subscriber.start(DEFAULT_EVENT, @id, {})
+
+              assert_empty txn.segments
+            end
+          end
+        end
+
+        def test_finish_when_not_traced
+          @subscriber.state.stub :is_execution_traced?, false do
+            in_transaction do |txn|
+              @subscriber.finish(DEFAULT_EVENT, @id, {})
+
+              assert_empty txn.segments
+            end
+          end
+        end
+
+        def test_metrics_recorded_for_known_methods
+          method_name_mapping = {
+            "cache_read.active_support" => "read".freeze,
+            "cache_generate.active_support" => "generate".freeze,
+            "cache_fetch_hit.active_support" => "fetch_hit".freeze,
+            "cache_write.active_support" => "write".freeze,
+            "cache_delete.active_support" => "delete".freeze,
+            "cache_exist?.active_support" => "exist?".freeze
+          }
+
+          in_transaction('test') do
+            method_name_mapping.keys.each do |event_name|
+              generate_event(event_name)
+            end
+          end
+
+          method_name_mapping.values.each do |method_name|
+            assert_metrics_recorded "#{METRIC_PREFIX}#{DEFAULT_STORE}/#{method_name}"
+          end
+        end
+
+        def test_metric_recorded_for_new_event_names
+          in_transaction('test') do
+            generate_event('cache_new_method.active_support')
+          end
+
+          assert_metrics_recorded "#{METRIC_PREFIX}#{DEFAULT_STORE}/new_method"
+        end
+
+        def test_failsafe_if_event_does_not_match_expected_pattern
+          in_transaction('test') do
+            generate_event('charcuterie_build_a_board_workshop')
+          end
+
+          assert_metrics_recorded "#{METRIC_PREFIX}#{DEFAULT_STORE}/unknown"
+        end
+
+        def test_key_recorded_as_attribute_on_traces
+          key = 'blades'
+          txn = in_transaction('test') do
+            generate_event('cache_read.active_support', key: key, hit: false)
+          end
+
+          trace = last_transaction_trace
+          tt_node = find_node_with_name(trace, "#{METRIC_PREFIX}#{DEFAULT_STORE}/read")
+
+          assert_equal key, tt_node.params[:key]
+        end
+
+        def test_hit_recorded_as_attribute_on_traces
+          txn = in_transaction('test') do
+            generate_event('cache_read.active_support', DEFAULT_PARAMS.merge(hit: false))
+          end
+
+          trace = last_transaction_trace
+          tt_node = find_node_with_name(trace, "#{METRIC_PREFIX}#{DEFAULT_STORE}/read")
+
+          puts txn.segments.last.inspect
+
+          assert tt_node.params.key?(:hit)
+          refute tt_node.params[:hit]
+        end
+
+        def test_super_operation_recorded_as_attribute_on_traces
+          txn = in_transaction('test') do
+            generate_event('cache_read.active_support', DEFAULT_PARAMS.merge(super_operation: nil))
+          end
+
+          trace = last_transaction_trace
+          tt_node = find_node_with_name(trace, "#{METRIC_PREFIX}#{DEFAULT_STORE}/read")
+
+          puts txn.segments.last.inspect
+
+          assert tt_node.params.key?(:super_operation)
+          refute tt_node.params[:super_operation]
+        end
+
+        def test_segment_created
+          in_transaction('test') do
+            txn = NewRelic::Agent::Tracer.current_transaction
+
+            assert_equal 1, txn.segments.size
+
+            generate_event('cache_write.active_support', key: 'blade')
+
+            assert_equal 2, txn.segments.size
+            assert_equal "#{METRIC_PREFIX}#{DEFAULT_STORE}/write", txn.segments.last.name
+            assert_predicate txn.segments.last, :finished?, "Segment #{txn.segments.last.name} was never finished.  "
+          end
+        end
+
+        def test_records_span_level_error
+          exception_class = StandardError
+          exception_msg = 'Natural 1'
+          exception = exception_class.new(msg = exception_msg)
+          # :exception_object was added in Rails 5 and above
+          params = {:exception_object => exception, :exception => [exception_class.name, exception_msg]}
+
+          txn = nil
+
+          in_transaction do |test_txn|
+            txn = test_txn
+            generate_event('cache_fetch_hit.active_support', params)
+          end
+
+          assert_segment_noticed_error txn, /fetch/i, exception_class.name, /Natural 1/i
+        end
+
+        def test_pop_segment_returns_false
+          @subscriber.stub :pop_segment, nil do
+            txn = in_transaction do |txn|
+              @subscriber.finish(DEFAULT_EVENT, @id, {})
+            end
+
+            assert txn.segments.none? { |s| s.name.include?('ActiveSupport') }
+          end
+        end
+
+        def test_start_logs_notification_error
+          logger = MiniTest::Mock.new
+
+          NewRelic::Agent.stub :logger, logger do
+            logger.expect :error, nil, [/Error during .* callback/]
+            logger.expect :log_exception, nil, [:error, ArgumentError]
+
+            in_transaction do |txn|
+              @subscriber.stub :start_segment, -> { raise 'kaboom' } do
+                @subscriber.start(DEFAULT_EVENT, @id, {})
+              end
+
+              assert_equal 1, txn.segments.size
+            end
+          end
+          logger.verify
+        end
+
+        def test_finish_logs_notification_error
+          logger = MiniTest::Mock.new
+
+          NewRelic::Agent.stub :logger, logger do
+            logger.expect :error, nil, [/Error during .* callback/]
+            logger.expect :log_exception, nil, [:error, ArgumentError]
+
+            in_transaction do |txn|
+              @subscriber.stub :finish_segment, -> { raise 'kaboom' } do
+                @subscriber.finish(DEFAULT_EVENT, @id, {})
+              end
+
+              assert_equal 1, txn.segments.size
+            end
+          end
+          logger.verify
+        end
+
+        private
+
+        def generate_event(event_name, attributes = {})
+          payload = DEFAULT_PARAMS.merge(attributes)
+          @subscriber.start(event_name, @id, payload)
+          yield if block_given?
+          @subscriber.finish(event_name, @id, payload)
+        end
+      end
+    end
+  end
+end