jessica dussault

Following a PaperTrail of intermittently failing tests

Date
14 May, 2025
Category
code
Tags
Ruby on Rails

A few weeks ago, I started a new job at Unabridged, a Ruby on Rails shop. It has been a number of years since I worked with Rails but I still reach for Ruby when I need to write a small script, so it has been nice getting back into the Rails swing of things.

I was given an easy first task: add auditing to a model to keep track of how and when records are changed, and by whom. The application already had PaperTrail installed and tracking several models. All I needed to do was add a single line to track changes to "students":

# app/models/student.rb

class Student < ApplicationRecord
  has_paper_trail
end

Easy enough! I tested out creating and updating records in the console a few times and I could see that the versioning was working. Although I nearly didn't, fearing it was a bit overkill, I decided to add a couple tests:

# test/models/student_test.rb

require "test_helper"

class StudentTest < ActiveSupport::TestCase
  describe "has_paper_trail" do
    subject { Fabricate(:student) }

    describe "new records" do
      it "should have one version with type create" do
        assert_equal 1, subject.versions.length
        assert_equal "create", subject.versions.last.event
      end
    end

    describe "updated records" do
      it "should have multiple versions" do
        subject.update(name_first: "Updated") )

        assert_equal 2, subject.versions.length
        assert_equal "update", subject.versions.last.event
      end
    end
  end
end

The problem

The tests passed as expected. A few minutes later, I ran the tests again before committing. This time, one of the tests failed? Kind of weird. I ran the tests repeatedly and found that sometimes they failed, sometimes they didn't. Usually I was seeing the following:

  Failure:
StudentTest::has_paper_trail::updated records#test_0001_should have multiple versions [test/models/student_test.rb:74]:
Expected: 2
  Actual: 4

What was going on??

I read through the PaperTrail documentation trying to find something obvious. Did it have any async behavior? No. Was I using .versions correctly? Seemed like it. I looked at the internal PaperTrail tests to see if they had set up anything I missed to check versions and nothing stood out. I tried disabling PaperTrail test-wide, re-enabling it for only my two tests, and then disabling it again, in case other tests altering students were impacting my new tests, but no dice.

I had a small breakthrough when I added identical tests to models that were already being tracked with PaperTrail and found that those tests passed every time. That meant it was something specific to the Student model.

I paired with my new coworker, Drew, who suggested setting the random seed for the tests so that we could at least replicate the failure reliably.

bin/rails test test/models/student_test.rb --seed 31139

To our surprise, the intermittent nature of the failures continued! Fortunately, Drew had an idea.

A combination of UUIDs and bigints

PaperTrail uses a single table in your database to store information about all of your tracked records. It has a field, :item_id which holds the id of your record. This, in combination with another field :item_type, can be used to find the record in question. When you first add PaperTrail to your app, you run a generator which allows you to specify whether your tables use integer or UUID primary keys. If you specify --uuid, the :item_id field will be a string. Otherwise, it's a bigint.

So here's the problem -- while most of our database tables used bigint primary keys, the student table used uuids. Therefore, anytime I altered a student record, PaperTrail would take the UUID in student.id and shove it into a bigint. Let's see what happens when we do that:

> "c54e8878-b9a1-40d9-a41d-3f5b248c0d19".to_i
=> 0
> "fd270cda-014a-4fbc-96ba-6b5dc69e78f0".to_i
=> 0
> "378c0d02-f8e8-4a66-94c1-4229c457b666".to_i
=> 378
> "004d6d27-2fb1-474e-99f9-3cf7725e0050".to_i
=> 4

If a UUID starts with a number, Ruby will take whatever it can off the front and call it good enough. Furthermore, UUIDs are "universally unique" identifiers, and clearly, the random seeds for tests aren't involved with their creation. So on one run, the two tests might come up with UUIDs that map to 0, therefore one test will find too many paper trail versions, but on the next run they might map to different numbers and the tests would appear to pass.

The solution

We decided the best option was to migrate the student id field to use bigint rather than a uuid type. This meant my 2 minute PR actually became more like a 3 day labor to write not only table migrations but a data migration to update all the tables associated with Student via its primary key.

That may need to be its own post, because it turns out changing primary keys when many other tables rely on them is kind of a whole thing!

A further embarrassment

Cut to a few days in the future. I've learned a valuable lesson about Ruby and the next time UUID to integer conversion comes up I will remember how Ruby handles it, right? Obviously!

Well anyhow, we wanted to make sure that any users who had bookmarked a student's page with the original UUID id in the URL will be able to use that link without any disruption caused by us changing the id field. I added the following to the controller so that if an id lookup failed, it would try finding the student by the new field, student.uuid, which stores the legacy id information in it for cases like this:

# app/controllers/student_controller.rb

def student
  ...

  begin
    students.find(id)
  rescue ActiveRecord::RecordNotFound
    # old links may still be using the original student uuid
    students.find_by!(uuid: id)
  end
end

I added tests to make sure that you can use either an id or a UUID to find a student and things were looking good:

# test/controllers/student_controller_test.rb

it "should get edit" do
  get :edit, params: { id: student.id }
  assert_response :success
end

it "should get edit when a uuid is passed as an id" do
  get :edit, params: { id: student.uuid }
  assert_response :success
end

Unfortunately, I had failed to think about how if a student's UUID starts with a number, Rails doesn't fail to find a matching id. Instead, it pulls a record for whatever number it gleans out of the UUID. Who could have possibly predicted this would happen?

Anyway, fool me twice...and hopefully I'll remember in the future after being burned multiple times in the same week. Here's how the controller looks now:

# app/controllers/student_controller.rb

def student
  ...
  # if id is not composed entirely of integers, look for the previous id (now uuid)
  /^\d+$/.match?(id) ? students.find(id) : students.find_by!(uuid: id)
end