Another take on 'Database and Ruby have inconsistent time zone info'

[feliperaul]

Ankane, I have carefully read through #215 and #209, but I still think I'm onto something different here and, regardless, those two issues couldn't help us reaching a solution.

We have a User has 3 reservations in the month of november/2019:

this is in production: 
user.reservations.where("DATE(check_in) >= :start_date AND DATE(check_in) <= :end_date", start_date: Date.parse("2019-11-01"), end_date: Date.parse("2019-11-30")).pluck(:check_in)

=> [Thu, 07 Nov 2019 12:00:00 -03 -03:00,
 Wed, 13 Nov 2019 12:00:00 -03 -03:00,
 Thu, 21 Nov 2019 16:00:00 -03 -03:00]

In development (after importing the production DB dump), if we group them by day, we get exactly what we expect:

user.reservations.where("DATE(check_in) >= :start_date AND DATE(check_in) <= :end_date", start_date: Date.parse("2019-11-01"), end_date: Date.parse("2019-11-30")).group_by_day(:check_in, series: false).count

=> {Thu, 07 Nov 2019=>1, Wed, 13 Nov 2019=>1, Thu, 21 Nov 2019=>1}

In production, we get an empty hash:

user.reservations.where("DATE(check_in) >= :start_date AND DATE(check_in) <= :end_date", start_date: Date.parse("2019-11-01"), end_date: Date.parse("2019-11-30")).group_by_day(:check_in, series: false).count

=> {}

First of all, this only happens in the month of november/2019. If we try to do the same in september, october, it works perfectly and the results of production and development are the same.

Suspecting of a gem bug, we upgraded from 4.0.1 to 4.1.2, and now we started having the exception:

user.reservations.where("DATE(check_in) >= :start_date AND DATE(check_in) <= :end_date", start_date: Date.parse("2019-11-01"), end_date: Date.parse("2019-11-30")).group_by_day(:check_in, series: false).count

=> Groupdate::Error: Database and Ruby have inconsistent time zone info. Database returned 2019-11-06 23:00:00 -0300

Passing time_zone: false as an argument makes production return correct results.

What doesn't make sense is why would the discrepancy not happen in the month of Sep, but only in October.

Also, the error message returned, Database returned 2019-11-06 23:00:00 -0300, doesn't help us much because the first record returned has a check_in of Thu, 07 Nov 2019 12:00:00 -03 -03:00, so midday of november 7th, very far from midnight that could be causing any troubles when going from UTC to -3.

We could just throw the time_zone: false arg, because it appears to not be messing up with our results, but we're afraid of future implications and would have to rewrite quite some code.

What is you general recommendation about this? Changing the production database timezone from UTC would go against Rails conventions and is strongly discouraged from all hosted databases services (like AWS RDS). Is that really what we should do to solve this?

PS:
Both production and development are running the same version of MySql 5.7.

In production, the DB is in UTC:

mysql> SHOW VARIABLES LIKE '%time_zone%';
+------------------+--------+
| Variable_name    | Value  |
+------------------+--------+
| system_time_zone | UTC    |

In development, the DB is in Brazil timezone, which I can only assume mysql took automatically when it was installed since I never changed it myself:

mysql> SHOW VARIABLES LIKE '%time_zone%';
+------------------+--------+
| Variable_name    | Value  |
+------------------+--------+
| system_time_zone | -03    |

[ankane]

Hey @feliperaul, from the information provided, this sounds just like the two issues you reference. Based on the date, it's likely due to this DST change: https://www.timeanddate.com/news/time/brazil-scraps-dst.html. My guess is Rails knows that DST was abolished but your production MySQL doesn't. Try upgrading the time zone info in MySQL.

[feliperaul]

@ankane Thanks for the reply.

Just for future readers, I want to tell the steps I already took that didn't solve the problem:

sudo apt-get install tzdata -> reports tzdata is already the newest version (2019b-0ubuntu0.16.04).

According to this page, the Brazil update came exactly in the 2019b version which I already had in my server, so I was up-to-date.

I then ran mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -u root mysql -pPassword to be sure MySql had the up-to-date data, but the bug still persists.

[odlp]

Signposting for others who might be experiencing 'Database and Ruby have inconsistent time zone info': There was an issue affecting the tzinfo gem - it's incompatible with timezone-data 2020b (onwards?). Recent versions of Alpine ship with 2020c for example. The file format changed from 'fat' to 'slim' which isn't compatible with the tzinfo gem yet.

Resources:

• Issue on tzinfo gem
• Workarounds in Ruby and Alpine/Docker

Update 2020/11/13: Upgrading the tzinfo gem to >= 1.2.8 or >= 2.0.3 should resolve this issue

[inyerade]

Thanks @odlp I solved my problem with:

bundle update tzinfo

[nuzelac]

In case anyone encounters similar issue, I was running my app inside Docker container with outdated tzdata and a PostgreSQL on the host machine with latest tzdata. Solution was to update tzdata inside Dockerfile.

[snex]

I am experiencing this issue even after updating everything I can regarding timezones. Strangely, I only receive the error when using "includes" on my model.

Model.group_by_month(:date).sum(:result)
=> works as expected

Model.includes(:some, :other, :model).group_by_month(:date).sum(:result)
=> Groupdate::Error (Database and Ruby have inconsistent time zone info. Database returned 2019-04-01 07:00:00 UTC)

These other models are pure lookup tables and don't even have any date columns on them.

[cgeoffray]

Same issue when using includes on my model.
=> I solved it by using joins

Model.includes(:some, :other, :model).group_by_month(:date).sum(:result)
replaced by:
Model.joins(:some, :other, :model).group_by_month(:date).sum(:result)

[simonfranzen]

We can reproduce this bug as well like @snex wrote in the post before. Only if we use a .includes() the error occurs. We had a combination of includes and left_outer_joins.

Our timezone in rails config is set to "Europe/Berlin"
Our psql database uses the ETC/UTC without offset.

[ankane]

If someone wants to submit a PR with a failing test case for the includes issue, I can look into it further.

[aried3r]

It's not a PR, but while researching another issue that only began occurring after updating to Rails 6.1 I've written a test case that shows the issue, I believe.

For this to work, you have to first:

$ createdb groupdate-rails61

Then run:

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  # Works with rails 6.0.0.
  gem "rails", "~> 6.1.0"
  gem "pg"
  gem "groupdate"
end

require "active_record"
require "minitest/autorun"
require "logger"

ActiveRecord::Base.establish_connection(adapter: "postgresql", database: "groupdate-rails61")
ActiveRecord::Base.logger = Logger.new(STDOUT)

class TestApp < Rails::Application
  # If you comment this out, the test case works as expected.
  config.time_zone = "Europe/Berlin"
end

Rails.application.initialize!

ActiveRecord::Schema.define do
  create_table :posts, force: true do |t|
    t.datetime "created_at", null: false
    t.datetime "updated_at", null: false
  end

  create_table :comments, force: true do |t|
    t.datetime "created_at", null: false
    t.datetime "updated_at", null: false
    t.integer :post_id
  end
end

class Post < ActiveRecord::Base
  has_many :comments
end

class Comment < ActiveRecord::Base
  belongs_to :post
end

class BugTest < Minitest::Test
  def test_association_stuff
    Post.create!(created_at: 11.months.ago)

    # Works
    pp Post.group_by_month(:created_at, last: 12, format: '%B').count

    # Also works
    pp Post.left_outer_joins(:comments).where(comments: { id: nil }).group_by_month(:created_at, last: 12, format: '%B').count

    # Only works if the time zone is not configured.
    pp Post.includes(:comments).where(comments: { id: nil }).group_by_month(:created_at, last: 12, format: '%B').count
  end
end

Output:

$ ruby group_date_rails_6.1.rb                                                                                                                                                                                                                                                                           
Fetching gem metadata from https://rubygems.org/.............
Resolving dependencies....
Using rake 13.0.6
Using concurrent-ruby 1.1.9
Using zeitwerk 2.4.2
Using racc 1.5.2
Using minitest 5.14.4
Using builder 3.2.4
Using erubi 1.10.0
Using crass 1.0.6
Using rack 2.2.3
Using websocket-extensions 0.1.5
Using bundler 2.2.16
Using marcel 1.0.1
Using mini_mime 1.1.1
Using nio4r 2.5.8
Using method_source 1.0.0
Using pg 1.2.3
Using thor 1.1.0
Using nokogiri 1.12.4 (x86_64-darwin)
Using sprockets 4.0.2
Using i18n 1.8.10
Using rack-test 1.1.0
Using mail 2.7.1
Using tzinfo 2.0.4
Using websocket-driver 0.7.5
Using loofah 2.12.0
Using activesupport 6.1.4.1
Using rails-dom-testing 2.0.3
Using rails-html-sanitizer 1.4.2
Using globalid 0.5.2
Using actionview 6.1.4.1
Using groupdate 5.2.2
Using actionpack 6.1.4.1
Using activejob 6.1.4.1
Using actioncable 6.1.4.1
Using railties 6.1.4.1
Using activemodel 6.1.4.1
Using sprockets-rails 3.2.2
Using actionmailer 6.1.4.1
Using activerecord 6.1.4.1
Using activestorage 6.1.4.1
Using actionmailbox 6.1.4.1
Using actiontext 6.1.4.1
Using rails 6.1.4.1
config.eager_load is set to nil. Please update your config/environments/*.rb files accordingly:

  * development - set it to false
  * test - set it to false (unless you use a tool that preloads your test environment)
  * production - set it to true

-- create_table(:posts, {:force=>true})
D, [2021-09-07T16:17:05.309675 #79312] DEBUG -- :    (4.6ms)  DROP TABLE IF EXISTS "posts"
D, [2021-09-07T16:17:05.320393 #79312] DEBUG -- :    (10.4ms)  CREATE TABLE "posts" ("id" bigserial primary key, "created_at" timestamp NOT NULL, "updated_at" timestamp NOT NULL)
   -> 0.0435s
-- create_table(:comments, {:force=>true})
D, [2021-09-07T16:17:05.323294 #79312] DEBUG -- :    (2.2ms)  DROP TABLE IF EXISTS "comments"
D, [2021-09-07T16:17:05.329961 #79312] DEBUG -- :    (6.2ms)  CREATE TABLE "comments" ("id" bigserial primary key, "created_at" timestamp NOT NULL, "updated_at" timestamp NOT NULL, "post_id" integer)
   -> 0.0096s
D, [2021-09-07T16:17:05.403529 #79312] DEBUG -- :   ActiveRecord::InternalMetadata Load (2.5ms)  SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 LIMIT $2  [["key", "environment"], ["LIMIT", 1]]
Run options: --seed 44364

# Running:

D, [2021-09-07T16:17:05.573472 #79312] DEBUG -- :   TRANSACTION (0.2ms)  BEGIN
D, [2021-09-07T16:17:05.574725 #79312] DEBUG -- :   Post Create (0.9ms)  INSERT INTO "posts" ("created_at", "updated_at") VALUES ($1, $2) RETURNING "id"  [["created_at", "2020-10-07 14:17:05.563125"], ["updated_at", "2021-09-07 14:17:05.572646"]]
D, [2021-09-07T16:17:05.575575 #79312] DEBUG -- :   TRANSACTION (0.4ms)  COMMIT
D, [2021-09-07T16:17:05.581145 #79312] DEBUG -- :    (3.0ms)  SELECT COUNT(*) AS count_all, DATE_TRUNC('month', "posts"."created_at"::timestamptz AT TIME ZONE 'Europe/Berlin') AT TIME ZONE 'Europe/Berlin' AS date_trunc_month_posts_created_at_timestamptz_at_time_zone_euro FROM "posts" WHERE ("posts"."created_at" >= '2020-09-30 22:00:00' AND "posts"."created_at" < '2021-09-30 22:00:00') GROUP BY DATE_TRUNC('month', "posts"."created_at"::timestamptz AT TIME ZONE 'Europe/Berlin') AT TIME ZONE 'Europe/Berlin'
{"October"=>1,
 "November"=>0,
 "December"=>0,
 "January"=>0,
 "February"=>0,
 "March"=>0,
 "April"=>0,
 "May"=>0,
 "June"=>0,
 "July"=>0,
 "August"=>0,
 "September"=>0}
D, [2021-09-07T16:17:05.681618 #79312] DEBUG -- :    (5.6ms)  SELECT COUNT(*) AS count_all, DATE_TRUNC('month', "posts"."created_at"::timestamptz AT TIME ZONE 'Europe/Berlin') AT TIME ZONE 'Europe/Berlin' AS date_trunc_month_posts_created_at_timestamptz_at_time_zone_euro FROM "posts" LEFT OUTER JOIN "comments" ON "comments"."post_id" = "posts"."id" WHERE "comments"."id" IS NULL AND ("posts"."created_at" >= '2020-09-30 22:00:00' AND "posts"."created_at" < '2021-09-30 22:00:00') GROUP BY DATE_TRUNC('month', "posts"."created_at"::timestamptz AT TIME ZONE 'Europe/Berlin') AT TIME ZONE 'Europe/Berlin'
{"October"=>1,
 "November"=>0,
 "December"=>0,
 "January"=>0,
 "February"=>0,
 "March"=>0,
 "April"=>0,
 "May"=>0,
 "June"=>0,
 "July"=>0,
 "August"=>0,
 "September"=>0}
D, [2021-09-07T16:17:05.711246 #79312] DEBUG -- :    (1.7ms)  SELECT COUNT(DISTINCT "posts"."id") AS count_id, DATE_TRUNC('month', "posts"."created_at"::timestamptz AT TIME ZONE 'Europe/Berlin') AT TIME ZONE 'Europe/Berlin' AS date_trunc_month_posts_created_at_timestamptz_at_time_zone_euro FROM "posts" LEFT OUTER JOIN "comments" ON "comments"."post_id" = "posts"."id" WHERE "comments"."id" IS NULL AND ("posts"."created_at" >= '2020-09-30 22:00:00' AND "posts"."created_at" < '2021-09-30 22:00:00') GROUP BY DATE_TRUNC('month', "posts"."created_at"::timestamptz AT TIME ZONE 'Europe/Berlin') AT TIME ZONE 'Europe/Berlin'
E

Error:
BugTest#test_association_stuff:
Groupdate::Error: Database and Ruby have inconsistent time zone info. Database returned 2021-10-01 02:00:00 +0200
    gems/groupdate-5.2.2/lib/groupdate/series_builder.rb:50:in `block in generate'
    gems/groupdate-5.2.2/lib/groupdate/series_builder.rb:35:in `each'
    gems/groupdate-5.2.2/lib/groupdate/series_builder.rb:35:in `generate'
    gems/groupdate-5.2.2/lib/groupdate/magic.rb:133:in `perform'
    gems/groupdate-5.2.2/lib/groupdate/magic.rb:219:in `block in process_result'
    gems/groupdate-5.2.2/lib/groupdate/magic.rb:218:in `each'
    gems/groupdate-5.2.2/lib/groupdate/magic.rb:218:in `process_result'
    gems/groupdate-5.2.2/lib/groupdate.rb:31:in `process_result'
    gems/groupdate-5.2.2/lib/groupdate/relation.rb:13:in `calculate'
    gems/activerecord-6.1.4.1/lib/active_record/relation/calculations.rb:51:in `count'
    group_date_rails_6.1.rb:62:in `test_association_stuff'


rails test group_date_rails_6.1.rb:52



Finished in 0.156254s, 6.3998 runs/s, 0.0000 assertions/s.
1 runs, 0 assertions, 0 failures, 1 errors, 0 skips

The test case doesn't assert anything right now, but just raises an exception. You can move the code outside the test case if you like.

If you comment out the config.time_zone line, it Works on My Machine™.

Leaving this line in there, it works with Rails 6.0 (change the version constraint at the top of the file), but doesn't with Rails 6.1. I'm not sure if it's a Rails issue or if it's groupdate or the fact that Rails 6.1 uses tzinfo 2.x instead of 1.x or a combination.

My only assumption is that it's not that columns are timezone aware, I think that's for Rails 7: rails/rails#41395.

[ankane]

Hey @aried3r, thanks for the repro script! Just pushed a fix (the issue was affecting includes with Rails 6.1+) if you point your Gemfile to GitHub.

Also, for Groupdate 6, I've updated the gem to work when time zones are inconsistent, so this error won't appear anymore.