Error after upgrading to jdbc-mysql 8.0: ActiveRecord::JDBCError: HOUR_OF_DAY: 2 -> 3
mohamedhafez opened this issue · 9 comments
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'
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)
(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)
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!
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)
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 #897 (comment), 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
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...