Merge pull request #149 from ebean-orm/feature/fix-close-busy-bug

Fix leak detection wrongly closing actively-in-use connections during…

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));
+  }
+
 }