MySQL Bugs: #55508: Replication is NOT HAPPENING Properly

Bug #55508	Replication is NOT HAPPENING Properly
Submitted:	23 Jul 2010 12:18	Modified:	26 Aug 2010 7:52
Reporter:	Anil Alpati	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S2 (Serious)
Version:	5.1.45	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
100723 17:39:35 [ERROR] Slave SQL: Could not execute Delete_rows event on table dbschema.tablename; Can't find record in 'tablename', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 19147446, Error_code: 1032

Above is the error I am getting in MySQL Replication.

The problem is replication stops when ever i get this error and after  that I need to get end log position number and go further.

As of All the informations in database are proper. I don't know how it breaks

Kindly give your feed back on this. 

"Can't find record in "tablename" - IRRITATING THIS ERROR ON EVERY COMMITs

Thanks in advance

How to repeat:
100723 17:39:35 [ERROR] Slave SQL: Could not execute Delete_rows event on table dbschema.tablename; Can't find record in 'tablename', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 19147446, Error_code: 1032

Please, find out from the binary log the exact statement failing. Is it possible that you change data on the slave by some local statements?

Please, find out from the binary log the exact statement failing. Is it
possible that you change data on the slave by some local statements?

DELETE &  UPDATE STATEMENT ARE FAILING

Description:
100723 17:39:35 [ERROR] Slave SQL: Could not execute Delete_rows event
on table dbschema.tablename; Can't find record in 'tablename',
Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's
master log FIRST, end_log_pos 19147446, Error_code: 1032

NO - I HAVE NOT DONE ANY MANUAL UPDATE IN SLAVE MACHINE. EXCEPT RUNNING BINARY FILES.

I need exact statements, with table names and WHERE clauses. Then I'll ask you to check for corresponding rows on slave, for the results of SHOW CREATE TABLE and SHOW TABLE STATUS statements for the tables involved, to begin with. We need a lot of information to find out where the bug is, if any.

Surely if you have a 100% repeatable test case to upload (file with SQL statements to run on clean master to get this error on slave), please, just present it.

Below are the information as requested -

STATUS

mysql>  SHOW TABLE STATUS LIKE 'journal' \G
*************************** 1. row ***************************
           Name: journal
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 183639
 Avg_row_length: 299
    Data_length: 55066624
Max_data_length: 0
   Index_length: 0
      Data_free: 4194304
 Auto_increment: NULL
    Create_time: 2010-06-06 07:06:27
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options: 
        Comment: 
1 row in set (0.12 sec)

CREATE TABLE -

CREATE TABLE `journal` (
  `DeptId` varchar(10) NOT NULL DEFAULT '',
  `TransactionDate` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
  `VoucherNo` varchar(15) NOT NULL DEFAULT '',
  `AccountCode` varchar(10) NOT NULL DEFAULT '',
  `TransactionType` varchar(2) NOT NULL DEFAULT '',
  `Debit` decimal(10,2) DEFAULT NULL,
  `Credit` decimal(10,2) DEFAULT NULL,
  `Narration` text,
  `VoucherType` varchar(10) DEFAULT NULL,
  `Reference` varchar(10) DEFAULT NULL,
  `DetailNaration` text,
  `UserID` varchar(1) DEFAULT NULL,
  `UserName` varchar(15) DEFAULT NULL,
  `RecordDate` datetime DEFAULT NULL,
  `Insertable` varchar(1) DEFAULT NULL,
  PRIMARY KEY (`DeptId`,`TransactionDate`,`VoucherNo`,`AccountCode`,`TransactionType`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

DELETE STATEMENTS FROM BINLOG

#100720 17:55:19 server id 1  end_log_pos 19171481 	Query	thread_id=217134	exec_time=0	error_code=0
SET TIMESTAMP=1279628719/*!*/;
BEGIN
/*!*/;
# at 19171481
# at 19171572
#100720 17:55:19 server id 1  end_log_pos 19171572 	Table_map: `microfindb`.`journal` mapped to number 58
#100720 17:55:19 server id 1  end_log_pos 19171934 	Delete_rows: table id 58 flags: STMT_END_F

BINLOG '
r5VFTBMBAAAAWwAAAPSIJAEAADoAAAAAAAAACm1pY3JvZmluZGIAB2pvdXJuYWwADw8MDw8P9vb8
Dw/8Dw8MDxgeAC0AHgAGAAoCCgICHgAeAAIDAC0AAwDgfw==
r5VFTBkBAAAAagEAAF6KJAEQADoAAAAAAAEAD///AIAFMDE6NznAMPoPSBIAAAVWMDQwNQQyMDEy
AkRygAAAVACAAAAAAC8AQmVpbmcgdGhlIGFtb3VudCAgcGFpZCB0byBDT3MgQXBwbGNpYXRpb24g
WGVyb3gEQ2FzaAAvAEJlaW5nIHRoZSBhbW91bnQgIHBhaWQgdG8gQ09zIEFwcGxjaWF0aW9uIFhl
cm94ATQKQWNjb3VudGFudMA5NxBIEgAAAACABTAxOjc5wDD6D0gSAAAFVjA0MDUENjAwMQJDcoAA
AAAAgAAAVAAvAEJlaW5nIHRoZSBhbW91bnQgIHBhaWQgdG8gQ09zIEFwcGxjaWF0aW9uIFhlcm94
BENhc2gALwBCZWluZyB0aGUgYW1vdW50ICBwYWlkIHRvIENPcyBBcHBsY2lhdGlvbiBYZXJveAE0
CkFjY291bnRhbnTAOTcQSBIAAAA=
'/*!*/;
### DELETE FROM microfindb.journal
### WHERE
###   @1='01:79'
###   @2=2010-07-15 00:00:00
###   @3='V0405'
###   @4='2012'
###   @5='Dr'
###   @6=000000084.000000000
###   @7=000000000
###   @8='Being the amount  paid to COs Applciation Xerox'
###   @9='Cash'
###   @10=''
###   @11='Being the amount  paid to COs Applciation Xerox'
###   @12='4'
###   @13='Accountant'
###   @14=2010-07-19 00:00:00
###   @15=''
### DELETE FROM microfindb.journal
### WHERE
###   @1='01:79'
###   @2=2010-07-15 00:00:00
###   @3='V0405'
###   @4='6001'
###   @5='Cr'
###   @6=000000000
###   @7=000000084.000000000
###   @8='Being the amount  paid to COs Applciation Xerox'
###   @9='Cash'
###   @10=''
###   @11='Being the amount  paid to COs Applciation Xerox'
###   @12='4'
###   @13='Accountant'
###   @14=2010-07-19 00:00:00
###   @15=''
# at 19171934
#100720 17:55:19 server id 1  end_log_pos 19171961 	Xid = 545505490
COMMIT/*!*/;
# at 19171961

Please, send the results of:

select count(*) from microfindb.journal
where `DeptId` = '01:79'
and `TransactionDate` = '2010-07-15 00:00:00'
and `VoucherNo` = 'V0405'
and `AccountCode` = '2012'
and `TransactionType` = 'Dr'; 

select count(*) from microfindb.journal
where `DeptId` = '01:79'
and `TransactionDate` = '2010-07-15 00:00:00'
and `VoucherNo` = 'V0405'
and `AccountCode` = '6001'
and `TransactionType` = 'Cr'; 

show slave status\G

from slave. 

Also, if previous SHOW TABLE STATUS results were from master (as I assume), please, send the results of the same statement from slave.

The OUTPUTS of two queries which you given are below -

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 440489
Server version: 5.1.45-community MySQL Community Server (GPL)

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select count(*) from microfindb.journal
    -> where `DeptId` = '01:79'
    -> and `TransactionDate` = '2010-07-15 00:00:00'
    -> and `VoucherNo` = 'V0405'
    -> and `AccountCode` = '2012'
    -> and `TransactionType` = 'Dr';
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)

mysql> 
mysql> select count(*) from microfindb.journal
    -> where `DeptId` = '01:79'
    -> and `TransactionDate` = '2010-07-15 00:00:00'
    -> and `VoucherNo` = 'V0405'
    -> and `AccountCode` = '6001'
    -> and `TransactionType` = 'Cr';
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)

mysql> 

------------------------------------------------------

As I sent TABLES STATUS YESTERDAY is of SLAVE SERVER.

BELOW IS THE TABLES STATUS of MASTER SLAVE 
mysql> SHOW TABLE STATUS LIKE 'journal' \G
*************************** 1. row ***************************
           Name: journal
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 168330
 Avg_row_length: 339
    Data_length: 57098240
Max_data_length: 0
   Index_length: 0
      Data_free: 6291456
 Auto_increment: NULL
    Create_time: 2010-06-06 05:39:38
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options: 
        Comment: 
1 row in set (0.16 sec)

Kindly response your feedback ASAP.

So, you do not have corresponding rows on slave, hence the error message. 

Also tables are notably different now. This is what we have on master:

           Rows: 168330
 Avg_row_length: 339
    Data_length: 57098240
Max_data_length: 0
   Index_length: 0
      Data_free: 6291456
 Auto_increment: NULL
    Create_time: 2010-06-06 05:39:38

and this is on slave:

           Rows: 183639
 Avg_row_length: 299
    Data_length: 55066624
Max_data_length: 0
   Index_length: 0
      Data_free: 4194304
 Auto_increment: NULL
    Create_time: 2010-06-06 07:06:27

Looks like you may have to set up replication from the beginning.

Now about possible reasons. We have similar bug #51501 that is not yet fixed. Is it possible that your applications use CREATE TABLE IF NOT EXISTS, CREATE TABLE ... SELECT (see bug #47899 also) or REPLACE INTO statements?

Since database size is huge. Its around 150 GB.

Its takes more time to make new setUp. 

Please give other solution to fix this ? Seting Up NEWLY is not final solution for fix

Sorry, but here we discuss bugs in MySQL code, not good ways to solve your replication problems. This is not a free support site for you.

As you can conclude from my previous comment, I suspect your problem was a result of a known bug that is already fixed. But I am not sure, and I need either complete repeatable test case from you, or results of your testing with 5.1.49, or at least answers to my questions to find out is it that older known bug or something else, new bug for example.

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".