Bug #121593 Query event with a NAME_LEN-byte database name in Q_UPDATED_DB_NAMES is misread: binlog unreadable, replica stops
Submitted: 23 Oct 9:53
Reporter: Marcin Babij (OCA) Email Updates:
Status: Open Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:8.0, 8.4, 9.7, 26.7, 26.10 OS:Any
Assigned to: CPU Architecture:Any

[23 Oct 9:53] Marcin Babij
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);