Uploaded image for project: 'Percona XtraDB Cluster'
  1. Percona XtraDB Cluster
  2. PXC-1723

LP #1362830: xtrabackup-v2 SST fails with multiple log_bin directives in my.cnf



    • Type: Bug
    • Status: Done
    • Priority: Low
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None


      **Reported in Launchpad by Ernie Souhrada last update 11-01-2016 11:10:47

      When attempting to join a fresh, new node to an existing cluster, if there are multiple "log_bin" or "log-bin" directives in the system's my.cnf, the xtrabackup-v2 SST method fails. On systems such as Ubuntu/Debian, which tend to use include files, the likelihood of this occuring is apparently higher than you might think. However, RHEL/CentOS is also impacted (tests below are from CentOS 6.5):

      To reproduce...
      Bootstrap a single PXC node with whatever configuration you want. Set wsrep_sst_method=xtrabackup-v2

      On the second node, add two "log_bin" or "log-bin" directives, such as:

      log_bin = mysql-bin
      log_bin = mysql-bin

      It doesn't matter if you use log-bin or log_bin, nor does it matter if the paths are identical. Try to start the second node.

      On the DONOR, you'll see the following in the MySQL error log:
      WSREP_SST: [INFO] Streaming the backup to joiner at 4444 (20140828 12:15:12.963)
      WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/etc/my.cnf --no-version-check $tmpopts $INNOEXTRA --galera-info --stream=$sfmt $itmpdir 2>${DATA}/innobackup.backup.log | socat -u stdio TCP:; RC=( ${PIPESTATUS[@]} ) (20140828 12:15:12.967)
      2014/08/28 12:15:12 socat[5812] E connect(4, AF=2, 16): Connection refused
      WSREP_SST: [ERROR] innobackupex finished with error: 1. Check /var/lib/mysql//innobackup.backup.log (20140828 12:15:13.137)
      WSREP_SST: [ERROR] Cleanup after exit with status:22 (20140828 12:15:13.139)
      WSREP_SST: [INFO] Cleaning up temporary directories (20140828 12:15:13.141)
      2014-08-28 12:15:13 5512 [ERROR] WSREP: Failed to read from: wsrep_sst_xtrabackup-v2 --role 'donor' --address '' --auth 'pxb:pxb' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' '' --gtid '5e0b98c4-2ee7-11e4-b8a5-2bb3225feb07:2'
      2014-08-28 12:15:13 5512 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'donor' --address '' --auth 'pxb:pxb' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' '' --gtid '5e0b98c4-2ee7-11e4-b8a5-2bb3225feb07:2': 22 (Invalid argument)
      2014-08-28 12:15:13 5512 [ERROR] WSREP: Command did not run: wsrep_sst_xtrabackup-v2 --role 'donor' --address '' --auth 'pxb:pxb' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' '' --gtid '5e0b98c4-2ee7-11e4-b8a5-2bb3225feb07:2'
      2014-08-28 12:15:13 5512 [Warning] WSREP: Could not find peer: 9a92816a-2ee7-11e4-a391-f72fde4981d7
      2014-08-28 12:15:13 5512 [Warning] WSREP: 0.0 (galera01): State transfer to -1.-1 (left the group) failed: -22 (Invalid argument)


      On the JOINER, you'll see this:
      2014-08-28 12:15:02 4249 [Note] WSREP: (9a92816a, 'tcp://') turning message relay requesting off
      WSREP_SST: [INFO] Proceeding with SST (20140828 12:15:02.962)
      WSREP_SST: [INFO] Cleaning the existing datadir (20140828 12:15:02.964)
      removed `/var/lib/mysql/gvwstate.dat'
      dirname: extra operand `mysql-bin'
      Try `dirname --help' for more information.
      WSREP_SST: [ERROR] Cleanup after exit with status:1 (20140828 12:15:02.974)
      WSREP_SST: [INFO] Removing the sst_in_progress file (20140828 12:15:02.975)
      2014-08-28 12:15:02 4249 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '' --auth 'pxb:pxb' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --parent '4249' '' : 1 (Operation not permitted)
      2014-08-28 12:15:02 4249 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
      2014-08-28 12:15:02 4249 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
      2014-08-28 12:15:02 4249 [ERROR] Aborting


      Note the "dirname: extra operand" line from the joiner's mysqld.log.

      The issue comes from lines 779 - 789 of the wsrep_sst_xtrabackup-v2 script, and also the parse_cnf function in this script, lines 229-238. Running just the parse_cnf function against a my.cnf that contains two log_bin (or log-bin) entries returns the following:

      /var/log/mysql/mysql-bin /var/log/mysql/mysql-bin

      Which, when passed to 'dirname', gives you the error mentioned above:

      (root@pxc-02 14:20:25)# dirname /var/log/mysql/mysql-bin /var/log/mysql/mysql-bin
      dirname: extra operand `/var/log/mysql/mysql-bin'
      Try `dirname --help' for more information.

      Anyway, once you comment out one of the log_bin/log-bin directives, SST proceeds without issue. The regular xtrabackup (v1) SST method is not impacted.


      Here is one simple way to fix it by always taking the first value returned; you may prefer some other approach.

      (root@pxc-02 14:30:04)# diff -Naur wsrep_sst_xtrabackup-v2.orig wsrep_sst_xtrabackup-v2
      — wsrep_sst_xtrabackup-v2.orig 2014-08-28 14:23:52.398146520 -0700
      +++ wsrep_sst_xtrabackup-v2 2014-08-28 14:29:12.078991948 -0700
      @@ -778,6 +778,7 @@
      tempdir=$(parse_cnf mysqld log-bin "")
      if [[ n ${tempdir:} ]];then
      + tempdir=$(echo $tempdir | cut -d\ -f 1)
      binlog_dir=$(dirname $tempdir)
      binlog_file=$(basename $tempdir)
      if [[ n ${binlog_dir:} && $binlog_dir != '.' && $binlog_dir != $DATA ]];then

        Smart Checklist




              krunal.bauskar Krunal Bauskar (Inactive)
              lpjirasync lpjirasync (Inactive)
              0 Vote for this issue
              1 Start watching this issue