Timestamp Truncation: A Ruby on Rails ActiveRecord Tale

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.

To ensure the change was not happening on another instance of calendar and then being saved, we performed one more experiment. We reloaded calendar before the test:

let(:calendar) { create(:calendar).reload }
specify do
  expect do
    perform
    calendar.reload
  end
    .not_to change(calendar, :attributes)
end

That made the test green.

The Fix

Knowing that it’s the database that truncates our timestamps and fails our tests, we decided to prevent the truncation from happening. We generated a DateTime object and rounded it to whole seconds. Then, we used this object to set Rails’ Active Record timestamps explicitly. This change fixed and stabilized the tests:

let(:time) { 1.day.ago.round }
let(:calendar) { create(:calendar, created_at: time, updated_at: time) }

specify do
  expect do
    perform
    calendar.reload
  end
    .not_to change(calendar, :attributes)
end

The Cause

Why did this happen? Active Record timestamps are set by the Rails’ ActiveRecord::Timestamp module using Time.now. Time precision is OS-dependent, and as the docs state, may include fractional seconds.

We tested Time.now resolution on MacOS and Linux with a script that counts frequencies of fractional part lengths:

pry> 10000.times.map { Time.now.to_f.to_s.match(/\.(\d+)/)[1].size }.group_by{|a| a}.map{|k, v| [k, v.count]}.to_h

# MacOS => {6=>6581, 7=>2682, 5=>662, 4=>67, 3=>7, 2=>1}
# Linux => {6=>2399, 7=>7300, 5=>266, 4=>32, 3=>3}

As you can see, about 70% of timestamps on Linux had seven digits of precision after the decimal, while on MacOS only 25% did. This is the reason the tests passed most of the time on MacOS and failed most of the time on Linux. You may have noticed that the test output had nine-digit precision—that’s because RSpec uses Time#nsec to format time output.

When Rails models are saved to the database, any timestamps they have are stored using a type in PostgreSQL called timestamp without time zone, which has microsecond resolution—i.e., six digits after the decimal. So when 1577987974.6472975 is sent to PostgreSQL, it truncates the last digit of the fractional part and instead saves 1577987974.647297.

The Questions

There is still the question of why calendar.created_at was not reloaded when we called calendar.reload, even though calendar.attributes['created_at'] was reloaded.

Also, the results of the Time precision test are a bit surprising. We were expecting that on MacOS, the maximal precision is six. We don’t know why it sometimes has seven digits. What surprised us more was the distribution of the value of the last digits:

pry> 10000.times.map { Time.now}.map{|t| t.to_f.to_s.match(/\.(\d+)/)[1] }.select{|s| s.size == 7}.group_by{|e| e[-1]}.map{|k, v| [k, v.size]}.to_h

# MacOS => {"9"=>536, "1"=>555, "2"=>778, "8"=>807}
# Linux => {"5"=>981, "1"=>311, "3"=>1039, "9"=>309, "8"=>989, "6"=>1031, "2"=>979, "7"=>966, "4"=>978}

As you can see, the seventh digit on MacOS is always 1, 2, 8, or 9.

If you know the answer to either of these questions, please share an explanation with us.

The Future

The fact that Ruby on Rails’ Active Record timestamps are generated on the application side may also hurt when those timestamps are used for reliable and precise ordering of events saved to the database. As application server clocks may be desynchronised, events ordered by created_at may appear in a different order than they really occurred. To get more reliable behavior, it would be better to let the database server handle timestamps (e.g., PostgreSQL’s now()).

That, however, is a story worth another article.

Special thanks to Gabriele Renzi for helping to create this article.