Incorrect query serialization of (some) DateTimes with fractional seconds

[bbornstein]

I'm encountering some unexpected behavior when Rails serializes a DateTime in a query string. Originally, I thought this bug might be specific to PostgreSQL, but I've also reproduced it using the steps below with SQLite3. Repeating the same steps with MySQL (5.1.15) didn't yield the same result. Apparently this is because MySQL's datetime data type doesn't store fractional seconds.

With Ruby 1.9.3p194, Rails 3.2.7, PostgreSQL 9.1.4, and pg 0.14.0 on Mac OS X 10.7.4:

$ rails new Test --database=postgresql
$ cd Test/
$ rails g model foo created_at:datetime
$ rake db:create db:migrate
$ rails c

Expected:

irb(main):001:0> Foo.create! :created_at => '2011-12-30 14:35:43.250862'
irb(main):002:0> foo = Foo.where(:created_at => '2011-12-30 14:35:43.250862').first
Foo Load (0.6ms)  SELECT "foos".* FROM "foos" WHERE "foos"."created_at" = '2011-12-30 14:35:43.250862'
=> #<Foo id: 1, created_at: "2011-12-30 14:35:43", updated_at: "2012-08-18 00:57:56">
irb(main):003:0> foo.created_at.to_f
=> 1325255743.2508612

Unexpected:

irb(main):004:0> Foo.where(:created_at => foo.created_at)
Foo Load (0.6ms)  SELECT "foos".* FROM "foos" WHERE "foos"."created_at" = '2011-12-30 14:35:43.250861'
=> []

Notice the difference in the last digit of the date string in the SQL query. It's a "1", but it should be a "2". I confirmed the value of created_at in the PostgreSQL database:

$ rails db

Test_development=# SELECT * FROM foos;
 id |         created_at         |         updated_at         
----+----------------------------+----------------------------
  1 | 2011-12-30 14:35:43.250862 | 2012-08-18 00:57:56.271528
(1 row)

[bbornstein]

I haven't dug into the Rails code, but I suspect the issue might be related to the use of strftime:

irb(main):005:0> foo.created_at.to_f
=> 1325255743.2508612
irb(main):006:0> foo.created_at.to_f.to_s
=> "1325255743.2508612"
irb(main):007:0> foo.created_at.strftime('%N')
=> "250861000"

But with pure Ruby, I get the following:

$ irb

irb(main):001:0> require 'date'
=> true
irb(main):002:0> created_at = DateTime.parse('2011-12-30 14:35:43.250862')
=> #<DateTime: 2011-12-30T14:35:43+00:00 ((2455926j,52543s,250862000n),+0s,2299161j)>
irb(main):003:0> created_at.strftime('%N')
=> "250862000"

[bbornstein]

Digging into ActiveSupport::TimeWithZone:

irb(main):005:0> foo.created_at.class
=> ActiveSupport::TimeWithZone

It looks like all string serializations go through the xmlschema method:

def xmlschema(fraction_digits = 0)
  fraction = if fraction_digits > 0
    (".%06i" % time.usec)[0, fraction_digits + 1]
  end

  "#{time.strftime("%Y-%m-%dT%H:%M:%S")}#{fraction}#{formatted_offset(true, 'Z')}"
end
alias_method :iso8601, :xmlschema

And the culprit may be time.usec:

irb(main):006:0> foo.created_at.time.class
=> Time
irb(main):007:0> foo.created_at.time.usec
=> 250861
irb(main):008:0> foo.created_at.usec
=> 250861

But when I create an ActiveSupport::TimeWithZone directly, I don't get the same behavior:

irb(main):009:0> created_at = Time.zone.parse('2011-12-30 14:35:43.250862')
=> Fri, 30 Dec 2011 14:35:43 UTC +00:00
irb(main):010:0> created_at.class
=> ActiveSupport::TimeWithZone
irb(main):011:0> created_at.usec
=> 250862

So, the issue is likely with how ActiveSupport::TimeWithZone's member variable @time is created?

[bbornstein]

Digging deeper still, in ActiveRecord::ConnectionAdapters::Column there are two methods, fallback_string_to_time and microseconds:

def fallback_string_to_time(string)
  time_hash = Date._parse(string)
  time_hash[:sec_fraction] = microseconds(time_hash)

  new_time(*time_hash.values_at(:year, :mon, :mday, :hour, :min, :sec, :sec_fraction))
end

def microseconds(time)
  ((time[:sec_fraction].to_f % 1) * 1_000_000).to_i
end

Stepping through this calculation at the Rails console shows the rounding error:

irb(main):001:0> time_hash = Date._parse('2011-12-30 14:35:43.250862')
=> {:hour=>14, :min=>35, :sec=>43, :sec_fraction=>(125431/500000), :year=>2011, :mon=>12, :mday=>30}
irb(main):002:0> time_hash[:sec_fraction].to_f
=> 0.250862
irb(main):003:0> time_hash[:sec_fraction].to_f % 1
=> 0.250862
irb(main):004:0> time_hash[:sec_fraction].to_f % 1 * 1_000_000
=> 250861.99999999997
irb(main):005:0> (time_hash[:sec_fraction].to_f % 1 * 1_000_000).to_i
=> 250861

Since Float.to_i truncates (indeed it's a synonym for Float.truncate), perhaps round is a better choice?:

irb(main):006:0> (time_hash[:sec_fraction].to_f % 1 * 1_000_000).round
=> 250862

[rafaelfranca]

@bbornstein I think I fixed this issue in my last two commits in the 3-2-stable

[bbornstein]

@rafaelfranca Thanks. Patching my 3.2.7 (in an initializer) with your changes from 3-2-stable fixed the issue. Specifically, in ActiveRecord::ConnectionAdapters::Column#fast_string_to_time, I changed the line:

microsec = ($7.to_f * 1_000_000).to_i

to:

microsec = ($7.to_r * 1_000_000).to_i

and similarly, ActiveRecord::ConnectionAdapters::Column#microseconds changes from:

((time[:sec_fraction].to_f % 1) * 1_000_000).to_i

to:

time[:sec_fraction] ? (time[:sec_fraction] * 1_000_000).to_i : 0

Thanks!

[rafaelfranca]

Thanks to report back and for the investigation.