Merge pull request #107 from FOCONIS/db2-tests

Fix leaking connections when it was not possible to close them.

Author: rbygrave

.github/workflows/build.yml

@@ -24,7 +24,7 @@ jobs:
         java-version: ${{ matrix.java_version }}
         distribution: 'zulu'
     - name: Maven cache
-      uses: actions/cache@v2
+      uses: actions/cache@v4
       env:
         cache-name: maven-cache
       with:

ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceBuilder.java

@@ -749,6 +749,27 @@ default DataSourceBuilder initDatabaseForPlatform(String platform) {
    */
   DataSourceBuilder loadSettings(Properties properties, String poolName);
 
+
+  /**
+   * When enabled, the datasource enforces a clean close. This means, if you close a possible dirty
+   * connection, that was not committed or rolled back, an exception is thrown.
+   * <p>
+   * When disabled, the situation is logged as warning.
+   * <p>
+   * This option has no effect on readonly or autocommit connections.
+   * <p>
+   * Note: It is recommended to enable this option in tests/test systems to find possible
+   * programming errors. See https://github.com/ebean-orm/ebean-datasource/issues/116 for details.
+   */
+  DataSourceBuilder enforceCleanClose(boolean enforceCleanClose);
+
+  /**
+   * When <code>true</code>, an exception is thrown when a dirty connection is closed.
+   * <p>
+   * See {@link #enforceCleanClose(boolean)}.
+   */
+  boolean enforceCleanClose();
+
   /**
    * The settings of the DataSourceBuilder. Provides getters/accessors
    * to read the configured properties of this DataSourceBuilder.

ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceConfig.java

@@ -83,6 +83,7 @@ public class DataSourceConfig implements DataSourceBuilder.Settings {
   private String applicationName;
   private boolean shutdownOnJvmExit;
   private boolean validateOnHeartbeat = !System.getenv().containsKey("LAMBDA_TASK_ROOT");
+  private boolean enforceCleanClose;
 
   @Override
   public Settings settings() {
@@ -144,6 +145,7 @@ public DataSourceConfig copy() {
     copy.initSql = initSql;
     copy.alert = alert;
     copy.listener = listener;
+    copy.enforceCleanClose = enforceCleanClose;
     return copy;
   }
 
@@ -798,6 +800,8 @@ private void loadSettings(ConfigPropertiesHelper properties) {
     offline = properties.getBoolean("offline", offline);
     shutdownOnJvmExit = properties.getBoolean("shutdownOnJvmExit", shutdownOnJvmExit);
     validateOnHeartbeat = properties.getBoolean("validateOnHeartbeat", validateOnHeartbeat);
+    enforceCleanClose = properties.getBoolean("enforceCleanClose", enforceCleanClose);
+
 
     String isoLevel = properties.get("isolationLevel", _isolationLevel(isolationLevel));
     this.isolationLevel = _isolationLevel(isoLevel);
@@ -846,6 +850,17 @@ Map<String, String> parseCustom(String customProperties) {
     return propertyMap;
   }
 
+  @Override
+  public DataSourceBuilder enforceCleanClose(boolean enforceCleanClose) {
+    this.enforceCleanClose = enforceCleanClose;
+    return this;
+  }
+
+  @Override
+  public boolean enforceCleanClose() {
+    return enforceCleanClose;
+  }
+
   /**
    * Return the isolation level description from the associated Connection int value.
    */

ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourcePoolListener.java

@@ -17,11 +17,12 @@ public interface DataSourcePoolListener {
   /**
    * Called after a connection has been retrieved from the connection pool
    */
-  void onAfterBorrowConnection(Connection connection);
+  default void onAfterBorrowConnection(Connection connection) {}
 
   /**
    * Called before a connection will be put back to the connection pool
    */
-  void onBeforeReturnConnection(Connection connection);
+  default void onBeforeReturnConnection(Connection connection) {}
+
 
 }

ebean-datasource/pom.xml

@@ -76,6 +76,13 @@
       <scope>test</scope>
     </dependency>
 
+    <dependency>
+      <groupId>com.ibm.db2</groupId>
+      <artifactId>jcc</artifactId>
+      <version>11.5.9.0</version>
+      <scope>test</scope>
+    </dependency>
+
   </dependencies>
 
 </project>

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

@@ -55,6 +55,7 @@ final class ConnectionPool implements DataSourcePool {
   private final boolean failOnStart;
   private final int maxInactiveMillis;
   private final long validateStaleMillis;
+  private final boolean enforceCleanClose;
   /**
    * Max age a connection is allowed in millis.
    * A value of 0 means no limit (no trimming based on max age).
@@ -128,6 +129,7 @@ final class ConnectionPool implements DataSourcePool {
     this.user = params.getUsername();
     this.shutdownOnJvmExit = params.isShutdownOnJvmExit();
     this.source = DriverDataSource.of(name, params);
+    this.enforceCleanClose = params.enforceCleanClose();
     if (!params.isOffline()) {
       init();
     }
@@ -516,6 +518,13 @@ boolean invalidConnection(PooledConnection conn) {
     }
   }
 
+  /**
+   * Fail hard in close() when there is uncommitted work. This is for debugging to find wrong code.
+   */
+  boolean enforceCleanClose() {
+    return enforceCleanClose;
+  }
+
   /**
    * Called by the PooledConnection themselves, returning themselves to the
    * pool when they have been finished with.

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

@@ -219,7 +219,7 @@ String description() {
   }
 
   String fullDescription() {
-    return "name[" + name + "] startTime[" + startUseTime() + "] busySeconds[" + busySeconds() + "] stackTrace[" + stackTraceAsString() + "] stmt[" + lastStatement() + "]";
+    return "name[" + name + "] startTime[" + startUseTime() + "] busySeconds[" + busySeconds() + "] stackTrace[" + stackTraceAsString(stackTrace) + "] stmt[" + lastStatement() + "]";
   }
 
   /**
@@ -448,6 +448,11 @@ public void close() throws SQLException {
     if (status == STATUS_IDLE) {
       throw new SQLException(IDLE_CONNECTION_ACCESSED_ERROR + "close()");
     }
+    boolean mayHaveUncommittedChanges = !autoCommit && !readOnly && status == STATUS_ACTIVE;
+    if (mayHaveUncommittedChanges && pool.enforceCleanClose()) {
+      pool.returnConnectionForceClose(this);
+      throw new AssertionError("Tried to close a dirty connection. See https://github.com/ebean-orm/ebean-datasource/issues/116 for details.");
+    }
     if (hadErrors) {
       if (failoverToReadOnly) {
         pool.returnConnectionReset(this);
@@ -464,6 +469,11 @@ public void close() throws SQLException {
         pool.removeClosedConnection(this);
         return;
       }
+      if (mayHaveUncommittedChanges) {
+        Log.warn("Tried to close a dirty connection at {0}. See https://github.com/ebean-orm/ebean-datasource/issues/116 for details.",
+          stackTraceAsString(Thread.currentThread().getStackTrace()));
+        connection.rollback();
+      }
       // reset the autoCommit back if client code changed it
       if (autoCommit != pool.isAutoCommit()) {
         connection.setAutoCommit(pool.isAutoCommit());
@@ -942,35 +952,23 @@ void setStackTrace(StackTraceElement[] stackTrace) {
   /**
    * Return the stackTrace as a String for logging purposes.
    */
-  private String stackTraceAsString() {
-    StackTraceElement[] stackTrace = stackTrace();
+  private String stackTraceAsString(StackTraceElement[] stackTrace) {
     if (stackTrace == null) {
       return "";
     }
-    return Arrays.toString(stackTrace);
-  }
-
-  /**
-   * Return the full stack trace that got the connection from the pool. You
-   * could use this if getCreatedByMethod() doesn't work for you.
-   */
-  private StackTraceElement[] stackTrace() {
-    if (stackTrace == null) {
-      return null;
-    }
 
     // filter off the top of the stack that we are not interested in
     ArrayList<StackTraceElement> filteredList = new ArrayList<>();
     boolean include = false;
     for (StackTraceElement stackTraceElement : stackTrace) {
-      if (!include && includeMethodLine(stackTraceElement.toString())) {
+      if (!include && includeMethodLine(stackTraceElement.getClassName())) {
         include = true;
       }
       if (include && filteredList.size() < maxStackTrace) {
         filteredList.add(stackTraceElement);
       }
     }
-    return filteredList.toArray(new StackTraceElement[0]);
+    return filteredList.toString();
   }
 
 }

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

@@ -0,0 +1,175 @@
+package io.ebean.datasource.pool;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
+import io.ebean.datasource.DataSourceBuilder;
+import io.ebean.datasource.DataSourcePool;
+import org.junit.jupiter.api.AfterAll;
+import org.junit.jupiter.api.BeforeAll;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.slf4j.LoggerFactory;
+
+import java.sql.Connection;
+import java.sql.SQLException;
+import java.sql.SQLSyntaxErrorException;
+import java.util.List;
+import java.util.stream.Collectors;
+
+import static org.assertj.core.api.Assertions.assertThat;
+import static org.assertj.core.api.Assertions.assertThatThrownBy;
+
+/**
+ * Tests, if connections are clean when closing them.
+ * <p>
+ * Test must run with "do not use module path" option in IntelliJ.
+ * <p>
+ * See also https://github.com/ebean-orm/ebean-datasource/issues/116 for more details
+ */
+class ConnectionPoolCloseTest {
+
+  private static ListAppender<ILoggingEvent> logCapture = new ListAppender<>();
+
+  private static DataSourcePool pool = createPool(false, false);
+  private static DataSourcePool poolRo = createPool(false, true);
+  private static DataSourcePool poolEnforce = createPool(true, false);
+  private static DataSourcePool poolEnforceRo = createPool(true, true);
+
+
+  @BeforeAll
+  static void before() {
+    // attach logback appender to capture log messages
+    ((ch.qos.logback.classic.Logger) LoggerFactory.getLogger("io.ebean.datasource")).addAppender(logCapture);
+    logCapture.start();
+  }
+
+  @BeforeEach
+  void beforeEach() {
+    logCapture.list.clear();
+  }
+
+  @AfterAll
+  static void after() {
+    logCapture.stop();
+    pool.shutdown();
+    poolRo.shutdown();
+    poolEnforce.shutdown();
+    poolEnforceRo.shutdown();
+  }
+
+  @Test
+  void testNoCommitOrRollback() throws SQLException {
+
+    doNoCommitOrRollback(pool);
+    assertThat(getAndResetLogWarinings())
+      .hasSize(1)
+      .first().asString().startsWith("[WARN] Tried to close a dirty connection at");
+
+    assertThatThrownBy(() -> doNoCommitOrRollback(poolEnforce)).isInstanceOf(AssertionError.class);
+
+    doNoCommitOrRollback(poolRo);
+    assertThat(getAndResetLogWarinings()).isEmpty();
+
+    doNoCommitOrRollback(poolEnforceRo);
+    assertThat(getAndResetLogWarinings()).isEmpty();
+
+  }
+
+  @Test
+  void testCommit() throws SQLException {
+    doCommit(pool);
+    doCommit(poolRo);
+    doCommit(poolEnforce);
+    doCommit(poolEnforceRo);
+    assertThat(getAndResetLogWarinings()).isEmpty();
+  }
+
+  @Test
+  void testRollback() throws SQLException {
+    doRollback(pool);
+    doRollback(poolRo);
+    doRollback(poolEnforce);
+    doRollback(poolEnforceRo);
+    assertThat(getAndResetLogWarinings()).isEmpty();
+  }
+
+  @Test
+  void testExecuteValidSql() throws SQLException {
+    doExecute(pool, "SELECT 1");
+    doExecute(poolRo, "SELECT 1");
+    doExecute(poolEnforce, "SELECT 1");
+    doExecute(poolEnforceRo, "SELECT 1");
+    assertThat(getAndResetLogWarinings()).isEmpty();
+  }
+
+  @Test
+  void testExecuteInvalidSql() throws SQLException {
+    assertThatThrownBy(() -> doExecute(pool, "invalid query"))
+      .isInstanceOf(SQLSyntaxErrorException.class)
+      .hasNoSuppressedExceptions();
+    // (un)fortunately, we will log a missing rollback, when exception in try-with-resourches is thrown.
+    assertThat(getAndResetLogWarinings())
+      .hasSize(1)
+      .first().asString().startsWith("[WARN] Tried to close a dirty connection at");
+
+    assertThatThrownBy(() -> doExecute(poolEnforce, "invalid query"))
+      .isInstanceOf(SQLSyntaxErrorException.class)
+      .hasSuppressedException(new AssertionError("Tried to close a dirty connection. See https://github.com/ebean-orm/ebean-datasource/issues/116 for details."));
+
+    assertThatThrownBy(() -> doExecute(poolRo, "invalid query"))
+      .isInstanceOf(SQLSyntaxErrorException.class)
+      .hasNoSuppressedExceptions();
+
+    assertThatThrownBy(() -> doExecute(poolEnforceRo, "invalid query"))
+      .isInstanceOf(SQLSyntaxErrorException.class)
+      .hasNoSuppressedExceptions();
+    assertThat(getAndResetLogWarinings()).isEmpty();
+  }
+
+  private static void doNoCommitOrRollback(DataSourcePool pool) throws SQLException {
+    try (Connection connection = pool.getConnection()) {
+      // we do nothing here.
+    }
+  }
+
+  private static void doCommit(DataSourcePool pool) throws SQLException {
+    try (Connection connection = pool.getConnection()) {
+      connection.commit();
+    }
+  }
+
+  private static void doRollback(DataSourcePool pool) throws SQLException {
+    try (Connection connection = pool.getConnection()) {
+      connection.rollback();
+    }
+  }
+
+  private static void doExecute(DataSourcePool pool, String query) throws SQLException {
+    try (Connection connection = pool.getConnection()) {
+      connection.createStatement().execute(query);
+      connection.commit();
+    }
+  }
+
+  private static List<ILoggingEvent> getAndResetLogWarinings() {
+    List<ILoggingEvent> warnings = logCapture.list.stream().filter(e -> e.getLevel().levelInt >= Level.WARN_INT).collect(Collectors.toList());
+    logCapture.list.clear();
+    return warnings;
+  }
+
+  private static DataSourcePool createPool(boolean enforceCleanClose, boolean readOnly) {
+    DataSourcePool ret = DataSourceBuilder.create()
+      .url("jdbc:h2:mem:tests")
+      .username("sa")
+      .password("")
+      .minConnections(2)
+      .maxConnections(4)
+      .enforceCleanClose(enforceCleanClose)
+      .readOnly(readOnly)
+      .build();
+    // clear capturer after create
+    logCapture.list.clear();
+    return ret;
+  }
+}