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

MariaDB galera SST broken using mariabackup

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Duplicate
    • Affects Version/s: 10.2.13
    • Fix Version/s: N/A
    • Component/s: Galera SST
    • Labels:
      None
    • Environment:

      Description

      Bootstrap the first node (1.1 T) and start the second node with mariabackup as SST option.
      With mariabackup it fail, with xtraback-v2 it works.
      details:

      same for node01( bootstap) and node02:
      [root@~]# rpm -qa | grep -i maria
      MariaDB-compat-10.2.13-1.el7.centos.x86_64
      MariaDB-backup-10.2.13-1.el7.centos.x86_64
      MariaDB-common-10.2.13-1.el7.centos.x86_64
      MariaDB-server-10.2.13-1.el7.centos.x86_64
      MariaDB-client-10.2.13-1.el7.centos.x86_64
      [root@~]# rpm -qa | grep -i xtra
      percona-xtrabackup-24-2.4.9-1.el7.x86_64

      when mariaback is used:
      SST started and it fail basically at the end :

      mysql error log node02:

      2018-04-09 20:34:06 140370872628992 [Note] WSREP: view((empty))
      2018-04-09 20:34:06 140370872628992 [Note] WSREP: gcomm: closed
      2018-04-09 20:34:06 140370872628992 [Note] WSREP: /usr/sbin/mysqld: Terminated.
      WSREP_SST: [ERROR] Removing /data/mysql//.sst/xtrabackup_galera_info file due to signal (20180409 20:34:12.897)
      rm: cannot remove ‘/data/mysql//innobackup.prepare.log’: No such file or directory
      rm: cannot remove ‘/data/mysql//innobackup.move.log’: No such file or directory
      WSREP_SST: [INFO] Moving the backup to /data/mysql/ (20180409 20:34:12.906)
      WSREP_SST: [INFO] Evaluating mariabackup --innobackupex --move-back --force-non-empty-directories ${DATA} &>${DATA}/innobackup.move.log (20180409 20:34:12.910)
      WSREP_SST: [INFO] Move successful, removing /data/mysql//.sst (20180409 20:34:12.987)
      WSREP_SST: [ERROR] SST magic file /data/mysql//xtrabackup_galera_info not found/readable (20180409 20:34:12.995)
      WSREP_SST: [ERROR] Cleanup after exit with status:2 (20180409 20:34:12.999)

      from innobackup.prepare.log of node02:

      180409 20:34:00 innobackupex: Starting the apply-log operation

      IMPORTANT: Please check that the apply-log run completes successfully.
      At the end of a successful apply-log run innobackupex
      prints "completed OK!".

      --innobackupex based on MariaDB server 10.2.13-MariaDB Linux (x86_64)
      mariabackup: cd to /data/mysql/.sst/
      mariabackup: This target seems to be not prepared yet.
      mariabackup: using the following InnoDB configuration for recovery:
      mariabackup: innodb_data_home_dir = .
      mariabackup: innodb_data_file_path = ibdata1:10M:autoextend
      mariabackup: innodb_log_group_home_dir = .
      mariabackup: Starting InnoDB instance for recovery.
      mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Uses event mutexes
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Number of pools: 1
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Using SSE2 crc32 instructions
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Completed initialization of buffer pool
      2018-04-09 20:34:00 140560264582912 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Highest supported file format is Barracuda.
      2018-04-09 20:34:00 140560545577088 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1129738763324
      2018-04-09 20:34:03 140560545577088 [Note] InnoDB: Starting a batch to recover 16805 pages from redo log.
      2018-04-09 20:34:06 140560545577088 [Note] InnoDB: Starting a batch to recover 16949 pages from redo log.
      2018-04-09 20:34:09 140560545577088 [Note] InnoDB: Starting a batch to recover 17923 pages from redo log.
      2018-04-09 20:34:11 140560545577088 [ERROR] InnoDB: We scanned the log up to 1129739289600. A checkpoint was at 1129642536715 and the maximum LSN on a database page was 1131122644674. It is possible that the database is now corrupt!
      2018-04-09 20:34:11 140560545577088 [Note] InnoDB: Starting final batch to recover 893 pages from redo log.
      2018-04-09 20:34:11 140560545577088 [ERROR] InnoDB: Page [page id: space=444, page number=1277953] log sequence number 1130614587164 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560545577088 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Page [page id: space=0, page number=98338] log sequence number 1129739977516 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Page [page id: space=0, page number=98339] log sequence number 1129764554732 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560306546432 [ERROR] InnoDB: Page [page id: space=503, page number=732882] log sequence number 1130160000447 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560306546432 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560314939136 [ERROR] InnoDB: Page [page id: space=196, page number=232866] log sequence number 1129861043014 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560314939136 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Page [page id: space=343, page number=3] log sequence number 1130893331080 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560306546432 [ERROR] InnoDB: Page [page id: space=503, page number=732884] log sequence number 1130291341737 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560306546432 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560323331840 [ERROR] InnoDB: Page [page id: space=240, page number=2897] log sequence number 1129964191715 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560323331840 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560314939136 [ERROR] InnoDB: Page [page id: space=552, page number=536491] log sequence number 1129770654451 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Page [page id: space=343, page number=8] log sequence number 1130929049236 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560306546432 [ERROR] InnoDB: Page [page id: space=215, page number=480] log sequence number 1130655708639 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560306546432 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560314939136 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560323331840 [ERROR] InnoDB: Page [page id: space=487, page number=101980] log sequence number 1130093651881 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Page [page id: space=343, page number=9] log sequence number 1130929049254 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560323331840 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:11 140560314939136 [ERROR] InnoDB: Page [page id: space=558, page number=7314] log sequence number 1130083883336 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:11 140560314939136 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      ......
      ......
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Page [page id: space=127, page number=2788865] log sequence number 1130197446545 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Page [page id: space=444, page number=2899968] log sequence number 1131013290244 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Page [page id: space=444, page number=2949676] log sequence number 1130648963935 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Page [page id: space=307, page number=4579605] log sequence number 1131118362954 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Page [page id: space=307, page number=4639036] log sequence number 1129842964079 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Page [page id: space=307, page number=4679434] log sequence number 1129807107124 is in the future! Current system log sequence number 1129739289517.
      2018-04-09 20:34:12 140560331724544 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.
      180409 20:34:12 completed OK!

      on the innobackup.move.log file on node02:

      180409 20:34:12 innobackupex: Starting the move-back operation

      IMPORTANT: Please check that the move-back run completes successfully.
      At the end of a successful move-back run innobackupex
      prints "completed OK!".

      --innobackupex based on MariaDB server 10.2.13-MariaDB Linux (x86_64)
      180409 20:34:12 [01] Moving ibdata1 to /data/mysql/ibdata1
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./mysql/gtid_slave_pos.ibd to /data/mysql/mysql/gtid_slave_pos.ibd
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./mysql/innodb_table_stats.ibd to /data/mysql/mysql/innodb_table_stats.ibd
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./mysql/innodb_index_stats.ibd to /data/mysql/mysql/innodb_index_stats.ibd
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./mysql/columns_priv.frm to /data/mysql/mysql/columns_priv.frm
      180409 20:34:12 [01] ...done
      ...
      ...
      180409 20:34:12 [01] Moving ./performance_schema/db.opt to /data/mysql/performance_schema/db.opt
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./aria_log_control to /data/mysql/aria_log_control
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./aria_log.00000001 to /data/mysql/aria_log.00000001
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./ib_buffer_pool to /data/mysql/ib_buffer_pool
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./xtrabackup_info to /data/mysql/xtrabackup_info
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./innobackup.prepare.log to /data/mysql/innobackup.prepare.log
      180409 20:34:12 [01] ...done
      180409 20:34:12 [01] Moving ./innobackup.move.log to /data/mysql/innobackup.move.log
      180409 20:34:12 [01] ...done
      180409 20:34:12 completed OK!

      on the node01 donor error.log file:

      2018-04-09 17:54:03 140501533583104 [Note] WSREP: Quorum results:
      version = 4,
      component = PRIMARY,
      conf_id = 3,
      members = 1/2 (joined/total),
      act_id = 0,
      last_appl. = 0,
      protocols = 0/8/3 (gcs/repl/appl),
      group UUID = 2cab0f6d-3bea-11e8-b564-c38fa1385a69
      2018-04-09 17:54:03 140501533583104 [Note] WSREP: Flow-control interval: [362, 362]
      2018-04-09 17:54:03 140501533583104 [Note] WSREP: Trying to continue unpaused monitor
      2018-04-09 17:54:03 140507105875712 [Note] WSREP: New cluster view: global state: 2cab0f6d-3bea-11e8-b564-c38fa1385a69:0, view# 4: Primary, number of nodes: 2, my index: 0, protocol version 3
      2018-04-09 17:54:03 140507105875712 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
      2018-04-09 17:54:03 140507105875712 [Note] WSREP: REPL Protocols: 8 (3, 2)
      2018-04-09 17:54:03 140507105875712 [Note] WSREP: Assign initial position for certification: 0, protocol version: 3
      2018-04-09 17:54:03 140507017230080 [Note] WSREP: Service thread queue flushed.
      2018-04-09 17:54:04 140501533583104 [Note] WSREP: Member 1.0 (node02) requested state transfer from 'any'. Selected 0.0 (node01)(SYNCED) as donor.
      2018-04-09 17:54:04 140501533583104 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 0)
      2018-04-09 17:54:04 140507105875712 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
      2018-04-09 17:54:04 140410794010368 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'donor' --address '192.168.102.208:4444/xtrabackup_sst//1' --socket '/data/mysql/mysql.sock' --datadir '/data/mysql/' '' --gtid '2cab0f6d-3bea-11e8-b564-c38fa1385a69:0' --gtid-domain-id '0''
      2018-04-09 17:54:04 140507105875712 [Note] WSREP: sst_donor_thread signaled with 0
      WSREP_SST: [INFO] Streaming with xbstream (20180409 17:54:04.858)
      WSREP_SST: [INFO] Using socat as streamer (20180409 17:54:04.864)
      WSREP_SST: [INFO] Using /tmp/tmp.ITKJXDjvll as innobackupex temporary directory (20180409 17:54:04.892)
      WSREP_SST: [INFO] Streaming GTID file before SST (20180409 17:54:04.907)
      WSREP_SST: [INFO] Evaluating mbstream -c ${INFO_FILE} | socat -u stdio TCP:192.168.102.208:4444; RC=( ${PIPESTATUS[@]} ) (20180409 17:54:04.914)
      WSREP_SST: [INFO] Sleeping before data transfer for SST (20180409 17:54:04.931)
      2018-04-09 17:54:05 140506983659264 [Note] WSREP: (2caa4f44, 'tcp://0.0.0.0:4567') turning message relay requesting off
      WSREP_SST: [INFO] Streaming the backup to joiner at 192.168.102.208 4444 (20180409 17:54:14.943)
      WSREP_SST: [INFO] Evaluating mariabackup --innobackupex $tmpopts $INNOEXTRA --galera-info --stream=$sfmt $itmpdir 2>${DATA}/innobackup.backup.log | socat -u stdio TCP:192.168.102.208:4444; RC=( ${PIPESTATUS[@]} ) (20180409 17:54:14.950)
      2018-04-09 20:34:02 140501469112064 [Note] WSREP: Provider paused at 2cab0f6d-3bea-11e8-b564-c38fa1385a69:0 (11)
      2018-04-09 20:34:03 140501469112064 [Note] WSREP: resuming provider at 11
      2018-04-09 20:34:03 140501469112064 [Note] WSREP: Provider resumed.
      WSREP_SST: [ERROR] mariabackup finished with error: 1. Check /data/mysql//innobackup.backup.log (20180409 20:34:03.980)
      WSREP_SST: [ERROR] Cleanup after exit with status:22 (20180409 20:34:03.986)
      WSREP_SST: [INFO] Cleaning up temporary directories (20180409 20:34:03.994)
      2018-04-09 20:34:04 140410794010368 [ERROR] WSREP: Failed to read from: wsrep_sst_mariabackup --role 'donor' --address '192.168.102.208:4444/xtrabackup_sst//1' --socket '/data/mysql/mysql.sock' --datadir '/data/mysql/' '' --gtid '2cab0f6d-3bea-11e8-b564-c38fa1385a69:0' --gtid-domain-id '0'
      2018-04-09 20:34:04 140410794010368 [ERROR] WSREP: Process completed with error: wsrep_sst_mariabackup --role 'donor' --address '192.168.102.208:4444/xtrabackup_sst//1' --socket '/data/mysql/mysql.sock' --datadir '/data/mysql/' '' --gtid '2cab0f6d-3bea-11e8-b564-c38fa1385a69:0' --gtid-domai
      n-id '0': 22 (Invalid argument)
      2018-04-09 20:34:04 140410794010368 [ERROR] WSREP: Command did not run: wsrep_sst_mariabackup --role 'donor' --address '192.168.102.208:4444/xtrabackup_sst//1' --socket '/data/mysql/mysql.sock' --datadir '/data/mysql/' '' --gtid '2cab0f6d-3bea-11e8-b564-c38fa1385a69:0' --gtid-domain-id '0'
      2018-04-09 20:34:04 140501533583104 [Warning] WSREP: 0.0 (node01): State transfer to 1.0 (node02) failed: -22 (Invalid argument)

      looking at the log of xtrabackup it seen apply log works and xtrabackup_galera_info is there

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                wlad Vladislav Vaintroub
                Reporter:
                massimo.disaro Massimo
              • Votes:
                1 Vote for this issue
                Watchers:
                11 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: