Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Received "Connection is closed" for the Connection acquired throught ConnectionRunnable #9815

Closed
TheKSoni opened this issue Feb 10, 2020 · 9 comments

Comments

@TheKSoni
Copy link

Getting exception org.jooq.exception.DataAccessException: SQL [select pg_try_advisory_lock(?)]; Connection is closed for following code (Connection acquired inside a ConnectionRunnable):

dslContext.connection(connection -> {   //ConnectionRunnable
        boolean locked = DSL.using(connection).dsl()
                .fetchOne("select pg_try_advisory_lock(?)", 1) //acquire postgres 9.6 advisory lock
                .get(0, Boolean.class);
.
.
.
}

Exception log for JOOQ version 3.12.1:

org.jooq.exception.DataAccessException: SQL [select pg_try_advisory_lock(?)]; Connection is closed
        at org.jooq_3.12.1.DEFAULT.debug(Unknown Source) ~[?:?]
        at org.jooq.impl.Tools.translate(Tools.java:2717) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:755) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:383) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.AbstractResultQuery.fetchLazy(AbstractResultQuery.java:501) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.AbstractResultQuery.fetchLazy(AbstractResultQuery.java:470) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.AbstractResultQuery.fetchLazyNonAutoClosing(AbstractResultQuery.java:484) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.AbstractResultQuery.fetchOne(AbstractResultQuery.java:653) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.DefaultDSLContext.fetchOne(DefaultDSLContext.java:992) ~[org.jooq.jooq-3.12.1.jar:?]
           .
	   ./// Removing Logs of personal codebase
	   .
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_191]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_191]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty.netty-common-4.1.42.Final.jar:4.1.42.Final]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]
Caused by: java.sql.SQLException: Connection is closed
        at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:494) ~[com.zaxxer.HikariCP-3.4.1.jar:?]
        at com.sun.proxy.$Proxy49.prepareStatement(Unknown Source) ~[?:?]
        at com.zaxxer.hikari.pool.ProxyConnection.prepareStatement(ProxyConnection.java:316) ~[com.zaxxer.HikariCP-3.4.1.jar:?]
        at com.zaxxer.hikari.pool.HikariProxyConnection.prepareStatement(HikariProxyConnection.java) ~[com.zaxxer.HikariCP-3.4.1.jar:?]
        at org.jooq.impl.ProviderEnabledConnection.prepareStatement(ProviderEnabledConnection.java:109) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.SettingsEnabledConnection.prepareStatement(SettingsEnabledConnection.java:73) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.AbstractResultQuery.prepare(AbstractResultQuery.java:273) ~[org.jooq.jooq-3.12.1.jar:?]
        at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:336) ~[org.jooq.jooq-3.12.1.jar:?]
        ... 13 more

Versions:

  • jOOQ: 3.12.1 and 3.12.4. Log extract is for version 3.12.1
  • Java: 1.8.0_191
  • Database (include vendor): Postgres 9.6
  • OS: ubuntu
  • JDBC Driver (include name if inofficial driver): NA
  • Connection Pool library: HikariCP-3.4.1
@lukaseder
Copy link
Member

Thanks a lot for your report.

Are you doing anything else that you may have omitted, before or after the code snippet you've shown? Also, how do you setup/configure your dslContext instance?

@lukaseder
Copy link
Member

Notice that such problems where third party libraries like HikariCP are involved, are always a bit tricky to reproduce. Perhaps an MCVE could help here. We have a handy template for this: https://github.com/jOOQ/jOOQ-mcve

@lukaseder
Copy link
Member

For example, this example here does not allow for reproducing the problem:

SQLDialect family = SQLDialect.POSTGRES;

HikariConfig config = new HikariConfig();
HikariDataSource ds;

config.setJdbcUrl( "jdbc:postgresql://localhost:5432/postgres" );
config.setUsername( "postgres" );
config.setPassword( "test" );
config.addDataSourceProperty( "cachePrepStmts" , "true" );
config.addDataSourceProperty( "prepStmtCacheSize" , "250" );
config.addDataSourceProperty( "prepStmtCacheSqlLimit" , "2048" );
ds = new HikariDataSource( config );

DSLContext ctx = DSL.using(ds, family);
System.out.println(ctx.selectOne().fetch());

ctx.connection(connection -> {   //ConnectionRunnable
    boolean locked = DSL.using(connection).dsl()
            .fetchOne("select pg_try_advisory_lock(?)", 1) //acquire postgres 9.6 advisory lock
            .get(0, Boolean.class);
});

@TheKSoni
Copy link
Author

Hey @lukaseder. Sorry for delay, I was trying few more stuff.
I have created mcve at https://github.com/TheKSoni/vertx-jooq.

I am using Vertx with Jooq.
Connection runs fine if used on main thread (event-loop). (see TestMainVerticle.java)
But if we use it on blocking executor
vertx.executeBlocking(...) then Connection closes. (see TestBlockingExecutor.java)

I also tried acquiring Connection manually from ConnectionProvider, there also results were same, Connection closes on blocking executors.

Not sure, Could be due to queries running on different thread while using Blocking Executor?

@lukaseder
Copy link
Member

Thanks for the feedback. I'll have a look soon

@lukaseder
Copy link
Member

Looking into this now, thanks for your patience. I can reproduce the following using Maven:

13:34:20,389 [ERROR] Errors:
13:34:20,390 [ERROR]   TestBlockingExecutor.connectionProviderAcquireConnection_FailCase » Completion
13:34:20,395 [ERROR]   TestBlockingExecutor.connectionRunnable_FailCase » Completion org.jooq.excepti...
13:34:20,398 [INFO]
13:34:20,399 [ERROR] Tests run: 4, Failures: 0, Errors: 2, Skipped: 0

Unfortunately, it seems that the combination of Vertx, javax.inject, Lombok ensures that I can't debug this using Eclipse. After removing Lombok and javax.inject, I can work with the MCVE in IntelliJ

@lukaseder
Copy link
Member

lukaseder commented Aug 6, 2020

Interseting. In Common::acquireLocked, where the pg_try_advisory_lock(?) call is being made, I can run:

try {
  ResultSet rs = connection.createStatement().executeQuery("select 1");
  rs.next();
  System.out.println(rs.getInt(1));
}
catch (SQLException ignore) {
  ignore.printStackTrace();
}

But I cannot run:

try {
  ResultSet rs = connection.prepareStatement("select 1").executeQuery();
  rs.next();
  System.out.println(rs.getInt(1));
}
catch (SQLException ignore) {
  ignore.printStackTrace();
}

@lukaseder
Copy link
Member

lukaseder commented Aug 6, 2020

Of course, if I debug this code with breakpoints, then it works. I'd say, there's a race condition somewhere in all this asynchronous code, either in Vertx, HikariCP, or the PostgreSQL JDBC driver (I don't see where jOOQ could cause this, but will continue looking)...

@lukaseder
Copy link
Member

This seems to be a clue:

Multithreaded access to Connections was deprecated in JDBC and is not supported by HikariCP either. It definitely sounds like multiple threads are interacting with a single Connection instance at once.

HikariCP is fast enough that you can obtain a Connection, execute SQL, and then return it back to the pool many times in the course of a request.

It is a Best Practice to only hold Connections in local variables, preferably in a try-with-resources block, or possibly passed on the stack, but never in a class member field. If you follow that pattern it is virtually impossible to leak a Connection or accidentally share across threads.

Adding this line:

System.out.println(Thread.currentThread().getId());

To both TestBlockingExecutor::connectionProviderAcquireConnection_FailCase and Common::acquireLocked shows:

1
26

I.e. you're using the same connection instance on two separate threads. I'm not sure if this is really a reasonable restriction in HikariCP, but if you remove HikariCP from the equation, e.g. by specifying:

    // Create a single connection jOOQ DSLContext without connection pool
    dslContext = DSL.using("jdbc:postgresql://localhost/mcve", "postgres", "test");
    connectionProvider = dslContext.configuration().connectionProvider();

In the Common constructor, then all tests seem to pass. I don't recommend avoiding the connection pool, but this clearly shows that the problem is caused by HikariCP.

Perhaps this can all be prevented by using the following third party integration: https://github.com/jklingsporn/vertx-jooq

I hope this helps

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants