diff --git a/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java b/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java index 4b7451f9fb..516960e97e 100644 --- a/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java +++ b/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java @@ -244,6 +244,16 @@ private static int standingReadBoundMillis(String connectionString, ConnectDiale static final long STALL_WARNING_AFTER_MS = 1000; static final long STALL_WARNING_INTERVAL_MS = 10000; + /** + * The next wait of a connect that is being retried: a millisecond, doubling to {@link + * #MAX_BACKOFF_MS} and staying there. One schedule for both loops that retry a connect of this + * backend - the borrow of {@link #getConnection} and the catalog connect of {@code + * JDBCStorage.newCatalogConnection} - so that the next change to it is a change to both (#929). + */ + static long nextBackoffMs(long backoffMs) { + return Math.min(backoffMs == 0 ? 1 : backoffMs * 2, MAX_BACKOFF_MS); + } + /** How many links of the cause and getNextException() chains of a failure are looked at. */ private static final int MAX_CHAIN_LENGTH = 32; @@ -275,7 +285,24 @@ private static int standingReadBoundMillis(String connectionString, ConnectDiale // safe form of it, the way warnedOnce below is: a static field of this class outlives every // borrow, and the password of the backend has no business in one. private static final Map lastStallWarning = new ConcurrentHashMap<>(); - private static final AtomicLong lastReadBoundWarning = new AtomicLong(); + + /** + * When a connection this backend could not put a read bound on was last reported, per + * consequence of that failure rather than once for the JVM. + *

+ * Keyed for the reason the stall warning above is keyed, and the reason is sharper here: the + * connections this happens to do not share a fate. A connection of the pool is closed rather + * than pooled, while the one catalog connection of a backend is kept and carries the bound of + * its login for the rest of its life ({@code JDBCStorage.connectCatalog}, #929) - so a single + * timestamp has the pool, which meets the failure first and on every connect, report for the + * catalog connection beside it, and an operator reads that the connection was closed when the + * one they will meet again was kept. + *

+ * Package private so that a test can read what was reported and clear it, the way + * {@link #warnedOnce} is read: the warning itself goes to a logger with a throttle no test can + * wind back. + */ + static final Map lastReadBoundWarning = new ConcurrentHashMap<>(); /** * When an operation last reported that the database had dropped a connection of a pool, as a @@ -1500,7 +1527,15 @@ static Connection getConnection(String connectionString, boolean trusted, long m timeout.initCause(reported(e, connectionString)); throw timeout; } - backoffMs = Math.min(backoffMs == 0 ? 1 : backoffMs * 2, MAX_BACKOFF_MS); + // The schedule the catalog connect of JDBCStorage waits on as well, from the one + // place that holds it (#929). What the two do with the wait is not the same and is + // not meant to be: this one hands it to the poll of the deque at the head of the + // loop, where a peer returning a connection ends the wait early, while a catalog + // connect has no peer to wait for and sleeps it out. The failure at the end of the + // deadline differs as deliberately - 08001 here, the driver's own state there, a + // manufactured class 08 being read by JDBCStorage.write() as a connection the + // database dropped. + backoffMs = nextBackoffMs(backoffMs); waitMs = Math.min(backoffMs, remaining); warnStall(connectionString, attempts, startedAt, e); } catch (RuntimeException e) { @@ -1733,8 +1768,48 @@ private static int boundValidation(Connection con) { return previous < 0 ? 0 : previous; } + /** How a connection of this pool is named where the read bound of its login would not come off. */ + static final String POOLED_CONNECTION = "a connection of this pool"; + /** + * And what becomes of it: whatever the driver will not take there it has warned about already, + * so such a connection serves the borrower that is waiting for it and is closed rather than + * pooled - the bound of its login does not outlive it in the pool. + */ + static final String POOLED_CONNECTION_FATE = "it is closed rather than pooled"; + static CachedConnection connect(String connectionString, ConnectDialect dialect, long connectTimeoutSeconds, Pool pool, boolean metered) throws SQLException { + final Established established = establish(connectionString, dialect, connectTimeoutSeconds, + POOLED_CONNECTION, POOLED_CONNECTION_FATE); + final CachedConnection con = new CachedConnection(connectionString, established.con, pool, metered, + established.loginBoundLifted); + con.lastKnownAliveNanos = established.provenAt; + return con; + } + + /** + * The login and the set-up behind it: one attempt of a connect, wherever this backend makes one. + *

+ * 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 @@ -1744,22 +1819,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; + } } /** @@ -1780,49 +1872,90 @@ 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" + return setNetworkTimeout(con, millis, readBoundConsequence(readBoundSet, loginBoundSeconds, what, fate)) + || !readBoundSet; + } + + /** + * What a driver refusing the read bound costs the connection it refused it on, as the warning + * about it says so. + *

+ * Built apart from the logging of it for the reason {@link #stallMessage} is, and it is what + * tells the two callers of {@link #establish} apart in the one place they differ: a connection + * of the pool is closed rather than pooled where this fails, while the one catalog connection + * of a backend is kept and carries the bound of its login for the rest of its life (#929). + * Reached through the shipped path only by a driver that really refuses the call, which is why + * it is a method a test can hold to the difference rather than a string inline. + */ + static String readBoundConsequence(boolean readBoundSet, long loginBoundSeconds, String what, String fate) { + return readBoundSet + ? "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; } /** * Puts a network timeout on a connection, reporting a driver that will not take one. The * consequence is the caller's to name: the same failure ends a freshly established connection * carrying the read bound of its login and a pooled one whose bound could not be put back. + *

+ * The failure itself rather than its message alone: the drivers that refuse this call refuse it + * as {@code SQLFeatureNotSupportedException}, which a driver is free to raise with no message + * at all - and a line reading "(null)" says neither what refused nor why. */ private static boolean setNetworkTimeout(Connection con, int millis, String consequence) { try { con.setNetworkTimeout(DIRECT_EXECUTOR, millis); return true; } catch (SQLException | RuntimeException e) { - // Throttled rather than reported once for the life of the JVM: every connection this - // happens to carries a read bound it was never meant to keep, and a statement dying of - // it hours later needs a warning of its own to be traced back to here. - final long now = System.currentTimeMillis(); - final long last = lastReadBoundWarning.get(); - if (now - last >= STALL_WARNING_INTERVAL_MS && lastReadBoundWarning.compareAndSet(last, now)) { + if (readBoundWarningDue(consequence, System.currentTimeMillis())) { logger.warn(LocalizableMessage.raw( "The read bound of a JDBC connection could not be set to %d ms (%s): %s", - millis, e.getMessage(), consequence)); + millis, e, consequence)); } return false; } } + /** + * Whether the warning about a read bound that would not take is due, and the filing of it. + *

+ * Throttled rather than reported once for the life of the JVM: every connection this happens to + * carries a read bound it was never meant to keep, and a statement dying of it hours later needs + * a warning of its own to be traced back to here. Throttled per consequence and not once for the + * JVM, for the reason {@link #stallWarningDue} is keyed per url: a connection of the pool meets + * this failure on every connect and would otherwise silence the line about the one catalog + * connection of a backend, which is kept rather than closed and has no other line about it at + * all (#929). + *

+ * Filing the moment is part of deciding it, so that two threads meeting the failure at once + * report once. + */ + static boolean readBoundWarningDue(String consequence, long now) { + final AtomicLong lastOfThisConsequence = + lastReadBoundWarning.computeIfAbsent(consequence, key -> new AtomicLong()); + final long last = lastOfThisConsequence.get(); + return now - last >= STALL_WARNING_INTERVAL_MS && lastOfThisConsequence.compareAndSet(last, now); + } + /** * Whether the database took no connection for the moment, rather than refusing one for good: * it is at its connection limit - one of our own connections is on its way back to the pool - @@ -1965,6 +2098,11 @@ static String stallMessage(String connectionString, int attempts, long waitedMs, * RootContainer.open() makes the message of the cause the message of what it throws - so a * link left as it stands would carry the password past the wrapper. The SQLState and the * vendor code of every link survive it: they are what tells a caller what happened. + *

+ * The whole chain is the causes, the further exceptions of {@code getNextException()} and what + * was suppressed on each of them - the last being where this class puts the failure of a close + * it could not make (#929), and a link nothing else points at is a link a walk that skipped it + * would report unredacted. */ static SQLException reported(SQLException e, String connectionString) { return holdsCredentials(e, connectionString) @@ -1972,7 +2110,15 @@ static SQLException reported(SQLException e, String connectionString) { : e; } - /** The same of an unchecked failure: a driver is free to report a connect it will not make as one. */ + /** + * The same of an unchecked failure: a driver is free to report a connect it will not make as one. + *

+ * Flat where {@link #reported} rebuilds a chain - the cause of a failure of this shape is the + * driver's own business - with the one exception of what was suppressed on it, which is this + * class's own: the close of a connection whose set-up failed is reported there (#929), and a + * rebuild dropping it would say nothing of a driver that will not close on the only path where + * the message is redacted at all. + */ static Exception reportedUnchecked(RuntimeException e, String connectionString) { if (!holdsCredentials(e, connectionString)) { return e; @@ -1981,6 +2127,7 @@ static Exception reportedUnchecked(RuntimeException e, String connectionString) + (e.getMessage() == null ? "" : ": " + redact(e.getMessage(), connectionString)), CONNECT_FAILED_SQL_STATE); redacted.setStackTrace(e.getStackTrace()); + copySuppressed(e, redacted, connectionString, new int[] { MAX_CHAIN_LENGTH }); return redacted; } @@ -2008,6 +2155,14 @@ private static boolean holdsCredentials(Throwable failure, String connectionStri enqueue(pending, visited, ((SQLException) t).getNextException()); } enqueue(pending, visited, t.getCause()); + // and the links nothing else of a failure points at: a close that could not be made is + // carried here (establish(), #929) and an interrupt that ended a wait for a connect is + // (JDBCStorage.newCatalogConnection), and a driver names the url it could not close as + // readily as the one it could not open. Left out of this walk, such a link is the one + // way a password of this backend reaches the log unredacted. + for (final Throwable suppressed : t.getSuppressed()) { + enqueue(pending, visited, suppressed); + } } return false; } @@ -2038,9 +2193,25 @@ private static SQLException redactedCopy(SQLException e, String connectionString if (e.getCause() != null) { copy.initCause(budget[0] > 0 ? redactedLink(e.getCause(), connectionString, budget) : droppedTail()); } + copySuppressed(e, copy, connectionString, budget); return copy; } + // The suppressed links of a failure are rebuilt with the rest of it and counted against the + // same budget. They are not decoration here: the failure of a close that could not be made + // rides on the failure being unwound (establish(), #929), and a rebuild that dropped them + // would lose it at the one deployment whose log is redacted - which is the deployment whose + // url has a password in it, the log that is worth reading. + private static void copySuppressed(Throwable from, Throwable to, String connectionString, int[] budget) { + for (final Throwable suppressed : from.getSuppressed()) { + if (budget[0] <= 0) { + to.addSuppressed(droppedTail()); + return; + } + to.addSuppressed(redactedLink(suppressed, connectionString, budget)); + } + } + // What stands where the budget ran out. Without it the same failure logs its root cause when // the url of the backend has no password in it and loses it without a word when it has, which // is a report of a connect nobody can read against a report of one they can. @@ -2062,6 +2233,7 @@ private static Throwable redactedLink(Throwable t, String connectionString, int[ if (t.getCause() != null) { copy.initCause(budget[0] > 0 ? redactedLink(t.getCause(), connectionString, budget) : droppedTail()); } + copySuppressed(t, copy, connectionString, budget); return copy; } @@ -2320,6 +2492,25 @@ 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. + *

+ * Package private because every connect of this backend closes a connection it could not set up + * the same way: the two roads {@link #establish} holds, and the stamp connection of {@code + * JDBCStorage.newStampConnection}, which has bounds of its own but the same rule about a close. + */ + 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 02a41a815d..70e45f8df9 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 @@ -1629,9 +1629,10 @@ Connection newStampConnection(Dialect dialect) throws SQLException { // transaction. con.commit(); }catch (SQLException e) { // nothing else holds this connection yet: it would leak - try { - con.close(); - }catch (SQLException e2) {} + // and a driver that will not close is said so on the failure being unwound, as it is on + // the two roads CachedConnection.establish() holds (#929): this connection is gone either + // way, and the failure of the set-up is the one report this attempt makes + CachedConnection.closeQuietly(con, e); throw e; } return con; @@ -1678,8 +1679,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 @@ -1812,7 +1814,11 @@ Connection newCatalogConnection(long budgetDeadline, long connectTimeoutSeconds, 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) { @@ -1881,57 +1887,47 @@ private static SQLTimeoutException catalogConnectTimedOut(String connectionStrin return timeout; } + /** How this connection is named where the read bound of its login would not come off. */ + static String catalogConnectionNamed(String backendId) { + return "the catalog connection of backend "+backendId; + } + + /** + * And what becomes of it, which is the whole of what this road does not share with the pool's: + * the pool closes such a connection rather than pooling it, having a borrower to hand another + * to, while this backend has one catalog connection and nothing behind it. + */ + static final String CATALOG_CONNECTION_FATE= + "it is kept as it is: this backend has one catalog connection and no second to fall back to"; + /** * One attempt of {@link #newCatalogConnection}, established and set up or left holding nothing. * Failures leave here as the driver reported them, checked and unchecked alike: what a retry is * 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, + catalogConnectionNamed(config.getBackendId()), CATALOG_CONNECTION_FATE).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 4250deb603..ce3d1d1b96 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 @@ -843,6 +843,9 @@ public void testEveryBoundTurnedOffInAPostgresUrlIsReported() throws Exception { * Walked by identity rather than link by link: a driver is free to make the cause and the next * exception of a link the same failure, which is the very shape the sibling test builds, and a * helper looping on it would hang the run it is checking for exactly that. + *

+ * The suppressed links along with the rest: the close of a connection whose set-up failed is + * carried there (#929), and everything that prints a failure prints those too. */ private static void assertNoCredentials(Throwable failure) { final Set seen = Collections.newSetFromMap(new IdentityHashMap()); @@ -856,6 +859,9 @@ private static void assertNoCredentials(Throwable failure) { enqueue(pending, seen, ((SQLException) t).getNextException()); } enqueue(pending, seen, t.getCause()); + for (final Throwable suppressed : t.getSuppressed()) { + enqueue(pending, seen, suppressed); + } } } @@ -935,6 +941,44 @@ public void testTheTailOfALongChainIsNamedRatherThanDropped() throws Exception { "the tail a rebuild had no budget for has to say so: " + last.getMessage()); } + /** + * A credential named by a suppressed link alone is redacted like any other. The close of a + * connection whose set-up failed rides there (establish(), #929) and an interrupt that ended a + * wait for a catalog connect does, and a driver names the url it could not close as readily as + * the one it could not open. Left out of the walk, such a link is the one way the password of + * this backend reaches the server error log as it stands: the failure it hangs on says nothing + * of the url, so the failure is handed on unredacted, suppressed link and all. + */ + @Test(timeOut = 60000) + public void testACredentialNamedOnlyBySuppressedIsStillRedacted() throws Exception { + final String url = "jdbc:postgresql://opendj:S3cretOfTheBackend@127.0.0.1:5432/opendj"; + final SQLException setupFailure = new SQLException("Connection to 127.0.0.1:5432 refused", "08006", 1); + setupFailure.addSuppressed(new SQLException("could not close " + url, "08003", 2)); + + assertNoCredentials(CachedConnection.reported(setupFailure, url)); + } + + /** + * ... and the link itself survives the rebuild rather than being dropped along with the + * password. A redacted failure is the only failure the deployment with a password in its url + * ever sees, so a rebuild that left the suppressed links behind would answer "the set-up failed" + * where the log of that deployment alone has to say "and the connection would not close either". + */ + @Test(timeOut = 60000) + public void testTheSuppressedLinksOfAFailureSurviveItsRedaction() throws Exception { + final String url = "jdbc:postgresql://opendj:S3cretOfTheBackend@127.0.0.1:5432/opendj"; + final SQLException setupFailure = new SQLException("no transaction on " + url, "08006", 1); + setupFailure.addSuppressed(new SQLException("the connection would not close", "08003", 2)); + + final SQLException reported = CachedConnection.reported(setupFailure, url); + + assertNoCredentials(reported); + assertEquals(reported.getSuppressed().length, 1, + "the rebuild of a redacted failure dropped what was suppressed on it"); + assertTrue(String.valueOf(reported.getSuppressed()[0].getMessage()).contains("would not close"), + "the suppressed link of a redacted failure: " + reported.getSuppressed()[0]); + } + /** * A database that is not listening at all: every dialect reports it instead of retrying the * refused connect until the caller gives up on the operation. @@ -1288,12 +1332,20 @@ public void testTheSessionLimitOfAnOracleInstanceIsRetried() { "the session limit of an instance is cleared by a session ending"); } - /** A connection the setup of which failed belongs to nobody: it has to be closed, not leaked. */ + /** + * A connection the setup of which failed belongs to nobody: it has to be closed, not leaked. + *

+ * And a driver that will not close is said so on the failure being unwound rather than swallowed + * (#929): the connection is gone either way, but a driver refusing to close is the shape of a + * leak nobody would otherwise hear about, and the failure of the set-up is the one report this + * attempt makes. + */ @Test(timeOut = 120000) public void testConnectionIsClosedWhenItsSetupFails() throws Exception { final String url = StubDriver.PREFIX + "setup-failure"; final Connection broken = mock(Connection.class); doThrow(new SQLException("read only")).when(broken).setAutoCommit(false); + doThrow(new SQLException("will not close")).when(broken).close(); stub.answerWith(broken); try { @@ -1301,6 +1353,9 @@ public void testConnectionIsClosedWhenItsSetupFails() throws Exception { fail("a connection that cannot be set up must be reported"); } catch (SQLException expected) { assertEquals(expected.getMessage(), "read only"); + assertEquals(expected.getSuppressed().length, 1, + "the failure of the close is not carried on the failure being unwound"); + assertEquals(expected.getSuppressed()[0].getMessage(), "will not close"); } verify(broken).close(); } @@ -1311,6 +1366,7 @@ public void testConnectionIsClosedWhenItsSetupFailsWithAnUncheckedError() throws final String url = StubDriver.PREFIX + "setup-unchecked"; final Connection broken = mock(Connection.class); doThrow(new IllegalStateException("driver internal")).when(broken).setTransactionIsolation(anyInt()); + doThrow(new IllegalStateException("will not close")).when(broken).close(); stub.answerWith(broken); try { @@ -1318,6 +1374,11 @@ public void testConnectionIsClosedWhenItsSetupFailsWithAnUncheckedError() throws fail("a connection that cannot be set up must be reported"); } catch (IllegalStateException expected) { assertEquals(expected.getMessage(), "driver internal"); + // the unchecked failure of a close as well: it 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 + assertEquals(expected.getSuppressed().length, 1, + "the failure of the close is not carried on the failure being unwound"); + assertEquals(expected.getSuppressed()[0].getMessage(), "will not close"); } verify(broken).close(); } @@ -2292,6 +2353,58 @@ 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() { + // the schedule itself and not a property of it: "grows until it reaches the ceiling" is + // answered by every factor there is - a schedule tripling from 1 reaches 1000 in eight steps + // and grows at every one of them - and the factor is what the two loops share + long backoffMs = 0; + for (final long expected : new long[] { 1, 2, 4, 8, 16, 32, 64, 128, 256, 512, 1000, 1000 }) { + final long previous = backoffMs; + backoffMs = CachedConnection.nextBackoffMs(backoffMs); + assertEquals(backoffMs, expected, + "the wait of a retry left the doubling schedule after " + previous + "ms"); + } + assertEquals(backoffMs, CachedConnection.MAX_BACKOFF_MS, "the wait of a retry is not at its ceiling"); + } + + /** + * The warning about a read bound a driver would not take is throttled per consequence and not + * once for the JVM, so that one connection does not report for another. + *

+ * The two connections this happens to do not share a fate: a connection of the pool is closed + * rather than pooled, while the one catalog connection of a backend is kept and carries the + * bound of its login for the rest of its life (#929). The pool meets the failure on every + * connect and the catalog once per open of the backend, so a single timestamp has the pool + * silence the line about the catalog connection - and the line that did come out says the + * connection was closed, of a connection that is still being read from. + */ + @Test(timeOut = 120000) + public void testTheReadBoundWarningOfOneConnectionDoesNotSilenceAnother() { + final long now = System.currentTimeMillis(); + final String pooled = "a connection of this pool of testTheReadBoundWarning"; + final String catalog = "the catalog connection of backend testTheReadBoundWarning"; + CachedConnection.lastReadBoundWarning.remove(pooled); + CachedConnection.lastReadBoundWarning.remove(catalog); + + assertTrue(CachedConnection.readBoundWarningDue(pooled, now), "the first line about a connection was not due"); + assertTrue(CachedConnection.readBoundWarningDue(catalog, now), + "a line about one connection silenced the line about another, which has no other line about it"); + + assertFalse(CachedConnection.readBoundWarningDue(pooled, now + 1), + "the same consequence was reported twice inside one interval"); + assertTrue(CachedConnection.readBoundWarningDue(pooled, now + CachedConnection.STALL_WARNING_INTERVAL_MS), + "a connection carrying a bound it was never meant to keep was reported once and never again"); + } + /** * 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 f582e6ba66..53404b31bc 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 @@ -93,6 +93,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(); @@ -120,6 +123,13 @@ 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; + // and for the throttle the warning about a read bound that would not take is filed in: it is + // a static of that class, so a case reading it would otherwise be reading whatever the case + // before it left there + CachedConnection.lastReadBoundWarning.clear(); } private static JDBCStorage storageFor(String url) { @@ -408,6 +418,10 @@ public void testTheCatalogConnectTakesTheDefaultWhereNothingIsConfigured() throw * Both properties, which is what the pool itself says leaves a connect unbounded: the deadline of * the retry bounds the attempt where there is one, so turning the per-attempt bound off alone * leaves the attempt bounded by what is left of that deadline - the case above. + *

+ * The standing read bound is pinned along with them, the way this class pins the two properties: + * this connect reads {@link CachedConnection#READ_TIMEOUT_PROPERTY} as a pooled connect does, so + * a JVM started with a value of it would have "unbounded" mean the bound of that value here. */ @Test public void testTheCatalogConnectIsUnboundedWhereTheOperatorTurnedTheBoundOff() throws Exception { @@ -417,6 +431,7 @@ public void testTheCatalogConnectIsUnboundedWhereTheOperatorTurnedTheBoundOff() 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 = 0; try { probeDriver.lastProperties = null; final Connection con = storageFor(ProbeDriver.URL).newCatalogConnection(NO_REPLAY_WINDOW); @@ -476,14 +491,25 @@ public void testTheCatalogConnectReadsTheTwoBoundsTheWayRoundTheyAreWritten() th /** * What the connection is handed back for: rows of its own, committed where they are written. The - * read bound of the login is lifted as soon as the login is through (#872) - it is a bound of the + * read bound of the login is gone as soon as the login is through (#872) - it is a bound of the * connect and not of the statements of the catalog - and the isolation is the pool's, a repeatable * read gap-locking a catalog two transactions enrol into. + *

+ * The one {@code setNetworkTimeout} of this case is the standing read bound taking the place of + * the bound of the login, at the 0 of a deployment that configured none: what the connection + * carries afterwards is that value and not a lift followed by a second call. Pinned here for the + * same reason the two bounds of the connect are handed in (#932) - the value is read off {@link + * CachedConnection} on every connect, and a JVM started with {@link + * CachedConnection#READ_TIMEOUT_PROPERTY} set would put its own number in this call. */ @Test public void testTheCatalogConnectionIsSetUpForItsRows() throws Exception { // the read bound is lifted only where the attempt was given one, and the attempt takes the // shorter of the two bounds: a deadline of 0 leaves the per-attempt bound as the only one + // ... and the bound the connection carries afterwards is the standing one of #885, handed in + // here the way the other two are: a jvm started with the property set would otherwise put its + // own number in the call this case reads + CachedConnection.readTimeoutMillis = 0; final Connection con = storageFor(ProbeDriver.URL).newCatalogConnection(NO_REPLAY_WINDOW, DEFAULT_BOUND, 0); con.close(); verify(con).setAutoCommit(false); @@ -514,6 +540,129 @@ public void testTheCatalogConnectionIsKeptWhereTheReadBoundWillNotComeOff() thro verify(con, never()).close(); } + /** + * ... and the line an operator meets says which connection that was and what became of it. The + * establish of a connect is shared with the pool now (#929), and this is the whole of what is + * not: a connection of the pool that would not take the bound is closed rather than pooled, + * while this one is kept and carries the bound of its login for the rest of its life - an + * operator reading "closed rather than pooled" about the connection the catalog of this backend + * goes on using is being told the opposite of what happened. + *

+ * Read off the throttle the warning is filed in rather than off the logger: the line itself goes + * to a logger with a JVM-wide interval no test can wind back, while the key of the throttle is + * the consequence that was reported - which is the thing this case is about. + */ + @Test + public void testTheReadBoundWarningOfTheCatalogNamesTheConnectionAndWhatBecomesOfIt() 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; + final Connection keeping = mock(Connection.class); + doThrow(new SQLFeatureNotSupportedException("no network timeout here")) + .when(keeping).setNetworkTimeout(any(), anyInt()); + probeDriver.answer = keeping; + try { + storageFor(ProbeDriver.URL).newCatalogConnection(NO_REPLAY_WINDOW); + + final String reported = CachedConnection.readBoundConsequence(true, 30, + JDBCStorage.catalogConnectionNamed("catalogProbe"), JDBCStorage.CATALOG_CONNECTION_FATE); + assertTrue(CachedConnection.lastReadBoundWarning.containsKey(reported), + "the catalog connect reported the read bound it could not lift as something else: " + + CachedConnection.lastReadBoundWarning.keySet()); + assertTrue(reported.contains("catalogProbe") && reported.contains("kept"), + "the line names neither the backend whose catalog connection this is nor its fate: " + reported); + assertFalse(CachedConnection.lastReadBoundWarning.containsKey( + CachedConnection.readBoundConsequence(true, 30, CachedConnection.POOLED_CONNECTION, + CachedConnection.POOLED_CONNECTION_FATE)), + "the catalog connect reported the fate of a pooled connection, which is closed rather than kept"); + } finally { + restore(previous); + restorePool(previousPool); + } + } + + /** + * 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. diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/StampConnectionTestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/StampConnectionTestCase.java index 25c5c141a7..d14a81240b 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/StampConnectionTestCase.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/StampConnectionTestCase.java @@ -45,7 +45,9 @@ import java.util.concurrent.TimeUnit; import static org.forgerock.opendj.config.ConfigurationMock.mockCfg; +import static org.mockito.Mockito.doThrow; import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; import static org.testng.Assert.assertEquals; import static org.testng.Assert.assertNotSame; @@ -135,6 +137,32 @@ public void testStampConnectionHandsItsBoundsToTheDriver() throws Exception { } } + /** + * A stamp connection whose set-up failed belongs to nobody and is closed, and a driver that will + * not close is said so on the failure being unwound rather than swallowed - the rule the two + * roads of {@code CachedConnection.establish()} keep (#929), and this connection is established + * apart from them, with bounds of its own. + */ + @Test + public void testAStampConnectionWhoseSetUpFailsIsClosedAndSaysWhenItWillNotClose() throws Exception { + final Connection broken = mock(Connection.class); + doThrow(new SQLException("read only")).when(broken).setAutoCommit(false); + doThrow(new SQLException("will not close")).when(broken).close(); + probeDriver.answer = broken; + try { + storageFor(ProbeDriver.URL).newStampConnection(JDBCStorage.Dialect.POSTGRES); + fail("a stamp connection that cannot be set up must be reported"); + } catch (SQLException expected) { + assertEquals(expected.getMessage(), "read only"); + assertEquals(expected.getSuppressed().length, 1, + "the failure of the close is not carried on the failure being unwound"); + assertEquals(expected.getSuppressed()[0].getMessage(), "will not close"); + } finally { + probeDriver.answer = null; + } + verify(broken).close(); + } + /** * What the bounds are for: a database that keeps its established connections alive but accepts * no new ones - a moved vip, a proxy at its connection limit - usually completes the tcp @@ -316,12 +344,18 @@ private static final class ProbeDriver implements Driver { volatile Properties lastProperties; + /** The connection to answer with, for the one case about what is done with a connection; a fresh mock otherwise. */ + volatile Connection answer; + @Override public Connection connect(String url, Properties info) throws SQLException { if (!acceptsURL(url)) { return null; // not ours: DriverManager goes on to the next driver } lastProperties = info; + if (answer != null) { + return answer; + } final Connection con = mock(Connection.class); when(con.createStatement()).thenReturn(mock(Statement.class)); return con;