Mysteriously Truncated Timestamps in Rails

Tests are supposed to help keep apps from being flaky. But once in a while, tests themselves can become flaky—even the most straightforward ones. Here’s how we dove into a problematic test on a Ruby on Rails app backed by PostgreSQL, and what we uncovered.

We wanted to check that certain business logic (called by a method perform) doesn’t change a calendar model (an instance of Calendar, a Ruby on Rails ActiveRecord model class) so we wrote:

let(:calendar) { create(:calendar) }
specify do
  expect do
    perform # call the business action
    calendar.reload
  end
    .not_to change(calendar, :attributes)
end

This was passing in one development environment (MacOS), but it was almost always failing in CI (Linux).

Fortunately, we managed to reproduce it on another development environment (Linux), where it failed with a message:

expected `Calendar#attributes` not to have changed, but did change from {"calendar_auth_id"=>8,
"created_at"=>2020-01-02 13:36:22.459149334 +0000, "enabled"=>false, "events_...t_sync_token"=>nil,
"title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149334 +0000, "user_id"=>100} to {
"calendar_auth_id"=>8, "created_at"=>2020-01-02 13:36:22.459149000 +0000, "enabled"=>false,
"events_...t_sync_token"=>nil, "title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149000 +0000, "user_id"=>100}

See something fishy?

The Investigation

On closer examination, we noticed that the created_at and updated_at timestamps were changed slightly inside the expect block:

{"created_at"=>2020-01-02 13:36:22.459149334 +0000, "updated_at"=>2020-01-02 13:36:22.459149334 +0000}
{"created_at"=>2020-01-02 13:36:22.459149000 +0000, "updated_at"=>2020-01-02 13:36:22.459149000 +0000}

The seconds’ fractional part was truncated so that 13:36:22.459149334 became 13:36:22.459149000.

We were confident that perform wasn’t updating the calendar object, so we formed a hypothesis that the timestamps were being truncated by the database. To test this, we used the most advanced debugging technique known, i.e., puts debugging:

let(:calendar) { create(:calendar) }
specify do
  expect do
    puts "before perform: #{calendar.created_at.to_f}"
    perform
    puts "after perform: #{calendar.created_at.to_f}"
    calendar.reload
    puts "after reload: #{calendar.created_at.to_f}"
  end
    .not_to change(calendar, :attributes)
end

But the truncation wasn’t visible in the output:

before perform: 1577983568.550754
after perform: 1577983568.550754
after reload: 1577983568.550754

This was quite surprising—the accessor #created_at should have had the same value as the attribute hash value of attributes['created_at']. To be sure we were printing the same value used in the assertion, we changed the way we accessed created_at.

Instead of using the accessor calendar.created_at.to_f, we switched to fetching it from the attributes hash directly: calendar.attributes['created_at'].to_f. Our suspicions toward calendar.reload were confirmed!

before perform: 1577985089.0547702
after perform: 1577985089.0547702
after reload: 1577985089.05477

As you can see, calling perform didn’t change created_at, but reload did.

#ruby on rails

The Investigation

toptal.com

Mysteriously Truncated Timestamps in Rails