search

jruby / activerecord-jdbc-adapter

JRuby's ActiveRecord adapter using JDBC.
BSD 2-Clause "Simplified" License
462 stars 386 forks source link

Error after upgrading to jdbc-mysql 8.0: ActiveRecord::JDBCError: HOUR_OF_DAY: 2 -> 3 #1091

Open mohamedhafez opened 3 years ago

mohamedhafez commented 3 years ago

I'm getting the following error after upgrading from jdbc-mysql from the 5.1.* series to 8.0.20: ActiveRecord::JDBCError: HOUR_OF_DAY: 2 -> 3

It looks like its due to upgrading Connector/J from the 5.1 series to the 8.0 series. It seems like someone reported the the bug to the Connector/J bug tracker here, and that it was marked as a possible duplicate of this bug that was resolved in Connector/J 8.0.22.

Currently, jdbc-mysql is using Connector/J 8.0.20, could we get an update to the latest version in the hopes of getting a fix to this bug?

Here's the stack trace I'm getting btw:

arjdbc/jdbc/RubyJdbcConnection.java:1082:in `execute_query'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-jdbc-adapter-61.1-java/lib/arjdbc/abstract/database_statements.rb:44:in `block in exec_query'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block in log'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block in synchronize'
        org/jruby/RubyThread.java:759:in `handle_interrupt'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
        org/jruby/RubyThread.java:759:in `handle_interrupt'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activesupport-6.1.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-jdbc-adapter-61.1-java/lib/arjdbc/abstract/core.rb:73:in `log'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-jdbc-adapter-61.1-java/lib/arjdbc/abstract/database_statements.rb:44:in `exec_query'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract/database_statements.rb:532:in `select'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract/database_statements.rb:69:in `select_all'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract/query_cache.rb:103:in `select_all'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-jdbc-adapter-61.1-java/lib/arjdbc/abstract/database_statements.rb:86:in `select_all'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/querying.rb:47:in `find_by_sql'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/relation.rb:843:in `block in exec_queries'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/relation.rb:861:in `skip_query_cache_if_necessary'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/relation.rb:828:in `exec_queries'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/relation.rb:631:in `load'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/relation.rb:249:in `records'
        /var/www/vhosts/myapp/shared/bundle/jruby/2.5.0/gems/activerecord-6.1.4/lib/active_record/relation/delegation.rb:88:in `each'
        /var/www/vhosts/myapp/releases/20210805091448/app/models/account.rb:817:in `customer_stats_str'
mohamedhafez commented 2 years ago

Just a little bump on this, it seems like some relevant fixes were made in Connector/J 8.0.22 and especially 8.0.23:

in 8.0.23:

After upgrading from Connector/J 5.1 to 8.0, the results of saving and then retrieving DATETIME and TIMESTAMP values became different sometimes. It was because while Connector/J 5.1 does not preserve a time instant by default, Connector/J 8.0.22 and earlier tried to do so by converting a timestamp to the server's session time zone before sending its value to the server. In this release, new mechanisms for controlling timezone conversion has been introduced—see Preserving Time Instants for details. Under this new mechanism, the default behavior of Connector/J 5.1 in this respect is preserved by setting the connection property preserveInstants=false. (Bug #30962953, Bug #98695, Bug #30573281, Bug #95644)

in 8.0.22:

LocalDate, LocalDateTime, and LocalTime values set through Connector/J were altered when there was a timezone difference between the server and the client. This fix corrects the issue by handling the LocalDate, LocalTime, and LocalDateTime with no time zone conversion and no intermediate conversions to other date-time classes. Thanks to Iwao Abe for his contribution to the fix. (Bug #29015453, Bug #93444)

mohamedhafez commented 2 years ago

(Note: i made some edits to the title of the bug and the original description of the bug to reflect that this error has nothing to do with going from activerecord-jdbcmysql-adapter 60.0 to 60.1, 60.1 works just fine if you make it use jdbc-mysql 5.1.49. Its only when when we upgrade jdbc-mysql from 5.1.* to 8.0.17 or 8.0.20 that I see the issue)

mohamedhafez commented 2 years ago

I just tested out with jdbc-mysql 8.0.27, and unfortunately the issue persists. I tried setting preserveInstants: false as per the Connector/J 8.0.23 release notes instructions to keep the Connector/J 5.1 behavior, but no luck. Perhaps part of the issue is that I've been setting serverTimezone: "America/Los_Angeles" as per https://github.com/jruby/activerecord-jdbc-adapter#mysql-specific-notes? I'm stumped. I understand that in general asking for database setup help here is inappropriate, but considering that the behavior here is very different than MRI, some help would very much be appreciated @headius, @enebo, or @kares!

kares commented 2 years ago

seems like a Connector/J bug to me - AR-JDBC uses roughly the same JDBC code when retrieving timestamps. we did the 8.x driver update as requested as the issue persist I recommend staying on 5.1.

there seems to be no capacity atm to look into driver specific issue esp. since the existing code works with the old one as well as MariaDB driver. happy to review PRs though, should not be hard to detetc the 8.0 driver being used.

the bug report is useful - thanks for that, any chance we'll get an isolated (AR) reproducer? (including your time-zone info)

mohamedhafez commented 2 years ago

Ok found an example of where this is happening!

Time Zone info: I'm running my MySQL 8.0.27 on AWS's RDS service, so the timezone data has been correctly loaded into MySQL by default, and all the time zone variables were left at their AWS default settings of UTC (system_time_zone, time_zone, etc). I've been connecting with serverTimezone: "America/Los_Angeles" in my database.yml, as per https://github.com/jruby/activerecord-jdbc-adapter#mysql-specific-notes. In my Rails application.rb, I have config.time_zone = 'America/Los_Angeles', and my Linux machine is also set to have a time zone of 'America/Los_Angeles' (Java seems to automatically pick this up, Java::JavaUtil::TimeZone.getDefault returns 'America/Los_Angeles'`

When I just connect to mysql via the command line (with the session time_zone going to the default of UTC), I get the following result for this given row:

mysql> SELECT created_at FROM accounts WHERE id = 1996;
+---------------------+
| created_at          |
+---------------------+
| 2013-03-10 02:21:54 |
+---------------------+

With jdbc-mysql 5.1.49, I get the following:

>> Account.where(id: 1996).pluck(:created_at)
=> [Sat, 09 Mar 2013 19:21:54.000000000 PST -08:00]

NOTE THAT THIS IS INCORRECT!! Time.parse("2013-03-10 02:21:54 UTC").in_time_zone('America/Los_Angeles') is actually Sat, 09 Mar 2013 18:21:54.000000000 PST -08:00

With jdbc-mysql 8.0.27, I get the following error:

>> Account.where(id: 1996).pluck(:created_at)
Traceback (most recent call last):
        1: from (irb):12:in `evaluate'
ActiveRecord::StatementInvalid (ActiveRecord::JDBCError: HOUR_OF_DAY: 2 -> 3)

On March 10, 2013 at 2am, America/Los_Angeles was supposed to spring forward to 3am. That's the "HOUR_OF_DAY: 2 -> 3" error. It seems like it is trying to interpret that UTC time stamp as being an America/Los_Angeles timestamp for some reason, and complaining that its an invalid time since there should be no times between 2:00am and 2:59am on that day in that timezone.

Doing ActiveRecord::Base.connection.execute("SELECT @@SESSION.time_zone;").to_a showed that the session timezone was still UTC, so I added forceConnectionTimeZoneToSession: true to database.yml (which essentially executes the mysql statement set time_zone = <whatever serverTimezone/connectionTimeZone is>), and verified that ActiveRecord::Base.connection.execute("SELECT @@SESSION.time_zone;").to_a did indeed now report America/Los_Angeles, but I got the exact same error when doing Account.where(id: 1996).pluck(:created_at)

As per the suggestion in https://github.com/jruby/activerecord-jdbc-adapter/issues/897#issuecomment-405534216, I also tried setting time_zone = 'America/Los_Angeles' globally, and removed the serverTimezone variable from my database.yml, but got the exact same results as above: jdbc-mysql 5.1.49 is off by an hour, and jdbc-mysql 8.0.27 returns the same error

mohamedhafez commented 2 years ago

If I start jruby with -J-Duser.timezone=UTC, and have default_time_zone=UTC in my mysqld config, basically turning off all of Connector/J and mysql's time zone conversion magic, then everything works perfectly with both jdbc-mysql 5.1.49 and 8.0.27

Perhaps there is a more elegant way of doing that that won't affect other parts of JRuby? Since there are issues with both jdbc-mysql 5.1.49 and 8.0.27 I'm hoping it merits a fix...

jbaiza commented 2 weeks ago

We at eazyBI faced a similar error and, in the end, created our fork to fix it by catching the exception. I made a new PR with our solution - https://github.com/jruby/activerecord-jdbc-adapter/pull/1160.

Here are my findings about possible solutions after more investigation and conversation with @headius:

With the patched AR JDBC JAR file, I compared results with the C Ruby in a sample test app, and they matched:

Time Returned value MRI Returned value JRuby
2024-03-31 00:00:01 Sun, 31 Mar 2024 01:00:01.000000000 CET +01:00 Sun, 31 Mar 2024 01:00:01.000000000 CET +01:00
2024-03-31 01:00:01 Sun, 31 Mar 2024 03:00:01.000000000 CEST +02:00 Sun, 31 Mar 2024 03:00:01.000000000 CEST +02:00
2024-03-31 02:00:01 Sun, 31 Mar 2024 04:00:01.000000000 CEST +02:00 Sun, 31 Mar 2024 04:00:01.000000000 CEST +02:00
2024-03-31 03:00:01 Sun, 31 Mar 2024 05:00:01.000000000 CEST +02:00 Sun, 31 Mar 2024 05:00:01.000000000 CEST +02:00
Time Returned value MRI Returned value JRuby
2024-03-31 00:00:01 Sun, 31 Mar 2024 00:00:01.000000000 CET +01:00 Sun, 31 Mar 2024 00:00:01.000000000 CET +01:00
2024-03-31 01:00:01 Sun, 31 Mar 2024 01:00:01.000000000 CET +01:00 Sun, 31 Mar 2024 01:00:01.000000000 CET +01:00
2024-03-31 02:00:01 Sun, 31 Mar 2024 03:00:01.000000000 CEST +02:00 Sun, 31 Mar 2024 03:00:01.000000000 CEST +02:00
2024-03-31 03:00:01 Sun, 31 Mar 2024 03:00:01.000000000 CEST +02:00 Sun, 31 Mar 2024 03:00:01.000000000 CEST +02:00

From the PR test results, I see that not only is the time zone set in the code important, but the environment time zone is also taken into account. My tests were conducted using the "Europe/Riga" time zone. When I run the tests using TZ="Europe/Prague", the error is "HOUR_OF_DAY: 2 -> 3" and occurs at "2024-03-31 02:00:01", not 3 AM. There is no MySQL HOUR_OF_DAY error with TZ="UTC".

headius commented 2 weeks ago

There's lots of posts online asking about this same issue, some with suggested fixes such as:

Suggested fixes here include fixing data in the database (the time entered is not valid and so should be fixed), configuring the connection for UTC, and setting the server timezone to UTC. @mohamedhafez suggested a similar workaround in https://github.com/jruby/activerecord-jdbc-adapter/issues/1091#issuecomment-1013325894.

I'm guessing that in @jbaiza's case we may be talking about databases we do not control, such as those set up by users of EazyBI? That certainly limits our options.

This one also suggests bulk scrubbing the data using a stored procedure that adjusts all datetime fields.

The fix in #1160 is not terrible but obviously it would be nice to avoid the error altogether. I'm wondering if that's really possible though.

@jbaiza A few more questions for you (and @mohamedhafez if you have some input):

I don't know what the right answer is here but getting a not-great fix in place for now would seem better than leaving it broken until we have a perfect solution (which may not exist if this is indeed bad data).

jbaiza commented 2 weeks ago

@headius, I can imagine two cases when the error could occur in eazyBI, and in both cases, the data stored in the database are valid: