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/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 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();