diff --git a/.gitignore b/.gitignore index fd3b0ef6c0..818f7b03a7 100644 --- a/.gitignore +++ b/.gitignore @@ -20,6 +20,9 @@ dependency-reduced-pom.xml buildNumber.properties .mvn/timing.properties +# Build output captured to a file +*.log + #--- IntelliJ ignores --- # Covers JetBrains IDEs: IntelliJ, RubyMine, PhpStorm, AppCode, PyCharm, CLion, Android Studio 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 c03b8f6414..98d3d52ee2 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 @@ -1178,8 +1178,13 @@ private static boolean isBound(String value) { * read bound that could not be lifted serves the borrower waiting for it and is closed * afterwards: left in the pool it would fail every statement slower than that bound - an * import batch among them - for every borrow the pool hands it to. + *

+ * Turned off during a borrow as well as at establish time ({@link #keepOutOfThePool}): a session + * setting a borrower could not take off again is the same kind of thing, and the pool cannot + * notice one by itself - {@link #isUsable} validates with {@code isValid()}, a liveness check a + * connection carrying a stale setting passes. */ - private final boolean poolable; + private volatile boolean poolable; /** * When this connection last answered the database, as a {@link System#nanoTime()} reading: @@ -1223,6 +1228,17 @@ public CachedConnection(String connectionString, Connection parent) { this.lastKnownAliveNanos = System.nanoTime(); } + /** + * Keeps this connection out of the pool: it serves the borrower holding it and is closed rather + * than pooled when that borrow ends. For a borrower that left something of its own on the session + * and could not take it off again - {@code JDBCStorage.restoreDdlLockBound()} is the one that + * does (#885) - where the blast radius is then this one connection instead of every borrow it + * would have served after this one. + */ + void keepOutOfThePool() { + poolable = false; + } + /** Gives back the right to hold this connection, once and only if it was taken. */ void releasePermit() { if (metered && permitReleased.compareAndSet(false, true)) { 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..f6644b5c54 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 @@ -45,6 +45,7 @@ import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.Executor; import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicLong; import java.util.function.Predicate; import static org.opends.server.backends.pluggable.spi.StorageUtils.addErrorMessage; @@ -308,7 +309,7 @@ enum StatementBound { * {@link JDBCStorage#MAX_BOUND_SECONDS} is taken down to it, for the reason recorded there. */ int seconds() { - return clampSeconds(Integer.getInteger(property, defaultSeconds)); + return boundSeconds(property, defaultSeconds); } } @@ -504,6 +505,20 @@ private Connection connectionOf(PreparedStatement statement) { /** How far under its bound a driver may report the cancel, its timer being kept in whole seconds. */ static final long CLOCK_SLACK_MILLIS = 250; + /** + * How far past its own value the lock bound of a DDL may still be what ended a wait. A statement + * pays a round trip before its wait begins, an engine keeps that timer in whole seconds, and the + * drop loop of {@code removeStorageFiles()} sets the bound once around a loop whose earlier drops + * are work of their own. + *

+ * Past it a failure is left exactly as the engine reported it, because more than one wait of an + * engine reports the same number: mysql reports the row lock of {@code innodb_lock_wait_timeout} - + * 50 s by default, and what a create index under {@code ALGORITHM=COPY} waits on - as the same + * ERROR 1205 as a metadata lock, and naming this backend's property for one of those would send an + * operator to raise the single setting that cannot help. + */ + static final long LOCK_BOUND_SLACK_MILLIS = 2000; + /** * Ceiling of every bound this backend arms, in seconds - 24.9 days, which is what a socket read * timeout can hold at all: {@code setNetworkTimeout} takes milliseconds of an {@code int}, and a @@ -525,6 +540,19 @@ static int clampSeconds(int seconds) { return Math.max(0, Math.min(MAX_BOUND_SECONDS, seconds)); } + /** + * How every bound of this backend reads the property configuring it, in seconds: 0, or a negative + * value, leaves what it bounds as unbounded as it was before that bound existed, a value that is + * not a number is ignored in favour of the default - {@code Integer.getInteger()} falls back to it + * rather than reading such a value as a zero - and a value above {@link #MAX_BOUND_SECONDS} is + * taken down to it. One reader rather than one per bound, so that a later change to how these are + * read - an env fallback, a warning on a value that is not a number, a different clamp - cannot + * leave one of them behaving unlike the rest. + */ + static int boundSeconds(String property, int defaultSeconds) { + return clampSeconds(Integer.getInteger(property, defaultSeconds)); + } + /** * What {@link #timedOut} calls the second layer when that layer is the only one a statement ran * under, so that a test can tell the two apart in a message: a run where the first layer stopped @@ -555,6 +583,20 @@ long nanoTime() { private final AtomicBoolean backstopFailedWarned = new AtomicBoolean(); private final AtomicBoolean queryTimeoutWarned = new AtomicBoolean(); private final AtomicBoolean standingReadBoundWarned = new AtomicBoolean(); + // The same, for the two ways the lock bound of a DDL degrades: a session that would not take the + // setting - or would not say what it carried before it - and one it could not be taken off again. + // The second one is a moment rather than a latch, the way CachedConnection throttles the read bound + // it could not lift: whatever makes a restore fail - a transaction the server has doomed, + // middleware that rejects a SET - recurs on every DDL, and each occurrence now costs the pool the + // connection it happened on, so said once for the life of the storage an operator could not tell + // one stranded bound from a pool full of them. + private final AtomicBoolean ddlLockBoundNotSetWarned = new AtomicBoolean(); + private final AtomicLong ddlLockBoundLeftBehindWarned = new AtomicLong(); + private static final long DDL_LOCK_BOUND_WARNING_INTERVAL_MS = 10000; + // And a third way, which is no failure of anything: an engine this backend knows no lock setting + // for is left unbounded deliberately, and says so once - see reportTheEngineIsNotKnown(). Not + // private, so that a case can read what a storage has already said without reading a log. + final AtomicBoolean ddlLockBoundEngineUnknownWarned = new AtomicBoolean(); /** * The socket read timeout of one connection, and the statements running on it. This second @@ -1182,6 +1224,50 @@ static String storedIdentifier(DatabaseMetaData metaData, String name) throws SQ // dialect is told to give up after this many seconds instead of waiting. private static final int COMMENT_LOCK_TIMEOUT_SECONDS=5; + /** + * The bound on the wait of a DDL of this backend for a lock another session holds, in seconds. A + * value of {@code 0}, or a negative one, leaves it waiting for as long as the engine lets it, + * which is what this backend did before this bound existed (#885). + *

+ * A bound of the statement is the wrong tool for this, which is why the DDL of this backend is + * {@link StatementBound#BULK} and stays there: a query timeout cannot tell a statement that is + * working - a create index of a populated table - from one that is queued behind + * an unrelated transaction of another session, and only the second one is worth ending. Three + * engines out of four wait for a lock essentially forever ({@code lock_wait_timeout} is a year on + * mysql, {@code LOCK_TIMEOUT} is -1 on sql server, {@code lock_timeout} is 0 on postgres), so the + * open of a backend - and {@code dsconfig create-backend-index} on a running server - could hang + * behind a session that has nothing to do with it; on postgres a queued {@code CREATE INDEX} parks + * every writer of that table behind its own lock request while it waits. + *

+ * The default is {@link #COMMENT_LOCK_TIMEOUT_SECONDS}: the stamp of the same open takes its lock + * on the very tables this DDL creates and drops, and has been bounded there since #866. + *

+ * Oracle is not one of the engines this is put on, and setting it there changes nothing: that + * engine keeps its own {@code ddl_lock_timeout}, which gives up at once by default - tighter than + * anything this would set - and which this property neither reads nor changes. An ORA-00054 out of + * {@code dsconfig create-backend-index} is answered by {@code alter system set ddl_lock_timeout}, + * not by this. + *

+ * An engine behind a driver this backend does not know is left alone as well, and is told about + * rather than left silent - see {@code reportTheEngineIsNotKnown()}. {@link #dialectOf} reads the + * engine off the class name of the driver, so a mariadb, percona or aurora driver against a live + * mysql is one of these: the bound stays off there, and the line saying so is what an operator has + * to go on. + *

+ * What it costs is the round trips of the statements around each DDL - three on mysql and sql + * server (reading the value back, setting the bound, giving the value back), two on postgres (the + * savepoint a failed setting is taken back to, and the setting), none on oracle - and only on the + * cold path: an existing backend issues no DDL at all, since every statement of {@code openTree()} + * is guarded by a catalog read. A session already giving up sooner than this bound pays none of + * them past the readback: it keeps what it has. + */ + static final String DDL_LOCK_TIMEOUT_PROPERTY="org.openidentityplatform.opendj.jdbc.ddl.lock.timeout"; + + /** That bound in seconds, as configured, read by the reader every bound of this backend shares. */ + static int ddlLockBoundSeconds() { + return boundSeconds(DDL_LOCK_TIMEOUT_PROPERTY, COMMENT_LOCK_TIMEOUT_SECONDS); + } + // The comment statement runs on a connection of its own (newStampConnection() below), and a // driver waits for a connect attempt without limit unless it is told otherwise: a database // that keeps its established connections alive but accepts no new ones (a moved vip, a proxy @@ -1224,16 +1310,102 @@ enum Dialect { /** postgresql: lock_timeout takes milliseconds; connectTimeout bounds socket.connect(), loginTimeout the whole login the driver runs on a thread of its own, socketTimeout every read after it - all three in seconds. */ POSTGRES("set lock_timeout = "+(COMMENT_LOCK_TIMEOUT_SECONDS*1000), "connectTimeout", STAMP_CONNECT_TIMEOUT_SECONDS, "loginTimeout", STAMP_CONNECT_TIMEOUT_SECONDS, - "socketTimeout", STAMP_READ_TIMEOUT_SECONDS), + "socketTimeout", STAMP_READ_TIMEOUT_SECONDS) { + // milliseconds, and "set local" rather than the plain SET of the stamp connection: it belongs + // to the transaction running the DDL and is discarded by the commit that ends it, so nothing is + // left behind on a pooled connection and nothing has to be put back. What the session carries is + // not read here, which makes this the one engine where the bound can be looser than a + // lock_timeout a deployment set for itself: reading it back is the round trip a set local exists + // to save, and what is loosened is loosened for the length of this transaction and no longer. + @Override + String ddlLockBoundSql(int seconds, Long previous) { + return "set local lock_timeout = "+seconds*1000L; + } + + @Override + String ddlLockBoundQuery() { + return null; // set local: the commit that ends the DDL discards it + } + + @Override + String ddlLockRestoreSql(long previous) { + return null; + } + + @Override + boolean boundLivesInTheTransaction() { + return true; + } + }, /** mysql: lock_wait_timeout takes seconds; connectTimeout bounds the socket connect and socketTimeout every read after it, both in milliseconds. */ MYSQL("set session lock_wait_timeout="+COMMENT_LOCK_TIMEOUT_SECONDS, - "connectTimeout", STAMP_CONNECT_TIMEOUT_SECONDS*1000, "socketTimeout", STAMP_READ_TIMEOUT_SECONDS*1000), + "connectTimeout", STAMP_CONNECT_TIMEOUT_SECONDS*1000, "socketTimeout", STAMP_READ_TIMEOUT_SECONDS*1000) { + // seconds, and this is the metadata lock a DDL waits for - never innodb_lock_wait_timeout, which + // is the row lock write() replays a conflict of and which is bounded at 50 s already. A session + // that gives up sooner than this keeps exactly what it has: a deployment that set + // lock_wait_timeout tighter did so on purpose, which is the argument that leaves oracle alone + // below, and this value has no encoding for "wait forever" to mistake for a tight one - its range + // starts at 1 and its default is a year. + @Override + String ddlLockBoundSql(int seconds, Long previous) { + return (previous!=null && previous<=seconds) ? null : "set session lock_wait_timeout="+seconds; + } + + @Override + String ddlLockBoundQuery() { + return "select @@session.lock_wait_timeout"; + } + + @Override + String ddlLockRestoreSql(long previous) { + return "set session lock_wait_timeout="+previous; + } + }, /** oracle: ddl_lock_timeout takes seconds and defaults to 0 (give up at once), but it can be raised globally; the connect and read bounds take milliseconds. */ ORACLE("alter session set ddl_lock_timeout="+COMMENT_LOCK_TIMEOUT_SECONDS, - "oracle.net.CONNECT_TIMEOUT", STAMP_CONNECT_TIMEOUT_SECONDS*1000, "oracle.jdbc.ReadTimeout", STAMP_READ_TIMEOUT_SECONDS*1000), + "oracle.net.CONNECT_TIMEOUT", STAMP_CONNECT_TIMEOUT_SECONDS*1000, "oracle.jdbc.ReadTimeout", STAMP_READ_TIMEOUT_SECONDS*1000) { + // oracle gives up on a ddl lock at once - ddl_lock_timeout is 0 - which is tighter than anything + // set here, so ours would only loosen it; and a deployment that raised it globally did so on + // purpose. Putting it back would also mean reading v$parameter, a privilege the account of a + // backend often does not have. + @Override + String ddlLockBoundSql(int seconds, Long previous) { + return null; + } + + @Override + String ddlLockBoundQuery() { + return null; // nothing of ours is set on it + } + + @Override + String ddlLockRestoreSql(long previous) { + return null; + } + }, /** ms sql server: lock_timeout takes milliseconds; loginTimeout bounds the socket connect, in seconds, and socketTimeout the prelogin read it leaves open - and every read after it - in milliseconds. */ MICROSOFT("set lock_timeout "+(COMMENT_LOCK_TIMEOUT_SECONDS*1000), - "loginTimeout", STAMP_CONNECT_TIMEOUT_SECONDS, "socketTimeout", STAMP_READ_TIMEOUT_SECONDS*1000); + "loginTimeout", STAMP_CONNECT_TIMEOUT_SECONDS, "socketTimeout", STAMP_READ_TIMEOUT_SECONDS*1000) { + // milliseconds, and this setting bounds every lock wait of the session, row locks included, + // which is why it is put back the moment the DDL is through. -1 is "wait forever" rather than a + // bound tighter than ours and is replaced; 0 - "do not wait at all" - is tighter, and a session + // carrying it is left exactly as the deployment set it. + @Override + String ddlLockBoundSql(int seconds, Long previous) { + final long millis=seconds*1000L; + return (previous!=null && previous>=0 && previous<=millis) ? null : "set lock_timeout "+millis; + } + + @Override + String ddlLockBoundQuery() { + return "select @@lock_timeout"; + } + + @Override + String ddlLockRestoreSql(long previous) { + return "set lock_timeout "+previous; + } + }; final String lockTimeoutSql; // The driver properties bounding the login attempt of a stamp connection: the one bounding @@ -1256,6 +1428,44 @@ enum Dialect { this(lockTimeoutSql, connectProperty, connectValue, readProperty, readValue); connectProperties.setProperty(loginProperty, String.valueOf(loginValue)); } + + /** + * The session setting bounding the wait of a DDL for its lock, or null where there is none to + * put on: an engine left to a bound of its own - oracle - and a session that already gives up + * sooner than this one would, which keeps what it has rather than being loosened to ours. Not + * {@link #lockTimeoutSql}, which bounds the same wait on the stamp connection: that one is a + * constant of a connection this backend owns for the length of a sweep, this one is configurable + * and runs on a pooled connection somebody else borrows next. + *

+ * Answered per constant rather than by a switch, and so are the two below: a constant added later + * cannot compile without saying what it sets, and one that forgot to would otherwise take out + * every DDL of this backend - {@link JDBCStorage#withDdlLockBound} asks these before any try, + * on the path whose whole contract is that no statement of the bound is ever the failure of a + * DDL. + * + * @param previous what the session carries now, as {@link #ddlLockBoundQuery()} read it, in the + * unit that query answers in - or null where nothing was read back + */ + abstract String ddlLockBoundSql(int seconds, Long previous); + + /** + * What the session carries now, asked before the bound above displaces it - or null where that + * bound undoes itself. A pooled connection outlives the transaction that borrowed it, and + * {@code CachedConnection.close()} only rolls back. + */ + abstract String ddlLockBoundQuery(); + + /** The setting that gives the session back the value {@link #ddlLockBoundQuery()} read off it. */ + abstract String ddlLockRestoreSql(long previous); + + /** + * Whether the bound belongs to the transaction running the DDL rather than to the session. Such a + * setting needs a transaction block to take effect at all, a rollback undoes it, and the commit + * ending the DDL is what takes it off again - so nothing is read back and nothing is put back. + */ + boolean boundLivesInTheTransaction() { + return false; + } } /** Returns the class name of the driver behind the given connection, which names the engine it talks to. */ @@ -1846,13 +2056,364 @@ public void close() { } } + /** + * Runs a DDL of this backend under {@link #DDL_LOCK_TIMEOUT_PROPERTY}, and gives the session back + * whatever it carried before. + *

+ * The dialect is passed in rather than read off the connection here, the way + * {@code commentTable()} takes it: the callers know it, and taking it as a parameter is what makes + * this reachable from a test with no database behind it. + *

+ * Nothing of ours is set where it could not be taken off again, and a failure of the readback is + * never the failure of the DDL: this runs mostly on a pooled connection, so a setting left behind + * reaches every statement of whoever borrows it next - on sql server that is every lock wait of + * theirs, row locks included, and {@link #isConflict} classifies error 1222 as no replayable + * conflict. A session this backend could not take its bound off again is kept out of the pool for + * that reason ({@link CachedConnection#keepOutOfThePool}), since the validation of the next borrow + * is {@code isValid()} - a liveness check a connection carrying a stale setting passes. The one + * connection here that is not the pool's is the catalog's own, which {@code createCatalogTable()} + * creates its table on: there a setting left behind reaches the rest of that write and goes with + * the connection, which is closed with it. + *

+ * The DDL runs whatever any of that did, and it runs under the same rewrite either way: a setting + * can reach the server and fail only as the statement carrying it is closed, which no driver tells + * apart from a setting that never arrived, and reporting a DDL that then really did give up at this + * bound as the bare 55P03 it arrives as is the gap this exists to close. + */ + T withDdlLockBound(Connection con, Dialect dialect, Execution action) throws SQLException { + final int seconds=ddlLockBoundSeconds(); + if (seconds<=0) { // the wait is left exactly as unbounded as it was, and nobody asked otherwise + return action.run(); + } + if (dialect==null) { + // The one branch where a bound was asked for and none is put on, which is why it is the one + // that says so: an engine none of these settings fit is fed none of them - untested SQL is no + // thing to send a database on the path a backend opens by - and the silence around that is + // what an operator has no way of finding out. + reportTheEngineIsNotKnown(con); + return action.run(); + } + // Asked with nothing displaced yet, which is what tells an engine this bound is never put on - + // oracle - from an engine it is put on. What the session actually carries is read below, and can + // take the bound off again all by itself. + if (dialect.ddlLockBoundSql(seconds, null)==null) { + return action.run(); + } + final String query=dialect.ddlLockBoundQuery(); + final Long previous=(query==null) ? null : sessionValue(con, dialect, query); + if (query!=null && previous==null) { // read it back first: see above + return action.run(); + } + // Asked again with it: a session already giving up sooner than this bound is left exactly as it + // is, rather than loosened to ours for the length of the DDL. That is the argument leaving oracle + // alone, applied where the displaced value is in hand and costs nothing to respect. + final String bound=dialect.ddlLockBoundSql(seconds, previous); + if (bound==null) { + return action.run(); + } + if (dialect.boundLivesInTheTransaction() && !inATransactionBlock(con, dialect, bound)) { + return action.run(); + } + final String restore=(previous==null) ? null : dialect.ddlLockRestoreSql(previous); + // A statement that fails inside a postgres transaction aborts it, and everything after it - the + // DDL included - then fails with 25P02 rather than running "unbounded, as before": a backend that + // opened before this bound existed would stop opening because of the bound meant to protect it. + // The rollback below goes back to here, which also undoes a set local that did reach the server, + // so the DDL really does run as unbounded as the warning says it does. + final Savepoint beforeTheBound=savepointBeforeTheBound(con, dialect, bound); + try { + boundedSessionCall(con, () -> { + executeSessionStatement(con, bound); + return null; + }); + }catch (SQLException | RuntimeException e) { + // The bound is an improvement on a wait, and never a reason to fail a DDL that would have gone + // through: a backend that opened before this bound existed has to open still. Whatever the + // setting displaced is given back by the finally below, whether it went on or not - giving back + // a value the session may never have left costs a round trip and changes nothing. + reportTheWaitIsLeftUnbounded(dialect, bound, e); + rollbackTheBound(con, dialect, beforeTheBound); + } + // From here rather than from the top of this method: what the statements above spent is not time + // the DDL waited for its lock, and it is the wait that this bound either ended or did not. + final long startedAt=nanoTime(); + try { + return action.run(); + }catch (SQLException e) { + throw gaveUpOnTheLock(e, dialect, seconds, startedAt); + }finally { + if (restore!=null) { + restoreDdlLockBound(con, dialect, bound, restore); + } + } + } + + /** + * Whether a setting that lives in the transaction would take effect on this connection at all. + * Outside a transaction block postgres answers {@code SET LOCAL} with a warning and does nothing + * with it - the driver raises nothing, so the DDL would run with no bound and the log would read + * exactly like a bounded one. What makes the block is the {@code setAutoCommit(false)} a pooled + * connection is established with and never re-asserts on borrow, so it is asked rather than + * assumed; the call is answered out of the driver's own state, not by a round trip. + */ + private boolean inATransactionBlock(Connection con, Dialect dialect, String bound) { + try { + if (!con.getAutoCommit()) { + return true; + } + reportTheWaitIsLeftUnbounded(dialect, bound, new SQLException("the connection is in auto-commit," + + " where this setting belongs to no transaction and the server answers it with a warning")); + }catch (SQLException | RuntimeException e) { + reportTheWaitIsLeftUnbounded(dialect, bound, e); + } + return false; + } + + /** + * The point a setting that failed is taken back to, or null where there is none to take: an engine + * whose bound is a session setting rather than a transaction one, and a connection that would not + * give a savepoint. Nothing of the bound has been set when this is asked, so a failure here only + * leaves the setting below without this net - which is where it was before the net existed. + */ + private Savepoint savepointBeforeTheBound(Connection con, Dialect dialect, String bound) { + if (!dialect.boundLivesInTheTransaction()) { + return null; + } + try { + return boundedSessionCall(con, con::setSavepoint); + }catch (SQLException | RuntimeException e) { + reportTheWaitIsLeftUnbounded(dialect, bound, e); + return null; + } + } + + /** + * Takes the transaction back to the point before the bound was set: it clears the abort a setting + * that failed inside it left behind, and it undoes a {@code set local} that did reach the server + * and failed only as its statement was closed. Best effort - a transaction that cannot be taken + * back is one whose DDL is about to say so, and the failure worth reporting is the one the caller + * has just reported. + */ + private void rollbackTheBound(Connection con, Dialect dialect, Savepoint beforeTheBound) { + if (beforeTheBound==null) { + return; + } + try { + boundedSessionCall(con, () -> { + con.rollback(beforeTheBound); + return null; + }); + }catch (SQLException | RuntimeException e) { + logger.trace(LocalizableMessage.raw("jdbc: the transaction of a DDL could not be taken back to the point" + + " before its lock bound on this %s database: %s", dialect, stackTraceToSingleLineString(e))); + } + } + + // The round trips of the bound itself - the readback, the savepoint, the setting, the value given + // back - are bounded at this, in seconds. None of them takes a lock or reads a table, so a wait of + // one of them is a database that has stopped answering rather than work in progress, and the socket + // read timeout behind it arrives a margin later still (BACKSTOP_MARGIN_SECONDS). + static final int SESSION_STATEMENT_BOUND_SECONDS=10; + + /** + * Runs one round trip of the bound itself under the socket read timeout backing it up. Without one + * a readback on a connection whose peer went quiet - a failed-over primary, a proxy that stops + * answering with the socket still open - parks the thread that is opening a backend for good, which + * is the hang #877 and #882 exist to end; and it parks it from the {@code finally} giving a pooled + * connection its value back, where the DDL has already failed. Deliberately not the class the DDL + * itself carries: a create index of a populated table legitimately runs for hours, a + * {@code set lock_timeout} never does, so a bound of its own costs the DDL nothing. + *

+ * The cancel layer is left off, for the reason {@link #executeSessionStatement} records: what these + * carry has to reach the server as a plain batch. This is the layer that ends a wait no cancel + * would reach anyway. + */ + private T boundedSessionCall(Connection con, Execution call) throws SQLException { + final Backstop backstop=holdBackstop(con, SESSION_STATEMENT_BOUND_SECONDS); + try { + return call.run(); + }finally { + releaseBackstop(backstop, con, SESSION_STATEMENT_BOUND_SECONDS); + } + } + + /** + * What a session setting of this engine carries right now, or null where it could not be read as a + * number: a server whose session does not have the variable, or one answering with something no + * {@code SET} of it would take back. The DDL then runs as unbounded as it was before this bound + * existed, which is why this is reported rather than thrown - and reported once, since every DDL + * of that backend would say the same thing. + */ + private Long sessionValue(Connection con, Dialect dialect, String query) { + if (logger.isTraceEnabled()) { + logger.trace(LocalizableMessage.raw("jdbc: %s",query)); + } + try { + return boundedSessionCall(con, () -> { + try (final Statement statement=con.createStatement(); final ResultSet rows=statement.executeQuery(query)) { + if (!rows.next()) { + throw new SQLException("the session answered no row"); + } + return Long.valueOf(rows.getString(1).trim()); + } + }); + }catch (SQLException | RuntimeException e) { // a value that is not a number arrives unchecked + reportTheWaitIsLeftUnbounded(dialect, query, e); + return null; + } + } + + /** + * Said once per storage, whichever round trip of the bound around a DDL the connection would not + * take: every DDL of that backend would say the same thing, and a backend opening its trees issues + * about 25 of them. The DDL itself is unaffected - it waits as it did before this bound existed. + *

+ * "May bound nothing" rather than "bounds nothing": a setting that reached the server and failed + * only as the statement carrying it was closed leaves the DDL bounded after all, and no driver says + * which of the two happened. Where the bound lives in the transaction the rollback that follows + * this settles it - there the DDL really does run unbounded. + */ + private void reportTheWaitIsLeftUnbounded(Dialect dialect, String sql, Exception e) { + if (ddlLockBoundNotSetWarned.compareAndSet(false, true)) { + logger.warn(LocalizableMessage.raw("jdbc: the wait of a DDL for its lock is not bounded as this backend" + + " means to bound it on this %s database: \"%s\" did not go through, so %s may bound nothing here" + + " and a DDL can wait for a lock another session holds for as long as this engine lets it (%s)", + dialect, sql, DDL_LOCK_TIMEOUT_PROPERTY, stackTraceToSingleLineString(e))); + } + } + + /** + * Said once per storage, where the engine behind a connection is not one this backend knows a lock + * setting for. Leaving the bound off such an engine is the conservative reading and stays - untested + * SQL is no thing to send a database on the path a backend opens by - but a deployment that asked + * for the bound has no way of finding out that it got none, which is the silence this ends. It is + * the argument the strict parsing of {@value #DDL_LOCK_TIMEOUT_PROPERTY} is made with, one property + * later. + *

+ * {@link #dialectOf} reads the engine off the class name of the driver, so this is not the engine + * of an exotic database alone: a mariadb, percona or aurora driver against a live mysql answers + * null here, and that is a session whose {@code lock_wait_timeout} is a year - the very wait this + * bound exists to end. {@link CachedConnection} says the same of a url it knows no connect bound + * for and cannot say it for this one: it keys on the url, which such a driver takes as a mysql one. + *

+ * The driver is named rather than the url, since the driver is what this reads and what a + * deployment would change - and a url carries the password of the account this backend works as. + */ + private void reportTheEngineIsNotKnown(Connection con) { + if (ddlLockBoundEngineUnknownWarned.compareAndSet(false, true)) { + logger.warn(LocalizableMessage.raw("jdbc: the wait of a DDL for a lock is left unbounded on this" + + " database: %s is not a driver this backend knows a lock setting of an engine for, so %s" + + " bounds nothing here and a DDL - the create table and create index of an open, the drop" + + " table of a clear - waits for a lock another session holds for as long as this engine" + + " lets it", driverNameOf(con), DDL_LOCK_TIMEOUT_PROPERTY)); + } + } + + /** + * Gives the session back the value it carried. Best effort, and never the outcome of the DDL: this + * runs from a {@code finally} while the caller may be being unwound, where a throw would replace + * the failure that brought it there (JLS 14.20.2) - the very one saying what went wrong. + *

+ * A connection this failed on is handed on to nobody. A pooled one is closed rather than given + * back, and the catalog's own - the one connection reaching this that was never in the pool - is + * closed with the write that opened it. Leaving it to the next borrow to + * notice does not work: that validation is {@code con.isValid()}, a liveness check which a + * connection whose reset failed for a transient reason passes while still carrying our bound, and + * on sql server it would then cut every lock wait of that borrower at it - row locks included, + * which {@link #isConflict} classifies as no replayable conflict, so {@code write()} does not + * replay them and a client sees a hard failure. That is the hazard this bound is scoped to a DDL to + * avoid, arriving through the back door. Kept out of the pool, its blast radius is this one + * connection instead of the rest of its life. + *

+ * The value is named as the statement that set it rather than read back off the property at log + * time: the property can have been changed since, and what a session is left carrying is what was + * put on it - which is not the configured figure either, where the session's own value was the + * tighter one. + */ + private void restoreDdlLockBound(Connection con, Dialect dialect, String bound, String restore) { + try { + boundedSessionCall(con, () -> { + executeSessionStatement(con, restore); + return null; + }); + }catch (SQLException | RuntimeException e) { + if (con instanceof CachedConnection) { + ((CachedConnection) con).keepOutOfThePool(); + } + final long now=System.currentTimeMillis(); + final long last=ddlLockBoundLeftBehindWarned.get(); + if (now-last >= DDL_LOCK_BOUND_WARNING_INTERVAL_MS && ddlLockBoundLeftBehindWarned.compareAndSet(last, now)) { + logger.warn(LocalizableMessage.raw("jdbc: the lock bound of a DDL could not be taken off a connection" + + " of this %s database, which may have been left carrying \"%s\" instead of the value it had:" + + " that connection is not handed on - a pooled one is closed rather than given back, and the" + + " catalog's own is closed with the write that opened it - so nothing after this gives up on a" + + " lock at a bound of %s it never asked for (%s)", dialect, bound, DDL_LOCK_TIMEOUT_PROPERTY, + stackTraceToSingleLineString(e))); + } + } + } + + /** + * A DDL that gave up at the bound, reported as what it is. It arrives as a bare 55P03 / + * ERROR 1205 / error 1222, naming neither the wait it ended nor the property that ended it - the + * gap {@link #timedOut} closes for the bound of a statement. The state and the vendor number are + * carried over and the failure itself chained, so a caller that classifies this reads exactly what + * it read before: a mysql lock wait stays the class 40 conflict {@link #write} knows. + *

+ * Only a failure this bound could still be what ended is renamed, measured on the monotonic clock + * the way {@link #timedOut} measures its own and allowed {@link #LOCK_BOUND_SLACK_MILLIS} past the + * bound: an engine reports more than one wait with the same number, and a wait that ran far longer + * than this bound was ended by something else - on mysql, by the {@code innodb_lock_wait_timeout} + * that reports the row lock of a create index under {@code ALGORITHM=COPY} as the same ERROR 1205. + * Past that the failure is left exactly as it arrived, which is what it was before this bound + * existed. There is no guard under the bound to go with it: the states matched here are what an + * engine says when a lock wait ran out and nothing else says them, so an early one does not arise - + * and adding one would cost every case of the suite the wait it exists to avoid. + *

+ * The time is reported as measured rather than as the bound, for the reason {@link #timedOut} + * records: an operator has to be able to put the message next to a clock. + */ + SQLException gaveUpOnTheLock(SQLException e, Dialect dialect, int seconds, long startedAt) { + if (!lockNotAvailable(e, dialect)) { + return e; + } + final long elapsedMillis=(nanoTime()-startedAt)/1000000L; + if (elapsedMillis > seconds*1000L+LOCK_BOUND_SLACK_MILLIS) { + return e; + } + return new SQLTimeoutException("jdbc: the statement gave up waiting for a lock another session holds after " + +elapsedMillis+" ms, at the "+seconds+"s of "+DDL_LOCK_TIMEOUT_PROPERTY+": raise that property, or set" + + " it to 0 to wait for the lock as this backend did before it was bounded", e.getSQLState(), + e.getErrorCode(), e); + } + + /** + * Whether any link of a failure is this engine's own way of saying the lock was not available. + * Asked of the engine's number alone rather than through {@link #failureScope}, which reads a + * {@link SQLTimeoutException} as a moment of its own as well: a statement the bound of its class + * cancelled is one of those, and it was ended by a bound {@link #timedOut} has already named. + *

+ * {@link #WITHOUT_THE_RELEASE}, unlike {@link #failureScope}: this asks what the engine did with + * this statement, and the release of the connection - whose rollback reports what it saw as a + * suppressed exception - runs after that outcome was decided and cannot speak for it. Read the + * other way, a 55P03 or a 1205 out of the rollback that gave the connection back would rename a DDL + * that failed for something else entirely. + */ + static boolean lockNotAvailable(Throwable failure, Dialect dialect) { + return firstLinkMatching(failure, WITHOUT_THE_RELEASE, EVERY_LINK, e -> isLockTimeout(e, dialect))!=null; + } + // A session setting must reach the server as a plain batch: the sql server driver runs a // prepared statement through sp_executesql, and a setting made there is reverted when that // call returns - before the statement it is meant to protect ever runs. // - // Outside both layers of the bound, like the comment statement executeAny() runs, and for the - // same reason: this is issued from newStampConnection() on a stamp connection, whose connect - // properties carry a socket read timeout of their own (Dialect.connectProperties). + // Outside the cancel layer of the bound, like the comment statement executeAny() runs: a setting + // the DDL is wrapped in must not be cut short by a bound the DDL itself does not have, and a cancel + // would have to reach a statement this one deliberately does not prepare. The second layer is not + // left off with it. From newStampConnection() that is a stamp connection, whose connect properties + // carry a socket read timeout of their own (Dialect.connectProperties); from withDdlLockBound() + // boundedSessionCall() arms one, since a session setting that answers no round trip is a database + // that has stopped answering rather than work in progress. private void executeSessionStatement(Connection con, String sql) throws SQLException { try (final Statement statement=con.createStatement()) { if (logger.isTraceEnabled()) { @@ -2011,20 +2572,27 @@ private static FailureScope scopeOf(SQLException e, Dialect dialect) { if (e instanceof SQLTimeoutException || e instanceof SQLTransientException) { return FailureScope.MOMENT; } - if (dialect==null) { // the failure came before the engine was known - return FailureScope.TREE; + return isLockTimeout(e, dialect) ? FailureScope.MOMENT : FailureScope.TREE; + } + + // What one engine reports when a statement gave up on a lock instead of getting it. A dialect with + // no number of its own here - and a failure that came before the engine was known at all - says + // nothing of the kind, and is not treated as a moment. + static boolean isLockTimeout(SQLException e, Dialect dialect) { + if (dialect==null) { + return false; } switch (dialect) { case POSTGRES: // 55P03 lock not available: lock_timeout expired - return "55P03".equals(sqlState) ? FailureScope.MOMENT : FailureScope.TREE; + return "55P03".equals(e.getSQLState()); case MYSQL: // 1205 lock wait timeout exceeded - return e.getErrorCode()==1205 ? FailureScope.MOMENT : FailureScope.TREE; + return e.getErrorCode()==1205; case ORACLE: // ORA-00054 resource busy, ORA-04021 timeout occurred while waiting to lock object - return e.getErrorCode()==54 || e.getErrorCode()==4021 ? FailureScope.MOMENT : FailureScope.TREE; + return e.getErrorCode()==54 || e.getErrorCode()==4021; case MICROSOFT: // 1222 lock request time out period exceeded - return e.getErrorCode()==1222 ? FailureScope.MOMENT : FailureScope.TREE; - default: // a dialect with no lock timeout code of its own here: its failures are not treated as ones of the moment - return FailureScope.TREE; + return e.getErrorCode()==1222; + default: + return false; } } @@ -2231,39 +2799,9 @@ public void removeStorageFiles() throws StorageRuntimeException { // owner of and which a clear must therefore leave exactly where they lie (#881) final List skippedRows=new ArrayList<>(); // rows the read could not act on: reported below final Map trees=catalogTables(con, scope, skippedRows); - final TreeName catalogTree=getCatalogTree(); - int dropped=0; - // the same count with the catalog itself left out, which is what says whether this clear - // removed anything of the backend: a catalog table standing over rows that name nothing - - // a backup restored older than the tables it was taken beside - is dropped like any other - // and would otherwise make a clear that removed no tree at all look like a clear that did - // something. See reportClearOutcome() - int droppedTrees=0; - // counted without the catalog, for the reason droppedTrees is kept apart from dropped: the - // catalog is walked by this loop like any other table, so a catalog table that went between - // the lookup of catalogTables() and the loop's own would otherwise be summed up as a tree of - // this backend that had lost its table - int missingTrees=0; + final ClearCounts counts; try { - for (final Map.Entry tree : trees.entrySet()) { - final String tableName=tree.getValue(); - final boolean isCatalog=catalogTree.equals(tree.getKey()); - if (!isExistsTable(con, scope, tableName)) { // a row of the catalog outliving its table - reportClearLine(LocalizableMessage.raw( - "jdbc: backend %s names tree %s, whose table %s is not there: nothing to drop for it", - config.getBackendId(), tree.getKey(), tableName)); - if (!isCatalog) { - missingTrees++; - } - continue; - } - dropTable(con, tableName); - dropped++; - if (!isCatalog) { - droppedTrees++; - } - } - con.commit(); + counts=dropCatalogTables(con, scope, trees); } catch (Exception e) { // every failure of the loop and not the SQLException alone: the lookup deciding each // drop answers with a StorageRuntimeException of its own, and a drop left pending by one @@ -2280,7 +2818,7 @@ public void removeStorageFiles() throws StorageRuntimeException { unstampableTrees.remove(treeName); } try { - reportClearOutcome(con, scope, dropped, droppedTrees, missingTrees, skippedRows); + reportClearOutcome(con, scope, counts.dropped, counts.droppedTrees, counts.missingTrees, skippedRows); } catch (RuntimeException e) { // the clear itself is done and committed: an account of what it left standing must not be // the thing that reports it as failed, and a caller retrying it would find nothing to drop @@ -2311,6 +2849,69 @@ public void removeStorageFiles() throws StorageRuntimeException { * the order that map was built in, and a test asserting on the map instead would go on passing * over a loop that had stopped doing so. */ + /** What the drop loop of a clear did, which {@link #reportClearOutcome} accounts for. */ + static final class ClearCounts { + /** Tables dropped, the catalog of the backend among them. */ + int dropped; + /** + * The same count with the catalog itself left out, which is what says whether this clear + * removed anything of the backend: a catalog table standing over rows that name nothing - a + * backup restored older than the tables it was taken beside - is dropped like any other and + * would otherwise make a clear that removed no tree at all look like a clear that did something. + */ + int droppedTrees; + /** + * Rows whose table was not there, counted without the catalog for the reason + * {@link #droppedTrees} is kept apart from {@link #dropped}: the catalog is walked by the loop + * like any other table, so a catalog table that went between the lookup of + * {@code catalogTables()} and the loop's own would otherwise be summed up as a tree of this + * backend that had lost its table. + */ + int missingTrees; + } + + /** + * Drops the tables the catalog of this backend names, in one transaction and under a single lock + * bound, and says what it did. This loop bypasses the {@code commitStatement()} every other DDL of + * this backend goes through and commits once at the end, so the bound is set once around the whole + * of it rather than once per table - on postgres one {@code set local} covers every drop of the + * single transaction they run in. + *

+ * A clear with no row to act on is committed without the bound: putting it on costs a readback and + * a restore of its own, and the case {@code CLEAR_DROPPED_NOTHING} describes - the first clear of a + * backend upgraded from a version that kept no catalog - has no DDL for them to bound. + */ + ClearCounts dropCatalogTables(Connection con, TableScope scope, Map trees) throws SQLException { + if (trees.isEmpty()) { + con.commit(); + return new ClearCounts(); + } + final TreeName catalogTree=getCatalogTree(); + return withDdlLockBound(con, dialectOf(con), () -> { + final ClearCounts counts=new ClearCounts(); + for (final Map.Entry tree : trees.entrySet()) { + final String tableName=tree.getValue(); + final boolean isCatalog=catalogTree.equals(tree.getKey()); + if (!isExistsTable(con, scope, tableName)) { // a row of the catalog outliving its table + reportClearLine(LocalizableMessage.raw( + "jdbc: backend %s names tree %s, whose table %s is not there: nothing to drop for it", + config.getBackendId(), tree.getKey(), tableName)); + if (!isCatalog) { + counts.missingTrees++; + } + continue; + } + dropTable(con, tableName); + counts.dropped++; + if (!isCatalog) { + counts.droppedTrees++; + } + } + con.commit(); + return counts; + }); + } + void dropTable(Connection con, String tableName) throws SQLException { try (final PreparedStatement statement = con.prepareStatement("drop table " + tableName)) { // bulk, as #882 made every drop of this backend: nobody waits on a clear, and what it takes @@ -3561,10 +4162,21 @@ private void commitStatement(String sql, boolean ddl) throws SQLException { // one of the ones #877 names as overridden downwards - the create table and the three create // index of openTree(), the delete from of clearTree() and the drop table of deleteTree() - // and nobody is waiting on any of them. - try (final PreparedStatement statement=con.prepareStatement(sql)) { - execute(statement, StatementBound.BULK); - partlyCommitted=true; // a commit that fails leaves the outcome unknown, which is no more replayable - con.commit(); + final Execution issue=() -> { + try (final PreparedStatement statement=con.prepareStatement(sql)) { + execute(statement, StatementBound.BULK); + partlyCommitted=true; // a commit that fails leaves the outcome unknown, which is no more replayable + con.commit(); + } + return null; + }; + if (ddl) { + // The DDL of this backend is the part of it that takes locks, and the part that waits for + // one with no bound of its own. The delete from of clearTree() waits for row locks, which + // write() replays a conflict of and which this bound has no business ending. + withDdlLockBound(con, dialectOf(con), issue); + }else { + issue.run(); } } @@ -3856,17 +4468,31 @@ void readEnrolledTrees(TreeName catalog) { * An account that may write its rows but not create a table is a configuration this can meet, * so the failure says which table it was and why the backend wanted it, rather than reaching * the operator as a bare SQL error inside ERR_OPEN_ENV_FAIL. + *

+ * It waits for its lock under {@link JDBCStorage#DDL_LOCK_TIMEOUT_PROPERTY} like every other DDL + * of this backend, and a lock it gives up on names that property: this statement is issued on the + * catalog's own connection rather than through {@code commitStatement()}, which is the funnel + * that bounds the rest, so the bound is put on here. */ void createCatalogTable(TreeName catalog) { final String tableName=getTableName(catalog); try { final Connection catalogCon=catalogSession.connection(); - try (final PreparedStatement statement=catalogCon.prepareStatement("create table "+tableName+" ("+getTableDialect()+")")) { - // bulk like every other create table of this backend (#882): it is DDL nobody waits on, - // and the class of a client operation is not what a statement of this kind can be given - execute(statement, StatementBound.BULK); - } - catalogCon.commit(); + // Under the same bound as every other DDL of this backend, although this one reaches no + // commitStatement(): it is a create table of an open like the ones openTree() issues, and + // it queues for the same kind of lock - another process creating this very table inside a + // transaction it has not committed is a wait three engines out of four never end. The + // commit is inside the bound because on postgres it is that commit which ends the + // transaction a "set local" belongs to. + withDdlLockBound(catalogCon, dialectOf(catalogCon), () -> { + try (final PreparedStatement statement=catalogCon.prepareStatement("create table "+tableName+" ("+getTableDialect()+")")) { + // bulk like every other create table of this backend (#882): it is DDL nobody waits on, + // and the class of a client operation is not what a statement of this kind can be given + execute(statement, StatementBound.BULK); + } + catalogCon.commit(); + return null; + }); } catch (SQLException | RuntimeException e) { // the unchecked one as well, for the reason enrolInCatalog() takes it: what the statement // left behind has to be rolled back whatever class the failure arrived in, this connection diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCDdlLockBoundTestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCDdlLockBoundTestCase.java new file mode 100644 index 0000000000..4f870a1839 --- /dev/null +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/JDBCDdlLockBoundTestCase.java @@ -0,0 +1,977 @@ +/* + * The contents of this file are subject to the terms of the Common Development and + * Distribution License (the License). You may not use this file except in compliance with the + * License. + * + * You can obtain a copy of the License at legal/CDDLv1.0.txt. See the License for the + * specific language governing permission and limitations under the License. + * + * When distributing Covered Software, include this CDDL Header Notice in each file and include + * the License file at legal/CDDLv1.0.txt. If applicable, add the following below the CDDL + * Header, with the fields enclosed by brackets [] replaced by your own identifying + * information: "Portions copyright [year] [name of copyright owner]". + * + * Copyright 2026 3A Systems, LLC. + */ +package org.opends.server.backends.jdbc; + +import org.forgerock.opendj.server.config.server.JDBCBackendCfg; +import org.opends.server.DirectoryServerTestCase; +import org.opends.server.backends.jdbc.JDBCStorage.Dialect; +import org.opends.server.backends.jdbc.JDBCStorage.StatementBound; +import org.opends.server.backends.pluggable.spi.AccessMode; +import org.opends.server.backends.pluggable.spi.Importer; +import org.opends.server.backends.pluggable.spi.StorageStatus; +import org.opends.server.backends.pluggable.spi.TreeName; +import org.testng.annotations.AfterMethod; +import org.testng.annotations.BeforeMethod; +import org.testng.annotations.DataProvider; +import org.testng.annotations.Test; + +import java.sql.Connection; +import java.sql.DatabaseMetaData; +import java.sql.PreparedStatement; +import java.sql.ResultSet; +import java.sql.SQLException; +import java.sql.SQLTimeoutException; +import java.sql.Savepoint; +import java.sql.Statement; +import java.util.ArrayList; +import java.util.Collections; +import java.util.LinkedHashMap; +import java.util.List; +import java.util.Map; +import java.util.concurrent.atomic.AtomicBoolean; + +import static java.util.Arrays.asList; +import static java.util.Collections.emptyList; +import static java.util.Collections.singletonList; +import static org.forgerock.opendj.config.ConfigurationMock.mockCfg; +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.doAnswer; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +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.assertSame; +import static org.testng.Assert.assertTrue; +import static org.testng.Assert.fail; + +/** + * What a DDL of this backend is told to do about a lock another session holds (#885). It needs no + * database: the connection is a mock, so what each engine is told - and what it is told to put back + * afterwards - is pinned wherever the build runs, while the container suites cover a drop really + * queued behind another session. + */ +@SuppressWarnings("javadoc") +@Test(groups = { "precommit", "jdbc" }, sequential = true) +public class JDBCDdlLockBoundTestCase extends DirectoryServerTestCase { + + /** The tree the cases below name; the table behind it is a hash of that name. */ + private static final TreeName TREE = new TreeName("dc=example,dc=com", "id2entry"); + /** A second one, for the loop that drops every table of a backend under a single bound. */ + private static final TreeName OTHER_TREE = new TreeName("dc=example,dc=com", "dn2id"); + + /** The DDL itself, as it appears among the session statements issued around it. */ + private static final String THE_DDL = "the ddl"; + + /** The backend the storage of a case is configured as, which is what names its tree catalog. */ + private static final String BACKEND_ID = "ddlLockBound"; + /** + * That catalog's table, which the connection of a case answers as not being there (see engine()): + * a case reaching {@code openTree()} therefore takes the branch that creates it. + */ + private static final String CATALOG_TABLE = + JDBCStorage.toTableName(new TreeName(JDBCStorage.CATALOG_BASE_DN, BACKEND_ID)); + + /** What the connection of a case was asked to run, in the order it was asked to run it. */ + private final List issued = new ArrayList<>(); + + /** + * What the catalog's own connection was asked to run. The create table of the catalog is issued + * on that connection rather than on the caller's ({@code CatalogSession}), so what is issued + * around it is read off a list of its own instead of out of the middle of the caller's. + */ + private final List catalogIssued = new ArrayList<>(); + + private JDBCStorage storage; + + @BeforeMethod + public void createStorage() { + storage = new JDBCStorage(backendCfg(), null); + issued.clear(); + catalogIssued.clear(); + } + + /** A configuration naming this backend, which is all any case here reads off one. */ + private static JDBCBackendCfg backendCfg() { + final JDBCBackendCfg cfg = mockCfg(JDBCBackendCfg.class); + when(cfg.getBackendId()).thenReturn(BACKEND_ID); + return cfg; + } + + @AfterMethod + public void clearProperties() { + System.clearProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY); + } + + /** + * The stamp of the same open is already bounded at five seconds + * ({@code COMMENT_LOCK_TIMEOUT_SECONDS}), and it takes its lock on the very tables this DDL + * creates and drops. + */ + @Test + public void testTheDefaultGivesUpOnALockAfterFiveSeconds() { + assertEquals(JDBCStorage.ddlLockBoundSeconds(), 5); + } + + /** Zero is "wait as this backend waited before this bound existed", and so is anything under it. */ + @Test + public void testAValueOfZeroOrLessLeavesTheWaitUnbounded() { + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, "0"); + assertEquals(JDBCStorage.ddlLockBoundSeconds(), 0); + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, "-1"); + assertEquals(JDBCStorage.ddlLockBoundSeconds(), 0); + } + + /** + * A value that is not a number leaves the default in force rather than reading as a zero, which + * is what {@code Integer.getInteger()} does with one - so a typo does not silently take the bound + * off. + */ + @Test + public void testAValueThatIsNotANumberKeepsTheDefault() { + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, "five seconds"); + assertEquals(JDBCStorage.ddlLockBoundSeconds(), 5); + } + + /** The ceiling every bound of this backend is taken down to, for the reason recorded there. */ + @Test + public void testAValuePastTheCeilingIsTakenDownToIt() { + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, String.valueOf(Integer.MAX_VALUE)); + assertEquals(JDBCStorage.ddlLockBoundSeconds(), JDBCStorage.MAX_BOUND_SECONDS); + } + + @DataProvider + public Object[][] engines() { + return new Object[][] { + // postgres takes milliseconds, and "set local" is discarded by the commit that ends the + // DDL: there is nothing to read beforehand and nothing to put back afterwards + { "postgres", Dialect.POSTGRES, "0", asList("set local lock_timeout = 5000", THE_DDL) }, + // mysql takes seconds, and the setting outlives the transaction on a pooled connection: + // what the session carried (a year, by default) is read first and put back after + { "mysql", Dialect.MYSQL, "31536000", asList("select @@session.lock_wait_timeout", + "set session lock_wait_timeout=5", THE_DDL, "set session lock_wait_timeout=31536000") }, + // sql server takes milliseconds, and its setting bounds every lock wait of the session - + // -1, wait forever, is what a session of it carries until something says otherwise + { "sql server", Dialect.MICROSOFT, "-1", asList("select @@lock_timeout", + "set lock_timeout 5000", THE_DDL, "set lock_timeout -1") }, + // oracle is left to its own ddl_lock_timeout, which is tighter than anything set here + { "oracle", Dialect.ORACLE, "0", singletonList(THE_DDL) }, + }; + } + + /** What each engine is told around a DDL of this backend, in the order it is told it. */ + @Test(dataProvider = "engines") + public void testWhatEachEngineIsToldAroundADdl(String name, Dialect dialect, String carries, + List expected) throws Exception { + storage.withDdlLockBound(recording(mock(Connection.class), carries), dialect, theDdl()); + assertEquals(issued, expected, name); + } + + /** + * Oracle gives up on a DDL lock at once ({@code ddl_lock_timeout} is 0), so a bound of ours would + * only loosen it - and a deployment that raised it globally did so on purpose. Putting it back + * would mean reading {@code v$parameter}, which the account of a backend often may not. + */ + @Test + public void testOracleIsLeftToItsOwnDdlLockTimeout() { + assertNull(Dialect.ORACLE.ddlLockBoundSql(5, null)); + } + + /** An engine none of these statements fit is fed none of them, as its statistics are left alone. */ + @Test + public void testAnEngineThisBackendDoesNotKnowIsLeftAlone() throws Exception { + storage.withDdlLockBound(recording(mock(Connection.class), "0"), null, theDdl()); + assertEquals(issued, singletonList(THE_DDL)); + } + + /** + * ... and is told so once, rather than left to be found out. {@code dialectOf()} keys on the class + * name of the driver, so a mariadb, percona or aurora driver against a live mysql answers null + * here - and that is a session whose {@code lock_wait_timeout} is a year, which is the wait this + * bound exists to end. The strict parsing of the property exists so that a deployment which asked + * for a bound is never quietly left with none, and this is the same silence one property later. + */ + @Test + public void testAnEngineThisBackendDoesNotKnowIsReported() throws Exception { + storage.withDdlLockBound(recording(mock(Connection.class), "0"), null, theDdl()); + + assertTrue(storage.ddlLockBoundEngineUnknownWarned.get(), + "a driver this backend knows no lock bound for left the wait of every DDL unbounded and unsaid"); + } + + /** A deployment that turned the bound off asked for none anywhere, and has nothing to act on. */ + @Test + public void testAWaitNobodyAskedToBoundIsNotReportedAsAnUnknownEngine() throws Exception { + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, "0"); + + storage.withDdlLockBound(recording(mock(Connection.class), "0"), null, theDdl()); + + assertFalse(storage.ddlLockBoundEngineUnknownWarned.get(), + "a bound nobody asked for was reported as an engine this backend does not know"); + } + + /** + * And oracle is an engine this backend knows perfectly well: it is left to its own + * {@code ddl_lock_timeout} on purpose, which is a decision rather than a gap to report. + */ + @Test + public void testOracleIsNotReportedAsAnEngineThisBackendDoesNotKnow() throws Exception { + storage.withDdlLockBound(recording(mock(Connection.class), "0"), Dialect.ORACLE, theDdl()); + + assertFalse(storage.ddlLockBoundEngineUnknownWarned.get(), + "the engine left alone deliberately was reported as one this backend cannot bound"); + } + + /** Turning the bound off costs no round trip either: the DDL waits exactly as it did before. */ + @Test + public void testAnUnboundedWaitIssuesNoSessionStatement() throws Exception { + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, "0"); + storage.withDdlLockBound(recording(mock(Connection.class), "31536000"), Dialect.MYSQL, theDdl()); + assertEquals(issued, singletonList(THE_DDL)); + } + + /** + * The setting is put back even when the DDL fails. It is a pooled connection, and + * {@code CachedConnection.close()} only rolls back: on sql server the setting left behind would + * bound every lock wait of whoever borrows the connection next, row locks included, and + * {@code write()} replays no conflict of those. + */ + @Test + public void testTheBoundIsPutBackWhenTheDdlFails() throws Exception { + final SQLException rejected = new SQLException("table already exists", "42S01"); + try { + storage.withDdlLockBound(recording(mock(Connection.class), "31536000"), Dialect.MYSQL, () -> { + issued.add(THE_DDL); + throw rejected; + }); + fail("the failure of the ddl was swallowed"); + }catch (SQLException e) { + assertSame(e, rejected, "the failure of the ddl was replaced"); + } + assertEquals(issued, asList("select @@session.lock_wait_timeout", "set session lock_wait_timeout=5", + THE_DDL, "set session lock_wait_timeout=31536000")); + } + + /** + * A setting can reach the server and still fail on the close() of the statement that carried it - + * a connection that broke in between - and no driver tells that apart from a setting that never + * arrived. The session has it either way, so it is taken off again once the DDL is through: this + * connection goes back to a pool, and on sql server a lock_timeout left behind ends every lock wait + * of whoever borrows it next, row locks included. + */ + @Test + public void testASettingThatBrokeOnTheCloseOfItsStatementIsStillTakenOff() throws Exception { + final Connection con = breakingOnTheCloseOfASetting(mock(Connection.class), "31536000"); + + storage.withDdlLockBound(con, Dialect.MYSQL, theDdl()); + + assertEquals(issued, asList("select @@session.lock_wait_timeout", "set session lock_wait_timeout=5", + THE_DDL, "set session lock_wait_timeout=31536000")); + } + + /** + * And the DDL it wrapped is reported the way a bounded one is. The setting reached the server, so + * the wait really was bounded - reporting that failure as the bare 55P03 it arrives as is the gap + * this bound exists to close, and the log line above it says only that the bound may not be there. + */ + @Test + public void testADdlBoundedByASettingWhoseCloseFailedStillNamesTheProperty() throws Exception { + final SQLException lockWait = new SQLException("Lock wait timeout exceeded", "40001", 1205); + try { + storage.withDdlLockBound(breakingOnTheCloseOfASetting(mock(Connection.class), "31536000"), + Dialect.MYSQL, () -> { + throw lockWait; + }); + fail("the lock timeout was swallowed"); + }catch (SQLException e) { + assertTrue(e.getMessage().contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY), e.getMessage()); + assertSame(e.getCause(), lockWait, "the failure of the engine was not chained"); + } + } + + /** + * A value that could not be given back does not fail a DDL that went through. The restore runs + * from a finally while the caller may be being unwound, where a throw takes the place of whatever + * brought it there (JLS 14.20.2) - here a create table the engine accepted. + */ + @Test + public void testAValueThatCouldNotBeGivenBackDoesNotFailADdlThatWentThrough() throws Exception { + final Connection con = refusingToGiveTheValueBack(mock(Connection.class), "31536000"); + + storage.withDdlLockBound(con, Dialect.MYSQL, theDdl()); + + assertEquals(issued, asList("select @@session.lock_wait_timeout", "set session lock_wait_timeout=5", + THE_DDL, "set session lock_wait_timeout=31536000")); + } + + /** And it does not displace the failure of one that did not: that failure is what says what went wrong. */ + @Test + public void testAValueThatCouldNotBeGivenBackDoesNotDisplaceTheFailureOfADdl() throws Exception { + final SQLException rejected = new SQLException("table already exists", "42S01"); + try { + storage.withDdlLockBound(refusingToGiveTheValueBack(mock(Connection.class), "31536000"), + Dialect.MYSQL, () -> { + throw rejected; + }); + fail("the failure of the ddl was swallowed"); + }catch (SQLException e) { + assertSame(e, rejected, "the failure of the ddl was replaced by the one of the restore"); + } + } + + /** + * A bound with no way of putting back what it displaces is not set at all: a server whose session + * does not have the variable - a mysql-compatible one behind connector/j - would otherwise be + * given a bound this backend could never take off the pooled connection again. + */ + @Test + public void testABoundThatCannotBeReadBackIsNotSetAtAll() throws Exception { + final Connection con = mock(Connection.class); + final Statement statement = mock(Statement.class); + when(statement.executeQuery(anyString())) + .thenThrow(new SQLException("unknown system variable", "HY000", 1193)); + when(con.createStatement()).thenReturn(statement); + + storage.withDdlLockBound(con, Dialect.MYSQL, theDdl()); + + assertEquals(issued, singletonList(THE_DDL)); + verify(statement, never()).execute(anyString()); + } + + /** The same where the session answers with something no setting of it would take back. */ + @Test + public void testAValueTheSessionCouldNotBeGivenBackIsNotDisplaced() throws Exception { + storage.withDdlLockBound(recording(mock(Connection.class), "unlimited"), Dialect.MYSQL, theDdl()); + assertEquals(issued, asList("select @@session.lock_wait_timeout", THE_DDL)); + } + + /** + * A connection that refuses the setting outright leaves the DDL unbounded rather than failing it. + * The bound is an improvement on a wait: a backend that opened before this bound existed has to + * open still, and a session statement that fails on a connection whose DDL would have gone through + * is not a reason to fail that DDL. + */ + @Test + public void testAConnectionThatRefusesTheSettingStillRunsTheDdl() throws Exception { + final Connection con = mock(Connection.class); + when(con.createStatement()).thenThrow(new SQLException("no session statement here", "42000")); + + storage.withDdlLockBound(con, Dialect.POSTGRES, theDdl()); + + assertEquals(issued, singletonList(THE_DDL)); + } + + /** + * A DDL that gave up at the bound arrives as a bare 55P03 / 1205 / 1222, naming neither the wait + * it ended nor the property that ended it - the gap {@code timedOut()} closes for a statement + * bound. + */ + @Test + public void testALockTheDdlGaveUpOnNamesTheProperty() throws Exception { + final SQLException lockNotAvailable = new SQLException("canceling statement due to lock timeout", "55P03"); + try { + storage.withDdlLockBound(recording(mock(Connection.class), "0"), Dialect.POSTGRES, () -> { + throw lockNotAvailable; + }); + fail("the lock timeout was swallowed"); + }catch (SQLException e) { + assertTrue(e.getMessage().contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY), e.getMessage()); + assertSame(e.getCause(), lockNotAvailable, "the failure of the engine was not chained"); + assertEquals(e.getSQLState(), "55P03", "the state a caller classifies this by was dropped"); + } + } + + /** + * The state and the vendor number are carried over, so a caller classifying the failure reads + * exactly what it read before this bound existed: a mysql lock wait arrives in class 40, and that + * state alone is what {@code write()} replays a conflict on. + */ + @Test + public void testARewrittenMysqlLockWaitStaysTheConflictAWriteKnows() throws Exception { + final SQLException lockWait = new SQLException("Lock wait timeout exceeded; try restarting transaction", + "40001", 1205); + try { + storage.withDdlLockBound(recording(mock(Connection.class), "31536000"), Dialect.MYSQL, () -> { + throw lockWait; + }); + fail("the lock timeout was swallowed"); + }catch (SQLException e) { + assertTrue(e.getMessage().contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY), e.getMessage()); + assertEquals(e.getErrorCode(), 1205, "the number a caller classifies this by was dropped"); + assertTrue(JDBCStorage.isRetryableConflict(e, "com.mysql.cj.jdbc.ConnectionImpl"), + "a conflict write() replayed before this bound existed is no longer read as one"); + } + } + + /** + * And a sql server lock wait is left as unreplayable as it was: error 1222 is no conflict of + * {@code isConflict()}, and a DDL made to look like one would be replayed into the same wait. + */ + @Test + public void testARewrittenSqlServerLockWaitIsMadeNoMoreReplayable() throws Exception { + final SQLException lockWait = new SQLException("Lock request time out period exceeded.", "S0001", 1222); + try { + storage.withDdlLockBound(recording(mock(Connection.class), "-1"), Dialect.MICROSOFT, () -> { + throw lockWait; + }); + fail("the lock timeout was swallowed"); + }catch (SQLException e) { + assertTrue(e.getMessage().contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY), e.getMessage()); + assertEquals(e.getErrorCode(), 1222, "the number a caller classifies this by was dropped"); + assertFalse(JDBCStorage.isRetryableConflict(e, "com.microsoft.sqlserver.jdbc.SQLServerConnection"), + "a lock wait of a ddl was made a conflict write() would replay"); + } + } + + /** + * A failure of another kind is left exactly as it is: naming a property that had nothing to do + * with it sends an operator to raise a value that changes nothing about what they saw. + */ + @Test + public void testAFailureThatIsNotALockIsLeftExactlyAsItIs() throws Exception { + final SQLException denied = new SQLException("permission denied for schema public", "42501"); + try { + storage.withDdlLockBound(recording(mock(Connection.class), "0"), Dialect.POSTGRES, () -> { + throw denied; + }); + fail("the failure was swallowed"); + }catch (SQLException e) { + assertSame(e, denied, "a failure that is not a lock wait was reported as one"); + } + } + + /** + * And so is a statement the bound of its own class cancelled: {@code bulk.timeout} ends a create + * index the engine was working on, which is not a lock this DDL was queued for, and + * {@code timedOut()} has already named the property that ended it. + */ + @Test + public void testAStatementItsOwnBoundCancelledIsNotReportedAsALockWait() throws Exception { + final SQLException cancelled = new SQLTimeoutException("jdbc: the statement took 100200 ms, reaching the" + + " 100s of " + StatementBound.BULK.property, "57014", 0); + try { + storage.withDdlLockBound(recording(mock(Connection.class), "0"), Dialect.POSTGRES, () -> { + throw cancelled; + }); + fail("the cancelled statement was swallowed"); + }catch (SQLException e) { + assertSame(e, cancelled, "a statement its own bound cancelled was reported as a lock wait"); + } + } + + /** + * The drop of a tree goes through the funnel every DDL of a transaction takes, so it is bounded + * wherever it is issued from - {@code deleteTree()} here, and the create table and create index of + * {@code openTree()} the same way. + */ + @Test + public void testTheDropOfATreeIsBounded() throws Exception { + final JDBCStorage bounded = storageHandingOut(engine(postgresConnection.class, "0")); + + bounded.write(txn -> txn.deleteTree(TREE)); + + // the search path in front of them is the lookup that decides whether there is a table to drop + // at all, narrowed to the schemas an unqualified name of this connection resolves in (#888): it + // reads a session setting rather than the data, and takes a bound of its own + assertEquals(issued, asList("select unnest(current_schemas(true))", + "set local lock_timeout = 5000", + "drop table " + JDBCStorage.toTableName(TREE))); + } + + /** + * The delete that empties a tree before an import is no DDL: it waits for row locks, which + * {@code write()} replays a conflict of and which a bound meant for the metadata lock of a DDL has + * no business ending. + */ + @Test + public void testTheDeleteThatEmptiesATreeIsNotBounded() throws Exception { + final JDBCStorage bounded = storageHandingOut(engine(postgresConnection.class, "0")); + + // closed the way an import closes one: the importer holds a borrowed connection, and only its + // close() gives that connection - and the permit it took - back. The statements of that close are + // no part of this case, so what was issued is read before it. + try (final Importer importer = bounded.new ImporterImpl()) { + importer.clearTree(TREE); + + assertEquals(issued, singletonList("delete from " + JDBCStorage.toTableName(TREE))); + } + } + + /** + * The drop loop of {@code removeStorageFiles()} bypasses that funnel and commits once at the end, + * so the bound is set once around the whole loop rather than once per table - on postgres one + * {@code set local} covers every drop of the single transaction it runs in. + */ + @Test + public void testTheDropLoopOfARemovedBackendIsBoundedOnce() throws Exception { + final Connection con = engine(postgresConnection.class, "0"); + final JDBCStorage.TableScope scope = JDBCStorage.TableScope.of(storage, con); + issued.clear(); // the search path the scope read is no part of what this case is about + + final JDBCStorage.ClearCounts counts = storage.dropCatalogTables(con, scope, catalogOf(TREE, OTHER_TREE)); + + assertEquals(issued, asList("set local lock_timeout = 5000", + "drop table " + JDBCStorage.toTableName(TREE), + "drop table " + JDBCStorage.toTableName(OTHER_TREE))); + assertEquals(counts.dropped, 2, "the clear did not account for the tables it dropped under the bound"); + } + + /** + * And a clear with no row to act on is committed without the bound: putting it on costs a readback + * and a restore of its own, and the first clear of a backend upgraded from a version that kept no + * catalog - the case {@code CLEAR_DROPPED_NOTHING} describes - has no DDL for them to bound. + */ + @Test + public void testAClearWithNoTableToDropIsGivenNoBound() throws Exception { + final Connection con = engine(postgresConnection.class, "0"); + final JDBCStorage.TableScope scope = JDBCStorage.TableScope.of(storage, con); + issued.clear(); + + storage.dropCatalogTables(con, scope, Collections.emptyMap()); + + assertEquals(issued, emptyList()); + } + + /** + * The create table of the tree catalog is the DDL of this backend that goes through neither + * {@code commitStatement()} nor the drop loop: {@code openTree()} creates that table on the + * catalog's own connection before it enrols the tree it is opening, and a backend upgraded from a + * version that kept no catalog meets it on the open of every one of its trees. + */ + @Test + public void testTheCreateOfTheCatalogTableIsBounded() throws Exception { + final JDBCStorage bounded = storageHandingOut(engine(postgresConnection.class, "0"), + engine(postgresConnection.class, "0", catalogIssued)); + + bounded.write(txn -> txn.openTree(TREE, true)); + + assertEquals(firstOfTheCatalog(2), asList("set local lock_timeout = 5000", + "create table " + CATALOG_TABLE + " (h char(128),k bytea,v bytea,primary key(h,k))")); + } + + /** + * And it goes through the same helper every other DDL of this backend does, so the session of an + * engine whose setting outlives the transaction is read back first and given its value back after + * - on a connection which is not the pool's, and which the write that opened it closes. + */ + @Test + public void testTheCreateOfTheCatalogTableGivesMysqlItsValueBack() throws Exception { + final JDBCStorage bounded = storageHandingOut(engine(mysqlConnection.class, "31536000"), + engine(mysqlConnection.class, "31536000", catalogIssued)); + + bounded.write(txn -> txn.openTree(TREE, true)); + + assertEquals(firstOfTheCatalog(4), asList("select @@session.lock_wait_timeout", + "set session lock_wait_timeout=5", + "create table " + CATALOG_TABLE + " (h char(128),k varbinary(255),v longblob,primary key(h,k))", + "set session lock_wait_timeout=31536000")); + } + + /** + * A lock that create gave up on names the property that ended the wait, all the way out to the + * operator: the failure is wrapped as the backend not being able to create the table which holds + * its catalog, and a bare 55P03 inside that says nothing about which wait ended or what to raise. + */ + @Test + public void testALockTheCreateOfTheCatalogTableGaveUpOnNamesTheProperty() throws Exception { + final JDBCStorage bounded = storageHandingOut(engine(postgresConnection.class, "0"), + failingTheCreate(engine(postgresConnection.class, "0", catalogIssued), + new SQLException("canceling statement due to lock timeout", "55P03"))); + + try { + bounded.write(txn -> txn.openTree(TREE, true)); + fail("a create of the catalog table that gave up on a lock has to reach the caller"); + }catch (Exception expected) { + assertTrue(namesTheProperty(expected), + "the lock this bound ended reached the operator unnamed: " + expected); + } + } + + /** The statements of the catalog's connection a case reads, without running off its end. */ + private List firstOfTheCatalog(int statements) { + return catalogIssued.subList(0, Math.min(statements, catalogIssued.size())); + } + + /** Whether the failure, or any link of its chain, names the property that ended the wait. */ + private static boolean namesTheProperty(Throwable failure) { + for (Throwable link = failure; link != null; link = link.getCause()) { + if (link.getMessage() != null + && link.getMessage().contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY)) { + return true; + } + } + return false; + } + + /** A connection whose create table is the statement the engine refuses, with the given failure. */ + private Connection failingTheCreate(final Connection con, final SQLException failure) throws SQLException { + // doAnswer() rather than when(): the connection has been given a prepareStatement() already, and + // calling it inside a when() would run that answer - which stubs a mock of its own - in the + // middle of this stubbing, which mockito reads as a stubbing that never named a method + doAnswer(invocation -> { + final String sql = (String) invocation.getArguments()[0]; + catalogIssued.add(sql); + final PreparedStatement statement = mock(PreparedStatement.class); + when(statement.getConnection()).thenReturn(con); + if (sql.startsWith("create table ")) { + when(statement.executeUpdate()).thenThrow(failure); + } + return statement; + }).when(con).prepareStatement(anyString()); + return con; + } + + /** A catalog naming each of the given trees at the table its name hashes to. */ + private static Map catalogOf(TreeName... trees) { + final Map catalog = new LinkedHashMap<>(); + for (final TreeName tree : trees) { + catalog.put(tree, JDBCStorage.toTableName(tree)); + } + return catalog; + } + + /** + * A session already giving up sooner than this bound keeps exactly what it has: a deployment that + * set {@code lock_wait_timeout} tighter did so on purpose, and loosening it to ours for the length + * of a DDL is the very thing that leaves oracle alone. Nothing is set, so nothing is put back + * either. + */ + @Test + public void testAMysqlSessionAlreadyTighterThanTheBoundKeepsWhatItHas() throws Exception { + storage.withDdlLockBound(recording(mock(Connection.class), "1"), Dialect.MYSQL, theDdl()); + + assertEquals(issued, asList("select @@session.lock_wait_timeout", THE_DDL)); + } + + /** + * On sql server 0 is "do not wait at all", which is tighter than any bound of ours, while -1 is + * "wait forever" and is replaced - the case the data provider above covers. A value read as a + * number that happens to be negative must not be mistaken for a tight one. + */ + @Test + public void testASqlServerSessionThatDoesNotWaitAtAllKeepsWhatItHas() throws Exception { + storage.withDdlLockBound(recording(mock(Connection.class), "0"), Dialect.MICROSOFT, theDdl()); + + assertEquals(issued, asList("select @@lock_timeout", THE_DDL)); + } + + /** + * Outside a transaction block postgres answers {@code SET LOCAL} with a warning and does nothing + * with it: the driver raises nothing, so the DDL would run with no bound at all and the log would + * read exactly like a bounded one. The setting is not issued there. + */ + @Test + public void testAConnectionInAutoCommitIsGivenNoSetLocal() throws Exception { + final Connection con = recording(mock(Connection.class), "0"); + when(con.getAutoCommit()).thenReturn(true); + + storage.withDdlLockBound(con, Dialect.POSTGRES, theDdl()); + + assertEquals(issued, singletonList(THE_DDL)); + } + + /** + * A statement that fails inside a postgres transaction aborts it, and the DDL after it would then + * fail with 25P02 rather than running unbounded as it did before this bound existed - a backend + * that used to open would stop opening because of the bound meant to protect it. The transaction is + * taken back to the point before the setting, which also undoes a {@code set local} that did reach + * the server. + */ + @Test + public void testTheTransactionIsTakenBackToBeforeASettingThatFailed() throws Exception { + final Connection con = mock(Connection.class); + final Savepoint beforeTheBound = mock(Savepoint.class); + when(con.setSavepoint()).thenReturn(beforeTheBound); + when(con.createStatement()).thenThrow(new SQLException("current transaction is aborted", "25P02")); + + storage.withDdlLockBound(con, Dialect.POSTGRES, theDdl()); + + verify(con).rollback(beforeTheBound); + assertEquals(issued, singletonList(THE_DDL)); + } + + /** And a setting that went through is left standing: it is what bounds the DDL that follows it. */ + @Test + public void testATransactionWhoseSettingWentThroughIsNotTakenBack() throws Exception { + final Connection con = recording(mock(Connection.class), "0"); + final Savepoint beforeTheBound = mock(Savepoint.class); + when(con.setSavepoint()).thenReturn(beforeTheBound); + + storage.withDdlLockBound(con, Dialect.POSTGRES, theDdl()); + + verify(con, never()).rollback(beforeTheBound); + assertEquals(issued, asList("set local lock_timeout = 5000", THE_DDL)); + } + + /** + * More than one wait of an engine reports the same number: mysql reports the row lock of + * {@code innodb_lock_wait_timeout} - 50 s by default, and what a create index under + * {@code ALGORITHM=COPY} waits on - as the same ERROR 1205 as a metadata lock. A wait that ran far + * longer than this bound was ended by something else, and naming this property for it would send an + * operator to raise the one setting that cannot help. + */ + @Test + public void testALockWaitFarPastTheBoundIsLeftExactlyAsItIs() { + final SQLException rowLock = new SQLException("Lock wait timeout exceeded; try restarting transaction", + "40001", 1205); + final long fiftySecondsAgo = System.nanoTime() - 50L * 1000 * 1000 * 1000; + + assertSame(storage.gaveUpOnTheLock(rowLock, Dialect.MYSQL, 5, fiftySecondsAgo), rowLock, + "a wait of innodb_lock_wait_timeout was reported as the bound this backend sets"); + } + + /** While one that ended where this bound is is renamed, which is what the bound exists to say. */ + @Test + public void testALockWaitTheBoundCouldHaveEndedIsRenamed() { + final SQLException lockWait = new SQLException("Lock wait timeout exceeded", "40001", 1205); + + final SQLException renamed = storage.gaveUpOnTheLock(lockWait, Dialect.MYSQL, 5, System.nanoTime()); + + assertTrue(renamed.getMessage().contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY), renamed.getMessage()); + assertSame(renamed.getCause(), lockWait, "the failure of the engine was not chained"); + } + + /** + * A connection left carrying a bound this backend could not take off again does not go back into + * the pool. Leaving it to the next borrow to notice does not work: that validation is + * {@code isValid()}, a liveness check such a connection passes - and on sql server the setting left + * on it would cut every lock wait of the next borrower, row locks included, which + * {@code isConflict()} classifies as no replayable conflict. + */ + @Test + public void testAConnectionWhoseBoundCouldNotBeTakenOffIsKeptOutOfThePool() throws Exception { + final AtomicBoolean keptOut = new AtomicBoolean(); + final Connection parent = refusingToGiveTheValueBack(mock(Connection.class), "31536000"); + try (final CachedConnection con = new CachedConnection("jdbc:mock", parent) { + @Override + void keepOutOfThePool() { + keptOut.set(true); + super.keepOutOfThePool(); + } + }) { + storage.withDdlLockBound(con, Dialect.MYSQL, theDdl()); + } + + assertTrue(keptOut.get(), "a connection left carrying our bound was handed back to the pool"); + } + + /** + * The round trips of the bound itself carry a bound of their own. Unbounded, a readback on a + * connection whose peer went quiet with the socket still open parks the thread opening a backend + * for good - the hang #877 and #882 exist to end - and the restore does it from the finally of a + * DDL that has already failed. The DDL between them keeps the class it had, which ships unbounded. + */ + @Test + public void testTheRoundTripsOfTheBoundCarryOneOfTheirOwn() throws Exception { + final List armed = new ArrayList<>(); + final Connection con = recording(mock(Connection.class), "31536000"); + doAnswer(invocation -> { + armed.add((Integer) invocation.getArguments()[1]); + return null; + }).when(con).setNetworkTimeout(any(), anyInt()); + + storage.withDdlLockBound(con, Dialect.MYSQL, theDdl()); + + assertTrue(armed.contains((JDBCStorage.SESSION_STATEMENT_BOUND_SECONDS + + JDBCStorage.BACKSTOP_MARGIN_SECONDS) * 1000), + "the session statements of the bound armed no socket read timeout: " + armed); + } + + /** The DDL itself, recording that it ran in among the session statements issued around it. */ + private JDBCStorage.Execution theDdl() { + return () -> { + issued.add(THE_DDL); + return null; + }; + } + + /** + * A connection recording every session statement it is given, and answering the readback of the + * setting with the value a session of that engine carries. + */ + private Connection recording(final Connection con, final String carries) throws SQLException { + return recording(con, carries, issued); + } + + /** The same, recording into the list the statements of this connection belong in. */ + private Connection recording(final Connection con, final String carries, final List into) + throws SQLException { + final Statement statement = mock(Statement.class); + when(statement.execute(anyString())).thenAnswer(invocation -> { + into.add((String) invocation.getArguments()[0]); + return false; + }); + when(statement.executeQuery(anyString())).thenAnswer(invocation -> { + into.add((String) invocation.getArguments()[0]); + final ResultSet carried = mock(ResultSet.class); + when(carried.next()).thenReturn(true, false); + when(carried.getString(1)).thenReturn(carries); + return carried; + }); + when(con.createStatement()).thenReturn(statement); + return con; + } + + /** + * The same, on a connection that takes a setting through and then breaks as the statement that + * carried it is closed - all a driver reports of a session that went in between. + */ + private Connection breakingOnTheCloseOfASetting(final Connection con, final String carries) + throws SQLException { + final Statement statement = recording(con, carries).createStatement(); + final AtomicBoolean carried = new AtomicBoolean(); + doAnswer(invocation -> { + issued.add((String) invocation.getArguments()[0]); + carried.set(true); + return false; + }).when(statement).execute(anyString()); + doAnswer(invocation -> { + if (carried.get()) { + throw new SQLException("the connection went as the statement was closed", "08006"); + } + return null; + }).when(statement).close(); + return con; + } + + /** And one that takes the bound and will not take back the value that bound displaced. */ + private Connection refusingToGiveTheValueBack(final Connection con, final String carries) throws SQLException { + final Statement statement = recording(con, carries).createStatement(); + final AtomicBoolean bound = new AtomicBoolean(); + doAnswer(invocation -> { + issued.add((String) invocation.getArguments()[0]); + if (!bound.compareAndSet(false, true)) { + throw new SQLException("the connection went before the value could be given back", "08006"); + } + return false; + }).when(statement).execute(anyString()); + return con; + } + + /** + * Connections whose class names carry the engine the way the drivers' own do - pgjdbc's + * {@code org.postgresql.jdbc.PgConnection}. That name is what {@code dialectOf()} reads the + * engine off, and the name of a mock is derived from the type it mocks, so a mock of plain + * {@link Connection} reaches no engine branch at all. Lowercase because the match is case + * sensitive. + */ + interface postgresConnection extends Connection { + } + + /** The same for mysql, whose setting outlives the transaction and is read back and put back. */ + interface mysqlConnection extends Connection { + } + + /** + * A connection of the given engine, recording the statements it is asked to run - the DDL among the + * session settings around it - over a catalog holding the table of every tree named here. + */ + private Connection engine(Class engine, String carries) throws SQLException { + return engine(engine, carries, issued); + } + + /** The same, recording into the list the statements of this connection belong in. */ + private Connection engine(Class engine, String carries, List into) + throws SQLException { + final Connection con = recording(mock(engine), carries, into); + when(con.isValid(anyInt())).thenReturn(true); + when(con.prepareStatement(anyString())).thenAnswer(invocation -> { + into.add((String) invocation.getArguments()[0]); + final PreparedStatement statement = mock(PreparedStatement.class); + when(statement.getConnection()).thenReturn(con); + return statement; + }); + final DatabaseMetaData metaData = mock(DatabaseMetaData.class); + when(metaData.getTables(any(), any(), any(), any())).thenAnswer(invocation -> { + final ResultSet tables = mock(ResultSet.class); + final String asked = (String) invocation.getArguments()[2]; + // Every tree of a case is found to exist, and the tree catalog of the backend is found not + // to be there: what these cases are about is the statements issued around a DDL, and a + // backend upgraded from a version that kept no catalog takes the shortest way to the funnel + // carrying them - the catalog would otherwise want a connection of its own, which is not a + // connection this mock hands out. CatalogConnectionTestCase covers that one. + when(tables.next()).thenReturn(!CATALOG_TABLE.equals(asked), false); + // the name the catalog was asked about, so that every tree of a case is found to exist + when(tables.getString("TABLE_NAME")).thenReturn(asked); + return tables; + }); + // The index of a tree is found missing, which is the shortest way through openTree() to the + // catalog table it creates on the way: a getIndexInfo() no case answers comes back null, which + // is a NullPointerException inside the lookup rather than a case. The create index that then + // follows is issued on the caller's connection, where these cases read nothing. + when(metaData.getIndexInfo(any(), any(), anyString(), anyBoolean(), anyBoolean())) + .thenAnswer(invocation -> { + final ResultSet indexes = mock(ResultSet.class); + when(indexes.next()).thenReturn(false); + return indexes; + }); + when(con.getMetaData()).thenReturn(metaData); + return con; + } + + /** + * A storage handing out the given connection, through the seam an import of + * {@code JDBCStatementBoundTestCase} borrows through: what these cases are about is the statements + * around a DDL, not the pool that produced the connection carrying them. + */ + private JDBCStorage storageHandingOut(final Connection con) { + return storageHandingOut(con, null); + } + + /** + * The same, handing out the given connection for the tree catalog as well: that connection is not + * a pooled one - {@code CatalogSession} opens it through {@code newCatalogConnection()} - so it is + * given its own seam rather than borrowed through the one above. + */ + private JDBCStorage storageHandingOut(final Connection con, final Connection catalogCon) { + final JDBCStorage handing = new JDBCStorage(backendCfg(), null) { + @Override + Connection getConnection(boolean trusted) { + return new CachedConnection("jdbc:mock", con); + } + + @Override + Connection newCatalogConnection(long budgetDeadline) throws SQLException { + if (catalogCon == null) { + throw new SQLException("this case opens no catalog connection"); + } + return catalogCon; + } + + @Override + Connection newStampConnection(Dialect dialect) throws SQLException { + // The stamp of an open is no part of any case here, and commentTable() takes this for + // what it is - a stamp connection that could not be made, which leaves the table + // unstamped and the open unaffected. Answered here rather than left to fail on its own, + // because failing on its own means DriverManager: this suite needs no database, and a + // mock-only case has no business registering every jdbc driver on the classpath. + throw new SQLException("this case stamps nothing"); + } + + @Override + public StorageStatus getStorageStatus() { + return StorageStatus.working(); // open already, so an importer borrows and no more + } + }; + handing.accessMode = AccessMode.READ_WRITE; + return handing; + } +} diff --git a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java index 0272ec0800..2a002a8c33 100644 --- a/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java +++ b/opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java @@ -267,6 +267,138 @@ public void testTheStandingReadBoundReachesTheSocket() throws Exception { } } + /** + * The DDL of this backend is the part of it that takes locks, and three engines out of four wait + * for one essentially forever: a drop queued behind an unrelated transaction of another session + * used to hang the backend that issued it, with no property to say otherwise (#885). It gives up + * at the bound now, and says which property ended the wait. + *

+ * Oracle asserts the other half of the same contract: nothing of ours is set there, because its + * own {@code ddl_lock_timeout} gives up at once - so the drop still fails rather than hanging, and + * the failure names the engine's own doing rather than a property of ours that armed nothing. + */ + @Test(timeOut = 120000) + public void testTheDdlGivesUpOnALockAnotherSessionHolds() throws Exception { + final TreeName tree = new TreeName("testDdlLockBound", "tree"); + final JDBCStorage storage = new JDBCStorage(createBackendCfg(), null); + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, "2"); + try { + storage.open(AccessMode.READ_WRITE); + storage.write(new WriteOperation() { + @Override + public void run(WriteableTransaction txn) throws Exception { + txn.openTree(tree, true); + txn.put(tree, key(1), value(1)); + } + }); + + // a session of its own, holding a lock the drop below conflicts with on every one of these + // engines: an uncommitted write takes a lock on the table that a drop cannot share + try (final Connection holder = DriverManager.getConnection(getJdbcUrl())) { + holder.setAutoCommit(false); + try (final PreparedStatement write = holder.prepareStatement( + "insert into " + JDBCStorage.toTableName(tree) + " (h,k,v) values (?,?,?)")) { + write.setString(1, "a lock this session holds"); + write.setBytes(2, new byte[]{ 1 }); + write.setBytes(3, new byte[]{ 1 }); + write.executeUpdate(); + } + final JDBCStorage.Dialect dialect = dialect(); + + final long startedAt = System.nanoTime(); + Exception failure = null; + try { + storage.write(new WriteOperation() { + @Override + public void run(WriteableTransaction txn) throws Exception { + txn.deleteTree(tree); + } + }); + fail("the drop went through while another session held the table locked"); + } catch (Exception e) { + failure = e; + } + final String reported = stackTraceToSingleLineString(failure); + final long tookSeconds = (System.nanoTime() - startedAt) / 1000000000L; + // generous, and still far under what an unbounded wait costs: mysql waits a year for a + // metadata lock by default, sql server and postgres wait for one without limit at all + assertTrue(tookSeconds < 60, "the drop waited " + tookSeconds + " s for the lock: " + reported); + // By the engine's own verdict rather than by the text of the message: without this the case + // passes for a drop that failed because the table was not there, because the account lacked + // the privilege, or because the statement never reached the engine - none of which is a lock + // this drop gave up on. ORA-00054 on oracle, 55P03 / 1205 / 1222 on the other three. + assertTrue(JDBCStorage.lockNotAvailable(failure, dialect), + "the drop did not fail as this engine says a lock was not available: " + reported); + if (dialect == JDBCStorage.Dialect.ORACLE) { + assertFalse(reported.contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY), + "oracle is left to its own ddl_lock_timeout: " + reported); + } else { + assertTrue(reported.contains(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY), + "the failure names neither the wait nor the property that ended it: " + reported); + } + holder.rollback(); + } + } finally { + System.clearProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY); + try { + storage.write(new WriteOperation() { + @Override + public void run(WriteableTransaction txn) throws Exception { + txn.deleteTree(tree); + } + }); + } catch (Exception ignored) { + } finally { + storage.close(); + } + } + } + + /** + * The value a pooled connection carried is given back the moment the DDL is through. That + * connection outlives the transaction that borrowed it and {@code CachedConnection.close()} only + * rolls back, so a bound left on it would end every lock wait of whoever borrows it next - on sql + * server row locks included, which {@code isConflict()} classifies as no replayable conflict, so + * {@code write()} would not replay them and a client would see a hard failure. + *

+ * {@code JDBCDdlLockBoundTestCase} pins the string each engine is handed; only a session of the + * engine itself can say what it does with it. Postgres asserts the other shape of the same + * contract: nothing is put back by hand there, because a {@code set local} belongs to the + * transaction and is gone with the commit that ends the DDL. + */ + @Test(timeOut = 120000) + public void testAConnectionGetsItsLockBoundBackAfterADdl() throws Exception { + final JDBCStorage.Dialect dialect = dialect(); + final JDBCStorage storage = new JDBCStorage(createBackendCfg(), null); + System.setProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY, "7"); + try { + storage.open(AccessMode.READ_WRITE); + try (final Connection con = CachedConnection.getConnection(getJdbcUrl())) { + final String before = sessionLockBound(con); + if (before == null) { // oracle: nothing of ours is set there, and v$parameter is out of reach + throw new SkipException("no session lock bound to read on " + getJdbcUrl()); + } + final String[] during = new String[1]; + storage.withDdlLockBound(con, dialect, () -> { + during[0] = sessionLockBound(con); + return null; + }); + assertNotEquals(during[0], before, + "the bound was never on the session the DDL ran on: it carried " + during[0]); + if (dialect.boundLivesInTheTransaction()) { + assertEquals(sessionLockBound(con), during[0], + "a set local was taken off before the commit that is what discards it"); + con.commit(); + } + assertEquals(sessionLockBound(con), before, + "the value the session carried was not given back after the DDL"); + } + } finally { + System.clearProperty(JDBCStorage.DDL_LOCK_TIMEOUT_PROPERTY); + storage.close(); + } + } + private static ByteString key(int i) { return ByteString.valueOfUtf8(String.format("key%02d", i)); } @@ -1056,7 +1188,7 @@ JDBCStorage.Dialect dialect() { * engine, or null where reading it needs a privilege the test user does not have: oracle * keeps ddl_lock_timeout in v$parameter, which an application user cannot select from. */ - String sessionLockBound(Connection con) throws Exception { + String sessionLockBound(Connection con) throws SQLException { final String url = getJdbcUrl(); final String sql; if (url.startsWith("jdbc:postgresql")) {