diff --git a/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java b/opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java index 328f7dd824..8b711a08a6 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 @@ -44,6 +44,7 @@ import java.util.*; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.Executor; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.Predicate; @@ -58,15 +59,25 @@ public class JDBCStorage implements org.opends.server.backends.pluggable.spi.Sto private static final int MAX_RETRIES = 10; /** - * Wall-clock budget the replays of a {@link #write} may spend, in nanoseconds. It is checked between attempts, - * so an attempt already running is never interrupted: the loop returns after at most this window plus one - * attempt. It bounds the conflicts that are slow to report, which {@link #MAX_RETRIES} alone does not - MySQL - * reports a lock wait timeout only after innodb_lock_wait_timeout, 50 s by default and not overridden here, so - * ten attempts would park a worker thread for eight minutes where a single one released it after 50 s. The - * deadlocks this retry exists for keep their full attempt budget, since every engine reports one in well under - * a second. + * Wall-clock budget the replays of a {@link #write} may spend, in nanoseconds, measured from the start of the + * first attempt. It is checked between attempts, so an attempt already running is never interrupted, and it + * applies from the first check, with the single exception {@link #grantedPastTheWindow} describes: a conflict + * its engine reports promptly is granted one replay whatever the clock says, because the lock wait that + * precedes such a conflict is charged to the attempt and is unbounded on three of the four engines here, so no + * window survives it. It bounds what {@link #MAX_RETRIES} alone does not - MySQL reports a lock wait timeout + * only after innodb_lock_wait_timeout, 50 s by default and not overridden here, so ten attempts would park a + * worker thread for eight minutes where one releases it after 50 s. + *

+ * What that costs, stated rather than left to be read off a test row: at the stock innodb_lock_wait_timeout a + * MySQL lock wait timeout is reported at ~50 s, which is past this window on the first check, so such a write + * is never replayed at all - the one conflict class of the set that a MySQL deployment sees most, and the one + * whose replay would most reliably succeed. It is the deliberate half of the trade the other half of which is + * #903: one bounded wait beats two, and a deployment that tunes innodb_lock_wait_timeout below this window + * gets its replays back. The trade only exists because nothing here bounds the attempt: with a session lock + * timeout on the transaction connection (#915) every wait would be shorter than this window, the tuned-down + * case would become the normal one, and this window would govern both classes with no grant needed at all. */ - private static final long MAX_RETRY_WINDOW_NANOS = 10L * 1000L * 1000L * 1000L; //10 s + private static final long RETRY_WINDOW_NANOS = TimeUnit.SECONDS.toNanos(10); /** Upper bound of the random delay before the second attempt, in milliseconds; it doubles with every attempt. */ private static final double BASE_SLEEP_ON_RETRY_MS = 50.0; @@ -75,15 +86,30 @@ public class JDBCStorage implements org.opends.server.backends.pluggable.spi.Sto private static final double MAX_SLEEP_ON_RETRY_MS = 1000.0; /** - * 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. + * Number of links walked by the questions that are not asked to the end of the chains: a guard against a chain + * long enough to matter, at the cost of what truncation costs each of them. 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. + *

+ * For the fallbacks of {@link #conflictSummary} truncation leaves a question unanswered and nothing more: the + * line reporting the replay names a less precise link, and no decision moves. For + * {@link #isConnectionFailure} it does weaken the verdict, which is the test {@link #EVERY_LINK} exists to + * apply: a class 08 link past this many links leaves {@code dropped} false in {@link #write}, so + * {@link #distrustPool} is not called and the pool keeps handing out - unvalidated - the connections it had + * established before the same restart or failover. That is what this walk did before #903 and it is left as it + * is here rather than widened along with the two below, since nothing about the grant of #903 depends on it; + * the budget is pinned from both sides by {@code testTheWalkOfAFailureStopsAtItsBudget}, which is where + * widening it would have to start. */ 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. */ + /** + * The budget of the two walks whose verdict would weaken rather than go unnoticed under truncation: + * {@link #failureScope} and {@link #conflictVerdict}. See the comments above them; the {@code seen} set of + * the walk terminates it either way. + */ private static final int EVERY_LINK = Integer.MAX_VALUE; /** SQL Server error number of the transaction picked as the deadlock victim: "Rerun the transaction". */ @@ -92,6 +118,15 @@ public class JDBCStorage implements org.opends.server.backends.pluggable.spi.Sto /** Oracle error number of a detected deadlock: ORA-00060, reported with SQLState 61000 rather than class 40. */ private static final int ORACLE_DEADLOCK_DETECTED = 60; + /** + * MySQL error number of a lock wait timeout, ER_LOCK_WAIT_TIMEOUT: the one conflict of the set an engine + * reports late rather than promptly. Connector/J maps it to the same class 40 state as a deadlock, so this + * number is not what matches it - it only tells the two apart, and only under a MySQL driver. That it repeats + * the literal of {@link #MSSQL_DEADLOCK_VICTIM} is the collision {@link #conflictVerdict} keys every vendor + * number by the driver for, and is stated there rather than again here. + */ + private static final int MYSQL_LOCK_WAIT_TIMEOUT = 1205; + /** * Class 40 states that are transaction rollbacks but must not be replayed. 40003 leaves the outcome of the * transaction unknown, so replaying an add that in fact committed would answer the client with @@ -537,6 +572,11 @@ static int clampSeconds(int seconds) { // below turns on a few milliseconds either side of the bound, and a mock statement cannot be made // to take a real second without the suite taking one too. Monotonic, so that a step of the wall // clock can neither lengthen nor shorten what a statement is measured to have taken. + // + // The retry window of write() is read off this same clock, once before the first attempt and once + // after each: what that window bounds is the whole run of attempts rather than each attempt on its + // own, which is a single startedAt outside the loop. #877 and #903 each added a clock of their own + // here, for the same reason and with the same body; this is the one they share. long nanoTime() { return System.nanoTime(); } @@ -1267,14 +1307,26 @@ static String driverNameOf(Connection con) { // The dialect behind a pooled connection, or null for an engine none of the statements of this // class fit: it is left unstamped and its statistics untouched rather than fed untested SQL. static Dialect dialectOf(Connection con) { - final String driverName=driverNameOf(con); - if (driverName.contains("postgres")) { + return dialectOf(driverNameOf(con)); + } + + /** + * The engine a driver class name names, or null for one this class does not recognise. Every question this + * class asks about the engine is keyed on this one answer - the column types, the upsert, the paging clause, + * whether a DDL statement commits, and the class of a conflict - so that they cannot disagree about a driver. + * A cascade of its own per question is how a deployment ends up given one engine's SQL and another engine's + * conflict class; what an unrecognised engine gets is a decision per question, taken and stated at each of + * them rather than falling out of the order the {@code contains} calls happen to be written in. + */ + static Dialect dialectOf(String driverName) { + final String name=String.valueOf(driverName); + if (name.contains("postgres")) { return Dialect.POSTGRES; - }else if (driverName.contains("mysql")) { + }else if (name.contains("mysql")) { return Dialect.MYSQL; - }else if (driverName.contains("oracle")) { + }else if (name.contains("oracle")) { return Dialect.ORACLE; - }else if (driverName.contains("microsoft")) { + }else if (name.contains("microsoft")) { return Dialect.MICROSOFT; } return null; @@ -1654,9 +1706,12 @@ final class CatalogSession implements Closeable { private WriteableTransactionTransactionImpl txn; // The moment the replay window of the write() this session belongs to runs out, as - // System.nanoTime() reads it - null where nothing above this session replays, which is the - // importer and nothing else. Boxed rather than given a sentinel: nanoTime() is documented to - // return an arbitrary long, so there is no reading of it that could stand for "no window". + // JDBCStorage.nanoTime() reads it - null where nothing above this session replays, which is the + // importer and nothing else. That clock and not System.nanoTime() directly: the window this is a + // reading of was taken from it, and the two are the same clock everywhere except the one place + // they would be compared as a mixed pair. Boxed rather than given a sentinel: nanoTime() is + // documented to return an arbitrary long, so there is no reading of it that could stand for + // "no window". private Long replayWindowEndsAt; /** @@ -1683,7 +1738,7 @@ private long budgetDeadline() { if (replayWindowEndsAt==null) { return Long.MAX_VALUE; } - final long leftNanos=replayWindowEndsAt-System.nanoTime(); + final long leftNanos=replayWindowEndsAt-nanoTime(); final long now=System.currentTimeMillis(); return leftNanos<=0 ? now : now+leftNanos/1_000_000L; } @@ -2944,10 +2999,15 @@ public T read(ReadOperation readOperation) throws Exception { * on the conflict exception of its own engine. The loop is bounded here, unlike PDBStorage: the database may be * shared with writers outside this server, so a conflict is not guaranteed to clear and failing the operation is * better than never returning. It is bounded twice - by {@link #MAX_RETRIES} attempts and by the - * {@link #MAX_RETRY_WINDOW_NANOS} wall-clock window - because an attempt is not guaranteed to be short: a - * conflict an engine reports only after its own lock wait timeout would otherwise multiply that wait by the - * attempt count. A conflict that slow consumes the whole window in one attempt and is not replayed, which is - * what master did with it. + * {@link #RETRY_WINDOW_NANOS} wall-clock window - because an attempt is not guaranteed to be short: a conflict + * an engine reports only after its own lock wait timeout would otherwise multiply that wait by the attempt + * count. The window alone is not enough either, in the other direction: it is shorter than the wait that + * precedes a conflict the engine reports promptly, so measured against such a conflict it does not bound that + * wait but only leaves the operation with no replay at all, which is what master did with the deadlock of + * issue #903. One replay is therefore granted to a prompt conflict whatever the clock says; see + * {@link #grantedPastTheWindow}. The window is checked between attempts, so an attempt already running is + * never interrupted: a conflicted operation holds its caller for the window plus one attempt, and a prompt + * conflict for two attempts when that is longer. *

* 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 @@ -2958,11 +3018,11 @@ public T read(ReadOperation readOperation) throws Exception { * 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)}. + * {@link #replayReason(Conflict, Throwable, boolean, boolean, boolean)}. */ @Override public void write(WriteOperation writeOperation) throws Exception { - final long giveUpAt=System.nanoTime()+MAX_RETRY_WINDOW_NANOS; + final long startedAt=nanoTime(); for (int attempt=1;;attempt++) { Exception failure=null; String driver=null; @@ -2978,8 +3038,12 @@ public void write(WriteOperation writeOperation) throws Exception { //the connect of the catalog is made inside this attempt and retries the way a borrow does, //up to the pool timeout - six times this window at the defaults. Left to its own deadline //it would spend a window it does not own and hand the loop a failure it has classified as - //replayable with nothing left to replay it in, so it is told where the window ends - txn.catalogSession.boundedAlsoBy(giveUpAt); + //replayable with nothing left to replay it in, so it is told where the window ends. The + //end of the window and not what is left of it: this is called once per attempt, and a + //window measured from the attempt that happens to be running would be spent over again by + //each of them. The grant of #903 is deliberately not passed on - it buys one more replay + //of the operation, not one more connect of the catalog inside it + txn.catalogSession.boundedAlsoBy(startedAt+RETRY_WINDOW_NANOS); try { writeOperation.run(txn); committing=true; @@ -3055,15 +3119,42 @@ public void write(WriteOperation writeOperation) throws Exception { 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 (reason==null || attempt>=MAX_RETRIES || System.nanoTime()-giveUpAt>=0) { + //Two questions, asked apart: what the failure is - which replayReason() answers, and which is the + //only place that reads committing, partlyCommitted and dropped - and whether another attempt is + //still allowed, which is the attempt count and the window of #903. Neither subsumes the other: a + //dropped connection is worth replaying and carries no conflict class, while a conflict past both + //bounds is not replayed however plainly it is one + //classified once and handed to every question below - the two decisions and the line reporting + //them: the walk of the chains is not free, and callers asking it apart could drift into + //disagreeing about the same failure. Not asked at all where the answer is discarded: replayReason() + //refuses a partly committed attempt its replay before anything about the failure matters, and that + //is also the path most likely to carry deeply wrapped chains, since RootContainer.open() commits + //DDL and raises the flag for the rest of the write + final ConflictVerdict verdict=partlyCommitted ? NOT_CLASSIFIED : conflictVerdict(failure,driver); + final String reason=replayReason(verdict.conflict,failure,committing,partlyCommitted,dropped); + //nanoTime()-startedAt is the overflow safe form of the elapsed time + final long elapsedNanos=nanoTime()-startedAt; + if (reason==null || !replayableWithin(attempt, elapsedNanos, verdict.conflict)) { 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 %s, attempt %d of %d: %s", - reason, attempt, MAX_RETRIES, conflictSummary(failure, driver))); + //one line per replay, since an add can emit nine of them and a stack trace each time reads as a failure. + //Both bounds are named, and the attempt count is the one that rarely fires: a replay usually stops + //because the window ran out, and a log naming only MAX_RETRIES leaves an operation that gave up at + //attempt 2 of a promised 10 with nothing saying why. Milliseconds rather than seconds, since the + //engines report a deadlock in a few of them and whole seconds would read "0" for most of a burst; and + //the one line that replays past its own window says so, rather than reading as a bound not honoured - + //asked of the predicate the loop just acted on rather than re-derived from the clock, so that the + //claim cannot outlive the grant that justifies it + if (logger.isWarnEnabled()) { + logger.warn(LocalizableMessage.raw( + "jdbc: replaying the transaction after %s, attempt %d of %d, %d ms elapsed of the %d ms window%s: %s", + reason, attempt, MAX_RETRIES, TimeUnit.NANOSECONDS.toMillis(elapsedNanos), + TimeUnit.NANOSECONDS.toMillis(RETRY_WINDOW_NANOS), + grantedPastTheWindow(attempt, elapsedNanos, verdict.conflict) + ? " (the first replay, granted past it)" : "", + conflictSummary(verdict, failure))); + } if (logger.isTraceEnabled()) { logger.trace("jdbc: the failure being replayed was %s", stackTraceToSingleLineString(failure)); } @@ -3086,9 +3177,9 @@ public void write(WriteOperation writeOperation) throws Exception { *

* 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 + * connection - see {@link #conflictVerdict} - 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}. *

@@ -3101,17 +3192,18 @@ public void write(WriteOperation writeOperation) throws Exception { * 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 conflict the class {@link #conflictVerdict} read from the failure, asked of it once by the caller * @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, + static String replayReason(Conflict conflict, Throwable failure, boolean committing, boolean partlyCommitted, boolean connectionClosed) { if (partlyCommitted) { return null; } - if (isRetryableConflict(failure, driver)) { + if (conflict!=Conflict.NONE) { return "a conflict"; } if (!committing && (connectionClosed || isConnectionFailure(failure))) { @@ -3184,6 +3276,27 @@ private static SQLException firstLinkMatching(Throwable failure, boolean withThe /** 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 SQLException[] found=new SQLException[1]; + walkLinks(failure, withTheRelease, links, e -> { + if (!matches.test(e)) { + return false; + } + found[0]=e; + return true; + }); + return found[0]; + } + + /** + * Hands every {@link SQLException} of the chains of a failure to the given reader, in walk order, until it + * says it has read enough. The single traversal of this class: a reader that can answer from the first link + * it matches stops here, and one that has to see them all - {@link #conflictVerdict}, which keeps the + * strongest class any of them carries - does not, so that neither has a walk of its own to drift from the + * other's. The {@code seen} set terminates the walk whatever budget it is given: a driver that chains an + * exception back to itself is walked once. + */ + private static void walkLinks(Throwable failure, boolean withTheRelease, int links, + Predicate readEnough) { final Deque pending=new ArrayDeque<>(); final Set seen=Collections.newSetFromMap(new IdentityHashMap()); if (failure!=null) { @@ -3209,11 +3322,10 @@ private static SQLException firstLinkMatching(Throwable failure, boolean withThe if (sqlException.getNextException()!=null) { pending.push(sqlException.getNextException()); } - if (matches.test(sqlException)) { - return sqlException; + if (readEnough.test(sqlException)) { + return; } } - return null; } /** @@ -3251,13 +3363,84 @@ static long retryDelayMillis(int attempt) { } /** - * Returns whether the given failure carries a transaction conflict that replaying the operation can resolve. + * The class of a failure. Whether it is a conflict at all is what decides that the operation is replayed; + * which of the remaining classes it is decides only whether the first replay is granted unconditionally, + * since the wait an engine spends before reporting a conflict is charged to the attempt that hit it. + *

+ * Declared in order of how much they restrict the replay, which is the order {@link #conflictVerdict} + * compares them in: the strongest class any link of a failure carries is the class of that failure. Only + * {@link #PROMPT} is granted the replay past the window, so every class this list gains - #915 adds one - + * has to be placed against that grant rather than merely appended. + */ + enum Conflict { + /** Not a conflict: no replay resolves it. */ + NONE, + /** A conflict reported as soon as the engine detects it, however long the attempt waited to reach it. */ + PROMPT, + /** + * A conflict under a driver none of the four engines is recognised in. Whether the engine bounded the + * wait that preceded it is not something this class can tell, and the grant of {@link #PROMPT} rests on + * knowing that it did not, so an unrecognised engine is refused it: see {@link #classOf}. + */ + UNKNOWN_ENGINE, + /** A conflict an engine reports only once a lock wait timeout of its own has elapsed. */ + AFTER_LOCK_WAIT + } + + /** + * The verdict of a failure nothing asked about, handed to the questions {@link #write} asks of a partly + * committed attempt: every one of them is answered by that flag alone, so its chains are never walked. It is + * not a claim that the failure carries no conflict - it may carry one, and is refused a replay either way. + */ + private static final ConflictVerdict NOT_CLASSIFIED=new ConflictVerdict(Conflict.NONE, null); + + /** + * The class of the conflict a failure carries and the link that class was read from, which are one answer + * rather than two: the line reporting a replay names the link the decision was taken on, and a summary that + * walked the chains again to find it could name a different one - see {@link #conflictSummary}. + */ + static final class ConflictVerdict { + final Conflict conflict; + /** Null where the failure carries no conflict at all, which is what {@link Conflict#NONE} says. */ + final SQLException link; + + ConflictVerdict(Conflict conflict, SQLException link) { + this.conflict=conflict; + this.link=link; + } + } + + /** + * Returns the class of the conflict the given failure carries, or {@link Conflict#NONE} if it carries none - + * which is what decides whether replaying the operation can resolve it - together with the link that class was + * read from. One walk of the chains that keeps the strongest class it meets, rather than one walk per class + * asked in the right order: asking per class is what let the two walks of the earlier form be given different + * budgets, and the ordering of an added class is then a rule its author has to find rather than one the enum + * states - see {@link Conflict}. *

* 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. + * least as often as it reports it as the cause. The suppressed links of the release are left out of it, for the + * reason {@link #replayReason} gives: the release runs after the outcome was decided. + *

+ * The strongest class in those chains wins rather than the first one found: a wrapper that carries a class + * 40 state of its own but no vendor number would otherwise downgrade the {@link Conflict#AFTER_LOCK_WAIT} of + * the {@link SQLException} it wraps, and hand a wait the engine already bounded a replay it does not need. + * That rule is deliberately not restricted to the wrapper it was introduced for, although the walk reaches + * links that are not ancestors of the operative failure - a deadlock whose chain also carries a lock wait + * timeout is classed by the timeout and loses the grant. The two errors are not equally costly to get wrong: + * granting a replay to a wait the engine had already bounded pays that bound a second time, while refusing + * one to a deadlock costs a replay the window was about to refuse anyway, wherever the bound that sibling + * names is longer than the window. So the class is read the conservative way, and the whole chain of a + * failure is evidence for it. + *

+ * Every link is looked at, rather than {@link #MAX_CHAIN_LINKS} of them, for the reason {@link #failureScope} + * walks to the end: the verdict weakens under truncation rather than simply going unnoticed. An + * {@link Conflict#AFTER_LOCK_WAIT} link past the budget with a bare class 40 link inside it comes back + * {@link Conflict#PROMPT}, and truncation there does not lose a replay - it grants one, which is the single + * thing this classification exists to refuse. The {@code seen} set terminates the walk regardless. *

* 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 @@ -3266,28 +3449,135 @@ static long retryDelayMillis(int attempt) { * reports a deadlock as ORA-00060 with SQLState 61000, and gives 1205 to a fatal "not a data file" error that * no replay can resolve, while 1205 is exactly the deadlock victim of SQL Server. The SQL Server number is * matched beyond its class 40 state because a deployment may add {@code xopenStates=true} to its connection - * URL, which reports the same deadlock as 42000. MySQL needs no number of its own, since its driver has already - * mapped both conditions into class 40; see {@link #NON_REPLAYABLE_ROLLBACK_STATES} for the two class 40 states - * that are excluded from that match. + * URL, which reports the same deadlock as 42000. MySQL needs no number of its own for the match, since its + * driver has already mapped both conditions into class 40 - its number is read by {@link #classOf} alone, and + * only to tell the two apart; see {@link #NON_REPLAYABLE_ROLLBACK_STATES} for the two class 40 states that are + * excluded from that match. + *

+ * The walk still stops as soon as its answer is final, but the class it stops at is the strongest one this + * engine can report - {@link #ceilingOf} - rather than the strongest one the enum declares. Only MySQL reports + * an {@link Conflict#AFTER_LOCK_WAIT}, so a walk stopping at that constant never stops early on the other + * three engines, nor under a driver none of them is recognised in: it reads every link of every failed write, + * a plain {@code 23000} from adding an entry that is already there included, on the driver whose chains are + * longest. The dialect is resolved once here for the same reason - {@link #classOf} and {@link #isConflict} + * would otherwise read it off the driver name twice for every link walked. + */ + static ConflictVerdict conflictVerdict(Throwable failure, String driver) { + final Dialect dialect=dialectOf(driver); + final Conflict ceiling=ceilingOf(dialect); + final Conflict[] strongest={Conflict.NONE}; + final SQLException[] link=new SQLException[1]; + walkLinks(failure, WITHOUT_THE_RELEASE, EVERY_LINK, e -> { + final Conflict conflict=classOf(e, dialect); + if (conflict.compareTo(strongest[0])>0) { + strongest[0]=conflict; + link[0]=e; + } + return strongest[0]==ceiling; + }); + return new ConflictVerdict(strongest[0], link[0]); + } + + /** + * The strongest class a conflict raised under the given engine can carry, which is where + * {@link #conflictVerdict} stops walking: nothing further along the chains can outrank it. It is the maximum + * of what {@link #classOf} returns for that dialect and has to be read together with it - a property of the + * engine rather than the last constant of {@link Conflict}, so that the class #915 adds cannot silently move + * the stop condition, and so that the walk of the three engines reporting no lock wait timeout of their own + * ends on the first conflict it meets rather than at the end of every chain. */ - static boolean isRetryableConflict(Throwable t, String driver) { - // without the suppressed exceptions, unlike isConnectionFailure(): a conflict is replayed whichever phase - // reported it, on the strength of the engine having rolled the transaction back before it answered - and - // the release of the connection runs after the outcome was decided and cannot make that claim. A class 40 - // raised there would otherwise replay a transaction commit() left in doubt, which is what the committing - // guard of replayReason() exists to prevent - return firstLinkMatching(t, WITHOUT_THE_RELEASE, e -> isConflict(e, driver))!=null; + static Conflict ceilingOf(Dialect dialect) { + if (dialect==null) { + return Conflict.UNKNOWN_ENGINE; + } + return dialect==Dialect.MYSQL ? Conflict.AFTER_LOCK_WAIT : Conflict.PROMPT; + } + + /** + * Returns the class of a single failure. The vendor number only refines a failure {@link #isConflict} has + * already matched and never widens that match, which the engines colliding on 1205 do not allow: the number is + * read here to tell the late conflict of MySQL from the deadlock its driver reports under the same state. + *

+ * A conflict raised under a driver {@link #dialectOf(String)} did not recognise is + * {@link Conflict#UNKNOWN_ENGINE}: still replayed, since replayability is what the class 40 state says and it + * says it whatever the engine, but not granted the replay past the window. The grant rests on knowing that + * the wait preceding the conflict was not bounded by the engine, and of an unrecognised engine that is not + * known. It is a MySQL-wire-compatible driver - MariaDB Connector/J, an Aurora- or Percona-branded one - + * that makes the difference concrete: it reports a lock wait timeout as 1205 under class 40 exactly as + * Connector/J does, this class would read the number only under a name carrying {@code mysql}, and granting + * a free replay there buys a second full {@code innodb_lock_wait_timeout}. Such a deployment does reach this + * code: a backend created under {@code com.mysql.cj.jdbc} and later opened through one of those drivers + * issues no DDL at all - every {@code create table} and {@code create index} of + * {@code openTree(createOnDemand)} is guarded by a catalog read - and its writes go down the ANSI branch of + * {@code upsert}, which is an {@code update} and an {@code insert}, not a statement a MySQL-wire engine + * refuses. The cost of the class is one replay of the window's own length for an engine whose conflicts are + * in fact prompt, which is the direction worth being wrong in; #915 removes the trade by bounding the + * attempt itself. + */ + private static Conflict classOf(SQLException e, Dialect dialect) { + if (!isConflict(e, dialect)) { + return Conflict.NONE; + } + if (dialect==null) { + return Conflict.UNKNOWN_ENGINE; + } + return dialect==Dialect.MYSQL && e.getErrorCode()==MYSQL_LOCK_WAIT_TIMEOUT + ? Conflict.AFTER_LOCK_WAIT : Conflict.PROMPT; } - private static boolean isConflict(SQLException e, String driver) { + /** + * Whether another attempt is still allowed: the bounds half of the decision {@link #write} takes after every + * attempt, asked of a failure {@link #replayReason} has already found worth replaying and made here apart + * from the clock so that it can be tested without a database. It is asked of the conflict class rather than + * of the failure because not every replayable failure carries one - a connection the database dropped is + * replayed on the evidence of the drop, and would be refused by a bound that first insisted on a class 40 + * state - and because {@code write()} has already read that class off the failure once. + *

+ * Replays are bounded by {@link #MAX_RETRIES} and by {@link #RETRY_WINDOW_NANOS} against the time elapsed + * since the first attempt began, with the one grant {@link #grantedPastTheWindow} states on top of them. + */ + static boolean replayableWithin(int attempt, long elapsedNanos, Conflict conflict) { + if (attempt>=MAX_RETRIES) { + return false; + } + if (grantedPastTheWindow(attempt, elapsedNanos, conflict)) { + return true; + } + return elapsedNanos + * Asked as a question of its own so that the line reporting the replay can name the bound that was actually + * applied instead of inferring it from the clock: {@code elapsed >= window} coincides with this grant only + * for as long as this stays the sole way past the window, and a line that keeps claiming "the first replay" + * after that would be describing a decision nobody took. + *

+ * {@code attempt==1} is a proxy and not the invariant: the invariant is that no clock can bound a wait + * nothing else bounds, and that holds on every attempt, not only the first. Widening the grant to all of them + * would leave {@link #MAX_RETRIES} as the only real cap, so it is held to one replay until the attempt itself + * carries a lock bound - see #915, which retires this method rather than widening it. + */ + static boolean grantedPastTheWindow(int attempt, long elapsedNanos, Conflict conflict) { + return attempt==1 && conflict==Conflict.PROMPT && elapsedNanos>=RETRY_WINDOW_NANOS; + } + + private static boolean isConflict(SQLException e, Dialect dialect) { final String state=String.valueOf(e.getSQLState()); if (state.startsWith("40") && !NON_REPLAYABLE_ROLLBACK_STATES.contains(state)) { return true; } - final String driverName=String.valueOf(driver); - if (driverName.contains("oracle")) { + if (dialect==Dialect.ORACLE) { return e.getErrorCode()==ORACLE_DEADLOCK_DETECTED; - } else if (driverName.contains("microsoft")) { + } else if (dialect==Dialect.MICROSOFT) { return e.getErrorCode()==MSSQL_DEADLOCK_VICTIM; } return false; @@ -3301,11 +3591,16 @@ private static boolean isConflict(SQLException e, String driver) { * 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. + *

+ * Asked of the verdict rather than of the failure and the driver, since {@link #write} - the only caller - has + * had the failure classified already: a form taking those two would walk the chains a second time to reach the + * verdict this one is handed. */ - static String conflictSummary(Throwable failure, String driver) { - // asked in the order replayReason() asks it, and of the same chains, so that the line names the link the - // decision was taken on rather than one that merely resembles it - SQLException named=firstLinkMatching(failure, WITHOUT_THE_RELEASE, e -> isConflict(e, driver)); + static String conflictSummary(ConflictVerdict verdict, Throwable failure) { + // the link the class was read from, handed over by the walk that read it rather than looked up again in + // the order that walk happens to use: repeated by hand, the two drift, and the line then names a link + // that merely resembles the one the decision was taken on + SQLException named=verdict.link; if (named==null) { named=firstLinkMatching(failure, WITH_THE_RELEASE, JDBCStorage::saysTheConnectionIsGone); } @@ -3359,7 +3654,7 @@ static byte[] db2real(byte[] db) { * Casting the parameter back to char keeps the comparison seekable. */ static String hashParam(Connection con) { - return driverNameOf(con).contains("microsoft") ? "cast(? as char(128))" : "?"; + return dialectOf(con)==Dialect.MICROSOFT ? "cast(? as char(128))" : "?"; } class ReadableTransactionImpl implements ReadableTransaction { @@ -3570,19 +3865,20 @@ private void commitStatement(String sql, boolean ddl) throws SQLException { /** 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"); + final Dialect dialect=dialectOf(con); + return dialect==Dialect.MYSQL || dialect==Dialect.ORACLE; } String getTableDialect() { - if (driverNameOf(con).contains("oracle")) { + final Dialect dialect=dialectOf(con); + if (dialect==Dialect.ORACLE) { return "h char(128),k raw(2000),v blob,primary key(h,k)"; - }else if (driverNameOf(con).contains("mysql")) { + }else if (dialect==Dialect.MYSQL) { return "h char(128),k varbinary(255),v longblob,primary key(h,k)"; - }else if (driverNameOf(con).contains("microsoft")) { + }else if (dialect==Dialect.MICROSOFT) { return "h char(128),k varbinary(max),v image,primary key(h)"; } - return "h char(128),k bytea,v bytea,primary key(h,k)"; + return "h char(128),k bytea,v bytea,primary key(h,k)"; // postgres, and an unrecognised engine with it } @Override @@ -3616,9 +3912,9 @@ public void openTree(TreeName treeName, boolean createOnDemand) { } } // CursorImpl iterates with "where k>? order by k" batches: primary key (h,k) cannot serve them - final String driverName=driverNameOf(con); + final Dialect dialect=dialectOf(con); final String tableName=getTableName(treeName); - if (driverName.contains("postgres")) { + if (dialect==Dialect.POSTGRES) { 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 @@ -3630,7 +3926,7 @@ public void openTree(TreeName treeName, boolean createOnDemand) { }catch (SQLException e) { throw new StorageRuntimeException(e); } - }else if (driverName.contains("mysql")) { + }else if (dialect==Dialect.MYSQL) { try { if (!isExistsIndex(tableName,"k_"+tableName.substring("opendj_".length()))) { // mysql has no "create index if not exists" commitStatement("create index k_"+tableName.substring("opendj_".length())+" on "+tableName+" (k)", true); @@ -3638,7 +3934,7 @@ public void openTree(TreeName treeName, boolean createOnDemand) { }catch (SQLException e) { throw new StorageRuntimeException(e); } - }else if (driverName.contains("oracle")) { + }else if (dialect==Dialect.ORACLE) { try { // oracle has no "create index if not exists"; unquoted identifiers are stored in uppercase if (!isExistsIndex(tableName.toUpperCase(Locale.ROOT),"k_"+tableName.substring("opendj_".length()))) { @@ -4065,29 +4361,29 @@ public void put(TreeName treeName, ByteSequence key, ByteSequence value) { } boolean upsert(TreeName treeName, ByteSequence key, ByteSequence value) throws SQLException { - final String driverName=driverNameOf(con); - if (driverName.contains("postgres")) { //postgres upsert + final Dialect dialect=dialectOf(con); + if (dialect==Dialect.POSTGRES) { //postgres upsert try (final PreparedStatement statement = con.prepareStatement("insert into " + getTableName(treeName) + " (h,k,v) values (?,?,?) ON CONFLICT (h, k) DO UPDATE set v=excluded.v")) { statement.setString(1, key2hash.get(ByteBuffer.wrap(key.toByteArray()))); statement.setBytes(2, real2db(key.toByteArray())); statement.setBytes(3, value.toByteArray()); return (execute(statement, bound) == 1 && statement.getUpdateCount() > 0); } - }else if (driverName.contains("mysql")) { //mysql upsert + }else if (dialect==Dialect.MYSQL) { //mysql upsert try (final PreparedStatement statement = con.prepareStatement("insert into " + getTableName(treeName) + " (h,k,v) values (?,?,?) as new ON DUPLICATE KEY UPDATE v=new.v")) { statement.setString(1, key2hash.get(ByteBuffer.wrap(key.toByteArray()))); statement.setBytes(2, real2db(key.toByteArray())); statement.setBytes(3, value.toByteArray()); return (execute(statement, bound) == 1 && statement.getUpdateCount() > 0); } - }else if (driverName.contains("oracle")) { //ANSI MERGE without ; + }else if (dialect==Dialect.ORACLE) { //ANSI MERGE without ; try (final PreparedStatement statement = con.prepareStatement("merge into " + getTableName(treeName) + " old using (select ? h,? k,? v from dual) new on (old.h=new.h and old.k=new.k) WHEN MATCHED THEN UPDATE SET old.v=new.v WHEN NOT MATCHED THEN INSERT (h,k,v) VALUES (new.h,new.k,new.v)")) { statement.setString(1, key2hash.get(ByteBuffer.wrap(key.toByteArray()))); statement.setBytes(2, real2db(key.toByteArray())); statement.setBytes(3, value.toByteArray()); return (execute(statement, bound) == 1 && statement.getUpdateCount() > 0); } - }else if (driverName.contains("microsoft")) { //ANSI MERGE with ; WITH (HOLDLOCK) makes the upsert atomic: without it SQL Server MERGE can race two concurrent NOT MATCHED inserts of the same key into a PRIMARY KEY violation. UPDLOCK is required on top of it: with HOLDLOCK alone the search phase takes a shared lock that the WHEN MATCHED update then has to convert to an exclusive one, so two concurrent upserts of the same key deadlock on the conversion; an update lock is taken right away and makes the second transaction wait instead. h is cast back to char so that the join can seek the primary key instead of scanning the whole table under those locks, see hashParam() + }else if (dialect==Dialect.MICROSOFT) { //ANSI MERGE with ; WITH (HOLDLOCK) makes the upsert atomic: without it SQL Server MERGE can race two concurrent NOT MATCHED inserts of the same key into a PRIMARY KEY violation. UPDLOCK is required on top of it: with HOLDLOCK alone the search phase takes a shared lock that the WHEN MATCHED update then has to convert to an exclusive one, so two concurrent upserts of the same key deadlock on the conversion; an update lock is taken right away and makes the second transaction wait instead. h is cast back to char so that the join can seek the primary key instead of scanning the whole table under those locks, see hashParam() try (final PreparedStatement statement = con.prepareStatement("merge into " + getTableName(treeName) + " WITH (HOLDLOCK, UPDLOCK) old using (select cast(? as char(128)) h,? k,? v) new on (old.h=new.h and old.k=new.k) WHEN MATCHED THEN UPDATE SET old.v=new.v WHEN NOT MATCHED THEN INSERT (h,k,v) VALUES (new.h,new.k,new.v);")) { statement.setString(1, key2hash.get(ByteBuffer.wrap(key.toByteArray()))); statement.setBytes(2, real2db(key.toByteArray())); @@ -4204,7 +4500,7 @@ public CursorImpl(boolean isReadOnly, Connection con, TreeName treeName, Stateme // of #873 reads the shared tree, and reading a tree must not put it up for removal this.tableName=readTableName(treeName); this.batchBound=batchBound; - this.limitClause=((CachedConnection)con).parent.getClass().getName().contains("mysql") + this.limitClause=dialectOf(con)==Dialect.MYSQL ? " limit ?,?" : " offset ? rows fetch next ? rows only"; } 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 2c339a9ceb..0aff8f7d3f 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 @@ -17,10 +17,12 @@ import org.forgerock.opendj.server.config.server.JDBCBackendCfg; import org.opends.server.DirectoryServerTestCase; +import org.opends.server.backends.jdbc.JDBCStorage.Conflict; 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.backends.pluggable.spi.WriteableTransaction; import org.opends.server.types.DirectoryException; import org.testng.annotations.AfterClass; import org.testng.annotations.BeforeClass; @@ -40,6 +42,7 @@ import java.sql.Statement; import java.util.Properties; import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.atomic.AtomicReference; import java.util.function.Predicate; @@ -60,16 +63,22 @@ import static org.mockito.Mockito.times; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; +import static org.opends.server.backends.jdbc.JDBCStorage.Conflict.AFTER_LOCK_WAIT; +import static org.opends.server.backends.jdbc.JDBCStorage.Conflict.NONE; +import static org.opends.server.backends.jdbc.JDBCStorage.Conflict.PROMPT; +import static org.opends.server.backends.jdbc.JDBCStorage.Conflict.UNKNOWN_ENGINE; import static org.testng.Assert.assertEquals; import static org.testng.Assert.assertFalse; import static org.testng.Assert.assertNull; +import static org.testng.Assert.assertSame; import static org.testng.Assert.assertTrue; import static org.testng.Assert.fail; /** - * 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. + * Tests how a failure is classified - as a transaction conflict of one class or another, or as a connection the + * database dropped - which is what decides whether {@link JDBCStorage#write} replays the operation, whether its + * first replay is granted regardless of the clock, how long the replays may go on for and how long it waits + * before each of them; 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, and the writes that carry them run @@ -84,6 +93,8 @@ public class JDBCStorageRetryTest extends DirectoryServerTestCase private static final String MYSQL = "com.mysql.cj.jdbc.ConnectionImpl"; private static final String ORACLE = "oracle.jdbc.driver.T4CConnection"; private static final String POSTGRES = "org.postgresql.jdbc.PgConnection"; + /** A MySQL-wire-compatible driver, whose class name carries no engine this backend recognises. */ + private static final String MARIADB = "org.mariadb.jdbc.Connection"; /** 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"); @@ -121,6 +132,16 @@ interface mysqlConnection extends Connection { } + /** + * A MySQL-wire-compatible driver none of the four engines is recognised in - MariaDB Connector/J, an Aurora- + * or Percona-branded one. It reports a lock wait timeout as 1205 under class 40 exactly as Connector/J does, + * and a backend created under {@code com.mysql.cj.jdbc} opens through it: every DDL of {@code openTree()} is + * guarded by a catalog read, so an existing backend issues none of it. + */ + interface mariadbConnection extends Connection + { + } + /** A failure whose cause chain is a cycle, to check that walking it terminates. */ private static final class SelfCausedException extends RuntimeException { @@ -133,62 +154,192 @@ public synchronized Throwable getCause() } } + /** + * The failures the engines report, and the class each of them belongs to: {@link Conflict#NONE} for a failure no + * replay resolves, and otherwise how promptly the engine reporting it does so, which is all the class decides. + */ @DataProvider public Object[][] failures() { return new Object[][] { - // SQL Server picking a transaction as the deadlock victim: the failure this retry exists for - { "mssql deadlock victim", sql(1205, "40001"), MSSQL, true }, + // SQL Server picking a transaction as the deadlock victim: the failure this retry exists for. It is reported + // as promptly as the deadlock monitor runs, but only once the victim has waited out a lock wait of its own, + // which SQL Server leaves unbounded - the wait belongs to the attempt, not to the reporting + { "mssql deadlock victim", sql(1205, "40001"), MSSQL, PROMPT }, // a deployment may add xopenStates=true to its connection URL, which reports the same deadlock as 42000 - { "mssql deadlock victim, xopenStates", sql(1205, "42000"), MSSQL, true }, + { "mssql deadlock victim, xopenStates", sql(1205, "42000"), MSSQL, PROMPT }, // the conflict of most other engines is carried by the SQLState, under a vendor number of their own - { "postgres serialization failure", sql(0, "40001"), POSTGRES, true }, - { "postgres deadlock detected", sql(0, "40P01"), POSTGRES, true }, + { "postgres serialization failure", sql(0, "40001"), POSTGRES, PROMPT }, + { "postgres deadlock detected", sql(0, "40P01"), POSTGRES, PROMPT }, // Connector/J replaces the server side HY000 of both conditions with 40001, so neither needs a number here - { "mysql deadlock", sql(1213, "40001"), MYSQL, true }, - // not a deadlock, but transient in the same way and equally resolved by a replay - { "mysql lock wait timeout", sql(1205, "40001"), MYSQL, true }, + { "mysql deadlock", sql(1213, "40001"), MYSQL, PROMPT }, + // not a deadlock, but transient in the same way and equally resolved by a replay - and the one conflict of + // them all that an engine reports only after a lock wait timeout of its own, innodb_lock_wait_timeout + { "mysql lock wait timeout", sql(1205, "40001"), MYSQL, AFTER_LOCK_WAIT }, // the rollback a MySQL group replication conflict reports, error 3101, which the driver maps to 40000 - { "mysql group replication rollback", sql(3101, "40000"), MYSQL, true }, + { "mysql group replication rollback", sql(3101, "40000"), MYSQL, PROMPT }, // Oracle maps ORA-00060 to SQLState 61000, so only its error number identifies the deadlock - { "oracle deadlock detected", sql(60, "61000"), ORACLE, true }, + { "oracle deadlock detected", sql(60, "61000"), ORACLE, PROMPT }, // the conflict reaches JDBCStorage.write() wrapped, so the whole cause chain has to be walked - { "wrapped once", new StorageRuntimeException(sql(1205, "40001")), MSSQL, true }, + { "wrapped once", new StorageRuntimeException(sql(1205, "40001")), MSSQL, PROMPT }, { "wrapped twice", new DirectoryException(OTHER, raw("unchecked"), new StorageRuntimeException(sql(1205, "40001"))), MSSQL, - true }, + PROMPT }, // the vendor numbers collide across engines, so they must not be matched driver-independently: // ORA-01205 "not a data file" is fatal, and no replay resolves it - { "oracle not a data file", sql(1205, "64000"), ORACLE, false }, + { "oracle not a data file", sql(1205, "64000"), ORACLE, NONE }, // and a lock wait timeout is a MySQL number: 1205 means nothing of the kind to PostgreSQL - { "postgres unrelated 1205", sql(1205, "22001"), POSTGRES, false }, + { "postgres unrelated 1205", sql(1205, "22001"), POSTGRES, NONE }, // two class 40 states are rollbacks that a replay must not repeat: 40003 leaves the outcome of the // transaction unknown, and 40002 is an integrity constraint violation that a replay would only hit again - { "statement completion unknown", sql(0, "40003"), POSTGRES, false }, - { "transaction integrity constraint violation", sql(0, "40002"), POSTGRES, false }, - // ... but the state of a conflict is still matched whatever vendor number carries it - { "class 40 is driver independent", sql(0, "40001"), null, true }, + { "statement completion unknown", sql(0, "40003"), POSTGRES, NONE }, + { "transaction integrity constraint violation", sql(0, "40002"), POSTGRES, NONE }, + // ... but the state of a conflict is still matched whatever vendor number carries it, which is what makes + // an unrecognised engine replayable at all. Which class of conflict it is cannot be told, though: the + // grant rests on the engine not having bounded the wait already, and of this engine that is not known + { "class 40 is driver independent", sql(0, "40001"), null, UNKNOWN_ENGINE }, + // the case that costs: a MySQL-wire-compatible driver reports innodb_lock_wait_timeout as 1205 under + // class 40 exactly as Connector/J does, and reading the number only under a name carrying "mysql" would + // hand it the grant - a second full 50 s wait, the one thing the window exists to refuse + { "mysql wire compatible lock wait timeout", sql(1205, "40001"), MARIADB, UNKNOWN_ENGINE }, + { "class 40 with 1205, no driver", sql(1205, "40001"), null, UNKNOWN_ENGINE }, // nothing a replay can resolve - { "primary key violation", sql(2627, "23000"), MSSQL, false }, - { "syntax error", sql(102, "S0001"), MSSQL, false }, - { "no SQLState", sql(0, null), MSSQL, false }, - { "not a SQLException", new IllegalStateException("connection closed"), MSSQL, false }, - { "wrapped, not a conflict", new StorageRuntimeException(sql(2627, "23000")), MSSQL, false }, - { "no failure at all", null, MSSQL, false }, + { "primary key violation", sql(2627, "23000"), MSSQL, NONE }, + { "syntax error", sql(102, "S0001"), MSSQL, NONE }, + { "no SQLState", sql(0, null), MSSQL, NONE }, + { "not a SQLException", new IllegalStateException("connection closed"), MSSQL, NONE }, + { "wrapped, not a conflict", new StorageRuntimeException(sql(2627, "23000")), MSSQL, NONE }, + { "no failure at all", null, MSSQL, NONE }, // a vendor number is never matched without a driver to key it off, since the engines collide on it - { "unknown driver", sql(1205, "HY000"), null, false }, - { "cyclic cause chain", new SelfCausedException(), MSSQL, false }, + { "unknown driver", sql(1205, "HY000"), null, NONE }, + // the state the MySQL server itself gives a lock wait timeout, before Connector/J remaps it to class 40: the + // number read to date that conflict refines a match its state has already made, and never makes one of its own + { "mysql lock wait timeout, server state", sql(1205, "HY000"), MYSQL, NONE }, + { "cyclic cause chain", new SelfCausedException(), MSSQL, NONE }, + + // the chain is walked to its end, not stopped at its first conflict: a hop carrying a bare class 40 state + // is a conflict by itself, and returning it would hand the lock wait timeout it wraps - a wait MySQL has + // already bounded - the replay that only the conflicts nothing bounds are granted + { "lock wait timeout under a bare class 40 wrapper", sql(0, "40001", sql(1205, "40001")), MYSQL, + AFTER_LOCK_WAIT }, + { "bare class 40 wrapper over a deadlock", sql(0, "40001", sql(1213, "40001")), MYSQL, PROMPT }, }; } + /** + * Whether a failure is a conflict at all decides that it is replayed; which class of conflict it is decides + * only whether its first replay is granted regardless of the clock. + */ @Test(dataProvider = "failures") - public void testIsRetryableConflict(String name, Throwable failure, String driver, boolean expected) + public void testConflictClass(String name, Throwable failure, String driver, Conflict expected) + { + assertEquals(conflictOf(failure, driver), expected, name); + } + + /** + * Which replays happen. The window bounds them from the first attempt, with one grant: a conflict its engine + * reports promptly is given its first replay whatever the clock says, since the wait charged to the attempt + * that hit it is unbounded and no window survives it. A conflict the engine reported only after a lock wait + * timeout of its own gets no such grant - that wait is bounded already, and repeating it is what the window + * refuses. + */ + @DataProvider + public Object[][] replays() + { + return new Object[][] { + // the engine asked for the transaction to be rerun after a wait nothing here bounds, and no clock denies + // that first rerun. The failure of run 33010633197 is the case: SQL Server leaves the lock wait unbounded, + // so its deadlock monitor picked a victim ~12 s into the first attempt, and master replayed it zero times + { "deadlock reported after a long lock wait", 1, seconds(12), sql(1205, "40001"), MSSQL, true }, + { "deadlock reported later than any window", 1, seconds(600), sql(1205, "40001"), MSSQL, true }, + // and exactly at the window, which is the boundary the grant is decided on: elapsed >= window, not > it. + // The rows around this one bracket that point without standing on it, and a > there would refuse the first + // replay of #903 to every conflict reported at the window to the nanosecond + { "deadlock at the window, first attempt", 1, seconds(10), sql(1205, "40001"), MSSQL, true }, + + // the grant is one replay, not an exemption: from the second attempt on the window governs, so that a + // conflict which never clears is failed rather than never returned + { "deadlock within the window", 2, seconds(9), sql(1205, "40001"), MSSQL, true }, + { "deadlock at the window", 2, seconds(10), sql(1205, "40001"), MSSQL, false }, + // the same elapsed time that was granted on attempt 1 is refused on attempt 2: one grant, and only one + { "deadlock past the window", 2, seconds(12), sql(1205, "40001"), MSSQL, false }, + // a MySQL deadlock is reported as promptly as any other engine reports one, so it is granted the same + { "mysql deadlock, first attempt", 1, seconds(12), sql(1213, "40001"), MYSQL, true }, + { "mysql deadlock, past the window", 2, seconds(12), sql(1213, "40001"), MYSQL, false }, + + // MySQL reports a lock wait timeout only after innodb_lock_wait_timeout, 50 s by default: that wait is + // bounded by the engine, so the window is measured against it from the first attempt and a second 50 s wait + // is refused - which is the whole reason the window was introduced + { "mysql lock wait timeout at the default 50 s", 1, seconds(50), sql(1205, "40001"), MYSQL, false }, + { "mysql lock wait timeout past the window", 1, seconds(12), sql(1205, "40001"), MYSQL, false }, + // ... and a deployment that tuned innodb_lock_wait_timeout below the window still gets its replays + { "mysql lock wait timeout tuned under the window", 1, seconds(3), sql(1205, "40001"), MYSQL, true }, + { "mysql lock wait timeout, second attempt within", 2, seconds(6), sql(1205, "40001"), MYSQL, true }, + { "mysql lock wait timeout, second attempt at the window", 2, seconds(10), sql(1205, "40001"), MYSQL, false }, + // the same 1205 under a MySQL-wire-compatible driver, which is what a backend created under Connector/J + // and opened through MariaDB Connector/J reports: the window governs it from the first attempt too, since + // a grant here would buy the second innodb_lock_wait_timeout the rows above refuse + { "mysql wire compatible lock wait timeout", 1, seconds(12), sql(1205, "40001"), MARIADB, false }, + { "mysql wire compatible conflict within the window", 1, seconds(3), sql(1205, "40001"), MARIADB, true }, + + // the attempt count bounds every class, whatever the window has left. It is the bound that rarely fires: + // reaching it takes ten attempts inside a 10 s window, which only a conflict reported in milliseconds + // leaves room for - a conflict preceded by a wait longer than the window stops at two attempts, the + // granted one included, and the line reporting the replay names the window for that reason + { "last attempt left", 9, 0L, sql(1205, "40001"), MSSQL, true }, + { "attempts exhausted", 10, 0L, sql(1205, "40001"), MSSQL, false }, + // a failure carrying no conflict class at all still passes these bounds: what makes it replayable is + // replayReason(), which write() asks first, and a dropped connection carries no class 40 state + { "a drop, which no class describes", 1, 0L, sql(2627, "23000"), MSSQL, true }, + }; + } + + /** + * Composed the way {@code write()} composes it: the class is read off the failure once, and the bounds are + * asked of the class. Whether the failure is worth replaying at all is {@code replayReason()}, tested apart. + */ + @Test(dataProvider = "replays") + public void testReplayable(String name, int attempt, long elapsedNanos, Throwable failure, String driver, + boolean expected) + { + assertEquals(JDBCStorage.replayableWithin(attempt, elapsedNanos, conflictOf(failure, driver)), + expected, name); + } + + /** + * The grant is reported rather than inferred: the line reporting a replay says "granted past it" only where + * the loop really took that branch. Pinned apart from {@link #testReplayable} because the two agree today by + * construction - a replay past the window can only be the grant - and it is that coincidence, not the claim, + * that a later change to the bounds would take away. + */ + @Test + public void testTheGrantIsTheOnlyReplayPastTheWindow() { - assertEquals(JDBCStorage.isRetryableConflict(failure, driver), expected, name); + // the grant, and the only shape of it: the first replay of a conflict reported past the window + assertTrue(JDBCStorage.grantedPastTheWindow(1, seconds(12), PROMPT), "the conflict of #903 was not granted"); + // inside the window nothing is granted - the window itself allows the replay, and the line says nothing + assertFalse(JDBCStorage.grantedPastTheWindow(1, seconds(9), PROMPT), "a replay inside the window was granted"); + // and past the first attempt, or for a wait the engine already bounded, there is no grant at all + assertFalse(JDBCStorage.grantedPastTheWindow(2, seconds(12), PROMPT), "a second replay was granted"); + assertFalse(JDBCStorage.grantedPastTheWindow(1, seconds(12), AFTER_LOCK_WAIT), "a bounded wait was granted"); + assertFalse(JDBCStorage.grantedPastTheWindow(1, seconds(12), UNKNOWN_ENGINE), + "an engine whose wait cannot be vouched for was granted"); + assertFalse(JDBCStorage.grantedPastTheWindow(1, seconds(12), NONE), "a failure carrying no conflict"); + + // every replay the bounds allow past the window is that grant, which is what lets the line name it + for (int attempt = 1; attempt < 12; attempt++) + { + for (Conflict conflict : Conflict.values()) + { + final boolean pastTheWindow = JDBCStorage.replayableWithin(attempt, seconds(11), conflict); + assertEquals(pastTheWindow, JDBCStorage.grantedPastTheWindow(attempt, seconds(11), conflict), + "attempt " + attempt + " of a " + conflict + " conflict past the window"); + } + } } @DataProvider @@ -251,9 +402,9 @@ public void testIsConnectionFailure(String name, Throwable failure, boolean expe public void testADroppedConnectionIsReplayedOnlyBeforeTheCommit() { final SQLException dropped = sql(0, "08006"); - assertEquals(JDBCStorage.replayReason(dropped, POSTGRES, false, false, false), + assertEquals(replayReason(dropped, POSTGRES, false, false, false), "a connection the database dropped"); - assertNull(JDBCStorage.replayReason(dropped, POSTGRES, true, false, false), + assertNull(replayReason(dropped, POSTGRES, true, false, false), "an in doubt transaction was replayed"); } @@ -265,10 +416,10 @@ public void testADroppedConnectionIsReplayedOnlyBeforeTheCommit() 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), + assertNull(replayReason(killed, MSSQL, false, false, false), "S0001 was replayed on its own"); + assertEquals(replayReason(killed, MSSQL, false, false, true), "a connection the database dropped"); - assertNull(JDBCStorage.replayReason(killed, MSSQL, true, false, true), + assertNull(replayReason(killed, MSSQL, true, false, true), "an in doubt transaction was replayed"); } @@ -281,9 +432,9 @@ public void testAConnectionTheDriverClosedIsADroppedOne() @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"); + assertNull(replayReason(sql(0, "40001"), POSTGRES, false, true, false), "a conflict was replayed"); + assertNull(replayReason(sql(0, "08006"), POSTGRES, false, true, false), "a drop was replayed"); + assertNull(replayReason(sql(596, "S0001"), MSSQL, false, true, true), "a drop was replayed"); } /** @@ -297,8 +448,8 @@ public void testAnAttemptThatCommittedPartOfItsWorkIsNotReplayed() 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), + assertEquals(conflictOf(onRelease, POSTGRES), NONE, "a conflict was read from the release"); + assertNull(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 @@ -328,16 +479,16 @@ public void testTheConnectionIsAskedWhetherTheDriverClosedIt() throws Exception 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"); + assertEquals(replayReason(conflict, POSTGRES, false, false, false), "a conflict"); + assertEquals(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)); + assertNull(replayReason(sql(2627, "23000"), MSSQL, false, false, false)); + assertNull(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. */ @@ -367,7 +518,7 @@ public void testRetryDelayGrowsAndStaysBounded() @Test public void testConflictSummaryNamesTheStateAndTheNumber() { - final String summary = JDBCStorage.conflictSummary( + final String summary = conflictSummary( new DirectoryException(OTHER, raw("unchecked"), new StorageRuntimeException(sql(1205, "40001"))), POSTGRES); assertTrue(summary.contains("40001"), summary); assertTrue(summary.contains("1205"), summary); @@ -382,26 +533,51 @@ public void testConflictSummaryNamesTheStateAndTheNumber() @Test public void testConflictSummaryNamesTheFailureTheReplayWasDecidedOn() { - final String summary = JDBCStorage.conflictSummary( + final String summary = conflictSummary( new StorageRuntimeException(suppressing(sql(2627, "23000"), sql(0, "08006"))), POSTGRES); assertTrue(summary.contains("08006"), summary); assertFalse(summary.contains("23000"), summary); } + /** + * The line names the link the class was decided on, which is not always the first conflict of the chain: + * {@code conflictVerdict()} keeps the most specific class it finds, so a wrapper carrying a bare class 40 state + * is walked past to the lock wait timeout underneath it. Naming the wrapper would print "error 0" for a replay + * whose whole bound was chosen by the 1205 it never shows. Asked of one verdict per chain, the way + * {@code write()} asks it: the class and the link are one answer, and two walks could disagree about them. + */ + @Test + public void testConflictSummaryNamesTheLinkTheClassWasDecidedOn() + { + final SQLException lateUnderAWrapper = sql(0, "40001", sql(1205, "40001")); + final JDBCStorage.ConflictVerdict late = JDBCStorage.conflictVerdict(lateUnderAWrapper, MYSQL); + assertEquals(late.conflict, AFTER_LOCK_WAIT); + final String summary = JDBCStorage.conflictSummary(late, lateUnderAWrapper); + assertTrue(summary.contains("1205"), summary); + + // the same chain under a driver that gives 1205 no such meaning is a prompt conflict, and the first link + // of it is the one the decision was taken on + final SQLException sameChain = sql(0, "40001", sql(1205, "40001")); + final JDBCStorage.ConflictVerdict prompt = JDBCStorage.conflictVerdict(sameChain, POSTGRES); + assertEquals(prompt.conflict, PROMPT); + final String firstLink = JDBCStorage.conflictSummary(prompt, sameChain); + assertTrue(firstLink.contains("error 0"), firstLink); + } + /** 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"), POSTGRES).contains("closed")); - assertTrue(JDBCStorage.conflictSummary(new SelfCausedException(), POSTGRES).contains("SelfCausedException")); - assertEquals(JDBCStorage.conflictSummary(null, POSTGRES), "null"); + assertTrue(conflictSummary(new IllegalStateException("connection closed"), POSTGRES).contains("closed")); + assertTrue(conflictSummary(new SelfCausedException(), POSTGRES).contains("SelfCausedException")); + assertEquals(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); + final String summary = 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 @@ -409,7 +585,7 @@ public void testConflictSummaryFallsBackToTheFirstFailureOfTheChain() // 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); + final String decidedOnTheConnection = conflictSummary(killedSession, MSSQL); assertTrue(decidedOnTheConnection.contains("S0001"), decidedOnTheConnection); assertFalse(decidedOnTheConnection.contains("25P02"), decidedOnTheConnection); } @@ -427,6 +603,112 @@ public void testTheWalkOfAFailureStopsAtItsBudget() assertFalse(JDBCStorage.isConnectionFailure(chainEndingInADrop(65)), "a drop past the budget was walked to"); } + /** + * The class of a conflict is the one walk that budget must not bound, and it is the reason + * {@code failureScope()} does not bound its own either: truncation does not leave this verdict unanswered, it + * weakens it. A lock wait timeout past the budget, with a bare class 40 link inside it, would come back + * {@link Conflict#PROMPT} and be handed the one replay the class exists to refuse - a second full + * {@code innodb_lock_wait_timeout}. Truncation here grants a replay rather than losing one. + */ + @Test + public void testTheConflictClassIsReadFromEveryLinkOfTheChain() + { + // a bare class 40 wrapper, then 64 links of a rejected statement, then the timeout that decided the class + final SQLException bareClass40 = sql(0, "40001"); + SQLException tail = bareClass40; + for (int link = 0; link < 64; link++) + { + tail = chained(tail, sql(2627, "23000")).getNextException(); + } + chained(tail, sql(1205, "40001")); + + final JDBCStorage.ConflictVerdict verdict = JDBCStorage.conflictVerdict(bareClass40, MYSQL); + assertEquals(verdict.conflict, AFTER_LOCK_WAIT, + "a lock wait timeout past MAX_CHAIN_LINKS came back as a conflict the window does not bound"); + assertFalse(JDBCStorage.replayableWithin(1, seconds(12), verdict.conflict), + "and was granted the replay past the window"); + // the line reporting a replay names that same link, since one walk produced both + assertTrue(JDBCStorage.conflictSummary(verdict, bareClass40).contains("1205")); + } + + /** + * The widening that reading every link brings, which is the one behaviour change of #903 outside the grant: a + * chain whose only conflict-bearing link sits past the budget was not a conflict at all on master - the + * truncating walk never reached it - so {@code replayReason()} answered null and the operation was failed. + * The case above pins the *class* of such a chain, since it puts a bare class 40 state at the head that the + * truncating walk already matched; this one pins that the conflict is found at all. + */ + @Test + public void testAConflictOnlyPastTheBudgetIsFoundAtAll() + { + // 64 links of a rejected statement - the whole budget - and the conflict on the 65th + final SQLException head = sql(2627, "23000"); + SQLException tail = head; + for (int link = 2; link <= 64; link++) + { + tail = chained(tail, sql(2627, "23000")).getNextException(); + } + chained(tail, sql(0, "40001")); + + assertEquals(conflictOf(head, POSTGRES), PROMPT, + "a conflict whose only link sits past MAX_CHAIN_LINKS was not found at all"); + assertEquals(replayReason(head, POSTGRES, false, false, false), "a conflict", + "and the operation carrying it was not replayed"); + } + + /** + * What that walk stops at is the strongest class the engine of its driver can report, not the last constant of + * {@link Conflict}: only MySQL reports a lock wait timeout of its own, so a walk stopping at + * {@link Conflict#AFTER_LOCK_WAIT} never stops early on the other three engines and reads every link of every + * failed write on the driver whose chains are longest. Pinned from both sides - no failure of an engine is + * classed above its own ceiling, and every ceiling is reached by some failure - since a ceiling set too low + * would end the walk on a class weaker than the chain carries, and one set too high never ends it early. + */ + @Test + public void testTheWalkStopsAtTheStrongestClassItsEngineCanReport() + { + // one shape per branch of the classification: a bare class 40, the two numbers the engines collide on, a + // deadlock of oracle, the state MySQL reports before its driver remaps it, and a failure that is no conflict + final SQLException[] shapes = { + sql(0, "40001"), sql(1205, "40001"), sql(1213, "40001"), sql(60, "61000"), sql(1205, "HY000"), + sql(2627, "23000") }; + + for (String driver : new String[] { POSTGRES, MYSQL, ORACLE, MSSQL, MARIADB, null }) + { + final Conflict ceiling = JDBCStorage.ceilingOf(JDBCStorage.dialectOf(driver)); + Conflict strongest = NONE; + for (SQLException shape : shapes) + { + final Conflict conflict = conflictOf(shape, driver); + assertTrue(conflict.compareTo(ceiling) <= 0, + driver + " classed " + shape.getSQLState() + "/" + shape.getErrorCode() + " as " + conflict + + ", above the ceiling its walk stops at"); + strongest = conflict.compareTo(strongest) > 0 ? conflict : strongest; + } + assertEquals(strongest, ceiling, "the walk of " + driver + " stops at a class it can never reach"); + } + + // and the walk really stops there: a link behind a conflict already at its engine's ceiling is not looked + // at. This is what makes reading every link affordable - write() classifies before it knows the failure is + // replayable at all, so a plain 23000 from adding an entry that is already there reaches this walk too + final AtomicBoolean walkedPast = new AtomicBoolean(); + final SQLException behindTheCeiling = new SQLException("synthetic failure", "23000", 2627) + { + @Override + public String getSQLState() + { + walkedPast.set(true); + return super.getSQLState(); + } + }; + assertEquals(conflictOf(sql(0, "40P01", behindTheCeiling), POSTGRES), PROMPT); + assertFalse(walkedPast.get(), "an engine reporting no lock wait timeout of its own walked past its ceiling"); + + // under mysql the same head is not the ceiling - a lock wait timeout could still be behind it - so it is + assertEquals(conflictOf(sql(0, "40001", behindTheCeiling), MYSQL), PROMPT); + assertTrue(walkedPast.get(), "mysql stopped before the link a lock wait timeout could have been on"); + } + /** * 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 @@ -515,7 +797,7 @@ public void testCreatingATreeTakesTheAttemptOutOfTheReplay() throws Exception } catch (StorageRuntimeException expected) { - assertTrue(JDBCStorage.isRetryableConflict(expected, POSTGRES), "the conflict was not the failure raised"); + assertEquals(conflictOf(expected, POSTGRES), PROMPT, "the conflict was not the failure raised"); } assertEquals(attempts.get(), 1, "a transaction that committed part of its work was replayed"); verify(statements).executeUpdate(); @@ -746,7 +1028,7 @@ public void testACreateIndexMysqlCommittedBeforeTakesTheAttemptOutOfTheReplay() } catch (StorageRuntimeException expected) { - assertTrue(JDBCStorage.isRetryableConflict(expected, MYSQL), "the conflict was not the failure raised"); + assertEquals(conflictOf(expected, MYSQL), PROMPT, "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_")); @@ -843,6 +1125,22 @@ private static ResultSet noRows() throws SQLException return rs; } + /** + * A mock of the given connection type, with the name every engine branch of {@code JDBCStorage} is keyed on + * asserted rather than assumed. The name of a mock is derived from the type it mocks, so a renamed fixture - + * or a Mockito that names its mocks differently - would move a case into another engine's branch with no test + * saying so, and there are cases no count of attempts would catch that in. + */ + private static Connection mockOfEngine(Class engine) + { + 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)); + return con; + } + /** * The connection the tree catalog of a storage of this test is written on: it opens one straight through the * driver, for the reason a stamp opens one of its own - the caller of openTree() is holding a pooled @@ -872,11 +1170,7 @@ private Connection catalogConnection() throws Exception 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)); + final Connection con = mockOfEngine(engine); engineConnection = con; // the connections behind it answer the connects the pool does not make: the tree catalog is read and // written on one of its own, straight through the driver, since the caller of openTree() is holding a @@ -999,11 +1293,155 @@ public Logger getParentLogger() } } + /** + * The two questions {@code write()} asks after a failed attempt, composed here the way it composes them: the + * conflict class is read off the failure once and handed to the reason, rather than being asked for again. + */ + private static String replayReason(Throwable failure, String driver, boolean committing, boolean partlyCommitted, + boolean connectionClosed) + { + return JDBCStorage.replayReason(conflictOf(failure, driver), failure, committing, partlyCommitted, + connectionClosed); + } + + /** + * The class of a failure, composed of the pieces {@code write()} composes it of. Forms of this and of + * {@link #conflictSummary} taking a failure and a driver used to live in {@code JDBCStorage} with no caller of + * their own in {@code src/main}, which left the classification javadoc hanging off methods production never + * called and made every test asking both questions walk the chains twice. The convenience is a test's, so it + * is written here. + */ + private static Conflict conflictOf(Throwable failure, String driver) + { + return JDBCStorage.conflictVerdict(failure, driver).conflict; + } + + /** The line reporting a replay, composed the way {@code write()} composes it: one walk, then the summary of it. */ + private static String conflictSummary(Throwable failure, String driver) + { + return JDBCStorage.conflictSummary(JDBCStorage.conflictVerdict(failure, driver), failure); + } + private static SQLException sql(int errorCode, String sqlState) { return new SQLException("synthetic failure", sqlState, errorCode); } + private static SQLException sql(int errorCode, String sqlState, Throwable cause) + { + return new SQLException("synthetic failure", sqlState, errorCode, cause); + } + + private static long seconds(long seconds) + { + return TimeUnit.SECONDS.toNanos(seconds); + } + + /** + * How {@link JDBCStorage#write} drives the two decisions above, which the cases before this one cannot see: + * they are handed an elapsed time and an attempt number rather than producing them. The clock is scripted and + * advances a fixed step per attempt - not per read of it - so that the timeline the loop sees depends on what + * it does rather than on how often it asks the time: a read added anywhere in {@code write()} leaves every row + * of this provider answering exactly as it does now. + *

+ * Between them the rows pin the three lines the rest of the file would let a refactor take away. A single + * {@code startedAt} outside the retry loop is what makes the window bound the whole run rather than each + * attempt: moved inside, every attempt is measured against its own start, sees the step and nothing more, and + * replays to MAX_RETRIES. The grant of the first replay is what issue #903 is about: without it an attempt + * that alone outlasts the window leaves the loop with no replay at all. And the class the grant is asked of is + * read off the failure of this very run, rather than off a driver the loop does not carry: the last two rows + * fail as plainly as the first two and are replayed no times at all. + */ + @DataProvider + public Object[][] writeRuns() + { + return new Object[][] { + // a step under the window, so the window is what ends the run: attempt 1 is granted its replay at 4 s, + // attempt 2 is inside the window at 8 s, attempt 3 is past it at 12 s. With startedAt inside the loop every + // attempt measures 4 s, never reaches the window, and the run goes to MAX_RETRIES instead + { "the window bounds the run, not the attempt", postgresConnection.class, sql(0, "40P01"), 4L, PROMPT, 3 }, + // a step past the window, so only the grant can produce a second attempt: remove it and the run ends on + // the first. This is the row that pins the grant end to end, and the row above is the one that pins + // startedAt - at 12 s a per-attempt startedAt also stops at two attempts, and at 4 s the window alone + // already allows the replay of attempt 1. Neither row is redundant + { "the first replay is granted past the window", postgresConnection.class, sql(0, "40P01"), 12L, PROMPT, 2 }, + // the same step, and the same class 40 state, for the one conflict the engine had already bounded: a + // single attempt. The predicate rows pin that decision, but only these rows pin that write() hands the + // predicate the class of its own failure - dropped on the way to replayableWithin() and the run above + // stays green while this one buys a second innodb_lock_wait_timeout + { "a lock wait timeout is granted no replay", mysqlConnection.class, sql(1205, "40001"), 12L, + AFTER_LOCK_WAIT, 1 }, + // and the driver that reports that same timeout under a name this backend does not recognise: no grant + // there either, since what the grant rests on - the engine having bounded nothing - is unknown of it. + // No number of attempts separates this row from the one above: AFTER_LOCK_WAIT and UNKNOWN_ENGINE are + // refused the grant and bounded by the window identically, so the mysql row misread as unrecognised + // produces exactly the count expected of it. That is why each row names the class its engine gives its + // failure and the case asserts it of the mock it actually built + { "an unrecognised engine is granted no replay", mariadbConnection.class, sql(1205, "40001"), 12L, + UNKNOWN_ENGINE, 1 }, + }; + } + + @Test(dataProvider = "writeRuns") + public void testWriteDrivesTheRetryLoop(String name, Class engine, + final SQLException conflict, final long stepSeconds, Conflict expectedClass, int expectedAttempts) + throws Exception + { + final AtomicInteger attempts = new AtomicInteger(); + // the class name of the mock is what write() reads the engine off, asserted here the way + // storageOverAnEngine() asserts it + final Connection connection = mockOfEngine(engine); + // which branch of the classification the row reaches, asserted rather than inferred from the count: the + // count cannot tell AFTER_LOCK_WAIT from UNKNOWN_ENGINE, since both are refused the grant and bounded by + // the window alike, so a fixture renamed out of the mysql branch would leave that row green + assertEquals(conflictOf(conflict, JDBCStorage.driverNameOf(connection)), expectedClass, + name + ": the mock does not reach the branch the row names"); + + // a url of its own, as storageOver() gives every fixture of this file: getConnection() is overridden below, + // but distrustPool() is not, and a null one would reach ConcurrentHashMap.merge(null, ...) rather than the + // assertion under test the moment a row of this provider scripts a connection failure + final JDBCBackendCfg cfg = mock(JDBCBackendCfg.class); + when(cfg.getDBDirectory()).thenReturn(StubDriver.PREFIX + pools.incrementAndGet()); + + final JDBCStorage storage = new JDBCStorage(cfg, null) + { + @Override + Connection getConnection() + { + return connection; + } + + @Override + long nanoTime() + { + // the attempts made are what moves this clock, so the run is the same however often write() reads it + return seconds(stepSeconds * attempts.get()); + } + }; + storage.accessMode = AccessMode.READ_WRITE; + + StorageRuntimeException thrown = null; + try + { + storage.write(new WriteOperation() + { + @Override + public void run(WriteableTransaction txn) + { + attempts.incrementAndGet(); + throw new StorageRuntimeException(conflict); + } + }); + } + catch (StorageRuntimeException e) + { + thrown = e; + } + + assertSame(thrown != null ? thrown.getCause() : null, conflict, name + ": the conflict reaches the caller"); + assertEquals(attempts.get(), expectedAttempts, name + ": attempts made"); + } + /** 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) {