From 64d62a6d1862b0667918cfc938abb67c55c35801 Mon Sep 17 00:00:00 2001 From: Kasper Timm Hansen Date: Mon, 29 Jan 2024 21:31:29 +0100 Subject: [PATCH 1/3] Add automatic instrumentation support for callbacks Callbacks can be useful but they can also be really tricky to trace and debug. This adds a new change that'll automatically log runs of `ActiveSupport::Callbacks`, such as when running jobs, saving models, delivering mailers and any other place callbacks are used. Note: users can disable with `config.bullet_train.instrument_callbacks = false`. Users can subscribe to `callback.active_support` if they need to do any more advanced handling with the callback: ```ruby ActiveSupport::Notifications.subscribe "callback.active_support" do |event| callback = event.payload[:callback] # Send to Sentry/Rollbar/HoneyBadger etc. end class LogSubscriber < ActiveSupport::LogSubscriber attach_to :active_support def callback(event) callback = event.payload[:callback] info { "Callback #{callback.full_name}: #{callback.filter} #{callback.options} from #{callback.location}".squish } end end ``` --- .../core_ext/callbacks_instrumentation.rb | 58 +++++++++ .../callbacks_instrumentation/backport.rb | 118 ++++++++++++++++++ bullet_train/lib/bullet_train/engine.rb | 10 ++ 3 files changed, 186 insertions(+) create mode 100644 bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb create mode 100644 bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb diff --git a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb new file mode 100644 index 000000000..ea58f6289 --- /dev/null +++ b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb @@ -0,0 +1,58 @@ +require_relative "callbacks_instrumentation/backport" + +::ActiveSupport::Callbacks::ClassMethods.prepend Module.new { + def set_callback(name, *filter_list, &block) + *, options = normalize_callback_params(filter_list.dup, block) + Instrumenter.options = options.merge(caller_locations:) + super + ensure + Instrumenter.options = nil + end +} + +::ActiveSupport::Callbacks::Callback.prepend Module.new { + def compiled + @compiled = super.then { Instrumenter.build self, _1 } unless defined?(@compiled) + @compiled + end + + class Instrumenter < Data.define(:callback, :callable, :options) + singleton_class.attr_accessor :options + + def self.build(callback, callable) + options ? new(callback, callable, options) : callable + end + + def initialize(callback:, callable:, options:) + caller_locations = options.delete(:caller_locations) + @location = Rails.backtrace_cleaner.clean(caller_locations).first if caller_locations + @full_name = callback.name == :commit ? caller_locations.first.base_label : "#{callback.kind}_#{callback.name}" + super + end + attr_reader :options, :location, :full_name + delegate :name, :kind, :filter, to: :callback + + def apply(sequence) + case kind + in :before then sequence.before(self) + in :after then sequence.after(self) + in :around then sequence.around(self) + end + end + + def call(env) + ActiveSupport::Notifications.instrument "callback.active_support", callback: self do + callable.call(env) + end + end + end +} + +class ActiveSupport::Callbacks::LogSubscriber < ActiveSupport::LogSubscriber + attach_to :active_support + + def callback(event) + event.payload => {callback:} + info { "Callback #{callback.full_name}: #{callback.filter} #{callback.options} from #{callback.location}".squish } + end +end diff --git a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb new file mode 100644 index 000000000..91b8bd8dc --- /dev/null +++ b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb @@ -0,0 +1,118 @@ +return if ActiveSupport::VERSION.to_s.start_with?("7.2") + +# Backports a few commits from Rails 7.2 to make our debugging extension easier: +# +# - https://github.com/rails/rails/commit/6c5a042824fdaf630ebaa7fb293b8c2543f20d00 +# - https://github.com/rails/rails/commit/42ad4d6b0bfc14e16050f9945a8b2ac5c87c294f +module ActiveSupport::Callbacks + Callback.prepend Module.new { + def initialize(...) + super + compiled # Eager load ActiveSupport::Callback procs + end + + def compiled + @compiled ||= + begin + user_conditions = conditions_lambdas + user_callback = CallTemplate.build(@filter, self) + + case kind + when :before + Filters::Before.new(user_callback.make_lambda, user_conditions, chain_config, @filter, name) + when :after + Filters::After.new(user_callback.make_lambda, user_conditions, chain_config) + when :around + Filters::Around.new(user_callback, user_conditions) + end + end + end + + def apply(callback_sequence) + compiled.apply(callback_sequence) + end + } + + class CallbackSequence + def before(before) + @before.unshift(before) + self + end + + def after(after) + @after.push(after) + self + end + end + + module Filters + # Around wasn't defined before our commit backport, so we don't need to remove that. + remove_const :Before + remove_const :After + + class Before + def initialize(user_callback, user_conditions, chain_config, filter, name) + halted_lambda = chain_config[:terminator] + @user_callback, @user_conditions, @halted_lambda, @filter, @name = user_callback, user_conditions, halted_lambda, filter, name + freeze + end + attr_reader :user_callback, :user_conditions, :halted_lambda, :filter, :name + + def call(env) + target = env.target + value = env.value + halted = env.halted + + if !halted && user_conditions.all? { |c| c.call(target, value) } + result_lambda = -> { user_callback.call target, value } + env.halted = halted_lambda.call(target, result_lambda) + if env.halted + target.send :halted_callback_hook, filter, name + end + end + + env + end + + def apply(callback_sequence) + callback_sequence.before(self) + end + end + + class After + attr_reader :user_callback, :user_conditions, :halting + def initialize(user_callback, user_conditions, chain_config) + halting = chain_config[:skip_after_callbacks_if_terminated] + @user_callback, @user_conditions, @halting = user_callback, user_conditions, halting + freeze + end + + def call(env) + target = env.target + value = env.value + halted = env.halted + + if (!halted || !@halting) && user_conditions.all? { |c| c.call(target, value) } + user_callback.call target, value + end + + env + end + + def apply(callback_sequence) + callback_sequence.after(self) + end + end + + class Around + def initialize(user_callback, user_conditions) + @user_callback, @user_conditions = user_callback, user_conditions + freeze + end + + def apply(callback_sequence) + callback_sequence.around(@user_callback, @user_conditions) + end + end + end +end diff --git a/bullet_train/lib/bullet_train/engine.rb b/bullet_train/lib/bullet_train/engine.rb index 28216abf0..83acc88ff 100644 --- a/bullet_train/lib/bullet_train/engine.rb +++ b/bullet_train/lib/bullet_train/engine.rb @@ -21,5 +21,15 @@ module BulletTrain class Engine < ::Rails::Engine + config.bullet_train = ActiveSupport::OrderedOptions.new + config.bullet_train.instrument_callbacks = Rails.env.development? || Rails.env.test? + + initializer "callbacks.instrumentation" do + if config.bullet_train.instrument_callbacks + config.after_initialize do + require_relative "../bullet_train/core_ext/callbacks_instrumentation" + end + end + end end end From a388f9e7b899ac3192fa109e98ce0cee39a07b30 Mon Sep 17 00:00:00 2001 From: Kasper Timm Hansen Date: Mon, 29 Jan 2024 21:46:55 +0100 Subject: [PATCH 2/3] backtrace_cleaner doesn't quite support caller_locations --- .../lib/bullet_train/core_ext/callbacks_instrumentation.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb index ea58f6289..b7a52fa81 100644 --- a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb +++ b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb @@ -25,7 +25,7 @@ def self.build(callback, callable) def initialize(callback:, callable:, options:) caller_locations = options.delete(:caller_locations) - @location = Rails.backtrace_cleaner.clean(caller_locations).first if caller_locations + @location = Rails.backtrace_cleaner.clean(caller_locations.map(&:to_s)).first if caller_locations @full_name = callback.name == :commit ? caller_locations.first.base_label : "#{callback.kind}_#{callback.name}" super end From cc7879d5d5ecd16f7a7a85a527b1925457f14eea Mon Sep 17 00:00:00 2001 From: Kasper Timm Hansen Date: Mon, 29 Jan 2024 21:49:47 +0100 Subject: [PATCH 3/3] Fix standardrb --- .../core_ext/callbacks_instrumentation.rb | 48 ++++++++++--------- .../callbacks_instrumentation/backport.rb | 4 +- 2 files changed, 27 insertions(+), 25 deletions(-) diff --git a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb index b7a52fa81..bf0cde706 100644 --- a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb +++ b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb @@ -1,20 +1,22 @@ require_relative "callbacks_instrumentation/backport" -::ActiveSupport::Callbacks::ClassMethods.prepend Module.new { - def set_callback(name, *filter_list, &block) - *, options = normalize_callback_params(filter_list.dup, block) - Instrumenter.options = options.merge(caller_locations:) - super - ensure - Instrumenter.options = nil - end -} +module ActiveSupport::Callbacks + ClassMethods.prepend Module.new { + def set_callback(name, *filter_list, &block) + *, options = normalize_callback_params(filter_list.dup, block) + Instrumenter.options = options.merge(caller_locations:) + super + ensure + Instrumenter.options = nil + end + } -::ActiveSupport::Callbacks::Callback.prepend Module.new { - def compiled - @compiled = super.then { Instrumenter.build self, _1 } unless defined?(@compiled) - @compiled - end + Callback.prepend Module.new { + def compiled + @compiled = super.then { Instrumenter.build self, _1 } unless defined?(@compiled) + @compiled + end + } class Instrumenter < Data.define(:callback, :callable, :options) singleton_class.attr_accessor :options @@ -25,8 +27,8 @@ def self.build(callback, callable) def initialize(callback:, callable:, options:) caller_locations = options.delete(:caller_locations) - @location = Rails.backtrace_cleaner.clean(caller_locations.map(&:to_s)).first if caller_locations - @full_name = callback.name == :commit ? caller_locations.first.base_label : "#{callback.kind}_#{callback.name}" + @location = Rails.backtrace_cleaner.clean(caller_locations.map(&:to_s)).first if caller_locations + @full_name = (callback.name == :commit) ? caller_locations.first.base_label : "#{callback.kind}_#{callback.name}" super end attr_reader :options, :location, :full_name @@ -35,7 +37,7 @@ def initialize(callback:, callable:, options:) def apply(sequence) case kind in :before then sequence.before(self) - in :after then sequence.after(self) + in :after then sequence.after(self) in :around then sequence.around(self) end end @@ -46,13 +48,13 @@ def call(env) end end end -} -class ActiveSupport::Callbacks::LogSubscriber < ActiveSupport::LogSubscriber - attach_to :active_support + class LogSubscriber < ActiveSupport::LogSubscriber + attach_to :active_support - def callback(event) - event.payload => {callback:} - info { "Callback #{callback.full_name}: #{callback.filter} #{callback.options} from #{callback.location}".squish } + def callback(event) + event.payload => {callback:} + info { "Callback #{callback.full_name}: #{callback.filter} #{callback.options} from #{callback.location}".squish } + end end end diff --git a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb index 91b8bd8dc..0a56fff58 100644 --- a/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb +++ b/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation/backport.rb @@ -60,7 +60,7 @@ def initialize(user_callback, user_conditions, chain_config, filter, name) def call(env) target = env.target - value = env.value + value = env.value halted = env.halted if !halted && user_conditions.all? { |c| c.call(target, value) } @@ -89,7 +89,7 @@ def initialize(user_callback, user_conditions, chain_config) def call(env) target = env.target - value = env.value + value = env.value halted = env.halted if (!halted || !@halting) && user_conditions.all? { |c| c.call(target, value) }