instrument Rails custom events

CHANGELOG.md

@@ -2,12 +2,16 @@
 
   ## v8.14.0
 
-  Version 8.14.0 of the agent restores desired Capistrano-based changelog lookup functionalty when a deployment is performed.
+  Version 8.14.0 of the agent restores desired Capistrano-based changelog lookup functionalty when a deployment is performed and delivers support for instrumenting Rails custom event notifications.
 
   * **Deployment Recipe: Restore desired Capistrano-based changelog lookup behavior**
 
     The New Relic Ruby agent offers [a Capistrano recipe for recording app deployments](https://docs.newrelic.com/docs/apm/agents/ruby-agent/features/record-deployments-ruby-agent/#capistrano3). The recipe code was significantly cleaned up with [PR#1498](https://github.com/newrelic/newrelic-ruby-agent/pull/1498) which inadvertently changed the way the recipe handles the changelog for a deployment. Community member [@arthurwozniak](https://github.com/arthurwozniak) spotted and corrected this change in order to restore the desired changelog lookup functionality while retaining all of the previous cleanup. Thank you very much for your contribution, [@arthurwozniak](https://github.com/arthurwozniak)! [PR#1653](https://github.com/newrelic/newrelic-ruby-agent/pull/1653)
 
+  * **Support for Rails ActiveSupport::Notifications for custom events**
+
+    When the new `active_support_custom_events_names` configuration parameter is set equal to an array of custom event names to subscribe to, the agent will now subscribe to each of the names specified and report instrumentation for the events when they take place. [Creating custom events](https://guides.rubyonrails.org/active_support_instrumentation.html#creating-custom-events) is simple and now reporting instrumentation for them to New Relic is simple as well. [PR#1659](https://github.com/newrelic/newrelic-ruby-agent/pull/1659)
+
 
   ## v8.13.1
 

lib/new_relic/agent/configuration/default_source.rb

@@ -358,6 +358,19 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil)
           :description => 'Sets the level of detail of log messages. Possible log levels, in increasing verbosity, are: `error`, `warn`, `info` or `debug`.'
         },
         # General
+        :active_support_custom_events_names => {
+          :default => [],
+          :public => true,
+          :type => Array,
+          :allowed_from_server => false,
+          :description => <<-DESCRIPTION
+An array of ActiveSupport custom events names to subscribe to and provide
+instrumentation for. For example,
+  - my.custom.event
+  - another.event
+  - a.third.event
+          DESCRIPTION
+        },
         :apdex_t => {
           :default => 0.5,
           :public => true,

lib/new_relic/agent/instrumentation/active_support.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

lib/new_relic/agent/instrumentation/custom_events_subscriber.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
+
+require 'new_relic/agent/instrumentation/notifications_subscriber'
+
+# Listen for ActiveSupport::Notifications events for custom events
+module NewRelic::Agent::Instrumentation
+  class CustomEventsSubscriber < NotificationsSubscriber
+    def start(name, id, _payload) # THREAD_LOCAL_ACCESS
+      return unless state.is_execution_traced?
+
+      finishable = NewRelic::Agent::Tracer.start_transaction_or_segment(name: transaction_name(name),
+        category: :custom_events)
+      push_segment(id, finishable)
+    rescue => e
+      log_notification_error(e, name, 'start')
+    end
+
+    def finish(name, id, payload) # THREAD_LOCAL_ACCESS
+      return unless state.is_execution_traced?
+
+      NewRelic::Agent.notice_error(payload[:exception_object]) if payload.key?(:exception_object)
+
+      finishable = pop_segment(id)
+      finishable.finish if finishable
+    rescue => e
+      log_notification_error(e, name, 'finish')
+    end
+
+    private
+
+    def transaction_name(name)
+      "ActiveSupport/CustomEvents/#{name}"
+    end
+  end
+end

lib/new_relic/agent/instrumentation/rails_notifications/custom_events.rb

@@ -0,0 +1,30 @@
+# 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/custom_events_subscriber'
+require 'new_relic/agent/prepend_supportability'
+
+DependencyDetection.defer do
+  @name = :custom_event_notifications
+
+  depends_on do
+    defined?(::ActiveSupport::Notifications) &&
+      defined?(::ActiveSupport::IsolatedExecutionState)
+  end
+
+  depends_on do
+    !::NewRelic::Agent.config[:active_support_custom_events_names].empty? &&
+      !::NewRelic::Agent::Instrumentation::CustomEventsSubscriber.subscribed?
+  end
+
+  executes do
+    ::NewRelic::Agent.logger.info('Installing notifications based ActiveSupport custom events instrumentation')
+  end
+
+  executes do
+    ::NewRelic::Agent.config[:active_support_custom_events_names].each do |name|
+      ::ActiveSupport::Notifications.subscribe(name, NewRelic::Agent::Instrumentation::CustomEventsSubscriber.new)
+    end
+  end
+end

newrelic.yml

@@ -26,6 +26,13 @@ common: &default_settings
   # All of the following configuration options are optional. Review them, and
   # uncomment or edit them if they appear relevant to your application needs.
 
+  # An array of ActiveSupport custom events names to subscribe to and provide
+  # instrumentation for. For example,
+  #   - my.custom.event
+  #   - another.event
+  #   - a.third.event
+  # active_support_custom_events_names: ""
+
   # If `true`, all logging-related features for the agent can be enabled or disabled
   # independently. If `false`, all logging-related features are disabled.
   # application_logging.enabled: true
@@ -173,6 +180,9 @@ common: &default_settings
   # If true, the agent won't sample the CPU usage of the host process.
   # disable_cpu_sampler: false
 
+  # If true, disables ActiveSupport custom events instrumentation.
+  # disable_custom_events_instrumentation: false
+
   # If true, disables DataMapper instrumentation.
   # disable_data_mapper: false
 

test/helpers/misc.rb

@@ -118,3 +118,9 @@ def wait_until_not_nil(give_up_after = 3, &block)
     current_tries += 1
   end
 end
+
+def skip_unless_minitest5_or_above
+  return if defined?(MiniTest::VERSION) && MiniTest::VERSION > '5'
+
+  skip 'This test requires MiniTest v5+'
+end

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

@@ -0,0 +1,126 @@
+# 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/custom_events_subscriber'
+
+module NewRelic::Agent::Instrumentation
+  class CustomEventsSubscriberTest < Minitest::Test
+    NAME = 'abre los ojos'
+    ID = 1138
+    SUBSCRIBER = NewRelic::Agent::Instrumentation::CustomEventsSubscriber.new
+
+    #
+    # tests with stubbing
+    #
+    def test_start
+      in_transaction do |txn|
+        time = Time.now.to_f
+        SUBSCRIBER.start(NAME, ID, {})
+        segment = txn.segments.last
+
+        assert_in_delta time, segment.start_time
+        assert_equal "ActiveSupport/CustomEvents/#{NAME}", segment.name
+      end
+    end
+
+    def test_start_when_not_traced
+      SUBSCRIBER.state.stub :is_execution_traced?, false do
+        in_transaction do |txn|
+          SUBSCRIBER.start(NAME, ID, {})
+
+          assert_empty txn.segments
+        end
+      end
+    end
+
+    def test_start_with_exception_raised
+      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|
+          NewRelic::Agent::Tracer.stub :start_transaction_or_segment, -> { raise 'kaboom' } do
+            SUBSCRIBER.start(NAME, ID, {})
+          end
+
+          assert_equal 1, txn.segments.size
+        end
+      end
+      logger.verify
+    end
+
+    def test_finish
+      in_transaction do |txn|
+        started_segment = NewRelic::Agent::Tracer.start_transaction_or_segment(name: NAME, category: :testing)
+        SUBSCRIBER.push_segment(ID, started_segment)
+
+        time = Time.now.to_f
+        SUBSCRIBER.finish(NAME, ID, {})
+        segment = txn.segments.last
+
+        assert_in_delta time, segment.end_time
+        assert_predicate(segment, :finished?)
+      end
+    end
+
+    def test_finish_with_exception_payload
+      skip_unless_minitest5_or_above
+
+      noticed = false
+      exception_object = StandardError.new
+      NewRelic::Agent.stub :notice_error, ->(_) { noticed = true }, [exception_object] do
+        SUBSCRIBER.finish(NAME, ID, {exception_object: exception_object})
+      end
+
+      assert noticed
+    end
+
+    def test_finish_with_exception_raised
+      logger = MiniTest::Mock.new
+
+      NewRelic::Agent.stub :logger, logger do
+        logger.expect :error, nil, [/Error during .* callback/]
+        logger.expect :log_exception, nil, [:error, RuntimeError]
+
+        in_transaction do |txn|
+          SUBSCRIBER.state.stub :is_execution_traced?, -> { raise 'kaboom' } do
+            SUBSCRIBER.finish(NAME, ID, {})
+          end
+
+          assert_equal 1, txn.segments.size
+        end
+      end
+      logger.verify
+    end
+
+    #
+    # tests with ActiveSupport enabled
+    #
+    def test_an_actual_custom_event_taking_place
+      unless defined?(::ActiveSupport::Notifications) && defined?(::ActiveSupport::IsolatedExecutionState)
+        skip 'Skipping test as ActiveSupport is not present'
+      end
+
+      with_config(active_support_custom_events_names: [NAME]) do
+        require 'new_relic/agent/instrumentation/rails_notifications/custom_events'
+        DependencyDetection.detect!
+
+        in_transaction do |txn|
+          ActiveSupport::Notifications.subscribe(NAME) { |_name, _started, _finished, _unique_id, _data| }
+          ActiveSupport::Notifications.instrument(NAME, key: :value) do
+            rand(1148)
+          end
+
+          assert_equal 2, txn.segments.size
+          segment = txn.segments.last
+
+          assert_equal "ActiveSupport/CustomEvents/#{NAME}", segment.name
+        end
+      end
+    end
+  end
+end

test/new_relic/recipes/helpers/send_deployment_test.rb

@@ -24,12 +24,8 @@ def tester
       @tester ||= Tester.new
     end
 
-    def minitest5?
-      defined?(MiniTest::VERSION) && MiniTest::VERSION > '5'
-    end
-
     def test_fetch_changelog_initial_fetch_succeeds_and_using_scm_then_use_fetched_value
-      skip 'Stubbing uses MiniTest v5 syntax' unless minitest5?
+      skip_unless_minitest5_or_above
 
       tester.stub :has_scm?, true do
         tester.stub :fetch, Tester::NR_CHANGELOG, [:nr_changelog] do
@@ -39,7 +35,7 @@ def test_fetch_changelog_initial_fetch_succeeds_and_using_scm_then_use_fetched_v
     end
 
     def test_fetch_changelog_initial_fetch_succeeds_and_not_using_scm_then_use_fetched_value
-      skip 'Stubbing uses MiniTest v5 syntax' unless minitest5?
+      skip_unless_minitest5_or_above
 
       tester.stub :has_scm?, false do
         tester.stub :fetch, Tester::NR_CHANGELOG, [:nr_changelog] do
@@ -49,7 +45,7 @@ def test_fetch_changelog_initial_fetch_succeeds_and_not_using_scm_then_use_fetch
     end
 
     def test_fetch_changelog_initial_fetch_fails_and_using_scm_then_perform_lookup
-      skip 'Stubbing uses MiniTest v5 syntax' unless minitest5?
+      skip_unless_minitest5_or_above
 
       tester.stub :has_scm?, true do
         tester.stub :fetch, nil, [:nr_changelog] do
@@ -59,7 +55,7 @@ def test_fetch_changelog_initial_fetch_fails_and_using_scm_then_perform_lookup
     end
 
     def test_fetch_changelog_initial_fetch_fails_and_not_using_scm_then_return_nil
-      skip 'Stubbing uses MiniTest v5 syntax' unless minitest5?
+      skip_unless_minitest5_or_above
 
       tester.stub :has_scm?, false do
         tester.stub :fetch, nil, [:nr_changelog] do