diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index bc82e55..1f5c33e 100644 --- a/.github/workflows/build.yml +++ b/.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: diff --git a/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceBuilder.java b/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceBuilder.java index 89b574f..501f2f2 100644 --- a/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceBuilder.java +++ b/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. + *

+ * When disabled, the situation is logged as warning. + *

+ * This option has no effect on readonly or autocommit connections. + *

+ * 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 true, an exception is thrown when a dirty connection is closed. + *

+ * See {@link #enforceCleanClose(boolean)}. + */ + boolean enforceCleanClose(); + /** * The settings of the DataSourceBuilder. Provides getters/accessors * to read the configured properties of this DataSourceBuilder. diff --git a/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceConfig.java b/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceConfig.java index 21d24fc..0320e6f 100644 --- a/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourceConfig.java +++ b/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 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. */ diff --git a/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourcePoolListener.java b/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourcePoolListener.java index 555628f..5471c51 100644 --- a/ebean-datasource-api/src/main/java/io/ebean/datasource/DataSourcePoolListener.java +++ b/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) {} + } diff --git a/ebean-datasource/pom.xml b/ebean-datasource/pom.xml index 04a2cbc..9958cf4 100644 --- a/ebean-datasource/pom.xml +++ b/ebean-datasource/pom.xml @@ -76,6 +76,13 @@ test + + com.ibm.db2 + jcc + 11.5.9.0 + test + + diff --git a/ebean-datasource/src/main/java/io/ebean/datasource/pool/ConnectionPool.java b/ebean-datasource/src/main/java/io/ebean/datasource/pool/ConnectionPool.java index c58651f..d2891aa 100644 --- a/ebean-datasource/src/main/java/io/ebean/datasource/pool/ConnectionPool.java +++ b/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. diff --git a/ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnection.java b/ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnection.java index 2e8185a..dac098b 100644 --- a/ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnection.java +++ b/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 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(); } } diff --git a/ebean-datasource/src/test/java/io/ebean/datasource/pool/ConnectionPoolCloseTest.java b/ebean-datasource/src/test/java/io/ebean/datasource/pool/ConnectionPoolCloseTest.java new file mode 100644 index 0000000..7b37969 --- /dev/null +++ b/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. + *

+ * Test must run with "do not use module path" option in IntelliJ. + *

+ * See also https://github.com/ebean-orm/ebean-datasource/issues/116 for more details + */ +class ConnectionPoolCloseTest { + + private static ListAppender 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 getAndResetLogWarinings() { + List 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; + } +} diff --git a/ebean-datasource/src/test/java/io/ebean/datasource/test/Db2Test.java b/ebean-datasource/src/test/java/io/ebean/datasource/test/Db2Test.java new file mode 100644 index 0000000..4fb68d5 --- /dev/null +++ b/ebean-datasource/src/test/java/io/ebean/datasource/test/Db2Test.java @@ -0,0 +1,163 @@ +package io.ebean.datasource.test; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import com.ibm.db2.jcc.DB2Connection; +import io.avaje.applog.AppLog; +import io.ebean.datasource.DataSourceBuilder; +import io.ebean.datasource.DataSourcePool; +import io.ebean.datasource.DataSourcePoolListener; +import io.ebean.test.containers.Db2Container; +import org.junit.jupiter.api.AfterAll; +import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.Disabled; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; + +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.SQLException; + +import static org.assertj.core.api.Assertions.assertThat; + +/** + * DB2 has a strange, but API-compliant behaviour, when a connection is in a dirty state and neither committed nor rolled back. + *

+ * By default, a DB2-connection cannot be closed if it is in a unit of work (=transaction) and an exception is thrown. + *

+ * This can be controlled with the "connectionCloseWithInFlightTransaction" parameter + * https://www.ibm.com/docs/en/db2/11.5?topic=pdsdjs-common-data-server-driver-jdbc-sqlj-properties-all-database-products + *

+ * There are several cases, when there is an open unit of work: + *

+ *

+ * See also https://github.com/ebean-orm/ebean-datasource/issues/116 for more details + */ +@Disabled("DB2 container start is slow - run manually") +class Db2Test { + + private static Db2Container container; + + private static ListAppender logCapture = new ListAppender<>(); + + @BeforeAll + static void before() { + container = Db2Container.builder("11.5.6.0a") + .dbName("unit") + .user("unit") + .password("unit") + // to change collation, charset and other parameters like pagesize: + .configOptions("USING CODESET UTF-8 TERRITORY DE COLLATE USING IDENTITY PAGESIZE 32768") + .configOptions("USING STRING_UNITS CODEUNITS32") + .build(); + + container.start(); + + // attach logback appender to capture log messages + ((ch.qos.logback.classic.Logger) LoggerFactory.getLogger("io.ebean.datasource")).addAppender(logCapture); + logCapture.start(); + } + + @AfterAll + static void after() { + logCapture.stop(); + } + + @Test + void testFalseFriendRollback() throws SQLException { + + DataSourcePool pool = getPool(); + + logCapture.list.clear(); + try { + try (Connection connection = pool.getConnection()) { + // we do a rollback here + connection.rollback(); + connection.getSchema(); // will re-open a new UOW + } + } finally { + pool.shutdown(); + } + + assertThat(logCapture.list.stream().filter(e -> e.getLevel().levelInt >= Level.WARN_INT)) + .extracting(ILoggingEvent::toString).containsExactly("[WARN] There is a DB2 UOW open!"); + } + + @Test + void testErrorOccured() throws SQLException { + + DataSourcePool pool = getPool(); + + logCapture.list.clear(); + try { + try (Connection connection = pool.getConnection()) { + try (PreparedStatement statement = connection.prepareStatement("i am invalid")) { + statement.execute(); + } + connection.commit(); // we will not get here + } catch (SQLException e) { + // expected + } + } finally { + pool.shutdown(); + } + + assertThat(logCapture.list.stream().filter(e -> e.getLevel().levelInt >= Level.WARN_INT)) + .hasSize(1) + .first().asString().startsWith("[WARN] Tried to close a dirty connection at"); + } + + + @Test + void testProperShutdownWithMissingListener() throws SQLException { + + DataSourcePool pool = DataSourceBuilder.create() + .url(container.jdbcUrl()) + .username("unit") + .password("unit") + .ownerUsername("unit") + .ownerPassword("unit") + .build(); + + logCapture.list.clear(); + try { + try (Connection connection = pool.getConnection()) { + // we do a rollback here + connection.rollback(); + connection.getSchema(); + } + } finally { + pool.shutdown(); + } + // when shuttind down the pool, a rollback will be performed on all connections. + assertThat(logCapture.list.stream().filter(e -> e.getLevel().levelInt >= Level.WARN_INT)).isEmpty(); + } + + private static DataSourcePool getPool() { + return DataSourceBuilder.create() + .url(container.jdbcUrl()) + .username("unit") + .password("unit") + .ownerUsername("unit") + .ownerPassword("unit") + .listener(new DataSourcePoolListener() { + @Override + public void onBeforeReturnConnection(Connection connection) { + try { + DB2Connection db2conn = connection.unwrap(DB2Connection.class); + if (db2conn.isInDB2UnitOfWork()) { + AppLog.getLogger("io.ebean.datasource").log(System.Logger.Level.WARNING, "There is a DB2 UOW open!"); + db2conn.rollback(); + } + } catch (SQLException e) { + throw new RuntimeException(e); + } + } + }) + .build(); + } +}