Description:
Since 8.0.13, a Query_log_event whose list of accessed databases (status variable Q_UPDATED_DB_NAMES) contains a database name of exactly NAME_LEN (192) bytes is not decoded correctly. Such names are valid: 64 characters that take 3 bytes each, for example U+FF21 FULLWIDTH LATIN CAPITAL LETTER A.
Observed on 8.0.46 (release and debug builds); the code is unchanged in 8.4.13 and trunk:
DROP TABLE IF EXISTS of a table that does not exist, in such a database, writes an event that cannot be read back:
SHOW BINLOG EVENTS: ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Error reading Log_event at position 1558: Failed decoding event: Found invalid event in binary log
mysqlbinlog: ERROR: Could not read entry at offset 989: Error in log format or read error 1.
A replica's SQL thread stops: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the source's binary log is corrupted ...
On every later server restart that reads this binary log: [Warning] [MY-010820] [Server] Error reading GTIDs from binary log: -1
Atomic DDL in such a database (CREATE DATABASE, CREATE TABLE) is read back without an error but loses its XID: SHOW BINLOG EVENTS lists the statement without /* xid=N */.
Root cause:
The writer (Query_log_event::write() in sql/log_event.cc) stores each accessed database name followed by '\0'. The reader (Query_event::Query_event() in libbinlogevents/src/statement_events.cpp) copies it into char mts_accessed_db_names[MAX_DBS_IN_EVENT_MTS][NAME_LEN] with
READER_TRY_CALL(strncpyz, mts_accessed_db_names[i],
std::min<unsigned long>(NAME_LEN, remaining), NAME_LEN);
Event_reader::strncpyz() copies at most NAME_LEN bytes, writes '\0' at NAME_LEN - 1, and advances by strlen(destination) + 1. For a name of NAME_LEN bytes the copy is truncated to NAME_LEN - 1 bytes and the reader advances by NAME_LEN instead of NAME_LEN + 1. It stops on the name's terminating '\0' and parses it as the next status variable code (Q_FLAGS2_CODE), which consumes the following 4 bytes:
Events without an XID: the status variables are over-read by one byte and the event is rejected ("Invalid query length").
Events with an XID (Q_DDL_LOGGED_WITH_XID): the misread consumes the XID code and part of the XID, then re-synchronizes. No error, but the XID is lost.
This came with the Event_reader rework in 8.0.13 (WL#11567).
How to repeat:
On a test server with the binary log enabled (RESET MASTER removes existing binary logs):
RESET MASTER;
SET NAMES utf8mb4;
-- 64 x U+FF21: 64 characters, 192 bytes
SET @db = REPEAT(CONVERT(0xEFBCA1 USING utf8mb4), 64);
SELECT CHAR_LENGTH(@db) AS chars, LENGTH(@db) AS bytes;
SET @s = CONCAT('CREATE DATABASE `', @db, '`');
PREPARE s FROM @s; EXECUTE s;
SET @s = CONCAT('CREATE TABLE `', @db, '`.t2 (a INT)');
PREPARE s FROM @s; EXECUTE s;
SHOW BINLOG EVENTS;
-- Expected: both events end with /* xid=N */
-- Actual: no /* xid=N */ on either event
SET @s = CONCAT('DROP TABLE IF EXISTS `', @db, '`.t1');
PREPARE s FROM @s; EXECUTE s;
SHOW BINLOG EVENTS;
-- Expected: the DROP TABLE IF EXISTS event is listed
-- Actual: ERROR 1220 (HY000): Error when executing command SHOW BINLOG
-- EVENTS: Error reading Log_event at position 1558: Failed
-- decoding event: Found invalid event in binary log
Run the same statements, without RESET MASTER, on a replication source: the replica's SQL thread stops with the "Relay log read failure" error above.
A database name of 63 such characters (189 bytes) works correctly.
Suggested fix:
Make the buffer hold a NAME_LEN-byte name plus its terminator, and copy the terminator so the reader moves past it:
--- a/libbinlogevents/include/statement_events.h
+++ b/libbinlogevents/include/statement_events.h
@@ class Query_event : public Binary_log_event {
unsigned char mts_accessed_dbs;
- char mts_accessed_db_names[MAX_DBS_IN_EVENT_MTS][NAME_LEN];
+ char mts_accessed_db_names[MAX_DBS_IN_EVENT_MTS][NAME_LEN + 1];
--- a/libbinlogevents/src/statement_events.cpp
+++ b/libbinlogevents/src/statement_events.cpp
@@ Query_event::Query_event(const char *buf, const Format_description_event *fde,
+ /*
+ A database name takes up to NAME_LEN bytes followed by '\0'.
+ Copy the terminator too, so that the reader moves past it.
+ */
READER_TRY_CALL(strncpyz, mts_accessed_db_names[i],
- std::min<unsigned long>(NAME_LEN, remaining),
- NAME_LEN);
+ std::min<unsigned long>(NAME_LEN + 1, remaining),
+ NAME_LEN + 1);
Description: Since 8.0.13, a Query_log_event whose list of accessed databases (status variable Q_UPDATED_DB_NAMES) contains a database name of exactly NAME_LEN (192) bytes is not decoded correctly. Such names are valid: 64 characters that take 3 bytes each, for example U+FF21 FULLWIDTH LATIN CAPITAL LETTER A. Observed on 8.0.46 (release and debug builds); the code is unchanged in 8.4.13 and trunk: DROP TABLE IF EXISTS of a table that does not exist, in such a database, writes an event that cannot be read back: SHOW BINLOG EVENTS: ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Error reading Log_event at position 1558: Failed decoding event: Found invalid event in binary log mysqlbinlog: ERROR: Could not read entry at offset 989: Error in log format or read error 1. A replica's SQL thread stops: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the source's binary log is corrupted ... On every later server restart that reads this binary log: [Warning] [MY-010820] [Server] Error reading GTIDs from binary log: -1 Atomic DDL in such a database (CREATE DATABASE, CREATE TABLE) is read back without an error but loses its XID: SHOW BINLOG EVENTS lists the statement without /* xid=N */. Root cause: The writer (Query_log_event::write() in sql/log_event.cc) stores each accessed database name followed by '\0'. The reader (Query_event::Query_event() in libbinlogevents/src/statement_events.cpp) copies it into char mts_accessed_db_names[MAX_DBS_IN_EVENT_MTS][NAME_LEN] with READER_TRY_CALL(strncpyz, mts_accessed_db_names[i], std::min<unsigned long>(NAME_LEN, remaining), NAME_LEN); Event_reader::strncpyz() copies at most NAME_LEN bytes, writes '\0' at NAME_LEN - 1, and advances by strlen(destination) + 1. For a name of NAME_LEN bytes the copy is truncated to NAME_LEN - 1 bytes and the reader advances by NAME_LEN instead of NAME_LEN + 1. It stops on the name's terminating '\0' and parses it as the next status variable code (Q_FLAGS2_CODE), which consumes the following 4 bytes: Events without an XID: the status variables are over-read by one byte and the event is rejected ("Invalid query length"). Events with an XID (Q_DDL_LOGGED_WITH_XID): the misread consumes the XID code and part of the XID, then re-synchronizes. No error, but the XID is lost. This came with the Event_reader rework in 8.0.13 (WL#11567). How to repeat: On a test server with the binary log enabled (RESET MASTER removes existing binary logs): RESET MASTER; SET NAMES utf8mb4; -- 64 x U+FF21: 64 characters, 192 bytes SET @db = REPEAT(CONVERT(0xEFBCA1 USING utf8mb4), 64); SELECT CHAR_LENGTH(@db) AS chars, LENGTH(@db) AS bytes; SET @s = CONCAT('CREATE DATABASE `', @db, '`'); PREPARE s FROM @s; EXECUTE s; SET @s = CONCAT('CREATE TABLE `', @db, '`.t2 (a INT)'); PREPARE s FROM @s; EXECUTE s; SHOW BINLOG EVENTS; -- Expected: both events end with /* xid=N */ -- Actual: no /* xid=N */ on either event SET @s = CONCAT('DROP TABLE IF EXISTS `', @db, '`.t1'); PREPARE s FROM @s; EXECUTE s; SHOW BINLOG EVENTS; -- Expected: the DROP TABLE IF EXISTS event is listed -- Actual: ERROR 1220 (HY000): Error when executing command SHOW BINLOG -- EVENTS: Error reading Log_event at position 1558: Failed -- decoding event: Found invalid event in binary log Run the same statements, without RESET MASTER, on a replication source: the replica's SQL thread stops with the "Relay log read failure" error above. A database name of 63 such characters (189 bytes) works correctly. Suggested fix: Make the buffer hold a NAME_LEN-byte name plus its terminator, and copy the terminator so the reader moves past it: --- a/libbinlogevents/include/statement_events.h +++ b/libbinlogevents/include/statement_events.h @@ class Query_event : public Binary_log_event { unsigned char mts_accessed_dbs; - char mts_accessed_db_names[MAX_DBS_IN_EVENT_MTS][NAME_LEN]; + char mts_accessed_db_names[MAX_DBS_IN_EVENT_MTS][NAME_LEN + 1]; --- a/libbinlogevents/src/statement_events.cpp +++ b/libbinlogevents/src/statement_events.cpp @@ Query_event::Query_event(const char *buf, const Format_description_event *fde, + /* + A database name takes up to NAME_LEN bytes followed by '\0'. + Copy the terminator too, so that the reader moves past it. + */ READER_TRY_CALL(strncpyz, mts_accessed_db_names[i], - std::min<unsigned long>(NAME_LEN, remaining), - NAME_LEN); + std::min<unsigned long>(NAME_LEN + 1, remaining), + NAME_LEN + 1);