will / crystal-pg

a postgres driver for crystal
BSD 3-Clause "New" or "Revised" License
463 stars 78 forks source link

When time is inserted into postgres, 4 hours get added to it. #182

Closed curioustolearn closed 5 years ago

curioustolearn commented 5 years ago

I recently updated from crystal-db 0.5.1 and crystal-pg 0.16.1 to crystal-db 0.6.0 and crystal-pg 0.18. This caused the following change in the application behavior, which appears to be a bug.

Behavior with the newer versions of these packages (1) I send an integer = 1565713800000 milliseconds since epoch to the server as part of JSON. This equals 12:30pm US Eastern time on August 13. (2) On server I use timecreated: {type: Time?, converter: Time::EpochMillisConverter} as part of JSON.mapping to read this value. (3) I insert the read value (which is now of type Time) into Postgres timestamptz column. The time in postgres shows up as 4:30pm US Eastern time. Postgres may be saving the timestamp, but in psql it displays the time locally (which is US Eastern time for me). (4) As expected, when I get this value out again on another page, it is now 4 hours ahead of what I expect.

I reverted crystal-pg to 0.16.1 (which automatically changed crystal-db to 0.5.1). The behavior is as expected. When I send the integer = 1565713800000 milliseconds, and follow the above steps, the time in Postgres shows as 12:30pm US Eastern time on August 13.

will commented 5 years ago

Could you try monkey-patch reverting https://github.com/will/crystal-pg/pull/175/files to see if that fixes it?

Do something like

module PQ
  def self.encode(val : Time)
    text val.to_s("%FT%X.%L%z")
  end
end

somewhere in your code after loading crystal-pg and it should pop it back to the old behavior.

bcardiff commented 5 years ago

We have that discussion in the forum https://forum.crystal-lang.org/t/treatment-of-time-in-recent-versions-of-crystal-db-crystal-pg-a-bug/1032/5?u=bcardiff

will commented 5 years ago

Oh, ok so the 6Netc formatting is correct but the problem is the #to_utc ?

bcardiff commented 5 years ago

The missin %z and T

bcardiff commented 5 years ago

The 6N would have been the required changes in the former pr to handle microseconds

will commented 5 years ago

I don’t get it :( can you do a PR with the correct thing?

bcardiff commented 5 years ago

Sure. As soon as I am not on mobile 😅

straight-shoota commented 5 years ago

It's probably best to simply use Time::Format::RFC_3339.

  def self.encode(val : Time)
    text Time::Format::RFC_3339.format(val)
  end

It's essentially the same as %FT%X.%N%:z, includes second fraction and time zone offset and is faster than the string-based pattern.

will commented 5 years ago

We could also maybe send the data as a binary format. I don’t remember why I chose text in https://github.com/will/crystal-pg/commit/cafef9b7827022f1c4260cd5bc04e4fa884b3052 but maybe there was a reason

straight-shoota commented 5 years ago

Go even has some more complicated logic for this: https://github.com/lib/pq/blob/master/encode.go#L477 But they also use string representation.

will commented 5 years ago

v0.18.1 has PR #183 which fixes this issue.

carcinocron commented 4 years ago

I'm still having this issue...

puts Time.utc
# 2020-06-15 17:23:39.456914000
puts Time.utc + 30.minutes
# 2020-06-15 17:53:39.456914000

after insertion, when reading:

puts ({run_at____: channeljob.run_at})
# {run_at____: 2020-06-15 13:53:39.0 UTC}
puts ({created_at: channeljob.created_at})
# {created_at: 2020-06-15 13:23:39.502775000 UTC}```
Failures:

  1) Http::Posts::Create accepts schedule_publish_at when invalid value
     Failure/Error: channel_jobs[0].run_at.should eq in_30_min

       Expected: 2020-06-15 17:53:39.456902000 UTC
            got: 2020-06-15 13:53:39.0 UTC
# SELECT id, run_at, created_at, NOW() as now FROM channeljobs;
 id |       run_at        |         created_at         |              now              
----+---------------------+----------------------------+-------------------------------
  1 | 2020-06-15 13:53:39 | 2020-06-15 13:23:39.502775 | 2020-06-15 13:38:13.875932-04

It happens with column type TIMESTAMP but not TIMESTAMPTZ.

straight-shoota commented 4 years ago

@InstanceOfMichael Time data types in postgres can be tricky. Essentially, for your use case you must use timestamptz. timestamp won't work (or it can work in some situations, but not in others). If you're not sure about the differences, read up on time data types (for example on postgrestutorial). You can see the effective difference in the SELECT result comparing the timestamp values run_at and created_at with now (which implicitly is a timestamptz): The latter has time zone information, the others don't.

I'm not completely aware of the exact reasons how your example works, but the result seems consistent with a misused data type. So the observed behaviour looks to be totally expected. When the postgres client decodes a timestamp value, it doesn't know the time zone becase this information simply doesn't exist in this data type. So it creates a Time instance with an arbitrary time zone. The resulting instance has the wall clock representation as intended by the database value, but not it does not necessarily represent the same instant on the time line as the original instance because time zone information was lost.