Fix idle timeout tests, sleep too tight to idle threshold. (+8 squash…

…ed commits)

Squashed commits:
[e0ec6b7] Fix idle timeout tests, sleep too tight to idle threshold.
[c40a690] Fix idle timeout tests, sleep too tight to idle threshold.
[7a0a156] Synchronize idleTimeout manipulation methods
[bab9f64] Fix idle timeout tests, sleep too tight to idle threshold.
[4ee5259] Add missing ) character in message
[e9d49fc] Enable debug logging for tests.
[89c1ab4] Fix idle timeout tests, sleep too tight to idle threshold.
[aa06bb8] Simplify pool entry last-accessed time handling.

src/main/java/com/zaxxer/hikari/HikariConfig.java

@@ -194,14 +194,14 @@ else if (connectionTimeoutMs < SOFT_TIMEOUT_FLOOR) {
 
    /** {@inheritDoc} */
    @Override
-   public long getIdleTimeout()
+   public synchronized long getIdleTimeout()
    {
       return idleTimeout;
    }
 
    /** {@inheritDoc} */
    @Override
-   public void setIdleTimeout(long idleTimeoutMs)
+   public synchronized void setIdleTimeout(long idleTimeoutMs)
    {
       if (idleTimeoutMs < 0) {
          throw new IllegalArgumentException("idleTimeout cannot be negative");

src/main/java/com/zaxxer/hikari/pool/HikariPool.java

@@ -173,7 +173,7 @@ public Connection getConnection(final long hardTimeout) throws SQLException
             }
             else {
                metricsTracker.recordBorrowStats(poolEntry, startTime);
-               return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry), now);
+               return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry));
             }
          } while (timeout > 0L);
 
@@ -518,7 +518,7 @@ private synchronized void fillPool(final boolean isAfterAdd)
          addConnectionExecutor.submit(isAfterAdd ? postFillPoolEntryCreator : poolEntryCreator);
       }
       else if (isAfterAdd) {
-         logger.debug("{} - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth={}.", poolName, queueDepth);
+         logger.debug("{} - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth={}).", poolName, queueDepth);
       }
    }
 
@@ -814,6 +814,7 @@ else if (now > plusMillis(previous, (3 * housekeepingPeriodMs) / 2)) {
                final var notInUse = connectionBag.values(STATE_NOT_IN_USE);
                var toRemove = notInUse.size() - config.getMinimumIdle();
                for (PoolEntry entry : notInUse) {
+                  logger.debug("Checking connection entry: {}", entry);
                   if (toRemove > 0 && elapsedMillis(entry.lastAccessed, now) > idleTimeout && connectionBag.reserve(entry)) {
                      closeConnection(entry, "(connection has passed idleTimeout)");
                      toRemove--;

src/main/java/com/zaxxer/hikari/pool/PoolEntry.java

@@ -27,6 +27,7 @@
 import java.util.concurrent.atomic.AtomicIntegerFieldUpdater;
 
 import static com.zaxxer.hikari.util.ClockSource.*;
+import static com.zaxxer.hikari.util.ClockSource.currentTime;
 
 /**
  * Entry used in the ConcurrentBag to track Connection instances.
@@ -72,13 +73,11 @@ final class PoolEntry implements IConcurrentBagEntry
 
    /**
     * Release this entry back to the pool.
-    *
-    * @param lastAccessed last access time-stamp
     */
-   void recycle(final long lastAccessed)
+   void recycle()
    {
       if (connection != null) {
-         this.lastAccessed = lastAccessed;
+         this.lastAccessed = currentTime();
          hikariPool.recycle(this);
       }
    }
@@ -97,9 +96,9 @@ public void setKeepalive(ScheduledFuture<?> keepalive) {
       this.keepalive = keepalive;
    }
 
-   Connection createProxyConnection(final ProxyLeakTask leakTask, final long now)
+   Connection createProxyConnection(final ProxyLeakTask leakTask)
    {
-      return ProxyFactory.getProxyConnection(this, connection, openStatements, leakTask, now, isReadOnly, isAutoCommit);
+      return ProxyFactory.getProxyConnection(this, connection, openStatements, leakTask, isReadOnly, isAutoCommit);
    }
 
    void resetConnectionState(final ProxyConnection proxyConnection, final int dirtyBits) throws SQLException

src/main/java/com/zaxxer/hikari/pool/ProxyConnection.java

@@ -28,14 +28,12 @@
 import java.util.concurrent.Executor;
 
 import static com.zaxxer.hikari.SQLExceptionOverride.Override.DO_NOT_EVICT;
-import static com.zaxxer.hikari.util.ClockSource.currentTime;
 
 /**
  * This is the proxy class for java.sql.Connection.
  *
  * @author Brett Wooldridge
  */
-@SuppressWarnings("ClassEscapesDefinedScope")
 public abstract class ProxyConnection implements Connection
 {
    static final int DIRTY_BIT_READONLY   = 0b000001;
@@ -57,7 +55,6 @@ public abstract class ProxyConnection implements Connection
    private final FastList<Statement> openStatements;
 
    private int dirtyBits;
-   private long lastAccess;
    private boolean isCommitStateDirty;
 
    private boolean isReadOnly;
@@ -89,14 +86,12 @@ protected ProxyConnection(final PoolEntry poolEntry,
                              final Connection connection,
                              final FastList<Statement> openStatements,
                              final ProxyLeakTask leakTask,
-                             final long now,
                              final boolean isReadOnly,
                              final boolean isAutoCommit) {
       this.poolEntry = poolEntry;
       this.delegate = connection;
       this.openStatements = openStatements;
       this.leakTask = leakTask;
-      this.lastAccess = now;
       this.isReadOnly = isReadOnly;
       this.isAutoCommit = isAutoCommit;
    }
@@ -196,10 +191,7 @@ final synchronized void untrackStatement(final Statement statement)
 
    final void markCommitStateDirty()
    {
-      if (isAutoCommit) {
-         lastAccess = currentTime();
-      }
-      else {
+      if (!isAutoCommit) {
          isCommitStateDirty = true;
       }
    }
@@ -255,13 +247,11 @@ public final void close() throws SQLException
          try {
             if (isCommitStateDirty && !isAutoCommit) {
                delegate.rollback();
-               lastAccess = currentTime();
                LOGGER.debug("{} - Executed rollback on connection {} due to dirty commit state on close().", poolEntry.getPoolName(), delegate);
             }
 
             if (dirtyBits != 0) {
                poolEntry.resetConnectionState(this, dirtyBits);
-               lastAccess = currentTime();
             }
 
             delegate.clearWarnings();
@@ -274,7 +264,7 @@ public final void close() throws SQLException
          }
          finally {
             delegate = ClosedConnection.CLOSED_CONNECTION;
-            poolEntry.recycle(lastAccess);
+            poolEntry.recycle();
          }
       }
    }
@@ -386,7 +376,6 @@ public void commit() throws SQLException
    {
       delegate.commit();
       isCommitStateDirty = false;
-      lastAccess = currentTime();
    }
 
    /** {@inheritDoc} */
@@ -395,7 +384,6 @@ public void rollback() throws SQLException
    {
       delegate.rollback();
       isCommitStateDirty = false;
-      lastAccess = currentTime();
    }
 
    /** {@inheritDoc} */
@@ -404,7 +392,6 @@ public void rollback(Savepoint savepoint) throws SQLException
    {
       delegate.rollback(savepoint);
       isCommitStateDirty = false;
-      lastAccess = currentTime();
    }
 
    /** {@inheritDoc} */

src/main/java/com/zaxxer/hikari/pool/ProxyFactory.java

@@ -39,12 +39,11 @@ private ProxyFactory()
     * @param connection the raw database Connection
     * @param openStatements a reusable list to track open Statement instances
     * @param leakTask the ProxyLeakTask for this connection
-    * @param now the current timestamp
     * @param isReadOnly the default readOnly state of the connection
     * @param isAutoCommit the default autoCommit state of the connection
     * @return a proxy that wraps the specified {@link Connection}
     */
-   static ProxyConnection getProxyConnection(final PoolEntry poolEntry, final Connection connection, final FastList<Statement> openStatements, final ProxyLeakTask leakTask, final long now, final boolean isReadOnly, final boolean isAutoCommit)
+   static ProxyConnection getProxyConnection(final PoolEntry poolEntry, final Connection connection, final FastList<Statement> openStatements, final ProxyLeakTask leakTask, final boolean isReadOnly, final boolean isAutoCommit)
    {
       // Body is replaced (injected) by JavassistProxyFactory
       throw new IllegalStateException("You need to run the CLI build and you need target/classes in your classpath to run.");

src/test/java/com/zaxxer/hikari/db/BasicPoolTest.java

@@ -77,14 +77,14 @@ public void testIdleTimeout() throws InterruptedException, SQLException
       System.setProperty("com.zaxxer.hikari.housekeeping.periodMs", "1000");
 
       try (HikariDataSource ds = new HikariDataSource(config)) {
+         getUnsealedConfig(ds).setIdleTimeout(3000);
+
          System.clearProperty("com.zaxxer.hikari.housekeeping.periodMs");
 
          SECONDS.sleep(1);
 
          HikariPool pool = getPool(ds);
 
-         getUnsealedConfig(ds).setIdleTimeout(3000);
-
          assertEquals("Total connections not as expected", 5, pool.getTotalConnections());
          assertEquals("Idle connections not as expected", 5, pool.getIdleConnections());
 
@@ -99,7 +99,7 @@ public void testIdleTimeout() throws InterruptedException, SQLException
 
          assertEquals("Idle connections not as expected", 6, pool.getIdleConnections());
 
-         SECONDS.sleep(2);
+         MILLISECONDS.sleep(3000);
 
          assertEquals("Third total connections not as expected", 5, pool.getTotalConnections());
          assertEquals("Third idle connections not as expected", 5, pool.getIdleConnections());

src/test/java/com/zaxxer/hikari/pool/TestJavassistCodegen.java

@@ -48,7 +48,6 @@ public void testCodegen() throws Exception {
             connection,
             fastList,
             null /*leakTask*/,
-            0L /*now*/,
             Boolean.FALSE /*isReadOnly*/,
             Boolean.FALSE /*isAutoCommit*/);
       Assert.assertNotNull(proxyConnection);

src/test/java/com/zaxxer/hikari/pool/TestMBean.java

@@ -86,7 +86,7 @@ public void testMBeanReporting() throws SQLException, InterruptedException, Malf
             assertEquals(4, hikariPoolMXBean.getTotalConnections());
          }
 
-         TimeUnit.SECONDS.sleep(2);
+         TimeUnit.SECONDS.sleep(4);
 
          assertEquals(0, hikariPoolMXBean.getActiveConnections());
          assertEquals(3, hikariPoolMXBean.getIdleConnections());

src/test/resources/log4j2-test.xml

@@ -6,7 +6,7 @@
     </Console>
   </appenders>
   <Loggers>
-    <Root level="info">
+    <Root level="debug">
       <AppenderRef ref="Console" />
     </Root>
   </Loggers>