Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-18963

Mariabackup 10.2.22 Restore Intermittent Failures

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 10.2.22
    • Fix Version/s: 10.2
    • Component/s: mariabackup
    • Labels:
      None
    • Environment:
      CentOS Linux 7.6.1810 (core)

      Description

      We recently upgraded from MariaDB 10.2.17 to 10.2.22; since this update, we are hitting intermittent issues with mariadb server failing to start on the mariabackup cloned host, with the following error logged:

      2019-03-18  0:18:02 139848147691712 [Note] Found 1 prepared transaction(s) in InnoDB
      2019-03-18  0:18:02 139848147691712 [ERROR] Found 1 prepared transactions! It means that mysqld was not shut down properly last time and critical recovery information (last binlog or tc.log file) was manually deleted after a crash. You have to start mysqld with --tc-heuristic-recover switch to commit or rollback pending transactions.
      2019-03-18  0:18:02 139848147691712 [ERROR] Aborting
      

      We use mariabackup (streaming backup over SSH) to clone a server, several times a day. The source server is a slave, all tables are InnoDB.
      I reviewed the updates between 10.2.17 and 10.2.22, and could not find anything obviously incompatible in how we are using mariabackup; I have included the options below in case I have missed something.

      We use following options when performing the backup:

      mariabackup \
          --backup \
          --no-lock \
          --host=127.0.0.1 \
          --user=redacted \
          --password=redacted \
          --safe-slave-backup \
          --stream=xbstream \
          --target-dir=./ 2> $LOGFILE \
          | ssh -o StrictHostKeyChecking=no hostname-redacted "mbstream -x -C /mysql-import/mysql/"
      

      We then prepare the backup on the cloned server using the following options:

      mariabackup \
        --prepare \
        --apply-log-only \
        --target-dir /mysql-import/mysql > $LOGFILE 2>&1
      

      Prepare logs as below, on a job, where server subsequently fails to start; no obvious errors shown - prepare job reported success.

      [00] 2019-03-18 00:17:55 mariabackup based on MariaDB server 10.2.22-MariaDB Linux (x86_64)
      [00] 2019-03-18 00:17:55 cd to /mysql-import/mysql/
      [00] 2019-03-18 00:17:55 This target seems to be not prepared yet.
      [00] 2019-03-18 00:17:55 mariabackup: using the following InnoDB configuration for recovery:
      [00] 2019-03-18 00:17:55 innodb_data_home_dir = .
      [00] 2019-03-18 00:17:55 innodb_data_file_path = ibdata1:500M:autoextend
      [00] 2019-03-18 00:17:55 innodb_log_group_home_dir = .
      [00] 2019-03-18 00:17:55 InnoDB: Using Linux native AIO
      [00] 2019-03-18 00:17:55 Starting InnoDB instance for recovery.
      [00] 2019-03-18 00:17:55 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Uses event mutexes
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Using Linux native AIO
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Number of pools: 1
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Using SSE2 crc32 instructions
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Completed initialization of buffer pool
      2019-03-18  0:17:55 139977107965696 [Note] InnoDB: page_cleaner coordinator priority: -20
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Highest supported file format is Barracuda.
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Starting crash recovery from checkpoint LSN=839911059558
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Starting final batch to recover 643 pages from redo log.
      2019-03-18  0:17:55 139977393436864 [Note] InnoDB: Last binlog file '/var/lib/mysql/logs/bin.000768', position 228369213
      [00] 2019-03-18 00:17:56 Last binlog file /var/lib/mysql/logs/bin.000768, position 228369213
      [00] 2019-03-18 00:17:56 completed OK!
      

      Note: We remove the empty ib_logfile0 file after mariabackup prepare due to server refusing to start with the empty mariabackup generated ib_logfile.

        Attachments

          Activity

            People

            • Assignee:
              marko Marko Mäkelä
              Reporter:
              stephen.hames Stephen Hames
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: