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.

    XMLWordPrintable

    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: