Socket timeout not working when uprading to postgres jdbc driver 42.2.10+

Question

I have a java application that is deployed into Tomcat as WAR file. Datasource to Postgres DB is looked up as JNDI resource and Tomcat's default connection pool is used - which is DBCP 2. Resource in context.xml is defined like this

<Resource name="jdbc/test" auth="Container" type="javax.sql.DataSource"
              maxTotal="50" maxIdle="15" maxWaitMillis="10000"
              username="test" password="test"
              driverClassName="org.postgresql.Driver"
              defaultReadOnly="true"
              url="jdbc:postgresql://localhost:5432/test?socketTimeout=45"
              validationQuery="SELECT 1" testOnBorrow="true" />

There is a class called DbConnectionChecker, which uses a Executors.newSingleThreadScheduledExecutor() executor to check if DB is alive every 3 seconds.

public class DbConnectionChecker {

    private static final Logger LOG = LoggerFactory.getLogger(DbConnectionChecker.class);
    private final ScheduledExecutorService taskExecutor;

    private String name;

    private DataSource dataSource;

    private volatile boolean enabled = false;

    public DbConnectionChecker(String name, DataSource dataSource, ScheduledExecutorService taskExecutor, Runnable onConnectionOk,
            Runnable onConnectionNoOk) {
        this.name = name;
        this.dataSource = dataSource;
        this.taskExecutor = taskExecutor;
        this.taskExecutor.scheduleAtFixedRate(() -> pingConnection(onConnectionOk, onConnectionNoOk), 0l, 3000l, TimeUnit.MILLISECONDS);
    }

    public void start() {
        LOG.info("Starting to check {} connection", name);
        enabled = true;

    }

    public void shutdown() {
        taskExecutor.shutdown();
    }

    public void stop() {
        enabled = false;
    }

    public void pingConnection(Runnable onConnectionOk, Runnable onConnectionNoOk) {
        if (!enabled) {
            return;
        }
        try (Connection connection = dataSource.getConnection(); PreparedStatement preparedStatement = connection.prepareStatement("SELECT 1")) {
            preparedStatement.executeQuery();
            LOG.info("Connection {} OK...", name);
            onConnectionOk.run();
        } catch (Exception e) {
            LOG.info("Connection {} couldn't be created...", name);
            onConnectionNoOk.run();
        }
    }
}

When everything is started I can sse a logline Connection test OK..., printed into log every 3 seconds. So far so good.

Now I try to simulate network failure and unreachable database. I will change iptables and cut off connections to local Postgres.

sudo iptables -A INPUT -i lo -p tcp --dport 5432 -j DROP

With postgres-42.2.9 everything works as expected and I will get a logline Connection test couldn't be created... in a minute or so. After upgrade to postgres-42.2.10+ - and I have tested all newest minor versions, this breaks. Executor's thread is stuck in some socket call and wait there for aprox. 30minutes before releasing. Relevant stack trace is here

pool-14-thread-1@12955" prio=5 tid=0x45 nid=NA runnable"pool-14-thread-1@12955" prio=5 tid=0x45 nid=NA runnable  java.lang.Thread.State: RUNNABLE   at
java.net.SocketInputStream.socketRead0(SocketInputStream.java:-1)   at
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)   at
java.net.SocketInputStream.read(SocketInputStream.java:171)   at
java.net.SocketInputStream.read(SocketInputStream.java:141)   at
sun.security.ssl.InputRecord.readFully(InputRecord.java:465)   at
sun.security.ssl.InputRecord.read(InputRecord.java:503)   at
sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)   - locked <0x3e55> (a java.lang.Object)   at
sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933)   at
sun.security.ssl.AppInputStream.read(AppInputStream.java:105)   - locked <0x3e37> (a sun.security.ssl.AppInputStream)   at
org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:161)   at
org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)   at
org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:113)   at
org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)   at
org.postgresql.core.PGStream.receiveChar(PGStream.java:370)   at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2043)   at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:312)   - locked <0x3e3a> (a org.postgresql.core.v3.QueryExecutorImpl)   at
org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:448)   at
org.postgresql.jdbc.PgStatement.execute(PgStatement.java:369)   at
org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:153)   at
org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:103)   at
org.apache.tomcat.dbcp.dbcp2.PoolableConnection.validate(PoolableConnection.java:287)   at
org.apache.tomcat.dbcp.dbcp2.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:630)   at
org.apache.tomcat.dbcp.dbcp2.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:648)   at
org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:476)   at
org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:353)   at
org.apache.tomcat.dbcp.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)   at
org.apache.tomcat.dbcp.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:753)   at
com...db.DbConnectionChecker.pingConnection(DbConnectionChecker.java:49)   at
com...db.DbConnectionChecker.lambda$new$0(DbConnectionChecker.java:28)   at
com...db.DbConnectionChecker$$Lambda$250.1931785101.run(Unknown Source:-1)   at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)   at
java.util.concurrent.FutureTask.runAndReset$$$capture(FutureTask.java:308)   at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:-1)   at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)   at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)   at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)   at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)   at
java.lang.Thread.run(Thread.java:748) 

Is there some issue with latest postgres drivers? Are there any timeouts - set by default, that I am not aware of?

Answer 1

I got the answer in pgjdbc's github issue. You can reference this issue.