Nothing work with "Pool has been closed" error when no queries are executed for a while

[fiarabbit]

Description

1. Create EntityManager and do some query
2. Wait for a while ( > 60 sec)
3. Create EntityManager and do some query again
   The query in 3. will fail with IllegalStateException: Pool has been closed

Environment

Environment 1

com.google.cloud:google-cloud-spanner:1.46.0
com.google.cloud:google-cloud-spanner-hibernate-dialect:1.0.0
com.google.cloud:google-cloud-spanner-jdbc:1.11.0

Environment 2 (Also seen)

com.google.cloud:google-cloud-spanner:1.52.0
com.google.cloud:google-cloud-spanner-hibernate-dialect:1.2.0
com.google.cloud:google-cloud-spanner-jdbc:1.15.0

Code to Reproduce

import entity.SomeEntity;
import lombok.SneakyThrows;

import javax.persistence.EntityManager;
import javax.persistence.EntityManagerFactory;
import javax.persistence.Persistence;
import java.util.HashMap;
import java.util.List;
import java.util.UUID;

public class Main {
    @SneakyThrows
    public static void main(String[] args) {
        EntityManagerFactory emf = new Persistence().createEntityManagerFactory("somePersistentUnit", new HashMap() {{
            put("hibernate.connection.driver_class", "com.google.cloud.spanner.jdbc.JdbcDriver");
            put("hibernate.connection.url", "jdbc:cloudspanner:/projects/PROJECT_ID/instances/INSTANCE_ID/databases/DATABASE");
            put("hibernate.dialect", "com.google.cloud.spanner.hibernate.SpannerDialect");
            put("hibernate.ejb.loaded.classes", List.of(SomeEntity.class));
        }});
        EntityManager em;
        em = emf.createEntityManager();
        em.find(SomeEntity.class, "someKey");

        Thread.sleep(1000 * 300); // 300 sec > 60 sec
       
        em = emf.createEntityManager();
        em.find(SomeEntity.class, "someKey");
        Thread.sleep(1000 * 1000); // wait for background processes
    }
}

Error Message

Exception in thread "main" java.lang.IllegalStateException: Pool has been closed
	at com.google.cloud.spanner.SessionPool.getReadWriteSession(SessionPool.java:1292)
	at com.google.cloud.spanner.DatabaseClientImpl.getReadWriteSession(DatabaseClientImpl.java:57)
	at com.google.cloud.spanner.DatabaseClientImpl.transactionManager(DatabaseClientImpl.java:181)
	at com.google.cloud.spanner.jdbc.ReadWriteTransaction.<init>(ReadWriteTransaction.java:120)
	at com.google.cloud.spanner.jdbc.ReadWriteTransaction.<init>(ReadWriteTransaction.java:55)
	at com.google.cloud.spanner.jdbc.ReadWriteTransaction$Builder.build(ReadWriteTransaction.java:106)
	at com.google.cloud.spanner.jdbc.ConnectionImpl.createNewUnitOfWork(ConnectionImpl.java:835)
	at com.google.cloud.spanner.jdbc.ConnectionImpl.getCurrentUnitOfWorkOrStartNewUnitOfWork(ConnectionImpl.java:803)
	at com.google.cloud.spanner.jdbc.ConnectionImpl.internalExecuteQuery(ConnectionImpl.java:748)
	at com.google.cloud.spanner.jdbc.ConnectionImpl.parseAndExecuteQuery(ConnectionImpl.java:681)
	at com.google.cloud.spanner.jdbc.ConnectionImpl.executeQuery(ConnectionImpl.java:654)
	at com.google.cloud.spanner.jdbc.AbstractJdbcStatement.executeQuery(AbstractJdbcStatement.java:157)
	at com.google.cloud.spanner.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:55)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
	at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.getResultSet(AbstractLoadPlanBasedLoader.java:390)
	at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:163)
	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)
	at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3293)
	at bin.Main.main(Main.java:32)

Cause

This bug is caused by another bug in google-cloud-spanner-jdbc: com.google.cloud.spanner.jdbc.SpannerPool.SpannerPoolKey.hashCode() includes com.google.auth.Credentials in its hashCode target, but OAuth2Credentials.requestMetadata and OAuth2Credentials.temporaryAccess (the actual implementation of Credentials) is not initialized first but initialized via Credentials.getRequestMetadata() by mutation.
This intervenes SpannerPoolKey to work as "key" of java.util.HashMap, in which the key must not be modified after registration as the key.
This causes error in com.google.cloud.spanner.jdbc.SpannerPool.closeUnusedSpanners, which is called every 60 secs, and potentially cause the "Pool has been closed" error.

Workaround

The patch workaround is inserting

GoogleCredentials.getApplicationDefault().getRequestMetadata();

into some initializer block. This initializes global Credential object and prevents the incongruence. However, this might not work for rotation of OAuth2Credentials.temporaryAccess, so better idea might be necessary as permanent measures.

[meltsufin]

@fiarabbit Thanks for reporting the issue and providing code to reproduce.
@olavloite Are you aware of this issue in the Spanner JDBC driver?

[olavloite]

@fiarabbit Thanks for the detailed report.

@meltsufin No, I didn't know about it and it does surprise me a little, as I normally have a DBeaver instance opened with multiple JDBC connections open to Cloud Spanner databases for days in a row, without ever seeing this error. But with the extensive information in this issue I think I'll be able to reproduce and fix it.

I'll make a separate issue in the JDBC driver repository.

[meltsufin]

Thanks for a speedy response @olavloite. We will wait for your triage of the issue.

[olavloite]

@fiarabbit Would you mind sharing exactly how you are creating the credentials that you are using?

The reason that I am asking is that in most cases you would be using either com.google.auth.oauth2.UserCredentials or com.google.auth.oauth2.ServiceAccountCredentials. Both these classes override the hashCode() and equals(Object) methods and only use final fields in their implementations. This problem should therefore not be possible when using either of those.

If you are using an instance of either GoogleCredentials or OAuth2Credentials that you create yourself directly from an AccessToken, then I can see how this might happen. But if you use the credentials that are returned by GoogleCredentials.getApplicationDefault() you should as far as I can tell always get an instance of either UserCredentials or ServiceAccountCredentials.

EDIT:

I'm also very interested in any connection pooling or other JDBC connection management that might also be involved here. SpannerPool#closeUnusedSpanners() is the only method that will close any Spanner instances. It only does so if it determines that all connections related to it have been closed. It can only reach this line if at least one JDBC connection has been closed, but I don't see any logical places where any connections are closed in your reproduction example.

[fiarabbit]

@olavloite Thanks for your support.

1

The credential used in my case is com.google.auth.oauth2.UserCredentials.
As you can see in here, UserCredentials calls super.hashCode(), in which OAuth2Credentials.hashCode (here) is called and in this method, non-final field of requestMetadata and temporaryAccess are used to calculate hash.

2

You can see that jdbc-connection removal does not work out of hibernate context by the following script:

package bin;

import lombok.SneakyThrows;
import org.junit.jupiter.api.Test;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;

public class ConnectionLeakageTest {
    @Test
    @SneakyThrows
    void connectionLeakage() {
        try (Connection connection = DriverManager.getConnection("jdbc:cloudspanner:/projects/PROJECT_ID/instances/INSTANCE_ID/databases/DATABASE_ID")) {
            try (ResultSet rs = connection.createStatement().executeQuery("SOME QUERY"))) {
                while (rs.next()) {
                    System.out.println(rs.getString("some_column"));
                }
            }
            Thread.sleep(1000 * 300);
            try (ResultSet rs = connection.createStatement().executeQuery("THE OTHER QUERY")) {
                while (rs.next()) {
                    System.out.println(rs.getString("the_other_column"));
                }
            }
        }
    }
}

This does not throw any Exception, but you can find warning message

9月 15, 2020 9:57:59 午前 com.google.cloud.spanner.jdbc.SpannerPool removeConnection
警告: There is no Spanner registered for ConnectionOptions cloudspanner:/projects/PROJECT_ID/instances/INSTANCE_ID/databases/DATABASE_ID

[fiarabbit]

@olavloite

It only does so if it determines that all connections related to it have been closed.

1. For my issue, the actual implementation is not under the namespace of com.google.cloud.spanner.connection but the namespace of com.google.cloud.spanner.jdbc, although this might not relate to this issue.
2. I guess what happens is as below
   a. spanners.put(temporaryAccessNullCredential, spannerInstanceA)
   b. temporaryAccessNullCredential.setTemporaryAccess(...) // becomes the same hashCode to temporaryAccessNonNullCredential
   c. spanners.put(temporaryAccessNonNullCredential, spannerInstanceB)
   d. spannerPool.closeUnusedSpanners(temporaryAccessNullCredential) // actually spannerInstanceB is closed
   e. 'Pool has been closed'

[olavloite]

@fiarabbit See googleapis/java-spanner#430