Details
-
Type:
Bug
-
Status: Open
-
Priority:
Major
-
Resolution: Unresolved
-
Affects Version/s: 10.0.17
-
Fix Version/s: None
-
Component/s: Replication
-
Labels:
-
Environment:rhel6
Description
replication error on 10.0.17 slave with 10.0.17 master. Table had no PK.
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 172.16.194.76
Master_User: repl
Master_Port: 3310
Connect_Retry: 60
Master_Log_File: tulwaurt005-mysql-bin.000325
Read_Master_Log_Pos: 185442169
Relay_Log_File: tulwaurt009-relay-bin.000026
Relay_Log_Pos: 835832166
Relay_Master_Log_File: tulwaurt005-mysql-bin.000309
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table: xxx.feed_bettordata_data,xxx_docs.session,xxx_docs.session,xxx.feed_bettordata_data
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1032
Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938
Skip_Counter: 0
Exec_Master_Log_Pos: 840720516
Relay_Log_Space: 14811971033
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: 12433
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 1032
Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938
Replicate_Ignore_Server_Ids:
Master_Server_Id: 20076
Master_SSL_Crl:
Master_SSL_Crlpath:
Using_Gtid: Slave_Pos
Gtid_IO_Pos: 3-20076-44284,0-20076-64741091
No sql thread progress between show slave status\G
MariaDB [(none)]> show processlist; +----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+------------------+----------+ | Id | User | Host | db | Command | Time | State | Info | Progress | +----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+------------------+----------+ | 3 | system user | | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 4 | system user | | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 5 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 6 | system user | | NULL | Connect | 404026 | Waiting for work from SQL thread | NULL | 0.000 | | 7 | system user | | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 8 | system user | | NULL | Connect | 404026 | Waiting for work from SQL thread | NULL | 0.000 | | 9 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 10 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 11 | system user | | NULL | Connect | 404026 | Waiting for work from SQL thread | NULL | 0.000 | | 12 | system user | | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 13 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 14 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 15 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 16 | system user | | NULL | Connect | 404026 | Waiting for work from SQL thread | NULL | 0.000 | | 17 | system user | | NULL | Connect | 404026 | Waiting for work from SQL thread | NULL | 0.000 | | 18 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 19 | system user | | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 20 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 21 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 22 | system user | | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | | 23 | system user | | NULL | Connect | 13502 | Waiting for master to send event | NULL | 0.000 | | 24 | system user | | NULL | Connect | 2990 | Waiting for room in worker thread event queue | NULL | 0.000 | | 40 | openquery | localhost | NULL | Sleep | 9519 | | NULL | 0.000 | | 44 | openquery | 127.0.0.1:55730 | NULL | Query | 0 | init | show processlist | 0.000 | +----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+------------------+----------+
Took attached gdb backtraces
mysqlbinlog --base64-output=decode-rows --verbose tulwaurt009-relay-bin.000026 --start-position 835832166 | 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 835832166 #150408 23:38:10 server id 20076 end_log_pos 840720554 GTID 0-20076-42437721 /*!100001 SET @@session.gtid_domain_id=0*//*!*/; /*!100001 SET @@session.server_id=20076*//*!*/; /*!100001 SET @@session.gtid_seq_no=42437721*//*!*/; BEGIN /*!*/; # at 835832204 # at 835832278 #150408 23:38:10 server id 20076 end_log_pos 840720854 Table_map: `xxx_20150210`.`data_source_prices` mapped to number 19326 #150408 23:38:10 server id 20076 end_log_pos 840720938 Update_rows: table id 19326 flags: STMT_END_F ### UPDATE `xxx_20150210`.`data_source_prices` ### WHERE ### @1=6379754 ### @2=1 ### @3=9 ### @4=000000023.600000000 ### @5=2015-04-09 09:07:23 ### SET ### @1=6379754 ### @2=1 ### @3=9 ### @4=000000023.800000000 ### @5=2015-04-09 09:08:10 # at 835832362 #150408 23:38:10 server id 20076 end_log_pos 840720965 Xid = 411642227 COMMIT/*!*/; # at 835832389 #150408 23:38:10 server id 20076 end_log_pos 840721003 GTID 0-20076-42437722 /*!100001 SET @@session.gtid_seq_no=42437722*//*!*/; BEGIN /*!*/; # at 835832427 # at 835832509 #150408 23:38:10 server id 20076 end_log_pos 840721304 Table_map: `xxx_20150210`.`data_source_prices_history` mapped to number 21912 #150408 23:38:10 server id 20076 end_log_pos 840721360 Write_rows: table id 21912 flags: STMT_END_F ### INSERT INTO `xxx_20150210`.`data_source_prices_history` ### SET ### @1=6379755 ### @2=1 ### @3=9 ### @4=000000003.200000000 ### @5=2015-04-09 09:07:23 # at 835832565 #150408 23:38:10 server id 20076 end_log_pos 840721387 Xid = 411642228 COMMIT/*!*/;
| data_source_prices | CREATE TABLE `data_source_prices` ( `market_selection_details_id` int(11) NOT NULL DEFAULT '0', `bet_type` int(10) NOT NULL DEFAULT '0', `data_source_id` int(11) NOT NULL DEFAULT '0', `price` decimal(12,2) NOT NULL DEFAULT '0.00', `last_updated` datetime DEFAULT NULL, KEY `market_selection_details_id` (`market_selection_details_id`,`bet_type`,`data_source_id`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC | MariaDB [xxx_20150210]> select * from data_source_prices where market_selection_details_id=6379754 and bet_type=1 and data_source_id=9; +-----------------------------+----------+----------------+-------+---------------------+ | market_selection_details_id | bet_type | data_source_id | price | last_updated | +-----------------------------+----------+----------------+-------+---------------------+ | 6379754 | 1 | 9 | 23.60 | 2015-04-08 23:37:23 | +-----------------------------+----------+----------------+-------+---------------------+
record doesn't match on last_updated
On master:
MariaDB [xxx_20150210_schema_test]> show master logs; +------------------------------+------------+ | Log_name | File_size | +------------------------------+------------+ | tulwaurt005-mysql-bin.000295 | 1073758494 | | tulwaurt005-mysql-bin.000296 | 1073742300 | | tulwaurt005-mysql-bin.000297 | 1073742367 | | tulwaurt005-mysql-bin.000298 | 1073743137 | | tulwaurt005-mysql-bin.000299 | 1073745171 | | tulwaurt005-mysql-bin.000300 | 1073741945 | | tulwaurt005-mysql-bin.000301 | 1073742118 | | tulwaurt005-mysql-bin.000302 | 1073742068 | | tulwaurt005-mysql-bin.000303 | 1073745675 | | tulwaurt005-mysql-bin.000304 | 1073742497 | | tulwaurt005-mysql-bin.000305 | 1073741977 | | tulwaurt005-mysql-bin.000306 | 1073741908 | | tulwaurt005-mysql-bin.000307 | 1073742723 | | tulwaurt005-mysql-bin.000308 | 1073742108 | | tulwaurt005-mysql-bin.000309 | 1073766758 | | tulwaurt005-mysql-bin.000310 | 1073742006 | | tulwaurt005-mysql-bin.000311 | 1073742880 | | tulwaurt005-mysql-bin.000312 | 1073744059 | | tulwaurt005-mysql-bin.000313 | 1073741975 | | tulwaurt005-mysql-bin.000314 | 1073743573 | | tulwaurt005-mysql-bin.000315 | 1073743122 | | tulwaurt005-mysql-bin.000316 | 1073743058 | | tulwaurt005-mysql-bin.000317 | 1073742208 | | tulwaurt005-mysql-bin.000318 | 1073743476 | | tulwaurt005-mysql-bin.000319 | 1073742423 | | tulwaurt005-mysql-bin.000320 | 1073742672 | | tulwaurt005-mysql-bin.000321 | 1073744024 | | tulwaurt005-mysql-bin.000322 | 1073743039 | | tulwaurt005-mysql-bin.000323 | 1073742110 | | tulwaurt005-mysql-bin.000324 | 1073742370 | | tulwaurt005-mysql-bin.000325 | 274709272 | +------------------------------+------------+ ls -la /u01/mariadb-10/tulwaurt005-mysql-bin.000309* -rw-rw----. 1 mysql mysql 1073766758 Apr 9 10:40 /u01/mariadb-10/tulwaurt005-mysql-bin.000309
back on slave:
Stop slave failed - same as MDEV-7126
strace -p 52045
Process 52045 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 1
fcntl(37, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(37, F_SETFL, O_RDWR|O_NONBLOCK) = 0
accept(37, {sa_family=AF_FILE, NULL}, [2]) = 619
fcntl(37, F_SETFL, O_RDWR) = 0
fcntl(619, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
setsockopt(619, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)
mmap(NULL, 299008, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fb83c839000
mprotect(0x7fb83c839000, 4096, PROT_NONE) = 0
clone(child_stack=0x7fb83c880ed0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb83c8819d0, tls=0x7fb83c881700, child_tidptr=0x7fb83c8819d0) = 46312
poll([{fd=36, events=POLLIN}, {fd=37, events=POLLIN}], 2, -1^C <unfinished ...>
Process 52045 detached
kill 52045
kill -9 52045
service mysql start
stop slave; start slave; show slave status\G
Slave_IO_State: Queueing master event to the relay log
Master_Host: 172.16.194.76
Master_User: repl
Master_Port: 3310
Connect_Retry: 60
Master_Log_File: tulwaurt005-mysql-bin.000309
Read_Master_Log_Pos: 858757740
Relay_Log_File: tulwaurt009-relay-bin.000002
Relay_Log_Pos: 791
Relay_Master_Log_File: tulwaurt005-mysql-bin.000309
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table: xxx.feed_bettordata_data,xxx_docs.session,xxx_docs.session,xxx.feed_bettordata_data
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1032
Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938
Skip_Counter: 0
Exec_Master_Log_Pos: 840720516
Relay_Log_Space: 15772314
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: 1032
Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938
Replicate_Ignore_Server_Ids:
Master_Server_Id: 20076
Master_SSL_Crl:
Master_SSL_Crlpath:
Using_Gtid: Slave_Pos
Gtid_IO_Pos: 3-20076-17655,0-20076-42465645
on 005 master
mysqlbinlog /u01/mariadb-10/tulwaurt005-mysql-bin.000309 --start-position 840720516 | 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
#150408 23:36:17 server id 20076 end_log_pos 248 Start: binlog v 4, server v 10.0.17-MariaDB-log created 150408 23:36:17
BINLOG '
2TUlVQ9sTgAA9AAAAPgAAAAAAAQAMTAuMC4xNy1NYXJpYURCLWxvZwAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA3AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQAC2l+iA==
'/*!*/;
# at 840720516
#150409 9:08:10 server id 20076 end_log_pos 840720554 GTID 0-20076-42437721
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=20076*//*!*/;
/*!100001 SET @@session.gtid_seq_no=42437721*//*!*/;
BEGIN
/*!*/;
# at 840720554
# at 840720780
# at 840720854
#150409 9:08:10 server id 20076 end_log_pos 840720780 Annotate_rows:
#Q> /*wp_r4 (MASTER)*/UPDATE data_source_prices
#Q> SET
#Q> price = '23.8',
#Q> last_updated = NOW()
#Q> WHERE
#Q> market_selection_details_id = '6379754' AND
#Q> bet_type = '1' AND
#Q> data_source_i
#150409 9:08:10 server id 20076 end_log_pos 840720854 Table_map: `xxx_20150210`.`data_source_prices` mapped to number
19326
#150409 9:08:10 server id 20076 end_log_pos 840720938 Update_rows: table id 19326 flags: STMT_END_F
BINLOG '
4rslVRNsTgAASgAAANZhHDIAAH5LAAAAAAEAD2x1eGJldF8yMDE1MDIxMAASZGF0YV9zb3VyY2Vf
cHJpY2VzAAUDAwP2DAIMAhA=
4rslVRhsTgAAVAAAACpiHDIAAH5LAAAAAAEABf//4OpYYQABAAAACQAAAIAAAAAXPKPW+aFTEgAA
4OpYYQABAAAACQAAAIAAAAAXUPrW+aFTEgAA
'/*!*/;
# at 840720938
#150409 9:08:10 server id 20076 end_log_pos 840720965 Xid = 411642227
COMMIT/*!*/;
# at 840720965
#150409 9:08:10 server id 20076 end_log_pos 840721003 GTID 0-20076-42437722
/*!100001 SET @@session.gtid_seq_no=42437722*//*!*/;
BEGIN
/*!*/;
# at 840721003
# at 840721222
# at 840721304
#150409 9:08:10 server id 20076 end_log_pos 840721222 Annotate_rows:
#Q> /*wp_r4 (MASTER)*/INSERT INTO data_source_prices_history (`market_selection_details_id`,`bet_type`,`data_source_id`,`price`,`
last_updated`) VALUES ('6379755', '1', '9', '3.20', '2015-04-09 09:07:23')
#150409 9:08:10 server id 20076 end_log_pos 840721304 Table_map: `xxx_20150210`.`data_source_prices_history` mapped t
o number 21912
#150409 9:08:10 server id 20076 end_log_pos 840721360 Write_rows: table id 21912 flags: STMT_END_F
BINLOG '
4rslVRNsTgAAUgAAAJhjHDIAAJhVAAAAAAEAD2x1eGJldF8yMDE1MDIxMAAaZGF0YV9zb3VyY2Vf
cHJpY2VzX2hpc3RvcnkABQMDA/YMAgwCEA==
4rslVRdsTgAAOAAAANBjHDIAAJhVAAAAAAEABf/g61hhAAEAAAAJAAAAgAAAAAMUo9b5oVMSAAA=
'/*!*/;
# at 840721360
#150409 9:08:10 server id 20076 end_log_pos 840721387 Xid = 411642228
COMMIT/*!*/;
# at 840721387
#150409 9:08:10 server id 20076 end_log_pos 840721425 GTID 0-20076-42437723
/*!100001 SET @@session.gtid_seq_no=42437723*//*!*/;
BEGIN
/*!*/;
# at 840721425
# at 840721650
# at 840721724
#150409 9:08:10 server id 20076 end_log_pos 840721650 Annotate_rows:
#Q> /*wp_r4 (MASTER)*/UPDATE data_source_prices
#Q> SET
#Q> price = '3.3',
#Q> last_updated = NOW()
#Q> WHERE
#Q> market_selection_details_id = '6379755' AND
#Q> bet_type = '1' AND
#Q> data_source_i
#150409 9:08:10 server id 20076 end_log_pos 840721724 Table_map: `xxx_20150210`.`data_source_prices` mapped to number
19326
#150409 9:08:10 server id 20076 end_log_pos 840721808 Update_rows: table id 19326 flags: STMT_END_F
BINLOG '
4rslVRNsTgAASgAAADxlHDIAAH5LAAAAAAEAD2x1eGJldF8yMDE1MDIxMAASZGF0YV9zb3VyY2Vf
cHJpY2VzAAUDAwP2DAIMAhA=
4rslVRhsTgAAVAAAAJBlHDIAAH5LAAAAAAEABf//4OtYYQABAAAACQAAAIAAAAADFKPW+aFTEgAA
4OtYYQABAAAACQAAAIAAAAADHvrW+aFTEgAA
'/*!*/;
# at 840721808
#150409 9:08:10 server id 20076 end_log_pos 840721835 Xid = 411642229
COMMIT/*!*/;
# at 840721835
#150409 9:08:10 server id 20076 end_log_pos 840721873 GTID 0-20076-42437724
set global slave_parallel_threads=0; start slave;
MariaDB [(none)]> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 172.16.194.76
Master_User: repl
Master_Port: 3310
Connect_Retry: 60
Master_Log_File: tulwaurt005-mysql-bin.000325
Read_Master_Log_Pos: 447467956
Relay_Log_File: tulwaurt009-relay-bin.000002
Relay_Log_Pos: 791
Relay_Master_Log_File: tulwaurt005-mysql-bin.000309
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table: xxx.feed_bettordata_data,xxx_docs.session,xxx_docs.session,xxx.feed_bettordata_data
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1032
Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938
Skip_Counter: 0
Exec_Master_Log_Pos: 840720516
Relay_Log_Space: 13110413617
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: 1032
Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938
Replicate_Ignore_Server_Ids:
Master_Server_Id: 20076
Master_SSL_Crl:
Master_SSL_Crlpath:
Using_Gtid: Slave_Pos
Gtid_IO_Pos: 3-20076-44284,0-20076-65091365
Gliffy Diagrams
Attachments
Issue Links
- relates to
-
- Closed
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
copyied master TZ file to slave and restarted mysql - no change.
Hi Daniel,
So, as I understand there are three issues here:
1) the initial failure, mismatch on the datetime value, which looks suspiciously related to the TZ difference;
2) a problem with error handling during parallel replication – even though there was an SQL error, the SQL thread is still kind of running, but the replication is not moving forward;
3) a problem with stopping the slave after that.
Regarding (2):
I remember things like that happened and were fixed before, apparently some cases still remain. I'll see if I can reproduce it.
Regarding (3):
Maybe it's a consequence of (2) – hopefully if I can reproduce (2), (3) will also become apparent...
Regarding (1):
AFAIK, DATETIME shouldn't depend on the timezone. The only "legal" scenario I can think of for this issue to happen is this:
- once upon a time, the table had the TIMESTAMP field on master and slave;
- '2015-04-09 09:07:23' was inserted into the table on the master, and converted into '2015-04-08 23:37:23' on the slave;
- then the table was ALTERed, the column type was switched from TIMESTAMP to DATETIME both on master and slave;
- then the day X came, when UPDATE was issued.
Is it in any way possible?
Regarding (1):
AFAIK, DATETIME shouldn't depend on the timezone.
I was assuming that too.
The only "legal" scenario I can think of for this issue to happen is this:
once upon a time, the table had the TIMESTAMP field on master and slave;
'2015-04-09 09:07:23' was inserted into the table on the master, and converted into '2015-04-08 23:37:23' on the slave;
then the table was ALTERed, the column type was switched from TIMESTAMP to DATETIME both on master and slave;
then the day X came, when UPDATE was issued.
Nope. Test server was set up a few weeks ago. This field was always a DATETIME.
Daniel Black,
Has it ever happened again? I mean the initial failure, with datetime values.
Alexander Barkov, Kristian Nielsen,
As experts in time values and replication, can you think of any scenario that could cause such a problem?
no it hasn't happened again. I did correct the TZ difference as above.
Temporarily assigning to Alexander Barkov to see if he has any ideas on what can cause such a problem.
2015-04-09 09:07:23 from the binlogs and 2015-04-08 23:37:23 in the table.
master:
Yes this is a GMT+9.5 timezone.
All other ACST timezone slaves survived.
slave:
corrected:
| system_time_zone | CST | | time_zone | SYSTEM | select @@gtid_slave_pos,@@gtid_current_pos; show slave status\G +--------------------------------+--------------------------------+ | 3-20076-17655,0-20076-42437720 | 3-20076-17655,0-20076-42437720 | +--------------------------------+--------------------------------+ 1 row in set (0.00 sec) *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 172.16.194.76 Master_User: repl Master_Port: 3310 Connect_Retry: 60 Master_Log_File: tulwaurt005-mysql-bin.000325 Read_Master_Log_Pos: 613876281 Relay_Log_File: tulwaurt009-relay-bin.000002 Relay_Log_Pos: 791 Relay_Master_Log_File: tulwaurt005-mysql-bin.000309 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: Replicate_Wild_Ignore_Table: Last_Errno: 1032 Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938 Skip_Counter: 0 Exec_Master_Log_Pos: 840720516 Relay_Log_Space: 13241702405 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: 784 Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 1032 Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938 Replicate_Ignore_Server_Ids: Master_Server_Id: 20076 Master_SSL_Crl: Master_SSL_Crlpath: Using_Gtid: Slave_Pos Gtid_IO_Pos: 3-20076-44284,0-20076-65300701sql thread still not moving gtid slave/current position despite running.
Is an identical TZ name essential for some reason (Master ACST != Slave CST)
[root@tulwaurt005 openquery]# cat /usr/share/zoneinfo/Australia/Darwin TZif2 �N����'��T��^x̷]�ͧ@xΠχ"x����ACDTACSTTZif2 ����s�X����{p�����N��������'������T������^x����̷]�����ͧ@x����Π����χ"xz�~��� ��LMTACSTACDT ACST-9:30 [root@tulwaurt009 etc]# ls -la /usr/share/zoneinfo/Australia/Darwin -rw-r--r--. 2 root root 288 Oct 3 2013 /usr/share/zoneinfo/Australia/Darwin [root@tulwaurt009 etc]# cat /usr/share/zoneinfo/Australia/Darwin TZif�N����'��T��^x̷]�ͧ@xΠχ"x����CSTTZif2 ����s�X����{p�����N��������'������T������^x����̷]�����ͧ@x����Π����χ"xz�~�����LMTCST CST-9:30