Bug #18245 Slave executes query from old binlog following master binlog rotation
Submitted: 15 Mar 2006 2:23 Modified: 23 Apr 2006 16:05
Reporter: Duke Ionescu Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:4.1.16 OS:Linux (Linux)
Assigned to: CPU Architecture:Any

[15 Mar 2006 2:23] Duke Ionescu 
Description:
2 servers, both 4.1.16, 1 master, 1 slave.  Slave is read-only=1 (in my.cnf).

Following rotation of binlog on master, slave fails on a query from an old binlog on master.

As can be seen below, the master (mysql1) rotates from binlog mysql1-bin.000012 to mysql1-bin.000013 around 1:18:41.  11 seconds later, slave (mysql2) errors out with 'Duplicate entry' on a query that comes from mysql1-bin.000002 (verified with a dump -- see below).

Ex:
master:
mysql1 data # ll --full-time mysql1-bin.*
-rw-rw----  1 mysql mysql      92030 2006-01-14 00:21:15.000000000 -0500 mysql1-bin.000001
-rw-rw----  1 mysql mysql 1073741895 2006-01-19 15:08:02.000000000 -0500 mysql1-bin.000002
-rw-rw----  1 mysql mysql 1073742062 2006-01-25 08:03:35.000000000 -0500 mysql1-bin.000003
-rw-rw----  1 mysql mysql 1073741978 2006-01-30 16:32:09.000000000 -0500 mysql1-bin.000004
-rw-rw----  1 mysql mysql 1073742163 2006-02-04 01:17:30.000000000 -0500 mysql1-bin.000005
-rw-rw----  1 mysql mysql 1073742046 2006-02-09 14:12:55.000000000 -0500 mysql1-bin.000006
-rw-rw----  1 mysql mysql 1073741868 2006-02-15 07:11:08.000000000 -0500 mysql1-bin.000007
-rw-rw----  1 mysql mysql 1073741888 2006-02-20 23:42:05.000000000 -0500 mysql1-bin.000008
-rw-rw----  1 mysql mysql 1073741877 2006-02-25 23:59:47.000000000 -0500 mysql1-bin.000009
-rw-rw----  1 mysql mysql 1073741894 2006-03-03 02:00:36.000000000 -0500 mysql1-bin.000010
-rw-rw----  1 mysql mysql 1073742222 2006-03-08 12:59:37.000000000 -0500 mysql1-bin.000011
-rw-rw----  1 mysql mysql 1073741940 2006-03-14 01:18:41.416537375 -0500 mysql1-bin.000012
-rw-rw----  1 mysql mysql  202266019 2006-03-14 20:44:23.687135005 -0500 mysql1-bin.000013
-rw-rw----  1 mysql mysql       1540 2006-03-14 01:18:41.532508958 -0500 mysql1-bin.index

mysql1 data # /usr/local/mysql/bin/mysqlbinlog --start-position=10570 --stop-position=10571 mysql1-bin.000002   
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
# at 10570
#060114  0:31:24 server id 1  log_pos 10570     Query   thread_id=119   exec_time=0     error_code=0
use spamassassin;
SET TIMESTAMP=1137216684;
INSERT INTO awl (username,email,ip,count,totscore) VALUES ('root','masked@domain.tld','241.38','1','7.874');

slave:
mysql2 data # ll --full-time mysql2*
-rw-rw----    1 mysql    mysql    1073741899 2006-03-14 01:22:38.000000000 -0500 mysql2-relay-bin.000013
-rw-rw----    1 mysql    mysql    1073741984 2006-03-14 01:25:29.000000000 -0500 mysql2-relay-bin.000014
-rw-rw----    1 mysql    mysql    1073741920 2006-03-14 01:28:29.000000000 -0500 mysql2-relay-bin.000015
-rw-rw----    1 mysql    mysql    1073742200 2006-03-14 01:31:13.000000000 -0500 mysql2-relay-bin.000016
-rw-rw----    1 mysql    mysql    1073742080 2006-03-14 01:34:03.000000000 -0500 mysql2-relay-bin.000017
-rw-rw----    1 mysql    mysql    1073741830 2006-03-14 01:36:44.110637058 -0500 mysql2-relay-bin.000018
-rw-rw----    1 mysql    mysql    1073742199 2006-03-14 01:39:26.957392435 -0500 mysql2-relay-bin.000019
-rw-rw----    1 mysql    mysql    1073742114 2006-03-14 01:42:42.679634714 -0500 mysql2-relay-bin.000020
-rw-rw----    1 mysql    mysql    1073742195 2006-03-14 01:45:50.234744506 -0500 mysql2-relay-bin.000021
-rw-rw----    1 mysql    mysql    1073742234 2006-03-14 01:48:40.000000000 -0500 mysql2-relay-bin.000022
-rw-rw----    1 mysql    mysql    1073741923 2006-03-14 01:51:22.990656390 -0500 mysql2-relay-bin.000023
-rw-rw----    1 mysql    mysql    69087022 2006-03-14 10:54:51.560374922 -0500 mysql2-relay-bin.000024
-rw-rw----    1 mysql    mysql         312 2006-03-14 01:51:23.024648618 -0500 mysql2-relay-bin.index

slave error-log:
060314  1:18:52 [ERROR] Slave: Error 'Duplicate entry 'root-masked@domain.tld-241.38' for key 1' on query. Default database: 'spamassassin'. Query: 'INSERT INTO awl (username,email,ip,count,totscore) VALUES ('root','masked@domain.tld','241.38','1','7.874')', Error_code: 1062
060314  1:18:52 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql1-bin.000002' position 10570

slave relay log:
#060314  1:18:41 server id 1  log_pos 1073741475 	Query	thread_id=6668501	exec_time=0	error_code=0
SET TIMESTAMP=1142317121;
INSERT INTO bayes_token
               (id, token, spam_count, ham_count, atime)
               VALUES ('1','‡Ûè·š','0','1','1142317101')
               ON DUPLICATE KEY UPDATE spam_count = GREATEST(spam_count + '0', 0),
                                       ham_count = GREATEST(ham_count + '1', 0),
                                       atime = GREATEST(atime, '1142317101');
# at 92234
#060314  1:18:41 server id 1  log_pos 1073741896 	Rotate to mysql1-bin.000013  pos: 4
# at 92278
#691231 19:00:00 server id 1  log_pos 0 	Rotate to mysql1-bin.000013  pos: 4
# at 92322
#060314  1:18:41 server id 1  log_pos 4 	Query	thread_id=6668501	exec_time=0	error_code=0
SET TIMESTAMP=1142317121;
INSERT INTO bayes_token
               (id, token, spam_count, ham_count, atime)
               VALUES ('1','‘D|´Å','0','1','1142317101')
               ON DUPLICATE KEY UPDATE spam_count = GREATEST(spam_count + '0', 0),
                                       ham_count = GREATEST(ham_count + '1', 0),
                                       atime = GREATEST(atime, '1142317101');

How to repeat:
Unknown.

Suggested fix:
n/a
[23 Mar 2006 16:05] Valeriy Kravchuk 
Thank you for a problem report. Are you sure your .index files are OK? Anyway, try to use newer version, 4.1.18, and reopen this report if you'll see similar problem with it.
[23 Apr 2006 23:00] Bugs System 
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".