[MDEV-15436] If log_bin and log_bin_index is different SST with rsync fails. Created: 2018-02-28  Updated: 2018-09-05  Resolved: 2018-09-05

Status: Closed
Project: MariaDB Server
Component/s: Galera SST
Affects Version/s: 10.1, 10.2.13
Fix Version/s: 10.1.36, 10.2.18, 10.3.11

Type: Bug Priority: Major
Reporter: Oli Sennhauser Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: galera, log_bin, log_bin_index, rsync, sst
Environment:

Ubuntu 14.04 (n.a.)

Issue Links:
Relates
relates to MDEV-8735 galera rsync sst - tar of binlog to f... Closed
relates to MDEV-15466 SST not working after upgrade from 10... Closed
relates to MDEV-10754 wsrep_sst_rsync does not support inno... Closed

 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.

 Comments   
Comment by Daniel Black [ 2018-03-01 ]

There are also assumptions about being in the same directory I suspect.

Comment by Jan Lindström (Inactive) [ 2018-06-26 ]

https://github.com/MariaDB/server/commit/44692f17a621d7f0261d84b97a7334352463038c

Generated at Thu Feb 08 08:21:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.