An RSpec time issue (and it’s not due to timezones)

An investigation into why a test fails only 30 minutes per day

via Pexels

We ran into an infrequent test failure that was only happening at a specific time of day. Through most of the day, the test passed routinely, but around 7:30pm EDT, suddenly it would always fail on CI — which then would stop Github from allowing merges while the build was fixed. This is clearly a problem when you have a distributed team working in multiple time zones.

it 'updates the curation time of the photo' do
  expect(photo).to receive(:update)
    .with(curated_at: DateTime.current)
  subject.call
end

The actual time was off from the expected time by exactly 30 minutes.

At first glance, this looks to be a timezone issue; it’s relatively common to have issues when the local timezone is in a different day than UTC, and 8pm Eastern is midnight UTC. As can be seen from the test output, the expected and actual times bridge the gap between two days.

However, there were a couple things that didn’t add up:

1. The difference between the expected and actual values is only 30 minutes. Given that there are only a handful of time zones with non-hour offsets (and none of our employees live in one or would have any reason to set one), this would be a strange result for a timezone issue.
2. By default, CircleCI operates in UTC, and as a double check, our CircleCI config explicitly sets TZ=UTC, so while local timezones are a good red herring, they should have no impact on the test run on Circle.

Time to take a deeper look at what’s going on.

Here is the actual code that gets called:

def update_timestamp(photo, column)
  stamp = [max_timestamp(column) + MIN_GAP, DateTime.current].max
  photo.update(column => stamp)
end

We wanted to make sure there’s a minimum time gap between timestamps, so we set stamp to either the maximum existing value of the column (max_timestamp(column)) plus a gap interval (MIN_GAP), or to DateTime.current, whichever one is later. MIN_GAP is set to 30.minutes — that mysterious amount of time that our test is failing by! So it looks like there’s a problem with the test, but why is it passing the majority of the time?

In the test, max_timestamp is stubbed out to return DateTime.current for simplicity, so stamp in the update_timestamp method should always be set to DateTime.current + MIN_GAP. Which means that the stub expectation set above in the test code should be failing, but is false-positive passing:

expect(photo).to receive(:update).with(curated_at: DateTime.current)

When a method is stubbed with an expected input, RSpec compares the actual input to the expectation using ===. As it turns out, two DateTimes are considered equivalent by === as long as the date component is equal, completely ignoring the time component!

a = DateTime.parse("8pm")
=> Tue, 19 Mar 2019 20:00:00 +0000
b = DateTime.parse("11pm")
=> Tue, 19 Mar 2019 23:00:00 +0000
a === b
=> true

So why is DateTime#=== only comparing dates? The answer is actually easily revealed using pry:

pry(main)> cd DateTime.current
pry(#<DateTime>):1> ? ===

  From: ext/date/date_core.c (C Method):
  Owner: Date
Visibility: public
Signature: ===(arg1)
Number of lines: 12

Returns true if they are the same day.

  Date.new(2001,2,3) === Date.new(2001,2,3)
#=> true
Date.new(2001,2,3) === Date.new(2001,2,4)
#=> false
DateTime.new(2001,2,3) === DateTime.new(2001,2,3,12)
#=> true
DateTime.new(2001,2,3) === DateTime.new(2001,2,3,0,0,0,'+24:00')
#=> true
DateTime.new(2001,2,3) === DateTime.new(2001,2,4,0,0,0,'+24:00')
#=> false

The === method is implemented in ext/date/date_core.c as a method on the Date class, which DateTime inherits from, but does not override (it’s not really evident why DateTime doesn’t have its own implementation). Therefore, DateTime#=== is identical to Date#===, which doesn’t know about time.

RSpec actually had a deprecation warning about this very thing in version 2.99, but it looks like the warning never made it into RSpec 3+ for whatever reason, and the maintainers decided against adding special behaviour for it.

With this information, we can fix the test and remove the false positive, by using Time instead of DateTime, as RSpec suggests, and fix the expectation to incorporate the 30 minute gap.

def update_timestamp(photo, column)
  stamp = [max_timestamp(column) + MIN_GAP, Time.current].max
  photo.update(column => stamp)
end
it 'updates the curation time of the photo' do
  expect(photo).to receive(:update)
    .with(curated_at: 30.minutes.from_now)
  subject.call
end

To wrap up, here’s what we learned:

• RSpec uses === to compare expectations in a stub, and DateTime#=== has some unexpected behaviour that causes it to ignore the time component when comparing with ===, leading to a false positive.
• Overall, it’s better to use Time than DateTime.
• The false positive was revealed by CircleCI, but the results were misunderstood.
• Don’t just throw away an intermittent or time-related test failure as a false negative.
• It can be helpful to write tests using a tool like timecop in order to cover situations where an operation might behave differently before and after midnight.

Update: A ticket was added to the Ruby Core bugtracker about DateTime#=== if you want to contribute to the discussion there.