Fix leak detection wrongly closing actively-in-use connections during pool reset

Problem

In production we saw this warning on a read-only pool:

 Connection [name[...] startTime[...] busySeconds[0] createdBy[null] stmt[select ...]] not found in BusyList?

busySeconds[0] shows the connection had just been checked out — it was not a leak, yet it had already been removed from the busy list.

Root cause

BusyConnectionBuffer.closeBusyConnections(leakTimeMinutes) decided whether a busy connection was a leak using lastUsedTime() — the time the connection was last returned to the pool (intended for trimming idle/free connections). The correct field is startUseTime() (the time the connection was checked out for its current use), which is even documented as "Used to detect busy connections that could be leaks" but was unused.

As a result, when reset() runs (read-only failover or a DB up/down heartbeat event), a connection that had sat idle in the free list longer than leakTimeMinutes and was then freshly checked out would be misidentified as a leak and force-closed mid-query. When the owning thread finished and called close(), its busy slot was already gone → "not found in BusyList?".

Fix

 - closeBusyConnections now uses startUseTime() (continuous checkout duration) instead of lastUsedTime(). Connections in genuine active use are left to be closed normally when returned, as the reset() Javadoc already intends.
 - Made PooledConnection.startUseTime() package-private.
 - Removed a stray System.out.println left in closeBusyConnection.
 - Moved the test-only pool == null guard above a TRACE log that dereferenced a null pstmtCache.

Tests

Added BusyConnectionBufferTest.closeBusyConnections_onlyClosesLeaks_notActiveConnections, which fails on the old behaviour and passes with the fix. Full module suite green (62 passed).

Author: rob-bygrave

ebean-datasource/src/main/java/io/ebean/datasource/pool/BusyConnectionBuffer.java

@@ -89,12 +89,11 @@ void closeBusyConnections(long leakTimeMinutes) {
     Log.debug("Closing busy connections using leakTimeMinutes {0}", leakTimeMinutes);
     for (int i = 0; i < slots.length; i++) {
       if (slots[i] != null) {
-        //tmp.add(slots[i]);
         PooledConnection pc = slots[i];
         //noinspection StatementWithEmptyBody
-        if (pc.lastUsedTime() > olderThanTime) {
-          // PooledConnection has been used recently or
-          // expected to be longRunning so not closing...
+        if (pc.startUseTime() > olderThanTime) {
+          // PooledConnection was checked out recently so it is in active
+          // use (not a leak) - leave it to be closed when returned to the pool
         } else {
           slots[i] = null;
           --size;
@@ -107,7 +106,6 @@ void closeBusyConnections(long leakTimeMinutes) {
   private void closeBusyConnection(PooledConnection pc) {
     try {
       Log.warn("DataSource closing busy connection? {0}", pc.fullDescription());
-      System.out.println("CLOSING busy connection: " + pc.fullDescription());
       pc.closeConnectionFully(false);
     } catch (Exception ex) {
       Log.error("Error when closing potentially leaked connection " + pc.description(), ex);

ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnection.java

@@ -232,12 +232,12 @@ String fullDescription() {
    * @param logErrors if false then don't log errors when closing
    */
   void closeConnectionFully(boolean logErrors) {
-    if (Log.isLoggable(System.Logger.Level.TRACE)) {
-      Log.trace("Closing Connection[{0}] reason[{1}], pstmtStats: {2}", name, closeReason, pstmtCache.description());
-    }
     if (pool == null) {
       return; // this can happen in tests only.
     }
+    if (Log.isLoggable(System.Logger.Level.TRACE)) {
+      Log.trace("Closing Connection[{0}] reason[{1}], pstmtStats: {2}", name, closeReason, pstmtCache.description());
+    }
     pool.pstmtCacheMetrics(pstmtCache);
     pool.closeConnectionFullyAsync(this, logErrors);
   }
@@ -585,7 +585,7 @@ boolean shouldTrim(long usedSince, long createdSince) {
    * <p>
    * Used to detect busy connections that could be leaks.
    */
-  private long startUseTime() {
+  long startUseTime() {
     return startUseTime;
   }
 

ebean-datasource/src/test/java/io/ebean/datasource/pool/BusyConnectionBufferTest.java

@@ -3,6 +3,8 @@
 import org.junit.jupiter.api.Test;
 
 import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertTrue;
 
 public class BusyConnectionBufferTest {
 
@@ -96,4 +98,29 @@ public void test_rotate() {
 
   }
 
+  @Test
+  public void closeBusyConnections_onlyClosesLeaks_notActiveConnections() {
+    BusyConnectionBuffer b = new BusyConnectionBuffer(4, 4);
+
+    // a connection that was checked out long ago and never returned (a leak)
+    PooledConnection leaked = new PooledConnection("leaked");
+    // a connection that sat idle in the free list for a while then was just
+    // checked out - it is in active use, not a leak (startUseTime is recent)
+    PooledConnection active = new PooledConnection("active");
+    active.resetForUse();
+
+    b.add(leaked);
+    b.add(active);
+    assertEquals(2, b.size());
+
+    // close connections considered leaked using a 1 minute leak time
+    b.closeBusyConnections(1);
+
+    // the leaked connection is removed, the active connection is retained
+    assertEquals(1, b.size());
+    // active is still held in its slot, leaked is gone
+    assertTrue(b.remove(active));
+    assertFalse(b.remove(leaked));
+  }
+
 }