Home > Debugging, Rails, Testing > Strange Rails Timestamp Errors

Strange Rails Timestamp Errors

12/11/2010

Strange Timestamp Errors
Occasionally (once or twice a week), we see strange failures in our Rails tests, with errors like the following:

<Wed Dec 08 23:47:09 -0600 2010> expected but was
<Wed Dec 08 23:47:09 -0600 2010>.

… generated from a test like the following:


    t = 2.days.ago
    Timecop.freeze(t) do
      saved_search = Factory(:user).saved_searches.create!(:name => 'My Search', :params => {'foo' => '1'}.to_json)
    end

    Timecop.freeze(1.day.ago) do
      get :show, :id => saved_search.id
      saved_search.reload
      assert_equal t, saved_search.last_used_at, "should not be updated"
    end

Off By Less Than 1s
If you’re familiar with Ruby Time objects, you can see that the time value is different, but at a resolution well below the seconds printed in the messages used. How can this be? We’re using Timecop to freeze all of the Ruby/Rails Time interfaces at a fixed point for this test.

We’re creating a record with a known Timestamp, reloading it from the database, and seeing that Timestamp off, but just slightly (by less than a second).

Background Info: Timecop
Timecop is one of my favorite Rails plugins, it allows you to pass a block of code that executes in a different Time, by stubbing out all the Ruby/Rails Time APIs to return the time you’ve chosen. You can see it used here to “travel” in time back to 2 days ago, then 1 day ago, and execute different parts of the test. This “freezes” time and makes any real difference in Timestamps impossible. So how is the Timestamp for this record changing? And in such a strange way?

Mystery Revealed: ActiveRecord DB Time Parsing/Rounding Error
It turns out there’s a bug in Rails 2.3/3.0 in Timestamp database value parsing, causing rounding errors for some edge case values. There’s a pending patch on it’s way into Rails, but I’ve manually patched our version of Rails to prevent this in the meantime. This means that when a test runs and happens to hit one of these category of Timestamp values (based on Time.now) this will blow up, since the Timestamp written to the DB will not be the one read back (off by less than a second). A truly maddening intermittent bug.

Much respect to Jacob Lauemøller who discovered/fixed this Rails bug. Here’s hoping this patch makes it in to the next 2.3.x release.

We’ve been suffering these erroneous failures for years and never knowing why. Glad to finally knock this off the list.

Advertisements
Categories: Debugging, Rails, Testing
  1. Joe Lind
    12/11/2010 at 3:29 pm

    Wow, I’ve torn my hair out over the same thing. I resorted to writing my own assertion method (like assert_nearly_equal) and never had the time to dig in further. Awesome find!

  1. No trackbacks yet.
Comments are closed.
%d bloggers like this: