[MDEV-7520] [patch] gtid replication broken during upgrade to debian 10.0.16 Created: 2015-01-28  Updated: 2015-02-22  Resolved: 2015-02-21

Status: Closed
Project: MariaDB Server
Component/s: Packaging, Platform Debian, Scripts & Clients
Affects Version/s: 10.0.16
Fix Version/s: 10.0.17

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: None
Environment:

debian wheezy x86_64


Attachments: File mdev-7520.patch    

 Description   

after upgrading two servers from 10.0.15 to 10.0.16 replicating off each other in gtid replication mode Current_Pos their slave status was as follows:

server greeneggs:

MariaDB [mysql]> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: 
                  Master_Host: 192.168.138.168
                  Master_User: replica
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mariadb-bin.010731
          Read_Master_Log_Pos: 25836657
               Relay_Log_File: mysqld-relay-bin.000053
                Relay_Log_Pos: 4
        Relay_Master_Log_File: mariadb-bin.010731
             Slave_IO_Running: No
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: peoplesforum.cache%
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 25836657
              Relay_Log_Space: 546
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Error: connecting slave requested to start from GTID 0-12302-1263736, which is not in the master's binlog. Since the master's binlog contains GTIDs with higher sequence numbers, it probably means that the slave has diverged due to executing extra errorneous transactions'
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 12301
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
                   Using_Gtid: Current_Pos
                  Gtid_IO_Pos: 13-12302-15747,0-12302-1263736,39-12302-34591,106-12302-476,33-12302-190678,49-12302-1664631,43-12302-7199375,15-12302-69257,37-12302-39157,104-12302-4,47-12302-29257,98-12302-4377,57-12302-48207,55-12302-1620,35-12302-356,17-12302-26913,29-12302-455091,67-12302-2829328
1 row in set (0.00 sec)

server catinthehat:

MariaDB [(none)]> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: 
                  Master_Host: 192.168.149.5
                  Master_User: replica
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mariadb-bin.008477
          Read_Master_Log_Pos: 26139596
               Relay_Log_File: mysqld-relay-bin.000001
                Relay_Log_Pos: 4
        Relay_Master_Log_File: mariadb-bin.008477
             Slave_IO_Running: No
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: peoplesforum.cache%
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 26139596
              Relay_Log_Space: 546
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Error: connecting slave requested to start from GTID 0-12301-1263736, which is not in the master's binlog. Since the master's binlog contains GTIDs with higher sequence numbers, it probably means that the slave has diverged due to executing extra errorneous transactions'
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 12302
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
                   Using_Gtid: Current_Pos
                  Gtid_IO_Pos: 13-12302-15747,0-12301-1263736,39-12302-34591,106-12302-476,33-12302-190678,49-12302-1664631,43-12302-7199362,15-12302-69257,37-12302-39157,104-12302-4,47-12302-29257,98-12302-4377,57-12302-48207,55-12302-1620,35-12302-356,17-12302-26913,29-12302-455087,67-12302-2829328

greeneggs:

no changes to domain_id 0 in this file after the 26139596 position.
 
root@greeneggs:/home/danblack# mysqlbinlog --base64-output=DECODE-ROWS --start-position=26139596     /var/lib/mysql/mariadb-bin.008477 | more         
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 26139596
#150127 22:09:33 server id 12302  end_log_pos 26139634  GTID 29-12302-455088
/*!100001 SET @@session.gtid_domain_id=29*//*!*/;
/*!100001 SET @@session.server_id=12302*//*!*/;
/*!100001 SET @@session.gtid_seq_no=455088*//*!*/;
BEGIN
/*!*/;
# at 26139634
#150127 22:09:33 server id 12302  end_log_pos 26139798  Query   thread_id=4077092       exec_time=0     error_code=0
use `lentzwiki`/*!*/;
SET TIMESTAMP=1422396573/*!*/;
SET @@session.pseudo_thread_id=4077092/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
UPDATE /*  157.55.39.103 */ `page` SET page_counter = page_counter + 1 WHERE page_id = 1385
/*!*/;
....
#150127 22:09:40 server id 12302  end_log_pos 26147317  Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
 
root@greeneggs:/home/danblack# mysqlbinlog --base64-output=DECODE-ROWS --verbose      /var/lib/mysql/mariadb-bin.008478 | more                        
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 22:10:04 server id 12302  end_log_pos 248       Start: binlog v 4, server v 10.0.16-MariaDB-1~wheezy-log created 150127 22:10:04 at startup
ROLLBACK/*!*/;
# at 248
#150127 22:10:04 server id 12302  end_log_pos 575       Gtid list [13-12302-15747,
# 0-12302-1263625,
# 0-12301-1263643,
# 55-12302-1620,
# 106-12302-476,
# 49-12302-1664631,
# 17-12302-26913,
# 43-12302-7199375,
# 15-12302-69257,
# 37-12302-39157,
# 104-12302-4,
# 47-12302-29257,
# 98-12302-4377,
# 57-12302-48207,
# 39-12302-34591,
# 67-12302-2829328,
# 35-12302-356,
# 29-12302-455091,
# 33-12302-190678]
# at 575
#150127 22:10:04 server id 12302  end_log_pos 616       Binlog checkpoint mariadb-bin.008478
# at 616
#150127 22:10:04 server id 12302  end_log_pos 654       GTID 0-12302-1263644
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=12302*//*!*/;
/*!100001 SET @@session.gtid_seq_no=1263644*//*!*/;
# at 654
#150127 22:10:04 server id 12302  end_log_pos 2418      Query   thread_id=2     exec_time=0     error_code=0
use `mysql`/*!*/;
SET TIMESTAMP=1422396604/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
CREATE TABLE IF NOT EXISTS db ( ...
/*!*/;
# at 2418
#150127 22:10:04 server id 12302  end_log_pos 2456      GTID 0-12302-1263645
/*!100001 SET @@session.gtid_seq_no=1263645*//*!*/;
# at 2456
#150127 22:10:04 server id 12302  end_log_pos 4116      Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396604/*!*/;
CREATE TABLE IF NOT EXISTS host (  Host....
.....
# at 65671
#150127 22:10:04 server id 12302  end_log_pos 65709     GTID 0-12302-1263733
/*!100001 SET @@session.gtid_seq_no=1263733*//*!*/;
# at 65709
#150127 22:10:04 server id 12302  end_log_pos 65861     Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396604/*!*/;
DROP TEMPORARY TABLE IF EXISTS `mysql`.`tmp_proxies_priv` /* generated by server */
/*!*/;
# at 65861
#150127 22:10:04 server id 12302  end_log_pos 65880     Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
# mysqlbinlog --base64-output=DECODE-ROWS --verbose      /var/lib/mysql/mariadb-bin.008479 | more
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 22:10:07 server id 12302  end_log_pos 248       Start: binlog v 4, server v 10.0.16-MariaDB-1~wheezy-log created 150127 22:10:07 at startup
ROLLBACK/*!*/;
# at 248
#150127 22:10:07 server id 12302  end_log_pos 575       Gtid list [13-12302-15747,
# 0-12301-1263643,
# 0-12302-1263733,
# 39-12302-34591,
# 106-12302-476,
# 33-12302-190678,
# 49-12302-1664631,
# 43-12302-7199375,
# 15-12302-69257,
# 37-12302-39157,
# 104-12302-4,
# 47-12302-29257,
# 98-12302-4377,
# 57-12302-48207,
# 55-12302-1620,
# 35-12302-356,
# 67-12302-2829328,
# 29-12302-455091,
# 17-12302-26913]
# at 575
#150127 22:10:07 server id 12302  end_log_pos 616       Binlog checkpoint mariadb-bin.008479
# at 616
#150127 22:10:07 server id 12302  end_log_pos 635       Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
 
mariadb-bin.008480
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 22:10:09 server id 12302  end_log_pos 248       Start: binlog v 4, server v 10.0.16-MariaDB-1~wheezy-log created 150127 22:10:09 at startup
ROLLBACK/*!*/;
# at 248
#150127 22:10:09 server id 12302  end_log_pos 575       Gtid list [13-12302-15747,
# 0-12301-1263643,
# 0-12302-1263733,
# 55-12302-1620,
# 106-12302-476,
# 17-12302-26913,
# 33-12302-190678,
# 43-12302-7199375,
# 15-12302-69257,
# 37-12302-39157,
# 104-12302-4,
# 47-12302-29257,
# 98-12302-4377,
# 57-12302-48207,
# 39-12302-34591,
# 67-12302-2829328,
# 35-12302-356,
# 29-12302-455091,
# 49-12302-1664631]
# at 575
#150127 22:10:09 server id 12302  end_log_pos 616       Binlog checkpoint mariadb-bin.008480
# at 616
#150127 22:10:09 server id 12302  end_log_pos 654       GTID 0-12302-1263734
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=12302*//*!*/;
/*!100001 SET @@session.gtid_seq_no=1263734*//*!*/;
# at 654
#150127 22:10:09 server id 12302  end_log_pos 835       Query   thread_id=2     exec_time=0     error_code=0
use `mysql`/*!*/;
SET TIMESTAMP=1422396609/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
 ALTER TABLE user CHANGE Password Password char(41) character set latin1 collate latin1_bin DEFAULT '' NOT NULL;
/*!*/;
# at 835
#150127 22:10:09 server id 12302  end_log_pos 854       Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
# mysqlbinlog --base64-output=DECODE-ROWS --verbose      /var/lib/mysql/mariadb-bin.008482 | more 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 22:10:14 server id 12302  end_log_pos 248       Start: binlog v 4, server v 10.0.16-MariaDB-1~wheezy-log created 150127 22:10:14 at startup
ROLLBACK/*!*/;
# at 248
#150127 22:10:14 server id 12302  end_log_pos 575       Gtid list [13-12302-15747,
# 0-12301-1263643,
# 0-12302-1263735,
# 55-12302-1620,
# 106-12302-476,
# 33-12302-190678,
# 49-12302-1664631,
# 43-12302-7199375,
# 15-12302-69257,
# 37-12302-39157,
# 104-12302-4,
# 47-12302-29257,
# 98-12302-4377,
# 57-12302-48207,
# 39-12302-34591,
# 67-12302-2829328,
# 35-12302-356,
# 29-12302-455091,
# 17-12302-26913]
# at 575
#150127 22:10:14 server id 12302  end_log_pos 616       Binlog checkpoint mariadb-bin.008482
# at 616
#150127 22:10:14 server id 12302  end_log_pos 654       GTID 0-12302-1263736
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=12302*//*!*/;
/*!100001 SET @@session.gtid_seq_no=1263736*//*!*/;
# at 654
#150127 22:10:14 server id 12302  end_log_pos 964       Query   thread_id=2     exec_time=0     error_code=0
use `mysql`/*!*/;
SET TIMESTAMP=1422396614/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
 CREATE TABLE IF NOT EXISTS plugin (name char(64) COLLATE utf8_bin NOT NULL DEFAULT '',    dl char(128) COLLATE utf8_bin NOT NULL DEFAULT '',    PRIMARY KEY (name)) ENGINE=MyISAM DEFAULT CHAR
SET=utf8 COLLATE=utf8_bin COMMENT='MySQL plugins';
/*!*/;
# at 964
#150127 22:10:14 server id 12302  end_log_pos 983       Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
# mysqlbinlog --base64-output=DECODE-ROWS --verbose      /var/lib/mysql/mariadb-bin.008482 | more 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 22:10:14 server id 12302  end_log_pos 248       Start: binlog v 4, server v 10.0.16-MariaDB-1~wheezy-log created 150127 22:10:14 at startup
ROLLBACK/*!*/;
# at 248
#150127 22:10:14 server id 12302  end_log_pos 575       Gtid list [13-12302-15747,
# 0-12301-1263643,
# 0-12302-1263735,
# 55-12302-1620,
# 106-12302-476,
# 33-12302-190678,
# 49-12302-1664631,
# 43-12302-7199375,
# 15-12302-69257,
# 37-12302-39157,
# 104-12302-4,
# 47-12302-29257,
# 98-12302-4377,
# 57-12302-48207,
# 39-12302-34591,
# 67-12302-2829328,
# 35-12302-356,
# 29-12302-455091,
# 17-12302-26913]
# at 575
#150127 22:10:14 server id 12302  end_log_pos 616       Binlog checkpoint mariadb-bin.008482
# at 616
#150127 22:10:14 server id 12302  end_log_pos 654       GTID 0-12302-1263736
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=12302*//*!*/;
/*!100001 SET @@session.gtid_seq_no=1263736*//*!*/;
# at 654
#150127 22:10:14 server id 12302  end_log_pos 964       Query   thread_id=2     exec_time=0     error_code=0
use `mysql`/*!*/;
SET TIMESTAMP=1422396614/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
 CREATE TABLE IF NOT EXISTS plugin (name char(64) COLLATE utf8_bin NOT NULL DEFAULT '',    dl char(128) COLLATE utf8_bin NOT NULL DEFAULT '',    PRIMARY KEY (name)) ENGINE=MyISAM DEFAULT CHAR
SET=utf8 COLLATE=utf8_bin COMMENT='MySQL plugins';
/*!*/;
# at 964
#150127 22:10:14 server id 12302  end_log_pos 983       Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
 
mariadb-bin.008483 (empty)
 
# mysqlbinlog --base64-output=DECODE-ROWS --verbose      /var/lib/mysql/mariadb-bin.008484 | more 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 22:10:18 server id 12302  end_log_pos 248       Start: binlog v 4, server v 10.0.16-MariaDB-1~wheezy-log created 150127 22:10:18
# Warning: this binlog is either in use or was not closed properly.
# at 248
#150127 22:10:18 server id 12302  end_log_pos 575       Gtid list [13-12302-15747,
# 0-12301-1263643,
# 0-12302-1263736,
# 39-12302-34591,
# 106-12302-476,
# 17-12302-26913,
# 33-12302-190678,
# 43-12302-7199375,
# 15-12302-69257,
# 37-12302-39157,
# 104-12302-4,
# 47-12302-29257,
# 98-12302-4377,
# 57-12302-48207,
# 55-12302-1620,
# 35-12302-356,
# 67-12302-2829328,
# 29-12302-455091,
# 49-12302-1664631]
# at 575
#150127 22:10:18 server id 12302  end_log_pos 616       Binlog checkpoint mariadb-bin.008483
# at 616
#700101  0:00:00 server id 12302  end_log_pos 657       Binlog checkpoint mariadb-bin.008484
# at 657
#150127 22:10:39 server id 12302  end_log_pos 695       GTID 29-12302-455092
/*!100001 SET @@session.gtid_domain_id=29*//*!*/;
/*!100001 SET @@session.server_id=12302*//*!*/;
/*!100001 SET @@session.gtid_seq_no=455092*//*!*/;
BEGIN
/*!*/;
# at 695
#150127 22:10:39 server id 12302  end_log_pos 858       Query   thread_id=70    exec_time=0     error_code=0
use `lentzwiki`/*!*/;
SET TIMESTAMP=1422396639/*!*/;
SET @@session.pseudo_thread_id=70/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;

catinthehat:

root@catinthehat:/home/danblack# mysqlbinlog  --start-position=25836657 /var/lib/mysql/mariadb-bin.010731       
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 18:33:46 server id 12301  end_log_pos 248       Start: binlog v 4, server v 10.0.15-MariaDB-1~wheezy-log created 150127 18:33:46
BINLOG '
CtrHVA8NMAAA9AAAAPgAAAAAAAQAMTAuMC4xNS1NYXJpYURCLTF+d2hlZXp5LWxvZwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA3AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQA1Ak15Q==
'/*!*/;
# at 25836657
#150127 22:09:33 server id 12301  end_log_pos 25836676  Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
 
 
# mysqlbinlog  /var/lib/mysql/mariadb-bin.010732 | more
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150127 22:09:42 server id 12301  end_log_pos 248       Start: binlog v 4, server v 10.0.16-MariaDB-1~wheezy-log created 150127 22:09:42 at startup
ROLLBACK/*!*/;
BINLOG '
pgzIVA8NMAAA9AAAAPgAAAAAAAQAMTAuMC4xNi1NYXJpYURCLTF+d2hlZXp5LWxvZwAAAAAAAAAA
AAAAAAAAAAAAAAAAAACmDMhUEzgNAAgAEgAEBAQEEgAA3AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQAnGHsRQ==
'/*!*/;
# at 248
#150127 22:09:42 server id 12301  end_log_pos 575       Gtid list [13-12302-15747,
# 0-12302-1263625,
# 0-12301-1263643,
# 55-12302-1617,
# 106-12302-476,
# 17-12302-26913,
# 49-12302-1664631,
# 43-12302-7199362,
# 15-12302-69257,
# 37-12302-39157,
# 104-12302-4,
# 47-12302-29257,
# 98-12302-4377,
# 57-12302-48207,
# 39-12302-34591,
# 67-12302-2829328,
# 35-12302-356,
# 29-12302-455087,
# 33-12302-190678]
# at 575
#150127 22:09:42 server id 12301  end_log_pos 616       Binlog checkpoint mariadb-bin.010732
# at 616
#150127 22:09:42 server id 12301  end_log_pos 654       GTID 0-12301-1263644
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=12301*//*!*/;
/*!100001 SET @@session.gtid_seq_no=1263644*//*!*/;
# at 654
#150127 22:09:42 server id 12301  end_log_pos 2418      Query   thread_id=2     exec_time=0     error_code=0
use `mysql`/*!*/;
SET TIMESTAMP=1422396582/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
CREATE TABLE IF NOT EXISTS db ( 
....
# at 2418
#150127 22:09:42 server id 12301  end_log_pos 2456      GTID 0-12301-1263645
/*!100001 SET @@session.gtid_seq_no=1263645*//*!*/;
# at 2456
#150127 22:09:42 server id 12301  end_log_pos 4116      Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396582/*!*/;
CREATE TABLE IF NOT EXISTS host 
...
# at 64324
#150127 22:09:42 server id 12301  end_log_pos 64501     Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396582/*!*/;
CREATE TABLE performance_schema.session_account_connect_attrs  LIKE performance_schema.session_connect_attrs
/*!*/;
# at 64501
#150127 22:09:42 server id 12301  end_log_pos 64539     GTID 0-12301-1263728
/*!100001 SET @@session.gtid_seq_no=1263728*//*!*/;
# at 64539
#150127 22:09:42 server id 12301  end_log_pos 64650     Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396582/*!*/;
CREATE TEMPORARY TABLE tmp_user LIKE user;
/*!*/;
# at 64650
#150127 22:09:42 server id 12301  end_log_pos 64688     GTID 0-12301-1263729
/*!100001 SET @@session.gtid_seq_no=1263729*//*!*/;
BEGIN
/*!*/;
# at 64688
#150127 22:09:42 server id 12301  end_log_pos 64960     Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396582/*!*/;
INSERT INTO tmp_user VALUES ('localhost','root','','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','','','','',0,0,0,0,'','
','N', 'N');
/*!*/;
# at 64960
#150127 22:09:42 server id 12301  end_log_pos 65035     Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396582/*!*/;
COMMIT
/*!*/;
# at 65035
...
#150127 22:09:42 server id 12301  end_log_pos 65709     GTID 0-12301-1263733
/*!100001 SET @@session.gtid_seq_no=1263733*//*!*/;
# at 65709
#150127 22:09:42 server id 12301  end_log_pos 65861     Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1422396582/*!*/;
DROP TEMPORARY TABLE IF EXISTS `mysql`.`tmp_proxies_priv` /* generated by server */
/*!*/;
# at 65861
#150127 22:09:42 server id 12301  end_log_pos 65880     Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Looks like the mysql_install_db pushed statements to the binlogs of both servers and confused the gtid positions. Can these be not written to binlog (like the mysql_update)?



 Comments   
Comment by Daniel Black [ 2015-01-28 ]

other sql updates in debian/dist/Debian/mariadb-server-10.0.postinst should also be sql_log_bin=0

(like https://github.com/ottok/mariadb-10.0/pull/3/files )

Comment by Elena Stepanova [ 2015-01-28 ]

Looks like the mysql_install_db pushed statements to the binlogs of both servers and confused the gtid positions. Can these be not written to binlog (like the mysql_update)?

Do you mean that mysql_install_db was run during upgrade?

Comment by Daniel Black [ 2015-01-28 ]

mysql_install_db is run in debian/dist/Debian/mariadb-server-10.0.postinst which is the postinstall of the upgrade

Comment by Elena Stepanova [ 2015-01-29 ]

mysql_install_db is run in debian/dist/Debian/mariadb-server-10.0.postinst which is the postinstall of the upgrade

Indeed... it's a bit weird, which in itself is not surprising when it comes to the deb install/upgrade scripts.

Looks like the mysql_install_db pushed statements to the binlogs of both servers and confused the gtid positions. Can these be not written to binlog (like the mysql_update)?

I believe we should do that (assigning to serg to confirm or maybe come up with another idea).

However, I don't see any signs of a change in this behavior in 10.0.16. Did it work before, or is it a new setup which was upgraded for the first time?

Note: I didn't verify the actual problem with GTID, but indeed updates from mysql_install_db are written to the binary log, which in itself is weird.

Comment by Daniel Black [ 2015-01-29 ]

No behaviour has changed in 10.0.16. Upgrades haven't affected file/pos replication or master_use_gtid=slave_pos (which may be what I should be using), however with replication mode master_use_gtid=current_pos (which I've only semi recently set on these servers).

There's no need to write these statements to the binlog they aren't needed by any slave (although usually harmless except for this case). On start up the same functions are called again so in a recovery situation there is no chance of a local db server missing its initialisation statements.

Comment by Sergei Golubchik [ 2015-02-20 ]

Yes, I agree too.
I'm not sure, though, on what level it should be fixed. The deeper it goes, the higher is the risk of breaking some weird use case, but also the better is the coverage. I mean, it could be fixed:

  • in server post-install script on Debian — by doing mysql_install_db --disable-log-bin
  • in mysql_install_db script, by adding --disable-log-big to mysqld bootstrap command line
  • in the server, by disabling binlog automatically in bootstrap mode (e.g. replication is already disabled in bootstrap).
Comment by Elena Stepanova [ 2015-02-20 ]

I will probably vote for the minimal solution (post-install). If we later get a complaint about another use case which involves deeper levels, we can reconsider.

Comment by Daniel Black [ 2015-02-21 ]

sounds fair to me.

Generated at Thu Feb 08 07:20:13 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.