Google-cloud-java: Spanner JDBC driver checks and fails hard when unknown properties provided

[saturnism]

Environment details

1. google-cloud-spanner-jdbc 1.7.0
2. OS type and version: osx
3. Java version: openjdk 11
4. google-cloud-java version(s): 1.7..0

Steps to reproduce

1. Create a Quarkus app
2. Use JPA w/ Hibernate and Spanner JDBC driver

Code example

persistence.xml

<persistence xmlns="http://xmlns.jcp.org/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
             xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence
http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd"
             version="2.1">
    <persistence-unit name="spanner-example">
        <provider>org.hibernate.jpa.HibernatePersistenceProvider</provider>

        <class>Person</class>

        <properties>
            <property name="javax.persistence.jdbc.url" value="jdbc:cloudspanner:/projects/wise-coyote-827/instances/demo/databases/demo" />
            <property name="javax.persistence.jdbc.driver" value="com.google.cloud.spanner.jdbc.JdbcDriver" />
            <property name="javax.persistence.jdbc.user" value="" />
            <property name="javax.persistence.jdbc.password" value="" />
            <property name="hibernate.dialect" value="com.google.cloud.spanner.hibernate.SpannerDialect"/>
            <property name="hibernate.connection.autocommit" value="true" />
            <property name="hibernate.hbm2ddl.auto" value="create-drop"/>
            <property name="show_sql" value="true"/>
        </properties>
    </persistence-unit>
</persistence>

This is reproducible in non-quarkus environment (e.g., Thorntail) by adding:

   <property name="hibernate.connection.provider_disables_autocommit" value="true"/>

@Entity
public class Person {
    @GeneratedValue(strategy = GenerationType.AUTO)
    @Type(type="uuid-char")
    @Id
    private UUID id;
    private String name;

    public UUID getId() {
        return id;
    }

    public void setId(UUID id) {
        this.id = id;
    }

    public String getName() {
        return name;
    }

    public void setName(String name) {
        this.name = name;
    }
}

@Path("/hi")
public class Say {

    @Inject EntityManager em;

    @GET
    @Produces(MediaType.TEXT_PLAIN)
    public String hello() {
        Person p = new Person();
        p.setName("Ray");
        em.persist(p);
        return "hello there";
    }
}

Stack trace

2019-10-31 17:45:22,186 WARN  [org.hib.orm.con.pooling] (main) HHH10001002: Using Hibernate built-in connection pool (not for production use!)
2019-10-31 17:45:22,188 INFO  [org.hib.orm.con.pooling] (main) HHH10001005: using driver [com.google.cloud.spanner.jdbc.JdbcDriver] at URL [jdbc:cloudspanner:/projects/wise-coyote-827/instances/demo/databases/demo]
2019-10-31 17:45:22,189 INFO  [org.hib.orm.con.pooling] (main) HHH10001001: Connection properties: {autocommit=true, provider_disables_autocommit=true}
2019-10-31 17:45:22,189 INFO  [org.hib.orm.con.pooling] (main) HHH10001003: Autocommit mode: true
2019-10-31 17:45:22,190 INFO  [org.hib.eng.jdb.con.int.DriverManagerConnectionProviderImpl] (main) HHH000115: Hibernate connection pool size: 20 (min=1)
2019-10-31 17:45:22,210 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (main) SQL Error: 3, SQLState: null
2019-10-31 17:45:22,210 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (main) INVALID_ARGUMENT: Invalid properties found in connection URI: provider_disables_autocommit
2019-10-31 17:45:22,214 INFO  [org.hib.ser.int.AbstractServiceRegistryImpl] (main) HHH000369: Error stopping service [class org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl]: java.lang.NullPointerException
    at org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl.stop(DriverManagerConnectionProviderImpl.java:207)
    at org.hibernate.service.internal.AbstractServiceRegistryImpl.stopService(AbstractServiceRegistryImpl.java:390)
    at org.hibernate.service.internal.AbstractServiceRegistryImpl.destroy(AbstractServiceRegistryImpl.java:373)
    at org.hibernate.service.internal.SessionFactoryServiceRegistryImpl.destroy(SessionFactoryServiceRegistryImpl.java:103)
    at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder$ServiceRegistryCloser.sessionFactoryClosed(FastBootEntityManagerFactoryBuilder.java:168)
    at org.hibernate.internal.SessionFactoryObserverChain.sessionFactoryClosed(SessionFactoryObserverChain.java:61)
    at org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:824)
    at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:404)
    at org.hibernate.boot.internal.SessionFactoryBuilderImpl.build(SessionFactoryBuilderImpl.java:462)
    at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:65)
    at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:54)
    at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
    at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
    at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:109)
    at io.quarkus.hibernate.orm.runtime.JPAConfig.startAll(JPAConfig.java:57)
    at io.quarkus.hibernate.orm.runtime.HibernateOrmRecorder.startAllPersistenceUnits(HibernateOrmRecorder.java:77)
    at io.quarkus.deployment.steps.HibernateOrmProcessor$startPersistenceUnits26.deploy_0(HibernateOrmProcessor$startPersistenceUnits26.zig:70)
    at io.quarkus.deployment.steps.HibernateOrmProcessor$startPersistenceUnits26.deploy(HibernateOrmProcessor$startPersistenceUnits26.zig:36)
    at io.quarkus.runner.ApplicationImpl1.doStart(ApplicationImpl1.zig:121)
    at io.quarkus.runtime.Application.start(Application.java:94)
    at io.quarkus.runner.RuntimeRunner.run(RuntimeRunner.java:143)
    at io.quarkus.dev.DevModeMain.doStart(DevModeMain.java:176)
    at io.quarkus.dev.DevModeMain.start(DevModeMain.java:94)
    at io.quarkus.dev.DevModeMain.main(DevModeMain.java:66)

javax.persistence.PersistenceException: [PersistenceUnit: spanner-example] Unable to build Hibernate SessionFactory
    at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.persistenceException(FastBootEntityManagerFactoryBuilder.java:113)
    at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:67)
    at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:54)
    at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
    at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
    at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:109)
    at io.quarkus.hibernate.orm.runtime.JPAConfig.startAll(JPAConfig.java:57)
    at io.quarkus.hibernate.orm.runtime.HibernateOrmRecorder.startAllPersistenceUnits(HibernateOrmRecorder.java:77)
    at io.quarkus.deployment.steps.HibernateOrmProcessor$startPersistenceUnits26.deploy_0(HibernateOrmProcessor$startPersistenceUnits26.zig:70)
    at io.quarkus.deployment.steps.HibernateOrmProcessor$startPersistenceUnits26.deploy(HibernateOrmProcessor$startPersistenceUnits26.zig:36)
    at io.quarkus.runner.ApplicationImpl1.doStart(ApplicationImpl1.zig:121)
    at io.quarkus.runtime.Application.start(Application.java:94)
    at io.quarkus.runner.RuntimeRunner.run(RuntimeRunner.java:143)
    at io.quarkus.dev.DevModeMain.doStart(DevModeMain.java:176)
    at io.quarkus.dev.DevModeMain.start(DevModeMain.java:94)
    at io.quarkus.dev.DevModeMain.main(DevModeMain.java:66)
Caused by: org.hibernate.exception.GenericJDBCException: Error calling Driver#connect
    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.connections.internal.BasicConnectionCreator.convertSqlException(BasicConnectionCreator.java:118)
    at org.hibernate.engine.jdbc.connections.internal.DriverConnectionCreator.makeConnection(DriverConnectionCreator.java:41)
    at org.hibernate.engine.jdbc.connections.internal.BasicConnectionCreator.createConnection(BasicConnectionCreator.java:58)
    at org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PooledConnections.addConnections(DriverManagerConnectionProviderImpl.java:321)
    at org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PooledConnections.<init>(DriverManagerConnectionProviderImpl.java:240)
    at org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PooledConnections.<init>(DriverManagerConnectionProviderImpl.java:218)
    at org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PooledConnections$Builder.build(DriverManagerConnectionProviderImpl.java:359)
    at org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl.buildPool(DriverManagerConnectionProviderImpl.java:98)
    at org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl.configure(DriverManagerConnectionProviderImpl.java:73)
    at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.configureService(StandardServiceRegistryImpl.java:107)
    at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:246)
    at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
    at org.hibernate.service.internal.SessionFactoryServiceRegistryImpl.getService(SessionFactoryServiceRegistryImpl.java:98)
    at org.hibernate.internal.SessionFactoryImpl.buildLocalConnectionAccess(SessionFactoryImpl.java:478)
    at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:315)
    at org.hibernate.boot.internal.SessionFactoryBuilderImpl.build(SessionFactoryBuilderImpl.java:462)
    at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:65)
    ... 14 more
Caused by: com.google.cloud.spanner.jdbc.JdbcSqlExceptionFactory$JdbcSqlExceptionImpl: INVALID_ARGUMENT: Invalid properties found in connection URI: provider_disables_autocommit
    at com.google.cloud.spanner.jdbc.JdbcSqlExceptionFactory.of(JdbcSqlExceptionFactory.java:296)
    at com.google.cloud.spanner.jdbc.JdbcDriver.connect(JdbcDriver.java:170)
    at org.hibernate.engine.jdbc.connections.internal.DriverConnectionCreator.makeConnection(DriverConnectionCreator.java:38)
    ... 29 more
Caused by: java.lang.IllegalArgumentException: Invalid properties found in connection URI: provider_disables_autocommit
    at com.google.common.base.Preconditions.checkArgument(Preconditions.java:141)
    at com.google.cloud.spanner.jdbc.ConnectionOptions.checkValidProperties(ConnectionOptions.java:482)
    at com.google.cloud.spanner.jdbc.ConnectionOptions$Builder.setUri(ConnectionOptions.java:285)
    at com.google.cloud.spanner.jdbc.JdbcDriver.connect(JdbcDriver.java:164)
    ... 30 more

External references such as API reference guides used

• ?

Any additional information below

/cc @meltsufin @olavloite

[saturnism]

/cc @Sanne @emmanuelbernard :)

[Sanne]

hi @saturnism !

So Quarkus with the Spanner driver? We've not tested that, and it will likely need its own Quarkus extension..

Also I suspect you might have better luck without using the persistence.xml, as you're side-stepping the use of our connection pool.

Many thanks I'll have a look at this next week

[saturnism]

@Sanne actually, this failed in non-Quarkus env w/ Thorntail if hibernate.connection.provider_disables_autocommit is configured. Whenever that's configured, it seems to propagate a provider_disables_autocommit property to JDBC driver (via connection string?) and our driver doesn't handle unknown properties.

Where is the provider_disables_autocommitJDBC property coming from? Does the driver need to handle this? Or does the Hibernate dialect need to translate this into a driver-specific property?

[saturnism]

If i switched to quarkus.hibernate-orm configuration, it actually works! (in JVM mode :)

But still, would like to know what the right behavior is when someone configures provider_disables_autocommit. Thanks!

quarkus.datasource.url=jdbc:cloudspanner:/projects/wise-coyote-827/instances/demo/databases/demo
quarkus.datasource.driver=com.google.cloud.spanner.jdbc.JdbcDriver
quarkus.datasource.username=
quarkus.datasource.password=
quarkus.datasource.min-size=2
quarkus.datasource.max-size=10

quarkus.hibernate-orm.dialect=com.google.cloud.spanner.hibernate.SpannerDialect

[Sanne]

Where is the provider_disables_autocommitJDBC property coming from?

provider_disables_autocommit is automatically applied in Quarkus, but it's expecting you to setup the datasource using Agroal.

Either way, it's not supposed to be passed on to the JDBC driver - I need to check why that happens.

FYI you're forcing Hibernate to use the embedded connection pool, which should be logging a scary banner - something like "not for production use" ? so... yes something is wrong in our code but your setup isn't entirely right either: don't do that :)

[saturnism]

@Sanne ah, i do see the warning. It wasn't scary enough I completely missed it 😄

[Sanne]

ahah ok :+1: Next time I'll write our source code in red...

I'm tracking this with both an issue on ORM and one in Quarkus as there's different aspects I'd want to cleanup.

• https://github.com/quarkusio/quarkus/issues/5103
• https://hibernate.atlassian.net/browse/HHH-13700

[saturnism]

Neat! FWIW, It seems like I was able to use the Panache repository too.

[Sanne]

It seems like I was able to use the Panache repository too.

Of course :)

What about compiling to native-images? I'd expect the Spanner JDBC driver to need an extension, but sometimes one could be lucky and not need any help. I couldn't try that yet, I might next week (postponing for real this time - HHH-13700 is resolved).

[olavloite]

Hi @saturnism
The Spanner JDBC driver currently explicitly checks that all properties that are passed to it are valid. This is not really needed for the driver to function properly, but is more of a 'service' to users if they accidentally misspell a property; Instead of giving the user unexpected behavior, it fails fast.

We could easily remove this check without breaking anything. Maybe we should just write out a warning instead :grin:

@skuruppu WDYT?

I just checked with a couple of other open source JDBC drivers, and they seem to just ignore unknown properties. The JDBC specification also does not specify anything about what a driver should do with an unknown property.

[saturnism]

@Sanne

What about compiling to native-images? I'd expect the Spanner JDBC driver to need an extension, but sometimes one could be lucky and not need any help.

I haven't tried it either. Since this most likely use gRPC behind the scenes, I'm expecting to run into issues: https://github.com/quarkusio/quarkus/issues/820

(and thnx for the quick fix!)

@olavloite

We could easily remove this check without breaking anything. Maybe we should just write out a warning instead

I thought the check was well intentioned. it helped us find this Hibernate issue :D I'm afraid that existing Hibernate users wouldn't be able to upgrade to a fix quick enough. And provider_disables_autocommit seems to be a recommended flag. I feel we have to ignore and warn as oppose to fail.

[Sanne]

I wouldn't rush in downgrading the severity to a WARN:
this flag is fairly new, so people on older versions who struggle to upgrade won't have it at all.

People on versions 5.2/5.3/5.4 might bump into this, but it should also be straight forward for them to either upgrade - or use the right connection pool ;)

The flag is also not set by default and rather obscure. We enable it by default only in Quarkus, and yet in Quarkus we control the version of Hibernate ORM so I'll simply make sure we get the fix in soon. And again.. people using the recommended connection pool won't even need the fix.

I thought the check was well intentioned. it helped us find this Hibernate issue :D

+1

[skuruppu]

Hi @saturnism
The Spanner JDBC driver currently explicitly checks that all properties that are passed to it are valid. This is not really needed for the driver to function properly, but is more of a 'service' to users if they accidentally misspell a property; Instead of giving the user unexpected behavior, it fails fast.

We could easily remove this check without breaking anything. Maybe we should just write out a warning instead 😁

@skuruppu WDYT?

I just checked with a couple of other open source JDBC drivers, and they seem to just ignore unknown properties. The JDBC specification also does not specify anything about what a driver should do with an unknown property.

Based on @Sanne's comment above, I think it's reasonable to leave the logic as is. But if we find users who have legitimate reasons for adding unknown properties (I can't think why anyone would want to do that) then we can consider changing the logic.

[olavloite]

Closing this for now as the conclusion is that we do not want to remove this check at the moment.