Add automatic instrumentation support for callbacks

[kaspth]

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:

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

[kaspth]

I wasn't sure of a better way to ensure we run this instrumentation in our CI tests than to just make it a default in Bullet Train apps' tests too, but that may be a bit too aggressive. @jagthedrummer would you happen to have a better idea?

[jagthedrummer]

Hey, so sorry for the delay on this! Can we use a config option to toggle this on or off, and then in the starter repo we default to it being on? Directly checking Rails.env seems less than ideal.

[kaspth]

We need a few commits to make our instrumentation a little easier, so we backport these commits …except if users are running on Rails 7.2 where they already are.

[kaspth]

Here's a sample of what it looks like in practice:

irb(main):001> User.first.touch
  User Load (1.5ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1]]
Callback after_find: after_find_invoked from app/models/user.rb:27:in `invoke'
Callback after_initialize: after_initialize_invoked from app/models/user.rb:27:in `invoke'
  TRANSACTION (0.1ms)  BEGIN
  User Update (1.1ms)  UPDATE "users" SET "updated_at" = $1 WHERE "users"."id" = $2  [["updated_at", "2024-01-29 20:41:18.519670"], ["id", 1]]
Callback after_touch: after_touch_invoked from app/models/user.rb:27:in `invoke'
  TRANSACTION (0.5ms)  COMMIT
Callback after_destroy_commit: after_destroy_commit_invoked from app/models/user.rb:27:in `invoke'
Callback after_update_commit: after_update_commit_invoked from app/models/user.rb:27:in `invoke'
Callback after_save_commit: after_save_commit_invoked from app/models/user.rb:27:in `invoke'
Callback after_create_commit: after_create_commit_invoked from app/models/user.rb:27:in `invoke'
Callback after_commit: #<Proc:0x000000010c97bdc0 /Users/kasperhansen/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activestorage-7.1.2/lib/active_storage/attached/model.rb:127> from /Users/kasperhansen/code/bullet-train-co/bullet_train-core/bullet_train/app/models/concerns/users/base.rb:33:in `block in <module:Base>'
[ActionCable] Broadcasting to User: {:changed=>["updated_at"]}
[ActionCable] Broadcasting to gid://untitled/User/1: {:changed=>["updated_at"]}
=> true

Note: I'm not sure why after_destroy_commit is invoked on touch but it looked like a Rails issue, IMO.

invoke was just a helper method to schedule all the callbacks:

class User
  def self.invoke(callback, with: :"#{callback}_invoked")
    define_method(with) { yield if callback.to_s.include?("around") }
    send(callback, with)
  end

  invoke :after_initialize
  invoke :after_find
  invoke :after_touch

  before_validation { puts "before_validation" }
  before_validation { throw :abort }
  before_validation { puts "after before_validation" }

  invoke :before_validation
  invoke :after_validation

  invoke :around_create
  invoke :before_create
  invoke :after_create

  invoke :around_save
  invoke :before_save
  invoke :after_save

  invoke :around_update
  invoke :before_update
  invoke :after_update

  invoke :around_destroy
  invoke :before_destroy
  invoke :after_destroy

  invoke :after_create_commit
  invoke :after_save_commit
  invoke :after_update_commit
  invoke :after_destroy_commit
end

[kaspth]

I'm also wondering if I should somehow add a uuid tag to a callback chain so users can grep for that in the log. E.g. User#1 and User#2 may execute similar callbacks but if/unless conditions may apply a callback to just User#1 say. Or TangibleThing executing callbacks is different from Active Job's before_perform/after_perform callbacks. I'm not sure how this easy this would be or how it would/could work.

[gazayas]

I got the messages to show in my logs! 👍 Here's one example.

> rails c
Loading development environment (Rails 7.1.3)
irb(main):001> User.first.update!(email: "[email protected]")
  User Load (0.6ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1]]
Callback before_validation: downcase_keys from local/bullet_train-core/bullet_train/app/models/concerns/users/base.rb:11:in `block in <module:Base>'
Callback before_validation: strip_whitespace from local/bullet_train-core/bullet_train/app/models/concerns/users/base.rb:11:in `block in <module:Base>'
...

I wrote a few comments, but I haven't looked into the code yet enough and I'm not too familiar with the classes to provide a proper solution/fix. I'll try to keep up with the conversation and see what @jagthedrummer also has to say though.

[gazayas]

I got this error when trying to migrate the database on a fresh new application:

Loading application environment...
Loading code in search of Active Record models...
bin/rails aborted!
NoMethodError: undefined method `first' for nil (NoMethodError)

      @full_name = (callback.name == :commit) ? caller_locations.first.base_label : "#{callback.kind}_#{callback.name}"
                                                                ^^^^^^
/home/gazayas/work/bt/bullet_train/local/bullet_train-core/bullet_train/lib/bullet_train/core_ext/callbacks_instrumentation.rb:31:in `initialize'

Since caller_locations is nil here, I wonder if we should simply return the method in that case? I can't say I know too much about this Instrumenter class to say that that's the right decision.

[gazayas]

As a side note, the Loading code in search of Active Record models comes from rails-erd. Dropping this for reference because we do some eager loading here: bullet-train-co/bullet_train#1200

[gazayas]

After migrating the database against main and switching over to this branch, I got the following error:

Looking at the first commit that you posted in backport.rb, I saw that they started using this in #apply:

callback_sequence.around(@user_callback, @user_conditions)

I went ahead and used that and then everything started working for me properly, but I don't know enough about this class to say if that's the proper fix or not.

[jagthedrummer]

Looks like there's a test failure that's complaining about the same thing: https://github.com/bullet-train-co/bullet_train-core/actions/runs/8115440263/job/22183312092?pr=760#step:7:34

[jagthedrummer]

@kaspth, this is super cool! I've often found myself wanting this exact thing in lots of apps. I'll use the heck out of this.

That said, I do wonder if this is really a "Bullet Train feature" that belongs in the main bullet_train gem. Ideally I'd love to see this up-streamed into Rails itself.

Or if that's not a possibility for whatever reason (or if it will take a long time), it might be a good candidate for a stand-alone gem that does one thing and does it well. Maybe bullet_train/callback_instrumentation or something?

If we did that I think the source for that gem could still live in the core repo but then it would be installable by non-BT applications. And maybe help get BT on the radar for some people who came across the gem? (Or maybe it's your own custom branded thing?)

I dunno, just kind of thinking out loud here. What do you think?

Whatever the case, I definitely love this idea and will do what I can to help it land somewhere, cuz I wanna use it! (Both in BT and non-BT apps.)

[jagthedrummer]

Also, to be clear, I'm not opposed to this being part of the main bullet_train gem, I just think it could be more widely accessible and available if we were to do something else.