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

If log_bin and log_bin_index is different SST with rsync fails.

    Details

      Description

      If the SST donor is configured with log_bin and log_bin_index differently the SST with rsync will fail.

      Config of donor:

      log_bin                        = /home/mysql/database/magal-102-b/binlog/laptop4_magal-102-b_binlog            
      log_bin_index                  = /home/mysql/database/magal-102-b/binlog/different.index
      

      Config of joiner:

      wsrep_sst_method               = rsync
      

      Error Log of joiner:

      2018-02-28 19:47:08 139733535151872 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (ac9c693b-0c24-11e8-bbd0-1e63d6801ac1): 1 (Operation not permitted)
               at galera/src/replicator_str.cpp:prepare_for_IST():482. IST will be unavailable.
      2018-02-28 19:47:08 139733229344512 [Note] WSREP: Member 1.0 (Node A) requested state transfer from '*any*'. Selected 0.0 (Node B)(SYNCED) as donor.
      2018-02-28 19:47:08 139733229344512 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 0)
      2018-02-28 19:47:08 139733535151872 [Note] WSREP: Requesting state transfer: success, donor: 0
      2018-02-28 19:47:08 139733535151872 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> ac9c693b-0c24-11e8-bbd0-1e63d6801ac1:0
      2018-02-28 19:47:08 139733229344512 [Warning] WSREP: 0.0 (Node B): State transfer to 1.0 (Node A) failed: -1 (Operation not permitted)
      2018-02-28 19:47:08 139733229344512 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():737: Will never receive state. Need to abort.
      2018-02-28 19:47:08 139733229344512 [Note] WSREP: gcomm: terminating thread
      2018-02-28 19:47:08 139733229344512 [Note] WSREP: gcomm: joining thread
      2018-02-28 19:47:08 139733229344512 [Note] WSREP: gcomm: closing backend
      2018-02-28 19:47:10 139733229344512 [Note] WSREP: (c68162be, 'tcp://127.0.0.1:5690') turning message relay requesting off
      2018-02-28 19:47:11 139733229344512 [Note] WSREP: (c68162be, 'tcp://127.0.0.1:5690') connection to peer 7b19fa32 with addr tcp://127.0.0.1:5691 timed out, no messages seen in PT3S
      2018-02-28 19:47:11 139733229344512 [Note] WSREP: (c68162be, 'tcp://127.0.0.1:5690') turning message relay requesting on, nonlive peers: tcp://127.0.0.1:5691 
      2018-02-28 19:47:12 139733229344512 [Note] WSREP: (c68162be, 'tcp://127.0.0.1:5690') reconnecting to 7b19fa32 (tcp://127.0.0.1:5691), attempt 0
      2018-02-28 19:47:13 139733229344512 [Note] WSREP: evs::proto(c68162be, LEAVING, view_id(REG,7b19fa32,4)) suspecting node: 7b19fa32
      2018-02-28 19:47:13 139733229344512 [Note] WSREP: evs::proto(c68162be, LEAVING, view_id(REG,7b19fa32,4)) suspected node without join message, declaring inactive
      2018-02-28 19:47:13 139733229344512 [Note] WSREP: view(view_id(NON_PRIM,7b19fa32,4) memb {
              c68162be,0
      } joined {
      } left {
      } partitioned {
              7b19fa32,0
      })
      2018-02-28 19:47:13 139733229344512 [Note] WSREP: view((empty))
      2018-02-28 19:47:13 139733229344512 [Note] WSREP: gcomm: closed
      2018-02-28 19:47:13 139733229344512 [Note] WSREP: /home/mysql/product/mariadb-10.2/bin/mysqld: Terminated.
      WSREP_SST: [ERROR] Parent mysqld process (PID:12826) terminated unexpectedly. (20180228 19:47:14.212)
      WSREP_SST: [INFO] Joiner cleanup. rsync PID: 12882 (20180228 19:47:14.212)
      WSREP_SST: [INFO] Joiner cleanup done. (20180228 19:47:14.720)
      

      Error Log of donor:

      2018-02-28 19:47:08 140650095822592 [Note] WSREP: Member 1.0 (Node A) requested state transfer from '*any*'. Selected 0.0 (Node B)(SYNCED) as donor.
      2018-02-28 19:47:08 140650095822592 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 0)
      2018-02-28 19:47:08 140650401990400 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
      2018-02-28 19:47:08 140648686540544 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4444/rsync_sst' --socket '/var/run/mysqld/mysql-3334.sock' --datadir '/home/mysql/database/magal-102-b/data/'  --defaults-file '/home/mysql/database/magal-102-b/etc/my.cnf'   --binlog '/home/mysql/database/magal-102-b/binlog/laptop4_magal-102-b_binlog' --gtid 'ac9c693b-0c24-11e8-bbd0-1e63d6801ac1:0' --gtid-domain-id '42''
      2018-02-28 19:47:08 140650401990400 [Note] WSREP: sst_donor_thread signaled with 0
      2018-02-28 19:47:08 140648686540544 [Note] WSREP: Flushing tables for SST...
      2018-02-28 19:47:08 140648686540544 [Note] WSREP: Provider paused at ac9c693b-0c24-11e8-bbd0-1e63d6801ac1:0 (7)
      2018-02-28 19:47:08 140648686540544 [Note] WSREP: Tables flushed.
      tail: cannot open 'laptop4_magal-102-b_binlog.index' for reading: No such file or directory
      2018-02-28 19:47:08 140648686540544 [ERROR] WSREP: Failed to read from: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4444/rsync_sst' --socket '/var/run/mysqld/mysql-3334.sock' --datadir '/home/mysql/database/magal-102-b/data/'  --defaults-file '/home/mysql/database/magal-102-b/etc/my.cnf'   --binlog '/home/mysql/database/magal-102-b/binlog/laptop4_magal-102-b_binlog' --gtid 'ac9c693b-0c24-11e8-bbd0-1e63d6801ac1:0' --gtid-domain-id '42'
      2018-02-28 19:47:08 140648686540544 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4444/rsync_sst' --socket '/var/run/mysqld/mysql-3334.sock' --datadir '/home/mysql/database/magal-102-b/data/'  --defaults-file '/home/mysql/database/magal-102-b/etc/my.cnf'   --binlog '/home/mysql/database/magal-102-b/binlog/laptop4_magal-102-b_binlog' --gtid 'ac9c693b-0c24-11e8-bbd0-1e63d6801ac1:0' --gtid-domain-id '42': 1 (Operation not permitted)
      2018-02-28 19:47:08 140648686540544 [Note] WSREP: resuming provider at 7
      2018-02-28 19:47:08 140648686540544 [Note] WSREP: Provider resumed.
      2018-02-28 19:47:08 140648686540544 [ERROR] WSREP: Command did not run: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4444/rsync_sst' --socket '/var/run/mysqld/mysql-3334.sock' --datadir '/home/mysql/database/magal-102-b/data/'  --defaults-file '/home/mysql/database/magal-102-b/etc/my.cnf'   --binlog '/home/mysql/database/magal-102-b/binlog/laptop4_magal-102-b_binlog' --gtid 'ac9c693b-0c24-11e8-bbd0-1e63d6801ac1:0' --gtid-domain-id '42'
      2018-02-28 19:47:08 140650095822592 [Warning] WSREP: 0.0 (Node B): State transfer to 1.0 (Node A) failed: -1 (Operation not permitted)
      2018-02-28 19:47:08 140650095822592 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 0)
      2018-02-28 19:47:09 140650095822592 [Note] WSREP: Member 0.0 (Node B) synced with group.
      2018-02-28 19:47:09 140650104215296 [Note] WSREP: forgetting c68162be (tcp://127.0.0.1:5690)
      2018-02-28 19:47:09 140650095822592 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 0)
      

      the important part is this:

      tail: cannot open 'laptop4_magal-102-b_binlog.index' for reading: No such file or directory
      

      Instead of evaluating log_bin_index log_bin is used and '.index' was just added. Which is IMHO wrong.
      We can reproduce this at will and have tested it at least twice.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                jplindst Jan Lindström
                Reporter:
                oli Oli Sennhauser
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: