Is `dripper/perform.rb` locating wrong `campaign` when database is MySQL?

[erwin]

I've been struggling with this one non-stop since Saturday. Please pardon me if I have missed something. It was a lot of work to slice this out of my app and find the breaking point. It's very subtle.

I've done my best to create a minimal reproducible test. I'm not sure if it impacts production or only the test harness.

The issue I'm seeing is that when using MySQL, the first call to perform! works fine. https://github.com/joshmn/caffeinate/blob/03560676e0fe8c834d37837fd9434defff8ae8c9/lib/caffeinate/dripper/perform.rb#L17

But in subsequent calls, the value of campaign is set incorrectly (I think to the value from the previous call) https://github.com/joshmn/caffeinate/blob/03560676e0fe8c834d37837fd9434defff8ae8c9/lib/caffeinate/dripper/perform.rb#L40

The result is upcoming_mailings returns an empty set on subsequent calls to perform, and thus the campaign is only run the first time.

Debugging the `Caffeinate::CampaignSubscription` result set inside of `Perform!`

I modified `perform` to dump the `Caffeinate::CampaignSubscription` set as it's filtered so I can see what was happening: https://github.com/joshmn/caffeinate/blob/03560676e0fe8c834d37837fd9434defff8ae8c9/lib/caffeinate/dripper/perform.rb#L19 Print the `Caffeinate::CampaignSubscription` inside of `perform!`: ```ruby puts "Caffeinate::CampaignSubscription.active, `campaign.id` == #{campaign.id}" tp(Caffeinate::CampaignSubscription.active, :id, :caffeinate_campaign_id, :subscriber_type, :subscriber_id, :user_type, :user_id, :ended_at, :unsubscribed_at) puts "Caffeinate::CampaignSubscription.active.where(caffeinate_campaign == #{campaign.id})" tp(Caffeinate::CampaignSubscription.active.where(caffeinate_campaign: campaign), :id, :caffeinate_campaign_id, :subscriber_type, :subscriber_id, :user_type, :user_id, :ended_at, :unsubscribed_at) ```

I created an empty rails 7 project that uses sqlite3 and the following works as expected:

• Creates a campaign
• Subscribes to a campaign
• And then twice calls .perform! on the campaign, to execute both of the drippers connected to the campaign.
• Then repeat the same in a second test

However, when I do the same thing on a blank rails 7 project that uses MySQL, when perform! is called in the 2nd test, the Caffeinate::CampaignSubscription result set is blank (because campaign is pointing to an invalid record, and thus no drips are sent the second time around.

From inside of calls to perform!, if we print all of the active campaigns with: Caffeinate::CampaignSubscription.active it contains:

Caffeinate::CampaignSubscription.active, `campaign.id` ==  44
                                                          ^^^^
ID | CAFFEINATE_CAMPAIGN_ID | SUBSCRIBER_TYPE | SUBSCRIBER_ID | USER_TYPE | USER_ID   | ENDED_AT | UNSUBSCRIBED_AT
---|------------------------|-----------------|---------------|-----------|-----------|----------|----------------
27 | 45                     | Subscriber      | 980190993     | User      | 980191007 |          |                
    ^^^^

You see how campaign.id does not match CAFFEINATE_CAMPAIGN_ID... So when we print the active campaigns where the campaign id matches, we get an empty set:

Caffeinate::CampaignSubscription.active.where(caffeinate_campaign == 44)
No data.

---

Reproducing...

Versions:

ubuntu-22-04% ruby -v
ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [x86_64-linux-gnu]
ubuntu-22-04% rails -v
Rails 7.0.6
ubuntu-22-04% cat /etc/debian_version
bookworm/sid

Create a new rails7 project to reproduce the bug:

```shell rails new --minimal repro -d mysql cd repro bin/bundle add caffeinate awesome_print table_print rails g caffeinate:install rails g model User name email before_drip_run_counter:integer rails g model Subscriber name email sudo mysql -e "CREATE DATABASE repro_development" sudo mysql -e "CREATE DATABASE repro_test" sudo mysql mysql -e "ALTER USER 'root'@'localhost' IDENTIFIED BY '';" rails db:migrate ```

application_dripper.rb

#### `app/drippers/application_dripper.rb` ```ruby # frozen_string_literal: true class ApplicationDripper < ::Caffeinate::Dripper::Base def self.process_unsubscribes(_drip,mailing) puts "Calling process_unsubscribes..." user = mailing.user user.before_drip_run_counter = user.before_drip_run_counter.to_i + 1 user.save end end ```

test_dripper.rb

### `app/drippers/test_dripper.rb` ```ruby class TestDripper < ApplicationDripper self.campaign = :test before_drip do |_drip, mailing| process_unsubscribes(_drip, mailing) end drip :first_reminder, action_class: 'TestAction', delay: 0.seconds drip :second_reminder, action_class: 'TestAction', delay: 1.seconds end ```

test_action.rb

### `app/actions/test_action.rb` ```ruby class TestAction < Caffeinate::ActionProxy def first_reminder(mailing) puts("Running first_reminder") end def second_reminder(mailing) puts("Running second_reminder") end end ```

caffeinate_test.rb

### `test/integration/caffeinate_test.rb` ```ruby require "test_helper" class CaffeinateTest < ActionDispatch::IntegrationTest test "foo" do campaign = Caffeinate::Campaign.find_or_create_by!(name: "Test", slug: "test") user = User.create!(name: "foo", email: "foo@foo") subscriber = Subscriber.create!(name: "bar", email: "bar@bar") assert Caffeinate::CampaignSubscription.count == 0 campaign.subscribe(subscriber, user: user) assert user.before_drip_run_counter.to_i == 0 TestDripper.perform! user.reload assert user.before_drip_run_counter == 1 sleep 1.seconds TestDripper.perform! user.reload assert user.before_drip_run_counter == 2 end test "foo-bar" do campaign = Caffeinate::Campaign.find_or_create_by!(name: "Test", slug: "test") user = User.create!(name: "bar", email: "bar@bar") subscriber = Subscriber.create!(name: "foo", email: "foo@foo") campaign.subscribe(subscriber, user: user) assert user.before_drip_run_counter.to_i == 0 TestDripper.perform! user.reload assert user.before_drip_run_counter == 1 sleep 1.seconds TestDripper.perform! user.reload assert user.before_drip_run_counter == 2 end end ```

If you run the above, but do not specify -d mysql (using the default sqlite3), then it will work fine.

But if you run it with mysql, it will fail.

test foo and test foo-bar should be equivalent, producing equivalent output, but running: bin/rails test you will get:

test output for mysql version

``` ubuntu-22-04% bin/rails test Running 2 tests in a single process (parallelization threshold is 50) Run options: --seed 48614 # Running: Calling process_unsubscribes... Running first_reminder Calling process_unsubscribes... Running second_reminder .F Failure: CaffeinateTest#test_foo [repro/test/integration/caffeinate_test.rb:14]: Expected false to be truthy. rails test test/integration/caffeinate_test.rb:4 ```

When you run the same thing under sqlite3 though, the test passes as you would expect.

create the sqlite3 version of the same app

```shell rails new --minimal repro2 cd repro2 bin/bundle add caffeinate awesome_print table_print rails g caffeinate:install rails g model User name email before_drip_run_counter:integer rails g model Subscriber name email rails db:migrate ```

test output for sqlite3 version

``` ubuntu-22-04% bin/rails test Running 2 tests in a single process (parallelization threshold is 50) Run options: --seed 50242 # Running: Calling process_unsubscribes... Running first_reminder Calling process_unsubscribes... Running second_reminder .Calling process_unsubscribes... Running first_reminder Calling process_unsubscribes... Running second_reminder . Finished in 2.118785s, 0.9439 runs/s, 3.3038 assertions/s. 2 runs, 7 assertions, 0 failures, 0 errors, 0 skips ```

---

One other issue that I also see when using MySQL but not when using sqlite3...

If we call subscribe as:

    TestDripper.subscribe(subscriber, user: user)

Instead of:

    campaign.subscribe(subscriber, user: user)

In the second test that calls TestDripper.subscribe it will return with:

Error:
CaffeinateTest#test_foo-bar:
NoMethodError: undefined method `to_dripper' for nil:NilClass
    test/integration/caffeinate_test.rb:31:in `block in <class:CaffeinateTest>'

When I run the same using sqlite3 it works fine...

Reproducing second issue...

Use the same content for application_dripper.rb, test_dripper.rb and test_action.rb.

Alternate version of caffeinate_test.rb

```ruby require "test_helper" class CaffeinateTest < ActionDispatch::IntegrationTest test "foo" do campaign = Caffeinate::Campaign.find_or_create_by!(name: "Test", slug: "test") user = User.create!(name: "foo", email: "foo@foo") subscriber = Subscriber.create!(name: "bar", email: "bar@bar") assert Caffeinate::CampaignSubscription.count == 0 campaign.subscribe(subscriber, user: user) assert user.before_drip_run_counter.to_i == 0 TestDripper.perform! user.reload assert user.before_drip_run_counter == 1 sleep 1.seconds TestDripper.perform! user.reload assert user.before_drip_run_counter == 2 end test "foo-bar" do campaign = Caffeinate::Campaign.find_or_create_by!(name: "Test", slug: "test") user = User.create!(name: "bar", email: "bar@bar") subscriber = Subscriber.create!(name: "foo", email: "foo@foo") ######################################################## # Here we're calling it as TestDripper.subscribe # rather than campaign.subscribe TestDripper.subscribe(subscriber, user: user) ######################################################## assert user.before_drip_run_counter.to_i == 0 TestDripper.perform! user.reload assert user.before_drip_run_counter == 1 sleep 1.seconds TestDripper.perform! user.reload assert user.before_drip_run_counter == 2 end end ```

output when running under sqlite3

``` ubuntu-22-04% bin/rails test Running 2 tests in a single process (parallelization threshold is 50) Run options: --seed 64571 # Running: Calling process_unsubscribes... Running first_reminder Calling process_unsubscribes... Running second_reminder .Calling process_unsubscribes... Running first_reminder Calling process_unsubscribes... Running second_reminder . Finished in 2.134845s, 0.9368 runs/s, 3.2789 assertions/s. 2 runs, 7 assertions, 0 failures, 0 errors, 0 skips ```

test output when running under mysql

``` ubuntu-22-04% bin/rails test Running 2 tests in a single process (parallelization threshold is 50) Run options: --seed 58143 # Running: Calling process_unsubscribes... Running first_reminder Calling process_unsubscribes... Running second_reminder .F Failure: CaffeinateTest#test_foo [/home/erwin/Dev/os.cash/repro/test/integration/caffeinate_test.rb:14]: Expected false to be truthy. rails test test/integration/caffeinate_test.rb:4 Finished in 1.112693s, 1.7974 runs/s, 5.3923 assertions/s. 2 runs, 6 assertions, 1 failures, 0 errors, 0 skips ```

Hopefully you made it this far... That's an awful lot to digest. It's been quite a challenge trying to trace exactly what is happening. Hopefully you've got some ideas on how we can patch caffeinate to get these test to pass, or if I'm just misunderstanding something basic and using caffeinate incorrectly.

Thank you.

[jon-sully]

Wow, you've put a ton of work into this issue before posting, and we super appreciate that. Than you for all the info!

You've actually stumbled upon something I patched in my company's app before I became a contributor to this project directly and I forgot to ever bring up. That's a bummer 🙁. While my usage of Caffeinate on the 'application' side of our application is fine (we only ever call perform! in background jobs in a way that causes no problems), I discovered this issue in the testing side of our app. The campaign value itself is memoized. This does cause issues in line with what you've described, I think. Here's what I did to patch our testing suite:

  config.before(:each) do
    # NOTE: Caffeinate maintains a couple of class-variables under the hood
    # that don't get reset between specs (while the db records they cache do
    # get truncated). This resets the appropriate class-variables between specs

    # NOTE: Caffeinate.dripper_collection gives us all the drippers in the project
    Caffeinate.dripper_collection.instance_variable_get(:@registry).values.each do |drppr|
      drppr.safe_constantize.class_eval { @caffeinate_campaign = nil }
    end
  end

🤔

[erwin]

Thank you!

That fixed it.

  setup do
    Caffeinate.dripper_collection.instance_variable_get(:@registry).values.each do |drppr|
      drppr.safe_constantize.class_eval { @caffeinate_campaign = nil }
    end
  end

Updated working source of caffeinate_test.rb

```ruby require "test_helper" class CaffeinateTest < ActionDispatch::IntegrationTest # See: https://github.com/joshmn/caffeinate/issues/39 # NOTE: Caffeinate maintains a couple of class-variables under the hood # that don't get reset between specs (while the db records they cache do # get truncated). This resets the appropriate class-variables between specs # NOTE: Caffeinate.dripper_collection gives us all the drippers in the project setup do Caffeinate.dripper_collection.instance_variable_get(:@registry).values.each do |drppr| drppr.safe_constantize.class_eval { @caffeinate_campaign = nil } end end test "foo" do campaign = Caffeinate::Campaign.find_or_create_by!(name: "Test", slug: "test") user = User.create!(name: "foo", email: "foo@foo") subscriber = Subscriber.create!(name: "bar", email: "bar@bar") assert Caffeinate::CampaignSubscription.count == 0 campaign.subscribe(subscriber, user: user) assert user.before_drip_run_counter.to_i == 0 TestDripper.perform! user.reload assert user.before_drip_run_counter == 1 sleep 1.seconds TestDripper.perform! user.reload assert user.before_drip_run_counter == 2 end test "foo-bar" do campaign = Caffeinate::Campaign.find_or_create_by!(name: "Test", slug: "test") user = User.create!(name: "bar", email: "bar@bar") subscriber = Subscriber.create!(name: "foo", email: "foo@foo") ######################################################## # Here we're calling it as TestDripper.subscribe # rather than campaign.subscribe TestDripper.subscribe(subscriber, user: user) ######################################################## assert user.before_drip_run_counter.to_i == 0 TestDripper.perform! user.reload assert user.before_drip_run_counter == 1 sleep 1.seconds TestDripper.perform! user.reload assert user.before_drip_run_counter == 2 end end ```

[joshmn]

@jon-sully thank you!

@erwin the campaigns are indeed memoized. I have actually shot myself in the foot with this before too 😬

@jon-sully what do you think about Caffeinate.test_mode! or something? I'll make a push to readme at some point with this as a disclaimer because it is, in fact, annoying and surprising (in test).

[jon-sully]

Yeah I think having a small macro like that and an explanation in the readme is a good way to go. That's pretty close to how Sidekiq does it, which I think is good

[joshmn]

Added a convenience method called Caffeinate.dripper_collection.clear_cache! in 2.5 that handles this. Closing, and thank you again!