[MDEV-17415] Error 1677, cannot start replication on newly imported sql dump. Created: 2018-10-10  Updated: 2019-10-29  Resolved: 2018-10-25

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.2.18
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Alexander Chernov Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

Debian Jessie

Issue Links:
Blocks
is blocked by MDEV-20766 Error 1677 Cluster failing due to syn... Closed

 Description   

Following a crash which affected our entire cluster (as a result of alter table), I am trying to set up a slave in order to recreate data cleanly and shift everything on new server.

After making a dump from galera cluster (thus row based binlog)

 mysqldump -u root -p --master-data=1 --single-transaction --ignore-table=mysql.inventory --all-databases

I import it on new server, and start the replication.
For some reason though, I am getting following error:

*************************** 1. row ***************************
 
               Slave_IO_State: Queueing master event to the relay log
 
                  Master_Host: 62.210.204.79
 
                  Master_User: replica
 
                  Master_Port: 3306
 
                Connect_Retry: 60
 
              Master_Log_File: mariadb-bin.000685
 
          Read_Master_Log_Pos: 647988717
 
               Relay_Log_File: mysqld-relay-bin.000002
 
                Relay_Log_Pos: 1032
 
        Relay_Master_Log_File: mariadb-bin.000678
 
             Slave_IO_Running: Yes
 
            Slave_SQL_Running: No
 
              Replicate_Do_DB:
 
          Replicate_Ignore_DB:
 
           Replicate_Do_Table:
 
       Replicate_Ignore_Table:
 
      Replicate_Wild_Do_Table:
 
  Replicate_Wild_Ignore_Table:
 
                   Last_Errno: 1677
 
                   Last_Error: Column 1 of table 'live.wishing_well' cannot be converted from type 'int' to type 'tinyint(1)'
 
                 Skip_Counter: 0
 
          Exec_Master_Log_Pos: 1063
 
              Relay_Log_Space: 6899708323
 
              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: 0
 
                Last_IO_Error:
 
               Last_SQL_Errno: 1677
 
               Last_SQL_Error: Column 1 of table 'live.wishing_well' cannot be converted from type 'int' to type 'tinyint(1)'
 
  Replicate_Ignore_Server_Ids:
 
             Master_Server_Id: 1
 
               Master_SSL_Crl:
 
           Master_SSL_Crlpath:
 
                   Using_Gtid: No
 
                  Gtid_IO_Pos:
 
      Replicate_Do_Domain_Ids:
 
  Replicate_Ignore_Domain_Ids:
 
                Parallel_Mode: conservative
 
                    SQL_Delay: 0
 
          SQL_Remaining_Delay: NULL
 
      Slave_SQL_Running_State:
 
1 row in set (0.02 sec)

table structure:

 CREATE TABLE `wishing_well` (
 
  `weevil_id` int(10) unsigned NOT NULL,
 
  `advert_ball` tinyint(1) NOT NULL DEFAULT 0,
 
  `refresh_time` int(10) unsigned DEFAULT NULL,
 
  `free_ball` tinyint(1) unsigned NOT NULL,
 
  `prize_collected` tinyint(1) unsigned NOT NULL DEFAULT 0,
 
  PRIMARY KEY (`weevil_id`),
 
  CONSTRAINT `fk_wishing_well_weevil1` FOREIGN KEY (`weevil_id`) REFERENCES `weevil` (`id`) ON DELETE CASCADE ON UPDATE CASCADE
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4

Mysql version, configs are the same on both servers, charset is the same...

Any hint?

 Comments   
Comment by Elena Stepanova [ 2018-10-10 ]

What is the actual statement / row event in the binary log which makes the replication choke?

Comment by Alexander Chernov [ 2018-10-10 ]

Not sure if I am extracting it right because I can't find any statements related to that table.
show slave status output

 Master_Log_File: mariadb-bin.000684
 
          Read_Master_Log_Pos: 648240354
 
               Relay_Log_File: mysqld-relay-bin.000002
 
                Relay_Log_Pos: 645
 
        Relay_Master_Log_File: mariadb-bin.000679
 
             Slave_IO_Running: Yes
 
            Slave_SQL_Running: No
 
              Replicate_Do_DB:
 
          Replicate_Ignore_DB:
 
           Replicate_Do_Table:
 
       Replicate_Ignore_Table:
 
      Replicate_Wild_Do_Table:
 
  Replicate_Wild_Ignore_Table:
 
                   Last_Errno: 1677
 
                   Last_Error: Column 1 of table 'live.wishing_well' cannot be converted from type 'int' to type 'smallint(10)'
 
                 Skip_Counter: 0
 
          Exec_Master_Log_Pos: 344
 
              Relay_Log_Space: 5088237708
 
              Until_Condition: None

Reading contents of relay.log with
mysqlbinlog --base64-output=decode-rows --verbose mysqld-relay-bin.000002 | more

on coordinates 645 there is nothing?

/*!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
 
#181010 16:50:27 server id 99  end_log_pos 256 CRC32 0xeeb1760d         Start: binlog v 4, server v 10.2.18-MariaDB-10.2.18+maria~stretch-log created 181010 16:50:27
 
# at 256
 
#700101  1:00:00 server id 1  end_log_pos 0 CRC32 0x11645e15    Rotate to mariadb-bin.000679  pos: 4
 
# at 305
 
#180930  8:17:42 server id 1  end_log_pos 256 CRC32 0xd1a4fc3f  Start: binlog v 4, server v 10.2.11-MariaDB-10.2.11+maria~jessie-log created 180930  8:17:42
 
# at 557
 
#180930  8:17:42 server id 1  end_log_pos 299 CRC32 0x8c942d42  Gtid list [0-1-184753947]
 
# at 600
 
#180930  8:17:42 server id 1  end_log_pos 344 CRC32 0x521b2437  Binlog checkpoint mariadb-bin.000678
 
# at 645
 
#180930  8:17:42 server id 1  end_log_pos 386 CRC32 0x4aea2fa9  GTID 0-1-184753948 trans
 
/*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
 
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
 
/*!100001 SET @@session.server_id=1*//*!*/;
 
/*!100001 SET @@session.gtid_seq_no=184753948*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 687
 
#180930  8:17:42 server id 1  end_log_pos 588 CRC32 0x1fd1f8d7  Table_map: `live`.`plant` mapped to number 1568377
 
# at 740
 
#180930  8:17:42 server id 1  end_log_pos 645 CRC32 0xbcbb8f97  Write_rows: table id 1568377 flags: STMT_END_F
 
### INSERT INTO `live`.`plant`
 
### SET
 
###   @1=218380843
 
###   @2=399574
 
###   @3=309
 
###   @4=1538288382
 
###   @5=1538547522
 
###   @6=0
 
# at 797
 
#180930  8:17:42 server id 1  end_log_pos 809 CRC32 0x7adcb959  Table_map: `live`.`terrain_soil` mapped to number 1568382
 
# at 856
 
#180930  8:17:42 server id 1  end_log_pos 874 CRC32 0xc88a0f87  Table_map: `live`.`plant_children` mapped to number 1646403
 
# at 921
 
#180930  8:17:42 server id 1  end_log_pos 950 CRC32 0xfebafa33  Update_rows: table id 1568382 flags: STMT_END_F

Comment by Alexander Chernov [ 2018-10-10 ]

Also, just to be clear: this happens everytime I try to make a new dump. So even if newer dumps are imported (and master log position changes as consequence), I am getting this error.

Comment by Alexander Chernov [ 2018-10-12 ]

My bad, after import I was resetting master info loosing the position in master binlog, which was causing slave starting from the beginning of master's binary logs and choking on the query which have destroyed cluster in the first place.

We can close this since I am unable to provide the query which caused the initial issue.

Comment by Aurélien LEQUOY [ 2019-10-29 ]

I got the same problem :

MySQL 5.5.27 => MariaDB 10.4.8

2019-10-29 12:39:49 48 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000627' position 26232511
 
2019-10-29 12:39:49 48 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.000627' at position 26232511

in binlog :

SET TIMESTAMP=1572268502/*!*/;
 
DROP TABLE `tbl_dbl` /* generated by server */
 
/*!*/;
 
# at 26232377
 
#191028 14:15:02 server id 328147  end_log_pos 26232511         Query   thread_id=5484035       exec_time=0     error_code=0
 
SET TIMESTAMP=1572268502/*!*/;
 
CREATE TABLE `tbl_dbl`(`idcommandefluxD` VARCHAR(100)  ,`nb` INT(10)  )
 
/*!*/;
 
# at 26232511

on Master :

mysql> select * from SCHEMATA where SCHEMA_NAME='mydb';
 
+--------------+-------------+----------------------------+------------------------+----------+
 
| CATALOG_NAME | SCHEMA_NAME | DEFAULT_CHARACTER_SET_NAME | DEFAULT_COLLATION_NAME | SQL_PATH |
 
+--------------+-------------+----------------------------+------------------------+----------+
 
| def          | mydb        | latin1                     | latin1_swedish_ci      | NULL     |
 
+--------------+-------------+----------------------------+------------------------+----------+
 
1 row in set (0.00 sec)

on slave :

MariaDB [mydb]> select * from information_schema.SCHEMATA where SCHEMA_NAME='mydb';
 
+--------------+-------------+----------------------------+------------------------+----------+
 
| CATALOG_NAME | SCHEMA_NAME | DEFAULT_CHARACTER_SET_NAME | DEFAULT_COLLATION_NAME | SQL_PATH |
 
+--------------+-------------+----------------------------+------------------------+----------+
 
| def          | mydb        | utf8                       | utf8_general_ci        | NULL     |
 
+--------------+-------------+----------------------------+------------------------+----------+
 
1 row in set (0.000 sec)

The problem come from mysqldump who made a convertion without say sth ... when you dump / restore one database

Comment by Aurélien LEQUOY [ 2019-10-29 ]

on slave

ALTER DATABASE mydb CHARACTER SET latin1 COLLATE latin1_swedish_ci;
 
 
 
select * from information_schema.SCHEMATA where SCHEMA_NAME='mydb';
 
+--------------+-------------+----------------------------+------------------------+----------+
 
| CATALOG_NAME | SCHEMA_NAME | DEFAULT_CHARACTER_SET_NAME | DEFAULT_COLLATION_NAME | SQL_PATH |
 
+--------------+-------------+----------------------------+------------------------+----------+
 
| def          | mydb        | latin1                     | latin1_swedish_ci      | NULL     |
 
+--------------+-------------+----------------------------+------------------------+----------+
 
1 row in set (0.000 sec)

but it's not help :

Last_SQL_Error: Column 0 of table 'mydb.tbl_dbl' cannot be converted from type 'varchar(100 octets)' to type 'varchar(300 octets) character set utf8'

Comment by Aurélien LEQUOY [ 2019-10-29 ]

everything in latin1 now why try to convert in utf8 ?

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