MDEV-39468 Mariabackup: redo log copier stalls and fails with misleading error message

extra/mariabackup/backup_mysql.cc

@@ -346,6 +346,26 @@ read_mysql_one_value(MYSQL *mysql, const char *query)
   return read_mysql_one_value(mysql, query, 0/*offset*/, 1/*total columns*/);
 }
 
+/** Poll InnoDB's durably flushed redo LSN from the running server.
+Log copier uses this as its parse limit; it never accepts a redo log
+record whose end exceeds this LSN
+@param connection MariaDB client connection
+@retval 0 on failure, lsn on success */
+uint64_t get_log_flushed_lsn(MYSQL *connection) noexcept
+{
+  char *lsn_str= nullptr;
+  mysql_variable status[] = {{"Innodb_lsn_flushed", &lsn_str},
+                             {NULL, NULL}};
+  uint64_t lsn= 0;
+  read_mysql_variables(connection,
+                       "SHOW STATUS LIKE 'Innodb_lsn_flushed'",
+                       status, true);
+  if (lsn_str)
+    lsn= strtoull(lsn_str, nullptr, 10);
+  free_mysql_variables(status);
+  return lsn;
+}
+
 
 static
 bool

extra/mariabackup/backup_mysql.h

@@ -2,6 +2,7 @@
 #define XTRABACKUP_BACKUP_MYSQL_H
 
 #include <mysql.h>
+#include <cstdint>
 #include <string>
 #include <unordered_set>
 #include "datasink.h"
@@ -97,4 +98,6 @@ bool
 write_slave_info(ds_ctxt *datasink, MYSQL *connection);
 
 ulonglong get_current_lsn(MYSQL *connection);
+
+uint64_t get_log_flushed_lsn(MYSQL *connection) noexcept;
 #endif

extra/mariabackup/xtrabackup.cc

@@ -205,7 +205,7 @@ struct xb_filter_entry_t{
 /** whether log_copying_thread() is active; protected by recv_sys.mutex */
 static bool log_copying_running;
 /** the log parsing function for --backup */
-static recv_sys_t::parser backup_log_parse;
+static recv_sys_t::parser backup_log_parse_low;
 /** for --backup, target LSN to copy the log to; protected by recv_sys.mutex */
 lsn_t metadata_to_lsn;
 
@@ -3443,6 +3443,39 @@ static my_bool xtrabackup_copy_datafile(ds_ctxt *ds_data,
 	return(FALSE);
 }
 
+/* Maximum LSN the copier may parse up to, derived from the
+server's durably-flushed redo LSN. The copier refuses to
+accept a mini-transaction whose end exceeds this, so it never
+parses the volatile tail block the server is still rewriting
+(which mmap can read torn, leading to a mis-computed mtr
+length and permanent mid-mtr drift). A pread() of the same
+still-being-written tail block can likewise return a torn read
+which can be observed on ext4, though not on XFS).
+Read/written only under recv_sys.mutex. */
+static lsn_t max_parse_lsn;
+
+/* Set by backup_log_parse() when the last parse was
+rejected because the mtr crossed max_parse_lsn. It means
+"caught up, wait" condition, not a stall. */
+static bool reached_parse_limit;
+
+static recv_sys_t::parse_mtr_result backup_log_parse()
+{
+  const lsn_t limit_lsn= max_parse_lsn;
+  const lsn_t prev_lsn= recv_sys.lsn;
+  const size_t prev_offset= recv_sys.offset;
+  reached_parse_limit= false;
+  recv_sys_t::parse_mtr_result r= backup_log_parse_low(false);
+  if (r == recv_sys_t::OK && limit_lsn && recv_sys.lsn > limit_lsn)
+  {
+    recv_sys.lsn= prev_lsn;
+    recv_sys.offset= prev_offset;
+    reached_parse_limit= true;
+    return recv_sys_t::GOT_EOF;
+  }
+  return r;
+}
+
 static int
 xtrabackup_copy_mmap_snippet(ds_file_t *ds, const byte *start, const byte *end)
 {
@@ -3468,7 +3501,7 @@ static bool xtrabackup_copy_mmap_logfile()
   const byte *start= &log_sys.buf[recv_sys.offset];
   ut_d(recv_sys_t::parse_mtr_result r);
 
-  if ((ut_d(r=) backup_log_parse(false)) == recv_sys_t::OK)
+  if ((ut_d(r=) backup_log_parse()) == recv_sys_t::OK)
   {
     do
     {
@@ -3486,7 +3519,7 @@ static bool xtrabackup_copy_mmap_logfile()
         start = seq + 1;
       }
     }
-    while ((ut_d(r=) backup_log_parse(false)) == recv_sys_t::OK);
+    while ((ut_d(r=) backup_log_parse()) == recv_sys_t::OK);
 
     if (xtrabackup_copy_mmap_snippet(dst_log_file, start,
                                      &log_sys.buf[recv_sys.offset]))
@@ -3559,7 +3592,7 @@ static bool xtrabackup_copy_logfile(bool early_exit)
       if (log_sys.buf[recv_sys.offset] <= 1)
         break;
 
-      if (backup_log_parse(false) == recv_sys_t::OK)
+      if (backup_log_parse() == recv_sys_t::OK)
       {
         do
         {
@@ -3569,7 +3602,7 @@ static bool xtrabackup_copy_logfile(bool early_exit)
                                                  sequence_offset));
           *seq= 1;
         }
-        while ((r= backup_log_parse(false)) == recv_sys_t::OK);
+        while ((r= backup_log_parse()) == recv_sys_t::OK);
 
         if (ds_write(dst_log_file, log_sys.buf + start_offset,
                      recv_sys.offset - start_offset))
@@ -3599,6 +3632,9 @@ static bool xtrabackup_copy_logfile(bool early_exit)
         if (retry_count == 100)
           break;
 
+	if (reached_parse_limit)
+          break;
+
         mysql_mutex_unlock(&recv_sys.mutex);
         if (!retry_count++)
           msg("Retrying read of log at LSN=" LSN_PF, recv_sys.lsn);
@@ -3617,9 +3653,20 @@ static bool backup_wait_timeout(lsn_t lsn, lsn_t last_lsn)
 {
   if (last_lsn >= lsn)
     return true;
+
+  const lsn_t checkpoint_lsn= log_sys.last_checkpoint_lsn.load();
+  const lsn_t capacity= log_sys.file_size - log_sys.START_OFFSET;
+  const lsn_t needed= lsn - checkpoint_lsn;
+
   msg("Was only able to copy log from " LSN_PF " to " LSN_PF
-      ", not " LSN_PF "; try increasing innodb_log_file_size",
-      log_sys.last_checkpoint_lsn.load(), last_lsn, lsn);
+      ", not " LSN_PF, checkpoint_lsn, last_lsn, lsn);
+
+  if (needed <= capacity)
+    msg("mariabackup: The required redo still fits within the log "
+        "capacity, so it has not been overwritten; check whether the "
+        "server and backup configuration are the same.");
+  else
+    msg("mariabackup: Try increasing the innodb_log_file_size.");
   return false;
 }
 
@@ -3674,16 +3721,56 @@ static bool backup_wait_for_lsn(lsn_t lsn)
 static void log_copying_thread()
 {
   my_thread_init();
+  MYSQL *limit_con= xb_mysql_connect();
+  if (!limit_con)
+  {
+    /* Without this connection we cannot poll the durably-flushed
+    LSN, so max_parse_lsn could never advance and the copier
+    would either stall or parse the volatile tail block.
+    Fail the copy gracefully and let the main thread report
+    it via backup_wait_timeout(). */
+    msg("mariabackup: Error: cannot open a server connection for "
+        "the log copying thread; the backup will fail.");
+    mysql_mutex_lock(&recv_sys.mutex);
+    log_copying_running= false;
+    pthread_cond_broadcast(&scanned_lsn_cond);
+    mysql_mutex_unlock(&recv_sys.mutex);
+    my_thread_end();
+    return;
+  }
+
   mysql_mutex_lock(&recv_sys.mutex);
-  while (!xtrabackup_copy_logfile(false) &&
-         (!metadata_last_lsn || metadata_last_lsn > recv_sys.lsn))
+  for (;;)
   {
+    if (metadata_last_lsn == 1)
+      break;
+    /* Refresh the max_parse_lsn before each copy pass */
+    const lsn_t final_target= metadata_last_lsn > metadata_to_lsn
+      ? metadata_last_lsn : metadata_to_lsn;
+    if (final_target)
+      max_parse_lsn= final_target;
+    else
+    {
+      mysql_mutex_unlock(&recv_sys.mutex);
+      lsn_t flushed= get_log_flushed_lsn(limit_con);
+      mysql_mutex_lock(&recv_sys.mutex);
+      if (flushed > log_sys.get_first_lsn())
+        max_parse_lsn= flushed;
+    }
+
+    if (xtrabackup_copy_logfile(false))
+      break;
+    if (final_target && final_target <= recv_sys.lsn)
+      break;
+
     timespec abstime;
     set_timespec_nsec(abstime, 1000000ULL * xtrabackup_log_copy_interval);
     mysql_cond_timedwait(&log_copying_stop, &recv_sys.mutex, &abstime);
   }
   log_copying_running= false;
   mysql_mutex_unlock(&recv_sys.mutex);
+  if (limit_con)
+    mysql_close(limit_con);
   my_thread_end();
 }
 
@@ -5614,9 +5701,15 @@ static bool xtrabackup_backup_func()
 	/* copy log file by current position */
 
 	mysql_mutex_lock(&recv_sys.mutex);
-	backup_log_parse = recv_sys.get_backup_parser();
+	backup_log_parse_low = recv_sys.get_backup_parser();
 	recv_sys.lsn = log_sys.last_checkpoint_lsn;
 
+	if (lsn_t flushed= get_log_flushed_lsn(mysql_connection))
+	{
+          if (flushed > log_sys.get_first_lsn())
+            max_parse_lsn= flushed;
+	}
+
 	const bool log_copy_failed = xtrabackup_copy_logfile(true);
 
 	mysql_mutex_unlock(&recv_sys.mutex);

mysql-test/suite/mariabackup/innodb_redo_overwrite.result

@@ -1,5 +1,5 @@
 CREATE TABLE t ENGINE=INNODB SELECT seq%10 i FROM seq_0_to_204796;
 # xtrabackup backup
-FOUND 1 /Was only able to copy log from \d+ to \d+, not \d+; try increasing innodb_log_file_size\b/ in backup.log
+FOUND 1 /mariabackup: Try increasing the innodb_log_file_size./ in backup.log
 NOT FOUND /failed: redo log block checksum does not match/ in backup.log
 DROP TABLE t;

mysql-test/suite/mariabackup/innodb_redo_overwrite.test

@@ -17,7 +17,7 @@ CREATE TABLE t ENGINE=INNODB SELECT seq%10 i FROM seq_0_to_204796;
 --exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir --dbug=+d,mariabackup_events > $backuplog
 --enable_result_log
 
---let SEARCH_PATTERN=Was only able to copy log from \\d+ to \\d+, not \\d+; try increasing innodb_log_file_size\\b
+--let SEARCH_PATTERN=mariabackup: Try increasing the innodb_log_file_size.
 --let SEARCH_FILE=$backuplog
 --source include/search_pattern_in_file.inc
 --remove_file $backuplog