Bullet.profile seems to cache association loading after 6.1.3

[tubaxenor]

I am trying to bump bullet from 6.1.2 to 6.1.5, but seems this commit is causing a regression when using Bullet.profile

Tested on 5.2, 6.0, 6.1, all failed.

Bug Code

# frozen_string_literal: true

require 'bundler/inline'

gemfile(true) do
  source 'https://rubygems.org'
  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  gem 'rails', ENV.fetch('RAILS_VERSION', '~> 6.1')
  gem 'sqlite3'

  gem 'bullet', github: 'flyerhzm/bullet', require: false
end

require 'active_record'
require 'minitest/autorun'
require 'logger'
require 'bullet'
require 'bullet/version'

STDOUT.puts "\n\nBULLET VERSION #{Bullet::VERSION}"

# This connection will do for database-independent bug reports.
ActiveRecord::Base.establish_connection(adapter: 'sqlite3', database: ':memory:')
ActiveRecord::Base.logger = Logger.new(STDOUT)
Rails.logger = ActiveRecord::Base.logger

ActiveRecord::Schema.define do
  create_table :users, force: true do |t|
    t.string :name, null: false
  end

  create_table :plans, force: true do |t|
    t.string :name, null: false
  end

  create_table :user_plans, force: true do |t|
    t.references :source, null: false, polymorphic: true
    t.references :plan, null: false
  end
end

class ApplicationRecord < ActiveRecord::Base
  self.abstract_class = true
end

class User < ApplicationRecord
  has_one :user_plan, as: :source, dependent: :destroy
  has_one :plan, through: :user_plan
  validate :foo

  def foo
    plan
  end
end

class Plan < ApplicationRecord
  has_many :user_plans, dependent: :delete_all
  has_many :users, through: :user_plans, source: :source, source_type: 'User'
end

class UserPlan < ApplicationRecord
  belongs_to :source, polymorphic: true
  belongs_to :plan
  validates :source_id, uniqueness: { case_sensitive: true, scope: ['source_type'] }
end

class BugTest < Minitest::Test
  def test_association
    Bullet.enable = true
    Bullet.rails_logger = true
    Bullet.raise = true
    Bullet.n_plus_one_query_enable = true

    Bullet.profile do
      user_1 = User.create!(name: 'user 1')
      user_2 = User.create!(name: 'user 2')
      plan_1 = Plan.create!(name: 'plan 1')
      plan_2 = Plan.create!(name: 'plan 2')

      User.all.each do |user|
        user.update!(plan: plan_1)
      end

      user_2.update!(plan: plan_2)
	  puts "AFTER UPDATE: #{user_2.association(:user_plan).target.inspect}"
      test_user = User.where(id: user_2.id).first
      assert_equal(test_user.plan.id, plan_2.id)
    end
  end
end

Bug Output

Fetching https://github.com/flyerhzm/bullet.git
Fetching gem metadata from https://rubygems.org/.............
Resolving dependencies....
Ignoring executable-hooks-1.6.0 because its extensions are not built. Try: gem pristine executable-hooks --version 1.6.0
Ignoring gem-wrappers-1.4.0 because its extensions are not built. Try: gem pristine gem-wrappers --version 1.4.0
Ignoring mysql2-0.3.18 because its extensions are not built. Try: gem pristine mysql2 --version 0.3.18
Ignoring rainbow-2.2.2 because its extensions are not built. Try: gem pristine rainbow --version 2.2.2
Error loading RubyGems plugin "/Users/wei-fun.chang/.rvm/rubies/ruby-2.7.2/lib/ruby/gems/2.7.0/gems/executable-hooks-1.6.0/lib/rubygems_plugin.rb": cannot load such file -- executable-hooks/wrapper (LoadError)
Error loading RubyGems plugin "/Users/wei-fun.chang/.rvm/rubies/ruby-2.7.2/lib/ruby/gems/2.7.0/gems/gem-wrappers-1.4.0/lib/rubygems_plugin.rb": cannot load such file -- gem-wrappers (LoadError)
Using rake 13.0.6
Using concurrent-ruby 1.1.9
Using minitest 5.14.4
Using uniform_notifier 1.14.2
Using bundler 2.2.24
Using erubi 1.10.0
Using racc 1.5.2
Using crass 1.0.6
Using rack 2.2.3
Using nio4r 2.5.8
Using websocket-extensions 0.1.5
Using sprockets 4.0.2
Using arel 9.0.0
Using marcel 1.0.1
Using thread_safe 0.3.6
Using websocket-driver 0.7.5
Using builder 3.2.4
Using tzinfo 1.2.9
Using sqlite3 1.4.2
Using i18n 1.8.10
Using nokogiri 1.12.4 (x86_64-darwin)
Using activesupport 5.2.6
Using rack-test 1.1.0
Using rails-dom-testing 2.0.3
Using method_source 1.0.0
Using mini_mime 1.1.1
Using loofah 2.12.0
Using mail 2.7.1
Using activemodel 5.2.6
Using rails-html-sanitizer 1.4.2
Using thor 1.1.0
Using globalid 0.5.2
Using activerecord 5.2.6
Using bullet 6.1.5 from https://github.com/flyerhzm/bullet.git (at master@371beec)
Using actionview 5.2.6
Using activejob 5.2.6
Using actionpack 5.2.6
Using actioncable 5.2.6
Using actionmailer 5.2.6
Using activestorage 5.2.6
Using railties 5.2.6
Using sprockets-rails 3.2.2
Using rails 5.2.6


BULLET VERSION 6.1.5
-- create_table(:users, {:force=>true})
D, [2021-09-08T13:14:50.626945 #30110] DEBUG -- :    (0.0ms)  DROP TABLE IF EXISTS "users"
D, [2021-09-08T13:14:50.627860 #30110] DEBUG -- :    (0.8ms)  SELECT sqlite_version(*)
D, [2021-09-08T13:14:50.628216 #30110] DEBUG -- :    (0.3ms)  CREATE TABLE "users" ("id" integer PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar NOT NULL)
   -> 0.0035s
-- create_table(:plans, {:force=>true})
D, [2021-09-08T13:14:50.628433 #30110] DEBUG -- :    (0.0ms)  DROP TABLE IF EXISTS "plans"
D, [2021-09-08T13:14:50.628611 #30110] DEBUG -- :    (0.1ms)  CREATE TABLE "plans" ("id" integer PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar NOT NULL)
   -> 0.0003s
-- create_table(:user_plans, {:force=>true})
D, [2021-09-08T13:14:50.628823 #30110] DEBUG -- :    (0.0ms)  DROP TABLE IF EXISTS "user_plans"
D, [2021-09-08T13:14:50.629028 #30110] DEBUG -- :    (0.1ms)  CREATE TABLE "user_plans" ("id" integer PRIMARY KEY AUTOINCREMENT NOT NULL, "source_type" varchar NOT NULL, "source_id" integer NOT NULL, "plan_id" integer NOT NULL)
D, [2021-09-08T13:14:50.629350 #30110] DEBUG -- :    (0.1ms)  CREATE  INDEX "index_user_plans_on_source_type_and_source_id" ON "user_plans" ("source_type", "source_id")
D, [2021-09-08T13:14:50.629833 #30110] DEBUG -- :    (0.1ms)  CREATE  INDEX "index_user_plans_on_plan_id" ON "user_plans" ("plan_id")
   -> 0.0012s
D, [2021-09-08T13:14:50.650914 #30110] DEBUG -- :    (0.1ms)  CREATE TABLE "ar_internal_metadata" ("key" varchar NOT NULL PRIMARY KEY, "value" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)
D, [2021-09-08T13:14:50.661066 #30110] DEBUG -- :   ActiveRecord::InternalMetadata Load (1.4ms)  SELECT  "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ?  [["key", "environment"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.664225 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.664896 #30110] DEBUG -- :   ActiveRecord::InternalMetadata Create (0.1ms)  INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES (?, ?, ?, ?)  [["key", "environment"], ["value", "development"], ["created_at", "2021-09-08 05:14:50.664486"], ["updated_at", "2021-09-08 05:14:50.664486"]]
D, [2021-09-08T13:14:50.665024 #30110] DEBUG -- :    (0.0ms)  commit transaction
Run options: --seed 18098

# Running:

D, [2021-09-08T13:14:50.706118 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.709075 #30110] DEBUG -- :   User Create (0.1ms)  INSERT INTO "users" ("name") VALUES (?)  [["name", "user 1"]]
D, [2021-09-08T13:14:50.711923 #30110] DEBUG -- :   UserPlan Load (0.1ms)  SELECT  "user_plans".* FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 1], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.712270 #30110] DEBUG -- :    (0.0ms)  commit transaction
D, [2021-09-08T13:14:50.712432 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.712860 #30110] DEBUG -- :   User Create (0.1ms)  INSERT INTO "users" ("name") VALUES (?)  [["name", "user 2"]]
D, [2021-09-08T13:14:50.713367 #30110] DEBUG -- :   UserPlan Load (0.0ms)  SELECT  "user_plans".* FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 2], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.713826 #30110] DEBUG -- :    (0.0ms)  commit transaction
D, [2021-09-08T13:14:50.716025 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.716946 #30110] DEBUG -- :   Plan Create (0.2ms)  INSERT INTO "plans" ("name") VALUES (?)  [["name", "plan 1"]]
D, [2021-09-08T13:14:50.717266 #30110] DEBUG -- :    (0.0ms)  commit transaction
D, [2021-09-08T13:14:50.717482 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.717858 #30110] DEBUG -- :   Plan Create (0.1ms)  INSERT INTO "plans" ("name") VALUES (?)  [["name", "plan 2"]]
D, [2021-09-08T13:14:50.718027 #30110] DEBUG -- :    (0.0ms)  commit transaction
D, [2021-09-08T13:14:50.718355 #30110] DEBUG -- :   User Load (0.1ms)  SELECT "users".* FROM "users"
D, [2021-09-08T13:14:50.719580 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.720214 #30110] DEBUG -- :   UserPlan Load (0.0ms)  SELECT  "user_plans".* FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 1], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.726002 #30110] DEBUG -- :   UserPlan Exists (0.1ms)  SELECT  1 AS one FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 1], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.726554 #30110] DEBUG -- :   UserPlan Create (0.1ms)  INSERT INTO "user_plans" ("source_type", "source_id", "plan_id") VALUES (?, ?, ?)  [["source_type", "User"], ["source_id", 1], ["plan_id", 1]]
D, [2021-09-08T13:14:50.728023 #30110] DEBUG -- :    (0.0ms)  commit transaction
D, [2021-09-08T13:14:50.728215 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.728629 #30110] DEBUG -- :   UserPlan Load (0.0ms)  SELECT  "user_plans".* FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 2], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.729315 #30110] DEBUG -- :   UserPlan Exists (0.1ms)  SELECT  1 AS one FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 2], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.729805 #30110] DEBUG -- :   UserPlan Create (0.1ms)  INSERT INTO "user_plans" ("source_type", "source_id", "plan_id") VALUES (?, ?, ?)  [["source_type", "User"], ["source_id", 2], ["plan_id", 1]]
D, [2021-09-08T13:14:50.731060 #30110] DEBUG -- :    (0.0ms)  commit transaction
D, [2021-09-08T13:14:50.731161 #30110] DEBUG -- :    (0.0ms)  begin transaction
D, [2021-09-08T13:14:50.731853 #30110] DEBUG -- :   UserPlan Exists (0.1ms)  SELECT  1 AS one FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 2], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.741520 #30110] DEBUG -- :   UserPlan Exists (0.1ms)  SELECT  1 AS one FROM "user_plans" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 2], ["source_type", "User"], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.742341 #30110] DEBUG -- :    (0.0ms)  commit transaction
AFTER UPDATE: #<UserPlan id: nil, source_type: "User", source_id: 2, plan_id: 2>
D, [2021-09-08T13:14:50.742893 #30110] DEBUG -- :   User Load (0.1ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? ORDER BY "users"."id" ASC LIMIT ?  [["id", 2], ["LIMIT", 1]]
D, [2021-09-08T13:14:50.745818 #30110] DEBUG -- :   Plan Load (0.1ms)  SELECT  "plans".* FROM "plans" INNER JOIN "user_plans" ON "plans"."id" = "user_plans"."plan_id" WHERE "user_plans"."source_id" = ? AND "user_plans"."source_type" = ? LIMIT ?  [["source_id", 2], ["source_type", "User"], ["LIMIT", 1]]
F

Failure:
BugTest#test_association [bullet_bug.rb:87]:
Expected: 1
  Actual: 2


bin/rails test bullet_bug.rb:69



Finished in 0.053298s, 18.7624 runs/s, 18.7624 assertions/s.
1 runs, 1 assertions, 1 failures, 0 errors, 0 skips

When validation loads the has_one through association, the association is somehow cached and set @loaded to true, can be fixed after removing this part of the code in active_recordxx.rb under def target:

association = owner.association(reflection.through_reflection.name)
Array(association.target).each do |through_record|
  Bullet::Detector::NPlusOneQuery.call_association(through_record, source_reflection.name)
end