Bug #68228 BINLOG statement failing in mixed log format
Submitted: 30 Jan 2013 21:37 Modified: 1 Mar 2013 8:37
Reporter: Jeff Smelser Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.1.66 OS:Linux (Red Hat Enterprise Linux Server release 6.3 (Santiago))
Assigned to: CPU Architecture:Any
Tags: mixedlog, replication

[30 Jan 2013 21:37] Jeff Smelser
Description:
We are running a mixed log format for replication and replication errors with:

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: proddb01.atl14.rightsflow.int
                  Master_User: replication
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.004080
          Read_Master_Log_Pos: 74043
               Relay_Log_File: mysqld-relay-bin.000770
                Relay_Log_Pos: 374545
        Relay_Master_Log_File: mysql-bin.004078
             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: 1032
                   Last_Error: Could not execute Update_rows event on table pub_data_housing.ULTRA_CMS_4; Can't find record in 'ULTRA_CMS_4', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log mysql-bin.004078, end_log_pos 375585
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 374400
              Relay_Log_Space: 1131532347
              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 event on table pub_data_housing.ULTRA_CMS_4; Can't find record in 'ULTRA_CMS_4', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log mysql-bin.004078, end_log_pos 375585

That table is ok:
mysql> check table pub_data_housing.ULTRA_CMS_4;
+------------------------------+-------+----------+----------+
| Table                        | Op    | Msg_type | Msg_text |
+------------------------------+-------+----------+----------+
| pub_data_housing.ULTRA_CMS_4 | check | status   | OK       |
+------------------------------+-------+----------+----------+
1 row in set (0.08 sec)

How to repeat:
We just re-run the log
[30 Jan 2013 21:38] Jeff Smelser
HEre is the log section:

[jsmelser@proddb03 /data/mysql/databases]$ sudo mysqlbinlog mysqld-relay-bin.000770 --start-position=374545| more
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130124 13:36:18 server id 3  end_log_pos 106   Start: binlog v 4, server v 5.1.66-log created 130124 13:36:18
BINLOG '
Mo0BUQ8DAAAAZgAAAGoAAAAAAAQANS4xLjY2LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 149
#130130 13:33:01 server id 1  end_log_pos 106   Start: binlog v 4, server v 5.1.66-log created 130130 13:33:01
BINLOG '
bXUJUQ8BAAAAZgAAAGoAAAAAAAQANS4xLjY2LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 374545
#130130 13:54:22 server id 1  end_log_pos 374480        Query   thread_id=27849 exec_time=0     error_code=0
SET TIMESTAMP=1359575662/*!*/;
SET @@session.pseudo_thread_id=27849/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 374625
# at 374748
#130130 13:54:22 server id 1  end_log_pos 374603        Table_map: `pub_data_housing`.`ULTRA_CMS_4` mapped to number 1960
#130130 13:54:22 server id 1  end_log_pos 375585        Update_rows: table id 1960 flags: STMT_END_F

BINLOG '
bnoJURMBAAAAewAAAEu3BQAAAKgHAAAAAAEAEHB1Yl9kYXRhX2hvdXNpbmcAC1VMVFJBX0NNU180
ABQPDw8PDw8PDw8PDw8PDw8PDw8PDyj9Av0C/QL9Av0CAgQCBP0C/QL9Av0C/QL9Av0C/QL9Av0C
/QL9Av0C//8P
bnoJURgBAAAA1gMAACG7BQAAAKgHAAAAAAEAFP///////wAA8AUARElZXzcQAFNleCBPbiBUaGUg
QmVhY2gIAFNwYW5rZXJzOABUb21hbW9zIEVuIExhIFBsYXlhCihTZXggT24gVGhlIEJlYWNoIC0g
U3BhbmlzaCBWZXJzaW9uKQ4AVWx0cmEgUmVjb3JkcyAOACwsLCwsLCwsLCwsLCwstQBJVEExNzA5
MDAyNjMsSVRBMTcwOTAwMjU5LElUQTE3MDkwMDI1OCxJVEExNzA5MDAyNjEsSVRBMTcwOTAwMjYy
LElUQTE3MDkwMDI2MCxJVEExNzA5MDAyNTcsSVRBMTcwOTAwMDk1LElUQTE3MTEwMDA4MyxJVEEx
NzExMDAwODQsQVVYTDMxMDAwMDQ3LElUQTE3MDkwMDA5OCxJVEExNzA5MDAwOTksQ0FEQzQwOTAz
MzA4AABXAEpvaG4gTWljaGFlbCBCaWFuY2FsZSwgTHVjYSBEZSBHcmVnb3JpbywgTWF1cml6aW8g
VmVyc2luaSwgUGFvbG8gT3J0ZWxsaSwgQmFyYmFyYSBDbGFyYSYAVWx0cmEgVHVuZXMgKEFTQ0FQ
KSBhL2MgRG8gSXQgWW91cnNlbGYDADEwMAMAMTAwDQBVbml0ZWQgU3RhdGVzAAAAAAAAAAAAAAAA
AAAAAPAFAERJWV83EABTZXggT24gVGhlIEJlYWNoCABTcGFua2VyczgAVG9tYW1vcyBFbiBMYSBQ
bGF5YQooU2V4IE9uIFRoZSBCZWFjaCAtIFNwYW5pc2ggVmVyc2lvbikOAFVsdHJhIFJlY29yZHMg
AAC1AElUQTE3MDkwMDI2MyxJVEExNzA5MDAyNTksSVRBMTcwOTAwMjU4LElUQTE3MDkwMDI2MSxJ
VEExNzA5MDAyNjIsSVRBMTcwOTAwMjYwLElUQTE3MDkwMDI1NyxJVEExNzA5MDAwOTUsSVRBMTcx
MTAwMDgzLElUQTE3MTEwMDA4NCxBVVhMMzEwMDAwNDcsSVRBMTcwOTAwMDk4LElUQTE3MDkwMDA5
OSxDQURDNDA5MDMzMDgAAFcASm9obiBNaWNoYWVsIEJpYW5jYWxlLCBMdWNhIERlIEdyZWdvcmlv
LCBNYXVyaXppbyBWZXJzaW5pLCBQYW9sbyBPcnRlbGxpLCBCYXJiYXJhIENsYXJhJgBVbHRyYSBU
dW5lcyAoQVNDQVApIGEvYyBEbyBJdCBZb3Vyc2VsZgMAMTAwAwAxMDANAFVuaXRlZCBTdGF0ZXMA
AAAAAAAAAAAAAAAAAA==
'/*!*/;
# at 375730
#130130 13:54:22 server id 1  end_log_pos 375612        Xid = 1192313
COMMIT/*!*/;
# at 375757
[1 Feb 2013 8:37] MySQL Verification Team
Can you check exactly what row it was updating?  You'll need to run mysqlbinlog with extra options: "--base64-output=decode-rows --verbose".

Then check if that row is really  there are not.
[2 Mar 2013 1: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".