+ * The pool makes them through {@link #connect}, and the tree catalog of a backend opens a + * connection of its own beside the pool ({@code JDBCStorage.newCatalogConnection}), the caller of + * {@code openTree()} being inside a transaction and holding a pooled connection already. What an + * attempt is, is the same either way and is here: the properties the driver is handed, the login, + * the transaction the rows of this backend need, and the read bound the connection carries from + * here on. Written out twice it drifted within one round - the standing read bound of #885 was + * given to the pooled half alone, leaving the catalog connection with the lift and no bound at + * all between its statements - which is why the two share this rather than being kept in step by + * hand (#929). + *
+ * What is not shared is what a caller makes of the connection, which is what {@link Established} + * hands back, and what becomes of one whose read bound would not come off: the pool closes such a + * connection rather than pooling it, while the catalog keeps it, having no second connection to + * fall back to. That difference is the {@code fate} of the warning, and it is the whole of it. + * + * @param what how the connection is named in the warning about a read bound that would not take + * @param fate what becomes of such a connection, named in the same warning + */ + static Established establish(String connectionString, ConnectDialect dialect, long connectTimeoutSeconds, + String what, String fate) throws SQLException { // A driver is free to write into the map it is handed, so it gets one of its own. final Properties properties = new Properties(); final boolean readBoundSet = dialect != null && connectTimeoutSeconds > 0 @@ -1583,22 +1641,39 @@ static CachedConnection connect(String connectionString, ConnectDialect dialect, // it returned could outlive a drop reported while it was still going on. final long provenAt = System.nanoTime(); final Connection conNew = DriverManager.getConnection(connectionString, properties); - boolean poolable = true; + final boolean loginBoundLifted; try { // still under the read bound: both of these are round trips of their own conNew.setAutoCommit(false); conNew.setTransactionIsolation(TRANSACTION_READ_COMMITTED); - // whatever the driver will not take here it has warned about already: a connection left - // carrying the read bound of its login serves the borrower that is waiting for it and is - // closed rather than pooled, so that bound does not outlive it in the pool - poolable = applyStandingReadBound(conNew, connectionString, dialect, connectTimeoutSeconds, readBoundSet); + loginBoundLifted = applyStandingReadBound(conNew, connectionString, dialect, connectTimeoutSeconds, + readBoundSet, what, fate); } catch (SQLException | RuntimeException e) { // nothing holds this connection yet: it would leak - closeQuietly(conNew); + closeQuietly(conNew, e); throw e; } - final CachedConnection established = new CachedConnection(connectionString, conNew, pool, metered, poolable); - established.lastKnownAliveNanos = provenAt; - return established; + return new Established(conNew, loginBoundLifted, provenAt); + } + + /** A connection just established, and what the caller that asked for it has to know about it. */ + static final class Established { + /** The connection, set up and carrying the read bound it keeps from here on. */ + final Connection con; + /** + * Whether the read bound of the login is off it. False for a driver that would not take the + * bound back, and the one thing a caller has to act on: such a connection fails every + * statement slower than a connect for the rest of its life, so the pool hands it to the + * borrower waiting for it and does not pool it afterwards. + */ + final boolean loginBoundLifted; + /** When the login was known to be through, as {@link System#nanoTime()} reads it. */ + final long provenAt; + + Established(Connection con, boolean loginBoundLifted, long provenAt) { + this.con = con; + this.loginBoundLifted = loginBoundLifted; + this.provenAt = provenAt; + } } /** @@ -1619,21 +1694,27 @@ static CachedConnection connect(String connectionString, ConnectDialect dialect, * the deadline of the borrow instead, and a deployment running that way would otherwise set the * property here and get nothing for it. *
- * Returns whether the connection may be pooled. A connection still carrying the bound of its - * login must not be: it would fail the statements of every borrower after this one. A - * connection that merely never took the standing bound may be - that is the connection this - * pool handed out before the property existed. + * Returns whether the read bound of the login is off the connection. One still carrying it must + * not be pooled: it would fail the statements of every borrower after this one. A connection + * that merely never took the standing bound may be - that is the connection this pool handed out + * before the property existed. + * + * @param what how the connection is named in the warning; the caller's, since the same failure + * ends a connection of the pool and the one connection of a backend's tree catalog + * @param fate what becomes of a connection whose read bound would not take, named in the same + * warning: the pool closes it rather than pooling it, the catalog keeps it */ private static boolean applyStandingReadBound(Connection con, String connectionString, ConnectDialect dialect, - long loginBoundSeconds, boolean readBoundSet) { + long loginBoundSeconds, boolean readBoundSet, + String what, String fate) { final int millis = standingReadBoundMillis(connectionString, dialect); if (millis == 0 && !readBoundSet) { return true; // nothing of ours on this connection: nothing to set here, and nothing to lift } final String consequence = readBoundSet - ? "statements taking longer than the " + loginBoundSeconds - + "s the login of this connection was bounded by fail on it, and it is closed rather than pooled" - : "this connection carries no read bound of its own, so a read of it the database stops answering waits" + ? "statements on " + what + " taking longer than the " + loginBoundSeconds + + "s the login of this connection was bounded by fail on it, and " + fate + : what + " carries no read bound of its own, so a read of it the database stops answering waits" + " with no deadline able to reach it"; return setNetworkTimeout(con, millis, consequence) || !readBoundSet; } @@ -2151,6 +2232,21 @@ private static void closeQuietly(Connection con) { } } + /** + * Closes a connection nothing holds yet, reporting the failure of the close on the one being + * unwound: the connection is gone either way, and a driver that will not close is worth knowing + * about where the failure that leads here is reported. + */ + private static void closeQuietly(Connection con, Throwable unwinding) { + try { + con.close(); + } catch (SQLException | RuntimeException e) { + // the unchecked one as well: this runs from the catch of a failure it must not replace + // (JLS 14.20.2) + unwinding.addSuppressed(e); + } + } + @Override public Statement createStatement() throws SQLException { return parent.createStatement(); diff --git a/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java b/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java index 328f7dd824..ee31e72d84 100644 --- a/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java +++ b/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java @@ -1395,8 +1395,9 @@ Connection newStampConnection(Dialect dialect) throws SQLException { * thread that is waiting. It is the pool's retry that is wanted here and not its queue, which is * why the loop below is its own rather than a borrow of {@link CachedConnection#getConnection}. * What one attempt is, is the login and the set-up behind it, exactly as an attempt of a borrow is - * ({@code CachedConnection.connect}): a session the server takes and then kills off answers the - * first statement of the set-up rather than the login, and it is the same refusal either way. + * - the same code, {@link CachedConnection#establish} (#929): a session the server takes and then + * kills off answers the first statement of the set-up rather than the login, and it is the same + * refusal either way. *
* That is also what this wait is weaker than a borrow at, and it is worth writing down rather than * leaving to be discovered: a borrow can be answered by a peer handing a connection back, while @@ -1502,7 +1503,11 @@ Connection newCatalogConnection(long budgetDeadline) throws SQLException { deadline==budgetDeadline, now-startedAt, attempts, e); } CachedConnection.warnStallOutsidePool(connectionString, "tree catalog", attempts, startedAt, e); - backoffMs=Math.min(backoffMs==0 ? 1 : backoffMs*2, CachedConnection.MAX_BACKOFF_MS); + // the schedule of the pool, from the one place that holds it (#929). The wait is slept + // out rather than handed to the deque of the pool, which is the difference this loop + // exists for: nothing here can be answered by a peer returning a connection, so there + // is no queue to wait on - see the head of this method + backoffMs=CachedConnection.nextBackoffMs(backoffMs); try { Thread.sleep(Math.min(backoffMs, remaining)); }catch (InterruptedException interrupted) { @@ -1577,51 +1582,29 @@ private static SQLTimeoutException catalogConnectTimedOut(String connectionStrin * decided on is the chain of the original, and the redaction is the caller's - a redacted copy is * rebuilt link by link, so redacting an attempt that is about to be retried would pay for a * failure nobody ever sees. + *
+ * The login, the transaction it is set up for and the read bound it carries afterwards are the + * pool's own, from the one place that holds them ({@link CachedConnection#establish}, #929): + * written out here as well they drifted inside a single round, the standing read bound of #885 + * reaching the pooled half alone and leaving this connection with nothing bounding the reads + * between its statements - its {@code commit()}, the {@code rollback()} of a session given up and + * the {@code close()} of one that lost the race to another thread. + *
+ * What is this connection's own is what becomes of it where the read bound of the login will not + * come off. A driver that refuses to take it back leaves it in force for the life of the + * connection, and that bound is the one this attempt was given - near the end of the deadline of + * the retry, a second. The connection is kept all the same, where the pool closes such a + * connection rather than pooling it: this backend has one catalog connection and no borrower + * behind it to hand another to, and failing here instead would stop the backend opening on a + * driver whose setNetworkTimeout is not implemented at all, where the pooled connection beside it + * works. There is no state to fail with that {@code write()} does not read as a connection the + * database dropped, either. So it is reported and the connection is used, at the bound in force. */ private Connection connectCatalog(String connectionString, CachedConnection.ConnectDialect dialect, long timeoutSeconds) throws SQLException { - // A driver is free to write into the map it is handed, so every attempt gets one of its own. - final Properties properties=new Properties(); - final boolean readBoundSet=dialect!=null && timeoutSeconds>0 - && dialect.bound(connectionString, properties, timeoutSeconds); - final Connection con=DriverManager.getConnection(connectionString, properties); - try { - con.setAutoCommit(false); - con.setTransactionIsolation(Connection.TRANSACTION_READ_COMMITTED); - }catch (SQLException | RuntimeException e) { // nothing else holds this connection yet: it would leak - closeQuietly(con, e); - throw e; - } - if (readBoundSet) { - try { - // only where this code set one: a read bound of the connection string is the - // administrator's and is not lifted along with it, exactly as the pool leaves it - con.setNetworkTimeout(Runnable::run, 0); - }catch (SQLException | RuntimeException e) { - // A driver that will not take the bound back leaves it in force for the life of the - // connection, and that bound is the one this attempt was given - near the end of the - // deadline of the retry, a second. The connection is kept all the same, which is the - // pool's own answer to this failure: it stops pooling such a connection and still hands - // it to the borrower that is waiting. Failing here instead would stop the backend opening - // on a driver whose setNetworkTimeout is not implemented at all, where the pooled - // connection beside it works - and there is no state to fail with that write() does not - // read as a connection the database dropped. So it is reported, at the bound in force. - logger.warn(LocalizableMessage.raw("jdbc: the catalog connection of backend %s keeps the %ds read bound its login was given, so a statement of the catalog slower than that fails on it: %s", - config.getBackendId(), timeoutSeconds, stackTraceToSingleLineString(e))); - } - } - return con; - } - - /** Closes a connection nothing holds yet, reporting the failure of the close on the one being unwound. */ - private static void closeQuietly(Connection con, Throwable unwinding) { - try { - con.close(); - }catch (SQLException | RuntimeException e) { - // the unchecked one as well: this runs from the catch of a failure it must not replace - // (JLS 14.20.2), which is the rule every close of this class keeps - unwinding.addSuppressed(e); - } + return CachedConnection.establish(connectionString, dialect, timeoutSeconds, + "the catalog connection of backend "+config.getBackendId(), + "it is kept as it is: this backend has one catalog connection and no second to fall back to").con; } /** diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java index 3e834f39b7..d34f549df0 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java @@ -2081,6 +2081,29 @@ public void testOnlyTheReadBoundThisClassSetsIsItsOwnToLift() { "a connection carries no standing bound where none is configured"); } + /** + * The wait between two attempts of a connect: a millisecond, doubling to the ceiling and staying + * there, so that a database refusing connections for a moment is asked again at once and one + * refusing them for a minute is asked once a second rather than in a spin. Pinned here because + * both loops that retry a connect of this backend wait on this schedule - the borrow of this + * class and the catalog connect of {@code JDBCStorage.newCatalogConnection} - and a change to it + * is a change to the pair (#929). + */ + @Test(timeOut = 120000) + public void testTheBackoffOfARetriedConnectDoublesToItsCeiling() { + assertEquals(CachedConnection.nextBackoffMs(0), 1, "the first wait of a retry is not a millisecond"); + long backoffMs = 0; + for (int attempt = 0; attempt < 20; attempt++) { + final long previous = backoffMs; + backoffMs = CachedConnection.nextBackoffMs(backoffMs); + assertTrue(backoffMs > previous || backoffMs == CachedConnection.MAX_BACKOFF_MS, + "the wait neither grew nor stood at its ceiling: " + previous + " -> " + backoffMs); + assertTrue(backoffMs <= CachedConnection.MAX_BACKOFF_MS, + "the wait of a retry grew past the ceiling of the schedule: " + backoffMs); + } + assertEquals(backoffMs, CachedConnection.MAX_BACKOFF_MS, "the wait never reached its ceiling"); + } + /** * The bound is configured in seconds and reaches the driver in milliseconds; 0, a negative * value and a value that is no number all leave a connection unbounded, which is what this diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CatalogConnectionTestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CatalogConnectionTestCase.java index 72d8d92b15..ac676cf9e8 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CatalogConnectionTestCase.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CatalogConnectionTestCase.java @@ -71,6 +71,9 @@ public class CatalogConnectionTestCase extends DirectoryServerTestCase { private ProbeDriver probeDriver; + /** The standing read bound as this JVM was started with it, put back before every case. */ + private static final int CONFIGURED_READ_TIMEOUT_MILLIS = CachedConnection.readTimeoutMillis; + @BeforeClass public void registerProbeDriver() throws SQLException { probeDriver = new ProbeDriver(); @@ -98,6 +101,9 @@ public void resetProbe() { probeDriver.attempts.set(0); probeDriver.refusalDelayMs = 0; probeDriver.interruptOnAttempt = false; + // the same for the bound the connect reads off the class: a case that varies it and fails + // before its finally would otherwise hand its value to whatever runs after it + CachedConnection.readTimeoutMillis = CONFIGURED_READ_TIMEOUT_MILLIS; } private static JDBCStorage storageFor(String url) { @@ -492,6 +498,86 @@ public void testTheCatalogConnectionIsKeptWhereTheReadBoundWillNotComeOff() thro } } + /** + * The catalog connection carries the read bound a deployment asked for + * ({@link CachedConnection#READ_TIMEOUT_PROPERTY}), exactly as a connection of the pool does. + *
+ * Its statements are bounded by the class of the work they belong to, and nothing else on it is: + * the {@code commit()} that writes a catalog row, the {@code rollback()} of a session given up + * and the {@code close()} of one that lost the race have no bound of their own, so against a + * database which stops answering after the login they wait for as long as the socket does. That + * is the gap #885 closed for every connection of the pool - this one was written beside them, + * one round before the property existed, and was left with the lift alone. + */ + @Test + public void testTheCatalogConnectionCarriesTheReadBoundAskedFor() throws Exception { + final String previous = System.getProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY); + final String previousPool = System.getProperty(CachedConnection.POOL_TIMEOUT_PROPERTY); + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, "30"); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "0"); + CachedConnection.readTimeoutMillis = 90000; + try { + final Connection con = storageFor(ProbeDriver.URL).newCatalogConnection(NO_REPLAY_WINDOW); + con.close(); + verify(con).setNetworkTimeout(any(), eq(90000)); + // and the bound of the login is gone with it: the value that replaces it is the whole of + // what this connection carries, not a lift followed by a second call putting one back + verify(con, never()).setNetworkTimeout(any(), eq(0)); + } finally { + restore(previous); + restorePool(previousPool); + } + } + + /** + * And it carries it whether or not the login had a bound of its own to lift: the read bound of a + * login is only ever set where the connect is bounded, so a deployment running with + * {@code connect.timeout=0} - the setting that leaves a connect to the deadline of the retry + * alone - would otherwise set this property and get nothing for it on this connection. + */ + @Test + public void testTheCatalogConnectionCarriesTheReadBoundWhereItsLoginHadNoneToLift() throws Exception { + final String previous = System.getProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY); + final String previousPool = System.getProperty(CachedConnection.POOL_TIMEOUT_PROPERTY); + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, "0"); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "0"); + CachedConnection.readTimeoutMillis = 90000; + try { + final Connection con = storageFor(ProbeDriver.URL).newCatalogConnection(NO_REPLAY_WINDOW); + con.close(); + verify(con).setNetworkTimeout(any(), eq(90000)); + } finally { + restore(previous); + restorePool(previousPool); + } + } + + /** + * A read bound standing in the connection string is the deployment's own: it is not replaced by + * the configured one here, exactly as it is not on a connection of the pool, and exactly as the + * read bound of a login is not set on top of it. A guard rather than a regression test - the + * bound is asked of {@link CachedConnection#standingReadBoundMillis}, which answers 0 for such a + * url - and it is here because a bound put on from the value of the property alone would pass + * every other case of this class. + */ + @Test + public void testAReadBoundOfTheUrlIsNotReplacedOnTheCatalogConnection() throws Exception { + final String previous = System.getProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY); + final String previousPool = System.getProperty(CachedConnection.POOL_TIMEOUT_PROPERTY); + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, "30"); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "0"); + CachedConnection.readTimeoutMillis = 90000; + try { + final Connection con = storageFor(ProbeDriver.URL + "?socketTimeout=30") + .newCatalogConnection(NO_REPLAY_WINDOW); + con.close(); + verify(con, never()).setNetworkTimeout(any(), anyInt()); + } finally { + restore(previous); + restorePool(previousPool); + } + } + /** * A connection whose set-up failed is held by nobody - the caller is answered with the failure - * so it is closed here or it leaks for the life of the process, one per open of a storage.