mirror of https://github.com/OpenIdentityPlatform/OpenDJ.git
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java
@@ -244,6 +244,16 @@ 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 @@ // 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<String, AtomicLong> 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. * <p> * 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. * <p> * 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<String, AtomicLong> lastReadBoundWarning = new ConcurrentHashMap<>(); /** * When an operation last reported that the database had dropped a connection of a pool, as a @@ -1500,7 +1527,15 @@ 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 @@ 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. * <p> * 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). * <p> * 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 @@ // 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,50 +1872,91 @@ * the deadline of the borrow instead, and a deployment running that way would otherwise set the * property here and get nothing for it. * <p> * 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. * <p> * 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. * <p> * 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. * <p> * 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). * <p> * 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 - * or it is not accepting connections yet, the state a database on its way up reports while it @@ -1965,6 +2098,11 @@ * 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. * <p> * 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 @@ : 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. * <p> * 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 @@ + (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 @@ 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 @@ 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 @@ 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 @@ } } /** * 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. * <p> * 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(); opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java
@@ -1629,9 +1629,10 @@ // 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 @@ * 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. * <p> * 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 @@ 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 @@ 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. * <p> * 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. * <p> * 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; } /** opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java
@@ -843,6 +843,9 @@ * 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. * <p> * 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<Throwable> seen = Collections.newSetFromMap(new IdentityHashMap<Throwable, Boolean>()); @@ -856,6 +859,9 @@ enqueue(pending, seen, ((SQLException) t).getNextException()); } enqueue(pending, seen, t.getCause()); for (final Throwable suppressed : t.getSuppressed()) { enqueue(pending, seen, suppressed); } } } @@ -936,6 +942,44 @@ } /** * 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 @@ "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. * <p> * 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 @@ 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 @@ 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 @@ 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(); } @@ -2293,6 +2354,58 @@ } /** * 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. * <p> * 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 * backend did before the property existed. A value past the ceiling of a socket read timeout is opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CatalogConnectionTestCase.java
@@ -93,6 +93,9 @@ 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 @@ 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 @@ * 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. * <p> * 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 @@ 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 @@ /** * 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. * <p> * 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); @@ -515,6 +541,129 @@ } /** * ... 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. * <p> * 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. * <p> * 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. */ 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; @@ -136,6 +138,32 @@ } /** * 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 * connect and then goes quiet, which leaves the driver in a read. Unbounded, that hangs the @@ -316,12 +344,18 @@ 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;
