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 188f7ba2fb..c111d34142 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 @@ -23,9 +23,21 @@ import java.sql.*; import java.time.Duration; +import java.util.ArrayDeque; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.Collections; +import java.util.Deque; +import java.util.HashSet; +import java.util.List; +import java.util.Locale; import java.util.Map; import java.util.Properties; +import java.util.Set; import java.util.concurrent.*; +import java.util.concurrent.atomic.AtomicLong; +import java.util.regex.Matcher; +import java.util.regex.Pattern; public class CachedConnection implements Connection { private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass(); @@ -33,11 +45,121 @@ public class CachedConnection implements Connection { static final String TTL_PROPERTY = "org.openidentityplatform.opendj.jdbc.ttl"; static final long DEFAULT_TTL_MS = 15000; + /** + * How long a pooled connection is handed out without being validated after it was last proven + * alive, in ms; 0 validates every borrow, the way this pool did before the window existed. + *

+ * The validation of a connection is a round trip of its own - an empty query on postgresql, a + * ping on mysql, a round trip of its own on oracle and sql server - and every operation of + * this backend pays it next to the single statement the operation came for. It earns that on a + * connection that has been sitting in the pool, which the database or a firewall may have + * dropped in the meantime; it earns nothing on one that answered a moment ago, which is most + * of them under load. So a connection proven alive within this window is trusted rather than + * validated, the way the aliveBypassWindow of HikariCP does it. + */ + static final String ALIVE_BYPASS_PROPERTY = "org.openidentityplatform.opendj.jdbc.alive.bypass"; + static final long DEFAULT_ALIVE_BYPASS_MS = 500; + + // Read once, at class initialization: every operation of this backend borrows a connection, + // and the borrow is not the place to parse a system property. Not final so that a test can + // vary the window without a class loader of its own, and volatile because a non-final static + // long is written neither atomically nor visibly to the threads reading it (JLS 17.7) - every + // worker of the backend and every replay thread reads this one. + static volatile long aliveBypassNanos = TimeUnit.MILLISECONDS.toNanos(getAliveBypassMillis()); + + /** + * Bounds the connect and the login of one attempt to establish a connection, in seconds; 0 for + * no bound of its own - the deadline of {@value #POOL_TIMEOUT_PROPERTY} still bounds the + * attempt, since it stands for the whole borrow. Setting both to 0 is what leaves a connect + * unbounded. + */ + static final String CONNECT_TIMEOUT_PROPERTY = "org.openidentityplatform.opendj.jdbc.connect.timeout"; + static final long DEFAULT_CONNECT_TIMEOUT_SECONDS = 30; + + /** + * Bounds a whole borrow - every connect attempt and every wait for a pooled connection - in + * seconds; 0 for no bound. Not to the millisecond: the connection in hand is validated + * whatever the deadline says, and an attempt is never given less than a second, so a borrow + * can return a validation and a last attempt past it. + */ + static final String POOL_TIMEOUT_PROPERTY = "org.openidentityplatform.opendj.jdbc.pool.timeout"; + static final long DEFAULT_POOL_TIMEOUT_SECONDS = 60; + + /** Bound of the validation of a pooled connection: isValid(0) means "no timeout" in the JDBC contract. */ + static final int VALIDATION_TIMEOUT_SECONDS = 5; + + /** 08001, sqlclient_unable_to_establish_sqlconnection: the state of a connect that did not happen. */ + private static final String CONNECT_FAILED_SQL_STATE = "08001"; + /** 53300, too_many_connections: how the standard - and postgresql - reports a server taking no further connection. */ + private static final String CONNECTION_LIMIT_SQL_STATE = "53300"; + /** 57P03, cannot_connect_now: postgresql starting up, shutting down or in recovery. */ + private static final String NOT_ACCEPTING_YET_SQL_STATE = "57P03"; + + static final long MAX_BACKOFF_MS = 1000; + static final long STALL_WARNING_AFTER_MS = 1000; + static final long STALL_WARNING_INTERVAL_MS = 10000; + + /** How many links of the cause and getNextException() chains of a failure are looked at. */ + private static final int MAX_CHAIN_LENGTH = 32; + + /** What a connection string is cut down to where this cannot tell its credentials from the rest of it. */ + static final String CREDENTIALS_HIDDEN = "

+ * What the window trades away is the connection that breaks inside it: it is handed out, and + * the failure surfaces on the statement of the caller rather than on the borrow. That is where + * a connection breaking mid-operation surfaces anyway - but not every caller of this backend + * reports such a failure to the client, so the trade is not the caller's alone to bear. + * {@code JDBCStorage} answers it on both sides: a write is replayed on a connection the next + * attempt borrows of its own, and a read as much as a write marks the pool distrusted, which + * closes the window for the rest of the generation the dropped connection belonged to. + */ + private static boolean isKnownAlive(CachedConnection con) { + final long window = aliveBypassNanos; + if (window <= 0) { + return false; + } + final long provenAt = con.lastKnownAliveNanos; + if (System.nanoTime() - provenAt >= window) { // the overflow safe form of the comparison + return false; + } + final Long distrusted = poolDistrustedAt.get(con.connectionString); + if (distrusted != null && provenAt - distrusted <= 0) { // the overflow safe form of the comparison + return false; + } + // What the validation this replaces also answered: the removalListener above closes every + // connection it finds in the deque when the pool expires, and it iterates a weakly + // consistent view, so a connection taken out by a borrow running at the same time can be + // closed under it. Answered by the driver out of a flag of its own, not by a round trip. + return !isClosed(con.parent); + } + + /** Whether the driver reports the connection as closed; one that cannot say is not one to trust. */ + private static boolean isClosed(Connection con) { + try { + return con.isClosed(); + } catch (SQLException e) { + return true; + } + } + + /** + * Reports that the database dropped a connection of this pool, so that no connection proven + * alive before now is handed out unvalidated again. It is called by the operation that saw the + * failure: this class only ever learns of one from the statement it broke, since a borrow + * inside the window asks the database nothing. + */ + static void distrustPool(String connectionString) { + // merge(max) rather than computeIfAbsent().set(): two operations reporting a drop at once + // would otherwise move the distrust point backwards - the later reading is written first + // and the earlier one overwrites it - and the AtomicLong of computeIfAbsent is published + // holding its initial 0 before set() runs, which a borrow racing it reads as "never". + poolDistrustedAt.merge(connectionString, System.nanoTime(), Math::max); + } + + /** + * Bounds the socket of a pooled connection for the length of its validation, returning the + * network timeout to put back afterwards - or {@link #VALIDATION_BOUND_LEFT_ALONE} for a + * connection left alone, either because the driver does not take a network timeout or because + * it is bounded at least as tightly already, by a read timeout of the connection string that + * is not ours to widen. + * A driver that takes the call and then fails inside it is told apart from both: it is free to + * have applied the bound before failing, and a connection put back into the pool carrying five + * seconds of ours fails every statement slower than that for the rest of its life. + */ + private static int boundValidation(Connection con) { + final int bound = VALIDATION_TIMEOUT_SECONDS * 1000; + final int previous; + try { + previous = con.getNetworkTimeout(); + } catch (SQLException | RuntimeException e) { // a driver that does not take one: nothing was changed + return VALIDATION_BOUND_LEFT_ALONE; + } + if (previous > 0 && previous <= bound) { + return VALIDATION_BOUND_LEFT_ALONE; } - Connection conNew = null; try { - conNew = DriverManager.getConnection(connectionString); + con.setNetworkTimeout(DIRECT_EXECUTOR, bound); + } catch (SQLException | RuntimeException e) { + return VALIDATION_BOUND_FAILED; + } + return previous; + } + + static CachedConnection connect(String connectionString, ConnectDialect dialect, long connectTimeoutSeconds) + 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 + && dialect.bound(connectionString, properties, connectTimeoutSeconds); + final Connection conNew = DriverManager.getConnection(connectionString, properties); + boolean poolable = true; + try { + // still under the read bound: both of these are round trips of their own conNew.setAutoCommit(false); conNew.setTransactionIsolation(TRANSACTION_READ_COMMITTED); - return new CachedConnection(connectionString, conNew); - } catch (SQLException e) { // max_connection server error: try recursion for reuse connection - if (conNew != null) { // the connection was established but not set up: nothing else would close it - try { - conNew.close(); - } catch (SQLException e2) {} + if (readBoundSet) { + // a driver that will not take the bound back has warned about it already: the + // connection serves the borrower that is waiting for it and is closed rather than + // pooled, so the bound of the login does not outlive it in the pool + poolable = relaxReadBound(conNew); + } + } catch (SQLException | RuntimeException e) { // nothing holds this connection yet: it would leak + closeQuietly(conNew); + throw e; + } + return new CachedConnection(connectionString, conNew, poolable); + } + + // The second bound of the login is a socket read timeout on mysql, oracle and sql server, in + // force for the whole life of the connection: left in place it would break every statement + // slower than it - an import batch, the statistics of a freshly loaded table - so it is lifted + // as soon as the login is through, restoring the behaviour of a connection this class + // established before. A read bound the connection string sets itself is never touched here: + // it is not set at all, so nothing of the administrator's is lifted along with it. Returns + // whether the bound is gone - a connection still carrying it must not be pooled. + private static boolean relaxReadBound(Connection con) { + return setNetworkTimeout(con, 0, "statements taking longer than the " + + CONNECT_TIMEOUT_PROPERTY + " property fail on it, and it is closed rather than pooled"); + } + + /** + * 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. + */ + 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)) { + logger.warn(LocalizableMessage.raw( + "The read bound of a JDBC connection could not be set to %d ms (%s): %s", + millis, e.getMessage(), consequence)); + } + return false; + } + } + + /** + * 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 + * recovers - the one JDBCStorage.open() has no second attempt of its own for, so a backend + * that meets it stays locked down until the server is restarted. Both clear themselves in + * seconds; every other failure is the caller's to see. + */ + static boolean isWorthRetrying(SQLException e, ConnectDialect dialect) { + // a failure of the driver is often wrapped, and a SQLException carries two chains of its + // own: the causes behind it and the further exceptions of getNextException() + final Deque pending = new ArrayDeque<>(); + pending.add(e); + for (int visited = 0; !pending.isEmpty() && visited < MAX_CHAIN_LENGTH; visited++) { + final Throwable t = pending.poll(); + if (t instanceof SQLException) { + final SQLException sql = (SQLException) t; + final String sqlState = sql.getSQLState(); + if (CONNECTION_LIMIT_SQL_STATE.equals(sqlState) || NOT_ACCEPTING_YET_SQL_STATE.equals(sqlState) + || (dialect != null && dialect.isWorthRetrying(sql.getErrorCode()))) { + return true; + } + if (sql.getNextException() != null) { + pending.add(sql.getNextException()); + } + } + if (t.getCause() != null) { + pending.add(t.getCause()); + } + } + return false; + } + + // A stall has to reach the server log: without it a database accepting no further connection + // is indistinguishable from a hang. Throttled, since every operation of the backend borrows + // through here and would otherwise log a copy of its own. + private static void warnStall(String connectionString, int attempts, long startedAt, SQLException cause) { + final long now = System.currentTimeMillis(); + if (now - startedAt < STALL_WARNING_AFTER_MS) { + return; + } + final AtomicLong lastOfThisUrl = lastStallWarning.computeIfAbsent(connectionString, url -> new AtomicLong()); + final long last = lastOfThisUrl.get(); + if (now - last >= STALL_WARNING_INTERVAL_MS && lastOfThisUrl.compareAndSet(last, now)) { + logger.warn(LocalizableMessage.raw("%s", stallMessage(connectionString, attempts, now - startedAt, cause))); + } + } + + /** + * The stall as it reaches the log. Built apart from the logging of it so that the rule it has + * to keep - neither the connection string nor the message of the driver reaches a log as it + * stands - is a rule a test can hold it to. + */ + static String stallMessage(String connectionString, int attempts, long waitedMs, SQLException cause) { + return String.format("%s takes no further connection: waiting %d ms for a pooled one so far (%d attempts)," + + " last error: %s", safeUrl(connectionString), waitedMs, attempts, + redact(cause.getMessage(), connectionString)); + } + + /** + * The failure of a connect as it may leave this class: the exception itself where nothing of it + * names the credentials of the backend, and a redacted rebuild of its whole chain where + * something does. Rebuilt rather than wrapped: a wrapper keeps its cause, and everything that + * prints a failure prints the causes along with it - a debug build of + * stackTraceToSingleLineString walks them, the config manager traces them, and + * 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. + */ + static SQLException reported(SQLException e, String connectionString) { + return holdsCredentials(e, connectionString) ? redactedSqlCopy(e, connectionString, 0) : e; + } + + /** The same of an unchecked failure: a driver is free to report a connect it will not make as one. */ + static Exception reportedUnchecked(RuntimeException e, String connectionString) { + if (!holdsCredentials(e, connectionString)) { + return e; + } + final SQLException redacted = new SQLNonTransientConnectionException(e.getClass().getName() + + (e.getMessage() == null ? "" : ": " + redact(e.getMessage(), connectionString)), + CONNECT_FAILED_SQL_STATE); + redacted.setStackTrace(e.getStackTrace()); + return redacted; + } + + /** Whether anything in the chain of a failure names what a connection string keeps out of the log. */ + private static boolean holdsCredentials(Throwable failure, String connectionString) { + final Deque pending = new ArrayDeque<>(); + pending.add(failure); + for (int visited = 0; !pending.isEmpty() && visited < MAX_CHAIN_LENGTH; visited++) { + final Throwable t = pending.poll(); + final String message = t.getMessage(); + if (message != null && !message.equals(redact(message, connectionString))) { + return true; + } + if (t instanceof SQLException && ((SQLException) t).getNextException() != null) { + pending.add(((SQLException) t).getNextException()); + } + if (t.getCause() != null) { + pending.add(t.getCause()); + } + } + return false; + } + + private static SQLException redactedSqlCopy(SQLException e, String connectionString, int depth) { + final SQLException copy = + new SQLException(redact(e.getMessage(), connectionString), e.getSQLState(), e.getErrorCode()); + copy.setStackTrace(e.getStackTrace()); + if (depth < MAX_CHAIN_LENGTH) { + if (e.getNextException() != null) { + copy.setNextException(redactedSqlCopy(e.getNextException(), connectionString, depth + 1)); + } + if (e.getCause() != null) { + copy.initCause(redactedCopy(e.getCause(), connectionString, depth + 1)); } - return getConnection(connectionString, (waitTime == 0) ? 1 : waitTime * 2); + } + return copy; + } + + // A link that is no SQLException keeps its class name in the message: its type is not one this + // can rebuild, and the name of the failure is what a reader of the log is after. + private static Throwable redactedCopy(Throwable t, String connectionString, int depth) { + if (t instanceof SQLException) { + return redactedSqlCopy((SQLException) t, connectionString, depth); + } + final Throwable copy = new Throwable(t.getClass().getName() + + (t.getMessage() == null ? "" : ": " + redact(t.getMessage(), connectionString))); + copy.setStackTrace(t.getStackTrace()); + if (t.getCause() != null && depth < MAX_CHAIN_LENGTH) { + copy.initCause(redactedCopy(t.getCause(), connectionString, depth + 1)); + } + return copy; + } + + /** + * A message of a driver as it may be logged. A driver is free to put the connection string it + * was handed into it - the jdk itself does, "No suitable driver found for " + url, which is + * what the ordinary oracle misconfiguration of a driver jar left out of lib/extensions arrives + * as - and that connection string is where the credentials of this backend live. + * What it cannot answer for is a driver quoting back a part of a url it failed to parse: + * a whole credential is replaced, a fragment of one is not. + */ + static String redact(String message, String connectionString) { + if (message == null || message.isEmpty()) { + return message; + } + String redacted = message.replace(connectionString, safeUrl(connectionString)); + for (final String secret : secretsOf(connectionString)) { + redacted = redacted.replace(secret, CREDENTIALS_HIDDEN); + } + return SECRET_PARAMETER.matcher(redacted).replaceAll("$1=***"); + } + + /** What of a connection string must not stand in a message: the credentials safeUrl() takes out of it. */ + private static List secretsOf(String connectionString) { + final List secrets = new ArrayList<>(); + final ConnectDialect dialect = ConnectDialect.of(connectionString); + final String separators = dialect == null ? "?;" : String.valueOf(dialect.parameterSeparator); + final int scheme = connectionString.indexOf(':', "jdbc:".length()) + 1; + if (scheme <= 0) { + return secrets; + } + final int authority = startOfAuthority(connectionString, scheme); + if (authority < 0) { + final int at = connectionString.indexOf('@', scheme); + if (at > scheme) { + addSecret(secrets, connectionString.substring(credentialsStart(connectionString, scheme, at), at)); + } + } else { + final int end = endOfAuthority(connectionString, authority, separators); + for (final String host : connectionString.substring(authority, end).split(",", -1)) { + final int at = host.lastIndexOf('@'); + if (at > 0) { + addSecret(secrets, host.substring(0, at)); + } + } + } + final Matcher parameter = SECRET_PARAMETER.matcher(connectionString); + while (parameter.find()) { + addSecret(secrets, parameter.group(3)); + } + return secrets; + } + + // The credentials of one host, and the password inside them without the user name in front of + // it: a driver quoting a url back names either. + private static void addSecret(List secrets, String credentials) { + if (credentials.isEmpty()) { + return; + } + secrets.add(credentials); + final int password = indexOfAny(credentials, ":/", 0); + if (password >= 0 && password + 1 < credentials.length()) { + secrets.add(credentials.substring(password + 1)); + } + } + + // The connection string carries the credentials of the backend - JDBCStorage hands the whole + // db-directory of the configuration to this class, so the url is the only place they live - + // and it is never logged as it stands. Three shapes hold them and all three are taken off: the + // "user/password@" in front of an oracle descriptor; the userinfo of an authority, one per + // host of it, since a url of Connector/J gives every host credentials of its own + // ("//u:p@h1:3306,u2:p2@h2:3306"); and the parameters behind their first separator, + // "?user=...&password=..." on postgresql, mysql and oracle, ";password=..." on sql server. + // What is left is looked over once more: the key-value host syntax of Connector/J puts a + // password inside the authority itself ("//address=(host=h)(user=u)(password=p)"), where + // neither of the first two shapes stands, so a "password=" of any case is blanked out wherever + // it is left standing. + // + // A password is free to hold either of the delimiters, so neither of them is looked for in the + // whole string. The credentials of an oracle url stand between the subprotocol and the first + // "@", which is the delimiter of its descriptor, so a "?" of one is part of the password + // rather than the start of the parameters. Everywhere else they stand inside the authority, + // between "//" and the path behind it, so a "?" of a password is inside them and an "@" of a + // parameter value ("?user=u@example.com") is not mistaken for the end of them: the host + // survives in the message either way. + // + // And a url none of this took apart is not logged past its subprotocol. An "@" left standing + // anywhere but where the credentials of an oracle url ended is one this did not recognize - a + // password holding a "/" inside an authority, a quoted one holding an "@" - and the host of a + // stall report is worth less than a password in the server log. + static String safeUrl(String connectionString) { + final ConnectDialect dialect = ConnectDialect.of(connectionString); + final String separators = dialect == null ? "?;" : String.valueOf(dialect.parameterSeparator); + final int scheme = connectionString.indexOf(':', "jdbc:".length()) + 1; // the end of "jdbc::" + if (scheme <= 0) { + return CREDENTIALS_HIDDEN; + } + final String stripped = stripCredentials(connectionString, scheme, separators); + final int parameters = indexOfAny(stripped, separators, scheme); + final String url = parameters < 0 ? stripped : stripped.substring(0, parameters); + final String redacted = SECRET_PARAMETER.matcher(url).replaceAll("$1=***"); + // an "@" standing anywhere but where the credentials of an oracle url ended is one this + // did not recognize - a password holding a "/" inside an authority, a quoted one holding + // an "@" - and the host of a stall report is worth less than a password in the server log + if (redacted.lastIndexOf('@') > endOfRecognizedCredentials(connectionString, scheme)) { + return redacted.substring(0, scheme) + CREDENTIALS_HIDDEN; + } + return parameters < 0 ? redacted + : redacted + identifyingParameters(stripped.substring(parameters), dialect); + } + + /** + * The parameters worth keeping in a message: the ones naming the database rather than whoever + * connects to it. Two backends of one host answer to the same url up to their parameters, and + * a stall report that cannot tell them apart is a stall report of neither. Everything else is + * dropped rather than looked at - a name this does not know is a name free to carry a secret. + */ + private static String identifyingParameters(String parameters, ConnectDialect dialect) { + final char separator = dialect == null ? ';' : dialect.parameterSeparator; + final StringBuilder kept = new StringBuilder(); + for (final String parameter : parameters.split("[?&;]")) { + final int equals = parameter.indexOf('='); + if (equals > 0 + && IDENTIFYING_PARAMETERS.contains(parameter.substring(0, equals).toLowerCase(Locale.ROOT))) { + kept.append(kept.length() == 0 || separator != '?' ? separator : '&').append(parameter); + } + } + return kept.toString(); + } + + private static String stripCredentials(String url, int scheme, String separators) { + final int authority = startOfAuthority(url, scheme); + if (authority < 0) { + // no authority: the credentials of an oracle url stand between the subprotocol and the + // first "@", which is the delimiter of the descriptor behind it - a password holding + // an "@" of its own has to be quoted for the driver itself + final int at = url.indexOf('@', scheme); + return at < 0 ? url : url.substring(0, credentialsStart(url, scheme, at)) + url.substring(at); + } + final int end = endOfAuthority(url, authority, separators); + return url.substring(0, authority) + withoutUserinfo(url.substring(authority, end)) + url.substring(end); + } + + /** + * Where the credentials of a url that names no authority start: behind the token naming the + * kind of driver, which stands in front of them ("jdbc:oracle:thin:user/pw@...") and is worth + * keeping - thin against oci is a first question of an oracle connect. The token is the one + * right behind the subprotocol rather than the last one in front of the "@", since a password + * is free to hold a ":" of its own. + */ + private static int credentialsStart(String url, int scheme, int at) { + final int driverType = url.indexOf(':', scheme); + return driverType >= 0 && driverType < at ? driverType + 1 : scheme; + } + + /** + * The last position a stripped url may still carry an "@" at: where the credentials of an + * oracle url ended, since the "@" is the delimiter of the descriptor behind them and stays. + * An authority keeps none of its own - every userinfo of it is taken off, delimiter included. + */ + private static int endOfRecognizedCredentials(String url, int scheme) { + final int at = url.indexOf('@', scheme); + return startOfAuthority(url, scheme) < 0 && at > scheme ? credentialsStart(url, scheme, at) : scheme; + } + + /** + * Where the hosts of a url of this shape start, or -1 for a url that names no authority. The + * subprotocol is free to name the kind of connection in front of it - "jdbc:mysql:replication://" + * - so the "//" is looked for rather than expected right behind the subprotocol. An "@" in + * front of it belongs to an oracle url ("jdbc:oracle:thin:user/pw@//host"), whose credentials + * stand where an authority has no place for them. + */ + private static int startOfAuthority(String url, int scheme) { + final int slashes = url.indexOf("//", scheme); + return slashes < 0 || url.lastIndexOf('@', slashes) >= scheme ? -1 : slashes + 2; + } + + /** + * Where the hosts of an authority end: at the path behind them - a password holds a "?" more + * readily than a "/" - or at the first parameter of a url that has no path. + */ + private static int endOfAuthority(String url, int authority, String separators) { + final int path = url.indexOf('/', authority); + if (path >= 0) { + return path; + } + final int parameter = indexOfAny(url, separators, authority); + return parameter < 0 ? url.length() : parameter; + } + + /** The hosts of an authority, each of them without the credentials a url may give it. */ + private static String withoutUserinfo(String authority) { + final StringBuilder hosts = new StringBuilder(); + final String[] split = authority.split(",", -1); + for (int i = 0; i < split.length; i++) { + if (i > 0) { // by the position rather than by what is in hand: a first host may be empty + hosts.append(','); + } + final int at = split[i].lastIndexOf('@'); + hosts.append(at < 0 ? split[i] : split[i].substring(at + 1)); + } + return hosts.toString(); + } + + private static int indexOfAny(String url, String separators, int from) { + int found = -1; + for (int i = 0; i < separators.length(); i++) { + final int at = url.indexOf(separators.charAt(i), from); + if (at >= 0 && (found < 0 || at < found)) { + found = at; + } + } + return found; + } + + private static void closeQuietly(Connection con) { + try { + con.close(); + } catch (SQLException e) { + // ignore: it is on its way out anyway } } @@ -153,8 +1295,21 @@ public void rollback() throws SQLException { @Override public void close() throws SQLException { - rollback(); - cached.get(connectionString).add(this); + try { + rollback(); + } catch (SQLException e) { + // A connection that cannot be rolled back must not be handed to the next borrower - + // and must not be dropped on the floor either: nothing else holds it any more. + closeQuietly(parent); + throw e; + } + if (!poolable) { + closeQuietly(parent); + return; + } + // Returned to the end the next borrow takes it from, so that the pool keeps reusing its + // hottest connections rather than cycling through every one it ever opened. + cached.get(connectionString).addFirst(this); } @Override 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 d1d8055314..390d66c9cf 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 @@ -69,7 +69,11 @@ public class JDBCStorage implements org.opends.server.backends.pluggable.spi.Sto /** Upper bound the doubled delay is capped at, in milliseconds. */ private static final double MAX_SLEEP_ON_RETRY_MS = 1000.0; - /** Number of {@link Throwable#getCause()} hops walked when classifying a failure, also a guard against a cycle. */ + /** + * Number of links walked when classifying a failure, also a guard against a chain long enough to matter. + * {@link #isRetryableConflict} walks the causes; {@link #isConnectionFailure} walks the causes, the next + * exceptions and the suppressed exceptions together, and counts them against the same number. + */ private static final int MAX_CAUSE_HOPS = 16; /** SQL Server error number of the transaction picked as the deadlock victim: "Rerun the transaction". */ @@ -90,6 +94,21 @@ public class JDBCStorage implements org.opends.server.backends.pluggable.spi.Sto private static final Set NON_REPLAYABLE_ROLLBACK_STATES = Collections.unmodifiableSet(new HashSet<>(Arrays.asList("40002", "40003"))); + /** SQLState class 08, connection exception: the connection is gone, whatever the statement asked for. */ + private static final String CONNECTION_FAILURE_CLASS = "08"; + + /** + * The states outside class 08 that also say the connection is gone rather than the statement wrong. PostgreSQL + * announces the connection it is about to drop as 57P01 (admin_shutdown - a pg_terminate_backend of an idle + * connection reaper, or a shutdown of the server), 57P02 (crash_shutdown) or 57P03 (cannot_connect_now), and + * only the next use of that connection is reported as class 08. They are the states of the list HikariCP + * evicts a connection on that a driver of this backend reports: of the rest, JZ0C0 and JZ0C1 belong to a Sybase + * driver this backend is not used with, 01002 is a disconnect none of these four drivers reports, and 0A000 is + * the standard "feature not supported", which says nothing about the connection at all. + */ + private static final Set CONNECTION_FAILURE_STATES = + Collections.unmodifiableSet(new HashSet<>(Arrays.asList("57P01", "57P02", "57P03"))); + private JDBCBackendCfg config; public JDBCStorage(JDBCBackendCfg cfg, ServerContext serverContext) { @@ -143,11 +162,23 @@ Connection getConnection() throws Exception { return CachedConnection.getConnection(config.getDBDirectory()); } + /** + * Borrows a connection the pool validates whatever the alive window of + * {@link CachedConnection#ALIVE_BYPASS_PROPERTY} says, for the borrows this class compensates a dropped + * connection on in no other way: {@link #open(AccessMode)}, {@link #removeStorageFiles()} and the importer + * issue their statements far from the borrow, and the open issues none at all, so a connection dropped inside + * the window would surface out of the rollback that releases it. One round trip on a path taken once per open, + * per import or per removal buys back exactly what master did on every borrow. + */ + Connection getValidatedConnection() throws Exception { + return CachedConnection.getConnection(config.getDBDirectory(), false); + } + AccessMode accessMode=AccessMode.READ_ONLY; @Override public void open(AccessMode accessMode) throws Exception { - try (final Connection con=getConnection()) { + try (final Connection con=getValidatedConnection()) { this.accessMode = accessMode; storageStatus = StorageStatus.working(); } @@ -781,7 +812,7 @@ public void removeStorageFiles() throws StorageRuntimeException { } final Set trees=listTrees(); if (!trees.isEmpty()) { - try (final Connection con = getConnection()) { + try (final Connection con = getValidatedConnection()) { try { for (final TreeName treeName : trees) { try (final PreparedStatement statement = con.prepareStatement("drop table " + getTableName(treeName))) { @@ -821,11 +852,36 @@ public void removeStorageFiles() throws StorageRuntimeException { * counters in instance fields that no attempt resets, so a replay reports twice the entry count of the backend. * Both are reachable while the server is online, since an export holds no more than a shared backend lock. * A conflict therefore fails the read here, exactly as it did before the retry of {@link #write} was added. + *

+ * A connection the database dropped is not replayed either, for the same reason - but it is reported to the + * pool, which cannot notice one on its own: a borrow inside the alive window of + * {@link CachedConnection#ALIVE_BYPASS_PROPERTY} asks the database nothing, so the statement that broke is the + * only place the drop is ever seen. */ @Override public T read(ReadOperation readOperation) throws Exception { - try(final Connection con=getConnection()) { - return readOperation.run(new ReadableTransactionImpl(con)); + //borrowed outside the try: a connect the pool could not make says nothing about the connections it + //holds - mysql reports a server at its connection limit as 08004, which is class 08 like a connection + //that broke - and distrusting the pool over it would validate every borrow under the very load the + //window exists for, against a server already refusing connections + final Connection con=getConnection(); + boolean dropped=false; + try (con) { + try { + return readOperation.run(new ReadableTransactionImpl(con)); + } catch (Exception e) { + //asked while this read still owns the connection: once the release below has returned it to + //the pool, another borrow may hold it and the driver would be answering about that one + dropped=isConnectionFailure(e,con); + throw e; + } + } catch (Exception e) { + //also the release of the connection: its rollback is the one round trip a read that found + //nothing makes, so it can be the only place a drop is ever seen + if (dropped||isConnectionFailure(e)) { + distrustPool(); + } + throw e; } } @@ -846,6 +902,13 @@ public T read(ReadOperation readOperation) throws Exception { * Only the operation itself is replayed: a failure of {@link #getConnection()} or of the implicit * {@link Connection#close()} - which returns the connection to the pool after a rollback - leaves the loop, so * that a completed write is never replayed because releasing its connection failed. + *

+ * A connection the database dropped is replayed as well, on a connection the next attempt borrows of its own. + * That is what makes the alive window of {@link CachedConnection#ALIVE_BYPASS_PROPERTY} safe to leave on: a + * connection handed out unvalidated and found dead costs an attempt rather than the operation, and a write of + * the replication replay - which records a failed operation as applied and advances the server state past it, + * see #889 - never sees it. Only while nothing of the attempt may have been committed yet, though: see + * {@link #replayReason(Throwable, String, boolean, boolean, boolean)}. */ @Override public void write(WriteOperation writeOperation) throws Exception { @@ -853,42 +916,66 @@ public void write(WriteOperation writeOperation) throws Exception { for (int attempt=1;;attempt++) { Exception failure=null; String driver=null; - try (final Connection con=getConnection()) { + boolean committing=false; + boolean dropped=false; + boolean partlyCommitted=false; + //borrowed outside the try, for the reason read() borrows outside it: a connect the pool could not + //make is not a connection of this pool that broke, and it leaves the loop as it always did + final Connection con=getConnection(); + try (con) { driver=driverNameOf(con); final WriteableTransactionTransactionImpl txn=new WriteableTransactionTransactionImpl(con); try { writeOperation.run(txn); + committing=true; con.commit(); return; } catch (Exception e) { try { con.rollback(); } catch (SQLException ex) {} + //asked while this attempt still owns the connection: the release below returns it to the + //pool, and the driver would then be answering about whichever borrow holds it next + dropped=isConnectionFailure(e,con); //rethrown, so that a failure of the implicit close() is suppressed into the failure being //replayed rather than replacing it failure=e; throw e; } finally { // the comment connection lives no longer than the trees it stamped, and no longer // than the attempt that opened it: a replay stamps on a session of its own + partlyCommitted=txn.partlyCommitted; txn.stampSession.close(); } } catch (Exception e) { - //anything the operation did not throw comes from getConnection() or from the implicit close(), - //which returns the connection to the pool: neither belongs to the replayed region + //anything the operation did not throw comes from around it - the name of the driver, the + //transaction, or the implicit close() that returns the connection to the pool: none of them + //belongs to the replayed region if (e!=failure) { + //a drop reported by the release of the connection still has to reach the pool, which has no + //other way of hearing of it. Only the chains of the failure can be asked for it now: the + //connection has been released, and whether it is closed is no longer this attempt's answer + if (isConnectionFailure(e)) { + distrustPool(); + } throw e; } } + //whatever the loop decides, the pool has to hear of a connection the database dropped: it holds the + //rest of that generation, and inside the alive window it would hand them out unvalidated as well + if (dropped) { + distrustPool(); + } + final String reason=replayReason(failure,driver,committing,partlyCommitted,dropped); //System.nanoTime()-giveUpAt is the overflow safe form of the comparison - if (attempt>=MAX_RETRIES || System.nanoTime()-giveUpAt>=0 || !isRetryableConflict(failure,driver)) { + if (reason==null || attempt>=MAX_RETRIES || System.nanoTime()-giveUpAt>=0) { throw failure; } //logged rather than silently absorbed, so that a deployment retrying most of its writes stays observable; //one line per replay, since an add can emit nine of them and a stack trace each time reads as a failure - logger.warn(LocalizableMessage.raw("jdbc: replaying the transaction after a conflict, attempt %d of %d: %s", - attempt, MAX_RETRIES, conflictSummary(failure))); + logger.warn(LocalizableMessage.raw("jdbc: replaying the transaction after %s, attempt %d of %d: %s", + reason, attempt, MAX_RETRIES, conflictSummary(failure))); if (logger.isTraceEnabled()) { - logger.trace("jdbc: the conflict being replayed was %s", stackTraceToSingleLineString(failure)); + logger.trace("jdbc: the failure being replayed was %s", stackTraceToSingleLineString(failure)); } try { //randomized to spread the retries of the transactions that collided, growing to outlast contention @@ -903,6 +990,138 @@ public void write(WriteOperation writeOperation) throws Exception { } } + /** + * Why the operation of a {@link #write} is worth replaying, as the noun phrase the message reporting the replay + * names - or null for a failure this loop must not repeat. + *

+ * A transaction conflict is replayable whichever phase reported it: the engine rolled the transaction back + * before it answered. A connection the database dropped is replayable only while the transaction had not been + * committed yet. A drop reported by {@code commit()} leaves the outcome unknown - the server may have committed + * and died before the answer reached us - and replaying a write that in fact committed applies it twice, which + * is the very reason 40003 is kept out of {@link #NON_REPLAYABLE_ROLLBACK_STATES}. + *

+ * Nothing is replayable once the attempt has committed part of its own work, whatever the failure says. The DDL + * of {@link WriteableTransactionTransactionImpl#openTree} and {@link WriteableTransactionTransactionImpl#deleteTree} + * commits inside {@link WriteOperation#run}, and mysql and oracle commit before a DDL statement whether asked + * to or not, so the attempt no longer rolls back as a whole - and {@link WriteOperation} is only idempotent in + * the database. {@code RootContainer.open} opens and registers every entry container of every base DN in one + * write: replayed after the trees of the first base DN were created and committed, it registers that base DN a + * second time and fails with ERR_ENTRY_CONTAINER_ALREADY_REGISTERED, which masks the failure that caused the + * replay and leaves the indexes of the previous attempt behind with their configuration listeners. + * + * @param committing whether the failure was reported by {@code commit()}, which leaves the outcome unknown + * @param partlyCommitted whether the attempt committed part of its work before it failed + * @param connectionClosed whether the driver closed the connection under the failure - evidence no SQLState + * carries on mssql-jdbc, which reports a killed session as S0001 and closes the connection behind it + */ + static String replayReason(Throwable failure, String driver, boolean committing, boolean partlyCommitted, + boolean connectionClosed) { + if (partlyCommitted) { + return null; + } + if (isRetryableConflict(failure, driver)) { + return "a conflict"; + } + if (!committing && (connectionClosed || isConnectionFailure(failure))) { + return "a connection the database dropped"; + } + return null; + } + + /** + * Whether a failure says the connection is gone rather than the statement rejected, asked of the failure and of + * the connection it was raised on. A driver is not required to say so in a SQLState: mssql-jdbc reports a + * session killed by {@code KILL}, by the resource governor or by an availability group transition as error 596, + * 3980, 10054, 18456 or 4060, and {@code generateStateCode} maps none of them - with xopenStates off, which is + * its default, every one of them comes out as {@code "S"+errorState}, measured as S0001. What the driver does + * do is close the connection for any error of severity 20 and above, before it throws. + *

+ * Asked only while the operation that failed still owns the connection: a released one is back in the pool and + * may already have been handed to another borrow, whose state it would then be answering about. + */ + static boolean isConnectionFailure(Throwable failure, Connection con) { + return isConnectionFailure(failure) || isClosed(con); + } + + /** Whether the driver reports the connection as closed; one that cannot answer is taken as closed. */ + private static boolean isClosed(Connection con) { + try { + return con.isClosed(); + } catch (SQLException e) { + return true; + } + } + + /** + * Whether a failure says the connection is gone rather than the statement rejected: the database dropped it, + * restarted, failed over, or the network did. + *

+ * Both chains of the failure are walked, for the reason {@link #failureScope} walks both: a driver reports the + * error that says what happened as the next exception of a generic one at least as often as it reports it as + * the cause, and mssql-jdbc chains every error of a message it received that way. The suppressed exceptions are + * walked with them, since the rollback and the release of a connection report a drop there - a write whose + * operation failed for its own reasons carries the drop of its {@code close()} as a suppressed exception (JLS + * 14.20.3.1) rather than as a cause. The walk starts at the failure this class was handed because it reaches it + * wrapped in a {@link StorageRuntimeException}, and a caller such as {@code EntryContainer.addEntry} may wrap + * it once more. + */ + static boolean isConnectionFailure(Throwable failure) { + final Deque pending=new ArrayDeque<>(); + final Set seen=Collections.newSetFromMap(new IdentityHashMap()); + if (failure!=null) { + pending.push(failure); + } + while (!pending.isEmpty() && seen.size() borrow = new FutureTask<>(() -> CachedConnection.getConnection(url)); + final Thread thread = new Thread(borrow, "borrow-" + CachedConnection.safeUrl(url)); + thread.setDaemon(true); + thread.start(); + try { + final Connection con = borrow.get(BOUND_SECONDS * 1000 + BOUND_MARGIN_MS, TimeUnit.MILLISECONDS); + fail("a database that never answers must not hand out a connection: " + con); + } catch (TimeoutException e) { + fail("the login of " + CachedConnection.safeUrl(url) + " is not bounded: it never gave up"); + } catch (ExecutionException expected) { + assertTrue(expected.getCause() instanceof SQLException, String.valueOf(expected.getCause())); + } + } + } + } + + /** + * The deadline of the borrow bounds the attempt inside it as well: the pool timeout stands for + * the whole borrow, and an attempt left to run out its own bound would overrun it by that bound. + */ + @Test(timeOut = 120000) + public void testTheAttemptIsBoundedByTheDeadlineOfTheBorrow() throws Exception { + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, "600"); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "2"); + try (final ServerSocket blackhole = new ServerSocket(0, 50, InetAddress.getLoopbackAddress())) { + final String url = "jdbc:postgresql://127.0.0.1:" + blackhole.getLocalPort() + "/opendj?user=opendj&password=opendj"; + final long startedAt = System.currentTimeMillis(); + try { + CachedConnection.getConnection(url); + fail("a database that never answers must not hand out a connection"); + } catch (SQLException expected) { + // reported, and within the borrow it was given rather than the 600 s of the attempt + } + final long elapsed = System.currentTimeMillis() - startedAt; + assertTrue(elapsed < 30000, "the attempt outlived the deadline of the borrow: " + elapsed + " ms"); + } + } + + /** Pool exhaustion stays a retry - one of our own connections is on its way back to the pool. */ + @Test(timeOut = 120000) + public void testConnectionLimitIsRetried() throws Exception { + final String url = StubDriver.PREFIX + "retried"; + stub.failWith(tooManyConnections(), 2); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "30"); + + final Connection con = CachedConnection.getConnection(url); + + assertNotNull(con); + assertEquals(stub.attempts.get(), 3, "the connect must be retried while the database is at its limit"); + } + + /** ... but under a deadline: the retry used to double its wait from 1 ms with no end to it. */ + @Test(timeOut = 120000) + public void testConnectionLimitGivesUpAtTheDeadline() throws Exception { + final String url = StubDriver.PREFIX + "deadline"; + stub.failWith(tooManyConnections(), StubDriver.ALWAYS); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "2"); + + final long startedAt = System.currentTimeMillis(); + try { + CachedConnection.getConnection(url); + fail("a database that stays at its connection limit must be reported, not waited out forever"); + } catch (SQLTimeoutException expected) { + assertTrue(expected.getMessage().contains("2s"), expected.getMessage()); + assertEquals(((SQLException) expected.getCause()).getSQLState(), "53300"); + // the state of a connect that did not happen, rather than none at all: this is the + // failure of a borrow, and monitoring reading the state off what it caught would + // otherwise see null where the driver's own exception carried one + assertEquals(expected.getSQLState(), "08001"); + } + final long elapsed = System.currentTimeMillis() - startedAt; + assertTrue(elapsed >= 2000, "gave up after " + elapsed + " ms, before the deadline it was given"); + assertElapsedWithinBound(startedAt, 2000); + assertTrue(stub.attempts.get() > 1, "the connect must be retried while the deadline lasts"); + } + + /** + * A database on its way up - starting, recovering, shutting down - says so, and says it for + * seconds: the backend it belongs to would otherwise stay locked down until the next restart + * of the server, since nothing above JDBCStorage.open() attempts it a second time. + */ + @Test(timeOut = 120000) + public void testDatabaseOnItsWayUpIsRetried() throws Exception { + final String url = StubDriver.PREFIX + "starting-up"; + stub.failWith(new SQLException("the database system is starting up", "57P03"), 2); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "30"); + + final Connection con = CachedConnection.getConnection(url); + + assertNotNull(con); + assertEquals(stub.attempts.get(), 3, "a database that is starting up must be waited out"); + } + + /** ... and it is recognized however the driver wrapped it: a SQLException carries two chains. */ + @Test(timeOut = 120000) + public void testTheWholeChainOfTheFailureIsLookedAt() throws Exception { + final String url = StubDriver.PREFIX + "wrapped"; + final SQLException wrapped = new SQLException("could not connect to the server", "08006"); + wrapped.setNextException(tooManyConnections()); + stub.failWith(wrapped, 1); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "30"); + + assertNotNull(CachedConnection.getConnection(url)); + assertEquals(stub.attempts.get(), 2, "the failure behind the one reported must be looked at"); + } + + /** + * The rest of the insufficient_resources class is not worth waiting out: a server out of disk + * is not made whole by a connection of ours coming back to the pool. + */ + @Test(timeOut = 120000) + public void testDiskFullIsNotRetried() throws Exception { + final String url = StubDriver.PREFIX + "disk-full"; + stub.failWith(new SQLException("could not extend file: No space left on device", "53100"), StubDriver.ALWAYS); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "30"); + + try { + CachedConnection.getConnection(url); + fail("a database out of disk must be reported to the caller"); + } catch (SQLException expected) { + assertEquals(expected.getSQLState(), "53100"); + } + assertEquals(stub.attempts.get(), 1, "a failure that waiting cannot clear must be attempted once"); + } + + /** + * Every other failure is the caller's to report. A password the database does not accept is + * never going to be accepted by waiting, and the retry that swallowed it left the operation + * hanging with nothing in the log. + */ + @Test(timeOut = 120000) + public void testRejectedLoginIsNotRetried() throws Exception { + final String url = StubDriver.PREFIX + "rejected"; + stub.failWith(new SQLException("password authentication failed", "28P01"), StubDriver.ALWAYS); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "30"); + + try { + CachedConnection.getConnection(url); + fail("a rejected login must be reported to the caller"); + } catch (SQLException expected) { + assertEquals(expected.getSQLState(), "28P01"); + } + assertEquals(stub.attempts.get(), 1, "a rejected login must be attempted once"); + } + + /** A connection the setup of which failed belongs to nobody: it has to be closed, not leaked. */ + @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); + stub.answerWith(broken); + + try { + CachedConnection.getConnection(url); + fail("a connection that cannot be set up must be reported"); + } catch (SQLException expected) { + assertEquals(expected.getMessage(), "read only"); + } + verify(broken).close(); + } + + /** The same, for a driver whose failure in the setup is not a SQLException but an unchecked one. */ + @Test(timeOut = 120000) + public void testConnectionIsClosedWhenItsSetupFailsWithAnUncheckedError() throws Exception { + final String url = StubDriver.PREFIX + "setup-unchecked"; + final Connection broken = mock(Connection.class); + doThrow(new IllegalStateException("driver internal")).when(broken).setTransactionIsolation(anyInt()); + stub.answerWith(broken); + + try { + CachedConnection.getConnection(url); + fail("a connection that cannot be set up must be reported"); + } catch (IllegalStateException expected) { + assertEquals(expected.getMessage(), "driver internal"); + } + verify(broken).close(); + } + + /** + * isValid(n) is not a bound at the socket on every driver - the SQL Server driver turns it + * into a query timeout, which needs an answer from the server to fire - and the read bound of + * the login was lifted the moment the connection was established, so the socket carries the + * bound of the validation, for the length of the validation only. + */ + @Test(timeOut = 120000) + public void testValidationOfAPooledConnectionIsBoundedAtTheSocket() throws Exception { + final String url = StubDriver.PREFIX + "validation-bound"; + final Connection pooled = mock(Connection.class); + when(pooled.isValid(anyInt())).thenReturn(true); + when(pooled.getNetworkTimeout()).thenReturn(0); + seedPool(url, pooled); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, pooled); + final InOrder inOrder = inOrder(pooled); + inOrder.verify(pooled).setNetworkTimeout(any(Executor.class), eq(CachedConnection.VALIDATION_TIMEOUT_SECONDS * 1000)); + inOrder.verify(pooled).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + inOrder.verify(pooled).setNetworkTimeout(any(Executor.class), eq(0)); + } + + /** + * A driver that takes the call bounding the validation and then fails inside it is told apart + * from one that never takes a network timeout at all: it is free to have applied the bound + * before failing, so the connection is discarded rather than validated unbounded and handed + * out - pooled, it would carry five seconds of ours into every statement for the rest of its + * life, and the import batch of a backend open is the first thing to die of that. + */ + @Test(timeOut = 120000) + public void testAPooledConnectionThatCannotBeBoundedForItsValidationIsDiscarded() throws Exception { + final String url = StubDriver.PREFIX + "validation-bound-fails"; + final Connection pooled = mock(Connection.class); + when(pooled.getNetworkTimeout()).thenReturn(0); + when(pooled.isValid(anyInt())).thenReturn(true); + doThrow(new SQLException("the driver took the bound and then failed")) + .when(pooled).setNetworkTimeout(any(Executor.class), anyInt()); + seedPool(url, pooled); + final Connection fresh = mock(Connection.class); + stub.answerWith(fresh); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, fresh, "a connection this could not bound was handed out"); + verify(pooled, never()).isValid(anyInt()); + verify(pooled).close(); + } + + /** A read bound of the connection string is tighter than ours and stays untouched. */ + @Test(timeOut = 120000) + public void testValidationLeavesTheBoundOfTheConnectionStringAlone() throws Exception { + final String url = StubDriver.PREFIX + "validation-tighter"; + final Connection pooled = mock(Connection.class); + when(pooled.isValid(anyInt())).thenReturn(true); + when(pooled.getNetworkTimeout()).thenReturn(2000); + seedPool(url, pooled); + + assertNotNull(CachedConnection.getConnection(url)); + + verify(pooled, never()).setNetworkTimeout(any(Executor.class), anyInt()); + } + + /** + * The pool has no upper bound on the number of connections it holds, and a validation is a + * round trip: after a failover that left them half-open, draining the pool must not outlive + * the deadline of the borrow - establishing a connection is the faster answer past it. + */ + @Test(timeOut = 120000) + public void testDrainOfThePoolStopsAtTheDeadline() throws Exception { + final String url = StubDriver.PREFIX + "drain-deadline"; + final int pooled = 8; + final AtomicInteger validated = new AtomicInteger(); + for (int i = 0; i < pooled; i++) { + final Connection stale = mock(Connection.class); + when(stale.isValid(anyInt())).thenAnswer(invocation -> { + validated.incrementAndGet(); + Thread.sleep(500); // a database that no longer answers: every validation waits out its bound + return false; + }); + seedPool(url, stale); + } + final Connection fresh = mock(Connection.class); + stub.answerWith(fresh); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "1"); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, fresh); + assertTrue(validated.get() > 0 && validated.get() < pooled, + "the drain has to start and to stop at the deadline: " + validated.get() + " of " + pooled); + } + + /** A pooled connection that no longer validates is closed and replaced, not handed out. */ + @Test(timeOut = 120000) + public void testBrokenPooledConnectionIsDiscarded() throws Exception { + final String url = StubDriver.PREFIX + "broken-pooled"; + final Connection stale = mock(Connection.class); + when(stale.isValid(anyInt())).thenReturn(false); + seedPool(url, stale); + final Connection fresh = mock(Connection.class); + when(fresh.isValid(anyInt())).thenReturn(true); + stub.answerWith(fresh); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, fresh); + verify(stale).close(); + // the validation of a pooled connection needs a bound of its own as well + verify(stale, never()).isValid(0); + verify(stale).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + + /** + * The same for a driver whose answer to the validation is an unchecked failure: it unwinds + * through poll(), which stands outside every try of the borrow, so the connection it was + * raised over is already out of the pool and would be held by nobody. + */ + @Test(timeOut = 120000) + public void testAPooledConnectionWhoseValidationThrowsIsDiscarded() throws Exception { + final String url = StubDriver.PREFIX + "validation-unchecked"; + final Connection broken = mock(Connection.class); + when(broken.isValid(anyInt())).thenThrow(new IllegalStateException("driver internal")); + seedPool(url, broken); + final Connection fresh = mock(Connection.class); + stub.answerWith(fresh); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, fresh); + verify(broken).close(); + } + + /** A connection that cannot be rolled back must not go back into the pool - nor be dropped. */ + @Test(timeOut = 120000) + public void testConnectionThatCannotBeRolledBackIsClosed() throws Exception { + final String url = StubDriver.PREFIX + "rollback-failure"; + final Connection parent = mock(Connection.class); + doThrow(new SQLException("connection is closed")).when(parent).rollback(); + + try { + new CachedConnection(url, parent).close(); + fail("a failed rollback must be reported"); + } catch (SQLException expected) { + assertEquals(expected.getMessage(), "connection is closed"); + } + verify(parent).close(); + assertTrue(CachedConnection.cached.get(url).isEmpty(), "a connection that cannot be rolled back was pooled"); + } + + @Test + public void testDialectIsRecognizedByTheConnectionString() throws Exception { + assertEquals(CachedConnection.ConnectDialect.of("jdbc:postgresql://h:5432/db"), CachedConnection.ConnectDialect.POSTGRES); + assertEquals(CachedConnection.ConnectDialect.of("jdbc:mysql://h:3306/db"), CachedConnection.ConnectDialect.MYSQL); + assertEquals(CachedConnection.ConnectDialect.of("jdbc:oracle:thin:@//h:1521/svc"), CachedConnection.ConnectDialect.ORACLE); + assertEquals(CachedConnection.ConnectDialect.of("jdbc:sqlserver://h:1433;databaseName=db"), CachedConnection.ConnectDialect.MICROSOFT); + assertNull(CachedConnection.ConnectDialect.of("jdbc:h2:mem:db"), "an unknown engine must not be fed the properties of another"); + } + + /** Both phases are bounded, in the units of the driver: the connect alone leaves the login open. */ + @Test + public void testBothPhasesOfTheLoginAreBounded() throws Exception { + // pgjdbc puts an SO_TIMEOUT on the login socket only where socketTimeout is set: without it + // loginTimeout bounds the caller alone, and the thread the driver runs the login on stays + // parked in the read it abandoned + final Properties postgres = new Properties(); + assertTrue(CachedConnection.ConnectDialect.POSTGRES.bound("jdbc:postgresql://h:5432/db", postgres, 7), + "the read bound of postgresql outlives the login and has to be lifted"); + assertEquals(postgres.getProperty("connectTimeout"), "7"); + assertEquals(postgres.getProperty("socketTimeout"), "7"); + assertEquals(postgres.getProperty("loginTimeout"), "7", "the bound of a url naming more than one host"); + + final Properties mysql = new Properties(); + assertTrue(CachedConnection.ConnectDialect.MYSQL.bound("jdbc:mysql://h:3306/db", mysql, 7), + "the read bound of mysql outlives the login and has to be lifted"); + assertEquals(mysql.getProperty("connectTimeout"), "7000"); + assertEquals(mysql.getProperty("socketTimeout"), "7000"); + + final Properties oracle = new Properties(); + assertTrue(CachedConnection.ConnectDialect.ORACLE.bound("jdbc:oracle:thin:@//h:1521/svc", oracle, 7)); + assertEquals(oracle.getProperty("oracle.net.CONNECT_TIMEOUT"), "7000"); + assertEquals(oracle.getProperty("oracle.jdbc.ReadTimeout"), "7000"); + + // the loginTimeout of the sql server driver leaves the read of the prelogin answer open + final Properties microsoft = new Properties(); + assertTrue(CachedConnection.ConnectDialect.MICROSOFT.bound("jdbc:sqlserver://h:1433;databaseName=db", microsoft, 7)); + assertEquals(microsoft.getProperty("loginTimeout"), "7"); + assertEquals(microsoft.getProperty("socketTimeout"), "7000"); + } + + /** + * A driver with a range of its own for its connect property is never handed a value beyond it: + * SQLServerDriverIntProperty.LOGIN_TIMEOUT is validated against [0, 65535], so a bound past + * that would not widen the connect, it would fail every one of them. + */ + @Test + public void testConnectBoundStaysInTheRangeTheDriverTakes() throws Exception { + final Properties microsoft = new Properties(); + CachedConnection.ConnectDialect.MICROSOFT.bound("jdbc:sqlserver://h:1433;databaseName=db", microsoft, 100000); + assertEquals(microsoft.getProperty("loginTimeout"), "65535"); + assertEquals(microsoft.getProperty("socketTimeout"), "100000000", "the read bound takes any value"); + } + + /** + * A bound the administrator put into the connection string by hand - the only workaround this + * backend had - keeps precedence, property by property. + */ + @Test + public void testConnectionStringKeepsPrecedence() throws Exception { + final Properties postgres = new Properties(); + CachedConnection.ConnectDialect.POSTGRES.bound( + "jdbc:postgresql://h:5432/db?user=u&password=p&loginTimeout=30&socketTimeout=300", postgres, 7); + assertNull(postgres.getProperty("loginTimeout"), "the setting of the connection string was overridden"); + assertNull(postgres.getProperty("socketTimeout"), "the setting of the connection string was overridden"); + assertNull(postgres.getProperty("connectTimeout"), + "the connect side is one budget: a bound of the administrator under either of its names is theirs"); + + // the sql server driver gives a supplied property precedence over the one of the url + final Properties microsoft = new Properties(); + CachedConnection.ConnectDialect.MICROSOFT.bound("jdbc:sqlserver://h:1433;loginTimeout=45;databaseName=db", microsoft, 7); + assertNull(microsoft.getProperty("loginTimeout"), "the setting of the connection string was overridden"); + assertEquals(microsoft.getProperty("socketTimeout"), "7000"); + + // inside the descriptor of an oracle tns url the property goes by the last segment of its name + final Properties oracle = new Properties(); + CachedConnection.ConnectDialect.ORACLE.bound( + "jdbc:oracle:thin:@(DESCRIPTION=(CONNECT_TIMEOUT=3)(ADDRESS=(HOST=h)(PORT=1521)))", oracle, 7); + assertNull(oracle.getProperty("oracle.net.CONNECT_TIMEOUT")); + assertEquals(oracle.getProperty("oracle.jdbc.ReadTimeout"), "7000"); + + // inside the descriptor the read bound goes by READ_TIMEOUT, and one of the administrator + // is never lifted after the login, because ours is not set on top of it + final Properties read = new Properties(); + assertFalse(CachedConnection.ConnectDialect.ORACLE.bound( + "jdbc:oracle:thin:@(DESCRIPTION=(READ_TIMEOUT=30)(ADDRESS=(HOST=h)(PORT=1521)))", read, 7), + "a read bound of the connection string must not be lifted once the login is through"); + assertNull(read.getProperty("oracle.jdbc.ReadTimeout")); + + // ... while RECV_TIMEOUT is a parameter of sqlnet.ora and of the listener that ojdbc8 does + // not read - the name appears nowhere in the driver - so a descriptor carrying one is not + // a read bound of the connection and must not take ours off it + final Properties recv = new Properties(); + assertTrue(CachedConnection.ConnectDialect.ORACLE.bound( + "jdbc:oracle:thin:@(DESCRIPTION=(RECV_TIMEOUT=30)(ADDRESS=(HOST=h)(PORT=1521)))", recv, 7), + "a parameter no driver reads left the login of this connection unbounded"); + assertEquals(recv.getProperty("oracle.jdbc.ReadTimeout"), "7000"); + + // a name that only appears as the tail of another parameter is not a setting of its own + final Properties mysql = new Properties(); + CachedConnection.ConnectDialect.MYSQL.bound("jdbc:mysql://h:3306/db?xconnectTimeout=1&socketTimeoutX=2", mysql, 7); + assertEquals(mysql.getProperty("connectTimeout"), "7000"); + assertEquals(mysql.getProperty("socketTimeout"), "7000"); + } + + /** + * A parameter is recognized the way the driver of its dialect recognizes it: pgjdbc and + * Connector/J look their properties up by their exact name, so a name of another case is a + * parameter of nobody - neither side bounds anything by it - and must not pass for a bound the + * administrator set, while the other two match either way. + */ + @Test + public void testTheCaseOfAParameterIsTheOneOfItsDriver() throws Exception { + final Properties postgres = new Properties(); + CachedConnection.ConnectDialect.POSTGRES.bound("jdbc:postgresql://h:5432/db?ConnectTimeout=5", postgres, 7); + assertEquals(postgres.getProperty("connectTimeout"), "7", "pgjdbc ignores a parameter of another case"); + + // PropertyKey.fromValue("SocketTimeout") answers null, and Connector/J then reads no bound + // out of the url either: a mis-cased parameter left the borrower parked on a host that + // completes the handshake and says nothing + final Properties mysql = new Properties(); + CachedConnection.ConnectDialect.MYSQL.bound("jdbc:mysql://h:3306/db?SocketTimeout=1", mysql, 7); + assertEquals(mysql.getProperty("socketTimeout"), "7000", "Connector/J ignores a parameter of another case"); + + final Properties microsoft = new Properties(); + CachedConnection.ConnectDialect.MICROSOFT.bound("jdbc:sqlserver://h:1433;LoginTimeout=45", microsoft, 7); + assertNull(microsoft.getProperty("loginTimeout"), "the sql server driver normalizes the name of a property"); + + // the keywords of an oracle descriptor are matched without regard to case as well + final Properties oracle = new Properties(); + CachedConnection.ConnectDialect.ORACLE.bound( + "jdbc:oracle:thin:@(description=(connect_timeout=3)(address=(host=h)(port=1521)))", oracle, 7); + assertNull(oracle.getProperty("oracle.net.CONNECT_TIMEOUT"), "an oracle descriptor is read without case"); + } + + /** + * The connection string is not the only channel of the administrator: the oracle driver reads + * some of its properties out of the system properties as well, which is how a whole jvm is + * bounded with -Doracle.jdbc.ReadTimeout. A property supplied to the driver outranks that one + * without a word, and this class would then lift it once the login is through as if it were + * its own - leaving a connection with no read bound at all where the administrator set one. + */ + @Test + public void testASystemPropertyOfTheAdministratorKeepsPrecedence() throws Exception { + System.setProperty("oracle.jdbc.ReadTimeout", "30000"); + try { + final Properties oracle = new Properties(); + assertFalse(CachedConnection.ConnectDialect.ORACLE.bound("jdbc:oracle:thin:@//h:1521/svc", oracle, 7), + "a read bound of the administrator must not be lifted once the login is through"); + assertNull(oracle.getProperty("oracle.jdbc.ReadTimeout"), "the setting of the administrator was overridden"); + assertEquals(oracle.getProperty("oracle.net.CONNECT_TIMEOUT"), "7000", + "the property it leaves open must still be bounded"); + } finally { + System.clearProperty("oracle.jdbc.ReadTimeout"); + } + + // the connect property of the same driver, over the same channel + System.setProperty("oracle.net.CONNECT_TIMEOUT", "30000"); + try { + final Properties oracle = new Properties(); + CachedConnection.ConnectDialect.ORACLE.bound("jdbc:oracle:thin:@//h:1521/svc", oracle, 7); + assertNull(oracle.getProperty("oracle.net.CONNECT_TIMEOUT"), "the setting of the administrator was overridden"); + } finally { + System.clearProperty("oracle.net.CONNECT_TIMEOUT"); + } + + // a plain name is common enough to be somebody else's system property: only a name a + // driver of these actually reads out of them is one of the administrator's + System.setProperty("socketTimeout", "30000"); + try { + final Properties mysql = new Properties(); + assertTrue(CachedConnection.ConnectDialect.MYSQL.bound("jdbc:mysql://h:3306/db", mysql, 7)); + assertEquals(mysql.getProperty("socketTimeout"), "7000"); + } finally { + System.clearProperty("socketTimeout"); + } + } + + /** + * ... and a dotted name is not a name a driver reads out of the system properties by the shape + * of it. ojdbc8 resolves oracle.jdbc.ReadTimeout and oracle.net.CONNECT_TIMEOUT in three tiers + * (the properties it was supplied, then System.getProperty, then the properties of the data + * source), while oracle.net.READ_TIMEOUT - a dotted name of the same driver, and the name the + * socket option is finally read under - reaches the socket from the connection properties + * alone: the classes carrying the literal hand it to Properties.get, none of them to + * System.getProperty. Taken for a bound of the administrator, a -D of it leaves the login with + * no read bound whatever: theirs is not read and ours is not set. + */ + @Test + public void testASystemPropertyNoDriverReadsIsNoBound() throws Exception { + System.setProperty("oracle.net.READ_TIMEOUT", "30000"); + try { + final Properties oracle = new Properties(); + assertTrue(CachedConnection.ConnectDialect.ORACLE.bound("jdbc:oracle:thin:@//h:1521/svc", oracle, 7), + "a -D the driver never reads left this login with no read bound at all"); + assertEquals(oracle.getProperty("oracle.jdbc.ReadTimeout"), "7000"); + } finally { + System.clearProperty("oracle.net.READ_TIMEOUT"); + } + + // ... while the same name written into the connection string is one the driver does read + final Properties declared = new Properties(); + assertFalse(CachedConnection.ConnectDialect.ORACLE.bound( + "jdbc:oracle:thin:@(DESCRIPTION=(READ_TIMEOUT=30)(ADDRESS=(HOST=h)(PORT=1521)))", declared, 7)); + assertNull(declared.getProperty("oracle.jdbc.ReadTimeout")); + } + + /** + * A property the administrator set to 0 is not a bound of theirs: every one of these drivers + * reads 0 as "wait as long as it takes", which is the default this class exists to replace - + * and on the three whose driver lets a supplied property win, ours is set on top of it. + * Postgresql is the one where it cannot be, and is covered on its own below. + */ + @Test + public void testAZeroIsNotABoundOfTheAdministrator() throws Exception { + final Properties mysql = new Properties(); + CachedConnection.ConnectDialect.MYSQL.bound("jdbc:mysql://h:3306/db?connectTimeout=0&socketTimeout=0", mysql, 7); + assertEquals(mysql.getProperty("connectTimeout"), "7000"); + assertEquals(mysql.getProperty("socketTimeout"), "7000"); + + // ... and neither is a property left without a value + final Properties microsoft = new Properties(); + CachedConnection.ConnectDialect.MICROSOFT.bound("jdbc:sqlserver://h:1433;socketTimeout=;databaseName=db", microsoft, 7); + assertEquals(microsoft.getProperty("socketTimeout"), "7000"); + + // the same of a system property, and of the descriptor of an oracle url + System.setProperty("oracle.jdbc.ReadTimeout", "0"); + try { + final Properties oracle = new Properties(); + assertTrue(CachedConnection.ConnectDialect.ORACLE.bound( + "jdbc:oracle:thin:@(DESCRIPTION=(READ_TIMEOUT=0)(ADDRESS=(HOST=h)(PORT=1521)))", oracle, 7)); + assertEquals(oracle.getProperty("oracle.jdbc.ReadTimeout"), "7000"); + } finally { + System.clearProperty("oracle.jdbc.ReadTimeout"); + } + + // a value that is no number is left to the driver it belongs to: it is not this class's to read + final Properties unreadable = new Properties(); + assertFalse(CachedConnection.ConnectDialect.MYSQL.bound( + "jdbc:mysql://h:3306/db?socketTimeout=PT30S", unreadable, 7)); + assertNull(unreadable.getProperty("socketTimeout")); + } + + /** + * On postgresql a parameter of the url outranks the property this class supplies: Driver + * .connect copies what it was handed into a flat map and parseURL then writes the parameters of + * the url on top of it. So a "socketTimeout=0" there cannot be replaced, and setting ours + * regardless would leave this class believing it bounded a login that carries no bound - and + * lifting a read bound after it that was never in force. The effective values are read back + * through the parser of the driver itself, since asserting on the map handed to it is + * asserting on the half of the story this bug lived in. + */ + @Test + public void testAParameterOfAPostgresUrlOutranksTheBoundOfThisClass() throws Exception { + final String url = "jdbc:postgresql://h:5432/db?connectTimeout=0&socketTimeout=0&loginTimeout=0"; + final Properties supplied = new Properties(); + assertFalse(CachedConnection.ConnectDialect.POSTGRES.bound(url, supplied, 7), + "a read bound that never reaches the driver must not be reported as one to lift"); + assertNull(supplied.getProperty("socketTimeout")); + assertNull(supplied.getProperty("connectTimeout")); + assertNull(supplied.getProperty("loginTimeout")); + + final Properties effective = org.postgresql.Driver.parseURL(url, supplied); + assertEquals(effective.getProperty("socketTimeout"), "0", "the url is what the driver ends up reading"); + assertEquals(effective.getProperty("connectTimeout"), "0"); + assertEquals(effective.getProperty("loginTimeout"), "0"); + } + + /** + * The connect side of a dialect is one budget rather than a set of independent knobs, so a + * bound of the administrator under any of its names leaves all of them alone. On postgresql + * connectTimeout bounds the socket connect and loginTimeout the login behind it: filling in the + * one they left out caps the one they set, since Driver.connect hands the login to a thread of + * its own as soon as loginTimeout is anything but 0 and gives up on it there. + */ + @Test + public void testAConnectBudgetOfTheAdministratorIsNotCappedByThisClass() throws Exception { + final String url = "jdbc:postgresql://h:5432/db?connectTimeout=300"; + final Properties supplied = new Properties(); + assertTrue(CachedConnection.ConnectDialect.POSTGRES.bound(url, supplied, 30), + "the read bound is a budget of its own and is still set"); + assertNull(supplied.getProperty("loginTimeout"), + "a loginTimeout of ours caps the connectTimeout the administrator set"); + assertNull(supplied.getProperty("connectTimeout")); + assertEquals(supplied.getProperty("socketTimeout"), "30"); + + final Properties effective = org.postgresql.Driver.parseURL(url, supplied); + assertEquals(effective.getProperty("connectTimeout"), "300", "the budget of the administrator, in full"); + assertNull(effective.getProperty("loginTimeout"), "nothing of ours hands this login to a thread to abandon"); + } + + /** + * The bound handed to a driver stays inside the range an int of milliseconds takes. Where the + * per-attempt property is off, the attempt takes what is left of the deadline of the borrow, + * and the pool timeout has no upper bound of its own - while the SQL Server driver rejects a + * socketTimeout past Integer.MAX_VALUE outright, failing every connect of that backend with + * the name of a property nobody typed. + */ + @Test(timeOut = 120000) + public void testTheBoundHandedToADriverStaysInTheRangeAnIntTakes() throws Exception { + final long deadline = System.currentTimeMillis() + 3000000L * 1000; // 34 days: past 2^31 ms + assertEquals(CachedConnection.attemptSeconds(0, deadline), Integer.MAX_VALUE / 1000); + + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, "0"); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "3000000"); + // a socket that answers the connect and closes it, rather than a port bound and released: + // with every bound of this borrow turned off, anything taking that port in between would + // leave the test hanging on the timeOut instead of failing + try (final ServerSocket rejecting = rejectingSocket()) { + final String url = "jdbc:sqlserver://127.0.0.1:" + rejecting.getLocalPort() + + ";databaseName=opendj;user=opendj;password=opendj;encrypt=false"; + final long startedAt = System.currentTimeMillis(); + try { + CachedConnection.getConnection(url); + fail("a connect the database closes must be reported"); + } catch (SQLException expected) { + assertFalse(expected.getMessage().contains("socketTimeout"), + "the driver was handed a bound it does not take: " + expected.getMessage()); + } + assertElapsedWithinBound(startedAt, 0); + } + } + + /** The clamp of the range holds where the borrow has no deadline to take it from either. */ + @Test + public void testTheBoundOfAnAttemptStaysInRangeWithoutADeadline() throws Exception { + assertEquals(CachedConnection.attemptSeconds(Long.MAX_VALUE, Long.MAX_VALUE), Integer.MAX_VALUE / 1000); + assertEquals(CachedConnection.attemptSeconds(0, Long.MAX_VALUE), 0, "0 stands for an attempt with no bound"); + assertEquals(CachedConnection.attemptSeconds(30, Long.MAX_VALUE), 30); + } + + /** The connection string holds the credentials of the backend: a stall report must not carry them. */ + @Test + public void testLoggedConnectionStringCarriesNoCredentials() throws Exception { + assertEquals(CachedConnection.safeUrl("jdbc:postgresql://h:5432/db?user=u&password=secret"), "jdbc:postgresql://h:5432/db"); + // the parameter naming the database stays: two backends of one sql server host answer to + // the same url up to it, and a stall report that cannot tell them apart is one of neither + assertEquals(CachedConnection.safeUrl("jdbc:sqlserver://h:1433;databaseName=db;password=secret"), + "jdbc:sqlserver://h:1433;databaseName=db"); + // ... and the token naming the kind of oracle driver stays as well: thin against oci is a + // first question of an oracle connect, and it stands in front of the credentials + assertEquals(CachedConnection.safeUrl("jdbc:oracle:thin:scott/secret@//h:1521/svc"), "jdbc:oracle:thin:@//h:1521/svc"); + assertEquals(CachedConnection.safeUrl("jdbc:mysql://u:secret@h:3306/db"), "jdbc:mysql://h:3306/db"); + assertEquals(CachedConnection.safeUrl("jdbc:oracle:thin:@//h:1521/svc"), "jdbc:oracle:thin:@//h:1521/svc"); + // a password holding the parameter separator of another dialect: ";" separates nothing on + // an oracle url, so the credentials are cut in front of the "@" rather than inside them + assertEquals(CachedConnection.safeUrl("jdbc:oracle:thin:scott/pa;ss@//h:1521/svc"), "jdbc:oracle:thin:@//h:1521/svc"); + // ... and one holding a ":" is cut in front of it too: the token of the driver is the one + // behind the subprotocol, not the last one standing in front of the "@" + assertEquals(CachedConnection.safeUrl("jdbc:oracle:thin:scott/pa:ss@//h:1521/svc"), "jdbc:oracle:thin:@//h:1521/svc"); + // ... and an "@" that stands inside a parameter is not the end of credentials: the host survives + assertEquals(CachedConnection.safeUrl("jdbc:postgresql://h:5432/db?user=u@example.com&password=secret"), + "jdbc:postgresql://h:5432/db"); + // a password holding the parameter separator of its own dialect: on an oracle url the + // parameters stand behind the descriptor, so a "?" in front of the "@" is part of the + // password and cutting there would leave the start of it in the log + assertEquals(CachedConnection.safeUrl("jdbc:oracle:thin:scott/pa?ss@//h:1521/svc"), "jdbc:oracle:thin:@//h:1521/svc"); + // the same inside an authority, where the credentials end at the path rather than at a "?" + assertEquals(CachedConnection.safeUrl("jdbc:mysql://u:sec?ret@h:3306/db"), "jdbc:mysql://h:3306/db"); + // a descriptor of an oracle url carries no credentials and survives whole + assertEquals(CachedConnection.safeUrl("jdbc:oracle:thin:@(DESCRIPTION=(ADDRESS=(HOST=h)(PORT=1521)))"), + "jdbc:oracle:thin:@(DESCRIPTION=(ADDRESS=(HOST=h)(PORT=1521)))"); + // a first host with nothing in front of the comma keeps the comma: what is left is the + // hosts of a url, not one host of it + assertEquals(CachedConnection.safeUrl("jdbc:mysql://,h2:3306/db"), "jdbc:mysql://,h2:3306/db"); + // a password under a name of its own, and one numbered by the factor it belongs to + assertEquals(CachedConnection.safeUrl("jdbc:mysql://(host=h,user=u,password2=secret)/db"), + "jdbc:mysql://(host=h,user=u,password2=***)/db"); + + // a url of Connector/J gives every host of it credentials of its own, and every one of + // them goes: the second used to stay in the message with the password of the failover host + assertEquals(CachedConnection.safeUrl("jdbc:mysql://u:p@h1:3306,u2:p2@h2:3306/db"), + "jdbc:mysql://h1:3306,h2:3306/db"); + // ... including a url whose subprotocol names the kind of connection in front of the hosts + assertEquals(CachedConnection.safeUrl("jdbc:mysql:replication://master:p1@h1:3306,slave:p2@h2:3306/db"), + "jdbc:mysql:replication://h1:3306,h2:3306/db"); + // the key-value host syntax of Connector/J puts the credentials inside the authority, where + // neither the userinfo nor the parameters of a url stand + assertEquals(CachedConnection.safeUrl("jdbc:mysql://address=(host=h)(port=3306)(user=u)(password=secret)/db"), + "jdbc:mysql://address=(host=h)(port=3306)(user=u)(password=***)/db"); + assertEquals(CachedConnection.safeUrl("jdbc:mysql://(host=h,port=3306,user=u,password=secret)/db"), + "jdbc:mysql://(host=h,port=3306,user=u,password=***)/db"); + assertEquals(CachedConnection.safeUrl("jdbc:sqlserver://h:1433;databaseName=db;PWD=secret"), + "jdbc:sqlserver://h:1433;databaseName=db"); + + // a shape none of this took apart is not logged past its subprotocol: a password holding a + // "/" ends the authority in front of the "@" that would have given the credentials away + assertEquals(CachedConnection.safeUrl("jdbc:mysql://u:pa/ss@h:3306/db"), + "jdbc:mysql:" + CachedConnection.CREDENTIALS_HIDDEN); + // ... and so does a password that holds an "@" and was quoted for the driver + assertEquals(CachedConnection.safeUrl("jdbc:oracle:thin:scott/\"pa@ss\"@//h:1521/svc"), + "jdbc:oracle:" + CachedConnection.CREDENTIALS_HIDDEN); + // a string that is no connection string of any driver carries nothing to the log either + assertEquals(CachedConnection.safeUrl("h:5432/db?password=secret"), CachedConnection.CREDENTIALS_HIDDEN); + } + + /** + * A driver is free to quote the connection string it was handed back into the message of its + * failure, and that message travels: RootContainer makes it the message of what it throws, + * BackendConfigManager logs it at ERROR and answers a config change with it. So the message is + * redacted rather than the two call sites that happen to log a url. + */ + @Test + public void testAMessageOfADriverCarriesNoCredentials() throws Exception { + final String url = "jdbc:postgresql://opendj:S3cret@h:5432/db"; + assertEquals(CachedConnection.redact("No suitable driver found for " + url, url), + "No suitable driver found for jdbc:postgresql://h:5432/db"); + // a driver naming the credentials alone, without the url around them + assertEquals(CachedConnection.redact("authentication of opendj:S3cret failed", url), + "authentication of " + CachedConnection.CREDENTIALS_HIDDEN + " failed"); + // ... and naming the password alone + assertEquals(CachedConnection.redact("the password S3cret was not accepted", url), + "the password " + CachedConnection.CREDENTIALS_HIDDEN + " was not accepted"); + // the credentials of an oracle url stand in front of its descriptor + final String oracle = "jdbc:oracle:thin:scott/S3cret@//h:1521/svc"; + assertEquals(CachedConnection.redact("IO Error connecting to " + oracle, oracle), + "IO Error connecting to jdbc:oracle:thin:@//h:1521/svc"); + // a password of a parameter is blanked wherever the message carries it + assertEquals(CachedConnection.redact("bad url jdbc:sqlserver://h:1433;password=S3cret", + "jdbc:sqlserver://h:1433;password=S3cret"), "bad url jdbc:sqlserver://h:1433"); + // a message naming nothing of the connection string is left as it stands + assertEquals(CachedConnection.redact("Connection to h:5432 refused", url), "Connection to h:5432 refused"); + assertNull(CachedConnection.redact(null, url)); + + // the stall report is the other way a driver's message reaches the log, and it carries the + // url of the backend alongside it + final String stall = CachedConnection.stallMessage(url, 3, 4000, + new SQLException("FATAL: too many connections for " + url)); + assertFalse(stall.contains("S3cret"), stall); + assertTrue(stall.contains("jdbc:postgresql://h:5432/db"), stall); + assertTrue(stall.contains("4000 ms") && stall.contains("(3 attempts)"), stall); + } + + /** + * pgjdbc enforces loginTimeout out of process: Driver.connect hands the login to a daemon + * thread of its own and gives up on the thread rather than on the login. Against the database + * this bound exists for - one that completes the handshake and then says nothing - an + * unbounded read there leaves that thread, and the socket it holds, behind on every borrow; + * a few operations a second are enough to run the server out of threads and file descriptors. + */ + @Test(timeOut = 300000) + public void testTheLoginThreadOfPostgresDoesNotOutliveTheBorrow() throws Exception { + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, Long.toString(BOUND_SECONDS)); + // counted as a delta of this borrow rather than as a count of the jvm: three tests of this + // file open a pgjdbc login against a socket that never answers, and the order they run in + // is not contractual - a thread left by any of them would be reported here + final int before = loginThreadsOfPostgres(); + try (final ServerSocket blackhole = new ServerSocket(0, 50, InetAddress.getLoopbackAddress())) { + final String url = "jdbc:postgresql://127.0.0.1:" + blackhole.getLocalPort() + "/opendj?user=opendj&password=opendj"; + try { + CachedConnection.getConnection(url); + fail("a database that never answers must not hand out a connection"); + } catch (SQLException expected) { + // reported to the caller, as the bound of the attempt promises + } + final long giveUpAt = System.currentTimeMillis() + BOUND_SECONDS * 1000 + BOUND_MARGIN_MS; + while (loginThreadsOfPostgres() > before && System.currentTimeMillis() < giveUpAt) { + Thread.sleep(100); + } + assertTrue(loginThreadsOfPostgres() <= before, + "the login thread pgjdbc abandoned outlived the borrow: the read of the login is not bounded"); + } + } + + private static int loginThreadsOfPostgres() { + int alive = 0; + for (final Thread thread : Thread.getAllStackTraces().keySet()) { + if (thread.isAlive() && thread.getName().startsWith("PostgreSQL JDBC driver connection thread")) { + alive++; + } + } + return alive; + } + + /** + * The deadline of the borrow stands for the whole borrow, so it bounds the attempt inside it + * even where the per-attempt property gives it no bound of its own: turning that property off + * must not turn the bound of the borrow off with it. + */ + @Test(timeOut = 300000) + public void testTheDeadlineBoundsAnAttemptTheConnectPropertyDoesNot() throws Exception { + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, "0"); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "2"); + try (final ServerSocket blackhole = new ServerSocket(0, 50, InetAddress.getLoopbackAddress())) { + final String url = "jdbc:postgresql://127.0.0.1:" + blackhole.getLocalPort() + "/opendj?user=opendj&password=opendj"; + final long startedAt = System.currentTimeMillis(); + try { + CachedConnection.getConnection(url); + fail("a database that never answers must not hand out a connection"); + } catch (SQLException expected) { + // bounded by what is left of the deadline of the borrow + } + assertElapsedWithinBound(startedAt, 2000); + } + } + + /** + * The deadline stops the drain of the pool; it does not throw away the connection in hand. A + * database at its connection limit has no other source of connections than the ones coming + * back to the pool, and closing one unvalidated takes it out of that source for good - while + * the borrow that closed it fails with a timeout anyway. + */ + @Test(timeOut = 120000) + public void testAPooledConnectionIsNotDiscardedUnvalidatedAtTheDeadline() throws Exception { + final String url = StubDriver.PREFIX + "unvalidated-at-deadline"; + final Connection stale = mock(Connection.class); + when(stale.isValid(anyInt())).thenAnswer(invocation -> { + Thread.sleep(1500); // a database that no longer answers: the validation waits out its bound + return false; + }); + final Connection good = mock(Connection.class); + when(good.isValid(anyInt())).thenReturn(true); + seedPool(url, stale, good); + final Connection fresh = mock(Connection.class); + stub.answerWith(fresh); + System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "1"); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, fresh, "the drain must stop at the deadline"); + verify(stale).close(); + verify(good, never()).close(); + assertFalse(CachedConnection.cached.get(url).isEmpty(), "a connection the deadline was reached in front of was lost"); + } + + /** + * A connection the validation of which failed is on its way out, and its driver knows it: + * Connector/J answers a failed validation by aborting the connection and the SQL Server driver + * by terminating it. Putting the previous bound back on it fails, and warns about statements + * of a connection that is being closed - over an idle connection the server reaped, which is + * nobody's problem. + */ + @Test(timeOut = 120000) + public void testAConnectionOnItsWayOutIsNotGivenItsBoundBack() throws Exception { + final String url = StubDriver.PREFIX + "reaped-idle"; + final Connection reaped = mock(Connection.class); + when(reaped.getNetworkTimeout()).thenReturn(0); + when(reaped.isValid(anyInt())).thenReturn(false); + seedPool(url, reaped); + final Connection fresh = mock(Connection.class); + stub.answerWith(fresh); + + assertSame(((CachedConnection) CachedConnection.getConnection(url)).parent, fresh); + + verify(reaped).setNetworkTimeout(any(Executor.class), eq(CachedConnection.VALIDATION_TIMEOUT_SECONDS * 1000)); + verify(reaped, never()).setNetworkTimeout(any(Executor.class), eq(0)); + verify(reaped).close(); + } + + /** + * The read bound of the login is lifted once the login is through, because left in place it + * fails every statement slower than it. A driver that will not take it back leaves a + * connection that must not be pooled: it would carry that bound into every borrow the pool + * hands it to, an import batch among them. + */ + @Test(timeOut = 120000) + public void testAConnectionStillCarryingTheBoundOfItsLoginIsNotPooled() throws Exception { + final String url = StubDriver.PREFIX + "unliftable-bound"; + final Connection parent = mock(Connection.class); + doThrow(new SQLException("setNetworkTimeout is not supported")) + .when(parent).setNetworkTimeout(any(Executor.class), eq(0)); + stub.answerWith(parent); + + final CachedConnection borrowed = CachedConnection.connect(url, CachedConnection.ConnectDialect.MYSQL, 30); + borrowed.close(); + + verify(parent).close(); + assertTrue(CachedConnection.cached.get(url).isEmpty(), + "a connection still carrying the read bound of its login went back into the pool"); + } + + /** + * The case the window exists for: the connection this borrow takes out answered the database a + * moment ago, and asking it again costs the round trip the operation came to make. + */ + @Test(timeOut = 120000) + public void testAConnectionProvenAliveIsNotValidatedAgainWithinTheWindow() throws Exception { + final String url = StubDriver.PREFIX + "within-the-window"; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + final Connection parent = mock(Connection.class); + when(parent.isValid(anyInt())).thenReturn(true); + stub.answerWith(parent); + + final Connection first = CachedConnection.getConnection(url); // established: it has just answered + first.close(); + final Connection second = CachedConnection.getConnection(url); + + assertSame(second, first, "the pooled connection was not the one handed back"); + assertEquals(stub.attempts.get(), 1, "the pool established a second connection"); + verify(parent, never()).isValid(anyInt()); + } + + /** Past the window it is the connection the database or a firewall may have dropped meanwhile. */ + @Test(timeOut = 120000) + public void testAConnectionIsValidatedAgainOnceTheWindowHasPassed() throws Exception { + final String url = StubDriver.PREFIX + "past-the-window"; + CachedConnection.aliveBypassNanos = TimeUnit.MILLISECONDS.toNanos(1); + final Connection parent = mock(Connection.class); + when(parent.isValid(anyInt())).thenReturn(true); + stub.answerWith(parent); + + final Connection first = CachedConnection.getConnection(url); + first.close(); + Thread.sleep(20); + final Connection second = CachedConnection.getConnection(url); + + assertSame(second, first); + verify(parent).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + + /** The window switched off validates every borrow, the way this pool did before it existed. */ + @Test(timeOut = 120000) + public void testAWindowOfZeroValidatesEveryBorrow() throws Exception { + final String url = StubDriver.PREFIX + "window-of-zero"; + CachedConnection.aliveBypassNanos = 0; + final Connection parent = mock(Connection.class); + when(parent.isValid(anyInt())).thenReturn(true); + stub.answerWith(parent); + + final Connection first = CachedConnection.getConnection(url); + first.close(); + final Connection second = CachedConnection.getConnection(url); + + assertSame(second, first); + verify(parent).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + + /** + * A connection is trusted for the window that follows the last answer it gave, never for the + * window that follows its return to the pool. pgjdbc short-circuits both rollback() and + * commit() when the transaction state is IDLE, so a borrow that issued no statement - the open + * of a backend, a configuration change that leaves the base DNs alone, an import of nothing - + * puts a connection back without a byte reaching the server: stamping the return would mark a + * connection the database dropped meanwhile as the freshest one in the pool. + */ + @Test(timeOut = 120000) + public void testTheReturnToThePoolIsNotTakenForProofOfLife() throws Exception { + final String url = StubDriver.PREFIX + "silent-return"; + CachedConnection.aliveBypassNanos = TimeUnit.MILLISECONDS.toNanos(50); + final Connection dropped = mock(Connection.class); + when(dropped.isValid(anyInt())).thenReturn(false); // dropped while it was out of the pool + stub.answerWith(dropped); + + final Connection borrowed = CachedConnection.getConnection(url); + Thread.sleep(80); // the answer of the login ages out of the window + borrowed.close(); // and the rollback of this return never leaves the driver + final Connection fresh = mock(Connection.class); + when(fresh.isValid(anyInt())).thenReturn(true); + stub.answerWith(fresh); + + final Connection next = CachedConnection.getConnection(url); + + verify(dropped).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + verify(dropped).close(); + assertSame(((CachedConnection) next).parent, fresh, + "a connection the database dropped was handed out on the strength of its return to the pool"); + } + + /** + * The pool hands out the connection returned last. Without it the window would rarely apply: a + * connection reached only after a whole cycle of the pool has been idle far longer than it. + */ + @Test(timeOut = 120000) + public void testTheConnectionReturnedLastIsBorrowedFirst() throws Exception { + final String url = StubDriver.PREFIX + "returned-last"; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + final Connection older = mock(Connection.class); + when(older.isValid(anyInt())).thenReturn(true); + stub.answerWith(older); + final Connection first = CachedConnection.getConnection(url); + final Connection newer = mock(Connection.class); + when(newer.isValid(anyInt())).thenReturn(true); + stub.answerWith(newer); + final Connection second = CachedConnection.getConnection(url); + assertNotSame(second, first); + first.close(); + second.close(); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, newer, "the pool cycled round to its coldest connection"); + } + + /** + * Whatever dropped one connection - a restart, a failover, a network that went away - dropped + * every connection established before it, and a borrow inside the window asks the database + * nothing: so the operation that saw the failure tells the pool, and the rest of that + * generation is validated once before it is trusted again. + */ + @Test(timeOut = 120000) + public void testThePoolIsValidatedAgainAfterTheDatabaseDroppedAConnection() throws Exception { + final String url = StubDriver.PREFIX + "distrusted-generation"; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + final Connection parent = mock(Connection.class); + when(parent.isValid(anyInt())).thenReturn(true); + stub.answerWith(parent); + CachedConnection.getConnection(url).close(); + + CachedConnection.distrustPool(url); + final Connection next = CachedConnection.getConnection(url); + next.close(); + CachedConnection.getConnection(url).close(); + + // once for the generation the drop condemned, and not again for the borrow behind it + verify(parent, times(1)).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + + /** + * The whole of the trade the window makes, end to end: a connection the database dropped + * inside the window is handed out unvalidated - that is the cost - the operation it broke + * reports the drop, and from there the pool validates the generation the drop condemned + * instead of handing out the rest of it the same way. + */ + @Test(timeOut = 120000) + public void testAConnectionDroppedInsideTheWindowIsHandedOutOnceAndThenValidated() throws Exception { + final String url = StubDriver.PREFIX + "dropped-inside-the-window"; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + final Connection parent = mock(Connection.class); + when(parent.isValid(anyInt())).thenReturn(true); + stub.answerWith(parent); + CachedConnection.getConnection(url).close(); + + when(parent.isValid(anyInt())).thenReturn(false); // the database dropped it where it lay + final Connection dropped = CachedConnection.getConnection(url); + assertSame(((CachedConnection) dropped).parent, parent, "the pooled connection was not the one handed back"); + verify(parent, never()).isValid(anyInt()); // handed out on the strength of its last answer + + // the statement of the caller is where the drop surfaces, and the caller reports it + CachedConnection.distrustPool(url); + dropped.close(); + final Connection fresh = mock(Connection.class); + when(fresh.isValid(anyInt())).thenReturn(true); + stub.answerWith(fresh); + + final Connection next = CachedConnection.getConnection(url); + + verify(parent).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + verify(parent).close(); + assertSame(((CachedConnection) next).parent, fresh, "the rest of the generation was handed out unvalidated"); + } + + /** + * Seeds the pool the way {@link CachedConnection#close()} fills it - at the end a borrow takes + * from - so that the connection named first here is the one the next borrow gets. + */ + private static void seedPool(String url, Connection... parents) { + for (int i = parents.length - 1; i >= 0; i--) { + CachedConnection.cached.get(url).addFirst(new CachedConnection(url, parents[i])); + } + } + + /** + * The borrows nothing compensates a dropped connection on - the open of a backend, the removal + * of its files, the start of an import - ask for a connection the pool validates whatever the + * window says. Each of them is one borrow of a cold path, and the one that opens a backend + * issues no statement at all: a connection dropped inside the window would surface there out of + * the rollback that releases it, with no statement to replay and nothing to tell the pool. + */ + @Test(timeOut = 120000) + public void testTheBorrowsNothingCompensatesAreValidated() throws Exception { + final String url = StubDriver.PREFIX + "validated-borrow"; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + final Connection parent = mock(Connection.class); + when(parent.isValid(anyInt())).thenReturn(true); + stub.answerWith(parent); + CachedConnection.getConnection(url).close(); + + final Connection borrowed = CachedConnection.getConnection(url, false); + + assertSame(((CachedConnection) borrowed).parent, parent, "the pooled connection was not the one handed back"); + verify(parent).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + + /** + * A connection closed under the borrow is not handed out on the strength of its last answer: + * the removal listener of the pool closes every connection it finds in the deque when the pool + * expires, and it iterates a weakly consistent view. The validation the window replaces + * answered that as well, out of a flag of the driver rather than out of a round trip. + */ + @Test(timeOut = 120000) + public void testAConnectionThePoolClosedIsNotHandedOut() throws Exception { + final String url = StubDriver.PREFIX + "closed-inside-the-window"; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + final Connection parent = mock(Connection.class); + when(parent.isValid(anyInt())).thenReturn(true); + stub.answerWith(parent); + CachedConnection.getConnection(url).close(); + // closed where it lay, by the expiry of the pool: a closed connection answers isValid() with + // false as well, which is what discards it once the window stops trusting it + when(parent.isClosed()).thenReturn(true); + when(parent.isValid(anyInt())).thenReturn(false); + final Connection fresh = mock(Connection.class); + when(fresh.isValid(anyInt())).thenReturn(true); + stub.answerWith(fresh); + + final Connection borrowed = CachedConnection.getConnection(url); + + assertSame(((CachedConnection) borrowed).parent, fresh, "a closed connection was handed out on its last answer"); + } + + /** + * The window is clamped to the idle time the pool keeps a connection for. A value the unit + * conversion saturates on would leave every connection of the pool trusted for the life of the + * server, and one merely longer than the pool holds a connection leaves the connection in + * constant use - the one the window exists for - validated not once per window but never. + */ + @Test(timeOut = 120000) + public void testTheWindowIsClampedToTheIdleTimeOfThePool() { + System.setProperty(CachedConnection.TTL_PROPERTY, "15000"); + System.setProperty(CachedConnection.ALIVE_BYPASS_PROPERTY, "500"); + assertEquals(CachedConnection.getAliveBypassMillis(), 500L, "a window inside the ttl was not left alone"); + + System.setProperty(CachedConnection.ALIVE_BYPASS_PROPERTY, Long.toString(Long.MAX_VALUE)); + assertEquals(CachedConnection.getAliveBypassMillis(), 15000L, "a window of Long.MAX_VALUE was not clamped"); + + System.setProperty(CachedConnection.TTL_PROPERTY, "100"); + assertEquals(CachedConnection.getAliveBypassMillis(), 100L, "the clamp is the configured ttl, not the default"); + } + + private static SQLException tooManyConnections() { + // 53300, too_many_connections, of the insufficient_resources class + return new SQLException("sorry, too many clients already", "53300"); + } + + /** A connection string of every dialect pointing at one host and port. */ + private static String[] urlsOf(int port) { + return new String[]{ + "jdbc:postgresql://127.0.0.1:" + port + "/opendj?user=opendj&password=opendj", + "jdbc:mysql://127.0.0.1:" + port + "/opendj?user=opendj&password=opendj", + "jdbc:oracle:thin:opendj/opendj@//127.0.0.1:" + port + "/free", + "jdbc:sqlserver://127.0.0.1:" + port + ";databaseName=opendj;user=opendj;password=opendj;encrypt=false" + }; + } + + private static int closedPort() throws Exception { + try (final ServerSocket socket = new ServerSocket(0, 1, InetAddress.getLoopbackAddress())) { + return socket.getLocalPort(); + } // closed again: nothing listens there any more + } + + /** + * A socket that answers a connect and closes it at once. A port bound and released is the + * shape of a refused connect a test would reach for, but it races whatever else on the host + * may take that port; this one is the failure it stands for and belongs to nobody else. + */ + private static ServerSocket rejectingSocket() throws Exception { + final ServerSocket socket = new ServerSocket(0, 50, InetAddress.getLoopbackAddress()); + final Thread accepting = new Thread(() -> { + while (!socket.isClosed()) { + try { + socket.accept().close(); + } catch (Exception closed) { + return; + } + } + }, "opendj-test-rejecting-socket"); + accepting.setDaemon(true); + accepting.start(); + return socket; + } + + private static void assertElapsedWithinBound(long startedAt, long boundMs) { + final long elapsed = System.currentTimeMillis() - startedAt; + assertTrue(elapsed < boundMs + BOUND_MARGIN_MS, "gave up only after " + elapsed + " ms"); + } + + /** + * Stands in for a database whose answer to a connect is the point of the test: the vendor + * codes and SQL states below are what the retry has to tell apart, and no engine is needed to + * produce them. + */ + private static final class StubDriver implements Driver { + static final String PREFIX = "jdbc:opendj-stub:"; + static final int ALWAYS = -1; + + final AtomicInteger attempts = new AtomicInteger(); + private volatile SQLException failure; + private volatile int failuresLeft; + private volatile Connection answer; + + void failWith(SQLException failure, int times) { + this.failure = failure; + this.failuresLeft = times; + this.answer = null; + this.attempts.set(0); + } + + void answerWith(Connection answer) { + this.failure = null; + this.failuresLeft = 0; + this.answer = answer; + this.attempts.set(0); + } + + @Override + public Connection connect(String url, Properties info) throws SQLException { + if (!acceptsURL(url)) { + return null; + } + attempts.incrementAndGet(); + if (failuresLeft != 0) { + if (failuresLeft > 0) { + failuresLeft--; + } + throw failure; + } + if (answer != null) { + return answer; + } + final Connection con = mock(Connection.class); + when(con.isValid(anyInt())).thenReturn(true); + return con; + } + + @Override + public boolean acceptsURL(String url) { + return url != null && url.startsWith(PREFIX); + } + + @Override + public DriverPropertyInfo[] getPropertyInfo(String url, Properties info) { + return new DriverPropertyInfo[0]; + } + + @Override + public int getMajorVersion() { + return 1; + } + + @Override + public int getMinorVersion() { + return 0; + } + + @Override + public boolean jdbcCompliant() { + return false; + } + + @Override + public Logger getParentLogger() { + return Logger.getLogger(StubDriver.class.getName()); + } + } +} diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCStorageRetryTest.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCStorageRetryTest.java index eac8048b4f..3431208de9 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCStorageRetryTest.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCStorageRetryTest.java @@ -21,16 +21,23 @@ import org.testng.annotations.DataProvider; import org.testng.annotations.Test; +import java.sql.Connection; import java.sql.SQLException; +import java.sql.SQLNonTransientConnectionException; +import java.sql.SQLRecoverableException; import static org.forgerock.i18n.LocalizableMessage.raw; import static org.forgerock.opendj.ldap.ResultCode.OTHER; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; import static org.testng.Assert.assertEquals; +import static org.testng.Assert.assertFalse; +import static org.testng.Assert.assertNull; import static org.testng.Assert.assertTrue; /** - * Tests how a failure is classified as a transaction conflict, which is what decides whether - * {@link JDBCStorage#write} replays the operation, and how long it waits before it does. + * Tests how a failure is classified - as a transaction conflict, or as a connection the database dropped - which + * is what decides whether {@link JDBCStorage#write} replays the operation, and how long it waits before it does. *

* Runs without a database: the failures the drivers report are reproduced as synthetic * {@link SQLException}s carrying the same vendor error number and SQLState. @@ -115,6 +122,135 @@ public void testIsRetryableConflict(String name, Throwable failure, String drive assertEquals(JDBCStorage.isRetryableConflict(failure, driver), expected, name); } + @DataProvider + public Object[][] connectionFailures() + { + return new Object[][] { + // class 08, connection exception: pgjdbc reports the next use of a connection the server dropped as 08003, + // and a socket that failed under it as 08006, while a connect that never came up is 08001 + { "connection does not exist", sql(0, "08003"), true }, + { "connection failure", sql(0, "08006"), true }, + { "unable to establish connection", sql(0, "08001"), true }, + // the FATAL message a pg_terminate_backend or a shutdown sends before the socket closes: the connection is + // gone, and only its next use would be reported as class 08 + { "admin shutdown", sql(0, "57P01"), true }, + { "crash shutdown", sql(0, "57P02"), true }, + { "cannot connect now", sql(0, "57P03"), true }, + // it reaches write() wrapped, exactly as a conflict does + { "wrapped once", new StorageRuntimeException(sql(0, "08006")), true }, + { "wrapped twice", + new DirectoryException(OTHER, raw("unchecked"), new StorageRuntimeException(sql(0, "08003"))), true }, + { "wrapped 57P0x", new StorageRuntimeException(sql(0, "57P01")), true }, + // the types the JDBC contract gives a driver to say the connection is gone, whatever state it fills in: + // oracle reports ORA-03113 and ORA-01089 as SQLRecoverableException, and only happens to map them to 08006 + { "recoverable", new SQLRecoverableException("closed connection", "72000", 3113), true }, + { "non transient connection", new SQLNonTransientConnectionException("socket closed", "S1000", 0), true }, + // a driver reports what happened as the next exception of a generic failure as readily as it reports it + // as the cause, and mssql-jdbc chains every error of a message it received that way + { "next exception", chained(sql(0, "HY000"), sql(0, "08006")), true }, + // the drop of the rollback that releases a connection arrives suppressed into the failure of the operation + { "suppressed", suppressing(sql(2627, "23000"), sql(0, "08006")), true }, + + // a statement the database answered, however badly, leaves the connection usable + { "deadlock victim", sql(1205, "40001"), false }, + { "primary key violation", sql(2627, "23000"), false }, + // 53300 is the server refusing a further connection, not the loss of one already established + { "too many connections", sql(0, "53300"), false }, + // a killed session on SQL Server: generateStateCode maps neither 596 nor its siblings, so with xopenStates + // off - the default - it arrives as "S"+errorState and no state tells it from a rejected statement. What + // does tell it apart is the connection the driver closed behind it, see the test below + { "mssql killed session", sql(596, "S0001"), false }, + { "no SQLState", sql(0, null), false }, + { "not a SQLException", new IllegalStateException("connection closed"), false }, + { "no failure at all", null, false }, + { "cyclic cause chain", new SelfCausedException(), false }, + }; + } + + @Test(dataProvider = "connectionFailures") + public void testIsConnectionFailure(String name, Throwable failure, boolean expected) + { + assertEquals(JDBCStorage.isConnectionFailure(failure), expected, name); + } + + /** + * A connection the database dropped is replayed on a connection the next attempt borrows of its own - but only + * while the transaction has not been committed yet. A drop reported by {@code commit()} leaves the outcome of + * the transaction unknown, and replaying a write that in fact committed applies it twice. + */ + @Test + public void testADroppedConnectionIsReplayedOnlyBeforeTheCommit() + { + final SQLException dropped = sql(0, "08006"); + assertEquals(JDBCStorage.replayReason(dropped, POSTGRES, false, false, false), + "a connection the database dropped"); + assertNull(JDBCStorage.replayReason(dropped, POSTGRES, true, false, false), + "an in doubt transaction was replayed"); + } + + /** + * A driver that closed the connection has said the connection is gone whatever SQLState it filled in - which is + * the only way a killed SQL Server session is ever recognized, since it arrives as S0001. + */ + @Test + public void testAConnectionTheDriverClosedIsADroppedOne() + { + final SQLException killed = sql(596, "S0001"); + assertNull(JDBCStorage.replayReason(killed, MSSQL, false, false, false), "S0001 was replayed on its own"); + assertEquals(JDBCStorage.replayReason(killed, MSSQL, false, false, true), + "a connection the database dropped"); + assertNull(JDBCStorage.replayReason(killed, MSSQL, true, false, true), + "an in doubt transaction was replayed"); + } + + /** + * An attempt that committed part of its own work is not replayed, whatever the failure says: what it did no + * longer rolls back as a whole, and a WriteOperation is only idempotent in the database. RootContainer.open + * opens and registers the entry containers of every base DN in one write, and a replay of it fails with + * ERR_ENTRY_CONTAINER_ALREADY_REGISTERED, masking the failure that caused the replay. + */ + @Test + public void testAnAttemptThatCommittedPartOfItsWorkIsNotReplayed() + { + assertNull(JDBCStorage.replayReason(sql(0, "40001"), POSTGRES, false, true, false), "a conflict was replayed"); + assertNull(JDBCStorage.replayReason(sql(0, "08006"), POSTGRES, false, true, false), "a drop was replayed"); + assertNull(JDBCStorage.replayReason(sql(596, "S0001"), MSSQL, false, true, true), "a drop was replayed"); + } + + /** The connection is asked only where a state does not already say the connection is gone. */ + @Test + public void testTheConnectionIsAskedWhetherTheDriverClosedIt() throws Exception + { + final Connection closed = mock(Connection.class); + when(closed.isClosed()).thenReturn(true); + final Connection alive = mock(Connection.class); + when(alive.isClosed()).thenReturn(false); + final Connection mute = mock(Connection.class); + when(mute.isClosed()).thenThrow(new SQLException("the connection cannot say")); + + assertTrue(JDBCStorage.isConnectionFailure(sql(596, "S0001"), closed), "a killed session was not recognized"); + assertFalse(JDBCStorage.isConnectionFailure(sql(2627, "23000"), alive), "a rejected statement was a drop"); + assertTrue(JDBCStorage.isConnectionFailure(sql(0, "08006"), alive), "class 08 needs no connection to say so"); + assertTrue(JDBCStorage.isConnectionFailure(sql(2627, "23000"), mute), "a connection that cannot answer"); + } + + /** A conflict is a rollback the engine completed before it answered, whichever phase reported it. */ + @Test + public void testAConflictIsReplayedFromEitherPhase() + { + final SQLException conflict = sql(0, "40001"); + assertEquals(JDBCStorage.replayReason(conflict, POSTGRES, false, false, false), "a conflict"); + assertEquals(JDBCStorage.replayReason(conflict, POSTGRES, true, false, false), "a conflict"); + } + + /** Everything else fails the operation, as it did before either replay existed. */ + @Test + public void testAFailureOfTheStatementIsNotReplayed() + { + assertNull(JDBCStorage.replayReason(sql(2627, "23000"), MSSQL, false, false, false)); + assertNull(JDBCStorage.replayReason(sql(2627, "23000"), MSSQL, true, false, false)); + } + /** The delay grows with the attempt, so that the replays outlast a contention lasting more than a few ms. */ @Test public void testRetryDelayGrowsAndStaysBounded() @@ -162,4 +298,18 @@ private static SQLException sql(int errorCode, String sqlState) { return new SQLException("synthetic failure", sqlState, errorCode); } + + /** The second failure as the next exception of the first, the way a driver chains the errors of one message. */ + private static SQLException chained(SQLException first, SQLException next) + { + first.setNextException(next); + return first; + } + + /** The second failure suppressed into the first, the way a failing close() joins the failure of an operation. */ + private static SQLException suppressing(SQLException failure, SQLException onRelease) + { + failure.addSuppressed(onRelease); + return failure; + } } diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java index b650301554..9d7cdac73c 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java @@ -45,6 +45,7 @@ import java.util.Collections; import java.util.List; import java.util.NoSuchElementException; +import java.util.Properties; import java.util.concurrent.Callable; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; @@ -56,6 +57,7 @@ import static org.testng.Assert.assertEquals; import static org.testng.Assert.assertFalse; import static org.testng.Assert.assertNotEquals; +import static org.testng.Assert.assertNotNull; import static org.testng.Assert.assertNull; import static org.testng.Assert.assertTrue; import static org.testng.Assert.fail; @@ -140,6 +142,40 @@ public void cleanUp() throws Exception { protected abstract String getJdbcUrl(); + /** + * The second property bounding a login is a socket read timeout on mysql, oracle and sql + * server: in force for the whole life of the connection it would fail every statement slower + * than it - an import batch, the statistics of a freshly loaded table - so it has to be lifted + * as soon as the login is through (#872). + */ + @Test(timeOut = 120000) + public void testLoginBoundDoesNotOutliveTheLogin() throws Exception { + final String url = createBackendCfg().getDBDirectory(); + final CachedConnection.ConnectDialect dialect = CachedConnection.ConnectDialect.of(url); + assertNotNull(dialect, "the dialect of the container is one this backend bounds: " + CachedConnection.safeUrl(url)); + System.setProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY, "2"); + try { + // the bound this lifts has to be in force first, or the assertion below holds of a + // connection that never carried one: established here with the very properties the + // borrow uses, and read back off the socket of this driver + final Properties bounding = new Properties(); + assertTrue(dialect.bound(url, bounding, 2), + "the read bound of the login is not set for this dialect, so there is nothing to lift"); + try (final Connection bounded = DriverManager.getConnection(url, bounding)) { + assertEquals(bounded.getNetworkTimeout(), 2000, + "the property this dialect names does not bound the socket of its login"); + } + + // a pooled connection would be handed back without being established again + CachedConnection.cached.invalidate(url); + try (final Connection con = CachedConnection.getConnection(url)) { + assertEquals(con.getNetworkTimeout(), 0, "the read bound of the login is still in force"); + } + } finally { + System.clearProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY); + } + } + private static ByteString key(int i) { return ByteString.valueOfUtf8(String.format("key%02d", i)); }