Relay log position corrupted with parallel replication after interrupting LOAD DATA on master

Description

A master was running a LOAD DATA statement, and the statement was interrupted by pressing CTRL-C on the client. This partially completed query caused errors on the slaves. For example, SHOW SLAVE STATUS showed:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 root@server2 [(none)]> show slave status\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: server2 Master_User: replicator Master_Port: 3306 Connect_Retry: 60 Master_Log_File: binlog.140014 Read_Master_Log_Pos: 88410906 Relay_Log_File: relaylog.033127 Relay_Log_Pos: 4 Relay_Master_Log_File: binlog.140008 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: 1158 Last_Error: Query partially completed on the master (error on master: 1158) and was aborted. There is a chance that your master is inconsistent at this point. If you are sure that your master is ok, run this query manually on the slave and then restart the slave with SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; . Query: 'LOAD DATA INFILE '../tmp/SQL_LOAD-187227023-187218030-143925.data' IGNORE INTO TABLE `sometab` CHARACTER SET utf8 FIELDS TERMINATED BY ',' ENCLOSED BY '"' ESCAPED BY '\\' LINES TERMINATED BY '\n' IGNORE 1 LINES (`field1`, `field2`)' Skip_Counter: 0 Exec_Master_Log_Pos: 20798609 Relay_Log_Space: 3019418333 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: 1158 Last_SQL_Error: Query partially completed on the master (error on master: 1158) and was aborted. There is a chance that your master is inconsistent at this point. If you are sure that your master is ok, run this query manually on the slave and then restart the slave with SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; . Query: 'LOAD DATA INFILE '../tmp/SQL_LOAD-187227023-187218030-143925.data' IGNORE INTO TABLE `sometab` CHARACTER SET utf8 FIELDS TERMINATED BY ',' ENCLOSED BY '"' ESCAPED BY '\\' LINES TERMINATED BY '\n' IGNORE 1 LINES (`field1`, `field2`)' Replicate_Ignore_Server_Ids: Master_Server_Id: 187218030 Master_SSL_Crl: Master_SSL_Crlpath: Using_Gtid: Slave_Pos Gtid_IO_Pos: 0-187226073-1732279097,999-186069024-2 1 row in set (0.00 sec)

The error log also showed the error:

1 2 3 151109 13:10:41 [ERROR] Slave SQL: Query partially completed on the master (error on master: 1158) and was aborted. There is a chance that your master is inconsistent at this point. If you are sure that your master is ok, run this query manually on the slave and then restart the slave with SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; . Query: 'LOAD DATA INFILE '../tmp/SQL_LOAD-187227023-187218030-143925.data' IGNORE INTO TABLE `sometab` CHARACTER SET utf8 FIELDS TERMINATED BY ',' ENCLOSED BY '"' ESCAPED BY '\\' LINES TERMINATED BY '\n' IGNORE 1 LINES (`field1`, `field2`)', Gtid 0-187218030-1732217639, Internal MariaDB error code: 1158 151109 13:10:41 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'binlog.140008' position 20798609; GTID position '0-187226073-1732217638,999-186069024-2' 151109 13:10:41 [Note] Error reading relay log event: slave SQL thread was killed

An error on the slave about a partially completed query is expected, but note that the master's error in this case was #1158 (ER_NET_READ_ERROR), and not error #1317 (ER_QUERY_INTERRUPTED), which would be the expected error when a query is interrupted.

When the partially completed query was skipped with "SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE;" as the error message recommended, this caused something strange to happen on slaves that had slave_parallel_threads > 0:

1 2 151109 13:19:41 [Note] Slave SQL thread initialized, starting replication in log 'binlog.140008' at position 20798609, relay log '../log/relaylog.031235' position: 4; GTID position '0-187226073-1732217638,999-186069024-2' 151109 13:19:41 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='../log/relaylog.031235', relay_log_pos='4', master_log_name='binlog.140008', master_log_pos='20798609', GTID '0-187226073-1732217638,999-186069024-2'; and new position at relay_log_file='../log/relaylog.031235', relay_log_pos='1866', master_log_name='binlog.140007', master_log_pos='1582', GTID '0-187226073-1732162247,999-186069024-2';

The relay log position jumps ahead from (relaylog.031235, 4) to (relaylog.031235, 1866), but the master binlog position actually goes backwards from (binlog.140008, 20798609) to (binlog.140007, 1582) and the GTID position goes backwards from '0-187226073-1732217638,999-186069024-2' to 0-187226073-1732162247,999-186069024-2'. When replication is restarted, duplicate key errors are seen as old insert statements are re-run.

This did not happen on slaves that were not using parallel replication.

After closer inspection, it appeared that the values of (Relay_Log_File, Relay_Log_Pos) and (Relay_Master_Log_File, Exec_Master_Log_Pos) reported by SHOW SLAVE STATUS did not match up to the same logical position. It seems that the slave's relay log position is corrupted when parallel replication is enabled and LOAD DATA is cancelled on the master with error #1158.

When the error occurred on slaves using parallel replication, relay log position corruption could be avoided by using this process:

  • stop slave;

  • start slave io_thread; # This wipes the relay logs and download back the binlog from the failed LOAD DATA INFILE.

  • SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE SQL_THREAD;

Environment

None

Status

Assignee

Kristian Nielsen

Reporter

Geoff Montee

External issue ID

None

External issue ID

None

Components

Fix versions

Affects versions

10.0.19
10.0.23

Priority

Major
Configure