Cover image
< 5 minute read

Timestamp Truncation: A Ruby on Rails ActiveRecord Tale

Tests should keep apps from being flaky. But tests themselves can become flaky—even the most straightforward ones. Here’s how we dove into a problematic test on a PostgreSQL-backed Rails app, and what we uncovered.

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
    .not_to change(calendar, :attributes)

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}"
    puts "after perform: #{calendar.created_at.to_f}"
    puts "after reload: #{calendar.created_at.to_f}"
    .not_to change(calendar, :attributes)

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
    .not_to change(calendar, :attributes)

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) { }
let(:calendar) { create(:calendar, created_at: time, updated_at: time) }

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

The Cause

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

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

pry> {\.(\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> {}.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.

Further Reading on the Toptal Engineering Blog:

Understanding the basics

ActiveRecord is an object-relational mapping library provided by Ruby on Rails. It lets you persist objects in a database, then retrieve saved data and instantiate objects.

Active Record is an enterprise architecture pattern used for persisting in-memory objects in relational databases. In Ruby on Rails' implementation, ActiveRecord monitors changes to Rails model attributes. When a model is saved, ActiveRecord sends the changes, along with required timestamps, to a database.

ActiveRecord by default stores two timestamps: created_at (time when the model was first saved) and updated_at (time when the model was last saved). They provide basic audit capabilities and allow apps to sort models starting from the newest or last updated ones.

Timestamp is a PostgreSQL datatype that stores both a date and a time. It has a one-microsecond resolution and precision, meaning that it keeps fractions of seconds up to six digits.

Ruby on Rails allows developers to use most of the popular databases. By default, Ruby on Rails uses the ActiveRecord library, which supports DB2, Firebird, FrontBase, MySQL, OpenBase, Oracle, PostgreSQL, SQLite, Microsoft SQL Server, and Sybase.