Physrep fail copy on recovery

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

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

plugins/logdelete/logdelete.c

@@ -19,12 +19,66 @@
 #include "comdb2_appsock.h"
 #include <comdb2_atomic.h>
 #include "unistd.h"
+#include <errno.h>
+#include <string.h>
+#include <poll.h>
+#include <sys/socket.h>
+
+#include <bdb_api.h>
+#include <bdbglue.h>
 
 /* 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"

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}};

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

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.

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