From edbfaf7321e36431f576ff48a3771b66016b1620 Mon Sep 17 00:00:00 2001 From: Mark Hannum Date: Tue, 11 Aug 2026 15:17:43 -0400 Subject: [PATCH 1/2] Abort a copy when recovery could rewind pages during it comdb2ar reads data files live; it tolerates forward page writes but not recovery that rewinds the log (__log_vtruncate), which silently corrupts the archive. Make copy and recovery mutually exclusive: a new logdelete4 appsock holds recoverlk and the bdb lock in read mode for the copy's duration (bdb before recoverlk, matching recovery's order, so no deadlock), polls to yield if an exclusive op waits, and reports ok/aborted via a copy_complete handshake so comdb2ar discards a doomed copy. comdb2ar negotiates logdelete4 then falls back to logdelete3/2 on an "unknown command" reply; a handshake timeout instead means the server is busy draining a recovery, so it fails hard rather than downgrade to an unprotected copy. debug_block_comdb2ar is gated to v4 for the test. Signed-off-by: Mark Hannum --- bdb/bdb_api.h | 4 + bdb/rep.c | 15 +++ plugins/logdelete/logdelete.c | 233 +++++++++++++++++++++++++++------- plugins/logdelete/plugin.h.in | 11 ++ tools/comdb2ar/appsock.cpp | 20 ++- tools/comdb2ar/appsock.h | 7 +- tools/comdb2ar/logholder.cpp | 69 ++++++++-- tools/comdb2ar/logholder.h | 18 ++- tools/comdb2ar/serialise.cpp | 10 ++ 9 files changed, 321 insertions(+), 66 deletions(-) diff --git a/bdb/bdb_api.h b/bdb/bdb_api.h index cb4c191ed2..533c9cec65 100644 --- a/bdb/bdb_api.h +++ b/bdb/bdb_api.h @@ -2375,6 +2375,10 @@ void bdb_get_txn_stats(bdb_state_type *bdb_state, int64_t *active, uint32_t bdb_get_rep_gen(bdb_state_type *bdb_state); int bdb_recoverlk_blocked(bdb_state_type *bdb_state); +/* Take/release the recovery lock in read mode (held by a hot copy so recovery + * cannot rewind pages underneath it; poll bdb_recoverlk_blocked to yield). */ +int bdb_readlock_recovery(bdb_state_type *bdb_state); +int bdb_unlock_recovery(bdb_state_type *bdb_state); void send_newmaster(bdb_state_type *bdb_state, int online); diff --git a/bdb/rep.c b/bdb/rep.c index 7e80cf05f4..d60cab1eac 100644 --- a/bdb/rep.c +++ b/bdb/rep.c @@ -2062,6 +2062,21 @@ int bdb_recoverlk_blocked(bdb_state_type *bdb_state) return bdb_state->dbenv->wrlock_recovery_blocked(bdb_state->dbenv); } +/* Take/release the recovery lock in read mode. A hot copy holds this (along + * with the bdb read lock) for its duration: recovery write-locks recoverlk + * before it rewinds any page -- in both online and offline modes -- so a reader + * blocks recovery from running underneath the copy. Poll bdb_recoverlk_blocked() + * to learn when recovery is waiting and yield. See the logdelete appsock. */ +int bdb_readlock_recovery(bdb_state_type *bdb_state) +{ + return bdb_state->dbenv->lock_recovery_lock(bdb_state->dbenv, __func__, __LINE__); +} + +int bdb_unlock_recovery(bdb_state_type *bdb_state) +{ + return bdb_state->dbenv->unlock_recovery_lock(bdb_state->dbenv, __func__, __LINE__); +} + void send_newmaster(bdb_state_type *bdb_state, int online) { bdb_state->dbenv->rep_start(bdb_state->dbenv, NULL, 0, DB_REP_MASTER); diff --git a/plugins/logdelete/logdelete.c b/plugins/logdelete/logdelete.c index 4ec092146e..ce749b7f05 100644 --- a/plugins/logdelete/logdelete.c +++ b/plugins/logdelete/logdelete.c @@ -19,12 +19,66 @@ #include "comdb2_appsock.h" #include #include "unistd.h" +#include +#include +#include +#include + +#include +#include /* For testcase demonstrating that file-delete cannot occur during a copy */ int gbl_debug_block_comdb2ar = 0; -/* Forward declaration */ +/* How often (ms) the logdelete4 copy loop wakes to check whether an exclusive + * operation (recovery / upgrade / downgrade) is waiting on a lock the copy is + * holding, and to notice the copy client disconnecting. */ +static int gbl_copy_poll_ms = 1000; + +/* Forward declarations */ comdb2_appsock_t logdelete3_plugin; +comdb2_appsock_t logdelete4_plugin; + +/* Return 1 if the peer has closed the connection. Called only after a read + * timeout (when the comdb2buf read buffer is drained), so a raw peek on the fd + * is authoritative. comdb2buf itself cannot distinguish a read timeout from an + * EOF -- both surface as a negative return -- so we probe the socket directly. */ +static int copy_peer_closed(int fd) +{ + struct pollfd pfd = {.fd = fd, .events = POLLIN}; + int rc = poll(&pfd, 1, 0); + if (rc <= 0) + return 0; /* no event pending -> it was a timeout, peer is alive */ + if (pfd.revents & (POLLHUP | POLLERR | POLLNVAL)) + return 1; + if (pfd.revents & POLLIN) { + char c; + int r = recv(fd, &c, 1, MSG_PEEK | MSG_DONTWAIT); + if (r == 0) + return 1; /* orderly shutdown */ + } + return 0; +} + +/* If recovery, or a node upgrade/downgrade, is waiting on a lock the copy holds, + * the copy is doomed: release the read locks so the operation can proceed, and + * mark the copy aborted. Recovery cannot rewind a page until we release, so a + * copy that gets here before answering copy_complete is correctly failed. + * Returns 1 if it just aborted the copy. */ +static int copy_yield_if_blocked(bdb_state_type *bdb_state, int *locks_held, int *aborted) +{ + if (!*locks_held || !(bdb_lock_desired(bdb_state) || bdb_recoverlk_blocked(bdb_state))) + return 0; + logmsg(LOGMSG_WARN, + "%s: releasing copy locks, an exclusive operation is waiting; " + "copy will be failed\n", + __func__); + bdb_unlock_recovery(bdb_state); + bdb_rellock(bdb_state, __func__, __LINE__); + *locks_held = 0; + *aborted = 1; + return 1; +} static int handle_logdelete_request(comdb2_appsock_arg_t *arg) { @@ -44,6 +98,14 @@ static int handle_logdelete_request(comdb2_appsock_arg_t *arg) thr_self = arg->thr_self; sb = arg->sb; + /* v3+ hands back recovery options; v4 additionally holds the copy's read + * locks against recovery and answers the copy_complete handshake. */ + int is_v3 = (strncmp(logdelete3_plugin.name, arg->cmdline, strlen(logdelete3_plugin.name)) == 0); + int is_v4 = (strncmp(logdelete4_plugin.name, arg->cmdline, strlen(logdelete4_plugin.name)) == 0); + bdb_state_type *bdb_state = thedb->bdb_env; + int locks_held = 0; + int aborted = 0; + /* There is no difference between log delete one and two, just that if the db doesn't have log delete two then the comdb2logdel.tsk @@ -64,7 +126,27 @@ static int handle_logdelete_request(comdb2_appsock_arg_t *arg) before_sc = gbl_sc_commit_count; logmsg(LOGMSG_INFO, "Disabling log file deletion\n"); - while (gbl_debug_block_comdb2ar) { + /* logdelete4: make the copy and recovery mutually exclusive. Hold the bdb + * read lock and the recovery read lock for the copy's duration. Recovery + * write-locks recoverlk (in both online and offline modes) before it rewinds + * any page, so holding recoverlk in read mode stops any recovery. Holding + * the bdb lock in read mode additionally blocks a node upgrade/downgrade + * (which take the bdb write lock and can lead to a rewind). Take the bdb + * lock first, then recoverlk, matching recovery's own order so we cannot + * deadlock. Acquiring them blocks until any in-flight recovery has finished, + * giving a consistent starting point. */ + if (is_v4) { + bdb_get_readlock(bdb_state, 0, "copy", __func__, __LINE__); + bdb_readlock_recovery(bdb_state); + locks_held = 1; + } + + /* Gated on is_v4 so the testcase can stall the v4 handshake specifically + * (the copy has already taken its read locks above) while a fallback + * logdelete3/2 connection still answers -- this is how the "hard-fail on a + * stalled v4 handshake instead of silently downgrading" test forces the + * timeout without also blocking the fallback it is checking we do NOT take. */ + while (gbl_debug_block_comdb2ar && is_v4) { logmsg(LOGMSG_USER, "%s blocking comdb2ar for testcase\n", __func__); sleep(1); } @@ -73,60 +155,112 @@ static int handle_logdelete_request(comdb2_appsock_arg_t *arg) cdb2buf_printf(sb, "log file deletion disabled\n"); cdb2buf_flush(sb); - if (strncmp(logdelete3_plugin.name, arg->cmdline, - strlen(logdelete3_plugin.name)) == 0) { - rc = bdb_recovery_start_lsn(thedb->bdb_env, recovery_lsn, - sizeof(recovery_lsn)); + if (is_v3 || is_v4) { + rc = bdb_recovery_start_lsn(thedb->bdb_env, recovery_lsn, sizeof(recovery_lsn)); if (rc) { logmsg(LOGMSG_ERROR, "bdb_recovery_start_lsn rc %d\n", rc); - snprintf(recovery_command, sizeof(recovery_command), - "-fullrecovery"); + snprintf(recovery_command, sizeof(recovery_command), "-fullrecovery"); } else { - snprintf(recovery_command, sizeof(recovery_command), - "-recovery_lsn %s", recovery_lsn); + snprintf(recovery_command, sizeof(recovery_command), "-recovery_lsn %s", recovery_lsn); } } - /* read from socket until it closes */ - cdb2buf_settimeout(sb, 0, 0); - while (cdb2buf_gets(line, sizeof(line), sb) > 0) { - static const char *delims = " \r\t\n"; - char *lasts; - char *tok; - tok = strtok_r(line, delims, &lasts); - if (!tok) { - continue; - } else if (strcmp(tok, "report_back") == 0) { - report_back = 1; - break; - } else if (strcmp(tok, "filenum") == 0) { - int filenum; - tok = strtok_r(NULL, delims, &lasts); - errno = 0; - if (tok && (filenum = strtol(tok, &lasts, 0)) > 0 && errno == 0 && - lasts && *lasts == '\0') { - log_delete_state.filenum = filenum; - log_delete_counter_change(thedb, LOG_DEL_REFRESH); - backend_update_sync(thedb); - } else { - logmsg(LOGMSG_ERROR, "logdelete2 thread got bad filenum <%s>\n", - tok); - cdb2buf_printf(sb, "expected +ve filenum\n"); + if (is_v4) { + /* Poll-based command loop. Wake every gbl_copy_poll_ms to (a) yield + * the read locks if an exclusive operation is waiting -- which means the + * copy is doomed, so we mark it aborted -- and (b) notice a disconnect. + * The copy learns whether it was aborted via the copy_complete reply. */ + int fd = cdb2buf_fileno(sb); + cdb2buf_settimeout(sb, gbl_copy_poll_ms, gbl_copy_poll_ms); + while (1) { + static const char *delims = " \r\t\n"; + char *lasts; + char *tok; + + if (cdb2buf_gets(line, sizeof(line), sb) <= 0) { + if (copy_peer_closed(fd)) + break; + /* read timeout: has an exclusive operation started waiting? */ + copy_yield_if_blocked(bdb_state, &locks_held, &aborted); + continue; + } + + tok = strtok_r(line, delims, &lasts); + if (!tok) { + continue; + } else if (strcmp(tok, "filenum") == 0) { + int filenum; + tok = strtok_r(NULL, delims, &lasts); + errno = 0; + if (tok && (filenum = strtol(tok, &lasts, 0)) > 0 && errno == 0 && lasts && *lasts == '\0') { + log_delete_state.filenum = filenum; + log_delete_counter_change(thedb, LOG_DEL_REFRESH); + backend_update_sync(thedb); + } else { + logmsg(LOGMSG_ERROR, "logdelete4 got bad filenum <%s>\n", tok ? tok : ""); + cdb2buf_printf(sb, "expected +ve filenum\n"); + cdb2buf_flush(sb); + } + } else if (strcmp(tok, "recovery_options") == 0) { + cdb2buf_printf(sb, "%s\n", recovery_command); + cdb2buf_flush(sb); + } else if (strcmp(tok, "copy_complete") == 0) { + /* The copy is valid iff the read locks were held continuously, + * i.e. no recovery/exclusive op ran during it. Check once more + * here: a fast copy can send copy_complete before the poll-loop + * timeout runs, but if an exclusive op is (or was) waiting it is + * still blocked behind our read locks, so we catch it now. */ + copy_yield_if_blocked(bdb_state, &locks_held, &aborted); + cdb2buf_printf(sb, "%s\n", aborted ? "aborted" : "ok"); cdb2buf_flush(sb); + } else { + logmsg(LOGMSG_ERROR, "logdelete4 got unknown token <%s>\n", tok); + } + } + } else { + /* read from socket until it closes */ + cdb2buf_settimeout(sb, 0, 0); + while (cdb2buf_gets(line, sizeof(line), sb) > 0) { + static const char *delims = " \r\t\n"; + char *lasts; + char *tok; + tok = strtok_r(line, delims, &lasts); + if (!tok) { continue; + } else if (strcmp(tok, "report_back") == 0) { + report_back = 1; + break; + } else if (strcmp(tok, "filenum") == 0) { + int filenum; + tok = strtok_r(NULL, delims, &lasts); + errno = 0; + if (tok && (filenum = strtol(tok, &lasts, 0)) > 0 && errno == 0 && lasts && *lasts == '\0') { + log_delete_state.filenum = filenum; + log_delete_counter_change(thedb, LOG_DEL_REFRESH); + backend_update_sync(thedb); + } else { + logmsg(LOGMSG_ERROR, "logdelete2 thread got bad filenum <%s>\n", tok); + cdb2buf_printf(sb, "expected +ve filenum\n"); + cdb2buf_flush(sb); + continue; + } + } else if (strcmp(tok, "recovery_options") == 0) { + logmsg(LOGMSG_DEBUG, "sent recovery options: %s\n", recovery_command); + cdb2buf_printf(sb, "%s\n", recovery_command); + cdb2buf_flush(sb); + } else { + logmsg(LOGMSG_ERROR, "logdelete2 thread got unknown token <%s>\n", tok); + /* la la la la fingers in my ears */ } - } else if (strcmp(tok, "recovery_options") == 0) { - logmsg(LOGMSG_DEBUG, "sent recovery options: %s\n", - recovery_command); - cdb2buf_printf(sb, "%s\n", recovery_command); - cdb2buf_flush(sb); - } else { - logmsg(LOGMSG_ERROR, "logdelete2 thread got unknown token <%s>\n", - tok); - /* la la la la fingers in my ears */ } } + if (locks_held) { + bdb_unlock_recovery(bdb_state); + bdb_rellock(bdb_state, __func__, __LINE__); + locks_held = 0; + } + logmsg(LOGMSG_INFO, "Reenabling log file deletion\n"); log_delete_rem_state(thedb, &log_delete_state); log_delete_counter_change(thedb, LOG_DEL_REFRESH); @@ -151,8 +285,7 @@ static int handle_logdelete_request(comdb2_appsock_arg_t *arg) /* If we committed a schema change then that's ruined it too... */ if (before_sc != after_sc) { - cdb2buf_printf(sb, - "Alert: schema changes committed during operation\n"); + cdb2buf_printf(sb, "Alert: schema changes committed during operation\n"); } cdb2buf_printf(sb, ".\n"); @@ -185,4 +318,12 @@ comdb2_appsock_t logdelete3_plugin = { handle_logdelete_request /* Handler function */ }; +comdb2_appsock_t logdelete4_plugin = { + "logdelete4", /* Name */ + "", /* Usage info */ + 0, /* Execution count */ + 0, /* Flags */ + handle_logdelete_request /* Handler function */ +}; + #include "plugin.h" diff --git a/plugins/logdelete/plugin.h.in b/plugins/logdelete/plugin.h.in index f8ad8eaf5d..3f3fbadc92 100644 --- a/plugins/logdelete/plugin.h.in +++ b/plugins/logdelete/plugin.h.in @@ -32,4 +32,15 @@ struct comdb2_plugin @PLUGIN_SYM@[] = { NULL, /* Destroy function */ &logdelete3_plugin /* Plugin-specific data */ }, + { + "logdelete", /* Plugin identifier */ + "logdelete plugin", /* Plugin description */ + COMDB2_PLUGIN_APPSOCK, /* Plugin type */ + 4, /* Plugin version */ + 1, /* Plugin interface version */ + 0, /* Plugin flags */ + NULL, /* Initialization function */ + NULL, /* Destroy function */ + &logdelete4_plugin /* Plugin-specific data */ + }, {0, 0, 0, 0, 0, 0, 0, 0, 0}}; diff --git a/tools/comdb2ar/appsock.cpp b/tools/comdb2ar/appsock.cpp index f0f882492c..99be64fff7 100644 --- a/tools/comdb2ar/appsock.cpp +++ b/tools/comdb2ar/appsock.cpp @@ -329,14 +329,24 @@ bool Appsock::response(const std::string& rsp) { SigPipeBlocker block_sigpipe; - // Get the response - we expect "log file deletion disable" + // Read one response line, distinguishing two failure modes the caller must + // treat differently: + // - no line at all within the timeout (cdb2buf_gets <= 0): the database + // accepted the request but did not answer in time. For logdelete4 this + // means the handler is blocked acquiring the copy locks -- typically + // because a recovery is already in flight -- so the caller must NOT + // quietly fall back to a lower, unprotected logdelete version. Throw so + // it fails hard. + // - a line came back but it is not what we expected: the database does not + // understand this request (an older DB answers "-1 #unknown command" + // immediately). Return false so the caller can step down a version. cdb2buf_settimeout(impl->m_sb, 10 * 1000, 10 * 1000); char line[256]; if(cdb2buf_gets(line, sizeof(line), impl->m_sb) <= 0) { - std::clog << "no response from " << impl->m_dbname << " expected " - << rsp << std::endl; - return false; - } else if(std::strcmp(line, rsp.c_str()) != 0) { + throw Error("no response from " + impl->m_dbname + + " (timeout or closed connection)"); + } + if(std::strcmp(line, rsp.c_str()) != 0) { std::clog << "bad response from " << impl->m_dbname << " expected " << rsp << std::endl; return false; diff --git a/tools/comdb2ar/appsock.h b/tools/comdb2ar/appsock.h index 30d2382aff..c08e1f2466 100644 --- a/tools/comdb2ar/appsock.h +++ b/tools/comdb2ar/appsock.h @@ -45,8 +45,11 @@ class Appsock { // Send a request to the database. bool response(const std::string& rsp); - // Listen for a response froom the database, returns true if the expected - // response was received. + // Listen for a response from the database. Returns true if the expected + // response was received, false if a different line came back (an older + // database that does not understand the request). Throws if no line + // arrives within the timeout or the connection closed -- so a caller + // negotiating logdelete4 fails hard instead of silently downgrading. std::string read_response(); }; diff --git a/tools/comdb2ar/logholder.cpp b/tools/comdb2ar/logholder.cpp index cc9a4e9ed7..34496052ca 100644 --- a/tools/comdb2ar/logholder.cpp +++ b/tools/comdb2ar/logholder.cpp @@ -45,22 +45,51 @@ void LogHolder_impl::reset(const std::string& dbname, const std::string& request } } -LogHolder::LogHolder(const std::string& dbname) : impl(new LogHolder_impl(dbname, "logdelete3\n")) +LogHolder::LogHolder(const std::string& dbname) : impl(new LogHolder_impl(dbname, "logdelete4\n")) { - - m_version = 3; - if(impl->mp_appsock.get() - && !impl->mp_appsock->response("log file deletion disabled\n")) { + + m_version = 4; + + // Negotiate the highest logdelete version the database supports. A database + // that does not understand a version answers "-1 #unknown command" + // immediately -- response() returns false -- and we step down to the next + // version. A *timeout* on logdelete4 is different: the database understood + // the request but could not answer in time, which means its handler is + // blocked acquiring the copy locks because a recovery is already in flight. + // Falling back to logdelete3 there would run the copy unprotected against + // that very recovery, so response() throws and we fail hard instead. + bool v4_ok = false; + if(impl->mp_appsock.get()) { + try { + v4_ok = impl->mp_appsock->response("log file deletion disabled\n"); + } catch(Error&) { + close(); + throw Error("logdelete4 handshake timed out on " + dbname + + " (database busy, possibly running recovery); refusing " + "to fall back to an unprotected copy"); + } + } + + if(impl->mp_appsock.get() && !v4_ok) { close(); - std::clog << "Doesn't support logdelete3" << std::endl; + std::clog << "Doesn't support logdelete4" << std::endl; - impl->reset(dbname, "logdelete2\n"); - m_version = 2; + impl->reset(dbname, "logdelete3\n"); + m_version = 3; if(impl->mp_appsock.get() && !impl->mp_appsock->response("log file deletion disabled\n")) { close(); - throw Error("Log holder appsock: bad response from " + dbname); + + std::clog << "Doesn't support logdelete3" << std::endl; + + impl->reset(dbname, "logdelete2\n"); + m_version = 2; + if(impl->mp_appsock.get() + && !impl->mp_appsock->response("log file deletion disabled\n")) { + close(); + throw Error("Log holder appsock: bad response from " + dbname); + } } } @@ -98,3 +127,25 @@ std::string LogHolder::recovery_options() else return ""; } + +bool LogHolder::copy_ok() +{ + // logdelete4 holds locks that block recovery for the copy's duration and + // releases them (marking the copy aborted) if an exclusive operation needs + // to run. Ask whether the hold stayed valid; a v4 database always answers, + // so anything but "ok" -- including a timeout or a dropped socket -- means + // the copy is not trustworthy. Pre-v4 databases have no such handshake. + if(impl->mp_appsock.get() && m_version >= 4) { + std::ostringstream request ; + request << "copy_complete" << "\n"; + impl->mp_appsock->request(request.str()); + try { + return impl->mp_appsock->read_response() == "ok"; + } catch(Error& e) { + std::clog << "copy_complete: no response from database: " + << e.what() << std::endl; + return false; + } + } + return true; +} diff --git a/tools/comdb2ar/logholder.h b/tools/comdb2ar/logholder.h index e5c22eb500..abbd73c429 100644 --- a/tools/comdb2ar/logholder.h +++ b/tools/comdb2ar/logholder.h @@ -33,10 +33,13 @@ class LogHolder { LogHolder(const std::string& dbname); // Construct a log holder object, opening the socket to the database and - // telling it to hold off on log file deletion. If this cannot be done - // for some reason then we will log this to std::clog but still construct - // a valid (inert) object. This is because the database might be down, - // so failure here is not an error. + // telling it to hold off on log file deletion. If the database cannot be + // reached at all (e.g. it is down) we log this to std::clog but still + // construct a valid (inert) object, because that is not an error. However, + // if the database accepts a logdelete4 connection but does not answer the + // handshake in time -- meaning it is busy acquiring the copy locks against a + // recovery already in flight -- we throw, rather than silently falling back + // to an older, unprotected logdelete version. virtual ~LogHolder(); // Destroy the object, closing our socket interface. @@ -52,6 +55,13 @@ class LogHolder { std::string recovery_options(); + bool copy_ok(); + // Ask the database (logdelete4+) whether the copy stayed valid -- i.e. no + // recovery or other exclusive operation ran during it. Returns true if the + // database confirms the copy is good, or if it is too old to have the + // handshake (pre-v4); returns false if the database reports the copy was + // aborted, or does not answer (timeout / dropped connection). + int version() { return m_version; }; }; diff --git a/tools/comdb2ar/serialise.cpp b/tools/comdb2ar/serialise.cpp index d7097bedcb..2ef477d84d 100644 --- a/tools/comdb2ar/serialise.cpp +++ b/tools/comdb2ar/serialise.cpp @@ -1500,6 +1500,16 @@ void serialise_database( sha_file.write(sha.c_str(), 40); } + // If recovery (or another exclusive operation) ran on the database while we + // were copying, the pages we captured no longer reconcile with the forward + // log replay the archive relies on, so the copy is corrupt. The database + // (logdelete4+) tells us via copy_complete; fail so the backup is discarded + // and retried rather than silently producing a bad copy. + if(log_holder.get() && !log_holder->copy_ok()) { + throw Error("recovery ran on the database during the copy; " + "archive would be corrupt - aborting"); + } + // Release the database for log file deletion. if(log_holder.get()) { log_holder->close(); From 8c35d3cdc1c9d270bf4b59e077bde9cda566b764 Mon Sep 17 00:00:00 2001 From: Mark Hannum Date: Tue, 11 Aug 2026 15:17:43 -0400 Subject: [PATCH 2/2] Test: abort a copy when recovery runs during the copy Holds a logdelete4 copy via debug_block_comdb2ar, forces a rewind with sys.cmd.truncate_time, and verifies comdb2ar aborts non-zero; also checks a clean copy still succeeds. Runs with online_recovery on and off. Plus: a stalled v4 handshake must fail hard, not silently downgrade to logdelete3. Signed-off-by: Mark Hannum --- tests/abort_copy_on_recovery.test/Makefile | 9 + tests/abort_copy_on_recovery.test/README | 23 ++ tests/abort_copy_on_recovery.test/lrl.options | 5 + tests/abort_copy_on_recovery.test/runit | 196 ++++++++++++++++++ 4 files changed, 233 insertions(+) create mode 100644 tests/abort_copy_on_recovery.test/Makefile create mode 100644 tests/abort_copy_on_recovery.test/README create mode 100644 tests/abort_copy_on_recovery.test/lrl.options create mode 100755 tests/abort_copy_on_recovery.test/runit diff --git a/tests/abort_copy_on_recovery.test/Makefile b/tests/abort_copy_on_recovery.test/Makefile new file mode 100644 index 0000000000..f276d17445 --- /dev/null +++ b/tests/abort_copy_on_recovery.test/Makefile @@ -0,0 +1,9 @@ +ifeq ($(TESTSROOTDIR),) + include ../testcase.mk +else + include $(TESTSROOTDIR)/testcase.mk +endif + +ifeq ($(TEST_TIMEOUT),) + export TEST_TIMEOUT=5m +endif diff --git a/tests/abort_copy_on_recovery.test/README b/tests/abort_copy_on_recovery.test/README new file mode 100644 index 0000000000..5743c04b0d --- /dev/null +++ b/tests/abort_copy_on_recovery.test/README @@ -0,0 +1,23 @@ +This test verifies that a hot copy (comdb2ar) is aborted if the database runs +recovery that rewinds the log (rep_verify_match) while the copy is in flight. + +Such a rewind -- which happens on a physical replicant when it truncates to +resync, or on a normal replicant that connects to a new master -- rewrites data +pages backwards, so the pages captured by an overlapping copy no longer +reconcile with the forward log replay the archive relies on. The copy would +otherwise be silently corrupt. + +The copy (logdelete4) holds the recovery lock and the bdb lock in read mode for +its duration; recovery write-locks these before it rewinds any page, in both +online and offline recovery modes. When recovery (or another exclusive +operation) waits on one of those locks, the copy releases them and is marked +aborted, and comdb2ar discards the archive. + +The test, for BOTH online_recovery on and off: + 1. Connects a copy and holds it at connect (debug_block_comdb2ar) after it has + taken the read locks. + 2. Forces a rewind with sys.cmd.truncate_time (blocks on the bdb write lock + when offline, on recoverlk when online). + 3. Releases the copy and verifies comdb2ar aborts with a non-zero exit, + reporting that recovery ran during the copy. + 4. Also verifies a copy with no concurrent recovery still succeeds. diff --git a/tests/abort_copy_on_recovery.test/lrl.options b/tests/abort_copy_on_recovery.test/lrl.options new file mode 100644 index 0000000000..66d674c513 --- /dev/null +++ b/tests/abort_copy_on_recovery.test/lrl.options @@ -0,0 +1,5 @@ +# Hold the copy open at connect time so we can force a rewind underneath it. +debug_block_comdb2ar 1 +# Keep checkpoints frequent so there is log history to rewind to. +setattr CHECKPOINTTIME 5 +setattr CHECKPOINTRAND 2 diff --git a/tests/abort_copy_on_recovery.test/runit b/tests/abort_copy_on_recovery.test/runit new file mode 100755 index 0000000000..07aba2489a --- /dev/null +++ b/tests/abort_copy_on_recovery.test/runit @@ -0,0 +1,196 @@ +#!/usr/bin/env bash +bash -n "$0" | exit 1 + +source ${TESTSROOTDIR}/tools/runit_common.sh +source ${TESTSROOTDIR}/tools/cluster_utils.sh + +export archivepid=0 +export truncpid=0 +export archiveout=./archive.out.$$ + +# Pin the node we operate on up front. The copy connects here and the rewind and +# the unblock all target this same node. +export MASTER=$(getmaster) +export MASTERLOG=${TESTDIR}/logs/${DBNAME}.${MASTER}.db + +# Create a table with some data and force a checkpoint so there is log history to +# rewind to. +function setup_data +{ + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME default "create table t1 (id int)" + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME default "insert into t1 select * from generate_series(1, 1000)" + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME --host $MASTER "exec procedure sys.cmd.send('flush')" +} + +function set_online_recovery +{ + local val=$1 + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME --host $MASTER "put tunable online_recovery $val" +} + +# Start a copy against the master. The remote copy stream (stdout) is discarded; +# its stderr is forwarded to us so we can capture the exit status and messages. +function start_archive +{ + rm -f $archiveout + ssh $MASTER "$COMDB2AR_EXE c ${DBDIR}/${DBNAME}.lrl 2>&1 >/dev/null" > $archiveout 2>&1 /dev/null) + echo "${n:-0}" +} + +# Wait until the logdelete handler for THIS copy has connected, taken its read +# locks, and parked in the debug_block_comdb2ar loop (so the locks are held +# before we induce a rewind). $1 is the hold_count captured before we started. +function wait_for_hold +{ + local base=$1 + local cnt=0 + while :; do + if [[ "$(hold_count)" -gt "$base" ]]; then + return 0 + fi + if ! kill -0 $archivepid 2>/dev/null; then + cat $archiveout + failexit "Archive process exited before it took the hold" + fi + let cnt=cnt+1 + if [[ $cnt -gt 20 ]]; then + cat $archiveout + failexit "Timed out waiting for the copy to take the hold" + fi + sleep 1 + done +} + +# Scenario: a copy that overlaps a rewind must be aborted. +function run_abort_scenario +{ + local online=$1 + echo "=== abort scenario, online_recovery=$online ===" + set_online_recovery $online + + # rewind target is now; the copy connects a moment later and the write below + # lands after it, so the truncate actually rolls something back. + local rewind_time=$(date +%s) + + local base=$(hold_count) + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME --host $MASTER "put tunable debug_block_comdb2ar 1" + start_archive + wait_for_hold $base + + # A write that lands after rewind_time; it proceeds under the copy's read + # locks (normal writes take neither the bdb write lock nor recoverlk). + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME default "insert into t1 select * from generate_series(1, 100)" >/dev/null 2>&1 + + # Force the rewind while the copy still holds its locks (debug_block). The + # truncate parks on the bdb write lock (offline) or recoverlk (online) that + # the copy holds; give it a few seconds to reach that block. + ( $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME --host $MASTER "exec procedure sys.cmd.truncate_time($rewind_time)" ) & + truncpid=$! + sleep 3 + + # Release the copy. When it answers copy_complete the exclusive operation is + # still blocked behind its read locks, so it drops the locks, marks the copy + # aborted, and comdb2ar discards the archive. + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME --host $MASTER "put tunable debug_block_comdb2ar 0" + + wait $archivepid + local rc=$? + wait $truncpid 2>/dev/null + cat $archiveout + + if [[ $rc -eq 0 ]]; then + failexit "online_recovery=$online: archive succeeded but should have aborted" + fi + if ! egrep -q "recovery ran on the database during the copy" $archiveout; then + failexit "online_recovery=$online: archive aborted (rc=$rc) but not for the expected reason" + fi + echo "online_recovery=$online: archive correctly aborted (rc=$rc)" +} + +# Scenario: a copy with no concurrent recovery must succeed (no false abort). +function run_success_scenario +{ + local online=$1 + echo "=== success scenario, online_recovery=$online ===" + set_online_recovery $online + $CDB2SQL_EXE ${CDB2_OPTIONS} $DBNAME --host $MASTER "put tunable debug_block_comdb2ar 0" + rm -f $archiveout + + ssh $MASTER "$COMDB2AR_EXE c ${DBDIR}/${DBNAME}.lrl 2>/dev/null >/dev/null" > $archiveout 2>&1