This is an automated email from the ASF dual-hosted git repository. rmaucher pushed a commit to branch 11.0.x in repository https://gitbox.apache.org/repos/asf/tomcat.git
commit 01afdc03862f4978dba661ff7081d3627b126f14 Author: opencode <[email protected]> AuthorDate: Wed Nov 4 16:46:45 2026 +0100 Say what the statement finalizer tracks and blames only from what it knows The interceptor's texts promised more than its net catches, and its trace report accused applications it could not have checked. Tracking is handle-based: it registers what the pooled connection's chain hands back. A statement created on the driver's own connection - the object Connection.unwrap(Connection.class) gives the application - never reaches the interceptor, so it is neither tracked nor closed when the connection is returned. That carve-out was stated only in StatementFacade's javadoc, while the finalizer's own javadoc and its documentation section read session-wide, which is exactly where a reader decides whether to close statements himself. Both now state the bound. The trace report went further than its evidence. When a driver's isClosed() throws, the interceptor forces the close attempt - right, a statement that may hold server-side state must not be skipped - but it also let that same forced attempt drive the "Statement created, but was not closed" warning. A statement the application had in fact closed takes the extra close as the no-op JDBC demands of it, so on the drivers the forced branch was written for, the warning was unfounded noise naming a leak that did not happen. The warning now waits for an answer to isClosed(); the close attempt itself is unchanged, and a driver that cannot answer is still closed. The class javadoc and the comments were also gathered up: the digression on interceptor ordering, the returnDrained rationale and the identity explanation said in forty-odd lines what takes fifteen, and one line of the returnDrained rationale had gone stale with the retry added at the borrow. Test: traceReportsOnlyWhatTheDriverCouldAnswer puts an open statement and a driver that cannot answer isClosed() into one return with tracing on and asks the interceptor how many applications it blamed. --- modules/jdbc-pool/doc/jdbc-pool.xml | 6 + .../jdbc/pool/interceptor/StatementFinalizer.java | 89 +++++++------- .../pool/interceptor/TestStatementFinalizer.java | 135 +++++++++++++++++++++ 3 files changed, 184 insertions(+), 46 deletions(-) diff --git a/modules/jdbc-pool/doc/jdbc-pool.xml b/modules/jdbc-pool/doc/jdbc-pool.xml index ebf7db0242..15315fecba 100644 --- a/modules/jdbc-pool/doc/jdbc-pool.xml +++ b/modules/jdbc-pool/doc/jdbc-pool.xml @@ -763,6 +763,12 @@ instead of closing it, as a <code>StatementCache</code> beneath this interceptor does. </p> + <p>The tracking covers the statements created through the pooled connection + handle. A statement created on the driver’s own connection – the + object <code>Connection.unwrap(Connection.class)</code> hands back – + never reaches this interceptor, so it is neither tracked nor closed when + the connection is returned to the pool. + </p> <attributes> <attribute name="trace" required="false"> <p>(boolean as String) Enable tracing of unclosed statements. diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java index 8604328367..2d538aa241 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java @@ -40,17 +40,14 @@ import org.apache.tomcat.jdbc.pool.util.MessageFactory; * <p> * A statement is tracked with a strong reference until it is closed: an application that forgot about a statement is * exactly the case the interceptor exists for, so finalisation must not depend on that statement still being reachable - * when the connection is returned. Statements that the application does close are forgotten by the returned proxy at - * the moment <code>close()</code> completes, keeping the tracked list bounded by the statements that are genuinely - * still open and closed through that handle. (The removal cannot observe a close that reaches the statement by - * another route: a statement the application closes through the driver handle that <code>unwrap</code> hands back - * never passes through this proxy; such entries are simply reclaimed at the connection return, where the renewed - * close meets a statement already closed as a harmless no-op, as they were before. An interceptor placed outside - * this one could swallow a close in the same way, but the pool's own {@link StatementCache} no longer does: listed - * above this interceptor it refuses to recycle, because a recycled statement is left open rather than closed and - * would be reclaimed here alive, out from under the cache.) A statement whose driver create was still in flight - * while the connection was returned cannot be reclaimed at the return either - it registers after that return has - * drained the list - so such a late registration is closed where it arrives instead of being tracked. + * when the connection is returned. A statement closed through the handle this interceptor returns is forgotten at that + * moment, which keeps the tracked list bounded by the statements that are genuinely still open. + * <p> + * A close that reaches the statement by another route cannot be observed by that removal, so its entry is reclaimed at + * the connection return: there the renewed close is a no-op on a statement the application had already closed, and the + * close it still owed on one it had not. A creation still in flight while the connection is returned is the one case + * that return cannot reach - it registers after the return drained the list - and is closed where it arrives instead of + * being tracked. * <p> * Tracked statements are handed to the application as proxies implementing the standard JDBC statement interfaces, as * is the statement facade the pool always installs in front of this interceptor and as are the proxies of the other @@ -59,6 +56,10 @@ import org.apache.tomcat.jdbc.pool.util.MessageFactory; * driver-specific statement methods. A statement the application reaches that way is still tracked here and is closed, * like any other tracked statement, when the connection is returned - unless an interceptor listed after this one * recycles the statement instead of closing it, as a statement cache beneath this interceptor does. + * <p> + * Tracking covers the statements created through the pooled connection handle. A statement created on the driver's + * own connection - the object <code>Connection.unwrap(Connection.class)</code> hands back - never reaches this + * interceptor and is neither tracked nor closed when the connection is returned. */ public class StatementFinalizer extends AbstractCreateStatementInterceptor { private static final Log log = LogFactory.getLog(StatementFinalizer.class); @@ -80,11 +81,10 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { * Whether the connection return has already drained {@link #statements}: set by {@link #closeInvoked()}, cleared by * {@link #reset} at the start of the next borrow. Every access is guarded by {@link #statementsLock}. * <p> - * A statement creation is not serialized against the connection return: the driver's create has completed and the - * statement is open before this interceptor can register it. A creation whose connection is returned inside that - * window would register after the drain - not closed by that return, dropped by the next borrow's {@link #reset}, - * and left open on a session that is about to serve another borrower. A registration that arrives drained - * therefore does not enter the list: {@link #createStatement} closes the statement itself. + * The driver's create has finished before this interceptor can register the statement, so a creation is not + * serialized against the connection return. One that lands after the return drained the list cannot be reclaimed by + * that return, and carrying it into the next borrow's books would only close it out from under the application + * still holding it; {@link #createStatement} closes it where it arrives instead. */ protected boolean returnDrained = false; @@ -127,10 +127,9 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { } } if (drained) { - // The connection return drained the list before this statement - // could be registered, so the return's renewed close cannot find - // it; close it here rather than leave it open on a session that - // is about to serve the next borrower. There is no later + // The return's drain has passed, so that return cannot reclaim + // this statement; close it here rather than leave it open on a + // session about to serve the next borrower. There is no later // attempt to make, so a failure is what the operator hears. if (!entry.close()) { log.warn(MessageFactory.get("statementFinalizer.unableToCloseStatement"), @@ -176,10 +175,9 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { } } if (failed != null) { - // A close the driver refused is retried, the same way a close - // that fails through the application's handle is kept for this - // return to retry: back on the list, the entries wait for the - // next attempt, which the reset at the next borrow makes. + // Back on the list, like an entry whose close failed through the + // application's handle: the reset at the next borrow makes the + // next attempt. synchronized (statementsLock) { statements.addAll(failed); } @@ -209,11 +207,10 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { statements.clear(); } } - // On a teardown (no connection) the physical close that precedes - // the reset has already released the statements. On a borrow the - // session is about to serve again, so an entry a failed return-time - // close left behind gets its last attempt here, before the new - // borrower is handed the session. + // On a teardown the physical close that precedes this reset has + // already released the statements. On a borrow the session serves + // again, so what a failed return-time close left behind gets its + // last attempt here, before the new borrower runs. if (left != null && con != null) { for (StatementEntry entry : left) { if (!entry.close()) { @@ -266,20 +263,27 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { } /** - * Closes the tracked statement, reporting failure the same way the connection return does. + * Closes the tracked statement unless the driver reports it closed already and, with tracing on, reports a + * statement the application left open. * * @return <code>true</code> if the statement is closed - because it was found closed or because the close * succeeded; <code>false</code> if an attempted close failed and the statement may still be open */ public boolean close() { - boolean shallClose = false; + boolean shallClose; + // Whether the driver answered at all. The forced close below is no evidence about the application - an + // already closed statement takes a close as the no-op JDBC demands of it - so the trace warning, which + // names the application, waits for an answer. + boolean answered; try { shallClose = !statement.isClosed(); + answered = true; } catch (Exception ignore) { // A driver that cannot say whether the statement is closed // must not get to skip the close attempt - the statement // may still hold server-side state. shallClose = true; + answered = false; } boolean closed = !shallClose; if (shallClose) { @@ -292,7 +296,7 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { } } } - if (logCreationStack && shallClose) { + if (logCreationStack && shallClose && answered) { log.warn(MessageFactory.get("statementFinalizer.statementNotClosed"), allocationStack); } return closed; @@ -306,11 +310,9 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { * <p> * <code>Object.equals(Object)</code> and <code>hashCode()</code> are answered on the handle itself, as * {@link org.apache.tomcat.jdbc.pool.ProxyConnection} and the pool's other statement proxies answer them: the - * handle equals only itself and hashes at its own identity. A container that holds this handle next to an - * unwrapped handle for the same statement therefore holds two elements, whichever of the two was added first, - * instead of resolving the pair to one element or the other by insertion order. The statement underneath stays a - * distinct object that the handle compares equal to in neither direction; reaching it is <code>unwrap</code>'s - * purpose, and there the driver's own equality applies, as it does for the statement facade's handle above. + * handle equals only itself and hashes at its own identity, so a container holding it next to an unwrapped handle + * for the same statement holds two elements whichever of the two arrived first. Reaching the statement underneath + * is <code>unwrap</code>'s purpose, and there the driver's own equality applies. */ protected class CloseAwareProxy implements InvocationHandler { private final StatementEntry entry; @@ -328,15 +330,10 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { if (compare(EQUALS_VAL, method)) { // The identity of the handle the application holds, and - // nothing else, as ProxyConnection answers it too. Equality - // was delegated to the statement underneath, which made the - // handle equal to a statement that - answering by its own - // equality, typically identity - did not answer equal to the - // handle back. That one-sided relation is what - // Object.equals(Object) rules out, and it decided membership - // of a container holding both objects by insertion order: - // the same pair hashed alike and came out as one element or - // two depending on which was added first. + // nothing else, as ProxyConnection answers it too: equality + // delegated to the statement underneath made the handle equal + // to a statement that did not answer equal back, and a set + // holding both objects resolved them by insertion order. Object other = (args == null || args.length == 0) ? null : args[0]; return Boolean.valueOf(proxy == other); } diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestStatementFinalizer.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestStatementFinalizer.java index a89da304f4..123414304a 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestStatementFinalizer.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestStatementFinalizer.java @@ -27,21 +27,31 @@ import java.sql.PreparedStatement; import java.sql.ResultSet; import java.sql.SQLException; import java.sql.Statement; +import java.util.ArrayList; +import java.util.HashMap; import java.util.HashSet; import java.util.List; +import java.util.Map; import java.util.Set; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicReference; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; +import java.util.stream.Collectors; import org.junit.jupiter.api.Assertions; import org.junit.jupiter.api.Test; +import org.apache.juli.logging.LogFactory; import org.apache.tomcat.jdbc.JdbcPoolBaseTest; import org.apache.tomcat.jdbc.pool.ConnectionPool; import org.apache.tomcat.jdbc.pool.DataSource; import org.apache.tomcat.jdbc.pool.JdbcInterceptor; +import org.apache.tomcat.jdbc.pool.PoolProperties; import org.apache.tomcat.jdbc.pool.PooledConnection; /** @@ -517,6 +527,131 @@ class TestStatementFinalizer extends JdbcPoolBaseTest { "a teardown drops the list; the statements die with the destroyed session"); } + /* + * A statement from a driver that cannot answer whether it is closed: + * isClosed() always throws, while an attempted close is taken. + */ + private static Statement fakedDriverThatCannotSay(AtomicBoolean closeWasTaken) { + return (Statement) Proxy.newProxyInstance( + TestStatementFinalizer.class.getClassLoader(), + new Class<?>[] { Statement.class }, + (p, m, a) -> { + switch (m.getName()) { + case "close": + closeWasTaken.set(true); + return null; + case "isClosed": + throw new SQLException("this driver cannot say"); + case "equals": + return Boolean.valueOf(p == (a == null || a.length == 0 ? null : a[0])); + case "hashCode": + return Integer.valueOf(System.identityHashCode(p)); + default: + return null; + } + }); + } + + @Test + void traceReportsOnlyWhatTheDriverCouldAnswer() throws Exception { + // With trace on, the interceptor tells the operator which statements + // the application left open. A driver that cannot answer isClosed() + // must still be forced through the close - a statement that may hold + // server-side state must not be skipped - but that forced attempt is + // no evidence that the application leaked the statement: one that was + // already closed takes the extra close as the no-op JDBC demands of + // it. So the report keeps its silence on a driver that could not + // answer, and has to keep speaking where the driver did. + StatementFinalizer finalizer = new StatementFinalizer(); + Map<String, PoolProperties.InterceptorProperty> properties = new HashMap<>(); + properties.put("trace", new PoolProperties.InterceptorProperty("trace", "true")); + finalizer.setProperties(properties); + + Method create = Connection.class.getMethod("createStatement"); + finalizer.reset(null, null); + Statement leftOpen = fakedStatement(); // answers honestly, and is left open + AtomicBoolean blindCloseTaken = new AtomicBoolean(); + Statement muteAboutClosure = fakedDriverThatCannotSay(blindCloseTaken); + finalizer.createStatement(null, create, null, leftOpen, 0L); + finalizer.createStatement(null, create, null, muteAboutClosure, 0L); + + try (NotClosedReports reports = new NotClosedReports()) { + finalizer.closeInvoked(); + List<LogRecord> seen = reports.seen(); + Assertions.assertEquals(1, seen.size(), + "only the statement the driver admitted leaving open may be reported, saw: " + + seen.stream().map(LogRecord::getMessage).collect(Collectors.toList())); + LogRecord report = seen.get(0); + Assertions.assertEquals(Level.WARNING.intValue(), report.getLevel().intValue(), + "the report is a warning, not something quieter: " + report.getMessage()); + Assertions.assertNotNull(report.getThrown(), + "the report has to name where the statement was created"); + Assertions.assertTrue(blindCloseTaken.get(), + "the driver that could not answer must still have been asked to close"); + } + } + + /** + * Captures the unclosed-statement reports this interceptor logs, + * following the handler idiom of the pool's other diagnostic tests. The + * canary record - written through the very JULI logger the interceptor + * logs through, not through JUL directly - proves the wiring observes + * those records before the finalizer under test gets its chance to log. + */ + private static final class NotClosedReports implements AutoCloseable { + private static final String CANARY = "statement-finalizer-trace-handler-wiring-canary"; + private static final String REPORT = "was not closed"; + + private final Logger logger = Logger.getLogger(StatementFinalizer.class.getName()); + private final Level originalLevel = logger.getLevel(); + private final List<LogRecord> records = new ArrayList<>(); + private final Handler handler = new Handler() { + @Override + public void publish(LogRecord record) { + synchronized (records) { + records.add(record); + } + } + + @Override + public void flush() { + // no buffering + } + + @Override + public void close() { + // nothing to release + } + }; + + NotClosedReports() { + logger.addHandler(handler); + logger.setLevel(Level.ALL); + LogFactory.getLog(StatementFinalizer.class).error(CANARY); + synchronized (records) { + if (records.stream().noneMatch(r -> CANARY.equals(r.getMessage()))) { + close(); + throw new AssertionError("the test handler must observe what this class logs"); + } + } + } + + /* The unclosed-statement reports seen so far; the canary is not one. */ + List<LogRecord> seen() { + synchronized (records) { + return records.stream() + .filter(r -> r.getMessage() != null && r.getMessage().contains(REPORT)) + .collect(Collectors.toList()); + } + } + + @Override + public void close() { + logger.removeHandler(handler); + logger.setLevel(originalLevel); + } + } + private DataSource finalizerPoolGated() { DataSource ds = finalizerPool(); ds.getPoolProperties().setJdbcInterceptors(StatementFinalizer.class.getName() + ';' --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
