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 480c3e4a5e..22d63d4902 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 @@ -43,9 +43,56 @@ public class CachedConnection implements Connection { private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass(); + // What has been reported once already. Every one of these reports a setting rather than an + // event - a property that is not a number, a url no bound of this class can reach, a driver + // whose property names are not known here - so it does not become truer by being repeated, + // and every operation of the backend comes through here. + // Declared above every field whose initializer can reach warnOnce(): class variable + // initializers run in textual order (JLS 12.4.2), so a set declared below aliveBypassNanos + // would still be null the moment a property this class reports on carries a value worth + // warning about - a window longer than the ttl, or one that is not a number - and the report + // would leave the class uninitializable rather than merely configured oddly. + static final Set warnedOnce = ConcurrentHashMap.newKeySet(); + 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; + + /** + * The longest window this class uses, whatever {@value #ALIVE_BYPASS_PROPERTY} and the + * {@value #TTL_PROPERTY} it is clamped to say. The clamp to the ttl alone does not bound it: + * the ttl has no upper bound of its own, and with both set high enough the conversion to + * nanoseconds saturates - the window then outlasts every reading it is compared against, and + * no connection of the pool is ever validated again. An hour is already far past what this + * window is about, which is a connection that answered a moment ago. + *

+ * A compile-time constant, so that it holds its value wherever it is read from: the initializer + * of {@link #aliveBypassNanos} reaches it, and a field initialized in declaration order would + * still be 0 there if it were ever moved below (JLS 12.4.2). + */ + static final long MAX_ALIVE_BYPASS_MS = 60 * 60 * 1000L; + + // 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 @@ -111,17 +158,34 @@ public class CachedConnection implements Connection { private static final Map lastStallWarning = new ConcurrentHashMap<>(); private static final AtomicLong lastReadBoundWarning = new AtomicLong(); - // What has been reported once already. Every one of these reports a setting rather than an - // event - a property that is not a number, a url no bound of this class can reach, a driver - // whose property names are not known here - so it does not become truer by being repeated, - // and every operation of the backend comes through here. - static final Set warnedOnce = ConcurrentHashMap.newKeySet(); + /** + * When an operation last reported that the database had dropped a connection of a pool, as a + * {@link System#nanoTime()} reading per connection string. A connection proven alive before + * that moment is validated on its next borrow whatever the window says: whatever dropped one + * connection - a restart, a failover, a network that went away - dropped every connection + * established before it, and the window would otherwise hand out the rest of that generation + * one by one until the pool runs out of them. It is set by the caller that saw the failure + * ({@code JDBCStorage}), never by a validation that failed here: an idle connection the server + * reaped is a routine event, and it says nothing about the connection in use that the pool is + * about to hand out. + */ + private static final Map poolDistrustedAt = new ConcurrentHashMap<>(); final Connection parent; - static LoadingCache> cached = Caffeine.newBuilder() + // A deque handed out from the end it is returned to: the connection borrowed next is the one + // returned last, so under any load the pool keeps reusing its hottest connections instead of + // walking round every one it ever opened. That is what gives the window above anything to + // bypass - a connection reached only after a whole cycle of the pool has been idle far longer + // than the window - and it leaves the connections nothing needs at the cold end of the deque, + // where the per-connection idle expiry of #878 can find them. Until that lands, the cold end + // is reached only when the whole pool expires, after DEFAULT_TTL_MS with the backend idle. + // A deque takes one lock for both of its ends where the queue it replaces took one for each, + // so a borrow and a return no longer proceed side by side - against the round trip the window + // above saves, and the connect the reuse saves, that lock is not worth a FIFO handoff. + static LoadingCache> cached = Caffeine.newBuilder() .expireAfterAccess(Duration.ofMillis(getCacheTtlMillis())) - .removalListener((String key, BlockingQueue value, RemovalCause cause) -> { + .removalListener((String key, BlockingDeque value, RemovalCause cause) -> { for (CachedConnection con : value) { try { if (!con.isClosed()) { @@ -132,7 +196,7 @@ public class CachedConnection implements Connection { } } }) - .build(conStr -> new LinkedBlockingQueue<>()); + .build(conStr -> new LinkedBlockingDeque<>()); /** * Returns the time after which an idle pooled connection is closed, as configured by the @@ -142,6 +206,40 @@ private static long getCacheTtlMillis() { return getNonNegativeProperty(TTL_PROPERTY, DEFAULT_TTL_MS, "ms"); } + /** + * Returns the alive window, clamped to the {@value #TTL_PROPERTY} an idle pooled connection is + * kept for and to {@link #MAX_ALIVE_BYPASS_MS} behind it. A window longer than the ttl is one + * the pool cannot back: it goes on trusting the last answer of a connection past the point the + * pool would have closed and replaced it, which is a claim about a connection that is no longer + * there. The ttl has no upper bound of its own, though, so the second clamp is what keeps a + * value the unit conversion saturates on from leaving every connection of the pool trusted for + * the life of the server. + *

+ * Read at class initialization, like the ttl it is clamped to, so a value set after that + * changes neither. + */ + static long getAliveBypassMillis() { + long configured = getNonNegativeProperty(ALIVE_BYPASS_PROPERTY, DEFAULT_ALIVE_BYPASS_MS, "ms"); + final long ttl = getCacheTtlMillis(); + if (configured > ttl) { + warnOnce(ALIVE_BYPASS_PROPERTY + "=" + configured + ">" + ttl, + "The %s window of %d ms is longer than the %d ms of %s a pooled connection is kept for," + + " and is used as %d ms: a connection trusted for longer than the pool keeps it would" + + " be trusted past the point the pool closed it", + ALIVE_BYPASS_PROPERTY, configured, ttl, TTL_PROPERTY, ttl); + configured = ttl; + } + if (configured > MAX_ALIVE_BYPASS_MS) { // the ttl it was just clamped to has no upper bound of its own + warnOnce(ALIVE_BYPASS_PROPERTY + ">" + MAX_ALIVE_BYPASS_MS, + "The %s window of %d ms is longer than the %d ms this pool trusts a connection for at most," + + " and is used as %d ms: a longer one saturates the arithmetic it is compared in and" + + " leaves every connection of the pool trusted for the life of the server", + ALIVE_BYPASS_PROPERTY, configured, MAX_ALIVE_BYPASS_MS, MAX_ALIVE_BYPASS_MS); + return MAX_ALIVE_BYPASS_MS; + } + return configured; + } + /** * Returns the value of a numeric system property, ignoring a value that is not a non-negative * number in favor of the default. The unit is the one the property is read in, so that the @@ -478,6 +576,26 @@ private static boolean isBound(String value) { */ private final boolean poolable; + /** + * When this connection last answered the database, as a {@link System#nanoTime()} reading: + * established - the login and the two round trips that set it up have just answered - or + * validated. It is never stamped on the way back into the pool, although that is where a + * connection has most recently been used: {@link #close()} ends the transaction, and pgjdbc + * short-circuits both {@code rollback()} and {@code commit()} when the transaction state is + * IDLE, so on a borrow that issued no statement - {@code JDBCStorage.open()}, a configuration + * change that leaves the base DNs alone, an import of nothing - not a byte reaches the server + * and the stamp would prove nothing, while marking a connection the database may have dropped + * as the freshest one in the pool. Stamping proof rather than use makes the window mean + * "validated at most once per window", which is a claim this class can always back. + *

+ * It stands for the moment the connection was asked, not the moment its answer was + * filed: {@link #distrustPool} is compared against it as an ordering of two moments, and a + * proof that took a second to arrive would otherwise outlive a drop reported while it was + * still in flight. Reading it early only ever ages the proof, which costs a validation and + * never skips one. + */ + private volatile long lastKnownAliveNanos; + public CachedConnection(String connectionString, Connection parent) { this(connectionString, parent, true); } @@ -486,6 +604,7 @@ public CachedConnection(String connectionString, Connection parent) { this.connectionString = connectionString; this.parent = parent; this.poolable = poolable; + this.lastKnownAliveNanos = System.nanoTime(); } /** @@ -495,6 +614,22 @@ public CachedConnection(String connectionString, Connection parent) { * not answer into a hang rather than into an error the caller can report. */ static Connection getConnection(String connectionString) throws Exception { + return getConnection(connectionString, true); + } + + /** + * Borrows a connection, either trusting the alive window of {@value #ALIVE_BYPASS_PROPERTY} or + * validating whatever comes out of the pool. + * + * @param trusted false for a borrow nothing compensates a dropped connection on. What the + * window trades away is the connection that breaks inside it, and {@code JDBCStorage} takes + * that off the caller where it can - a write is replayed, a read tells the pool - but the + * borrows that open a backend, remove its files or start an import have neither: they issue + * their statements far from the borrow, and the one that opens a backend issues none at all, + * so a dropped connection would surface out of the {@code rollback()} of its release. Each of + * them is one borrow of a cold path, where the round trip the window saves is worth nothing. + */ + static Connection getConnection(String connectionString, boolean trusted) throws Exception { final ConnectDialect dialect = ConnectDialect.of(connectionString); reportUnknownDialect(connectionString, dialect); final long connectTimeoutSeconds = Math.min( @@ -508,7 +643,7 @@ static Connection getConnection(String connectionString) throws Exception { long backoffMs = 0; int attempts = 0; while (true) { - final CachedConnection pooled = poll(connectionString, waitMs, deadline); + final CachedConnection pooled = poll(connectionString, waitMs, deadline, trusted); if (pooled != null) { return pooled; } @@ -598,27 +733,32 @@ static long attemptSeconds(long connectTimeoutSeconds, long deadline) { * The validation of a connection costs a round trip, and the pool has no upper bound on the * number of them it holds, so draining a pool the database no longer answers is given the * deadline of the borrow as well: past it, establishing a connection is the faster answer. - * The connection in hand is always validated first, whatever the deadline says - a database at - * its connection limit has no other source of connections than the ones coming back, and one - * returned to the pool a moment before the deadline is the very connection this borrow waited - * for. Only a connection the database no longer answers is closed here. + * The connection in hand is always looked at first - trusted or validated, see + * {@link #isKnownAlive} - whatever the deadline says: a database at its connection limit has + * no other source of connections than the ones coming back, and one returned to the pool a + * moment before the deadline is the very connection this borrow waited for. Only a connection + * the database no longer answers is closed here. */ - private static CachedConnection poll(String connectionString, long waitMs, long deadline) throws InterruptedException { - CachedConnection con = cached.get(connectionString).poll(waitMs, TimeUnit.MILLISECONDS); + private static CachedConnection poll(String connectionString, long waitMs, long deadline, boolean trusted) + throws InterruptedException { + CachedConnection con = cached.get(connectionString).pollFirst(waitMs, TimeUnit.MILLISECONDS); while (con != null) { - if (isUsable(con)) { + if (isUsable(con, trusted)) { return con; } closeQuietly(con.parent); if (System.currentTimeMillis() >= deadline) { return null; } - con = cached.get(connectionString).poll(); + con = cached.get(connectionString).pollFirst(); } return null; } - private static boolean isUsable(CachedConnection con) { + private static boolean isUsable(CachedConnection con, boolean trusted) { + if (trusted && isKnownAlive(con)) { + return true; + } // The validation needs a bound of its own: isValid(0) means "no timeout" in the JDBC // contract, and a connection whose socket is half-open answers it no sooner than it // answers anything else. isValid(n) is not that bound on every driver either - the SQL @@ -632,6 +772,12 @@ private static boolean isUsable(CachedConnection con) { // avoid, and pooling it would hand out a connection carrying a bound of ours return false; } + // Read before the round trip rather than after it: this stamp is what distrustPool() is + // compared against, as an ordering of two moments. A validation is allowed + // VALIDATION_TIMEOUT_SECONDS, so a stamp filed once the answer is in can be younger than a + // drop another operation reported while it was still in flight - and the connection would + // then be trusted for the rest of the window by the very check that exists to stop it. + final long provenAt = System.nanoTime(); boolean usable; try { usable = con.isValid(VALIDATION_TIMEOUT_SECONDS); @@ -651,6 +797,7 @@ private static boolean isUsable(CachedConnection con) { "the connection is closed rather than pooled")) { return false; // it would carry the bound of the validation into every statement } + con.lastKnownAliveNanos = provenAt; return true; } @@ -659,6 +806,66 @@ private static boolean isUsable(CachedConnection con) { /** A connection {@link #boundValidation} could not bound, which may still carry the bound it failed to report. */ private static final int VALIDATION_BOUND_FAILED = -2; + /** + * Whether a connection can be handed out on the strength of the last answer it gave, without a + * round trip to ask for another. Three things have to hold: the window is on, the answer is + * younger than it, and nothing has reported since that the database dropped a connection of + * this pool. + *

+ * 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(later of the two) 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". Not Math.max: nanoTime() has no defined origin, so the readings are compared by + // their difference, the way every other comparison of one in this class is. + poolDistrustedAt.merge(connectionString, System.nanoTime(), + (reported, now) -> now - reported > 0 ? now : reported); + } + /** * 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 @@ -699,6 +906,10 @@ static CachedConnection connect(String connectionString, ConnectDialect dialect, final Properties properties = new Properties(); final boolean readBoundSet = dialect != null && connectTimeoutSeconds > 0 && dialect.bound(connectionString, properties, connectTimeoutSeconds); + // Read before the connect rather than after it, for the reason isUsable() reads it before + // the validation: the login answered somewhere inside this attempt, and a stamp taken once + // it returned could outlive a drop reported while it was still going on. + final long provenAt = System.nanoTime(); final Connection conNew = DriverManager.getConnection(connectionString, properties); boolean poolable = true; try { @@ -715,7 +926,9 @@ static CachedConnection connect(String connectionString, ConnectDialect dialect, closeQuietly(conNew); throw e; } - return new CachedConnection(connectionString, conNew, poolable); + final CachedConnection established = new CachedConnection(connectionString, conNew, poolable); + established.lastKnownAliveNanos = provenAt; + return established; } // The second bound of the login is a socket read timeout on mysql, oracle and sql server, in @@ -1232,7 +1445,9 @@ public void close() throws SQLException { closeQuietly(parent); return; } - cached.get(connectionString).add(this); + // 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 c94088c361..0309d69f13 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 @@ -41,6 +41,7 @@ import java.sql.*; import java.util.*; import java.util.concurrent.ConcurrentHashMap; +import java.util.function.Predicate; import static org.opends.server.backends.pluggable.spi.StorageUtils.addErrorMessage; import static org.opends.server.util.StaticUtils.stackTraceToSingleLineString; @@ -69,8 +70,17 @@ 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. */ - private static final int MAX_CAUSE_HOPS = 16; + /** + * Number of links walked when classifying a failure, also a guard against a chain long enough to matter. One + * number for three chains at once - the causes, the next exceptions and the suppressed exceptions are walked + * together and counted together - so it is set well above the depth a wrapped failure of this backend reaches: + * mssql-jdbc chains every error of one message it received through {@code setNextException}, and a budget spent + * on those would never reach the cause the wrapper carries. + */ + private static final int MAX_CHAIN_LINKS = 64; + + /** The budget of {@link #failureScope}, which walks to the end of the chains: see the comment above it. */ + private static final int EVERY_LINK = Integer.MAX_VALUE; /** SQL Server error number of the transaction picked as the deadlock victim: "Rerun the transaction". */ private static final int MSSQL_DEADLOCK_VICTIM = 1205; @@ -90,6 +100,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 +168,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(); } @@ -583,42 +620,25 @@ enum FailureScope { SESSION } - // What a failed stamp says about trying again. Both chains of the failure are walked: a driver - // reports the vendor error of a rejected statement as the next exception of a generic one at - // least as often as it reports it as the cause, and reading only one of the two would classify - // a lock timeout as a rejection, which leaves the tree unstamped for the life of the backend - // over a moment of contention. + // What a failed stamp says about trying again. Every chain of the failure is walked, by the walk + // every other classifier of this class uses: a driver reports the vendor error of a rejected + // statement as the next exception of a generic one at least as often as it reports it as the + // cause, the statement of a try-with-resources carries what its close() saw as a suppressed + // exception, and reading fewer of them than the others do would classify a connection that broke + // as a rejection - which leaves the tree unstamped for the life of the backend. Walked to its end + // rather than to MAX_CHAIN_LINKS: the seen set already terminates it, and the verdict weakens + // under truncation rather than simply going unnoticed - a SESSION past the budget would come back + // as TREE. The strongest verdict wins, so it is asked for in that order. static FailureScope failureScope(Throwable failure, Dialect dialect) { - FailureScope scope=FailureScope.TREE; - final Deque pending=new ArrayDeque<>(); - final Set seen=Collections.newSetFromMap(new IdentityHashMap()); - if (failure!=null) { - pending.push(failure); + if (firstLinkMatching(failure, WITH_THE_RELEASE, EVERY_LINK, + e -> scopeOf(e, dialect)==FailureScope.SESSION)!=null) { + return FailureScope.SESSION; } - while (!pending.isEmpty()) { - final Throwable e=pending.pop(); - if (!seen.add(e)) { // a driver that chains an exception back to itself must not loop this walk - continue; - } - if (e.getCause()!=null) { - pending.push(e.getCause()); - } - if (!(e instanceof SQLException)) { - continue; - } - final SQLException sqlException=(SQLException) e; - if (sqlException.getNextException()!=null) { - pending.push(sqlException.getNextException()); - } - final FailureScope found=scopeOf(sqlException, dialect); - if (found==FailureScope.SESSION) { // nothing further down either chain can weaken this one - return FailureScope.SESSION; - } - if (found==FailureScope.MOMENT) { - scope=FailureScope.MOMENT; - } + if (firstLinkMatching(failure, WITH_THE_RELEASE, EVERY_LINK, + e -> scopeOf(e, dialect)==FailureScope.MOMENT)!=null) { + return FailureScope.MOMENT; } - return scope; + return FailureScope.TREE; } // What one exception of the chain says on its own. @@ -781,7 +801,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 +841,43 @@ 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); + if (dropped) { + //told before the release rather than after it: a rollback that never reaches the server - + //which is what pgjdbc does with a transaction it left IDLE - leaves the connection poolable, + //so the release puts the dropped connection back at the head of the deque, and a borrow + //racing the distrust would be handed it unvalidated + distrustPool(); + } + 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 +898,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 +912,95 @@ 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) {} + } catch (SQLException ex) { + //joined to the failure rather than dropped: a rollback issued on a connection the + //database dropped is often the first place - and on a driver that reports a killed + //session as a plain vendor error, the only place - the drop is stated outright, and + //every classifier below reads the chains of this failure + e.addSuppressed(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); + if (dropped) { + //told before the release rather than after it, for the reason read() tells it there: a + //rollback that never reached the server leaves the connection poolable, so the release + //returns the dropped connection to the head of the deque, where a borrow racing this + //would be handed it unvalidated + distrustPool(); + } //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 - txn.stampSession.close(); + partlyCommitted=txn.partlyCommitted; + try { + txn.stampSession.close(); + } catch (RuntimeException e) { + //the stamp is a diagnostic aid and must not become the outcome of the write: an unchecked + //throw out of a driver's close() would otherwise replace the failure being unwound (JLS + //14.20.2) - the very one the replay is decided on and the only one that says what went + //wrong - or turn a transaction that has just committed into a failure of its own + if (failure!=null) { + failure.addSuppressed(e); + } else { + logger.trace(LocalizableMessage.raw("jdbc: unable to close the comment connection: %s", + stackTraceToSingleLineString(e))); + } + } } } 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; } } + //a drop the release of the connection reported still has to reach the pool, which has no other way + //of hearing of it. It is suppressed into the failure being unwound (JLS 14.20.3.1) rather than + //replacing it, which is what leaves e==failure and skips the branch above - and it is the very + //evidence replayReason() replays the attempt on, so the pool must not be told less than the loop + //acts on. The drop of the operation itself was reported before the release, above + if (!dropped && isConnectionFailure(failure)) { + 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, driver))); 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 +1015,168 @@ 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. It is read from the failure of the operation only, never from the release of the + * connection - see {@link #isRetryableConflict} - since the release runs after the outcome was decided and + * cannot make that claim for it. 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 one 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) { + return firstLinkMatching(failure, WITH_THE_RELEASE, JDBCStorage::saysTheConnectionIsGone)!=null; + } + + /** + * Whether {@link #firstLinkMatching} reads the suppressed exceptions along with the causes and the next + * exceptions. They are where the release of the connection reports what it saw - a rollback that failed as the + * attempt was unwound is suppressed into the failure being unwound (JLS 14.20.3.1) - so a question about the + * connection is asked of them, and a question about what the engine did with the transaction is not: the + * release runs after the outcome was decided, and cannot speak for it. + */ + private static final boolean WITH_THE_RELEASE=true; + private static final boolean WITHOUT_THE_RELEASE=false; + + /** + * The first {@link SQLException} of the chains of a failure that answers the given question, or null where none + * does. Every classifier of this class walks the failure this way, so that none of them reads a chain the others + * act on: what makes a write replayable must also be what the pool is told about and what the replay logs. + */ + private static SQLException firstLinkMatching(Throwable failure, boolean withTheRelease, + Predicate matches) { + return firstLinkMatching(failure, withTheRelease, MAX_CHAIN_LINKS, matches); + } + + /** The walk above, with the number of links it is allowed to look at. */ + private static SQLException firstLinkMatching(Throwable failure, boolean withTheRelease, int links, + Predicate matches) { + final Deque pending=new ArrayDeque<>(); + final Set seen=Collections.newSetFromMap(new IdentityHashMap()); + if (failure!=null) { + pending.push(failure); + } + while (!pending.isEmpty() && seen.size() - * The conflict is looked up along the whole cause chain because it reaches this class wrapped: a deadlock in - * {@code put} arrives as {@code StorageRuntimeException(SQLException)}, and a caller such as - * {@code EntryContainer.addEntry} may wrap it once more. + * The conflict is looked up along every chain of the failure, for the reason {@link #isConnectionFailure} walks + * them all: it reaches this class wrapped - a deadlock in {@code put} arrives as + * {@code StorageRuntimeException(SQLException)}, and a caller such as {@code EntryContainer.addEntry} may wrap it + * once more - and 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. *

* The standard class 40 states carry the conflict of most engines - 40P01 for PostgreSQL, 40001 for SQL Server * and for MySQL, whose driver replaces the server side HY000 of a deadlock and of a lock wait timeout with @@ -928,12 +1204,12 @@ static long retryDelayMillis(int attempt) { * that are excluded from that match. */ static boolean isRetryableConflict(Throwable t, String driver) { - for (int hop=0; t!=null && hop isConflict(e, driver))!=null; } private static boolean isConflict(SQLException e, String driver) { @@ -951,18 +1227,30 @@ private static boolean isConflict(SQLException e, String driver) { } /** - * Returns the SQLState and vendor error number of the first {@link SQLException} of the given cause chain, which - * is what identifies a conflict, so that a replay can be logged without a stack trace on every attempt. + * Returns the SQLState and vendor error number of the exception a replay was decided on, so that a replay can be + * logged without a stack trace on every attempt. That line is the only record a replay leaves, so it names the + * link the decision was taken on rather than the first {@link SQLException} of the failure: a write whose + * operation failed for its own reasons and whose release then reported a drop is replayed on the class 08 + * suppressed into it, and naming the state of the rejected statement instead would describe a replay that did + * not happen. Falls back to the first SQLException of the failure, and to the failure itself where it carries + * none. */ - static String conflictSummary(Throwable failure) { - Throwable t=failure; - for (int hop=0; t!=null && hop isConflict(e, driver)); + if (named==null) { + named=firstLinkMatching(failure, WITH_THE_RELEASE, JDBCStorage::saysTheConnectionIsGone); + } + if (named==null) { + // without the release, so that the line names the statement that failed rather than the rollback + // behind it: this is the fallback of a replay decided on isClosed(con) alone, where neither chain + // carries a verdict, and the walk reaches the suppressed exceptions before the cause + named=firstLinkMatching(failure, WITHOUT_THE_RELEASE, e -> true); + } + return named==null + ? String.valueOf(failure) + : "SQLState "+named.getSQLState()+", error "+named.getErrorCode()+": "+named.getMessage(); } static final byte[] NULL=new byte[]{(byte)0}; @@ -1060,6 +1348,18 @@ private final class WriteableTransactionTransactionImpl extends ReadableTransact // write() (and by ImporterImpl.close()) when the transaction is done with. final StampSession stampSession=new StampSession(); + /** + * Whether this transaction has committed part of its own work, which takes the attempt out of the + * replay of {@link JDBCStorage#write}: what it did no longer rolls back as a whole, and a + * {@link WriteOperation} is only idempotent in the database. + *

+ * Raised by {@link #commitStatement} alone, which is what every statement of this transaction that + * commits goes through - never once for a method that may issue one: a catalog read deciding that the + * statement is not needed commits nothing, and a transaction the engine rolled back whole is still worth + * replaying. Which side of the statement the flag goes up on is the engine's answer, see there. + */ + boolean partlyCommitted; + public WriteableTransactionTransactionImpl(Connection con) { super(con); //captured once rather than read per operation: the access mode of the storage is mutable state - @@ -1075,6 +1375,36 @@ void checkReadOnly() { } } + /** + * Issues a statement that ends in a commit, raising {@link #partlyCommitted} at the moment the attempt + * stops rolling back as a whole. + *

+ * mysql and oracle commit before a DDL statement whether asked to or not, so there the work behind it is + * committed by the statement itself and the flag has to be up before it is issued: the statement that + * fails has committed everything before it just as surely as the one that succeeds. postgresql and sql + * server run DDL inside the transaction, and a DML statement commits of its own accord nowhere - one that + * fails there has committed nothing, {@link JDBCStorage#write} rolls the attempt back whole, and a flag + * raised in front of it would take a conflict the engine itself undid out of the replay. On those the + * flag goes up in front of the commit instead, which is the call that leaves the outcome of the + * transaction unknown when it fails. + * + * @param ddl whether the statement is a DDL one, which two of the four engines commit before + */ + private void commitStatement(String sql, boolean ddl) throws SQLException { + partlyCommitted|=ddl && commitsBeforeDdl(); + try (final PreparedStatement statement=con.prepareStatement(sql)) { + execute(statement); + partlyCommitted=true; // a commit that fails leaves the outcome unknown, which is no more replayable + con.commit(); + } + } + + /** Whether this engine commits the transaction before a DDL statement whether asked to or not. */ + private boolean commitsBeforeDdl() { + final String driverName=driverNameOf(con); + return driverName.contains("mysql") || driverName.contains("oracle"); + } + boolean isExistsTable(TreeName treeName) { final String tableName = getTableName(treeName); try { @@ -1114,10 +1444,16 @@ String getTableDialect() { public void openTree(TreeName treeName, boolean createOnDemand) { if (createOnDemand) { checkReadOnly(); + // Every statement below is a DDL that commits, and each raises partlyCommitted through + // commitStatement() rather than once for the method: every one of them is guarded by a + // catalog read, so on an existing backend this method issues nothing at all. Raising the + // flag for a catalog read that commits nothing would make the whole attempt unreplayable - + // the conflict replay of #867 as much as the drop replay, since replayReason() reads the + // flag before it asks anything else - and RootContainer.open() opens every tree of every + // base DN in a single write, whose first act is one of these. if (!isExistsTable(treeName)) { - try (final PreparedStatement statement=con.prepareStatement("create table "+getTableName(treeName)+" ("+getTableDialect()+")")){ - execute(statement); - con.commit(); + try { + commitStatement("create table "+getTableName(treeName)+" ("+getTableDialect()+")", true); }catch (SQLException e) { throw new StorageRuntimeException(e); } @@ -1126,19 +1462,21 @@ public void openTree(TreeName treeName, boolean createOnDemand) { final String driverName=driverNameOf(con); final String tableName=getTableName(treeName); if (driverName.contains("postgres")) { - try (final PreparedStatement statement=con.prepareStatement("create index if not exists k_"+tableName.substring("opendj_".length())+" on "+tableName+" (k)")){ - execute(statement); - con.commit(); + try { + // asked although postgresql has "create index if not exists": that statement commits + // whether it creates anything or not, and this is the engine of every default + // deployment - unguarded, it would take every write that opens a tree out of the + // conflict replay, RootContainer.open() and its ~25 trees per suffix included + if (!isExistsIndex(tableName,"k_"+tableName.substring("opendj_".length()))) { + commitStatement("create index if not exists k_"+tableName.substring("opendj_".length())+" on "+tableName+" (k)", true); + } }catch (SQLException e) { throw new StorageRuntimeException(e); } }else if (driverName.contains("mysql")) { try { if (!isExistsIndex(tableName,"k_"+tableName.substring("opendj_".length()))) { // mysql has no "create index if not exists" - try (final PreparedStatement statement=con.prepareStatement("create index k_"+tableName.substring("opendj_".length())+" on "+tableName+" (k)")){ - execute(statement); - con.commit(); - } + commitStatement("create index k_"+tableName.substring("opendj_".length())+" on "+tableName+" (k)", true); } }catch (SQLException e) { throw new StorageRuntimeException(e); @@ -1147,10 +1485,7 @@ public void openTree(TreeName treeName, boolean createOnDemand) { try { // oracle has no "create index if not exists"; unquoted identifiers are stored in uppercase if (!isExistsIndex(tableName.toUpperCase(),"k_"+tableName.substring("opendj_".length()))) { - try (final PreparedStatement statement=con.prepareStatement("create index k_"+tableName.substring("opendj_".length())+" on "+tableName+" (k)")){ - execute(statement); - con.commit(); - } + commitStatement("create index k_"+tableName.substring("opendj_".length())+" on "+tableName+" (k)", true); } }catch (SQLException e) { throw new StorageRuntimeException(e); @@ -1177,9 +1512,8 @@ boolean isExistsIndex(String tableName, String indexName) throws SQLException { public void clearTree(TreeName treeName) { checkReadOnly(); - try (final PreparedStatement statement=con.prepareStatement("delete from "+getTableName(treeName))){ - execute(statement); - con.commit(); + try { // the commit takes the attempt out of the replay: it commits the delete, and everything before it + commitStatement("delete from "+getTableName(treeName), false); }catch (SQLException e) { throw new StorageRuntimeException(e); } @@ -1189,9 +1523,8 @@ public void clearTree(TreeName treeName) { public void deleteTree(TreeName treeName) { checkReadOnly(); if (isExistsTable(treeName)) { - try (final PreparedStatement statement = con.prepareStatement("drop table " + getTableName(treeName))) { - execute(statement); - con.commit(); + try { + commitStatement("drop table " + getTableName(treeName), true); } catch (SQLException e) { throw new StorageRuntimeException(e); } @@ -1534,7 +1867,7 @@ public ImporterImpl() { } } try { - con = getConnection(); + con = getValidatedConnection(); }catch (Exception e){ throw new StorageRuntimeException(e); } diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java index 0caad175f2..c98f280910 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/CachedConnectionTestCase.java @@ -19,8 +19,14 @@ import org.testng.annotations.AfterClass; import org.testng.annotations.AfterMethod; import org.testng.annotations.BeforeClass; +import org.testng.annotations.BeforeMethod; +import org.testng.annotations.DataProvider; import org.testng.annotations.Test; +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.InputStream; +import java.lang.reflect.Field; import java.net.InetAddress; import java.net.ServerSocket; import java.sql.Connection; @@ -52,11 +58,13 @@ import static org.mockito.Mockito.inOrder; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; +import static org.mockito.Mockito.times; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; import static org.testng.Assert.assertEquals; import static org.testng.Assert.assertFalse; import static org.testng.Assert.assertNotNull; +import static org.testng.Assert.assertNotSame; import static org.testng.Assert.assertNull; import static org.testng.Assert.assertSame; import static org.testng.Assert.assertTrue; @@ -83,6 +91,9 @@ public class CachedConnectionTestCase extends DirectoryServerTestCase { private final StubDriver stub = new StubDriver(); + /** The window as this JVM was started with it, put back after every test that varies it. */ + private static final long CONFIGURED_ALIVE_BYPASS_NANOS = CachedConnection.aliveBypassNanos; + @BeforeClass public void registerStubDriver() throws Exception { DriverManager.registerDriver(stub); @@ -93,13 +104,26 @@ public void deregisterStubDriver() throws Exception { DriverManager.deregisterDriver(stub); } + /** + * Most of the tests below seed the pool by hand, and a connection built a moment ago is inside + * the alive window - they are about what the validation of a borrow does, so the window is off + * unless the test at hand is one of the window's own. + */ + @BeforeMethod + public void validateEveryBorrow() { + CachedConnection.aliveBypassNanos = 0; + } + @AfterMethod public void clearProperties() { System.clearProperty(CachedConnection.CONNECT_TIMEOUT_PROPERTY); System.clearProperty(CachedConnection.POOL_TIMEOUT_PROPERTY); + System.clearProperty(CachedConnection.TTL_PROPERTY); + System.clearProperty(CachedConnection.ALIVE_BYPASS_PROPERTY); // what has been reported once is remembered for the life of the jvm: left standing, the key // of one test is what the next one finds when it asserts that it reported something itself CachedConnection.warnedOnce.clear(); + CachedConnection.aliveBypassNanos = CONFIGURED_ALIVE_BYPASS_NANOS; } /** @@ -546,7 +570,7 @@ public void testValidationOfAPooledConnectionIsBoundedAtTheSocket() throws Excep final Connection pooled = mock(Connection.class); when(pooled.isValid(anyInt())).thenReturn(true); when(pooled.getNetworkTimeout()).thenReturn(0); - CachedConnection.cached.get(url).add(new CachedConnection(url, pooled)); + seedPool(url, pooled); final Connection borrowed = CachedConnection.getConnection(url); @@ -572,7 +596,7 @@ public void testAPooledConnectionThatCannotBeBoundedForItsValidationIsDiscarded( when(pooled.isValid(anyInt())).thenReturn(true); doThrow(new SQLException("the driver took the bound and then failed")) .when(pooled).setNetworkTimeout(any(Executor.class), anyInt()); - CachedConnection.cached.get(url).add(new CachedConnection(url, pooled)); + seedPool(url, pooled); final Connection fresh = mock(Connection.class); stub.answerWith(fresh); @@ -615,7 +639,7 @@ public void testValidationLeavesTheBoundOfTheConnectionStringAlone() throws Exce final Connection pooled = mock(Connection.class); when(pooled.isValid(anyInt())).thenReturn(true); when(pooled.getNetworkTimeout()).thenReturn(2000); - CachedConnection.cached.get(url).add(new CachedConnection(url, pooled)); + seedPool(url, pooled); assertNotNull(CachedConnection.getConnection(url)); @@ -639,7 +663,7 @@ public void testDrainOfThePoolStopsAtTheDeadline() throws Exception { Thread.sleep(500); // a database that no longer answers: every validation waits out its bound return false; }); - CachedConnection.cached.get(url).add(new CachedConnection(url, stale)); + seedPool(url, stale); } final Connection fresh = mock(Connection.class); stub.answerWith(fresh); @@ -658,7 +682,7 @@ public void testBrokenPooledConnectionIsDiscarded() throws Exception { final String url = StubDriver.PREFIX + "broken-pooled"; final Connection stale = mock(Connection.class); when(stale.isValid(anyInt())).thenReturn(false); - CachedConnection.cached.get(url).add(new CachedConnection(url, stale)); + seedPool(url, stale); final Connection fresh = mock(Connection.class); when(fresh.isValid(anyInt())).thenReturn(true); stub.answerWith(fresh); @@ -682,7 +706,7 @@ public void testAPooledConnectionWhoseValidationThrowsIsDiscarded() throws Excep final String url = StubDriver.PREFIX + "validation-unchecked"; final Connection broken = mock(Connection.class); when(broken.isValid(anyInt())).thenThrow(new IllegalStateException("driver internal")); - CachedConnection.cached.get(url).add(new CachedConnection(url, broken)); + seedPool(url, broken); final Connection fresh = mock(Connection.class); stub.answerWith(fresh); @@ -1273,8 +1297,7 @@ public void testAPooledConnectionIsNotDiscardedUnvalidatedAtTheDeadline() throws }); final Connection good = mock(Connection.class); when(good.isValid(anyInt())).thenReturn(true); - CachedConnection.cached.get(url).add(new CachedConnection(url, stale)); - CachedConnection.cached.get(url).add(new CachedConnection(url, good)); + seedPool(url, stale, good); final Connection fresh = mock(Connection.class); stub.answerWith(fresh); System.setProperty(CachedConnection.POOL_TIMEOUT_PROPERTY, "1"); @@ -1300,7 +1323,7 @@ public void testAConnectionOnItsWayOutIsNotGivenItsBoundBack() throws Exception final Connection reaped = mock(Connection.class); when(reaped.getNetworkTimeout()).thenReturn(0); when(reaped.isValid(anyInt())).thenReturn(false); - CachedConnection.cached.get(url).add(new CachedConnection(url, reaped)); + seedPool(url, reaped); final Connection fresh = mock(Connection.class); stub.answerWith(fresh); @@ -1333,6 +1356,387 @@ public void testAConnectionStillCarryingTheBoundOfItsLoginIsNotPooled() throws E "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"); + } + + /** + * A proof taken while the database was going away does not outlive the distrust that reported it. + *

+ * The stamp stands for the moment the connection was asked, not the moment its answer was filed: + * a validation is given {@link CachedConnection#VALIDATION_TIMEOUT_SECONDS}, and one that started + * before another operation reported a drop and returned after it would otherwise be the younger of + * the two. The connection would then be handed out unvalidated for the rest of the window - and + * LIFO puts it at the head of the deque, so it is the very one the next borrow takes - by the + * check that exists to stop exactly that. + */ + @Test(timeOut = 120000) + public void testAProofTakenWhileTheDatabaseWentAwayIsNotTrusted() throws Exception { + final String url = StubDriver.PREFIX + "proof-across-a-drop"; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); // nothing here ages out of the window + final AtomicInteger validations = new AtomicInteger(); + final Connection parent = mock(Connection.class); + // the database goes away while this validation is in flight: another operation of the backend + // reports the drop of its own connection before this one has answered + when(parent.isValid(anyInt())).thenAnswer(invocation -> { + CachedConnection.distrustPool(url); + validations.incrementAndGet(); + return true; + }); + stub.answerWith(parent); + + CachedConnection.getConnection(url).close(); // established and returned, proven by its login + CachedConnection.distrustPool(url); // an operation reports a drop: what the pool holds predates it + CachedConnection.getConnection(url).close(); // validated, and a second drop is reported while it is + + final Connection borrowed = CachedConnection.getConnection(url); + + assertEquals(validations.get(), 2, + "a connection was trusted on a proof that started before the drop it is compared against"); + assertSame(((CachedConnection) borrowed).parent, parent, "the connection answered and was still discarded"); + } + + /** + * 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 twice: to the idle time the pool keeps a connection for, since a window + * longer than that is one the pool can never back - the connection it was meant for is gone + * before it closes - and to {@link CachedConnection#MAX_ALIVE_BYPASS_MS} behind it, since the + * ttl has no upper bound of its own and a value the unit conversion saturates on would leave + * every connection of the pool trusted for the life of the server. + *

+ * About the value the class settles on at initialization: the field the pool reads is assigned + * once, so a ttl set after that changes neither it nor the idle time it was clamped to. + */ + @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"); + + // the ttl has no upper bound of its own, so the clamp to it does not bound the window either: both set + // to a value the conversion to nanoseconds saturates on would leave every connection of the pool + // trusted for the life of the server, which is the outcome this javadoc says the clamp rules out + System.setProperty(CachedConnection.TTL_PROPERTY, Long.toString(Long.MAX_VALUE)); + System.setProperty(CachedConnection.ALIVE_BYPASS_PROPERTY, Long.toString(Long.MAX_VALUE)); + assertEquals(CachedConnection.getAliveBypassMillis(), CachedConnection.MAX_ALIVE_BYPASS_MS, + "a window the ttl did not bound was left to saturate"); + } + + /** + * A setting worth warning about must leave the class usable. Both properties are read by the + * initializer of {@code aliveBypassNanos}, and both report an unusable value through the set of + * what has been said once already - which, declared below that initializer, would still be null + * when the initializer reaches it (JLS 12.4.2). A window longer than the ttl is exactly the + * tuning the javadoc of the property invites, and it would turn a log line into an + * ExceptionInInitializerError on the first borrow and a causeless NoClassDefFoundError on every + * one after it: no connection can be borrowed, so the backend cannot open at all. + *

+ * Asserted on the class loaded afresh rather than on this one, which was initialized long + * before the property was set. + */ + @Test(timeOut = 120000, dataProvider = "settingsWorthWarningAbout") + public void testASettingWorthWarningAboutStillInitializesTheClass(String ttl, String window, long expectedMillis) + throws Exception { + System.setProperty(CachedConnection.TTL_PROPERTY, ttl); + System.setProperty(CachedConnection.ALIVE_BYPASS_PROPERTY, window); + + final Class reloaded = loadedAfresh(CachedConnection.class); + + assertNotSame(reloaded, CachedConnection.class, "the class under test was not loaded afresh"); + final Field field = reloaded.getDeclaredField("aliveBypassNanos"); + field.setAccessible(true); + assertEquals(field.getLong(null), TimeUnit.MILLISECONDS.toNanos(expectedMillis), + "the window the reloaded class settled on"); + } + + @DataProvider + public Object[][] settingsWorthWarningAbout() { + return new Object[][]{ + // a window longer than the ttl: reported once and used as the ttl + {"15000", "60000", 15000L}, + // not a number, and negative: reported once and ignored in favour of the default + {"15000", "half a second", CachedConnection.DEFAULT_ALIVE_BYPASS_MS}, + {"15000", "-1", CachedConnection.DEFAULT_ALIVE_BYPASS_MS}, + // the ttl is read by the same initializer, and reports its own value the same way + {"30s", "500", 500L} + }; + } + + /** + * The class again, defined by a loader of this test rather than taken from the one that has + * already initialized it: a static initializer runs once per loader, and this is about what it + * does. Every other class is delegated to the parent, so the reloaded one shares the types it + * is written against. + */ + private static Class loadedAfresh(Class type) throws Exception { + final String name = type.getName(); + final ClassLoader parent = type.getClassLoader(); + final ClassLoader loader = new ClassLoader(parent) { + @Override + protected Class loadClass(String candidate, boolean resolve) throws ClassNotFoundException { + if (!name.equals(candidate)) { + return super.loadClass(candidate, resolve); + } + Class defined = findLoadedClass(candidate); + if (defined == null) { + final byte[] bytecode = bytecodeOf(candidate, parent); + defined = defineClass(candidate, bytecode, 0, bytecode.length); + } + if (resolve) { + resolveClass(defined); + } + return defined; + } + }; + return Class.forName(name, true, loader); + } + + private static byte[] bytecodeOf(String name, ClassLoader from) throws ClassNotFoundException { + try (final InputStream in = from.getResourceAsStream(name.replace('.', '/') + ".class")) { + if (in == null) { + throw new ClassNotFoundException(name); + } + final ByteArrayOutputStream bytecode = new ByteArrayOutputStream(); + final byte[] chunk = new byte[8192]; + for (int read; (read = in.read(chunk)) >= 0; ) { + bytecode.write(chunk, 0, read); + } + return bytecode.toByteArray(); + } catch (IOException e) { + throw new ClassNotFoundException(name, e); + } + } + private static SQLException tooManyConnections() { // 53300, too_many_connections, of the insufficient_resources class return new SQLException("sorry, too many clients already", "53300"); 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..ee1e112d18 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 @@ -15,25 +15,62 @@ */ package org.opends.server.backends.jdbc; +import org.forgerock.opendj.server.config.server.JDBCBackendCfg; import org.opends.server.DirectoryServerTestCase; +import org.opends.server.backends.pluggable.spi.AccessMode; import org.opends.server.backends.pluggable.spi.StorageRuntimeException; +import org.opends.server.backends.pluggable.spi.TreeName; +import org.opends.server.backends.pluggable.spi.WriteOperation; import org.opends.server.types.DirectoryException; +import org.testng.annotations.AfterClass; +import org.testng.annotations.BeforeClass; import org.testng.annotations.DataProvider; import org.testng.annotations.Test; +import java.sql.Connection; +import java.sql.DatabaseMetaData; +import java.sql.Driver; +import java.sql.DriverManager; +import java.sql.DriverPropertyInfo; +import java.sql.PreparedStatement; +import java.sql.ResultSet; import java.sql.SQLException; +import java.sql.SQLNonTransientConnectionException; +import java.sql.SQLRecoverableException; +import java.sql.Statement; +import java.util.Properties; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.logging.Logger; import static org.forgerock.i18n.LocalizableMessage.raw; import static org.forgerock.opendj.ldap.ResultCode.OTHER; +import static org.mockito.Mockito.any; +import static org.mockito.Mockito.anyBoolean; +import static org.mockito.Mockito.anyInt; +import static org.mockito.Mockito.anyString; +import static org.mockito.Mockito.doNothing; +import static org.mockito.Mockito.doThrow; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.startsWith; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; +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; +import static org.testng.Assert.fail; /** - * 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; + * and what {@code write()} itself does with that verdict, replay and pool alike. *

* Runs without a database: the failures the drivers report are reproduced as synthetic - * {@link SQLException}s carrying the same vendor error number and SQLState. + * {@link SQLException}s carrying the same vendor error number and SQLState, and the writes that carry them run + * against mocked connections handed out by a driver of this test. */ @Test(sequential = true) @SuppressWarnings("javadoc") @@ -45,6 +82,35 @@ public class JDBCStorageRetryTest extends DirectoryServerTestCase private static final String ORACLE = "oracle.jdbc.driver.T4CConnection"; private static final String POSTGRES = "org.postgresql.jdbc.PgConnection"; + /** The tree every write of this test opens; the table name behind it is a hash of this name. */ + private static final TreeName TREE = new TreeName("dc=example,dc=com", "id2entry"); + + private final StubDriver stub = new StubDriver(); + + /** Every test gets a pool of its own: the pools and the distrust of a pool are keyed by the url. */ + private final AtomicInteger pools = new AtomicInteger(); + + /** The statement a create of a test runs, so that a test can assert that it ran - or that it did not. */ + private PreparedStatement statements; + + /** The connection behind the pool of a test, so that a test can assert the statement it was asked to prepare. */ + private Connection engineConnection; + + /** + * Connections whose class names carry the engine the way the drivers' own do - pgjdbc's + * {@code org.postgresql.jdbc.PgConnection}, Connector/J's {@code com.mysql.cj.jdbc.ConnectionImpl}. That name + * is what {@code driverNameOf()} matches an engine on, and the name of a mock is derived from the type it + * mocks, so a mock of plain {@link Connection} reaches no engine branch of {@code openTree()} at all. Lowercase + * because the match is case sensitive. + */ + interface postgresConnection extends Connection + { + } + + interface mysqlConnection extends Connection + { + } + /** A failure whose cause chain is a cycle, to check that walking it terminates. */ private static final class SelfCausedException extends RuntimeException { @@ -115,6 +181,155 @@ 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"); + } + + /** + * A conflict is replayed on the strength of the engine having rolled the transaction back before it answered, + * so it is read from the failure of the operation and not from the release of the connection: a class 40 the + * release contributed - Oracle reports a transaction rolled back under it as ORA-02091, SQLState 40000 - would + * otherwise re-authorise the replay of a commit whose outcome is unknown, past the guard that exists for it. + * A drop is read from the release as well, which is the one place it is often stated at all. + */ + @Test + public void testAConflictIsNotReadFromTheReleaseOfTheConnection() + { + final SQLException onRelease = suppressing(sql(2627, "23000"), sql(0, "40000")); + assertFalse(JDBCStorage.isRetryableConflict(onRelease, POSTGRES), "a conflict was read from the release"); + assertNull(JDBCStorage.replayReason(onRelease, POSTGRES, true, false, false), + "a transaction the commit left in doubt was replayed"); + + // the same shape carrying a drop instead: read, since the release is where a drop is stated at all + assertTrue(JDBCStorage.isConnectionFailure(suppressing(sql(2627, "23000"), sql(0, "08006"))), + "a drop was not read from the release"); + } + + /** 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() @@ -143,23 +358,575 @@ public void testRetryDelayGrowsAndStaysBounded() public void testConflictSummaryNamesTheStateAndTheNumber() { final String summary = JDBCStorage.conflictSummary( - new DirectoryException(OTHER, raw("unchecked"), new StorageRuntimeException(sql(1205, "40001")))); + new DirectoryException(OTHER, raw("unchecked"), new StorageRuntimeException(sql(1205, "40001"))), POSTGRES); assertTrue(summary.contains("40001"), summary); assertTrue(summary.contains("1205"), summary); assertTrue(summary.contains("synthetic failure"), summary); } + /** + * That line is the only record a replay leaves, so it names the failure the replay was decided on. A write whose + * operation was rejected and whose release then reported a drop is replayed on the class 08 suppressed into the + * rejection, and naming the state of the rejected statement would describe a replay that did not happen. + */ + @Test + public void testConflictSummaryNamesTheFailureTheReplayWasDecidedOn() + { + final String summary = JDBCStorage.conflictSummary( + new StorageRuntimeException(suppressing(sql(2627, "23000"), sql(0, "08006"))), POSTGRES); + assertTrue(summary.contains("08006"), summary); + assertFalse(summary.contains("23000"), summary); + } + /** A failure carrying no SQLException at all, and a cyclic cause chain, still have to yield something loggable. */ @Test public void testConflictSummaryTerminatesWithoutASQLException() { - assertTrue(JDBCStorage.conflictSummary(new IllegalStateException("connection closed")).contains("closed")); - assertTrue(JDBCStorage.conflictSummary(new SelfCausedException()).contains("SelfCausedException")); - assertEquals(JDBCStorage.conflictSummary(null), "null"); + assertTrue(JDBCStorage.conflictSummary(new IllegalStateException("connection closed"), POSTGRES).contains("closed")); + assertTrue(JDBCStorage.conflictSummary(new SelfCausedException(), POSTGRES).contains("SelfCausedException")); + assertEquals(JDBCStorage.conflictSummary(null, POSTGRES), "null"); + } + + /** A statement that carries neither a conflict nor a drop is still the one the summary names. */ + @Test + public void testConflictSummaryFallsBackToTheFirstFailureOfTheChain() + { + final String summary = JDBCStorage.conflictSummary(new StorageRuntimeException(sql(2627, "23000")), POSTGRES); + assertTrue(summary.contains("23000"), summary); + + // the fallback names the statement, not the rollback of the release behind it: this is where a replay + // decided on the closed flag of the connection alone lands - neither chain carries a verdict of its own - + // and the walk reaches the suppressed exceptions of a failure before its cause + final StorageRuntimeException killedSession = new StorageRuntimeException(sql(596, "S0001")); + killedSession.addSuppressed(sql(0, "25P02")); + final String decidedOnTheConnection = JDBCStorage.conflictSummary(killedSession, MSSQL); + assertTrue(decidedOnTheConnection.contains("S0001"), decidedOnTheConnection); + assertFalse(decidedOnTheConnection.contains("25P02"), decidedOnTheConnection); + } + + /** + * The walk of a failure looks at a bounded number of links: mssql-jdbc chains every error of one message it + * received through {@code setNextException}, and a budget spent on those would never reach the cause a wrapper + * carries. Pinned from both sides - a drop on the last link of the budget is found and one link further is not + * - since a number nothing pins drifts unnoticed in either direction. + */ + @Test + public void testTheWalkOfAFailureStopsAtItsBudget() + { + assertTrue(JDBCStorage.isConnectionFailure(chainEndingInADrop(64)), "a drop on the last link of the budget"); + assertFalse(JDBCStorage.isConnectionFailure(chainEndingInADrop(65)), "a drop past the budget was walked to"); + } + + /** + * Opening a tree that is already there commits nothing, so the attempt stays replayable. The create table is + * guarded by a catalog read, and so is the create index on every engine but postgresql, so on an existing + * backend {@code openTree(name, true)} issues no statement at all - while + * {@code RootContainer.open()} opens every tree of every base DN in a single write whose first act is one of + * these. A flag raised on the catalog read alone would leave that write unreplayable for the life of the + * backend, the conflict replay of #867 included: {@code replayReason()} reads the flag before anything else. + */ + @Test + public void testOpeningAnExistingTreeLeavesTheAttemptReplayable() throws Exception + { + final JDBCStorage storage = storageOverACatalogHolding(true); + final AtomicInteger attempts = new AtomicInteger(); + + storage.write(txn -> { + txn.openTree(TREE, true); + if (attempts.incrementAndGet() == 1) + { + throw new StorageRuntimeException(sql(0, "40001")); + } + }); + + assertEquals(attempts.get(), 2, "a transaction that committed nothing was not replayed"); + verify(statements, never()).executeUpdate(); + } + + /** + * A tree that had to be created did commit - the create table commits, and mysql and oracle commit before a DDL + * statement of their own accord - so the attempt is out of the replay whatever the failure says: a + * {@link WriteOperation} is only idempotent in the database, and {@code RootContainer.open()} replayed after the + * trees of the first base DN were created registers that base DN a second time. + */ + @Test + public void testCreatingATreeTakesTheAttemptOutOfTheReplay() throws Exception + { + final JDBCStorage storage = storageOverACatalogHolding(false); + final AtomicInteger attempts = new AtomicInteger(); + + try + { + storage.write(txn -> { + txn.openTree(TREE, true); + attempts.incrementAndGet(); + throw new StorageRuntimeException(sql(0, "40001")); + }); + fail("a transaction that had committed a create table was replayed"); + } + catch (StorageRuntimeException expected) + { + assertTrue(JDBCStorage.isRetryableConflict(expected, POSTGRES), "the conflict was not the failure raised"); + } + assertEquals(attempts.get(), 1, "a transaction that committed part of its work was replayed"); + verify(statements).executeUpdate(); + } + + /** + * The rollback that unwinds a failed attempt is often the first place a drop is stated outright, and on a + * driver that reports a killed session as a plain vendor error it is the only one. It is joined to the failure + * being unwound rather than dropped on the floor, so that the classifiers below read it: without it the attempt + * would lean on the driver having flipped its closed flag already, and a driver that has not gives neither the + * replay nor the distrust. + */ + @Test + public void testTheRollbackOfAFailedAttemptIsNotSwallowed() throws Exception + { + final long window = CachedConnection.aliveBypassNanos; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + try + { + final Connection pooled = mock(Connection.class); + when(pooled.isValid(anyInt())).thenReturn(true); + final Connection dropped = mock(Connection.class); + when(dropped.isValid(anyInt())).thenReturn(true); + when(dropped.isClosed()).thenReturn(false); // the driver has not flipped its flag yet + + final JDBCStorage storage = storageOver(pooled, dropped); + final Connection first = storage.getConnection(); + final Connection second = storage.getConnection(); + first.close(); + second.close(); + // proven alive by the connect itself, and inside the window ever since: nothing has validated + verify(dropped, never()).isValid(anyInt()); + + // only the rollback that unwinds the attempt says the connection is gone: the release behind it + // goes through, so the dropped connection is back at the head of the pool - where the replay + // borrows it again - with nothing else to report what it saw + doThrow(new SQLException("connection reset", "08006")).doNothing().when(dropped).rollback(); + + final AtomicInteger attempts = new AtomicInteger(); + storage.write(txn -> { + if (attempts.incrementAndGet() == 1) + { + throw new StorageRuntimeException(sql(596, "S0001")); // a killed session, as mssql-jdbc reports it + } + }); + + assertEquals(attempts.get(), 2, "the drop the rollback reported was not replayed"); + // the distrust reached the pool: the borrow of the replay validated instead of trusting the + // last answer of a connection that predates the drop + verify(dropped, times(1)).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + finally + { + CachedConnection.aliveBypassNanos = window; + } + } + + /** + * A drop the release of the connection reported reaches the pool as well as the replay. It is suppressed into + * the failure of the operation (JLS 14.20.3.1) rather than replacing it, so the attempt sees it only on the + * chains of that failure - and the pool has no other way of hearing of it: the rest of that generation would + * otherwise be handed out unvalidated one by one until the pool runs out of it. + */ + @Test + public void testADropReportedByTheReleaseReachesThePool() throws Exception + { + final long window = CachedConnection.aliveBypassNanos; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + try + { + final Connection pooled = mock(Connection.class); + when(pooled.isValid(anyInt())).thenReturn(true); + final Connection released = mock(Connection.class); + when(released.isValid(anyInt())).thenReturn(true); + + final JDBCStorage storage = storageOver(pooled, released); + // both are proven alive and back in the pool; the one released last is the one the write borrows + final Connection first = storage.getConnection(); + final Connection second = storage.getConnection(); + first.close(); + second.close(); + + // from here the database has dropped the connection at the head of the pool: the operation is + // rejected for its own reasons, the rollback that unwinds the attempt goes through, and the release + // behind it is where the drop surfaces. Chained, so that the drop lands on the second rollback: an + // unchained stub fails the first one - the rollback of the attempt - and pins the sibling test above + doNothing().doThrow(new SQLException("connection reset", "08006")).when(released).rollback(); + + final AtomicInteger attempts = new AtomicInteger(); + storage.write(txn -> { + if (attempts.incrementAndGet() == 1) + { + throw new StorageRuntimeException(sql(2627, "23000")); + } + }); + + assertEquals(attempts.get(), 2, "the drop suppressed into the failure was not replayed"); + // the return to the pool that seeded it, the rollback of the attempt, and the release behind it - which + // is the one that reported, since the stub above lets the rollback of the attempt through + verify(released, times(3)).rollback(); + // the distrust reached the pool from the release: the borrow of the replay validated instead of + // trusting the last answer of a connection established before the drop + verify(pooled).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + finally + { + CachedConnection.aliveBypassNanos = window; + } + } + + /** + * A read is never replayed - two of the read operations of this server are not idempotent - but a drop it ran + * into still has to reach the pool, which has no other way of hearing of one: a borrow inside the window asks + * the database nothing, so the statement that broke is the only place the drop is ever seen. The release of + * the connection counts as such a statement: its rollback is the one round trip a read that found nothing + * makes. + */ + @Test + public void testADropAReadRanIntoReachesThePool() throws Exception + { + final long window = CachedConnection.aliveBypassNanos; + CachedConnection.aliveBypassNanos = TimeUnit.HOURS.toNanos(1); + try + { + final Connection pooled = mock(Connection.class); + when(pooled.isValid(anyInt())).thenReturn(true); + final Connection released = mock(Connection.class); + when(released.isValid(anyInt())).thenReturn(true); + + final JDBCStorage storage = storageOver(pooled, released); + final Connection first = storage.getConnection(); + final Connection second = storage.getConnection(); + first.close(); + second.close(); + // both are proven alive and inside the window: nothing has validated + verify(released, never()).isValid(anyInt()); + + // the read is rejected for its own reasons, and the release behind it - a read issues no rollback of its + // own - is where the connection the database dropped says so + doThrow(new SQLException("connection reset", "08006")).when(released).rollback(); + try + { + storage.read(txn -> { + throw new StorageRuntimeException(sql(2627, "23000")); + }); + fail("the failure of the read was swallowed"); + } + catch (StorageRuntimeException expected) + { + assertTrue(JDBCStorage.isConnectionFailure(expected), "the drop of the release did not reach the failure"); + } + + storage.getConnection().close(); // the borrow that follows it validates instead of trusting + + verify(pooled).isValid(CachedConnection.VALIDATION_TIMEOUT_SECONDS); + } + finally + { + CachedConnection.aliveBypassNanos = window; + } + } + + /** + * The create index of the postgres branch is asked of the catalog first, although postgresql has "create index + * if not exists": that statement commits whether it creates anything or not, and unguarded it would take every + * write that opens a tree out of the replay - {@code RootContainer.open()} and its ~25 trees per suffix + * included. + */ + @Test + public void testThePostgresIndexIsAskedOfTheCatalogBeforeItIsCreated() throws Exception + { + final JDBCStorage storage = storageOverAnEngine(postgresConnection.class, true); + final AtomicInteger attempts = new AtomicInteger(); + + storage.write(txn -> { + txn.openTree(TREE, true); + if (attempts.incrementAndGet() == 1) + { + throw new StorageRuntimeException(sql(0, "40001")); + } + }); + + assertEquals(attempts.get(), 2, "a transaction that committed nothing was not replayed"); + verify(statements, never()).executeUpdate(); + } + + /** + * postgresql runs DDL inside the transaction, so a create index the engine rolled back has committed nothing: + * {@code write()} rolls the attempt back whole and replays it. Raising the flag in front of the statement - + * which is what mysql and oracle need, since they commit before a DDL of their own accord - would turn a + * deadlock the engine itself undid into a hard failure of the open. + */ + @Test + public void testACreateIndexPostgresRolledBackLeavesTheAttemptReplayable() throws Exception + { + final JDBCStorage storage = storageOverAnEngine(postgresConnection.class, false); + when(statements.executeUpdate()).thenThrow(sql(0, "40P01")).thenReturn(0); + final AtomicInteger attempts = new AtomicInteger(); + + storage.write(txn -> { + attempts.incrementAndGet(); + txn.openTree(TREE, true); + }); + + assertEquals(attempts.get(), 2, "a create index the engine rolled back was not replayed"); + verify(engineConnection, times(2)).prepareStatement(startsWith("create index if not exists k_")); + } + + /** + * mysql commits before a DDL statement whether asked to or not, so a create index that failed there has + * committed everything the transaction did before it just as surely as one that succeeded: the attempt is out + * of the replay whatever the failure says. + */ + @Test + public void testACreateIndexMysqlCommittedBeforeTakesTheAttemptOutOfTheReplay() throws Exception + { + final JDBCStorage storage = storageOverAnEngine(mysqlConnection.class, false); + when(statements.executeUpdate()).thenThrow(sql(1213, "40001")); + final AtomicInteger attempts = new AtomicInteger(); + + try + { + storage.write(txn -> { + attempts.incrementAndGet(); + txn.openTree(TREE, true); + }); + fail("a transaction whose create index had committed before it was replayed"); + } + catch (StorageRuntimeException expected) + { + assertTrue(JDBCStorage.isRetryableConflict(expected, MYSQL), "the conflict was not the failure raised"); + } + assertEquals(attempts.get(), 1, "an attempt that committed part of its work was replayed"); + verify(engineConnection).prepareStatement(startsWith("create index k_")); + } + + /** + * The connection the tree names are stamped on is closed as the attempt is unwound, and an unchecked throw out + * of a driver's {@code close()} there would replace the exception being unwound (JLS 14.20.2) - the very one + * the replay is decided on, and the only one that says what went wrong. The stamp is a diagnostic aid: it is + * joined to the failure instead, and the replay goes ahead. + */ + @Test + public void testAFailingCommentConnectionDoesNotReplaceTheFailureOfTheWrite() throws Exception + { + final Connection stamp = mock(Connection.class); + when(stamp.createStatement()).thenReturn(mock(Statement.class)); // the lock bound of the stamp session + // the readback of the stored comment fails, so the stamp is given up on - with its connection open + when(stamp.prepareStatement(anyString())).thenThrow(new SQLException("no readback in this test", "42000")); + doThrow(new IllegalStateException("the driver threw out of close()")).when(stamp).close(); + final JDBCStorage storage = storageOverAnEngine(postgresConnection.class, true, stamp); + final AtomicInteger attempts = new AtomicInteger(); + + storage.write(txn -> { + txn.openTree(TREE, true); // opens the stamp session, which is closed as this attempt is unwound + if (attempts.incrementAndGet() == 1) + { + throw new StorageRuntimeException(sql(0, "40001")); + } + }); + + assertEquals(attempts.get(), 2, "the failure of the comment connection replaced the conflict being unwound"); + verify(stamp).close(); + } + + @BeforeClass + public void registerStubDriver() throws Exception + { + DriverManager.registerDriver(stub); + } + + @AfterClass + public void deregisterStubDriver() throws Exception + { + DriverManager.deregisterDriver(stub); + } + + /** + * A storage whose pool hands out one connection of this test, over a catalog that either holds the table of + * {@link #TREE} or does not. The connection is a mock of no recognized driver, which is how the engines that + * guard their create index - and mssql, which has none - reach {@code openTree}. + */ + private JDBCStorage storageOverACatalogHolding(boolean theTable) throws Exception + { + final Connection con = mock(Connection.class); + final JDBCStorage storage = storageOver(con); + + statements = mock(PreparedStatement.class); + final String tableName = storage.getTableName(TREE); + final DatabaseMetaData metaData = mock(DatabaseMetaData.class); + // a result set of its own per call: the catalog is asked once per attempt, and a replayed attempt + // reading a result set the previous one had already walked to its end would find no table there + when(metaData.getTables(any(), any(), any(), any())).thenAnswer(invocation -> { + final ResultSet tables = mock(ResultSet.class); + when(tables.next()).thenReturn(theTable, false); + when(tables.getString("TABLE_NAME")).thenReturn(tableName); + return tables; + }); + + when(con.isValid(anyInt())).thenReturn(true); + when(con.getMetaData()).thenReturn(metaData); + when(con.prepareStatement(anyString())).thenReturn(statements); + return storage; + } + + /** + * A storage whose pool hands out one connection of the given engine, over a catalog holding the table of + * {@link #TREE} and either holding its {@code k_} index or not. The index guard and the statement behind it + * are the branches {@code openTree()} takes per engine, and a mock of plain {@link Connection} reaches none + * of them - so the name the mock ends up with is asserted here rather than assumed. + */ + private JDBCStorage storageOverAnEngine(Class engine, boolean theIndex, + Connection... behind) throws Exception + { + final Connection con = mock(engine); + final String engineName = engine.getSimpleName().replace("Connection", ""); + assertTrue(JDBCStorage.driverNameOf(con).contains(engineName), + "a mock of " + engine.getSimpleName() + " reaches no " + engineName + " branch: " + + JDBCStorage.driverNameOf(con)); + engineConnection = con; + // the connections behind it answer the connects the pool does not make: the stamp of a tree name opens one + // of its own, straight through the driver, since the caller of openTree() is holding a pooled connection + final Connection[] answers = new Connection[behind.length + 1]; + answers[0] = con; + System.arraycopy(behind, 0, answers, 1, behind.length); + final JDBCStorage storage = storageOver(answers); + + statements = mock(PreparedStatement.class); + final String tableName = storage.getTableName(TREE); + final DatabaseMetaData metaData = mock(DatabaseMetaData.class); + // a result set of its own per call, for the reason the catalog of the test above hands out one: a replayed + // attempt reading a result set the previous one had already walked to its end would find nothing there + when(metaData.getTables(any(), any(), any(), any())).thenAnswer(invocation -> { + final ResultSet tables = mock(ResultSet.class); + when(tables.next()).thenReturn(true, false); + when(tables.getString("TABLE_NAME")).thenReturn(tableName); + return tables; + }); + when(metaData.getIndexInfo(any(), any(), any(), anyBoolean(), anyBoolean())).thenAnswer(invocation -> { + final ResultSet indexes = mock(ResultSet.class); + when(indexes.next()).thenReturn(theIndex, false); + when(indexes.getString("INDEX_NAME")).thenReturn("k_" + tableName.substring("opendj_".length())); + return indexes; + }); + + when(con.isValid(anyInt())).thenReturn(true); + when(con.getMetaData()).thenReturn(metaData); + when(con.prepareStatement(anyString())).thenReturn(statements); + // the tree name the sweep stamps the table with runs on a connection of its own and is a diagnostic aid: a + // failure of it only logs, and this fixture is about the index statement rather than about the comment + when(con.createStatement()).thenThrow(new SQLException("no session statement in this test", "42000")); + return storage; + } + + /** + * A storage of a pool of its own, which connects to the given connections in turn and answers every connect + * beyond them with the last. Every test gets a url of its own: both the pools and the distrust of a pool are + * keyed by the connection string, so a shared one would carry the state of one test into the next. + */ + private JDBCStorage storageOver(Connection... connections) throws Exception + { + final JDBCBackendCfg cfg = mock(JDBCBackendCfg.class); + when(cfg.getDBDirectory()).thenReturn(StubDriver.PREFIX + pools.incrementAndGet()); + final JDBCStorage storage = new JDBCStorage(cfg, null); + storage.accessMode = AccessMode.READ_WRITE; + stub.answerWith(connections); + return storage; + } + + /** A driver of this test, so that the pool the write borrows from needs no database behind it. */ + private static final class StubDriver implements Driver + { + static final String PREFIX = "jdbc:opendj-retry-stub:"; + + private volatile Connection[] answers = new Connection[0]; + private final AtomicInteger connects = new AtomicInteger(); + + void answerWith(Connection... answers) + { + this.answers = answers; + this.connects.set(0); + } + + @Override + public Connection connect(String url, Properties info) + { + if (!acceptsURL(url) || answers.length == 0) + { + return null; + } + // the last one answers every connect beyond the ones named, so a pool that opens more than the + // test set up gets a working connection rather than a null the driver contract reads as "not mine" + return answers[Math.min(connects.getAndIncrement(), answers.length - 1)]; + } + + @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()); + } } 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; + } + + /** A chain of the given number of next exceptions whose last link is a connection that broke. */ + private static SQLException chainEndingInADrop(int links) + { + final SQLException head = sql(2627, "23000"); + SQLException tail = head; + for (int link = 2; link <= links; link++) + { + tail = chained(tail, sql(0, link == links ? "08006" : "23000")).getNextException(); + } + return head; + } + + /** 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/StampConnectionTestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/StampConnectionTestCase.java index 05b055ee02..25c5c141a7 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/StampConnectionTestCase.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/StampConnectionTestCase.java @@ -214,12 +214,13 @@ public void testFailureScopeTellsTheThreeApart() { /** * A driver reports the vendor error of a failed statement as the next exception of a generic - * one at least as often as it reports it as the cause. Reading only the cause chain classifies - * a lock timeout as a rejection, which leaves the tree unstamped until the next start over a - * moment of contention. + * one at least as often as it reports it as the cause, and the statement of a try-with-resources + * carries what its {@code close()} saw as a suppressed exception. Reading fewer chains than the + * classifiers of a write read classifies a lock timeout - or a connection that broke - as a + * rejection, which leaves the tree unstamped for the life of the backend. */ @Test - public void testFailureScopeWalksBothChains() { + public void testFailureScopeWalksEveryChain() { final SQLException reportedAsTheCause = new SQLException("statement failed", new SQLException("lock wait timeout exceeded", "HY000", 1205)); assertEquals(JDBCStorage.failureScope(reportedAsTheCause, JDBCStorage.Dialect.MYSQL), @@ -236,6 +237,13 @@ public void testFailureScopeWalksBothChains() { assertEquals(JDBCStorage.failureScope(connectionGone, JDBCStorage.Dialect.MYSQL), JDBCStorage.FailureScope.SESSION, "a connection exception on the next-exception chain was missed"); + // the close() of the statement is where a connection that broke under a stamp is often the + // only witness, and it joins the failure being unwound as a suppressed exception (JLS 14.20.3.1) + final SQLException reportedByTheClose = new SQLException("statement failed"); + reportedByTheClose.addSuppressed(new SQLException("connection closed", "08006")); + assertEquals(JDBCStorage.failureScope(reportedByTheClose, JDBCStorage.Dialect.MYSQL), + JDBCStorage.FailureScope.SESSION, "a connection exception suppressed into the failure was missed"); + // a driver that chains an exception back to itself must not make the walk loop final SQLException selfReferring = new SQLException("statement failed"); selfReferring.setNextException(selfReferring);