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/pom.xml b/ebean-datasource-api/pom.xml index 4c3217f..cea0c8d 100644 --- a/ebean-datasource-api/pom.xml +++ b/ebean-datasource-api/pom.xml @@ -4,7 +4,7 @@ ebean-datasource-parent io.ebean - 9.3-SNAPSHOT + 9.3-FOC4-SNAPSHOT ebean-datasource-api 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..afcd6ef 100644 --- a/ebean-datasource/pom.xml +++ b/ebean-datasource/pom.xml @@ -4,7 +4,7 @@ io.ebean ebean-datasource-parent - 9.3-SNAPSHOT + 9.3-FOC4-SNAPSHOT ebean-datasource @@ -16,7 +16,7 @@ io.ebean ebean-datasource-api - 9.3-SNAPSHOT + 9.3-FOC4-SNAPSHOT @@ -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/BusyConnectionBuffer.java b/ebean-datasource/src/main/java/io/ebean/datasource/pool/BusyConnectionBuffer.java index 2fe702d..2f67baa 100644 --- a/ebean-datasource/src/main/java/io/ebean/datasource/pool/BusyConnectionBuffer.java +++ b/ebean-datasource/src/main/java/io/ebean/datasource/pool/BusyConnectionBuffer.java @@ -1,6 +1,8 @@ package io.ebean.datasource.pool; +import java.util.ArrayList; import java.util.Arrays; +import java.util.List; /** * A buffer especially designed for Busy PooledConnections. @@ -82,9 +84,10 @@ boolean remove(PooledConnection pc) { } /** - * Close connections that should be considered leaked. + * Remove connections that should be considered leaked. */ - void closeBusyConnections(long leakTimeMinutes) { + List removeBusyConnections(long leakTimeMinutes) { + List busyConnections = null; long olderThanTime = System.currentTimeMillis() - (leakTimeMinutes * 60000); Log.debug("Closing busy connections using leakTimeMinutes {0}", leakTimeMinutes); for (int i = 0; i < slots.length; i++) { @@ -98,20 +101,14 @@ void closeBusyConnections(long leakTimeMinutes) { } else { slots[i] = null; --size; - closeBusyConnection(pc); + if (busyConnections == null) { + busyConnections = new ArrayList<>(); + } + busyConnections.add(pc); } } } - } - - 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); - } + return busyConnections; } /** 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..7662b58 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(); } @@ -290,7 +292,7 @@ public SQLException dataSourceDownReason() { private void notifyDataSourceIsDown(SQLException reason) { if (dataSourceUp.get()) { - reset(); + reset(false); notifyDown(reason); } } @@ -314,7 +316,7 @@ private void notifyDown(SQLException reason) { private void notifyDataSourceIsUp() { if (!dataSourceUp.get()) { - reset(); + reset(true); notifyUp(); } } @@ -447,6 +449,10 @@ private Connection createConnection() throws SQLException { return initConnection(source.getConnection()); } + public int forceTrim(int trimCount) { + return queue.forceTrim(trimCount); + } + @Override public void setMaxSize(int max) { queue.setMaxSize(max); @@ -516,6 +522,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. @@ -537,7 +550,7 @@ void returnConnectionForceClose(PooledConnection pooledConnection) { } void removeClosedConnection(PooledConnection pooledConnection) { - queue.returnPooledConnection(pooledConnection, true); + queue.returnPooledConnection(pooledConnection, true, false); } /** @@ -548,7 +561,7 @@ private void returnTheConnection(PooledConnection pooledConnection, boolean forc if (poolListener != null && !forceClose) { poolListener.onBeforeReturnConnection(pooledConnection); } - queue.returnPooledConnection(pooledConnection, forceClose); + queue.returnPooledConnection(pooledConnection, forceClose, true); if (forceClose) { // Got a bad connection so check the pool testConnection(); @@ -556,9 +569,9 @@ private void returnTheConnection(PooledConnection pooledConnection, boolean forc } void returnConnectionReset(PooledConnection pooledConnection) { - queue.returnPooledConnection(pooledConnection, true); + queue.returnPooledConnection(pooledConnection, true, false); Log.warn("Resetting DataSource on read-only failure [{0}]", name); - reset(); + reset(false); } /** @@ -587,9 +600,9 @@ PooledConnection createConnectionForQueue(int connId) throws SQLException { *

  • Busy connections are closed when they are returned to the pool.
    • * */ - private void reset() { + private void reset(boolean logErrors) { heartbeatPoolExhaustedCount = 0; - queue.reset(leakTimeMinutes); + queue.reset(leakTimeMinutes, logErrors); } /** diff --git a/ebean-datasource/src/main/java/io/ebean/datasource/pool/FreeConnectionBuffer.java b/ebean-datasource/src/main/java/io/ebean/datasource/pool/FreeConnectionBuffer.java index a78ee39..8bbc37e 100644 --- a/ebean-datasource/src/main/java/io/ebean/datasource/pool/FreeConnectionBuffer.java +++ b/ebean-datasource/src/main/java/io/ebean/datasource/pool/FreeConnectionBuffer.java @@ -62,18 +62,22 @@ void closeAll(boolean logErrors) { /** * Trim any inactive connections that have not been used since usedSince. + *

    + * The connections are returned to close. */ - int trim(int minSize, long usedSince, long createdSince) { - int trimCount = 0; + List trim(int minSize, long usedSince, long createdSince, boolean forced) { + List trimmedConnections = null; ListIterator iterator = freeBuffer.listIterator(minSize); while (iterator.hasNext()) { PooledConnection pooledConnection = iterator.next(); - if (pooledConnection.shouldTrim(usedSince, createdSince)) { + if (pooledConnection.shouldTrim(usedSince, createdSince, forced)) { iterator.remove(); - pooledConnection.closeConnectionFully(true); - trimCount++; + if (trimmedConnections == null) { + trimmedConnections = new ArrayList<>(); + } + trimmedConnections.add(pooledConnection); } } - return trimCount; + return trimmedConnections; } } 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..228399a 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 @@ -37,6 +37,11 @@ final class PooledConnection extends ConnectionDelegator { */ private static final String REASON_RESET = "reset"; + /** + * Marker for when connection is closed due a forced trim. + */ + private static final String REASON_FORCED = "forced"; + /** * Set when connection is idle in the pool. In general when in the pool the * connection should not be modified. @@ -219,7 +224,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() + "]"; } /** @@ -363,7 +368,7 @@ private PreparedStatement prepareStatement(String sql, boolean useFlag, int flag lastStatement = sql; // try to get a matching cached PStmt from the cache. ExtendedPreparedStatement pstmt = pstmtCache.remove(cacheKey); - if (pstmt != null) { + if (pstmt != null && !pstmt.isClosed()) { return pstmt.reset(); } @@ -448,6 +453,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 +474,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()); @@ -529,7 +544,7 @@ boolean shouldTrimOnReturn(long lastResetTime, long maxAgeMillis) { /** * Return true if the connection has been idle for too long or is too old. */ - boolean shouldTrim(long usedSince, long createdSince) { + boolean shouldTrim(long usedSince, long createdSince, boolean forced) { if (lastUseTime < usedSince) { // been idle for too long so trim it this.closeReason = REASON_IDLE; @@ -540,6 +555,10 @@ boolean shouldTrim(long usedSince, long createdSince) { this.closeReason = REASON_MAXAGE; return true; } + if (forced) { + this.closeReason = REASON_FORCED; + return true; + } return false; } @@ -942,35 +961,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/main/java/io/ebean/datasource/pool/PooledConnectionQueue.java b/ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnectionQueue.java index 7a66c98..2f6dbd1 100644 --- a/ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnectionQueue.java +++ b/ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnectionQueue.java @@ -5,6 +5,7 @@ import io.ebean.datasource.pool.ConnectionPool.Status; import java.sql.SQLException; +import java.util.List; import java.util.concurrent.TimeUnit; import java.util.concurrent.locks.Condition; import java.util.concurrent.locks.ReentrantLock; @@ -87,12 +88,7 @@ private PoolStatus createStatus() { @Override public String toString() { - lock.lock(); - try { - return createStatus().toString(); - } finally { - lock.unlock(); - } + return status(false).toString(); } PoolStatus status(boolean reset) { @@ -147,31 +143,40 @@ void ensureMinimumConnections() throws SQLException { /** * Return a PooledConnection. */ - void returnPooledConnection(PooledConnection c, boolean forceClose) { + void returnPooledConnection(PooledConnection c, boolean forceClose, boolean logErrors) { + boolean closeConnection = false; lock.lock(); try { if (!busyList.remove(c)) { Log.error("Connection [{0}] not found in BusyList?", c); } if (forceClose || c.shouldTrimOnReturn(lastResetTime, maxAgeMillis)) { - c.closeConnectionFully(false); + closeConnection = true; // close outside lock } else { freeList.add(c); - notEmpty.signal(); + notEmpty.signal(); // notify _obtainConnectionWaitLoop, that there are new connections in the freelist } } finally { lock.unlock(); } + if (closeConnection) { + c.closeConnectionFully(logErrors); + } } - private PooledConnection extractFromFreeList() { + /** + * Returns one connection from the free list and put it into the busy list or null if no connections are free. + * + * @throws StaleConnectionException there was a connection in the freeList, but it is stale. + * The connection has to be closed outside the lock. + */ + private PooledConnection extractFromFreeList() throws StaleConnectionException { if (freeList.isEmpty()) { return null; } final PooledConnection c = freeList.remove(); if (validateStaleMillis > 0 && staleEviction(c)) { - c.closeConnectionFully(false); - return null; + throw new StaleConnectionException(c); } registerBusyConnection(c); return c; @@ -192,15 +197,24 @@ private boolean stale(PooledConnection c) { } PooledConnection obtainConnection() throws SQLException { - try { - PooledConnection pc = _obtainConnection(); - pc.resetForUse(); - return pc; - - } catch (InterruptedException e) { - // restore the interrupted status as we throw SQLException - Thread.currentThread().interrupt(); - throw new SQLException("Interrupted getting connection from pool", e); + var start = System.nanoTime(); + while (true) { + try { + PooledConnection pc = _obtainConnection(); + pc.resetForUse(); + final var elapsed = System.nanoTime() - start; + totalAcquireNanos += elapsed; + maxAcquireNanos = Math.max(maxAcquireNanos, elapsed); + return pc; + + } catch (InterruptedException e) { + // restore the interrupted status as we throw SQLException + Thread.currentThread().interrupt(); + throw new SQLException("Interrupted getting connection from pool", e); + } catch (StaleConnectionException e) { + e.getConnection().closeConnectionFully(true); + // try again... + } } } @@ -215,8 +229,8 @@ private int registerBusyConnection(PooledConnection connection) { return busySize; } - private PooledConnection _obtainConnection() throws InterruptedException, SQLException { - var start = System.nanoTime(); + private PooledConnection _obtainConnection() throws InterruptedException, SQLException, StaleConnectionException { + lock.lockInterruptibly(); try { if (doingShutdown) { @@ -246,9 +260,6 @@ private PooledConnection _obtainConnection() throws InterruptedException, SQLExc waitingThreads--; } } finally { - final var elapsed = System.nanoTime() - start; - totalAcquireNanos += elapsed; - maxAcquireNanos = Math.max(maxAcquireNanos, elapsed); lock.unlock(); } } @@ -270,7 +281,7 @@ private PooledConnection createConnection() throws SQLException { /** * Got into a loop waiting for connections to be returned to the pool. */ - private PooledConnection _obtainConnectionWaitLoop() throws SQLException, InterruptedException { + private PooledConnection _obtainConnectionWaitLoop() throws SQLException, InterruptedException, StaleConnectionException { long nanos = MILLIS_TIME_UNIT.toNanos(waitTimeoutMillis); for (; ; ) { if (nanos <= 0) { @@ -307,7 +318,7 @@ PoolStatus shutdown(boolean closeBusyConnections) { try { doingShutdown = true; PoolStatus status = createStatus(); - closeFreeConnections(true); + freeList.closeAll(true); if (!closeBusyConnections) { // connections close on return to pool @@ -332,14 +343,14 @@ PoolStatus shutdown(boolean closeBusyConnections) { *

    * This is typically done when a database down event occurs. */ - void reset(long leakTimeMinutes) { + void reset(long leakTimeMinutes, boolean logErrors) { lock.lock(); try { PoolStatus status = createStatus(); Log.info("Resetting DataSource [{0}] {1}", name, status); lastResetTime = System.currentTimeMillis(); - closeFreeConnections(false); + freeList.closeAll(logErrors); closeBusyConnections(leakTimeMinutes); String busyInfo = getBusyConnectionInformation(); @@ -353,17 +364,12 @@ void reset(long leakTimeMinutes) { } void trim(long maxInactiveMillis, long maxAgeMillis) { - lock.lock(); - try { - if (trimInactiveConnections(maxInactiveMillis, maxAgeMillis)) { - try { - ensureMinimumConnections(); - } catch (SQLException e) { - Log.error("Error trying to ensure minimum connections", e); - } + if (trimInactiveConnections(maxInactiveMillis, maxAgeMillis)) { + try { + ensureMinimumConnections(); + } catch (SQLException e) { + Log.error("Error trying to ensure minimum connections", e); } - } finally { - lock.unlock(); } } @@ -372,33 +378,57 @@ void trim(long maxInactiveMillis, long maxAgeMillis) { */ private boolean trimInactiveConnections(long maxInactiveMillis, long maxAgeMillis) { final long createdSince = (maxAgeMillis == 0) ? 0 : System.currentTimeMillis() - maxAgeMillis; - final int trimmedCount; - if (freeList.size() > minSize) { - // trim on maxInactive and maxAge - long usedSince = System.currentTimeMillis() - maxInactiveMillis; - trimmedCount = freeList.trim(minSize, usedSince, createdSince); - } else if (createdSince > 0) { - // trim only on maxAge - trimmedCount = freeList.trim(0, createdSince, createdSince); - } else { - trimmedCount = 0; + final List trimmed; + lock.lock(); + try { + if (freeList.size() > minSize) { + // trim on maxInactive and maxAge + long usedSince = System.currentTimeMillis() - maxInactiveMillis; + trimmed = freeList.trim(minSize, usedSince, createdSince, false); + } else if (createdSince > 0) { + // trim only on maxAge + trimmed = freeList.trim(0, createdSince, createdSince, false); + } else { + trimmed = null; + } + } finally { + lock.unlock(); } - if (trimmedCount > 0 && Log.isLoggable(DEBUG)) { - Log.debug("DataSource [{0}] trimmed [{1}] inactive connections. New size[{2}]", name, trimmedCount, totalConnections()); + if (trimmed != null) { + if (Log.isLoggable(DEBUG)) { + Log.debug("DataSource [{0}] trimmed [{1}] inactive connections. New size[{2}]", name, trimmed.size(), totalConnections()); + } + for (PooledConnection pc : trimmed) { + pc.closeConnectionFully(true); + } + return freeList.size() < minSize; } - return trimmedCount > 0 && freeList.size() < minSize; + return false; } - /** - * Close all the connections that are in the free list. - */ - private void closeFreeConnections(boolean logErrors) { + int forceTrim(int trimCount) { + List trimmed = null; lock.lock(); try { - freeList.closeAll(logErrors); + int trimStart = freeList.size() - trimCount; + trimStart = Math.max(trimStart, 0); + + if (freeList.size() > trimStart) { + trimmed = freeList.trim(trimStart, 0, 0, true); + } } finally { lock.unlock(); } + if (trimmed != null) { + if (Log.isLoggable(DEBUG)) { + Log.debug("DataSource [{0}] forced trimmed [{1}] connections. New size[{2}]", name, trimmed.size(), totalConnections()); + } + for (PooledConnection pc : trimmed) { + pc.closeConnectionFully(true); + } + return trimmed.size(); + } + return 0; } /** @@ -412,12 +442,23 @@ private void closeFreeConnections(boolean logErrors) { * closed and put back into the pool. */ void closeBusyConnections(long leakTimeMinutes) { + List busyConnections; lock.lock(); try { - busyList.closeBusyConnections(leakTimeMinutes); + busyConnections = busyList.removeBusyConnections(leakTimeMinutes); } finally { lock.unlock(); } + if (busyConnections != null) { + for (PooledConnection pc : busyConnections) { + try { + Log.warn("DataSource closing busy connection? {0}", pc.fullDescription()); + pc.closeConnectionFully(true); + } catch (Exception ex) { + Log.error("Error when closing potentially leaked connection " + pc.description(), ex); + } + } + } } String getBusyConnectionInformation() { diff --git a/ebean-datasource/src/main/java/io/ebean/datasource/pool/StaleConnectionException.java b/ebean-datasource/src/main/java/io/ebean/datasource/pool/StaleConnectionException.java new file mode 100644 index 0000000..4502179 --- /dev/null +++ b/ebean-datasource/src/main/java/io/ebean/datasource/pool/StaleConnectionException.java @@ -0,0 +1,18 @@ +package io.ebean.datasource.pool; + +/** + * Used to return a stale connection, so that it can be closed outside a lock. + * + * @author Roland Praml, Foconis Analytics GmbH + */ +class StaleConnectionException extends Exception { + private final PooledConnection connection; + + StaleConnectionException(PooledConnection connection) { + this.connection = connection; + } + + public PooledConnection getConnection() { + return connection; + } +} 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(); + } +} diff --git a/pom.xml b/pom.xml index 46744bf..5df0152 100644 --- a/pom.xml +++ b/pom.xml @@ -9,7 +9,7 @@ io.ebean ebean-datasource-parent - 9.3-SNAPSHOT + 9.3-FOC4-SNAPSHOT pom