Querying for PaperTrail::Version in tests despite PaperTrail being disabled

[gracjan-grala]

Hello,
I have a Rails application with PaperTrail disabled in config/environment/test.rb:

config.after_initialize do
  PaperTrail.enabled = false
  PaperTrail.enabled_for_controller = false
end

As expected, this stops _Version_s being created in test environment, but when I look at test.log there's still plenty of PaperTrail::Version Loads on model creation.

I benchmarked my test suite speed before and after removing all has_paper_trails from my app, and the improvement is quite significant.

With has_paper_trail (median of 3):

real 1m54.697s
user 1m33.708s
sys 0m2.536s

Without (median of 3):

real 1m11.597s
user 0m54.632s
sys 0m1.768s

I assume there is currently no setting to disable PaperTrail entirely in test environment, but could it be implemented?

[jaredbeck]

As expected, this stops Versions being created in test environment, but when I look at test.log there's still plenty of PaperTrail::Version Loads on model creation.

Hi Gracjan. Were you able to determine why? Perhaps your test suite explicitly loads versions. Can you reproduce this using our bug report template?

I assume there is currently no setting to disable PaperTrail entirely in test environment ..

Well, that's what PaperTrail.enabled= is supposed to do. This is actively being discussed in a number of open issues right now.

[gracjan-grala]

Hello @jaredbeck. Thank you for your response.
I dug into the logs some more and the Version loads occur on transaction rollbacks.
I use database_cleaner in my tests with :transaction strategy, so the changes to DB are rolled back after each test.

I simulated this behaviour in a bug report template and it behaves exactly the same.

It outputs the following:

[2016-03-02T14:13:52.745732 #76911] DEBUG -- :    (0.1ms)  begin transaction
[2016-03-02T14:13:52.748896 #76911] DEBUG -- :    (0.1ms)  SELECT COUNT(*) FROM "versions"
[2016-03-02T14:13:52.760405 #76911] DEBUG -- :    (0.2ms)  SAVEPOINT active_record_1
[2016-03-02T14:13:52.766969 #76911] DEBUG -- :   SQL (0.7ms)  INSERT INTO "users" ("first_name", "created_at", "updated_at") VALUES (?, ?, ?)  [["first_name", "Jane"], ["created_at", "2016-03-02 13:13:52.762840"], ["updated_at", "2016-03-02 13:13:52.762840"]]
[2016-03-02T14:13:52.770572 #76911] DEBUG -- :    (0.5ms)  RELEASE SAVEPOINT active_record_1
[2016-03-02T14:13:52.771474 #76911] DEBUG -- :    (0.1ms)  SELECT COUNT(*) FROM "versions"
[2016-03-02T14:13:52.771725 #76911] DEBUG -- :    (0.1ms)  rollback transaction
[2016-03-02T14:13:52.787963 #76911] DEBUG -- :   PaperTrail::Version Load (0.2ms)  SELECT "versions".* FROM "versions" WHERE "versions"."item_id" = ? AND "versions"."item_type" = ?  ORDER BY "versions"."created_at" ASC, "versions"."id" ASC  [["item_id", 1], ["item_type", "User"]]
.

Finished in 0.046459s, 21.5242 runs/s, 21.5242 assertions/s.

1 runs, 1 assertions, 0 failures, 0 errors, 0 skips

As you can see, the PaperTrail::Version Load is triggered after (or during) the rollback.
Do you know where it comes from?

[jaredbeck]

I simulated this behaviour in a bug report template ..

Thanks! That's very helpful.

As you can see, the PaperTrail::Version Load is triggered after (or during) the rollback. Do you know where it comes from?

Looks like there is a after_rollback callback named clear_rolled_back_versions:

      # Invoked after rollbacks to ensure versions records are not created
      # for changes that never actually took place
      def clear_rolled_back_versions
        send(self.class.versions_association_name).reload
      end

Basically, it's eagerly reloading the versions association. Maybe there's a way we could lazily reload instead?

[jaredbeck]

Maybe there's a way we could lazily reload instead?

Looks like ::ActiveRecord::Associations::CollectionProxy#reset might work.