PaperTrail Behaving Oddly in testing

[rposborne]

I have implemented Ryan Bates Undo with papertrail http://railscasts.com/episodes/255-undo-with-paper-trail a long time ago, and wrote some simple tests on it. Since upgrading from 3.0.0beta1 to 3.0.0 these tests are now failing and I am stumped.

It looks like @version.next is returning nil. Even though Papertrail is enabled.

Tests are Rspec. Helpers are manually included (running zeus), Ruby 2.1.0

below is code for one of the failing specs.

  describe "POST revert", :versioning => true  do
    describe "with more than one version" do
      it "reverts to the last version" do
        slip = create(:slip)
        slip.update_attributes!(:hours => 12)
        slip.update_attributes!(:hours => 11)
        slip.should be_versioned
        post :revert, {id: slip.versions.first.id }
        slip.reload.hours.should eq 12
      end
    end
end

and the controller

class VersionsController < ApplicationController
  def revert
    @version = PaperTrail::Version.find(params[:id])
    if @version.reify
      @version.reify.save!
    else
      @version.item.destroy
    end
    link_name = params[:redo] == "true" ? "undo" : "redo"
    link = view_context.link_to(link_name, revert_version_path(@version.next, :redo => !params[:redo]), :method => :post)
    redirect_to :back, :notice => "Undid #{@version.event}. #{link}"
  end
end

Edit adding controller code

[batter]

Please see the special section of the README pertaining to using the RSpec helper for PaperTrail with Zeus. If this doesn't fix the issue, let me know and I'll try to take a closer look.

[rposborne]

@batter I appreciate you looking at this. I didn't post this lightly, I re read the readme multiple times include the section on zeus. And added the explicit require call for the new embed helpers (and removing our previous ones). The tests fail with zeus running and no zeus, as well as against our ci server doing a normal rake test call.

PaperTrail is enabled, I have multiple versions by the end of the call, just the next function returns nil. 1 create 2 edits, 1 for the reify.

[rposborne]

More insight.

Pulling the raw sql it's easy to see what's going on.

SELECT `versions`.* FROM `versions`  WHERE `versions`.`item_type` = 'Slip' AND `versions`.`item_id` = 1 AND (versions.created_at > '2014-01-08 21:02:45')  ORDER BY versions.created_at ASC

Below are the timestamps for all the versions in the system.
2014-01-08 21:02:45 -0500
2014-01-08 21:02:45 -0500
2014-01-08 21:02:45 -0500
2014-01-08 21:02:45 -0500

Clearly the sql above won't pull any of those versions.

[rposborne]

I concur on the closing

The bottom of the rabbit hole.
rails/rails#8240

[batter]

@rposborne - My apologies, wasn't sure if your comment of "Helpers are manually included (running zeus)" meant that you had heeded to that. Ok, after thinking about this closely, the reason it works with 3.0.0.beta1 but not 3.0.0, is likely 6a4aba2, but to understand the reasoning behind it, you need to take a look at #235. It was always assumed that theoretically that secondary sort on the primary key should've been unecessary, and furthermore, could actually mess some users up if they were using UUID's without an auto-incrementing ID for a table's primary key that they wanted to attach PaperTrail to. Hmm, now I'm not sure what to do about this. Do you also see this if you run the test without Zeus?

[rposborne]

I agree with the removal of the primary key removal. But the issue is if you are running on a DB that does not support higher resolution timestamps you can easily have something like this happen. Most likely this will happen more frequently in testing as it's more likely to create versions back to back.

This is not a PaperTrail issue directly but the changes introduced in 6a4aba2 make it much more likely to suffer from versions having the exact same created_at time (in DB).

I am not really sure on a solution for this without hacking things up. Maybe allowing a configurable field in the query? Or changing the subsequent call to include >= and not ask for the first record but the second? Not sure on the implications of that one though.

But yes we see this on multiple machines Zeus + No Zeus and in Jenkins CI. Anything hitting a DB that does not have millisecond support.

[dwbutler]

We've used timecop in the past to workaround duplicate timestamps in tests. (This was mongodb rather than mysql). I'm having the same issue here so I'll probably do the same thing.

[rposborne]

I am familiar with timecop (great tool) but it seems a bit overkill to bring it in. As it is technically a real issue (not just in tests) It is simply more likely to occur in tests due to the nature of them.

[dwbutler]

I agree this a real issue, not just in tests. I'm not entirely clear why Paper Trail moved away from simply sorting on the primary key column. Perhaps it should revert back to that implementation and only sort by timestamp if the primary key isn't defined?

[willkoehler]

I've run into the same problem in my tests. This thread was really helpful in sorting out what was going on. Thanks for everyone's input.

In terms of a solution, it doesn't look like we can rely on microsecond precision in timestamps (rails/rails#8240) because that's still in the preliminary stages and requires MySQL 5.6. So unfortunately it looks like backing out 6a4aba2 is the only solution. Without a secondary sort on the primary key, there will be a race condition. The race condition mostly manifests itself in tests. But, as @rposborne pointed out, there's nothing stopping this from happening in production.

In the meantime I've added sleep calls to my tests. The sleep needs to be 1 second to ensure the version timestamp is different, which results in really slow tests. For example:

it "should be successful for previous version of a contract" do
  contract = create(:contract, :system => @current_system, :created_by_id => @current_user.id)
  sleep 1        # needed until https://github.com/airblade/paper_trail/issues/314 is resolved
  contract.update_attribute(:title, "New Title")                      # create another contract version
  get :show, :id => contract, :version_id => contract.versions.last   # request the original contract version
  response.status.should be(200)
  assigns(:contract).should == contract
  assigns(:contract).title.should == "Test Contract"
end

[dwbutler]

@willkoehler Look into using timecop instead of sleep. It results in different timestamps without the slowdowns.

[willkoehler]

@dwbutler Thanks for the tip. That's a better solution than my sleep call. But most likely I'll roll back to v2.7.2 until I can find a better long-term solution. I'm also seeing issues with the fake data I generate for development and I'm concerned about race conditions in the production systems.

After reviewing all the related issues and commits, I can see how this issue is tangled up with some other really tricky problems. Maybe pressing forward to require high-resolution time-stamps is the only long-term fix.

With that in mind can anyone give me advice on what's required to enable high-resolution timestamps in a Rails app? I didn't think that rails/rails#8240 had been merged yet. But looking at some of the related issues I see log messages with high-resolution timestamps in the log messages, so it must be working somewhere. Thanks.

[batter]

@dwbutler - I agree, that it may make sense to sort by the primary key by default and revert to the timestamp as the primary sort column if no primary is available. I moved away from it due to discussions that stemmed from #235 and #177. The idea was to try to make the gem more compatible with all apps out of the box, including those that use UUID's instead of auto-incrementing integers. Think it may make sense to revert to using primary keys if available by default...

[dwbutler]

@batter - It might make sense to have an (optional) autoincrementing version number. This would be the autoincrementing primary key if available, or perhaps a different column (configurable). Without the version number, it would default to using the timestamp as a version "number".

[rposborne]

Looks like mysql fractional seconds has been merged in. rails/rails#14359

[batter]

So are we thinking it makes sense to add the autoincrementing ID / version number as a sorted key? Not sure what the best course of action is here. If someone wants to make a Pull Request that would be welcome. I'm trying to release 3.0.1 shortly but would be happy to try to sneak a solution that accommodates this issue in prior.

[dwbutler]

Fractional second support doesn't help anyone on older versions of Rails or mysql. So I vote for the autoincrementing version number solution.

[batter]

@rposborne - I just looked a little more closely at your failing spec, and it would fail regardless of whether the timestamp was being listed properly. Unless you have PaperTrail setup not to track create events.

Can you share what args your has_paper_trail method call takes on your Slip model?

If it looks like this, then you need to change your test accordingly (due to the fact that create actions ARE tracked by default):

class Slip < ActiveRecord::Base
  has_paper_trail
end

describe "POST revert", :versioning => true  do
  describe "with more than one version" do
    it "reverts to the last version" do
      slip = create(:slip)
      slip.update_attributes!(:hours => 12)
      # this is the state you want to revert to, so this is the version id you must pass in
      version_id = slip.versions.last.id
      slip.update_attributes!(:hours => 11)
      slip.should be_versioned
      post :revert, {id: version_id }
      slip.reload.hours.should eq 12
    end
  end
end

Are you absolutely certain this test is failing due to timestamp comparison issues or is the test constructed in a manner that would fail to begin with?

Can someone provide a failing spec or test that I can work with here to ensure that I'm making changes that will address the issue?

[rposborne]

@batter Yes you are correct the last line saying calling the first revision would only work if the factory was also setting hours to 12. Below is the current test I have in my specs which swaps out first for the last revision.

    describe "with more than one version" do
      it "reverts to the latest version" do
        pending "Github issue https://github.com/airblade/paper_trail/issues/314"
        slip = create(:slip)
        slip.update_attributes!(:hours => 12)
        slip.update_attributes!(:hours => 11)

        slip.should be_versioned
        post :revert, {id: slip.versions.reload.last.id }
        slip.reload.hours.should eq 12
      end
    end

[batter]

And it still fails consistently? (with the pending line removed / commented out)

[willkoehler]

@batter I have a spec that fails in 3.0.0 due to the change in sorting. The spec passes in 2.7.2. See my comment #314 (comment). In 3.0.0 the spec fails without the sleep call. The message is

 Failure/Error: assigns(:contract).title.should == "Test Contract"
   expected: "Test Contract"
        got: "New Title" (using ==)

I can provide more context or try to put together something you can run if needed.

[batter]

@willkoehler - I'm trying to put together a failing spec that I can put in the gem repository to work against when trying to fix this issue. If I don't have a spec that fails consistently it's a little more difficult to try to fix (and also difficult to prove that any change does actually fix the issue). Pull requests or even gists would be much appreciated!

[rposborne]

@batter Yes it does fail consistently.

Mainly do the to the @version.next call which is returning nil as all of the versions have the same timestamp.

[willkoehler]

@batter I might be able to add a failing spec to the gem. I just pulled down the latest into my fork. Can you point me to a good location to add the test? The basic flow will be

• create a model
• change the model
• navigate the model version with .next, .last (or something) and show it fails because the sort order is wrong because all the version timestamps are the same.

I just realized the test will probably be DB dependent. I haven't work with specs in a gem before so I don't know if you even have access to a DB for the models?

[batter]

@willkoehler - @rposborne was generous enough to make PR #344. Still need to get it working, but that should get us pointed in the right direction!

[willkoehler]

@batter @rposborne nice! Let me know if you need any help, but it looks like you've got a handle on it.

[rposborne]

@batter Alright, so we are now setup to test against pg and mysql. And we can now clearly see the impact of the 6a4aba2 on mysql. (Really broken)

I think we have a few options.

1. Implement a nanosecond col for mysql
2. Implement a PaperTrail::Version.sort_field (defaults to timestamp field, change to ID for basic mysql support)

I would hate to revert the scalable solution that is in the system now for legacy support.

[willkoehler]

@batter @rposborne glad you are able to reproduce the problem now.

This may be an edge case, but a problem with option 1 is that it will not be possible to update existing version records with the nanosecond data. So if there are version records with identical timestamps, they will not be sorted correctly. Option 1 only works for new version records.

One case were this will be a problem is in my populated data. Since the populate task runs quickly, many of the version records have the same timestamp.

[rposborne]

@willkoehler yes i am certainly leaning towards the sort field which basically replaces the timestamp field in all instances except lookback.

[batter]

I agree, it seems like an auto-incrementing sort field is probably the best solution for the time being. Do we think using the primary key ID field is a bad idea? The InstallGenerator currently provides a migration with an auto-incrementing ID but I'm guessing there are certain gems / plugins you can hook up to ActiveRecord to make it so that is not the case by default, so do we think it makes sense to add a different field specifically for that purpose to the versions table?

[rposborne]

@batter Not suggesting a new field in the db, Just a config option to tell which field to use. Similar to the PaperTrail::Version.timestamp_field.

I think ID will meet 99% of the implementations.

[batter]

@rposborne - When you get a free moment, can you clone down the branch I pushed up yesterday (order_by_primary_key) and give that a try with your test suite and see if that fixes some or any of your issues. Trying to figure out if I'm on the right track here. I see that the tests are still failing in MySQL but I don't think it's entirely due to the timestamp issues..

[rposborne]

Sure thing. The branch looks pretty good. I added a couple notes / questions for your consideration.

[rposborne]

@batter So my specs pass running against this branch. Maybe drop the travis ci allowed exclusions for mysql?

[batter]

Well the issue is that the MySQL specs are all still failing. I have a feeling this may be related to the fact that when using transactions in MySQL, auto-incrementing ID numbers do not get reverted back to their previous state prior to the initialization of the transaction. I'll see if I can take a closer look today or tomorrow, been really busy lately 😒

[batter]

@rposborne - I've manage to get all MySQL specs passing on my order_by_primary_key branch. The ActiveSupport::TestCase test's continue to fail, and I've figured out why. ActiveSupport::TestCase apparently doesn't know how to properly do transactional fixtures (i.e. resetting the db after every test) properly in conjunction with MySQL. I don't work with ActiveSupport::TestCase much outside of this gem, as RSpec is my goto testing tool. Not sure what the best approach to fix this is... If I had my way, I'd rather see all of the tests converted into specs, however, many of the tests aren't even great tests to begin with, so it would likely also be logical to refactor a bunch of them, which would be a time consuming process. At any rate, it's nice to know that the specs are passing which seems to insinuate that branch functions properly with MySQL... Think I might merge it and try to make it part of 3.0.2 and get some feedback from the community on this.

[rposborne]

Is the db rollback issue something that could be solved by https://github.com/bmabey/database_cleaner. Maybe I'll take a swing. I do like rspec but not sure if the cost benefit ratio is skewed in it's favor.

All and all I do greatly appreciate your work on this.

[dwbutler]

Definitely, you just choose the truncation strategy rather than the transactional strategy.

On Apr 30, 2014, at 4:59 PM, rposborne [email protected] wrote:

Is the db rollback issue something that could be solved by https://github.com/bmabey/database_cleaner. Maybe I'll take a swing. I do like rspec but not sure if the cost benefit ratio is skewed in it's favor.

All and all I do greatly appreciate your work on this.

—
Reply to this email directly or view it on GitHub.

[rposborne]

Thanks @batter

[batter]

Thanks for the tip on DatabaseCleaner usage @dwbutler, it's annoying that RSpec knows how to properly use transactional specs but ActiveSupport::TestCase needs that gem in order to do it properly. Oh well.

Also thanks a lot to all who contributed on this one, especially @rposborne! I plan on releasing 3.0.2 later today assuming nobody finds any issues.

[willkoehler]

Awesome. Thanks to everyone that contributed to this fix!