Automated software tests are designed to prevent software from becoming unreliable. However, there are instances where the tests themselves can become inconsistent—even the simplest ones. This article details our experience investigating a problematic test in a Ruby on Rails application using PostgreSQL as its database, and what we discovered.

We wanted to ensure that a specific part of our application logic (invoked by a method called perform) didn’t modify a calendar model (an instance of Calendar, which is a Ruby on Rails ActiveRecord model class). To verify this, we wrote the following test:

1
2
3
4
5
6
7
8

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

This test consistently passed in one of our development environments (MacOS), but it almost always failed in our Continuous Integration environment (Linux).

Fortunately, we were able to reproduce the failure in another development environment (Linux), where it failed with the following error message:

1
2
3
4
5

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}

Do you notice anything unusual?

Investigating the Issue

Upon closer inspection, we observed that the created_at and updated_at timestamps were slightly altered within the expect block:

1
2

{"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 fractional part of the seconds value was truncated, changing 13:36:22.459149334 to 13:36:22.459149000.

We were confident that the perform method wasn’t actually modifying the calendar object, so we hypothesized that the database was truncating the timestamps. To verify this, we employed a highly sophisticated debugging technique—puts debugging:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

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

However, the truncation wasn’t evident in the output:

1
2
3

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

This was quite unexpected because the #created_at accessor should have returned the same value as the attributes['created_at'] hash entry. To guarantee we were examining the same value used in the assertion, we modified how we accessed created_at.

We replaced the accessor calendar.created_at.to_f with direct access via the attributes hash: calendar.attributes['created_at'].to_f. Our suspicions about calendar.reload were confirmed!

1
2
3

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

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

To rule out the possibility of another instance of calendar being modified and saved, we conducted one final experiment. We reloaded calendar before the test:

1
2
3
4
5
6
7
8

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

This resulted in the test passing consistently.

Resolving the Problem

Armed with the knowledge that the database was truncating our timestamps and causing our tests to fail, we decided to prevent this truncation. Our solution involved generating a DateTime object, rounding it to the nearest second, and then explicitly setting Rails’ Active Record timestamps using this object. This modification successfully resolved the issue and stabilized the tests:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

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

Identifying the Root Cause

What was the underlying reason for this behavior? Active Record timestamps rely on the Ruby set by the Rails’ ActiveRecord::Timestamp module using Time.now. Time precision is OS-dependent, and according to the documentation, may include fractional seconds.

We tested Time.now resolution on both MacOS and Linux using a script that tallied the frequency of fractional part lengths:

1
2
3
4

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}

The results showed that approximately 70% of timestamps on Linux had seven digits of precision after the decimal, while only 25% on MacOS did. This discrepancy explains why the tests mostly passed on MacOS but failed frequently on Linux. You may have noticed nine-digit precision in the test output—this is because RSpec uses Time#nsec when formatting time output.

When Rails models are persisted to the database, their timestamps are stored in PostgreSQL using a data type called timestamp without time zone, which has a precision of microsecond resolution—meaning six digits after the decimal. Consequently, when a value like 1577987974.6472975 is sent to PostgreSQL, it truncates the last digit of the fractional part, storing it as 1577987974.647297.

Unanswered Questions

The behavior of calendar.created_at not being reloaded when we called calendar.reload, even though calendar.attributes['created_at'] was updated, remains unclear.

Furthermore, the results of the Time precision test were unexpected. We anticipated a maximum precision of six digits on MacOS. The intermittent occurrence of seven digits is puzzling. Even more surprising was the distribution of the last digit’s values:

1
2
3
4

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, on MacOS, the seventh digit is always 1, 2, 8, or 9.

If you have insights into either of these questions, we would appreciate an explanation.

Looking Ahead

The fact that Ruby on Rails’ Active Record](https://www.bogotobogo.com/RubyOnRails/RubyOnRails_Active_Records.php) timestamps are generated on the application side might also pose challenges when using these timestamps for reliable and accurate ordering of events stored in the database. If application server clocks are not synchronized, events sorted by created_at could appear in an order different from the actual sequence of events. Achieving [more reliable behavior, it would be better to let the database server handle timestamps (e.g., PostgreSQL’s now()).

However, that topic deserves its own dedicated article.

We extend our gratitude to Gabriele Renzi for their contributions to this article.