Logging changes

pom.xml

@@ -43,11 +43,11 @@
       <mockito.version>3.7.7</mockito.version>
       <pax.exam.version>4.13.5</pax.exam.version>
       <pax.url.version>2.5.4</pax.url.version>
-      <postgresql.version>42.5.1</postgresql.version>
+      <postgresql.version>42.7.4</postgresql.version>
       <log4j.version>2.18.0</log4j.version>
       <slf4j.version>1.7.36</slf4j.version>
       <commons.csv.version>1.5</commons.csv.version>
-      <h2.version>2.1.212</h2.version>
+      <h2.version>2.3.232</h2.version>
       <junit.version>4.13.2</junit.version>
       <testcontainers.version>1.20.1</testcontainers.version>
    </properties>

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

@@ -481,7 +481,7 @@ int[] getPoolStateCounts()
    private PoolEntry createPoolEntry()
    {
       try {
-         final var poolEntry = newPoolEntry();
+         final var poolEntry = newPoolEntry(getTotalConnections() == 0);
 
          final var maxLifetime = config.getMaxLifetime();
          if (maxLifetime > 0) {
@@ -503,8 +503,7 @@ private PoolEntry createPoolEntry()
       }
       catch (ConnectionSetupException e) {
          if (poolState == POOL_NORMAL) { // we check POOL_NORMAL to avoid a flood of messages if shutdown() is running concurrently
-            logger.error("{} - Error thrown while acquiring connection from data source", poolName, e.getCause());
-            lastConnectionFailure.set(e);
+            logger.debug("{} - Error thrown while acquiring connection from data source", poolName, e.getCause());
          }
       }
       catch (Exception e) {

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

@@ -41,13 +41,13 @@
 import java.util.concurrent.Executors;
 import java.util.concurrent.ThreadFactory;
 import java.util.concurrent.ThreadPoolExecutor;
+import java.util.concurrent.atomic.AtomicLong;
 import java.util.concurrent.atomic.AtomicReference;
 
 import static com.zaxxer.hikari.pool.ProxyConnection.*;
 import static com.zaxxer.hikari.util.ClockSource.*;
 import static com.zaxxer.hikari.util.UtilityElf.createInstance;
-import static java.util.concurrent.TimeUnit.MILLISECONDS;
-import static java.util.concurrent.TimeUnit.SECONDS;
+import static java.util.concurrent.TimeUnit.*;
 
 abstract class PoolBase
 {
@@ -60,6 +60,7 @@ abstract class PoolBase
 
    volatile String catalog;
    final AtomicReference<Exception> lastConnectionFailure;
+   final AtomicLong connectionFailureTimestamp;
 
    long connectionTimeout;
    long validationTimeout;
@@ -110,6 +111,7 @@ abstract class PoolBase
       this.connectionTimeout = config.getConnectionTimeout();
       this.validationTimeout = config.getValidationTimeout();
       this.lastConnectionFailure = new AtomicReference<>();
+      this.connectionFailureTimestamp = new AtomicLong();
 
       initializeDataSource();
    }
@@ -198,9 +200,9 @@ public DataSource getUnwrappedDataSource()
    //                         PoolEntry methods
    // ***********************************************************************
 
-   PoolEntry newPoolEntry() throws Exception
+   PoolEntry newPoolEntry(final boolean isEmptyPool) throws Exception
    {
-      return new PoolEntry(newConnection(), this, isReadOnly, isAutoCommit);
+      return new PoolEntry(newConnection(isEmptyPool), this, isReadOnly, isAutoCommit);
    }
 
    void resetConnectionState(final Connection connection, final ProxyConnection proxyConnection, final int dirtyBits) throws SQLException
@@ -347,9 +349,9 @@ else if (dataSourceJNDI != null && ds == null) {
    /**
     * Obtain connection from data source.
     *
-    * @return a Connection connection
+    * @return a Connection
     */
-   private Connection newConnection() throws Exception
+   private Connection newConnection(final boolean isEmptyPool) throws Exception
    {
       final var start = currentTime();
       final var id = java.util.UUID.randomUUID();
@@ -360,24 +362,32 @@ private Connection newConnection() throws Exception
          final var username = credentials.getUsername();
          final var password = credentials.getPassword();
 
-         logger.debug("{} - Attempting to create/setup new connection: {} ", poolName, id.toString());
-         
+         logger.debug("{} - Attempting to create/setup new connection ({})", poolName, id);
+
          connection = (username == null) ? dataSource.getConnection() : dataSource.getConnection(username, password);
          if (connection == null) {
             throw new SQLTransientConnectionException("DataSource returned null unexpectedly");
          }
 
          setupConnection(connection);
-         logger.debug("{} - Established new connection: {}", poolName, id);
+
          lastConnectionFailure.set(null);
+         connectionFailureTimestamp.set(0);
+
+         logger.debug("{} - Established new connection ({})", poolName, id);
          return connection;
       }
       catch (Exception e) {
-         if (connection != null) {
-            quietlyCloseConnection(connection, "(Failed to create/setup connection for id:".concat(id.toString()));
+         logger.debug("{} - Failed to create/setup connection ({}): {}", poolName, id, e.getMessage());
+
+         connectionFailureTimestamp.compareAndSet(0, start);
+         if (isEmptyPool && elapsedMillis(connectionFailureTimestamp.get()) > MINUTES.toMillis(1)) {
+            logger.warn("{} - Pool is empty, failed to create/setup connection ({})", poolName, id, e);
+            connectionFailureTimestamp.set(0);
          }
-         else if (getLastConnectionFailure() == null) {
-            logger.debug("{} - Failed to create/setup connection: {} {}", poolName, e.getMessage(), id.toString());
+
+         if (connection != null) {
+            quietlyCloseConnection(connection, "(Failed to create/setup connection (".concat(id.toString()).concat(")"));
          }
 
          lastConnectionFailure.set(e);
@@ -392,7 +402,7 @@ else if (getLastConnectionFailure() == null) {
    }
 
    /**
-    * Setup a connection initial state.
+    * Set up a connection initial state.
     *
     * @param connection a Connection
     * @throws ConnectionSetupException thrown if any exception is encountered
@@ -634,7 +644,7 @@ private void setLoginTimeout(final DataSource dataSource)
    /**
     * This will create a string for debug logging. Given a set of "reset bits", this
     * method will return a concatenated string, for example:
-    *
+    * <p
     * Input : 0b00110
     * Output: "autoCommit, isolation"
     *

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

@@ -72,15 +72,15 @@ public void testConcurrentBag() throws Exception
       try (ConcurrentBag<PoolEntry> bag = new ConcurrentBag<>(x -> CompletableFuture.completedFuture(Boolean.TRUE))) {
          assertEquals(0, bag.values(8).size());
 
-         PoolEntry reserved = pool.newPoolEntry();
+         PoolEntry reserved = pool.newPoolEntry(false);
          bag.add(reserved);
          bag.reserve(reserved);      // reserved
 
-         PoolEntry inuse = pool.newPoolEntry();
+         PoolEntry inuse = pool.newPoolEntry(false);
          bag.add(inuse);
          bag.borrow(2, MILLISECONDS); // in use
 
-         PoolEntry notinuse = pool.newPoolEntry();
+         PoolEntry notinuse = pool.newPoolEntry(false);
          bag.add(notinuse); // not in use
 
          bag.dumpState();
@@ -103,7 +103,7 @@ public void testConcurrentBag() throws Exception
 
          bag.close();
          try {
-            PoolEntry bagEntry = pool.newPoolEntry();
+            PoolEntry bagEntry = pool.newPoolEntry(false);
             bag.add(bagEntry);
             assertNotEquals(bagEntry, bag.borrow(100, MILLISECONDS));
          }