[MDEV-7315] Error in Log_event::read_log_event for mysql binlogs Created: 2014-12-13  Updated: 2022-09-08

Status: Open
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 5.5.40, 10.0
Fix Version/s: 10.1

Type: Bug Priority: Major
Reporter: Z Toth Assignee: Kristian Nielsen
Resolution: Unresolved Votes: 0
Labels: replication, upstream-fixed
Environment:

Ubuntu 12.04 64 bit,
3.13.0-40-generic #69~precise1-Ubuntu SMP Fri Nov 14 10:29:31 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux


 Description   

Slave: MariaDB, 5.5.40-tokudb-7.5.3-MariaDB-log MariaDB Server
Master: MySQL, Server version: 5.5.30-ndb-7.2.12-log Source distribution

When the replication is started, it stops with the error:

 Last_SQL_Errno: 1594
 
 Last_SQL_Error: Relay log read failure: Could not parse relay log event entry....

Looking at the binlog file copied from the master, the MariaDB mysqlbinlog says:
mysqlbinlog -vv -H log-bin.000001

ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 61, event_type: 30
 
ERROR: Could not read entry at offset 3554: Error in log format or read error.

Therefore, mariadb's mysqlbinlog stops before 3554:

SET TIMESTAMP=1417540710/*!*/;
 
BEGIN
 
/*!*/;
 
# at 3248
 
# at 3365
 
# at 3429
 
# at 3492
 
DELIMITER ;
 
# End of log file
 
ROLLBACK /* added by mysqlbinlog */;
 
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
 
<EOF>

Looking at the same file on the master with the MySQL version of mysqlbinlog, I can see the contents with no problem:

 SET TIMESTAMP=1417540710/*!*/;
 
BEGIN
 
/*!*/;
 
# at 3248
 
# at 3365
 
# at 3429
 
# at 3492
 
# at 3554
 
# at 3615
 
# at 3944
 
# at 4108
 
# at 4274
 
# at 4339
 
# at 4379
 
# at 4440
 
# at 4480
 
# at 4541
 
# at 4581
 
# at 4777
 
#141202 18:18:30 server id 11901  end_log_pos 3365 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#      cb0 66 f4 7d 54   13   7d 2e 00 00   75 00 00 00   25 0d 00 00   80 00
 
#      cc3 f5 00 00 00 00 00 01 00  0e 63 75 64 62 5f 75 73 |.........cudb.us|
 
#      cd3 65 72 5f 64 61 74 61 00  07 43 55 44 42 5f 44 4e |er.data..CUDB.DN|
 
#      ce3 00 18 0f 0f 0f 0f 0f 0f  0f 0f 0f 0f 0f 0f 0f 0f |................|
 
#      cf3 08 0f 01 01 01 07 07 0f  0f 0f 24 f0 00 f0 00 f0 |................|
 
#      d03 00 f0 00 f0 00 f0 00 f0  00 f0 00 f0 00 f0 00 f0 |................|
 
#      d13 00 f0 00 90 01 58 02 00  06 2d 00 2d 00 2d 00 00 |.....X..........|
 
#      d23 20 f8  |..|
 
#       Table_map: `cudb_user_data`.`CUDB_DN` mapped to number 245
 
#141202 18:18:30 server id 11901  end_log_pos 3429 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#      d25 66 f4 7d 54   13   7d 2e 00 00   40 00 00 00   65 0d 00 00   80 00
 
#      d38 3b 01 00 00 00 00 01 00  0e 63 75 64 62 5f 75 73 |.........cudb.us|
 
#      d48 65 72 5f 64 61 74 61 00  0c 43 55 44 42 64 63 4f |er.data..CUDBdcO|
 
#      d58 62 6a 65 63 74 00 02 08  0f 02 ff 00 00  |bject........|
 
#       Table_map: `cudb_user_data`.`CUDBdcObject` mapped to number 315
 
#141202 18:18:30 server id 11901  end_log_pos 3492 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#      d65 66 f4 7d 54   13   7d 2e 00 00   3f 00 00 00   a4 0d 00 00   80 00
 
#      d78 b9 01 00 00 00 00 01 00  0e 63 75 64 62 5f 75 73 |.........cudb.us|
 
#      d88 65 72 5f 64 61 74 61 00  0b 43 55 44 42 53 65 72 |er.data..CUDBSer|
 
#      d98 76 69 63 65 00 02 08 0f  02 20 00 00  |vice........|
 
#       Table_map: `cudb_user_data`.`CUDBService` mapped to number 441
 
#141202 18:18:30 server id 11901  end_log_pos 3554



 Comments   
Comment by Elena Stepanova [ 2014-12-15 ]

Hi,
Would you be able to upload the binary log which causes the problem to our ftp.askmonty.org/private? Only MariaDB developers will have access to it.
Thanks.

Comment by Z Toth [ 2014-12-17 ]

I did so. The problematic binlog files are in binlog_errors.tgz .
The error messages given by MariaDB-s mysqlbinlog are:

log-bin.000001:
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 61, event_type: 30
ERROR: Could not read entry at offset 3554: Error in log format or read error.
log-bin.000003:
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 61, event_type: 30
ERROR: Could not read entry at offset 312: Error in log format or read error.
log-bin.000004:
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 61, event_type: 30
ERROR: Could not read entry at offset 303: Error in log format or read error.
log-bin.000005:
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 61, event_type: 30
ERROR: Could not read entry at offset 303: Error in log format or read error.
log-bin.000006:
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 61, event_type: 30
log-bin.000008:
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 61, event_type: 30

Comment by Elena Stepanova [ 2014-12-22 ]

Thank you.

So, the events in question relate to NDB (update NDB tables). mysqlbinlog from the normal non-ndb-cluster MySQL 5.5 also fails to read them. However, in MySQL 5.6 it works starting from MySQL 5.6.6, particularly from this revision:

revno: 3776
 
revision-id: frazer.clement@oracle.com-20120503094132-txb7j8vzsynr1qi0
 
parent: thayumanavar.x.sachithanantha@oracle.com-20120503083942-9tfv1b4jqgppulys
 
committer: Frazer Clement <frazer.clement@oracle.com>
 
branch nick: mysql-trunk-wl5917
 
timestamp: Thu 2012-05-03 10:41:32 +0100
 
message:
 
  WL#5917 Appending data to Rows_log_event
 
  
  Overview
 
  --------
 
  This feature implements new 'version 2' Binlog row events for the existing
 
  WRITE_ROW, UPDATE_ROW, DELETE_ROW events.  Version 2 Binlog row events
 
  become the default.
 
  
  These new 'version 2' Binlog row events can transport extra information
 
  *with* each row event.
 
  
  A Master can optionally generate 'version 1' Binlog row events by setting the
 
  --log-bin-use-v1-row-events=1 MySQLD option/variable.  This is necessary
 
  during an upgrade where the Master is upgraded before the Slave.
 
  
  Motivation
 
  ----------
 
  This feature is primarily motivated by WL5353 Reflecting GCI, which uses
 
  the extra row event data to transport per-row event transaction identities.
 
  
  
  Details
 
  -------
 
  - 3 new event types added
 
  - Existing row events renamed with _v1 suffix
 
  - log-bin-use-v1-row-events option added
 
  - Existing row event classes reused
 
  - Extra row info is one use case of new 'v2' extensible row 
    event format.  Should be no need for 'v3'.
 
  - Binlog injector Api enhanced to allow info to be passed in
 
  - THD Api enhanced to expose info to storage engine running as 
    Slave SQL thread
 
  - mysqlbinlog tool enhanced to show extra info in --verbose mode.
 
  - New testcases : rpl_extra_row_data, log_bin_use_v1_row_events_basic
 
  - Enhanced testcase : binlog_old_versions
 
  - Various corrected / adjusted testcases

So, I expect the fix might be merged into 10.0 if it is safe enough, otherwise in 10.1; but I doubt it's going to be fixed in 5.5. I also don't think that NDB => non-NDB replication is officially supported, so if the problem only affects this flow, it doesn't look too critical.

Comment by Z Toth [ 2015-01-08 ]

Just for the record:
I checked with MariaDB 10.0.15 (mariadb-10.0.15-linux-glibc_214-x86_64.tar.gz) against the same MySQL + NDB server and replication works with that.

Generated at Thu Feb 08 07:18:39 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.