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

When using xtrabackup-v2 SST, built-in xtrabackup SSL fails on CentOS/RHEL 6

    Details

      Description

      The wsrep_sst_xtrabackup-v2 script supports 3 different types of encryption. An encryption type is chosen via the encrypt option:

      • XtraBackup-based encryption (set encrypt=1 in [sst]).
      • OpenSSL encryption via socat (set encrypt=2 in [sst]).
      • Galera-compatible OpenSSL encryption via socat (set encrypt=3 in [sst]).

      The first encryption option above uses XtraBackup's built-in encryption. This option currently fail on CentOS/RHEL 6 with the following error:

      xbcrypt:xb_crypt_read_chunk: wrong chunk magic at offset 0x0.

      This may be related to MDEV-9403.

      Reproducing

      The configuration file that is used on both joiner and donor is:

      [mariadb-10.0]
      binlog_format=ROW
      default_storage_engine=InnoDB
      innodb_autoinc_lock_mode=2
      wsrep_provider=/usr/lib64/galera/libgalera_smm.so
      wsrep_cluster_address="gcomm://172.31.33.135,172.31.32.117,172.31.32.116"
      wsrep_sst_auth="sst:password"
      wsrep_sst_method=xtrabackup-v2

      To generate the encryption key, let's follow the directions shown here. For example:

      $ openssl rand -base64 24
      d8PtcnuenpRb1IGgPISDgmRrhLxwTKsE

      Then we can fill in the [sst] section of the configuration file for the donor and joiner:

      encrypt=1
      encrypt-key="d8PtcnuenpRb1IGgPISDgmRrhLxwTKsE"
      encrypt-algo="AES256"

      When the joiner attempts to SST, it fails. The joiner's log:

      160119 18:41:30 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '172.31.32.116' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --parent '2422'  '' '
      WSREP_SST: [INFO] Streaming with xbstream (20160119 18:41:30.472)
      WSREP_SST: [INFO] Using socat as streamer (20160119 18:41:30.473)
      WSREP_SST: [INFO] Stale sst_in_progress file: /var/lib/mysql//sst_in_progress (20160119 18:41:30.476)
      WSREP_SST: [INFO] Xtrabackup based encryption enabled in my.cnf - Supported only from Xtrabackup 2.1.4 (20160119 18:41:30.490)
      WSREP_SST: [INFO] Evaluating timeout -s9 100 socat -u TCP-LISTEN:4444,reuseaddr stdio |  xbcrypt --encrypt-algo=AES256 --encrypt-key=d8PtcnuenpRb1IGgPISDgmRrhLxwTKsE -d | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20160119 18:41:30.496)
      160119 18:41:30 [Note] WSREP: Prepared SST request: xtrabackup-v2|172.31.32.116:4444/xtrabackup_sst//1
      160119 18:41:30 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
      160119 18:41:30 [Note] WSREP: REPL Protocols: 7 (3, 2)
      160119 18:41:30 [Note] WSREP: Service thread queue flushed.
      160119 18:41:30 [Note] WSREP: Assign initial position for certification: 5, protocol version: 3
      160119 18:41:30 [Note] WSREP: Service thread queue flushed.
      160119 18:41:30 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (fbeb045d-b94f-11e5-8504-4ae80b892690): 1 (Operation not permitted)
               at galera/src/replicator_str.cpp:prepare_for_IST():456. IST will be unavailable.
      160119 18:41:30 [Note] WSREP: Member 1.0 (ip-172-31-32-116.us-west-2.compute.internal) requested state transfer from '*any*'. Selected 0.0 (ip-172-31-32-117.us-west-2.compute.internal)(SYNCED) as donor.
      160119 18:41:30 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 5)
      160119 18:41:30 [Note] WSREP: Requesting state transfer: success, donor: 0
      WSREP_SST: [INFO] WARNING: Stale temporary SST directory: /var/lib/mysql//.sst from previous state transfer (20160119 18:41:30.835)
      WSREP_SST: [INFO] Proceeding with SST (20160119 18:41:30.837)
      WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio |  xbcrypt --encrypt-algo=AES256 --encrypt-key=d8PtcnuenpRb1IGgPISDgmRrhLxwTKsE -d | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20160119 18:41:30.839)
      WSREP_SST: [INFO] Cleaning the existing datadir and innodb-data/log directories (20160119 18:41:30.840)
      removed `/var/lib/mysql/aria_log_control'
      removed `/var/lib/mysql/aria_log.00000001'
      removed `/var/lib/mysql/mysql.sock'
      removed `/var/lib/mysql/ib_logfile0'
      removed `/var/lib/mysql/ibdata1'
      removed `/var/lib/mysql/ib_logfile1'
      WSREP_SST: [INFO] Waiting for SST streaming to complete! (20160119 18:41:30.860)
      160119 18:41:32 [Note] WSREP: (299ea548, 'tcp://0.0.0.0:4567') turning message relay requesting off
      xbcrypt:xb_crypt_read_chunk: wrong chunk magic at offset 0x0.
      2016/01/19 18:41:41 socat[2688] E write(1, 0xfc7410, 8192): Broken pipe
      WSREP_SST: [ERROR] Error while getting data from donor node:  exit codes: 1 0 0 (20160119 18:41:41.433)
      WSREP_SST: [ERROR] Cleanup after exit with status:32 (20160119 18:41:41.434)
      160119 18:41:41 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '172.31.32.116' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --parent '2422'  '' : 32 (Broken pipe)
      160119 18:41:41 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
      160119 18:41:41 [ERROR] WSREP: SST failed: 32 (Broken pipe)
      160119 18:41:41 [ERROR] Aborting

      The donor's log:

      160119 18:28:50 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'donor' --address '172.31.32.116:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix ''   '' --gtid 'fbeb045d-b94f-11e5-8504-4ae80b892690:5''
      160119 18:28:50 [Note] WSREP: sst_donor_thread signaled with 0
      WSREP_SST: [INFO] Streaming with xbstream (20160119 18:28:50.776)
      WSREP_SST: [INFO] Using socat as streamer (20160119 18:28:50.778)
      WSREP_SST: [INFO] Using /tmp/tmp.G7JKmrB9YZ as xtrabackup temporary directory (20160119 18:28:50.787)
      WSREP_SST: [INFO] Using /tmp/tmp.T2xAk6fxFZ as innobackupex temporary directory (20160119 18:28:50.789)
      WSREP_SST: [INFO] Xtrabackup based encryption enabled in my.cnf - Supported only from Xtrabackup 2.1.4 (20160119 18:28:50.791)
      WSREP_SST: [INFO] Streaming GTID file before SST (20160119 18:28:50.792)
      WSREP_SST: [INFO] Evaluating xbstream -c ${INFO_FILE} |  xbcrypt --encrypt-algo=AES256 --encrypt-key=92FABFA2213999936FD6B0EA04291157 | socat -u stdio TCP:172.31.32.116:4444 ; RC=( ${PIPESTATUS[@]} ) (20160119 18:28:50.794)
      WSREP_SST: [INFO] Sleeping before data transfer for SST (20160119 18:28:50.805)
      160119 18:28:52 [Note] WSREP: (5ef55a82, 'tcp://0.0.0.0:4567') turning message relay requesting off
      WSREP_SST: [INFO] Streaming the backup to joiner at 172.31.32.116 4444 (20160119 18:29:00.807)
      WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/etc/my.cnf  --defaults-group=mysqld --no-version-check  $tmpopts $INNOEXTRA --galera-info --stream=$sfmt $itmpdir 2>${DATA}/innobackup.backup.log | socat -u stdio TCP:172.31.32.116:4444; RC=( ${PIPESTATUS[@]} ) (20160119 18:29:00.809)
      2016/01/19 18:29:01 socat[2317] E write(3, 0x1c61200, 8192): Broken pipe
      WSREP_SST: [ERROR] innobackupex finished with error: 1.  Check /var/lib/mysql//innobackup.backup.log (20160119 18:29:01.461)
      WSREP_SST: [ERROR] Cleanup after exit with status:22 (20160119 18:29:01.462)
      WSREP_SST: [INFO] Cleaning up temporary directories (20160119 18:29:01.464)
      160119 18:29:01 [ERROR] WSREP: Failed to read from: wsrep_sst_xtrabackup-v2 --role 'donor' --address '172.31.32.116:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix ''   '' --gtid 'fbeb045d-b94f-11e5-8504-4ae80b892690:5'
      160119 18:29:01 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'donor' --address '172.31.32.116:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix ''   '' --gtid 'fbeb045d-b94f-11e5-8504-4ae80b892690:5': 22 (Invalid argument)
      160119 18:29:01 [ERROR] WSREP: Command did not run: wsrep_sst_xtrabackup-v2 --role 'donor' --address '172.31.32.116:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix ''   '' --gtid 'fbeb045d-b94f-11e5-8504-4ae80b892690:5'
      160119 18:29:01 [Warning] WSREP: 0.0 (ip-172-31-32-117.us-west-2.compute.internal): State transfer to 1.0 (ip-172-31-32-116.us-west-2.compute.internal) failed: -22 (Invalid argument)

      And /var/lib/mysql/innobackup.backup.log on the donor contains:

      160119 18:41:40 innobackupex: Starting the backup operation
       
      IMPORTANT: Please check that the backup run completes successfully.
                 At the end of a successful backup run innobackupex
                 prints "completed OK!".
       
      160119 18:41:40 Connecting to MySQL server host: localhost, user: sst, password: not set, port: 0, socket: /var/lib/mysql/mysql.sock
      Using server version 10.0.23-MariaDB-wsrep
      innobackupex version 2.3.3 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 525ca7d)
      xtrabackup: uses posix_fadvise().
      xtrabackup: cd to /var/lib/mysql/
      xtrabackup: open files limit requested 0, set to 1024
      xtrabackup: using the following InnoDB configuration:
      xtrabackup:   innodb_data_home_dir = ./
      xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
      xtrabackup:   innodb_log_group_home_dir = ./
      xtrabackup:   innodb_log_files_in_group = 2
      xtrabackup:   innodb_log_file_size = 50331648
      160119 18:41:40 >> log scanned up to (1619735)
      xtrabackup: Generating a list of tablespaces
      160119 18:41:40 [01] Encrypting and streaming ./ibdata1
      ^Ginnobackupex: Error writing file 'UNOPENED' (Errcode: 32 - Broken pipe)
      xb_stream_write_data() failed.
      encrypt: write to the destination file failed.
      ^Ginnobackupex: Error writing file 'UNOPENED' (Errcode: 32 - Broken pipe)
      [01] xtrabackup: Error: xtrabackup_copy_datafile() failed.
      [01] xtrabackup: Error: failed to copy datafile.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                seppo Seppo Jaakola
                Reporter:
                GeoffMontee Geoff Montee
              • Votes:
                2 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: