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 2917915fbbaf7b80d474bf6b7bc4c357ce892f1c Author: opencode <[email protected]> AuthorDate: Tue Nov 3 23:31:59 2026 +0100 Keep the abandoned timer on the borrow it is armed for Eight iterative fixes on the interceptor that resets the abandoned connection timer on activity, folded into one change. Each was found in verification or in a clean-room review of the class, and each is pinned by a test: TestResetAbandonedTimerNestedCursor, TestResetAbandonedTimerSuspectReturnReport, TestResetAbandonedTimerMBeanIdle, TestResetAbandonedTimerFailedSetupDiscard and TestResetAbandonedTimerParkedCallStamp are new. Coverage. A cursor the application reaches through ResultSet.getObject() - a nested cursor, or a REF cursor selected as a column - was handed out with the statement facade directly over the driver's object and no timer layer beneath it, so iterating it kept a session busy while this interceptor watched what it was told was an idle connection. The result- set handle now wraps every result set a call hands back, whatever the method that returned it was called, on the same return-type rule the statement handle already used and the facade applies above. Whose connection. The binding, the checked-out flag and the MBean name are volatile - the borrower's thread and the pool's write them, the activity hooks and the thread invoking the JMX operation read them - and the rebind and the disposal, together with the register/unregister pair, now run under one monitor, with the flag coming down before the binding so a reader outside the monitor reads a retired chain as over rather than as running. The JMX publish is documented as best effort: the name is keyed by class, so a chain that configures this interceptor twice asks twice for one name and the second instance is refused; the report of the refusal is deliberately left at error level as the configuration mistake an operator wants told about. Whose borrow. Stamping is now booked only for the connection that is checked out and for the borrow the stamping call started under. A volatile epoch is bumped under the monitor on every re-arm, and the connection hook and both handle proxies capture it as their call enters the chain and stamp only while it is still current; the checked-out flag alone cannot tell two borrows of one physical connection apart, because it is raised again for the next. A call parked in the driver while its borrow ended therefore no longer pushes the next borrower's abandonment deadline back by a full timeout and clears the suspect state recorded about that borrower - the facade above seals a handle after the borrow, but not a call already in flight beneath the seal. The execution stamp moved off the query-report hooks, which sit inside the parked frame and cannot see its borrow, onto the statement handle's own borrow-gated finally, and the prepare hooks defer to the connection hook that already wraps the same call. The query-report hooks and the MBean contract are documented accordingly, and a changelog entry describes the behaviour change. What the timer no longer touches. The borrow-end hook no longer stamps: that reset landed below the pool's own read of the suspect state, so a connection returned while suspected read back as never suspected and neither the log line nor the notification of the suspect-return report ever fired. The hook now only takes the flag down, which is also what keeps the close's own finally from stamping after the connection is back in the pool. A borrow whose setup walk threw after arming this interceptor used to park the connection idle with the chain still armed; the pool now discards that connection, so the half-armed chain goes out of service with it, as it already does for the neighbouring failures. Documentation. The user documentation said the timer resets on a successful query execution; it now says what it does - any operation, any attempted query whether it succeeds or fails, and every result set read, which is what keeps a large fetch alive. The two handle javadocs no longer claim every call is passed straight through, naming the identity, kept getStatement() and closed-contract answers that are not, and the claim about what a closed handle stops retaining is limited to the layer it actually releases - the interceptor beneath it, as with the facade's own inner-class handles, remains reachable. --- modules/jdbc-pool/doc/jdbc-pool.xml | 6 +- .../apache/tomcat/jdbc/pool/ConnectionPool.java | 9 +- .../jdbc/pool/interceptor/ResetAbandonedTimer.java | 429 ++++++++++---- .../pool/interceptor/ResetAbandonedTimerMBean.java | 13 +- .../TestResetAbandonedTimerFailedSetupDiscard.java | 246 ++++++++ .../TestResetAbandonedTimerMBeanIdle.java | 283 +++++++++ .../TestResetAbandonedTimerNestedCursor.java | 650 +++++++++++++++++++++ .../TestResetAbandonedTimerParkedCallStamp.java | 402 +++++++++++++ ...TestResetAbandonedTimerSuspectReturnReport.java | 240 ++++++++ webapps/docs/changelog.xml | 12 + 10 files changed, 2168 insertions(+), 122 deletions(-) diff --git a/modules/jdbc-pool/doc/jdbc-pool.xml b/modules/jdbc-pool/doc/jdbc-pool.xml index d13ada6d0e..f82475e075 100644 --- a/modules/jdbc-pool/doc/jdbc-pool.xml +++ b/modules/jdbc-pool/doc/jdbc-pool.xml @@ -917,8 +917,10 @@ This means if you have a 30second timeout and run 10x10second queries using the connection it will be marked abandoned and potentially reclaimed depending on the <code>abandonWhenPercentageFull</code> attribute. - Using this interceptor it will reset the checkout timer every time you perform an operation on the connection or execute a - query successfully. + Using this interceptor it will reset the checkout timer every time you perform an operation on the + connection or attempt to execute a query, whether the attempt succeeds or fails, and on every read of a + result set returned through the connection. Iterating a large result set therefore keeps the connection + alive through the fetch phase, rather than only until the query returns. </p> <attributes> </attributes> diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java index 1fc81ca409..2e059606eb 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java @@ -523,7 +523,14 @@ public class ConnectionPool { } catch (Exception x) { SQLException s = new SQLException(); s.initCause(x); - abandonSetup(con, s, false); + // The reset walk above has already armed every interceptor of the chain for this borrow, and from here + // no close() will ever travel that chain - the handle was never handed out - while the return path does + // not walk the chain either. The connection itself is healthy; it is the borrow state that is unusable, + // and there is no chain-wide unwind that is safe for arbitrary interceptors, as each keys its disposal + // on the reset(null, null) call the release's setHandler(null) makes (StatementCache.reset is one). + // So the half-armed chain goes out of service with the connection, the posture the two catches above + // take, rather than being parked idle armed for a borrow that never started. + abandonSetup(con, s, true); throw s; } diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java index 1a8767cf8b..a3f6662296 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java @@ -44,22 +44,68 @@ import org.apache.tomcat.jdbc.pool.util.MessageFactory; * itself blocks on the database for longer than * {@link org.apache.tomcat.jdbc.pool.PoolConfiguration#setRemoveAbandonedTimeout(int)} still gets the connection * abandoned. The statement facade is always used, so a result set handle that outlives its borrow is sealed off before - * it can go on refreshing the abandoned timer of whoever holds that physical connection next. The handles this - * interceptor hands out release what they wrap - the statement layer, the physical result set - once a close has been - * forwarded to it, and answer any later call from the closed contract, as the statement facade's own handles do; a - * handle the application keeps beyond its close therefore stops keeping the physical objects below it reachable. This + * it can go on refreshing the abandoned timer of whoever holds that physical connection next, and because every stamp + * from a call counts only for the borrow that call was started under, a call that was still in flight when its borrow + * ended cannot refresh that timer either. The handles this interceptor hands out release what they wrap - the + * statement layer, the physical result set - once a close has been forwarded to them, and answer any later call from + * the closed contract, as the statement facade's own handles do; a handle the application keeps beyond its close + * therefore stops keeping the physical objects it wrapped reachable, though it continues to keep the interceptor + * beneath it, and through it the pooled connection, reachable - as the facade's own inner-class handles do. This * interceptor is useful for when you have a * {@link org.apache.tomcat.jdbc.pool.PoolConfiguration#setRemoveAbandonedTimeout(int)} that is fairly low, and you - * want to reset the abandoned time each time any operation on the connection is performed This is useful for batch + * want to reset the abandoned time each time any operation on the connection is performed. This is useful for batch * processing programs that use connections for extensive amount of times. */ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAbandonedTimerMBean { private static final Log log = LogFactory.getLog(ResetAbandonedTimer.class); - private PooledConnection pcon; + /** + * The pooled connection this instance is bound to. It is written by the + * borrow that binds the chain and by the disposal that releases it, which + * are the borrower's thread and the pool's own, and it is read by the + * activity hooks and by whichever thread invokes the JMX operation, so, as + * in the proxies below, volatile in order to reach those readers at all. + */ + private volatile PooledConnection pcon; + + /** + * Whether the pooled connection this instance is bound to is currently + * checked out. It is written by the paths that settle that binding - the + * borrow that arms the chain, the close that ends the borrow and the + * disposal of the chain - which are the borrower's thread and the pool's + * own, and it is read by the activity hooks and by whichever thread invokes + * the JMX operation, so, as in the proxies below, volatile in order to reach + * those readers at all. + */ + private volatile boolean checkedOut; - private ObjectName oname = null; + /** + * Identifies the borrow that armed this instance. It is bumped by the + * walk that arms the chain, so a value taken from this field names one + * particular borrow for as long as that borrow, and no other, is the + * armed one. It exists because the flag beside it identifies only the + * pooled connection, and a connection is borrowed again after it is + * handed back: the call of a past borrow that was still in flight when + * that borrow ended finds the flag up again, raised for the newer + * borrow it has nothing to do with. A frame that stamps from a call + * therefore carries the value captured when the call entered the chain, + * and stamps only while it is still the current one; the value is + * bumped, never reused, so a past borrow's value can never answer for a + * later one. As in the fields beside it, volatile in order to reach the + * stamping threads at all. + */ + private volatile long borrowEpoch; + + /** + * The name this instance is registered under as an MBean, or {@code null} + * while it is not registered. The borrow that registers it and the disposal + * that unregisters it are different threads, and a disposal reading a + * stale null would skip the unregistration and leave the MBean published, + * pinning this instance and everything it reaches, so volatile like the + * fields beside it. + */ + private volatile ObjectName oname = null; /** * Default constructor. @@ -71,38 +117,129 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba public void reset(ConnectionPool parent, PooledConnection con) { super.reset(parent, con); if (con == null) { - this.pcon = null; - if (oname != null) { - JmxUtil.unregisterJmx(oname); - oname = null; + // The chain is going out of service. The monitor is the one the + // borrow takes below, so the unbinding and the unregistration + // cannot interleave with a rebind. Within it the flag comes down + // before the binding does, so that a reader which catches the + // binding while it is still live - the JMX caller reads these + // fields without the monitor - reads this borrow as over rather + // than as running, and stamps nothing. + synchronized (this) { + this.checkedOut = false; + this.pcon = null; + if (oname != null) { + JmxUtil.unregisterJmx(oname); + oname = null; + } } } else { - this.pcon = con; - if (oname == null) { - String keyprop = ",JdbcInterceptor=" + getClass().getSimpleName(); - oname = JmxUtil.registerJmx(pcon.getObjectName(), keyprop, this); + // This walk is the borrow, under the same monitor the disposal + // takes above: the connection it binds is the one being handed + // out, so from here on the timer this class keeps is worth + // resetting again, and the name registered here can never be + // missed by an unbinding running beside this walk. + synchronized (this) { + // The new borrow's identity is taken before the binding is + // published: a call that enters the chain from here on + // captures this value and stands for this borrow, and every + // frame that captured a value before it now names a borrow + // that is over, whatever else it finds settled. + this.borrowEpoch++; + this.pcon = con; + this.checkedOut = true; + if (oname == null) { + // The publish is best effort: what this interceptor does on + // the borrow path does not depend on its management + // surface, and a connection the application reaches without + // an MBean works exactly like one it reaches with. The name + // is keyed by the class rather than the instance, so a + // chain that configures this interceptor twice asks twice + // for one name and the second instance is refused - a + // configuration mistake an operator wants told about, and + // told about on every attempt, which is why the report of + // the refusal is left where JmxUtil puts it: at error + // level, with the exception behind it. A refused name is + // not claimed here, so it stays the property of whoever + // holds it and the next borrow tries again. + String keyprop = ",JdbcInterceptor=" + getClass().getSimpleName(); + oname = JmxUtil.registerJmx(pcon.getObjectName(), keyprop, this); + } } } } + /** + * Resets the abandoned timer of the pooled connection this interceptor is bound to, and only while that connection + * is checked out. This is the implementation of the MBean operation; the activity hooks below stamp through + * {@link #stampFor(long)}, which adds a borrow gate on top of this one. The flag alone is what keeps the management + * operation off a connection that is idle in the pool, where a stamp had nothing to avert - the abandoned check + * looks only at connections that are held - and did undo the age + * {@link org.apache.tomcat.jdbc.pool.ConnectionPool#checkIdle()} measures it by. That flag is also what keeps the + * stamp from the close's own finally: by the time that finally runs, the borrow it would answer for is over. What + * the flag cannot tell apart is the late finally of a call that was in flight when its borrow ended and whose + * connection has since been borrowed again - the flag is up again by then, for a borrow the late call is not part + * of - which is why the hooks are gated on the borrow, not on this flag alone. + * + * @return {@code true} if the timestamp of a checked-out connection was reset, {@code false} if this interceptor is + * bound to no connection or to one that is not checked out + */ @Override public boolean resetTimer() { - boolean result = false; - if (pcon != null) { - pcon.setTimestamp(System.currentTimeMillis()); - result = true; + // Each field is read once: both are settled by other threads, and a gate + // that read one of them twice could act on a state that no longer holds. + // The window this leaves is the race itself - a stamp taken on a + // connection that was being discarded as the read happened, at most one + // - which is the posture the proxies below take toward a concurrent + // close, and borne for the same reason: no decision is taken on a + // timestamp of a connection that is on its way out. + final PooledConnection con = pcon; + final boolean held = checkedOut; + if (con == null || !held) { + return false; } - return result; + con.setTimestamp(System.currentTimeMillis()); + return true; + } + + /** + * Takes the stamp of an activity hook on behalf of the frame that entered the chain under the given borrow. + * <p> + * A call that entered the chain during one borrow can finish after that borrow has ended and after the same pooled + * connection has been handed to the next borrower - the application closed the handle from another thread while + * the call was still with the driver, which is the very situation this interceptor is configured against. The flag + * {@link #resetTimer()} reads is up again by then, raised for that newer borrow, so a hook stamping through it + * directly would attribute this call's activity to whoever holds the connection now: it would push that borrower's + * abandonment deadline back by a full timeout, and {@link PooledConnection#setTimestamp(long)} would clear the + * suspect state recorded about that borrow. The borrow the frame entered under tells the two apart: an armed chain + * past this frame's borrow has bumped the epoch this frame captured, and its stamp is refused. + * <p> + * What the gate costs a legitimate call whose close races it is its own stamp, which has nothing left to avert: + * the borrow it would protect is ending as the stamp is decided. + * + * @param epoch the borrow this frame captured when it entered the chain + */ + private void stampFor(long epoch) { + // The epoch is read once, as in resetTimer(): it is settled by the + // thread that arms the chain, and a second read could match an arm + // this frame has nothing to do with. + if (epoch != borrowEpoch) { + return; + } + resetTimer(); } @Override public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { + final long epoch = borrowEpoch; try { return super.invoke(proxy, method, args); } finally { // The operation was attempted on the connection, which counts - // as activity even when it failed - resetTimer(); + // as activity even when it failed - for the borrow the call + // entered the chain under, and for that one only: if that + // borrow is over, whoever holds the connection now is not to + // be kept alive by this call's completing + stampFor(epoch); } } @@ -131,6 +268,11 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba } return getConstructor(index, type).newInstance(new Object[] { new TimerStatementProxy(result) }); } catch (Exception x) { + // The application keeps the query-report handle beneath: its + // result sets come un-wrapped, and since the execution stamp is + // taken on this handle, its queries keep no timer either. The + // degraded keep-alive this leaves is the price of the one stamp + // that knows its own borrow. log.warn(MessageFactory.get("resetAbandonedTimer.unableToCreateTimerStatementProxy", getClass().getName()), x); } @@ -139,46 +281,52 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba @Override protected void prepareCall(String query, long time) { - resetTimer(); + // Nothing is stamped here. A prepare is a call on the connection, and + // the invoke() above stamps it once the call completes, under the + // borrow that call entered the chain under; a hook cannot see that + // borrow, so a stamp taken here would be taken without the gate, in + // the middle of a call that may outlive its borrow. } @Override protected void prepareStatement(String sql, long time) { - resetTimer(); - + // As above } + /** + * Takes the borrow down. The base class fires this hook on the connection-level close, on the way down to the pool + * and once per borrow, so it is where this instance stops belonging to a checked-out connection - and it comes down + * here, on the way to the pool, rather than at the unbind below, because that unbind does not happen on a return at + * all: the chain stays bound to its pooled connection for the whole idle period, so a flag left up until then would + * leave every hook of this interceptor, and the MBean operation, acting on a connection the application let go of. + * <p> + * What this hook still does not do is stamp. It runs at the end of a borrow rather than during it, which is + * precisely where a stamp has nothing left to avert. An abandonment or suspect decision is a decision about a borrow + * that is still held, and the sweep that makes it has looked at this connection before the close started. What a + * stamp here does change is the state the return is reported from, and that read happens below this hook, in the + * pool: {@link PooledConnection#setTimestamp(long)} clears the suspect flag and moves the timestamp the elapsed time + * of that report is computed from, so resetting here hands {@code ConnectionPool.returnConnection} a connection that + * reads as never suspected, and neither half of that report - neither the log line nor the notification - ever + * speaks for the connections it exists for. The stamp a returned connection does need, the timestamp it goes idle + * under, is the return path's own to write and it writes it, below this hook. The close is therefore the one call on + * a borrowed connection this interceptor leaves unstamped, and the flag lowered here is what keeps it that way: + * {@link #invoke(Object, Method, Object[])} stamps once the call it wraps has run, so without the flag its finally + * would take that stamp after the connection is back in the pool and its state has been settled - which is the same + * interference one layer down. The override stays because the hook is abstract in the base class. + */ @Override public void closeInvoked() { - resetTimer(); - } - - @Override - protected String reportFailedQuery(String query, Object[] args, String name, long start, long delta, - Throwable t) { - // The timer only needs to know that the execution was attempted, so - // it takes no interest in the start or the duration it reports - resetTimer(); - return super.reportFailedQuery(query, args, name, start, delta, t); - } - - @Override - protected String reportQuery(String query, Object[] args, String name, long start, long delta) { - resetTimer(); - return super.reportQuery(query, args, name, start, delta); - } - - @Override - protected String reportSlowQuery(String query, Object[] args, String name, long start, long delta) { - resetTimer(); - return super.reportSlowQuery(query, args, name, start, delta); + // The borrow is ending: see above + checkedOut = false; } /** * Proxy for a statement that turns the result sets the statement hands out into {@link TimerResultSetProxy} - * instances, whatever the method that returned one was called. Every other call is passed straight through to the - * wrapped statement, and so is what the {@link java.sql.Wrapper} methods hand back: a driver object reached through - * {@code unwrap()} stays the driver's own object, even one that implements {@link java.sql.ResultSet}. + * instances, whatever the method that returned one was called. Every other call is forwarded to the wrapped + * statement, apart from the identity of this handle and from every call after a close has been forwarded, which + * this proxy and the closed contract answer; what the {@link java.sql.Wrapper} methods hand back is forwarded + * unwrapped - a driver object reached through {@code unwrap()} stays the driver's own object, even one that + * implements {@link java.sql.ResultSet}. */ private final class TimerStatementProxy implements InvocationHandler { /** @@ -202,7 +350,10 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { // Handle identity on this proxy, like the statement facade // does, rather than on the object below it: the application - // must be able to rely on its own handles + // must be able to rely on its own handles. These answers come + // from this object alone, so they are not an operation on the + // connection and the timer stays as it is - as for the result + // set proxy's own identity calls below. if (compare(TOSTRING_VAL, method)) { return toString(); } @@ -215,71 +366,82 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba if (compare(HASHCODE_VAL, method)) { return Integer.valueOf(this.hashCode()); } - // Read the delegate once for this call: the close that nulls it - // can come from another thread, and the guards and the forward - // must agree on the one value this call read. A call that finds - // the delegate gone is answered from the closed contract below - - // the same answers the query report proxy beneath gives for its - // own closed state - rather than by invoking on a null receiver: - // that is a NullPointerException, where the closed contract owes - // the application a SQLException. The window this cannot close is - // the race itself: a call that read the delegate while it was - // still live goes to it, an outcome indistinguishable from having - // simply outrun the close. - final Object target = delegate; - final boolean close = compare(CLOSE_VAL, method); - // Allow close to be called multiple times, from either thread - if (close && target == null) { - return null; - } - if (compare(ISCLOSED_VAL, method) && target == null) { - return Boolean.TRUE; - } - if (target == null) { - throw new SQLException(MessageFactory.get("resetAbandonedTimer.statementClosed")); - } - Object result; + final long epoch = borrowEpoch; try { - // Execute the call on the delegate this call read as live: - // the snapshot keeps a concurrent close from replacing the - // receiver with null between the guards and the call - result = method.invoke(target, args); - } catch (InvocationTargetException x) { - Throwable cause = x.getCause(); - if (cause == null) { - throw x; + // Read the delegate once for this call: the close that nulls it + // can come from another thread, and the guards and the forward + // must agree on the one value this call read. A call that finds + // the delegate gone is answered from the closed contract below - + // the same answers the query report proxy beneath gives for its + // own closed state - rather than by invoking on a null receiver: + // that is a NullPointerException, where the closed contract owes + // the application a SQLException. The window this cannot close is + // the race itself: a call that read the delegate while it was + // still live goes to it, an outcome indistinguishable from having + // simply outrun the close. Under the always-installed facade an + // application never reaches these answers - the facade's own + // handle seals a retained handle first; they stand for a caller + // that holds this handle directly. + final Object target = delegate; + final boolean close = compare(CLOSE_VAL, method); + // Allow close to be called multiple times, from either thread + if (close && target == null) { + return null; } - throw cause; - } - // Perform close cleanup: the handle kept beyond this close now - // holds nothing that can reach the statement beneath it - if (close) { - delegate = null; - } - // Wrap every result set the call hands back, whatever the method - // that returned it was called, on the same rule the statement - // facade uses: a decision made on the method name only sees the - // three calls the standard API names, and misses the result sets - // declared to come back as an Object - a cursor OUT-parameter - // reaches the application through CallableStatement.getObject(...), - // and iterating it keeps a cursor open on this connection just as - // an executeQuery one does. The Wrapper methods are kept out of - // this for the facade's reason: unwrap() is the documented way to - // reach the driver's own object, and a driver's cursor type is - // such an object, so what it hands back stays the driver's object - // even where that object implements ResultSet. - if (result instanceof ResultSet && method.getDeclaringClass() != Wrapper.class) { + if (compare(ISCLOSED_VAL, method) && target == null) { + return Boolean.TRUE; + } + if (target == null) { + throw new SQLException(MessageFactory.get("resetAbandonedTimer.statementClosed")); + } + Object result; try { - return getConstructor(RESULTSET_IDX, ResultSet.class) - .newInstance(new Object[] { new TimerResultSetProxy(result, proxy) }); - } catch (Exception x) { - // The application just does not get the timer reset - // while reading this result set - log.warn(MessageFactory.get("resetAbandonedTimer.unableToCreateTimerResultSetProxy", - ResetAbandonedTimer.this.getClass().getName()), x); + // Execute on the delegate this call read as live + result = method.invoke(target, args); + } catch (InvocationTargetException x) { + Throwable cause = x.getCause(); + if (cause == null) { + throw x; + } + throw cause; } + // Perform close cleanup: the handle kept beyond this close now + // holds nothing that can reach the statement beneath it + if (close) { + delegate = null; + } + // Wrap every result set the call hands back, whatever the method + // that returned it was called, on the same rule the statement + // facade uses: a decision made on the method name only sees the + // three calls the standard API names, and misses the result sets + // declared to come back as an Object - a cursor OUT-parameter + // reaches the application through CallableStatement.getObject(...), + // and iterating it keeps a cursor open on this connection just as + // an executeQuery one does. The Wrapper methods are kept out of + // this for the facade's reason: unwrap() is the documented way to + // reach the driver's own object, and a driver's cursor type is + // such an object, so what it hands back stays the driver's object + // even where that object implements ResultSet. + if (result instanceof ResultSet && method.getDeclaringClass() != Wrapper.class) { + try { + return getConstructor(RESULTSET_IDX, ResultSet.class) + .newInstance(new Object[] { new TimerResultSetProxy(result, proxy) }); + } catch (Exception x) { + // The application just does not get the timer reset + // while reading this result set + log.warn(MessageFactory.get("resetAbandonedTimer.unableToCreateTimerResultSetProxy", + ResetAbandonedTimer.this.getClass().getName()), x); + } + } + return result; + } finally { + // The operation was attempted on the statement, which counts + // as activity on the connection even when it failed - the + // execution of a query, which this class exists to keep + // alive, passes through this handle like every other call on + // it. The stamp is the borrow's, as in the connection hook. + stampFor(epoch); } - return result; } @Override @@ -301,7 +463,13 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba /** * Proxy for a result set that resets the abandoned timer on every read, so that an application iterating a result - * set - or doing its per-row work between the reads - counts as active and is not abandoned mid-iteration. + * set - or doing its per-row work between the reads - counts as active and is not abandoned mid-iteration. Every + * result set a read hands out is turned into a handle of this proxy too, on the statement proxy's return-type rule, + * so that iterating a nested cursor reaches this timer as well; every other call is forwarded to the wrapped result + * set, apart from the identity of this handle, from the {@link java.sql.ResultSet#getStatement()} answer this proxy + * keeps, and from every call after a close has been forwarded, which this proxy and the closed contract answer; + * what the {@link java.sql.Wrapper} methods hand back is forwarded unwrapped - a driver object reached through + * {@code unwrap()} stays the driver's own object, even one that implements {@link java.sql.ResultSet}. */ private final class TimerResultSetProxy implements InvocationHandler { /** @@ -345,6 +513,7 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba if (compare(HASHCODE_VAL, method)) { return Integer.valueOf(this.hashCode()); } + final long epoch = borrowEpoch; try { // Read both fields once for this call: the close that nulls // them can come from another thread, and the guards and the @@ -374,9 +543,7 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba } Object result; try { - // Invoke on the delegate this call read as live: the - // snapshot keeps a concurrent close from replacing the - // receiver with null between the guards and the call + // Invoke on the delegate this call read as live result = method.invoke(target, args); } catch (InvocationTargetException x) { Throwable cause = x.getCause(); @@ -391,14 +558,42 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba delegate = null; statement = null; } + // The statement proxy's rule, mirrored one layer down: a + // cursor-valued column - a nested cursor, or a REF cursor + // selected as a column - reaches the application through a + // getObject(...) overload that comes back as an Object, and + // the facade above this handle wraps whatever a read hands + // back, so a cursor let through raw here reaches the + // application with the facade's handle directly over the + // driver's cursor: iterating it would keep the session busy + // while this interceptor's timer watched what it is told is an + // idle connection. The new handle is parented to the same + // statement as this one reports, so getStatement() keeps + // answering a Statement, and the Wrapper methods are kept out + // of this for the statement proxy's reason: unwrap() is the + // documented way to reach the driver's own object, and a + // driver's cursor type is such an object. + if (result instanceof ResultSet && method.getDeclaringClass() != Wrapper.class) { + try { + return getConstructor(RESULTSET_IDX, ResultSet.class) + .newInstance(new Object[] { new TimerResultSetProxy(result, stmt) }); + } catch (Exception x) { + // The application just does not get the timer reset + // while reading this nested cursor + log.warn(MessageFactory.get("resetAbandonedTimer.unableToCreateTimerResultSetProxy", + ResetAbandonedTimer.this.getClass().getName()), x); + } + } return result; } finally { // Reading the result set is activity on the connection, // even when the read failed. The guards above sit inside // this block, so a read refused on a handle whose delegate // has been released counts as activity too, like every - // other attempted operation on this connection. - resetTimer(); + // other attempted operation on this connection - for the + // borrow this call entered the handle under, and for that + // one only. + stampFor(epoch); } } diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimerMBean.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimerMBean.java index f3b5109c62..d084293a2e 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimerMBean.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimerMBean.java @@ -21,9 +21,18 @@ package org.apache.tomcat.jdbc.pool.interceptor; */ public interface ResetAbandonedTimerMBean { /** - * Reset the abandoned timer for the pooled connection. + * Reset the abandoned timer of the pooled connection this interceptor is + * bound to, while that connection is checked out. For a connection sitting + * idle in the pool the operation resets nothing - the abandoned timer is a + * property of a borrow, and the timestamp it moves is the age the idle check + * releases a connection by + * ({@link org.apache.tomcat.jdbc.pool.PoolConfiguration#setMinEvictableIdleTimeMillis(int)}), + * so the operation cannot postpone that release either. * - * @return True if the timer was reset, false if no connection is associated + * @return True if the timer was reset, false if the connection bound to this + * interceptor is not currently checked out - including a + * connection idle in the pool and one this interceptor has been + * unbound from */ boolean resetTimer(); } diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerFailedSetupDiscard.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerFailedSetupDiscard.java new file mode 100644 index 0000000000..539fcc63bf --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerFailedSetupDiscard.java @@ -0,0 +1,246 @@ +/* + * 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.lang.management.ManagementFactory; +import java.lang.reflect.Field; +import java.lang.reflect.Method; +import java.sql.Connection; + +import javax.management.InstanceNotFoundException; +import javax.management.MBeanServer; +import javax.management.ObjectName; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +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.PooledConnection; +import org.apache.tomcat.jdbc.pool.ProxyConnection; + +/** + * A borrow whose setup fails after the reset walk has already armed the + * interceptor chain must retire that chain with the connection, not park the + * connection idle under it. + * + * <p>{@code ConnectionPool.setupConnection()} walks the chain before it builds + * the handle, and the walk is the arm: every interceptor takes the pooled + * connection as its own and starts keeping per-borrow state - the timer + * interceptor also publishes its MBean below the connection's. A failure in + * the part of setup that comes after the walk therefore fails on a chain that + * is already armed, and the borrow ends through the setup's own catch rather + * than through a close: no close() will ever travel that chain from here, and + * the return path does not walk the chain either. The catch hands the sequence + * {@code setDiscarded(true)} and {@code returnConnection()}: the discarded flag + * makes the return release the connection, and the release walks + * {@code reset(null, null)} over the chain, which is the disposal every + * interceptor implements - for the timer it lowers the checked-out flag, drops + * the binding and takes its MBean back. Without the flag the same return parks + * the connection idle with the chain still armed: the timer keeps reporting a + * borrow nobody holds, and its operation rewrites the timestamp the idle check + * measures that connection's age by.</p> + * + * <p>The natural trigger for that catch - a proxy constructor that fails - + * cannot be forced from a test, so this test pins the premise the fix rests + * on: the exact sequence the fixed catch performs leaves no armed interceptor + * behind. It borrows from a published pool running nothing but the timer + * interceptor, confirms the arm through the MBean, drives the sequence + * reflectively, and finds the connection retired rather than parked: gone from + * the pool and from the MBean server, its timer unbound and its flag down.</p> + */ +class TestResetAbandonedTimerFailedSetupDiscard extends JdbcPoolBaseTest { + + /* The MBean operation that reads the interceptor's armed state. */ + private static final String RESET_TIMER = "resetTimer"; + + /* The pool under test, for the forced teardown below. */ + private DataSource pool; + + /* + * The sequence the fixed catch runs: the mark that turns the return into a + * release, then the return itself. Both are reached reflectively - the + * catch is private to the pool's setup path and no borrower can fail a + * proxy constructor on demand - and the test drives exactly what the catch + * does, in that order. + */ + private static void runAbandonSetup(ConnectionPool pool, PooledConnection con) throws Exception { + con.setDiscarded(true); + Method back = ConnectionPool.class.getDeclaredMethod("returnConnection", PooledConnection.class); + back.setAccessible(true); + back.invoke(pool, con); + } + + /* The interceptor's own record of the borrow it is armed for. */ + private static boolean armed(ResetAbandonedTimer timer) throws Exception { + Field checkedOut = ResetAbandonedTimer.class.getDeclaredField("checkedOut"); + checkedOut.setAccessible(true); + return checkedOut.getBoolean(timer); + } + + /* The pooled connection the interceptor instance is bound to, or null. */ + private static Object boundTo(ResetAbandonedTimer timer) throws Exception { + Field pcon = ResetAbandonedTimer.class.getDeclaredField("pcon"); + pcon.setAccessible(true); + return pcon.get(timer); + } + + /* + * These tests can end with the connection still borrowed (a failed + * assertion between the borrow and its retirement). The regular data + * source teardown only disconnects idle connections, so the session of a + * borrowed one would linger until the garbage collector finalizes it; + * force-close disconnects the busy ones as well, right away. The pool's + * publication is released with it, so nothing of these tests stays + * registered. + */ + @AfterEach + void disconnectLeakedBusyConnections() { + if (pool != null) { + pool.close(true); + pool.postDeregister(); + } + } + + /* + * A pool running nothing but the timer interceptor, published the way a + * container publishes one. The publication is what makes the interceptor's + * registration possible at all: it registers below the pooled connection, + * which registers below the pool's own MBean, so an unpublished pool has no + * name for them to sit under. The uid is carried down into every name + * derived from the registration, which is how the interceptor's name is + * found below a pool of this test's own and nothing else. + */ + private final class Published { + private final MBeanServer server = ManagementFactory.getPlatformMBeanServer(); + private final DataSource ds; + private final String uid; + + private Published(DataSource ds, String role) throws Exception { + this.ds = ds; + this.uid = Long.toString(System.nanoTime()); + ds.createPool(); + ds.preRegister(server, new ObjectName("tomcat:type=ResetAbandonedTimerFailedSetupTest,role=" + role + + ",uid=" + uid)); + Assertions.assertNotNull(ds.getPool().getJmxPool().getObjectName(), + "an enabled pool publishes its MBean together with its registration"); + pool = ds; + } + + /* + * The MBean the timer has published for the connection it is bound to, + * or {@code null} while no timer of this pool is registered. The test + * reads the name in both directions: present to confirm the arm, and + * gone to confirm the disposal the retirement owes. + */ + private ObjectName timerName() throws Exception { + ObjectName found = null; + for (ObjectName name : server.queryNames(new ObjectName("tomcat.jdbc:*"), null)) { + if (ResetAbandonedTimer.class.getSimpleName().equals(name.getKeyProperty("JdbcInterceptor")) + && uid.equals(name.getKeyProperty("uid"))) { + Assertions.assertNull(found, "this test hands out one pooled connection, but a second timer is" + + " published as " + name); + found = name; + } + } + return found; + } + + /* One call of the operation, as a management client makes it. */ + private Object poke(ObjectName oname) throws Exception { + return server.invoke(oname, RESET_TIMER, null, null); + } + } + + /* + * A pool with nothing but the timer interceptor. The eviction sweep is + * stilled: this test asserts who owns the connection at the moment it + * inspects it, and nothing else may be releasing or re-stamping idle + * connections while it looks. + */ + private DataSource timerPool() { + DataSource ds = newDataSource(); + ds.getPoolProperties().setJmxEnabled(true); + ds.getPoolProperties().setJdbcInterceptors(ResetAbandonedTimer.class.getName()); + ds.getPoolProperties().setInitialSize(0); + ds.getPoolProperties().setTimeBetweenEvictionRunsMillis(0); + return ds; + } + + /* + * The premise of the fix: the sequence the post-walk catch performs - + * mark the connection discarded, then hand it to the return path - retires + * the armed chain with the connection. The test arms it first the way a + * borrow does, through the pool's own setup, and confirms the arm from the + * outside: the timer's MBean answers and reports a checked-out connection. + * After the sequence, every trace of that borrow has to be gone: the pool + * holds no connection, the MBean server holds no timer, the instance is + * unbound with its flag down, and the bookkeeping counts the hand-back and + * the release it just performed. + */ + @Test + void theSequenceTheFixedCatchRunsRetiresTheArmedChainWithTheConnection() throws Exception { + awaitSessions(0); + Published published = new Published(timerPool(), "discard"); + Connection con = published.ds.getConnection(); + + // The arm, confirmed as management sees it: the timer published itself + // below this connection's MBean and the operation finds a borrow + // running. This is the state the post-walk catch fails on. + ObjectName oname = published.timerName(); + Assertions.assertNotNull(oname, "the timer of a borrowed connection publishes itself below that" + + " connection's MBean, and none was found below the pool published as uid " + published.uid); + Assertions.assertEquals(Boolean.TRUE, published.poke(oname), + "precondition: the walk armed the timer, so the operation reports a checked-out connection"); + ResetAbandonedTimer timer = interceptorOf(con, ResetAbandonedTimer.class); + Assertions.assertNotNull(timer, "precondition: the pool runs the timer interceptor"); + PooledConnection pcon = interceptorOf(con, ProxyConnection.class).getConnection(); + Assertions.assertNotNull(pcon, "precondition: the tail of the chain knows its pooled connection"); + + // What the fixed catch does with this half-started borrow. The handle + // dies here - the connection is retired - so the timer instance and the + // pooled connection, read off the live chain above, are what the + // assertions below inspect: the instance the disposal walks is the same + // one the arm bound, cached on the pooled connection's handler. + runAbandonSetup(published.ds.getPool(), pcon); + + // The chain went out of service with the connection: the release took + // the pool's size down and took the timer's name back, and the same + // walk unbound the instance and lowered its flag. + Assertions.assertEquals(0, published.ds.getPool().getSize(), + "the discarded connection must be released, not parked idle under its armed chain"); + Assertions.assertNull(published.timerName(), + "the timer of a retired connection takes its MBean back with the disposal walk, so the" + + " operation can no longer reach a borrow nobody holds"); + Assertions.assertThrows(InstanceNotFoundException.class, () -> published.poke(oname), + "the registration the arm made is the one the disposal must have released"); + Assertions.assertFalse(armed(timer), "the disposal walk must leave the timer of a retired connection" + + " disarmed: an armed timer on an idle connection rewrites that connection's idle age"); + Assertions.assertNull(boundTo(timer), "and it must leave it bound to nothing"); + + // The counters the sequence moved, kept straight by the same path: the + // hand-back is a return, the retirement is a release, and the session + // is gone with them. + Assertions.assertEquals(1, published.ds.getReturnedCount(), + "the hand-back after the failed setup is counted as a return"); + Assertions.assertEquals(1, published.ds.getPool().getReleasedCount(), + "the discarded connection must have gone through the release that disposes the chain"); + awaitSessions(0); + } +} diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerMBeanIdle.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerMBeanIdle.java new file mode 100644 index 0000000000..ceda27f1c3 --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerMBeanIdle.java @@ -0,0 +1,283 @@ +/* + * 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.lang.management.ManagementFactory; +import java.sql.Connection; + +import javax.management.InstanceNotFoundException; +import javax.management.MBeanServer; +import javax.management.ObjectName; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import org.apache.tomcat.jdbc.JdbcPoolBaseTest; +import org.apache.tomcat.jdbc.pool.DataSource; +import org.apache.tomcat.jdbc.pool.PooledConnection; +import org.apache.tomcat.jdbc.pool.ProxyConnection; + +/** + * The {@code resetTimer()} operation of the {@code ResetAbandonedTimer} + * interceptor MBean, driven the way a management client drives it - through the + * MBean server, on a connection the application is not holding. + * + * <p>The interceptor publishes one MBean per pooled connection, below that + * connection's own MBean, and the binding the operation acts through is settled + * at the borrow and released only when the chain is disposed: the chain lives + * with the pooled connection, so handing it back leaves the instance bound to + * it for the whole idle period. A stamp taken on that binding lands on a + * connection that is not checked out. There is nothing for such a stamp to + * avert - the abandoned check looks only at connections that are held - but + * {@link PooledConnection#getTimestamp()} is also the age the idle check + * measures an idle connection by + * ({@link org.apache.tomcat.jdbc.pool.PoolConfiguration#setMinEvictableIdleTimeMillis(int) + * minEvictableIdleTimeMillis}), so the operation rewrites that age. An operator + * poking it on a schedule - which is what one does for a connection believed + * stuck - keeps the connection in the pool for as long as the poking lasts, + * past every idle limit the pool is configured with.</p> + * + * <p>These tests drive the operation against a published pool and pin that it + * acts only while the pooled connection it is bound to is checked out: it + * resets during a borrow, it resets nothing once the connection is back in the + * pool, and idle eviction goes through while the operation is poked at the + * interval that defeated it.</p> + */ +class TestResetAbandonedTimerMBeanIdle extends JdbcPoolBaseTest { + + /* The MBean operation under test, invoked as a client invokes it. */ + private static final String RESET_TIMER = "resetTimer"; + + /* The age past which the idle check releases a connection. */ + private static final int EVICTABLE_IDLE_MILLIS = 1000; + + /* How often the evicter looks at the idle connections. */ + private static final int EVICTION_RUN_MILLIS = 100; + + /* How long the last test keeps poking the operation at an idle connection. */ + private static final long POKING_MILLIS = 2500; + + /* The interval between two pokes - a quarter of the idle limit above. */ + private static final long POKING_INTERVAL_MILLIS = 100; + + /* + * A lower bound on the pokes that must have landed. The connection cannot + * go before it is an idle period old, so a loop that ran at all has poked + * far more often than this; the bound only catches a loop that never ran. + */ + private static final int MIN_POKES = 5; + + /* The pool under test, for the forced teardown below. */ + private DataSource pool; + + /* + * These tests can end with the connection still borrowed (a failed + * assertion between the borrow and its close). The regular data source + * teardown only disconnects idle connections, so the session of a borrowed + * one would linger until the garbage collector finalizes it; force-close + * disconnects the busy ones as well, right away. The pool's publication is + * released with it, so nothing of these tests stays registered. + */ + @AfterEach + void disconnectLeakedBusyConnections() { + if (pool != null) { + pool.close(true); + pool.postDeregister(); + } + } + + /* + * A pool running nothing but the timer interceptor, published the way a + * container publishes one. The publication is what makes the operation + * reachable at all: the interceptor registers below the pooled connection, + * which registers below the pool's own MBean, so an unpublished pool has no + * name for them to sit under. The uid is carried down into every name + * derived from the registration, which is how the interceptor's name is + * found below a pool of this test's own and nothing else. + */ + private final class Published { + private final MBeanServer server = ManagementFactory.getPlatformMBeanServer(); + private final DataSource ds; + private final String uid; + + private Published(DataSource ds, String role) throws Exception { + this.ds = ds; + this.uid = Long.toString(System.nanoTime()); + ds.createPool(); + ds.preRegister(server, new ObjectName("tomcat:type=ResetAbandonedTimerMBeanTest,role=" + role + + ",uid=" + uid)); + Assertions.assertNotNull(ds.getPool().getJmxPool().getObjectName(), + "an enabled pool publishes its MBean together with its registration"); + pool = ds; + } + + /* The MBean the timer has published for the connection it is bound to. */ + private ObjectName timerName() throws Exception { + ObjectName found = null; + for (ObjectName name : server.queryNames(new ObjectName("tomcat.jdbc:*"), null)) { + if (ResetAbandonedTimer.class.getSimpleName().equals(name.getKeyProperty("JdbcInterceptor")) + && uid.equals(name.getKeyProperty("uid"))) { + Assertions.assertNull(found, "this test hands out one pooled connection, but a second timer is" + + " published as " + name); + found = name; + } + } + Assertions.assertNotNull(found, "the timer of a borrowed connection publishes itself below that" + + " connection's MBean, and none was found below the pool published as uid " + uid); + return found; + } + + /* One call of the operation, as a management client makes it. */ + private Object poke(ObjectName oname) throws Exception { + return server.invoke(oname, RESET_TIMER, null, null); + } + } + + /* A pool with the timer interceptor, with the given extra configuration. */ + private DataSource timerPool(int minEvictableIdleTimeMillis, int evictionRunMillis) { + DataSource ds = newDataSource(); + ds.getPoolProperties().setJmxEnabled(true); + ds.getPoolProperties().setJdbcInterceptors(ResetAbandonedTimer.class.getName()); + ds.getPoolProperties().setInitialSize(0); + ds.getPoolProperties().setMinEvictableIdleTimeMillis(minEvictableIdleTimeMillis); + ds.getPoolProperties().setTimeBetweenEvictionRunsMillis(evictionRunMillis); + return ds; + } + + /* A pool with nothing but the interceptor's own defaults. */ + private DataSource timerPool() { + return timerPool(EVICTABLE_IDLE_MILLIS, EVICTION_RUN_MILLIS); + } + + /* + * The half of the operation that is not the defect, and the control for the + * two tests below: the same call on the same registration, on a connection + * that really is held, still does what the operation says it does. + */ + @Test + void theOperationResetsTheTimerOfACheckedOutConnection() throws Exception { + Published published = new Published(timerPool(), "borrowed"); + Connection con = published.ds.getConnection(); + ObjectName oname = published.timerName(); + PooledConnection pcon = interceptorOf(con, ProxyConnection.class).getConnection(); + Assertions.assertNotNull(pcon, "precondition: the tail of the chain knows its pooled connection"); + + // Not a window the fix has to hit: the sleep only makes the two reads + // of the timestamp distinguishable, since a reset that cannot be told + // apart from the stamp it replaced would prove nothing either way. + sleep(50); + long before = pcon.getTimestamp(); + + Assertions.assertEquals(Boolean.TRUE, published.poke(oname), + "the operation on a checked-out connection must report that it reset the timer"); + Assertions.assertTrue(pcon.getTimestamp() > before, + "the reset must have moved the timestamp of the connection that is being held, read " + before + + " and found " + pcon.getTimestamp()); + + con.close(); + } + + /* + * The defect: the same operation, on a connection that has been handed back + * and is sitting idle in the pool. The chain is still bound to it - which is + * what makes the connection reachable to management at all - so the + * operation reaches it, resets a timer that only counts for a borrow, and + * moves the timestamp the idle check measures this connection by. + */ + @Test + void theOperationResetsNothingForAConnectionIdleInThePool() throws Exception { + Published published = new Published(timerPool(), "idle"); + Connection con = published.ds.getConnection(); + ObjectName oname = published.timerName(); + PooledConnection pcon = interceptorOf(con, ProxyConnection.class).getConnection(); + + con.close(); + + Assertions.assertEquals(1, published.ds.getReturnedCount(), + "precondition: the pool has taken this connection back"); + Assertions.assertEquals(1, published.ds.getPool().getSize(), + "precondition: the connection is idle in the pool rather than released"); + // The name still answers: the registration is released with the chain, + // not with the borrow, so this is the connection the operation reaches. + Assertions.assertEquals(oname, published.timerName(), + "precondition: the timer of an idle connection stays published"); + + sleep(50); + long before = pcon.getTimestamp(); + + Assertions.assertEquals(Boolean.FALSE, published.poke(oname), + "an idle connection is held by nobody, and the abandoned timer this operation resets is a property" + + " of a borrow that is not running"); + Assertions.assertEquals(before, pcon.getTimestamp(), + "the age the idle check measures an idle connection by must not move under this operation, it was " + + before + " and is " + pcon.getTimestamp() + " now"); + } + + /* + * The harm that defect causes, on the pool's own bookkeeping. An operator + * who pokes the operation on a short schedule while a connection is idle + * keeps rewriting the age of that connection, and the evicter - which acts + * on nothing but that age - never finds it old enough. The pool is configured + * to release an idle connection after one second and to look every hundred + * milliseconds; the loop pokes every hundred milliseconds for two and a half + * seconds, and the connection has to be gone anyway. + */ + @Test + void pokingTheOperationWhileIdleDoesNotKeepTheConnectionOutOfEviction() throws Exception { + awaitSessions(0); + Published published = new Published(timerPool(EVICTABLE_IDLE_MILLIS, EVICTION_RUN_MILLIS), "eviction"); + + // The borrow exists to get one connection into the pool; it is back in + // the pool when the block ends, idle and evictable from then on. + try (Connection con = published.ds.getConnection()) { + Assertions.assertNotNull(con, "precondition: the pool handed out a connection"); + } + ObjectName oname = published.timerName(); + + int pokes = 0; + long resets = 0; + long deadline = System.currentTimeMillis() + POKING_MILLIS; + while (System.currentTimeMillis() < deadline) { + try { + if (Boolean.TRUE.equals(published.poke(oname))) { + resets++; + } + } catch (InstanceNotFoundException gone) { + // The timer takes its name back with the connection it is bound + // to - the release unbinds the chain - which is the outcome the + // loop is waiting for. + break; + } + pokes++; + sleep(POKING_INTERVAL_MILLIS); + } + + Assertions.assertTrue(pokes >= MIN_POKES, + "the operation must have been poked on a schedule across the idle period, only " + pokes + + " calls landed"); + Assertions.assertEquals(0, published.ds.getPool().getSize(), + "a connection idle past minEvictableIdleTimeMillis must be released while this operation is poked" + + " at it: " + resets + " of " + pokes + " pokes reset the timer of a connection nobody" + + " holds, and each of those rewrote the age the idle check measures it by"); + Assertions.assertEquals(0, resets, + "none of the pokes above may reset a timer: the connection was idle in the pool throughout"); + Assertions.assertEquals(1, published.ds.getPool().getReleasedIdleCount(), + "the release must be the idle check's own, which is the bookkeeping the pokes defeated"); + awaitSessions(0); + } +} diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerNestedCursor.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerNestedCursor.java new file mode 100644 index 0000000000..59218a787e --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerNestedCursor.java @@ -0,0 +1,650 @@ +/* + * 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.lang.reflect.InvocationHandler; +import java.lang.reflect.InvocationTargetException; +import java.lang.reflect.Method; +import java.lang.reflect.Proxy; +import java.sql.CallableStatement; +import java.sql.Connection; +import java.sql.ResultSet; +import java.sql.ResultSetMetaData; +import java.sql.SQLException; +import java.sql.Statement; +import java.util.HashMap; +import java.util.Map; +import java.util.logging.Logger; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import org.apache.tomcat.jdbc.JdbcPoolBaseTest; +import org.apache.tomcat.jdbc.pool.DataSource; + +/** + * A nested cursor - a REF cursor selected as a column - reaches the + * application through the {@code ResultSet.getObject(...)} overloads of the + * result set handle that owns the column, which come back as a plain + * {@link Object}. It is read row by row over the same physical session as the + * cursor that handed it out, so the {@code ResetAbandonedTimer} interceptor + * must keep the abandoned timer alive while it is read. The statement layer + * already wraps every result set a call hands back, whatever the call was + * called; the result set layer wrapped none of the ones a read hands back, + * and the always installed statement facade then wrapped the driver's + * untouched cursor, so an application iterating a cursor-valued column with + * {@code removeAbandoned} enabled was abandoned mid-iteration. The pins below + * are the interceptor counterpart, one layer down, of the facade's and the + * statement layer's return-type rule (see {@code + * TestCursorOutParameterSealing} and {@link + * TestResetAbandonedTimerCursorOutParameter}): whatever a result set read + * hands back that is a {@code java.sql.ResultSet} reaches the application as + * the facade's handle over exactly one handle of this interceptor over the + * driver's cursor, while what the {@code Wrapper} methods hand back stays the + * driver's object and a plain column value stays itself. + * + * <p>H2 has no cursor-valued columns, so the pool here is fed by a small + * delegating provider: a designated column of the result set its callable + * statements hand out answers {@code getObject(...)} with a second real H2 + * result set, opened on the very physical session the pool borrowed, the way + * a nested cursor reaches the application on the drivers that have them.</p> + */ +class TestResetAbandonedTimerNestedCursor extends JdbcPoolBaseTest { + + /* + * Time the busy connection is kept streaming rows off the nested cursor. + * It must stay well above removeAbandonedTimeout plus one sweep interval + * so that the idle control connection - and, while the nested reads did + * not reset the timer, the streaming one too - is certain to expire while + * the iteration is still running. + */ + private static final long STREAM_MILLIS = 2500; + + /* + * Lower bound on streamed rows. An app iterating rows between the + * per-row pauses makes far more than this; the bound only catches an + * iteration that never really ran. + */ + private static final int MIN_STREAM_ROWS = 20; + + /* + * The parameter this provider's callable statements answer with the + * cursor that owns the cursor-valued column, mirroring what a driver + * with a REF cursor selected as a column hands the application. + */ + private static final int CURSOR_COLUMN_PARAMETER = 1; + + /* + * The column of that cursor which holds a nested cursor rather than a + * value, and its plain neighbour, so the pins can tell the two apart. + * The row count and the fetch size of the nested cursor keep the reads + * pulling from the server across the whole iteration, so the iteration + * stands for streaming a genuine server-side cursor. + */ + private static final int CURSOR_COLUMN = 2; + private static final int PLAIN_COLUMN = 1; + private static final String CURSOR_COLUMN_NAME = "CURSOR_VALUE"; + private static final String PLAIN_COLUMN_VALUE = "not a cursor"; + private static final String CURSOR_CALL = "CALL 1"; + private static final String CURSOR_COLUMN_SQL = "SELECT X, '" + PLAIN_COLUMN_VALUE + + "' " + CURSOR_COLUMN_NAME + " FROM SYSTEM_RANGE(1,3)"; + private static final String NESTED_CURSOR_SQL = "SELECT X FROM SYSTEM_RANGE(101,100000)"; + private static final int NESTED_CURSOR_FIRST_ROW = 101; + private static final int NESTED_FETCH_SIZE = 10; + + /* The batch processing between the reads, as any per-row work stands for. */ + private static final long READ_PAUSE_MILLIS = 10; + + /* + * Stands for the driver's own cursor interface. A real driver's cursor + * class implements such an interface and implements ResultSet, and an + * application that needs the driver-only cursor methods reaches it with + * unwrap(); a pooled handle must hand that object back untouched rather + * than a proxy of its own, whatever rule decides the wrapping. + */ + public interface DriverCursor { + } + + /* + * A connection provider shaped like a driver with cursor-valued + * columns: its callable statements hand the cursor that owns the column + * - a real H2 result set on the very physical session the pool holds - + * to getObject(...), that cursor hands its designated column out as a + * second real H2 result set, and every other call goes straight to the + * H2 objects beneath. + */ + private static final class CursorProvider implements javax.sql.DataSource { + + private final org.h2.jdbcx.JdbcDataSource delegate; + + CursorProvider(String url) { + delegate = new org.h2.jdbcx.JdbcDataSource(); + delegate.setUrl(url); + delegate.setUser("sa"); + delegate.setPassword(""); + } + + @Override + public Connection getConnection() throws SQLException { + return (Connection) Proxy.newProxyInstance( + CursorProvider.class.getClassLoader(), + new Class<?>[] { Connection.class }, + new ConnectionHandler(delegate.getConnection())); + } + + @Override + public Connection getConnection(String username, String password) throws SQLException { + // The credentials are the pool's configuration, not the + // database's; the physical provider is the fixed H2 one. (Same + // posture as the provider in TestCursorOutParameterSealing.) + return getConnection(); + } + + @Override + public java.io.PrintWriter getLogWriter() { + return null; + } + + @Override + public void setLogWriter(java.io.PrintWriter out) { + // no-op + } + + @Override + public void setLoginTimeout(int seconds) { + // no-op + } + + @Override + public int getLoginTimeout() { + return 0; + } + + @Override + public Logger getParentLogger() { + return Logger.getLogger(CursorProvider.class.getName()); + } + + // javax.sql.DataSource is a Wrapper: answer it honestly, from the + // H2 provider beneath, as a real driver's data source does. + @Override + public <T> T unwrap(Class<T> iface) throws SQLException { + return delegate.unwrap(iface); + } + + @Override + public boolean isWrapperFor(Class<?> iface) throws SQLException { + return delegate.isWrapperFor(iface); + } + } + + /* + * Intercepts prepareCall to wrap the H2 callable statement in the + * cursor-column behaviour below. Everything else - createStatement, + * prepareStatement, close, the pool's own setup calls and the session + * marker probes - goes to the H2 connection unchanged. + */ + private static final class ConnectionHandler implements InvocationHandler { + + private final Connection physical; + + ConnectionHandler(Connection physical) { + this.physical = physical; + } + + @Override + public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { + try { + Object result = method.invoke(physical, args); + if ("prepareCall".equals(method.getName())) { + return Proxy.newProxyInstance( + CursorProvider.class.getClassLoader(), + new Class<?>[] { CallableStatement.class }, + new CallableStatementHandler(physical, (CallableStatement) result)); + } + return result; + } catch (InvocationTargetException e) { + throw e.getCause(); + } + } + } + + /* + * The fictional cursor behaviour, and nothing else: getObject(...) for + * the designated parameter returns the session's H2 result set that has + * a cursor-valued column - its rows are H2's own, only the cursor column + * is the fiction, and that lives in the handler below. Every other call + * is forwarded to the H2 callable statement. + */ + private static final class CallableStatementHandler implements InvocationHandler { + + private final Connection physical; + private final CallableStatement delegate; + /* Kept open with the cursor: closing the owner would close it. */ + private Statement cursorColumnOwner; + private ResultSet cursorColumnCursor; + + CallableStatementHandler(Connection physical, CallableStatement delegate) { + this.physical = physical; + this.delegate = delegate; + } + + /* + * The session's cursor whose column holds a cursor, opened on the + * physical session once. + */ + private ResultSet cursorWithCursorColumn() throws SQLException { + if (cursorColumnCursor == null) { + cursorColumnOwner = physical.createStatement(); + cursorColumnCursor = (ResultSet) Proxy.newProxyInstance( + CursorProvider.class.getClassLoader(), + new Class<?>[] { ResultSet.class }, + new CursorColumnResultSetHandler(physical, + cursorColumnOwner.executeQuery(CURSOR_COLUMN_SQL))); + } + return cursorColumnCursor; + } + + @Override + public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { + String name = method.getName(); + try { + if ("getObject".equals(name) && args != null && args.length >= 1 + && args[0] instanceof Integer) { + int parameter = ((Integer) args[0]).intValue(); + if (parameter == CURSOR_COLUMN_PARAMETER) { + if (args.length == 1) { + return cursorWithCursorColumn(); + } + if (args[1] instanceof Class + && ((Class<?>) args[1]).isInstance(cursorWithCursorColumn())) { + return cursorWithCursorColumn(); + } + } + } + return method.invoke(delegate, args); + } catch (InvocationTargetException e) { + throw e.getCause(); + } + } + } + + /* + * The one-layer-deeper fiction, and nothing else: the result set the + * callable statement hands out has one column that is itself a cursor - + * the nested cursor a driver reports for a cursor-valued column - and + * reading that column through any of the ResultSet.getObject(...) + * overloads hands out a second real H2 result set, opened on the very + * same physical session. The plain column, the conversions the driver + * cannot make here, the metadata and every other call go to the H2 + * result set beneath, and unwrap(DriverCursor.class) hands out that same + * nested cursor object, the way the driver's own cursor method would. + */ + private static final class CursorColumnResultSetHandler implements InvocationHandler { + + private final Connection physical; + private final ResultSet delegate; + /* Kept open with the nested cursor: closing it closes the cursor. */ + private Statement nestedOwner; + private ResultSet nested; + + CursorColumnResultSetHandler(Connection physical, ResultSet delegate) { + this.physical = physical; + this.delegate = delegate; + } + + /* The session's nested cursor, opened on the physical session once. */ + private ResultSet nestedCursor() throws SQLException { + if (nested == null) { + nestedOwner = physical.createStatement(); + nestedOwner.setFetchSize(NESTED_FETCH_SIZE); + nested = nestedOwner.executeQuery(NESTED_CURSOR_SQL); + } + return nested; + } + + private static boolean isCursorColumn(Object column) { + return (column instanceof Integer + && ((Integer) column).intValue() == CURSOR_COLUMN) + || CURSOR_COLUMN_NAME.equals(column); + } + + @Override + public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { + String name = method.getName(); + try { + if ("getObject".equals(name) && args != null && args.length >= 1 + && isCursorColumn(args[0])) { + // The column is a cursor, so every one of the six + // overloads the standard API declares to come back as an + // Object hands it out - the typed one only where the + // requested type is one the cursor satisfies, the way a + // driver's conversion would. + if (args.length == 1 || args[1] instanceof Map) { + return nestedCursor(); + } + if (args[1] instanceof Class + && ((Class<?>) args[1]).isInstance(nestedCursor())) { + return nestedCursor(); + } + } else if ("unwrap".equals(name)) { + Class<?> iface = (Class<?>) args[0]; + if (DriverCursor.class.equals(iface)) { + return nestedCursor(); + } + return delegate.unwrap(iface); + } else if ("isWrapperFor".equals(name)) { + Class<?> iface = (Class<?>) args[0]; + return Boolean.valueOf(DriverCursor.class.equals(iface) || delegate.isWrapperFor(iface)); + } + return method.invoke(delegate, args); + } catch (InvocationTargetException e) { + throw e.getCause(); + } + } + } + + /* + * A pool that serves its connections through the cursor provider and + * abandons an idle one after a second, swept every 100ms - the same + * setting the other abandoned-timer tests drive. + */ + private DataSource nestedTimerPool() throws SQLException { + DataSource ds = newDataSource(); + ds.setDataSource(new CursorProvider(getUrl())); + ds.getPoolProperties().setJdbcInterceptors( + "org.apache.tomcat.jdbc.pool.interceptor.ResetAbandonedTimer"); + ds.getPoolProperties().setRemoveAbandoned(true); + ds.getPoolProperties().setRemoveAbandonedTimeout(1); // seconds + ds.getPoolProperties().setTimeBetweenEvictionRunsMillis(100); + ds.createPool(); + pool = ds; + return ds; + } + + /* The pool under test, for forced teardown. */ + private DataSource pool; + + /* + * These tests deliberately end with connections still borrowed. The + * regular data source teardown only disconnects idle connections, so the + * sessions of the borrowed ones would linger until the garbage collector + * finalizes them and leak their session counts into the starting point of + * the next test; force-close disconnects the busy ones as well, right + * away. + */ + @AfterEach + void disconnectLeakedBusyConnections() { + if (pool != null) { + pool.close(true); + } + } + + /* + * Borrows an idle control connection - left borrowed and untouched, it + * exists only to prove the abandoned sweep is running - and a busy + * connection, each identified by a session marker, and pins the session + * count to two while both are still live. The caller must have waited out + * any sessions dying from a previous test first: with a one-second + * abandoned timeout there is no time to absorb stale sessions once these + * connections have started their countdown. Returns the busy connection. + */ + private Connection borrowBusyWithIdleControl(DataSource ds) throws SQLException { + Connection idle = ds.getConnection(); + setSessionMarker(idle, 2); + Connection busy = ds.getConnection(); + setSessionMarker(busy, 1); + Assertions.assertEquals(2, poolSessions(), + "both borrowed connections must start on live physical sessions"); + return busy; + } + + /* + * The busy connection ends with one live physical session carrying the + * marker it was given before the iteration, and the idle control + * connection has lost its session to the abandoned sweep. + */ + private void assertBusySurvivedAndIdleAbandoned(Connection busy) throws SQLException { + Integer marker = sessionMarker(busy); + Assertions.assertNotNull(marker, "the session of the busy connection must still be alive"); + Assertions.assertEquals(1, marker.intValue(), "the busy connection must still own its original session"); + awaitSessions(1); + } + + /* + * The composition the keep-alive depends on, pinned without waiting on a + * sweep: the nested cursor handed back by a result set read must reach + * the application as the facade's handle over exactly one handle of this + * interceptor over the driver's own cursor - the same three-layer shape + * the statement layer's rule gives a cursor OUT-parameter, and no layer + * of it doubled. + */ + private static void assertTimerHandleBeneathTheFacade(ResultSet handle, Object driverCursor, + String path) throws ReflectiveOperationException { + Assertions.assertTrue(Proxy.isProxyClass(handle.getClass()), + path + ": the application's result set must be a handle, was " + handle.getClass().getName()); + Assertions.assertTrue(Proxy.getInvocationHandler(handle).getClass().getName() + .contains("StatementFacade"), + path + ": the outermost handle must be the facade's, found " + + Proxy.getInvocationHandler(handle).getClass().getName()); + Object interceptorHandle = proxiedObject(handle); + Assertions.assertTrue(Proxy.isProxyClass(interceptorHandle.getClass()), + path + ": the facade must sit over this interceptor's own handle, found " + + interceptorHandle.getClass().getName()); + Assertions.assertTrue(Proxy.getInvocationHandler(interceptorHandle).getClass().getName() + .contains(ResetAbandonedTimer.class.getSimpleName()), + path + ": the handle beneath the facade must be this interceptor's, found " + + Proxy.getInvocationHandler(interceptorHandle).getClass().getName()); + Object driver = proxiedObject(interceptorHandle); + Assertions.assertFalse(Proxy.isProxyClass(driver.getClass()), + path + ": this interceptor must wrap the driver's cursor once, not its own handle again"); + Assertions.assertSame(driverCursor, driver, + path + ": the handle must wrap exactly this session's driver cursor"); + } + + /* + * Iterates the nested cursor this pool's result set handles hand out + * through getObject(int) with a pause between the reads - the batch + * processing between fetches that the abandoned timeout is meant to look + * over - for STREAM_MILLIS, and returns the number of rows read. + */ + private int streamNestedCursorSlowly(Connection busy) throws SQLException { + int rows = 0; + try (CallableStatement cs = busy.prepareCall(CURSOR_CALL)) { + cs.execute(); + try (ResultSet outer = (ResultSet) cs.getObject(CURSOR_COLUMN_PARAMETER)) { + Assertions.assertTrue(outer.next(), "the cursor that owns the column is live"); + try (ResultSet nested = (ResultSet) outer.getObject(CURSOR_COLUMN)) { + long deadline = System.currentTimeMillis() + STREAM_MILLIS; + while (System.currentTimeMillis() < deadline && nested.next()) { + rows++; + Assertions.assertEquals(NESTED_CURSOR_FIRST_ROW + rows - 1, nested.getInt(1), + "the nested cursor read through getObject must hand out its own rows"); + sleep(READ_PAUSE_MILLIS); + } + } + } + } + return rows; + } + + /** + * An application streaming a nested cursor is active for as long as it + * reads it, exactly as it is when it iterates the cursor that handed the + * column out. The abandoned timer must be reset by the reads made + * through the nested cursor - through the always installed statement + * facade, over the interceptor's own handle, over the driver's cursor - + * and not only until the getObject(...) that produced it returned. + */ + @Test + void streamingANestedCursorKeepsConnectionAlive() throws Exception { + awaitSessions(0); + DataSource ds = nestedTimerPool(); + Connection busy = borrowBusyWithIdleControl(ds); + + int rows = streamNestedCursorSlowly(busy); + Assertions.assertTrue(rows >= MIN_STREAM_ROWS, + "the streaming loop must have run, only " + rows + " rows"); + + assertBusySurvivedAndIdleAbandoned(busy); + } + + /** + * The nested cursor arrives through {@code getObject(int)}, the named + * and the typed overloads alike, and every one of them must produce the + * interceptor's handle beneath the facade's rather than the facade + * standing directly over the driver's raw cursor, so that reading it + * keeps this borrow alive. It must still behave like every other handle + * while it is read: the application's own statement as its statement, + * and its own rows coming through. The calls the statement layer already + * wrapped keep exactly the same composition, which is to say the result + * set layer's type rule adds a layer to the nested cursor without + * doubling one anywhere. + */ + @Test + void aNestedCursorArrivesAsATimerHandleBeneathTheFacade() throws Exception { + DataSource ds = nestedTimerPool(); + try (Connection pooled = ds.getConnection()) { + try (CallableStatement cs = pooled.prepareCall(CURSOR_CALL)) { + cs.execute(); + ResultSet outer = (ResultSet) cs.getObject(CURSOR_COLUMN_PARAMETER); + Assertions.assertTrue(Proxy.getInvocationHandler(outer).getClass().getName() + .contains("StatementFacade"), + "the cursor that owns the column must arrive as the facade's handle"); + Object outerBeneath = proxiedObject(outer); + Assertions.assertTrue(Proxy.isProxyClass(outerBeneath.getClass()) + && Proxy.getInvocationHandler(outerBeneath).getClass().getName() + .contains(ResetAbandonedTimer.class.getSimpleName()), + "the facade must sit over this interceptor's own handle"); + Assertions.assertTrue(outer.next(), "the cursor that owns the column is live"); + Object driverNested = outer.unwrap(DriverCursor.class); + Assertions.assertTrue(driverNested instanceof ResultSet, + "precondition: the driver's nested cursor implements ResultSet"); + + ResultSet nested = (ResultSet) outer.getObject(CURSOR_COLUMN); + assertTimerHandleBeneathTheFacade(nested, driverNested, "getObject(int)"); + Assertions.assertSame(cs, nested.getStatement(), + "the handle must report the application's own statement"); + Assertions.assertTrue(nested.next(), "the nested cursor is live during the borrow"); + Assertions.assertEquals(NESTED_CURSOR_FIRST_ROW, nested.getInt(1), + "the nested cursor's own rows must come through the handle"); + } + + // The named and typed overloads carry the column too, and a + // return-type rule has to see every one of them. + try (CallableStatement cs = pooled.prepareCall(CURSOR_CALL)) { + cs.execute(); + ResultSet outer = (ResultSet) cs.getObject(CURSOR_COLUMN_PARAMETER); + Assertions.assertTrue(outer.next(), "the cursor that owns the column is live"); + Object driverNested = outer.unwrap(DriverCursor.class); + + assertTimerHandleBeneathTheFacade( + (ResultSet) outer.getObject(CURSOR_COLUMN_NAME), driverNested, "getObject(String)"); + assertTimerHandleBeneathTheFacade( + (ResultSet) outer.getObject(CURSOR_COLUMN, new HashMap<String, Class<?>>()), + driverNested, "getObject(int, Map)"); + assertTimerHandleBeneathTheFacade( + outer.getObject(CURSOR_COLUMN, ResultSet.class), driverNested, "getObject(int, Class)"); + } + + try (Statement st = pooled.createStatement(); + ResultSet rs = st.executeQuery(NESTED_CURSOR_SQL)) { + assertTimerHandleBeneathTheFacade(rs, rs.unwrap(ResultSet.class), "executeQuery"); + Assertions.assertTrue(rs.next()); + Assertions.assertEquals(NESTED_CURSOR_FIRST_ROW, rs.getInt(1)); + } + } + } + + /** + * The documented escape hatch, pinned one layer down at exactly the + * point where a wrap-by-return-type rule could break it: this driver's + * nested cursor implements ResultSet, so a blanket rule would silently + * wrap what {@code unwrap()} hands back - and with the interceptor + * installed the driver's object passes through this layer, not only + * through the facade's. {@code unwrap()} on a result set handle must + * still arrive at the driver's very own nested cursor, and so must + * {@code unwrap()} through the nested handle itself. + */ + @Test + void unwrapAtTheResultSetLayerStillHandsBackTheDriversOwnCursor() throws Exception { + DataSource ds = nestedTimerPool(); + try (Connection pooled = ds.getConnection(); + CallableStatement cs = pooled.prepareCall(CURSOR_CALL)) { + cs.execute(); + ResultSet outer = (ResultSet) cs.getObject(CURSOR_COLUMN_PARAMETER); + Assertions.assertTrue(outer.isWrapperFor(DriverCursor.class), + "the provider must answer its own cursor interface honestly, as a driver does"); + + Object nested = outer.unwrap(DriverCursor.class); + + Assertions.assertTrue(nested instanceof ResultSet, + "precondition: the object reached by unwrapping implements ResultSet"); + Assertions.assertFalse(Proxy.isProxyClass(nested.getClass()), + "unwrap() must hand back the driver's object, not a handle: " + nested.getClass().getName()); + Assertions.assertTrue(nested.getClass().getName().startsWith("org.h2."), + "unwrap() must arrive at the driver object through every layer: " + + nested.getClass().getName()); + Assertions.assertSame(nested, outer.unwrap(DriverCursor.class), + "a repeated unwrap() must return the same object, not a new wrapper"); + + // The same carve-out holds one layer further in: what the nested + // handle's unwrap() reaches is the driver's nested cursor, the + // object the interceptor's handle happens to be made of. + ResultSet handle = outer.getObject(CURSOR_COLUMN, ResultSet.class); + Assertions.assertSame(nested, handle.unwrap(ResultSet.class), + "unwrap() through the nested handle must still arrive at the driver object"); + Assertions.assertTrue(((ResultSet) nested).next(), + "what the escape hatch hands back must still work"); + handle.close(); + } + } + + /** + * The rule fires on the return type, so it must leave everything the + * same {@code getObject(...)} family hands back alone: an ordinary + * column value, in the plain and in the typed overload, a conversion of + * the cursor column that the driver answers with its plain value, and + * the result set metadata, which is no result set at all. + */ + @Test + void aPlainColumnValuePassesThroughTheNestedCursorRuleUnchanged() throws Exception { + DataSource ds = nestedTimerPool(); + try (Connection pooled = ds.getConnection(); + CallableStatement cs = pooled.prepareCall(CURSOR_CALL)) { + cs.execute(); + ResultSet outer = (ResultSet) cs.getObject(CURSOR_COLUMN_PARAMETER); + Assertions.assertTrue(outer.next(), "the cursor that owns the column is live"); + + Object plain = outer.getObject(PLAIN_COLUMN); + Assertions.assertFalse(Proxy.isProxyClass(plain.getClass()), + "an ordinary column value must reach the application untouched, was " + + plain.getClass().getName()); + Assertions.assertEquals(1, ((Number) plain).intValue()); + Assertions.assertEquals(Integer.valueOf(1), outer.getObject(PLAIN_COLUMN, Integer.class), + "the typed overload must pass the plain value through unchanged too"); + Assertions.assertEquals(PLAIN_COLUMN_VALUE, outer.getObject(CURSOR_COLUMN, String.class), + "a conversion the driver answers with a value must not become a cursor"); + + ResultSetMetaData meta = outer.getMetaData(); + Assertions.assertFalse(Proxy.isProxyClass(meta.getClass()), + "metadata is not a result set and must not be wrapped: " + meta.getClass().getName()); + Assertions.assertEquals(2, meta.getColumnCount(), "the metadata must still answer through the handle"); + } + } +} diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerParkedCallStamp.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerParkedCallStamp.java new file mode 100644 index 0000000000..b231bd272b --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerParkedCallStamp.java @@ -0,0 +1,402 @@ +/* + * 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.lang.reflect.InvocationTargetException; +import java.lang.reflect.Method; +import java.lang.reflect.Proxy; +import java.sql.Connection; +import java.sql.Statement; +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.Logger; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import org.apache.tomcat.jdbc.JdbcPoolBaseTest; +import org.apache.tomcat.jdbc.pool.DataSource; +import org.apache.tomcat.jdbc.pool.JdbcInterceptor; +import org.apache.tomcat.jdbc.pool.PooledConnection; +import org.apache.tomcat.jdbc.pool.ProxyConnection; + +/** + * A call that entered the chain during one borrow can finish after that + * borrow has ended - the application closed the handle from another thread + * while the call was still down at the driver, which is the very situation + * the abandonment machinery is configured against - and after the same + * pooled connection has been handed to the next borrower. The stamp the + * interceptor takes when such a call completes used to be taken while the + * connection was checked out again, and the checked-out flag alone cannot + * tell the two borrows apart: the stamp moves the + * {@link PooledConnection#getTimestamp()} of the live borrower forward by a + * full {@code removeAbandonedTimeout} and + * {@link PooledConnection#setTimestamp(long)} clears that borrow's suspect + * state, so neither the deadline nor the suspect report the abandoned check + * computed for the current borrower survives the stranger's stamp. + * + * <p>The pins below drive exactly the scenario of the defect, at both + * layers: a connection-level call is parked between the timer and the tail, + * and a query is parked inside a small physical provider beneath the timer's + * statement handle. The handle is closed, the session is re-borrowed, and + * the parked call is then released to complete. Its stamp may answer only + * for its own borrow; the live borrower's timestamp and suspect state must + * not move. The controls pin that calls made during the current borrow keep + * the timer they are made to protect.</p> + */ +class TestResetAbandonedTimerParkedCallStamp extends JdbcPoolBaseTest { + + /* The pool under test, for the forced teardown below. */ + private DataSource pool; + + /* The first test's release latch, for the same teardown. */ + private CountDownLatch blockerRelease; + + /* + * These tests can end with the connection still borrowed, or with a + * parked thread still waiting on a latch (a failed assertion between the + * park and its release). Release the latches first, then force-close: + * the regular data source teardown only disconnects idle connections, so + * the session of a borrowed one would linger until the garbage collector + * finalizes it. + */ + @AfterEach + void releaseAndDisconnect() { + if (blockerRelease != null) { + blockerRelease.countDown(); + } + if (parkedProvider != null) { + parkedProvider.release.countDown(); + } + if (pool != null) { + pool.close(true); + } + } + + /* The provider of the second test, for the latch release above. */ + private ParkingProvider parkedProvider; + + /* + * A link that parks one named method on the way down and forwards + * everything else. Spliced between the timer and the tail it stands for + * a call still in flight when the application closes the handle, and it + * lets the call continue to the tail afterwards, so it is the pool's own + * borrow fence - and nothing test-made - that answers the released call. + */ + private static final class Blocker extends JdbcInterceptor { + private final String blocked; + private final CountDownLatch inside; + private final CountDownLatch release; + + Blocker(String blocked, CountDownLatch inside, CountDownLatch release) { + this.blocked = blocked; + this.inside = inside; + this.release = release; + setUseEquals(true); + } + + @Override + public void reset(org.apache.tomcat.jdbc.pool.ConnectionPool parent, PooledConnection con) { + // The spliced link stands for the driver's part of the call, not + // for an interceptor: the borrow walk must not arm or rearm it. + } + + @Override + public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { + if (blocked.equals(method.getName())) { + inside.countDown(); + release.await(); + } + return getNext().invoke(proxy, method, args); + } + } + + /* + * A physical provider shaped like a hung database: the first executeQuery + * after the test arms it parks on the way to the H2 statement, standing + * for a query still with the driver when the application gives the + * handle back. Releasing it lets the very same call run - against the + * still-open physical session, exactly as a late reply from a dead-slow + * database arrives on a session the pool has long since re-served. + */ + private static final class ParkingProvider implements javax.sql.DataSource { + + private final org.h2.jdbcx.JdbcDataSource delegate = new org.h2.jdbcx.JdbcDataSource(); + private final CountDownLatch inside = new CountDownLatch(1); + private final CountDownLatch release = new CountDownLatch(1); + private final AtomicBoolean armed = new AtomicBoolean(); + + ParkingProvider(String url) { + delegate.setUrl(url); + delegate.setUser("sa"); + delegate.setPassword(""); + } + + @Override + public Connection getConnection() throws java.sql.SQLException { + return (Connection) Proxy.newProxyInstance(ParkingProvider.class.getClassLoader(), + new Class<?>[] { Connection.class }, new ConnectionHandler(delegate.getConnection())); + } + + @Override + public Connection getConnection(String username, String password) throws java.sql.SQLException { + // The credentials are the pool's configuration, not the + // database's; the physical provider is the fixed H2 one. + return getConnection(); + } + + @Override + public java.io.PrintWriter getLogWriter() { + return null; + } + + @Override + public void setLogWriter(java.io.PrintWriter out) { + // no-op + } + + @Override + public void setLoginTimeout(int seconds) { + // no-op + } + + @Override + public int getLoginTimeout() { + return 0; + } + + @Override + public Logger getParentLogger() { + return Logger.getLogger(ParkingProvider.class.getName()); + } + + @Override + public <T> T unwrap(Class<T> iface) throws java.sql.SQLException { + return delegate.unwrap(iface); + } + + @Override + public boolean isWrapperFor(Class<?> iface) throws java.sql.SQLException { + return delegate.isWrapperFor(iface); + } + + private final class ConnectionHandler implements java.lang.reflect.InvocationHandler { + private final Connection physical; + + ConnectionHandler(Connection physical) { + this.physical = physical; + } + + @Override + public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { + try { + Object result = method.invoke(physical, args); + if ("createStatement".equals(method.getName())) { + return Proxy.newProxyInstance(ParkingProvider.class.getClassLoader(), + new Class<?>[] { Statement.class }, new ParkingStatement((Statement) result)); + } + return result; + } catch (InvocationTargetException e) { + throw e.getCause(); + } + } + } + + private final class ParkingStatement implements java.lang.reflect.InvocationHandler { + private final Statement delegate; + + ParkingStatement(Statement delegate) { + this.delegate = delegate; + } + + @Override + public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { + try { + if ("executeQuery".equals(method.getName()) && armed.compareAndSet(true, false)) { + inside.countDown(); + release.await(); + } + return method.invoke(delegate, args); + } catch (InvocationTargetException e) { + throw e.getCause(); + } + } + } + } + + /* A pool running nothing but the timer interceptor, one session max. */ + private DataSource timerPool() { + DataSource ds = newDataSource(); + ds.getPoolProperties().setJdbcInterceptors(ResetAbandonedTimer.class.getName()); + ds.getPoolProperties().setInitialSize(0); + ds.getPoolProperties().setMinIdle(0); + ds.getPoolProperties().setMaxActive(1); + pool = ds; + return ds; + } + + /* + * The defect at the connection layer: a parked connection-level call + * that completes after its borrow ended must not stamp the borrow that + * holds the session now. The call's refusal by the tail's fence is what + * proves the scenario ran - it was refused precisely because its own + * borrow is over - and its stamp is what used to land on the new + * borrower anyway. + */ + @Test + void aCallInFlightAtBorrowEndDoesNotStampTheNextBorrower() throws Exception { + DataSource ds = timerPool(); + + Connection first = ds.getConnection(); + ResetAbandonedTimer timer = interceptorOf(first, ResetAbandonedTimer.class); + Assertions.assertNotNull(timer, "precondition: the chain carries the timer interceptor"); + JdbcInterceptor tail = timer.getNext(); + PooledConnection pcon = interceptorOf(first, ProxyConnection.class).getConnection(); + + CountDownLatch inside = new CountDownLatch(1); + CountDownLatch release = new CountDownLatch(1); + Blocker blocker = new Blocker("getAutoCommit", inside, release); + blocker.setNext(tail); + timer.setNext(blocker); + + AtomicReference<Throwable> parkedFailure = new AtomicReference<>(); + Thread parked = new Thread(() -> { + try { + first.getAutoCommit(); + } catch (Throwable t) { + parkedFailure.set(t); + } + }, "parked-call"); + parked.setDaemon(true); + parked.start(); + Assertions.assertTrue(inside.await(5, TimeUnit.SECONDS), + "precondition: the connection-level call reached the link below the timer"); + + // The parked call's borrower gives the session back, and it is handed + // out again - the same pooled connection, under a new borrow. + first.close(); + Connection second = ds.getConnection(); + Assertions.assertSame(pcon, interceptorOf(second, ProxyConnection.class).getConnection(), + "precondition: the parked call's session is the one held now"); + + // A reset that cannot be told apart from the stamp it replaced would + // prove nothing either way, so separate the two reads in time. + sleep(50); + long before = pcon.getTimestamp(); + pcon.setSuspect(true); + + release.countDown(); + parked.join(5000); + Assertions.assertFalse(parked.isAlive(), "precondition: the parked call completed"); + Assertions.assertNotNull(parkedFailure.get(), + "precondition: the tail's fence refused the parked call - that refusal is what shows the call " + + "completed after its own borrow ended"); + + Assertions.assertEquals(before, pcon.getTimestamp(), + "the parked call's stamp landed on the borrow that holds the session now: its timestamp was " + + before + " and is " + pcon.getTimestamp() + " after the call completed"); + Assertions.assertTrue(pcon.isSuspect(), + "setTimestamp clears the suspect flag, and the parked call wiped the suspect state recorded" + + " about the current borrow"); + + // The control: a call of the current borrow still keeps the timer - + // the borrow gate refuses stale borrows' stamps, not this one's. + timer.setNext(tail); + sleep(50); + long held = pcon.getTimestamp(); + second.getAutoCommit(); + Assertions.assertTrue(pcon.getTimestamp() > held, + "a call made during the current borrow must still reset the timer of the connection it is" + + " made on"); + + second.close(); + } + + /* + * The defect at the handle layer, which is where it bites in earnest: + * the query a hung database answers after its borrower already gave the + * handle back. The call had passed the pool's own borrow fence long + * before, so nothing below this interceptor can tell it belongs to a + * finished borrow; only the gate on the stamp knows. + */ + @Test + void aQueryInFlightAtBorrowEndDoesNotStampTheNextBorrower() throws Exception { + ParkingProvider provider = new ParkingProvider(getUrl()); + parkedProvider = provider; + DataSource ds = timerPool(); + ds.setDataSource(provider); + + Connection first = ds.getConnection(); + PooledConnection pcon = interceptorOf(first, ProxyConnection.class).getConnection(); + Statement statement = first.createStatement(); + + provider.armed.set(true); + AtomicReference<Throwable> parkedFailure = new AtomicReference<>(); + Thread parked = new Thread(() -> { + try { + statement.executeQuery("CALL 1"); + } catch (Throwable t) { + parkedFailure.set(t); + } + }, "parked-query"); + parked.setDaemon(true); + parked.start(); + Assertions.assertTrue(provider.inside.await(5, TimeUnit.SECONDS), + "precondition: the query reached the provider below the statement handle"); + + // The borrower times out and gives the handle back; the session goes + // straight to the next borrower, physical session still open. + first.close(); + Connection second = ds.getConnection(); + Assertions.assertSame(pcon, interceptorOf(second, ProxyConnection.class).getConnection(), + "precondition: the parked query's session is the one held now"); + + sleep(50); + long before = pcon.getTimestamp(); + pcon.setSuspect(true); + + provider.release.countDown(); + parked.join(5000); + Assertions.assertFalse(parked.isAlive(), "precondition: the parked query completed"); + Assertions.assertNull(parkedFailure.get(), + "precondition: the parked query ran to its end on the still-open session - a reply arriving that" + + " late is the scenario this interceptor exists for, and it never passes the fence again"); + + Assertions.assertEquals(before, pcon.getTimestamp(), + "the parked query's stamp landed on the borrow that holds the session now: its timestamp was " + + before + " and is " + pcon.getTimestamp() + " after the query completed"); + Assertions.assertTrue(pcon.isSuspect(), + "the parked query wiped the suspect state recorded about the current borrow"); + + // The control, on the very path the execution stamp moved onto: a + // query executed on the current borrow keeps the timer of the borrow + // it runs on. + sleep(50); + long held = pcon.getTimestamp(); + try (Statement live = second.createStatement()) { + Assertions.assertNotNull(live.executeQuery("CALL 1")); + } + Assertions.assertTrue(pcon.getTimestamp() > held, + "a query executed on the current borrow must still reset the timer of the connection it runs" + + " on"); + + second.close(); + } +} diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerSuspectReturnReport.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerSuspectReturnReport.java new file mode 100644 index 0000000000..67ee2fddc1 --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestResetAbandonedTimerSuspectReturnReport.java @@ -0,0 +1,240 @@ +/* + * 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.lang.management.ManagementFactory; +import java.sql.Connection; +import java.sql.Statement; +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; +import java.util.stream.Collectors; + +import javax.management.InstanceNotFoundException; +import javax.management.ListenerNotFoundException; +import javax.management.MBeanServer; +import javax.management.Notification; +import javax.management.NotificationListener; +import javax.management.ObjectName; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import org.apache.tomcat.jdbc.JdbcPoolBaseTest; +import org.apache.tomcat.jdbc.pool.DataSource; +import org.apache.tomcat.jdbc.pool.PooledConnection; +import org.apache.tomcat.jdbc.pool.ProxyConnection; +import org.apache.tomcat.jdbc.pool.jmx.ConnectionPoolMBean; + +/** + * What a pool with the {@code ResetAbandonedTimer} interceptor still reports + * when a connection comes back that was flagged suspect while borrowed. + * + * <p>The marking and the report are two ends of one story: the sweep that + * finds a borrow past {@code suspectTimeout} marks the connection and reports + * the marking, and {@code ConnectionPool.returnConnection} reads that same + * flag when the application finally hands the session back, reporting the + * return of a suspect connection to the pool's JMX listeners (and, with + * logAbandoned, in the log). That read happens after the application's + * {@link java.sql.Connection#close()} has travelled down the interceptor chain + * to the pool's tail, and the interceptor base class fires + * {@code closeInvoked()} on that way down - exactly once per borrow, at its + * end, before the close reaches the pool. A timer reset at that point wipes + * the report before it is made: {@link PooledConnection#setTimestamp(long)} + * clears the suspect flag and moves the timestamp the elapsed time of that + * report is measured from, so the return path reads a connection that never + * was suspected and neither the notification nor the log ever speaks for the + * connections that were. Nor is there anything left for such a stamp to + * protect: the borrow is ending, and the timestamp the returned connection + * needs - the one it goes idle under - is the return path's own to write, and + * it writes it.</p> + */ +class TestResetAbandonedTimerSuspectReturnReport extends JdbcPoolBaseTest { + + /* + * A notification type of this test's own, used as a barrier. The pool + * delivers its notifications on a single thread, in the order the pool + * queued them, so a marker queued once a borrow has ended is reached by + * the listener only after everything that borrow reported - or failed to + * report - has been delivered. That makes both the positive and the + * negative assertion below a question of what is in the list rather than + * of how long the test is willing to wait. + */ + private static final String FLUSH = "TEST-NOTIFY-BARRIER"; + + /* The pool under test, for forced teardown. */ + private DataSource pool; + + /* + * These tests can end with the connection still borrowed (a failed + * assertion between the borrow and its close). The regular data source + * teardown only disconnects idle connections, so the session of a borrowed + * one would linger until the garbage collector finalizes it and leak its + * session count into the starting point of the next test; force-close + * disconnects the busy ones as well, right away. + */ + @AfterEach + void disconnectLeakedBusyConnections() { + if (pool != null) { + pool.close(true); + } + } + + /* + * An enabled pool with the given interceptor configuration - the pool's + * default chain when no configuration is given - published the way a + * container publishes it, with this test's listener attached to the pool's + * own MBean. That MBean is what a monitoring client subscribes to, so it + * is what the report has to reach. + */ + private final class Subscribed { + private final DataSource ds; + private final ObjectName oname; + private final List<Notification> received = new CopyOnWriteArrayList<>(); + /* The one instance registered, so that it is the one detached again. */ + private final NotificationListener listener = (notification, handback) -> received.add(notification); + + private Subscribed(String role, String interceptors) throws Exception { + MBeanServer server = ManagementFactory.getPlatformMBeanServer(); + ds = newDataSource(); + ds.getPoolProperties().setJmxEnabled(true); + if (interceptors != null) { + ds.getPoolProperties().setJdbcInterceptors(interceptors); + } + ds.createPool(); + // The pool's MBean name is derived from the name the registration + // uses, so a uid of its own keeps this pool out of the names any + // other test of the suite publishes. + ds.preRegister(server, new ObjectName("tomcat:type=SuspectReturnReportTest,role=" + role + + ",uid=" + System.nanoTime())); + oname = ds.getPool().getJmxPool().getObjectName(); + Assertions.assertNotNull(oname, "an enabled pool publishes its MBean with its registration"); + server.addNotificationListener(oname, listener, null, null); + pool = ds; + } + + /* Everything the pool reported so far, once its notifier caught up. */ + private List<Notification> delivered() { + Assertions.assertTrue(ds.getPool().getJmxPool().notify(FLUSH, "everything this borrow reported"), + "the barrier notification must be accepted for delivery"); + awaitUntil(() -> received.stream().anyMatch(n -> FLUSH.equals(n.getType()))); + return received.stream().filter(n -> !FLUSH.equals(n.getType())).collect(Collectors.toList()); + } + + /* The reports of a returned suspect connection among a delivery. */ + private List<Notification> suspectReturned(List<Notification> delivered) { + return delivered.stream() + .filter(n -> ConnectionPoolMBean.SUSPECT_RETURNED_NOTIFICATION.equals(n.getType())) + .collect(Collectors.toList()); + } + + private void unsubscribe() { + try { + ManagementFactory.getPlatformMBeanServer().removeNotificationListener(oname, listener); + } catch (ListenerNotFoundException | InstanceNotFoundException ignore) { + // never added, or the pool's own teardown already took the + // MBean back - either way there is nothing left to detach + } + } + } + + /* + * The regression: the sweep has flagged this borrow, and the application + * hands the session back anyway. The flag must survive the close all the + * way to the read the return path makes of it, or the report that the + * marking exists for never happens. + */ + @Test + void aConnectionClosedWhileFlaggedSuspectStillReportsItsReturn() throws Exception { + Subscribed watched = new Subscribed("timer", ResetAbandonedTimer.class.getName()); + try { + Connection con = watched.ds.getConnection(); + PooledConnection pcon = interceptorOf(con, ProxyConnection.class).getConnection(); + // Stands in for the sweep's marking - the state a borrow is in + // once ConnectionPool.suspect() has reported it as running past + // suspectTimeout - set directly here so that nothing in this test + // depends on a timer expiring. + pcon.setSuspect(true); + Assertions.assertTrue(pcon.isSuspect(), "precondition: this borrow is flagged suspect"); + + con.close(); + + Assertions.assertEquals(1, watched.ds.getReturnedCount(), + "precondition: the pool must have taken this connection back"); + List<Notification> delivered = watched.delivered(); + List<Notification> reports = watched.suspectReturned(delivered); + Assertions.assertEquals(1, reports.size(), "the return of a suspect connection must be reported to the" + + " pool's listeners - the hook running on the way to the pool must not clear the state the" + + " return path reports, received: " + delivered); + Assertions.assertTrue(reports.get(0).getMessage().contains("marked suspect"), + "the report must say what it is reporting, read: " + reports.get(0).getMessage()); + } finally { + watched.unsubscribe(); + } + } + + /* + * The other half of the contract, on a pool without this interceptor: the + * same flow with the same marking does report, so the report this test + * pins is real, and what the test above fails on is the interceptor in the + * chain and nothing else. + */ + @Test + void theSameReturnReportsWhenNoTimerInterceptorIsConfigured() throws Exception { + Subscribed watched = new Subscribed("plain", null); + try { + Connection con = watched.ds.getConnection(); + PooledConnection pcon = interceptorOf(con, ProxyConnection.class).getConnection(); + pcon.setSuspect(true); + Assertions.assertTrue(pcon.isSuspect(), "precondition: this borrow is flagged suspect"); + + con.close(); + + Assertions.assertEquals(1, watched.ds.getReturnedCount(), + "precondition: the pool must have taken this connection back"); + List<Notification> delivered = watched.delivered(); + Assertions.assertEquals(1, watched.suspectReturned(delivered).size(), + "a pool without the interceptor must report the return of a suspect connection, received: " + + delivered); + } finally { + watched.unsubscribe(); + } + } + + /* + * Keeping the hook quiet must not turn the report into something that + * fires on any return: a connection that was never suspected goes back + * silently, active work under the interceptor included. + */ + @Test + void anOrdinaryReturnUnderTheInterceptorReportsNothingSuspect() throws Exception { + Subscribed watched = new Subscribed("clean", ResetAbandonedTimer.class.getName()); + try { + try (Connection con = watched.ds.getConnection(); Statement st = con.createStatement()) { + st.execute("SELECT 1"); + } + + Assertions.assertEquals(1, watched.ds.getReturnedCount(), + "precondition: the pool must have taken this connection back"); + List<Notification> delivered = watched.delivered(); + Assertions.assertTrue(watched.suspectReturned(delivered).isEmpty(), + "an ordinary return must not be reported as a suspect one, received: " + delivered); + } finally { + watched.unsubscribe(); + } + } +} diff --git a/webapps/docs/changelog.xml b/webapps/docs/changelog.xml index ccedeec6da..ec23ecefa8 100644 --- a/webapps/docs/changelog.xml +++ b/webapps/docs/changelog.xml @@ -1275,6 +1275,18 @@ the URL stay readable, and an authority that carries no credential - a bare host or a port - is left untouched. (remm) </fix> + <fix> + Correct a defect in the <code>ResetAbandonedTimer</code> interceptor + where a call that was still in flight when its borrow ended, and that + completed after the same connection had been handed to the next + borrower, reset the timer of that next borrower and cleared its + suspect state: the completing call is refused by the pool below, but + the interceptor booked its activity from the completion of the call, + where the connection looked checked out again, and the borrower the + abandoned check was watching read as active. Stamps from calls are now + booked only for the borrow the call started under, while the + <code>resetTimer()</code> management operation is unchanged. (remm) + </fix> </changelog> </subsection> <subsection name="Other"> --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
