quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.79k stars 2.68k forks source link

Timezone mappings missing for MySQL JDBC driver in native mode #5269

Closed johnaohara closed 4 years ago

johnaohara commented 5 years ago

Describe the bug MySQL jdbc driver fails to create connection as timezone mapping in missing in native image. New connection fails with com.mysql.cj.exceptions.WrongArgumentException: No timezone mapping entry for 'Etc/GMT'

Expected behavior Database connection to be created

Actual behavior

2019-11-07 00:38:09,507 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-worker-thread-0) HTTP Request to /owners/1 failed, error id: e5480ad3-242e-4408-b173-d29a8662c9b9-1: org.jboss.resteasy.spi.UnhandledException: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
    at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:106)
    at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:372)
    at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:209)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:496)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:252)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:153)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:156)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:238)
    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:109)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatchRequestContext(VertxRequestHandler.java:84)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.lambda$handle$0(VertxRequestHandler.java:71)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)
    at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:460)
    at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
    at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3355)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3293)
    at io.quarkus.hibernate.orm.runtime.entitymanager.TransactionScopedEntityManager.find(TransactionScopedEntityManager.java:143)
    at io.quarkus.hibernate.orm.runtime.entitymanager.ForwardingEntityManager.find(ForwardingEntityManager.java:42)
    at io.quarkus.hibernate.orm.panache.runtime.JpaOperations.findById(JpaOperations.java:196)
    at org.springframework.samples.petclinic.customers.model.OwnerRepositoryImpl.findById(OwnerRepositoryImpl.zig:337)
    at org.springframework.samples.petclinic.customers.model.OwnerRepositoryImpl.findById(OwnerRepositoryImpl.zig:320)
    at org.springframework.samples.petclinic.customers.model.OwnerRepositoryImpl_ClientProxy.findById(OwnerRepositoryImpl_ClientProxy.zig:533)
    at org.springframework.samples.petclinic.customers.web.PetResource.findOwner(PetResource.java:122)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:151)
    at org.jboss.resteasy.core.MethodInjectorImpl.lambda$invoke$3(MethodInjectorImpl.java:122)
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
    at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:614)
    at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1983)
    at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:110)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:122)
    at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:594)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:468)
    at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:421)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:423)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:391)
    at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invoke$1(ResourceMethodInvoker.java:365)
    at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981)
    at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124)
    at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:110)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:365)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:477)
    ... 16 more
Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:107)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:198)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:162)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:104)
    at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:197)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4350)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:569)
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:537)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:208)
    at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:332)
    at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:108)
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:74)
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:118)
    at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1168)
    at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1157)
    at org.hibernate.internal.SessionImpl.access$2000(SessionImpl.java:197)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.doLoad(SessionImpl.java:2795)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.lambda$load$1(SessionImpl.java:2776)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.perform(SessionImpl.java:2732)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2776)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3326)
    ... 44 more
Caused by: java.sql.SQLException: No timezone mapping entry for 'Etc/GMT'
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129)
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89)
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63)
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73)
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:85)
    at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:827)
    at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:447)
    at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:237)
    at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:199)
    at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:200)
    at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:390)
    at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:372)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:65)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    ... 3 more
Caused by: com.mysql.cj.exceptions.WrongArgumentException: No timezone mapping entry for 'Etc/GMT'
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:85)
    at com.mysql.cj.protocol.a.NativeProtocol.configureTimezone(NativeProtocol.java:2153)
    at com.mysql.cj.protocol.a.NativeProtocol.initServerSession(NativeProtocol.java:2163)
    at com.mysql.cj.jdbc.ConnectionImpl.initializePropsFromServer(ConnectionImpl.java:1301)
    at com.mysql.cj.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:958)
    at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:817)
    ... 13 more

To Reproduce Steps to reproduce the behavior:

  1. Create a project using quarkus-jdbc-mysql artefact
  2. generate native image
  3. run native image
  4. hit endpoint that retrieves data from mysql database.
jaikiran commented 5 years ago

It looks like the database server is responding with a timezone string Etc/GMT which the driver isn't able to translate back to GMT for some reason. One workaround you can do to get past this is to include serverTimezone=GMT in the JDBC URL string as a key/value property.

Is this reproducible only in native mode?

jaikiran commented 5 years ago

Having said that, I do see that there probably is a bug in here. I'll take a more detailed look in a while.

johnaohara commented 5 years ago

Yes, works fine in JVM mode. Probably a class/method has been dce'd during native image compilation

Sanne commented 5 years ago

Interesting; the ms-sql driver had a similar problem, but with charsets rather than timezones.

SubstrateVM attempts to not include all charsets to save some space - unless explicitly asked to add them. I would suspect it's attempting to do something similar with timezones.

jaikiran commented 5 years ago

We are seeing more and more of these issues in native-image. I looked around in the code of substratevm and there's really no way (even an hacky one) where we can override, in Quarkus, the timezones that are included in the native-image. So I decided to give it a try adding this as a feature within graal itself. I've raised a enhancement PR https://github.com/oracle/graal/pull/1819 with the initial proposal. Will see how it goes.

Sanne commented 5 years ago

I suspect a valid alternative could be to "grab" the timezone instances you need at build time; put them in a constant Map, retrieve them as needed at runtime.

In case of the JDBC driver, perhaps it would be possible to go one step further and skip the map: inject the instances by semi-initializing the driver during build.

The simples solution for the above issue is probably to have a substitution for the method which is failing the timezone lookup, and have it return the constant. That would solve this specific issue, but it doesn't solve the more general purpose problem of timezones across the board.

johnaohara commented 5 years ago

In this instance, how would you know what TZ's you need at build time? The error is coming from com.mysql.cj.jdbc.ConnectionImpl.initializePropsFromServer() so would need to have all TZ's that the server might return. What if you are running in public cloud, and a the db server is migrated to a different TZ?

jaikiran commented 5 years ago

The simples solution for the above issue is probably to have a substitution for the method which is failing the timezone lookup, and have it return the constant.

That's what the current TimeZone substitution in graal does[1]. It tries to find the requested timezone and when it doesn't find it (because the requested one isn't initialized into the native image), it defaults to GMT. In this specific MySQL issue, the MySQL driver has a (smart) check[2] to verify that the JDK doesn't do such "fallbacks" and when it finds cases like these, it raises this error from the driver. [1] https://github.com/oracle/graal/blob/master/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/jdk/TimeZoneSubstitutions.java#L72 [2] https://github.com/mysql/mysql-connector-j/blob/release/8.0/src/main/protocol-impl/java/com/mysql/cj/protocol/a/NativeProtocol.java#L2132

jaikiran commented 5 years ago

I suspect a valid alternative could be to "grab" the timezone instances you need at build time; put them in a constant Map, retrieve them as needed at runtime.

If/when the proposed enhancement to timezone support in graal is introduced, I think one way we (Quarkus) can use that is to have build step(s) which know certain timezones must be part of the target native image (at least the various variants of the GMT like Etc/GMT) and auto-include them when native-image is being created. That way users don't have to bother about adding it themselves, unless they want to.

johnaohara commented 5 years ago

I think one way we (Quarkus) can use that is to have build step(s) which know certain timezones must be part of the target native image (at least the various variants of the GMT like Etc/GMT) and auto-include them when native-image is being created.

I think we also need uesrs to be able to overwrite the list of included timezones, esp in the case where the user knows which timezone their DB is in, otherwise, we are at risk of increasing native image size with unnecessary extra classes

Sanne commented 5 years ago

In this instance, how would you know what TZ's you need at build time?

Yes I understand. It really is the same issue (conceptually) as I had with character sets: I don't know which charsets the DB will use, so we introduced a build item which registers them all.

That gives the best dev experience, but at cost of more bloat. An alternative would be to include them all by default (when an extension like this is included), but allow fine-tuning by having a configuration property to narrow them down.

Sanne commented 5 years ago

I'd suggest indeed to include GMT by default. It's going to be commonly used as it's often the recommended default - we could postpone the better solution to tune for the others.

Sanne commented 5 years ago

FYI another thing you might want to keep in mind: Hibernate ORM usually postpones building of its internal metamodel until after the first connection was established, so to gather metadata from the server. This metadata might include details such as these, but also details such as micro version of the DB to apply potentially needed workarounds.

This behaviour was disabled in Quarkus, as we need to build the metadata upfront. So we assume "defaults" and build the metadata from that - this is also the reason for the Dialect being a required configuration property, while in vanilla Hibernate it's auto-detected.

johnaohara commented 5 years ago

this is also the reason for the Dialect being a required configuration property, while in vanilla Hibernate it's auto-detected.

I did wonder about that. IIRC I switched from postgres to mysql and then needed to provide a Dialect. Is there a default assumption made about Postgres dialect?

Sanne commented 5 years ago

I see there's also -H:±IncludeAllTimeZones, as menioned by @jaikiran oracle/graal#1819 - so while we can't make a fine-grained choice, there's a solution at least.

Should we include it by default when e.g. the MySQL feature is activated? With such use cases, we can't safely know at build time actually which timezones should be included.

In such cases there's some tension between being nice and useable by default, vs allowing to optimise for small. I guess I'll bring it up on the mailing list.

johnaohara commented 5 years ago

Tested building with quarkus.native.additional-build-args=-H:+IncludeAllTimeZones the native image succesfully connects to the mysql database

Sanne commented 5 years ago

I did wonder about that. IIRC I switched from postgres to mysql and then needed to provide a Dialect. Is there a default assumption made about Postgres dialect?

We try to infer the Dialect from the driver. Both driver and Dialect being build-time only options, so if you change them you'll need to rebuild the app: remember the dialect has an impact on the ORM metadata and the SQL statements we generate as part of the metadata, and such metadata is prepared at build time.

Sanne commented 4 years ago

As discussed on the mailing list, we should have the MySQL extension set the "all timezones" flag by default.