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 c25a795e6a15225f2921276f16665f3d0174d20f Author: opencode <[email protected]> AuthorDate: Tue Nov 3 22:52:56 2026 +0100 Tell the operator where the configured query timeout does not take effect The one protection this interceptor configures can fail to be in effect through three routes, and it now ends the silence on each as the configuration is made or the refusal happens, rather than after the first uncancelled query. A pool backed by an XADataSource gets one warning at start: the only connection such an application uses comes from XAConnection.getConnection(), which the pool answers with the raw session behind the chain, so the interceptor cannot reach the statements created there; the pool's own chained handle keeps its timeout, so the warning names the route rather than refusing to start a pool whose driver may still apply the timeout on its own. A driver that refuses setQueryTimeout - by SQLException, the shape the spec prescribes, or by UnsupportedOperationException, the shape a non-compliant wrapper uses - no longer fails statement creation, as the unchecked shape did when only the checked one was caught: the statement is handed out and the refusal is reported once per physical connection, with a reason that reads even when the driver's exception states no message, on a record that is volatile against the cleaner and forced close threads that clear it and re-arms when the session is replaced. An unexpected RuntimeException is the driver failing to answer rather than answering, so it is reported on its own line and may not spend the refusal's. A property name no one reads is reported at configuration time through a protected isKnownProperty hook, since a mis-cased name leaves the aggressive default armed, the wrong direction for a typo. The module docs in accord: the attribute required=false with the consequence of its default, exact-match names, and the caveat that statements created outside the chain keep driver defaults; the class javadoc says what the class does. Three new test classes pin the routes and TestTrapException's import order and a missing @return bring the module through ant validate. No changelog entry. --- modules/jdbc-pool/doc/jdbc-pool.xml | 20 +- .../pool/interceptor/QueryTimeoutInterceptor.java | 173 ++++++++++++--- .../tomcat/jdbc/pool/util/LocalStrings.properties | 3 + .../apache/tomcat/jdbc/pool/TestTrapException.java | 3 +- .../interceptor/TestQueryTimeoutDriverRefusal.java | 240 ++++++++++++++++++++- .../TestQueryTimeoutMalformedProperty.java | 72 +++++++ .../TestQueryTimeoutXaBypassWarning.java | 227 +++++++++++++++++++ 7 files changed, 703 insertions(+), 35 deletions(-) diff --git a/modules/jdbc-pool/doc/jdbc-pool.xml b/modules/jdbc-pool/doc/jdbc-pool.xml index d06529a6d9..d13ada6d0e 100644 --- a/modules/jdbc-pool/doc/jdbc-pool.xml +++ b/modules/jdbc-pool/doc/jdbc-pool.xml @@ -832,13 +832,25 @@ to zero, so an interceptor listed after the cache does not see cached statements on reuse and those statements execute with no timeout. </p> + <p><strong>Note:</strong> the timeout is applied by an interceptor, so it only covers statements that pass + through the interceptor chain. Statements created from a connection reached through + <code>XAConnection.getConnection()</code>, <code>PooledConnection.getConnection()</code> or + <code>unwrap()</code> are created outside the chain and keep whatever timeout the driver gives them. On a + pool backed by an <code>XADataSource</code> the first of these is the normal route an application takes to + its connection, so the pool logs a warning at startup when a positive query timeout is configured on such + a pool. + </p> <attributes> - <attribute name="queryTimeout" required="true"> + <attribute name="queryTimeout" required="false"> <p>(int as String) The number of seconds to set for the query timeout. A value less than or equal to zero will disable this feature. - The default value is <code>1</code> seconds. - A value that is not an integer is not applied: the pool logs a - warning and the default stays in effect. + The default value is <code>1</code> seconds, and omitting the + attribute still arms that default: any query that needs longer than + one second will be cancelled by the driver, so set the attribute + deliberately. The attribute name is matched exactly: an unrecognized + name is not applied and is logged as a warning, leaving the default + in effect. A value that is not an integer is likewise not applied: + the pool logs a warning and the default stays in effect. </p> </attribute> </attributes> diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/QueryTimeoutInterceptor.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/QueryTimeoutInterceptor.java index 367666236e..71c6bfd60f 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/QueryTimeoutInterceptor.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/QueryTimeoutInterceptor.java @@ -40,6 +40,13 @@ import org.apache.tomcat.jdbc.pool.util.MessageFactory; * cached statement executes with no timeout. Listed before the cache, the hook runs for every creation request, * including the ones the cache serves, and the timeout is re-applied to the reused statement. * <p> + * The same applies to statements whose connection never enters the chain: one reached through + * {@link javax.sql.PooledConnection#getConnection()} or {@code unwrap}, and, on a pool backed by an + * {@link javax.sql.XADataSource}, the only connection an application uses - such an application gets its connection + * from {@link javax.sql.XAConnection#getConnection()}, which the pool answers with the session behind the chain. + * Those statements keep whatever timeout the driver gives them; for the XA case the pool warns at startup, see + * {@link #poolStarted(ConnectionPool)}. + * <p> * Whether a configured timeout actually interrupts a query is up to the driver. A driver that refuses * {@link Statement#setQueryTimeout(int)} does not stop the statement from being handed out - the pool cannot enforce a * timeout itself, so such a statement runs unbounded - and the refusal is reported once per physical connection rather @@ -61,11 +68,25 @@ public class QueryTimeoutInterceptor extends AbstractCreateStatementInterceptor * of the statement creation that happened to notice it: a driver that refuses the call refuses it for every * statement it is asked about, and one line per creation would bury the fact that the configured protection is not * in effect. It is cleared when the physical session is replaced, so the session that takes over reports itself. - * The hook runs on the thread that borrowed the connection, and a pooled connection is only borrowed by one thread - * at a time - the next borrower reaches this instance through the pool's idle queue, which publishes what the - * previous one stored here - so a plain field is enough, as it is for the cached state of {@link ConnectionState}. + * <p> + * It is {@code volatile} because that clear is not always on a borrower thread: the pool drives + * {@code disconnected()} from its own threads when it takes a connection out of service under a borrower - the + * abandoned-connection cleaner or a forced close - and either can overlap a borrower still creating statements. + * The hook itself runs on one borrower at a time, so its check-and-set is not contended, and the only cost of + * the clear racing the set is one duplicate or one missing warning line. + */ + private volatile boolean timeoutRefusalReported; + + /** + * Whether an unexpected failure of {@link Statement#setQueryTimeout(int)} - + * an exception that is not a refusal to apply the timeout - has already + * been reported on this connection. Same per-physical-connection record, + * written and read under the same reasoning and with the same visibility + * as {@link #timeoutRefusalReported}, and deliberately kept a separate + * record: the two reports say different things about the driver, and + * neither may spend the other's single line. */ - private boolean timeoutRefusalReported; + private volatile boolean timeoutFailureReported; /** * Default constructor. @@ -75,18 +96,27 @@ public class QueryTimeoutInterceptor extends AbstractCreateStatementInterceptor } /** - * Initializes the {@code queryTimeout} property from the provided configuration map. A value that is not an - * integer is not applied and is warned about: the timeout keeps the value it has - for a fresh instance the - * one-second default - so a misconfigured pool behaves as the default and the warning says so as the bad value - * is configured. The pool configures an interceptor instance once at pool start, once per physical connection - * chain, and once when the pool stops, so the report shares the per-connection reporting volume of the driver - * refusal below. + * Initializes the {@code queryTimeout} property from the provided configuration map. A name that is not one of + * the {@link #isKnownProperty(String) names this interceptor reads} is not applied and is warned about: names + * are matched exactly, so a mis-cased {@code queryTimeout} is not a spelling of the property but a different, + * unread name - and the timeout it leaves unconfigured keeps the aggressive default, which is the wrong + * direction for a typo to fail in. A value that is not an integer is likewise not applied and is warned about: + * the timeout keeps the value it has - for a fresh instance the one-second default - so a misconfigured pool + * behaves as the default and the warning says so as the bad value is configured. The pool configures an + * interceptor instance once at pool start, once per physical connection chain, and once when the pool stops, so + * these warnings are no more frequent than the per-connection driver refusal report below; that report is the + * one that can re-fire, when the pool replaces the physical session behind a connection. * * @param properties map of interceptor properties */ @Override public void setProperties(Map<String, InterceptorProperty> properties) { super.setProperties(properties); + for (String name : properties.keySet()) { + if (!isKnownProperty(name)) { + log.warn(MessageFactory.get("queryTimeoutInterceptor.unknownProperty", name)); + } + } InterceptorProperty p = properties.get("queryTimeout"); if (p == null || p.getValue() == null) { // No property, or one with no value to read: as ever, the timeout @@ -101,6 +131,54 @@ public class QueryTimeoutInterceptor extends AbstractCreateStatementInterceptor } } + /** + * Ends the silence about the one configuration in which this interceptor is + * inert for an application's normal use: a pool backed by a + * {@link javax.sql.XADataSource}, where the application's only + * {@link java.sql.Connection} comes from + * {@link javax.sql.XAConnection#getConnection()} and so stays outside this + * chain (see the class javadoc and the {@code getConnection()} branch of + * {@link org.apache.tomcat.jdbc.pool.ProxyConnection}). The interceptor + * cannot reach the statements created there - that would mean re-wrapping the + * session the pool hands out, which is a pool-level change, not an + * interceptor's - and refusing to start the pool would deny an application a + * timeout its driver may still apply at its own creation call, so what is + * done instead is one warning at pool start, while the configuration is + * still the operator's to change. Statements taken through the pool's own + * chained handle keep the configured timeout even on an XA-backed pool, so + * the warning names the one route the escape runs by, not the pool as a + * whole. + * + * @param pool the pool that is starting + */ + @Override + public void poolStarted(ConnectionPool pool) { + super.poolStarted(pool); + // The configured timeout is already applied: the pool configures the + // properties of a definition instance before it lets that instance know + // about the pool start. A timeout of zero or less switches the feature + // off, and there is then no configured protection whose absence the + // warning could report. + if (pool != null && timeout > 0 + && pool.getPoolProperties().getDataSource() instanceof javax.sql.XADataSource) { + log.warn(MessageFactory.get("queryTimeoutInterceptor.xaBypass", timeout)); + } + } + + /** + * Whether this interceptor configuration understands the named property. {@code queryTimeout} is this class's + * own; {@code useEquals} is read by the {@link JdbcInterceptor} base. A subclass that adds properties should + * recognize them here too, so the unrecognized-name report stays a report about a typo rather than becoming a + * report about the subclass's own design. + * + * @param name the property name as configured + * + * @return {@code true} if the name is understood and its value acted upon + */ + protected boolean isKnownProperty(String name) { + return "queryTimeout".equals(name) || "useEquals".equals(name); + } + /** * Sets the query timeout on the created statement if it is a {@link Statement} and the timeout value is positive. * @@ -118,39 +196,86 @@ public class QueryTimeoutInterceptor extends AbstractCreateStatementInterceptor Statement s = (Statement) statement; try { s.setQueryTimeout(timeout); - } catch (SQLException x) { + } catch (SQLException | UnsupportedOperationException x) { + // These are the two shapes of a refusal. The spec has the + // driver refuse a feature by throwing SQL, and a wrapper + // driver that has not implemented the call refuses it by + // throwing its Unsupported-OperationException where the + // wrapped driver would have thrown the SQL: both answer the + // call with "this driver will not set your timeout", which + // is the news the refusal report tells. reportTimeoutRefusal(x); + } catch (RuntimeException x) { + // Any other unchecked exception is not an answer to the + // call, it is the driver failing to answer it - a driver bug + // rather than a refusal. The statement is still handed out + // (the application must not lose it to the pool's inability + // to set an optional protection) and the failure is still + // reported, but not as a refusal, and not on the refusal's + // single-per-connection line: one odd failure must not spend + // the report a genuine refusal later on the same connection + // still deserves. Errors stay out of both catches, as + // everywhere in the module: they are not a driver's answer + // to anything. + reportUnexpectedTimeoutFailure(x); } } return statement; } /* - * Reports that the driver will not apply the configured timeout, once per physical connection. - * - * The statement is still handed out, unchanged: enforcing a timeout is something only the driver can do, so - * refusing to create a statement an application can use would trade a protection the pool cannot deliver for a - * driver that simply does not implement the call. What the pool can do is say so - and say it in a way that is - * readable, which per-statement warnings are not. The warning therefore names the timeout that is not in effect and - * says that this connection will not mention it again, so one line tells the operator both the state and the - * volume of what is missing from the log. + * Reports that the driver will not apply the configured timeout, once per + * physical connection. The statement is still handed out, unchanged: only + * the driver can enforce a timeout, so refusing to create a statement the + * application can use would trade it for a protection the pool cannot + * deliver. What the pool can do is say so, and say it once: the warning + * names the timeout that is not in effect and says this connection will not + * mention it again, so one line carries both the state and the volume of + * what is missing from the log. */ - private void reportTimeoutRefusal(SQLException x) { + private void reportTimeoutRefusal(Throwable x) { if (timeoutRefusalReported) { return; } timeoutRefusalReported = true; - log.warn(MessageFactory.get("queryTimeoutInterceptor.queryTimeoutRefused", timeout, x.getMessage()), x); + log.warn(MessageFactory.get("queryTimeoutInterceptor.queryTimeoutRefused", timeout, reasonOf(x)), x); + } + + /* + * Reports an unexpected failure once per physical connection and on its own + * line, so the failure is heard without being called a refusal and without + * taking the refusal's report out of this connection's hands. The statement + * is still handed out, for the same reason a refusal hands it out. + */ + private void reportUnexpectedTimeoutFailure(RuntimeException x) { + if (timeoutFailureReported) { + return; + } + timeoutFailureReported = true; + log.warn(MessageFactory.get("queryTimeoutInterceptor.queryTimeoutSetupFailed", timeout, reasonOf(x)), x); + } + + /* + * The reason a report quotes for an exception. Each report is the one line + * of its kind this connection will ever get, so the reason slot must read + * even when the exception states no message - which an unchecked failure + * commonly does: the exception's own name says what the missing message + * cannot, where a raw null would render the literal "null". + */ + private static String reasonOf(Throwable x) { + String reason = x.getMessage(); + return reason != null && !reason.isEmpty() ? reason : x.toString(); } /** - * Forgets the reported refusal, as the physical connection this interceptor is attached to is gone: the session - * that replaces it gets its own refusal recorded and its own warning, the way it gets its own driver to answer the - * call. + * Forgets the reported refusal and the reported unexpected failure, as the physical connection this interceptor is + * attached to is gone: the session that replaces it gets its own reports, the way it gets its own driver to answer + * the call. */ @Override public void disconnected(ConnectionPool parent, PooledConnection con, boolean finalizing) { timeoutRefusalReported = false; + timeoutFailureReported = false; super.disconnected(parent, con, finalizing); } diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/util/LocalStrings.properties b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/util/LocalStrings.properties index 68e5b64c35..62f2abc9b5 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/util/LocalStrings.properties +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/util/LocalStrings.properties @@ -189,8 +189,11 @@ proxyConnection.connectionClosed=Connection has already been closed. proxyConnection.notAWrapper=Not a wrapper of {0} proxyConnection.notXAConnection=The pooled connection is not an XA connection; method [{0}] cannot be dispatched. +queryTimeoutInterceptor.unknownProperty=[QueryTimeoutInterceptor] The interceptor property [{0}] is not recognized and is not applied: property names are matched exactly, and a name this interceptor does not know leaves the query timeout at the value it carries. Check the jdbcInterceptors configuration for the name that was meant to be configured. queryTimeoutInterceptor.invalidQueryTimeout=[QueryTimeoutInterceptor] The configured queryTimeout [{0}] is not an integer number of seconds and is not applied: statements created through this configuration keep the default {1}-second query timeout. Correct the value in the jdbcInterceptors configuration to set the timeout that was meant to be configured. queryTimeoutInterceptor.queryTimeoutRefused=[QueryTimeoutInterceptor] Unable to set the query timeout of {0} seconds on a statement of this connection: {1}. The driver does not apply the timeout, so statements created on this physical connection run without a query timeout. Refusals are not logged again on this connection. +queryTimeoutInterceptor.queryTimeoutSetupFailed=[QueryTimeoutInterceptor] Setting the configured query timeout of {0} seconds failed on a statement of this connection with an exception other than a refusal to apply it: {1}. The statement is still handed out and runs with whatever query timeout its driver leaves on it. Unexpected failures of the call are not logged again on this connection. +queryTimeoutInterceptor.xaBypass=[QueryTimeoutInterceptor] The configured query timeout of {0} seconds will not reach the statements applications create on the connection obtained from XAConnection.getConnection(): the pool is backed by a javax.sql.XADataSource, that call hands out the session from behind the interceptor chain, and no statement created there passes through this interceptor. Those statements run with whatever query timeout their driver gives them. Set the timeout where th [...] resetAbandonedTimer.resultSetClosed=ResultSet closed. resetAbandonedTimer.statementClosed=Statement closed. diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestTrapException.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestTrapException.java index e1a51006ae..b622d2b33a 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestTrapException.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestTrapException.java @@ -25,10 +25,11 @@ import java.sql.SQLException; import java.sql.SQLTimeoutException; import java.sql.Statement; -import org.apache.tomcat.jdbc.pool.util.MessageFactory; import org.junit.jupiter.api.Assertions; import org.junit.jupiter.api.Test; +import org.apache.tomcat.jdbc.pool.util.MessageFactory; + /** * Pins the exception translation the trap performs on each of its paths: a * declared exception is re-thrown as the same instance - nothing of its diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutDriverRefusal.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutDriverRefusal.java index 84a4a5ad45..c94f887667 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutDriverRefusal.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutDriverRefusal.java @@ -33,6 +33,7 @@ import java.util.ArrayList; import java.util.List; import java.util.Properties; import java.util.concurrent.atomic.AtomicInteger; +import java.util.function.Supplier; import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.LogRecord; @@ -64,6 +65,9 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { private static final String QUERY_TIMEOUT_WARNING = "Unable to set the query timeout of 5 seconds"; + /* Substring identifying the unexpected-failure warning among the records. */ + private static final String UNEXPECTED_FAILURE_WARNING = "an exception other than a refusal"; + /* A pool whose driver refuses the timeout the interceptor configures. */ private DataSource refusingTimeoutPool() { DataSource ds = newDataSource(); @@ -73,6 +77,16 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { return ds; } + /* The same, with a driver that refuses the timeout unchecked, as a + * non-spec-compliant wrapper driver does. */ + private DataSource uncheckedRefusingTimeoutPool() { + DataSource ds = newDataSource(); + ds.setDriverClassName(UncheckedRefusingTimeoutDriver.class.getName()); + ds.getPoolProperties().setJdbcInterceptors( + QueryTimeoutInterceptor.class.getName() + "(queryTimeout=5)"); + return ds; + } + /* * Statements created and used through a pooled connection. Every creation * runs the interceptor's hook, so this is what generates refusals; each @@ -120,6 +134,117 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { } } + /** + * The report's job is the driver's reason for the refusal, so a driver + * that refuses without stating one must still produce a readable line: + * the exception's own name fills the reason slot, rather than the literal + * "null" the raw message would render there - a line the operator is told + * they will not get again should not be unreadable. + */ + @Test + void aRefusalWithoutAMessageIsStillReportedWithAReadableReason() throws Exception { + DataSource ds = newDataSource(); + ds.setDriverClassName(SilentRefusingTimeoutDriver.class.getName()); + ds.getPoolProperties().setJdbcInterceptors( + QueryTimeoutInterceptor.class.getName() + "(queryTimeout=5)"); + ds.createPool(); + + try (PoolLogCapture logs = new PoolLogCapture()) { + try (Connection pooled = ds.getConnection(); + Statement st = pooled.createStatement()) { + Assertions.assertTrue(st.execute("SELECT 1"), + "a message-less refusal must cost the timeout only, not the statement"); + } + List<String> refusals = logs.refusalMessages(); + Assertions.assertEquals(1, refusals.size(), "the message-less refusal is reported once"); + String message = refusals.get(0); + Assertions.assertFalse(message.contains(": null."), + "the reason slot must not render the raw null message: " + message); + Assertions.assertTrue(message.contains("java.sql.SQLException"), + "the exception's own name must stand in for the missing message: " + message); + } + } + + /** + * The widening that lets an unchecked refusal cost the timeout rather + * than the statement must not turn every unrelated driver stumble in + * that call into the assertion "the driver does not apply the timeout", + * and above all must not let one odd failure spend the single report the + * physical connection will ever get: a driver that fails the call oddly + * once and genuinely refuses it later has to be heard refusing it, or + * the one line the operator does get says the wrong thing about the + * wrong exception. + */ + @Test + void anUnexpectedFailureIsNeitherCalledARefusalNorSilencesOne() throws Exception { + DataSource ds = newDataSource(); + ds.setDriverClassName(MixedFailureTimeoutDriver.class.getName()); + ds.getPoolProperties().setJdbcInterceptors( + QueryTimeoutInterceptor.class.getName() + "(queryTimeout=5)"); + ds.createPool(); + MixedFailureTimeoutDriver.reset(); + + try (PoolLogCapture logs = new PoolLogCapture()) { + try (Connection pooled = ds.getConnection()) { + for (int creation = 1; creation <= 3; creation++) { + try (Statement st = pooled.createStatement()) { + Assertions.assertTrue(st.execute("SELECT 1"), + "an unexpected failure in the timeout call must still cost only the timeout"); + } + } + } + List<String> unexpected = logs.unexpectedFailures(); + List<String> refusals = logs.refusalMessages(); + Assertions.assertEquals(1, unexpected.size(), + "the unexpected failure is reported once per connection like a refusal"); + Assertions.assertEquals(1, refusals.size(), + "the genuine refusal after the unexpected failure must still be reported"); + Assertions.assertTrue(refusals.get(0).contains("genuine refusal"), + "the refusal line must carry the refusal's own reason: " + refusals.get(0)); + Assertions.assertFalse(unexpected.get(0).contains("does not apply"), + "the unexpected failure must not assert a driver refusal: " + unexpected.get(0)); + } + } + + /** + * A driver that refuses the timeout with an unchecked exception - the shape + * a non-spec-compliant wrapper driver uses, where the spec-compliant + * refusal is an exception the hook has to see coming - must fail exactly + * like the checked refusal. The interceptor's promise is that a refusal + * costs the timeout and not the statement, and that promise does not depend + * on whether the driver's refusal happens to be a checked exception; a + * refusal the hook lets escape closes the statement behind the failed + * creation and leaves the pool unable to create any statement at all, in + * silence. + */ + @Test + void anUncheckedRefusalStillLeavesAUsableStatementAndReportsItOnce() throws Exception { + DataSource ds = uncheckedRefusingTimeoutPool(); + ds.createPool(); + TIMEOUT_ATTEMPTS.set(0); + + try (PoolLogCapture logs = new PoolLogCapture()) { + try (Connection pooled = ds.getConnection()) { + try (Statement st = pooled.createStatement()) { + Assertions.assertTrue(st.execute("SELECT 1"), + "a statement whose timeout the driver refused unchecked must still run its query"); + Assertions.assertEquals(0, st.getQueryTimeout(), + "a statement the driver refused must not claim a timeout"); + } + Assertions.assertEquals(1, TIMEOUT_ATTEMPTS.get(), + "the hook must try the configured timeout before noticing the refusal"); + logs.assertRefusals(1, UnsupportedOperationException.class, + "the unchecked refusal is as reportable as the checked one"); + try (Statement again = pooled.createStatement()) { + Assertions.assertTrue(again.execute("SELECT 1"), + "the refusal must not poison the connection for later statements"); + } + logs.assertRefusals(1, UnsupportedOperationException.class, + "the unchecked refusal is reported once per physical connection like the checked one"); + } + } + } + /** * The pool caches one interceptor chain per pooled connection, so the * statements of one physical session all meet the same interceptor instance @@ -247,6 +372,16 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { * interceptor having gone quiet. */ void assertRefusals(int expected, String why) { + assertRefusals(expected, SQLException.class, why); + } + + /* + * As above, with the shape of the driver's refusal pinned per case: + * the spec-compliant refusal is checked, the wrapper-driver one is + * not, and the report must carry the driver's own exception either + * way. + */ + void assertRefusals(int expected, Class<? extends Throwable> thrownType, String why) { List<LogRecord> seen; synchronized (records) { seen = new ArrayList<>(records); @@ -264,7 +399,7 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { "the report must say that the timeout is not in effect: " + record.getMessage()); Assertions.assertTrue(record.getMessage().contains("not logged again"), "the report must say what the log will not show later: " + record.getMessage()); - Assertions.assertInstanceOf(SQLException.class, record.getThrown(), + Assertions.assertInstanceOf(thrownType, record.getThrown(), "the driver's refusal must survive as the cause: " + record.getMessage()); } } @@ -274,6 +409,26 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { logger.removeHandler(handler); logger.setLevel(originalLevel); } + + /* The refusal warning messages captured, for content assertions. */ + List<String> refusalMessages() { + synchronized (records) { + return records.stream() + .map(LogRecord::getMessage) + .filter(m -> m != null && m.contains(QUERY_TIMEOUT_WARNING)) + .collect(Collectors.toList()); + } + } + + /* The unexpected-failure warning messages captured. */ + List<String> unexpectedFailures() { + synchronized (records) { + return records.stream() + .map(LogRecord::getMessage) + .filter(m -> m != null && m.contains(UNEXPECTED_FAILURE_WARNING)) + .collect(Collectors.toList()); + } + } } /** @@ -287,6 +442,18 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { private final Driver delegate = new org.h2.Driver(); + /** + * The refusal this driver's statements hand out. Checked, the way the + * JDBC spec says a driver refuses a feature; the subclass below swaps + * in the unchecked shape a non-compliant wrapper uses. + * + * @return the supplier of the exception the wrapped statements throw + * from {@code setQueryTimeout} + */ + protected Supplier<Throwable> refusal() { + return () -> new SQLException("this driver does not support query timeouts"); + } + @Override public Connection connect(String url, Properties info) throws SQLException { Connection connection = delegate.connect(url, info); @@ -296,7 +463,7 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { return (Connection) Proxy.newProxyInstance( RefusingTimeoutDriver.class.getClassLoader(), new Class<?>[] { Connection.class }, - new RefusingConnectionHandler(connection)); + new RefusingConnectionHandler(connection, refusal())); } @Override @@ -337,9 +504,11 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { private static class RefusingConnectionHandler implements InvocationHandler { private final Connection vendor; + private final Supplier<Throwable> refusal; - RefusingConnectionHandler(Connection vendor) { + RefusingConnectionHandler(Connection vendor, Supplier<Throwable> refusal) { this.vendor = vendor; + this.refusal = refusal; } @Override @@ -360,7 +529,7 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { private Object refusing(Statement statement, Class<?> api) { return Proxy.newProxyInstance(RefusingTimeoutDriver.class.getClassLoader(), - new Class<?>[] { api }, new RefusingStatementHandler(statement)); + new Class<?>[] { api }, new RefusingStatementHandler(statement, refusal)); } } @@ -371,21 +540,80 @@ class TestQueryTimeoutDriverRefusal extends JdbcPoolBaseTest { private static class RefusingStatementHandler implements InvocationHandler { private final Statement vendor; + private final Supplier<Throwable> refusal; - RefusingStatementHandler(Statement vendor) { + RefusingStatementHandler(Statement vendor, Supplier<Throwable> refusal) { this.vendor = vendor; + this.refusal = refusal; } @Override public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { if ("setQueryTimeout".equals(method.getName())) { TIMEOUT_ATTEMPTS.incrementAndGet(); - throw new SQLException("this driver does not support query timeouts"); + throw refusal.get(); } return delegate(vendor, method, args); } } + /* + * The same refusal as {@link RefusingTimeoutDriver}, but thrown unchecked - + * a shape no compliant driver uses and wrapper drivers do. Configured + * through {@code driverClassName}, so it must stay public with a no-arg + * constructor. + */ + public static class UncheckedRefusingTimeoutDriver extends RefusingTimeoutDriver { + + @Override + protected Supplier<Throwable> refusal() { + return () -> new UnsupportedOperationException("query timeouts are not implemented"); + } + } + + /* + * Refuses the timeout with a checked exception that carries no message - + * a driver stating that it refuses without saying why. Configured through + * {@code driverClassName}, so it must stay public with a no-arg + * constructor. + */ + public static class SilentRefusingTimeoutDriver extends RefusingTimeoutDriver { + + @Override + protected Supplier<Throwable> refusal() { + return SQLException::new; + } + } + + /* + * A driver whose setQueryTimeout fails three ways in a row: once with an + * unrelated unchecked exception (a driver bug, not a refusal), then with a + * genuine checked refusal, then with the unrelated failure again. The + * interceptor must tell the bug from the refusal, and the bug must not + * spend the refusal's single report. Configured through + * {@code driverClassName}, so it must stay public with a no-arg + * constructor. + */ + public static class MixedFailureTimeoutDriver extends RefusingTimeoutDriver { + + private static final AtomicInteger ATTEMPTS = new AtomicInteger(); + + static void reset() { + ATTEMPTS.set(0); + } + + @Override + protected Supplier<Throwable> refusal() { + return () -> { + int attempt = ATTEMPTS.incrementAndGet(); + if (attempt == 2) { + return new SQLException("genuine refusal"); + } + return new IllegalStateException("driver bug number " + attempt); + }; + } + } + /* Calls the vendor method, letting its own exception out unchanged. */ private static Object delegate(Object target, Method method, Object[] args) throws Throwable { try { diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutMalformedProperty.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutMalformedProperty.java index 8c716b3530..a6ee8df289 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutMalformedProperty.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutMalformedProperty.java @@ -54,6 +54,14 @@ class TestQueryTimeoutMalformedProperty extends JdbcPoolBaseTest { */ private static final String MALFORMED_REPORT = "is not an integer number of seconds"; + /* + * Stable fragment of the report of an unrecognized property name. The + * name-typo case is the asymmetric one: a bad value warns while a + * mis-cased name used to leave the aggressive one-second default armed in + * silence, degrading protection in the destructive direction. + */ + private static final String UNKNOWN_NAME_REPORT = "is not recognized and is not applied"; + private DataSource poolWith(String interceptorEntry) { DataSource ds = newDataSource(); ds.getPoolProperties().setJdbcInterceptors(interceptorEntry); @@ -148,6 +156,45 @@ class TestQueryTimeoutMalformedProperty extends JdbcPoolBaseTest { } } + @Test + void unknownPropertyNameIsReportedAndKeepsTheDefault() throws Exception { + try (PoolLogCapture logs = new PoolLogCapture()) { + // the lowercase t makes this a different name, not a spelling of + // the property: the intended ten seconds never arrive and the + // one-second default goes on cancelling real queries + DataSource ds = poolWith(QueryTimeoutInterceptor.class.getName() + "(querytimeout=10)"); + ds.createPool(); + try (Connection pooled = ds.getConnection()) { + assertDriverTimeout(pooled, 1, + "an unrecognized name must not be read as the property - the default stays in" + + " effect, which is exactly why the typo must not pass in silence"); + } + List<LogRecord> reports = logs.assertUnknownNameReports(2, + "the instance the pool configures at start plus the chain the first borrow builds;" + + " the pool-stop instance is configured after this capture is closed"); + for (LogRecord report : reports) { + Assertions.assertTrue(report.getMessage().contains("[querytimeout]"), + "the report must name the unrecognized property: " + report.getMessage()); + } + } + } + + @Test + void knownPropertyNamesAreSilent() throws Exception { + try (PoolLogCapture logs = new PoolLogCapture()) { + // useEquals is a name the JdbcInterceptor base reads; recognizing + // it keeps the warning a report about typos and not about every + // configuration that is more than a single property + DataSource ds = poolWith( + QueryTimeoutInterceptor.class.getName() + "(queryTimeout=5,useEquals=false)"); + ds.createPool(); + try (Connection pooled = ds.getConnection()) { + assertDriverTimeout(pooled, 5, "both known names apply as themselves"); + } + logs.assertUnknownNameReports(0, "a configuration made only of known names is not a typo"); + } + } + /** * Captures what {@link QueryTimeoutInterceptor} logs, following the * handler idiom of the pool's other diagnostic tests. The canary record - @@ -219,6 +266,31 @@ class TestQueryTimeoutMalformedProperty extends JdbcPoolBaseTest { return reports; } + /* + * Every report of an unrecognized property name, with the volume + * pinned and each report checked to be a warning naming the property, + * the way the bad-value reports above are checked. + */ + List<LogRecord> assertUnknownNameReports(int expected, String why) { + List<LogRecord> seen; + synchronized (records) { + seen = new ArrayList<>(records); + } + List<LogRecord> reports = seen.stream() + .filter(r -> r.getMessage() != null && r.getMessage().contains(UNKNOWN_NAME_REPORT)) + .collect(Collectors.toList()); + Assertions.assertEquals(expected, reports.size(), + why + ", messages seen: " + seen.stream().map(LogRecord::getMessage) + .collect(Collectors.toList())); + for (LogRecord record : reports) { + Assertions.assertEquals(Level.WARNING.intValue(), record.getLevel().intValue(), + "the report of a bad name is a warning, not something quieter: " + record.getMessage()); + Assertions.assertTrue(record.getMessage().contains("property"), + "the report must say it rejects a property: " + record.getMessage()); + } + return reports; + } + @Override public void close() { logger.removeHandler(handler); diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutXaBypassWarning.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutXaBypassWarning.java new file mode 100644 index 0000000000..2e8f333e2f --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryTimeoutXaBypassWarning.java @@ -0,0 +1,227 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.tomcat.jdbc.pool.interceptor; + +import java.sql.Connection; +import java.sql.Statement; +import java.util.ArrayList; +import java.util.List; +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 javax.sql.XAConnection; + +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.DataSource; +import org.apache.tomcat.jdbc.pool.XADataSource; + +/** + * On a pool backed by a {@link javax.sql.XADataSource} the applications' + * statements are created on the session that + * {@link javax.sql.XAConnection#getConnection()} hands out, which is the + * physical session from behind the interceptor chain - so the query timeout + * this interceptor configures never reaches them. That is a property of the + * pool's dispatch, not something this class can change, but the interceptor + * must not then go about its silence: an operator who configured the timeout + * as a protection has to hear, at pool start, that the pool they configured is + * one this interceptor cannot serve. And the warning must stay honest - it is + * due on an XA pool with a configured timeout and on no other pool, and not + * even on an XA pool whose timeout is switched off. + */ +class TestQueryTimeoutXaBypassWarning extends JdbcPoolBaseTest { + + /** Substring identifying the bypass warning among the captured records. */ + private static final String BYPASS_WARNING = "will not reach the statements applications create"; + + /* + * An XA-backed pool with this interceptor configured the way an operator + * configures it, backed by H2's real XA data source so the dispatch under + * test is the pool's genuine XA path. + */ + private XADataSource xaPool(String interceptorProperties) { + org.h2.jdbcx.JdbcDataSource inner = new org.h2.jdbcx.JdbcDataSource(); + inner.setUrl(getUrl()); + inner.setUser("sa"); + inner.setPassword(""); + XADataSource ds = new XADataSource(); + ds.setDriverClassName("org.h2.Driver"); + ds.getPoolProperties().setJmxEnabled(false); + ds.getPoolProperties().setInitialSize(1); + ds.getPoolProperties().setMinIdle(0); + ds.getPoolProperties().setDataSource(inner); + ds.getPoolProperties().setJdbcInterceptors( + QueryTimeoutInterceptor.class.getName() + interceptorProperties); + return manage(ds); + } + + /** + * The warning is about a hole that is really there: prove it end to end on + * the same pool - a statement created through the XA handle's + * {@code getConnection()} keeps the driver's own timeout while a statement + * created on a chained borrow gets the configured one - before asserting + * that the interceptor says so at start. + */ + @Test + void anXaPoolHearsOneBypassWarningAtStartNamingWhatItCovers() throws Exception { + XADataSource ds = xaPool("(queryTimeout=5)"); + try (BypassLogCapture logs = new BypassLogCapture()) { + ds.createPool(); + logs.assertBypassWarnings(1, "an XA pool must be told once at start"); + + // The hole the warning names: statements from the XA handle's + // logical session never pass through the interceptor. + XAConnection xc = ds.getXAConnection(); + try { + Connection logical = xc.getConnection(); + try (Statement st = logical.createStatement()) { + Assertions.assertEquals(0, st.getQueryTimeout(), + "a statement created through XAConnection.getConnection() must be untouched by the interceptor"); + } + } finally { + xc.close(); + } + + // And the warning must not be talk about a hole this pool does + // not have: a statement created on the chained borrow is timed. + try (Connection pooled = ds.getConnection(); + Statement st = pooled.createStatement()) { + Assertions.assertEquals(5, st.getQueryTimeout(), + "a statement created through the chain must carry the configured timeout"); + } + } + } + + /** + * A plain pool - driver and URL, no XA data source - serves its statements + * through the chain, so there is nothing to warn about and the interceptor + * must stay quiet about a bypass that does not exist. + */ + @Test + void aPlainPoolHearsNoBypassWarning() throws Exception { + DataSource ds = newDataSource(); + ds.getPoolProperties().setJdbcInterceptors( + QueryTimeoutInterceptor.class.getName() + "(queryTimeout=5)"); + try (BypassLogCapture logs = new BypassLogCapture()) { + ds.createPool(); + try (Connection pooled = ds.getConnection(); + Statement st = pooled.createStatement()) { + Assertions.assertEquals(5, st.getQueryTimeout(), + "the chained path must still apply the timeout the silence of this test is about"); + } + logs.assertBypassWarnings(0, "a pool that serves its statements through the chain has no bypass to report"); + } + } + + /** + * A timeout of zero switches the interceptor off, so on such a pool nothing + * is withheld and the bypass warning would report a missing protection + * nobody configured. The silence here is the honest one. + */ + @Test + void anXaPoolWithoutAConfiguredTimeoutHearsNoBypassWarning() throws Exception { + XADataSource ds = xaPool("(queryTimeout=0)"); + try (BypassLogCapture logs = new BypassLogCapture()) { + ds.createPool(); + logs.assertBypassWarnings(0, + "a switched-off interceptor has no protection to report as bypassed"); + } + } + + /** + * Captures what {@link QueryTimeoutInterceptor} 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 pool + * under test gets its chance to log. + */ + private static final class BypassLogCapture implements AutoCloseable { + private static final String CANARY = "query-timeout-xa-bypass-handler-wiring-canary"; + + private final Logger logger = Logger.getLogger(QueryTimeoutInterceptor.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 + } + }; + + BypassLogCapture() { + logger.addHandler(handler); + logger.setLevel(Level.ALL); + LogFactory.getLog(QueryTimeoutInterceptor.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 bypass warnings seen so far, with the volume pinned: an empty + * list fails the no-warning tests as silently as a chatty one fails the + * warning test, so both directions assert here. + */ + void assertBypassWarnings(int expected, String why) { + List<LogRecord> seen; + synchronized (records) { + seen = new ArrayList<>(records); + } + List<LogRecord> warnings = seen.stream() + .filter(r -> r.getMessage() != null && r.getMessage().contains(BYPASS_WARNING)) + .collect(Collectors.toList()); + Assertions.assertEquals(expected, warnings.size(), + why + ", messages seen: " + seen.stream().map(LogRecord::getMessage) + .collect(Collectors.toList())); + for (LogRecord record : warnings) { + Assertions.assertEquals(Level.WARNING.intValue(), record.getLevel().intValue(), + "the bypass is a warning, not something quieter: " + record.getMessage()); + Assertions.assertTrue(record.getMessage().contains("javax.sql.XADataSource"), + "the report must name the backing that causes it: " + record.getMessage()); + Assertions.assertTrue(record.getMessage().contains("XAConnection.getConnection()"), + "the report must name the route the statements escape by: " + record.getMessage()); + } + } + + @Override + public void close() { + logger.removeHandler(handler); + logger.setLevel(originalLevel); + } + } +} --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
