From 7d3e56fbc0cbdb2c1804f7c8a689693fb1c5444f Mon Sep 17 00:00:00 2001 From: monthdev Date: Mon, 9 Mar 2026 15:45:12 -0700 Subject: [PATCH] MDEV-20749 Improve mysqlbinlog --flashback error reporting Handle corrupted row events by reporting whether the field length could not be determined from metadata or whether the field extends past the row buffer instead of falling out through debug-only assertion paths or ad hoc exits during flashback row conversion. Propagate flashback conversion failures through the normal mysqlbinlog error path so debug builds produce the intended diagnostics cleanly. Add replication tests covering corrupted BLOB metadata and corrupted BLOB length prefixes using server-side debug injection to write broken binlog contents and mysqltest-friendly mysqlbinlog invocation patterns. Reviewed-by: Brandon Nesterenko Reviewed-by: Georgi Kodinov --- client/mysqlbinlog.cc | 16 +++- .../rpl/r/mdev_20749_bad_field_length.result | 16 ++++ .../suite/rpl/r/mdev_20749_truncated.result | 17 ++++ .../rpl/t/mdev_20749_bad_field_length.test | 27 ++++++ .../suite/rpl/t/mdev_20749_truncated.test | 28 ++++++ sql/log_event.h | 8 +- sql/log_event_client.cc | 96 +++++++++++++------ sql/log_event_server.cc | 57 +++++++++-- 8 files changed, 221 insertions(+), 44 deletions(-) create mode 100644 mysql-test/suite/rpl/r/mdev_20749_bad_field_length.result create mode 100644 mysql-test/suite/rpl/r/mdev_20749_truncated.result create mode 100644 mysql-test/suite/rpl/t/mdev_20749_bad_field_length.test create mode 100644 mysql-test/suite/rpl/t/mdev_20749_truncated.test diff --git a/client/mysqlbinlog.cc b/client/mysqlbinlog.cc index 5393bd98e6f83..f3ae85a541694 100644 --- a/client/mysqlbinlog.cc +++ b/client/mysqlbinlog.cc @@ -893,10 +893,12 @@ static bool print_row_event(PRINT_EVENT_INFO *print_event_info, Log_event *ev, for (size_t i= events_in_stmt.elements; i > 0; --i) { e= *(dynamic_element(&events_in_stmt, i - 1, Log_event**)); - result= result || print_base64(print_event_info, e); + if ((result= print_base64(print_event_info, e))) + break; } // Copy all output into the Log_event - ev->output_buf.copy(e->output_buf); + if (!result) + ev->output_buf.copy(e->output_buf); // Delete Log_event for (size_t i= 0; i < events_in_stmt.elements-1; ++i) { @@ -904,6 +906,8 @@ static bool print_row_event(PRINT_EVENT_INFO *print_event_info, Log_event *ev, delete e; } reset_dynamic(&events_in_stmt); + if (result) + return result; } } @@ -1955,6 +1959,14 @@ static void cleanup() mysql_server_end(); if (opt_flashback) { + if (binlog_events.buffer) + { + for (size_t i= 0; i < binlog_events.elements; ++i) + { + LEX_STRING *event_str= dynamic_element(&binlog_events, i, LEX_STRING*); + my_free(event_str->str); + } + } delete_dynamic(&binlog_events); delete_dynamic(&events_in_stmt); } diff --git a/mysql-test/suite/rpl/r/mdev_20749_bad_field_length.result b/mysql-test/suite/rpl/r/mdev_20749_bad_field_length.result new file mode 100644 index 0000000000000..0c497919ab2c6 --- /dev/null +++ b/mysql-test/suite/rpl/r/mdev_20749_bad_field_length.result @@ -0,0 +1,16 @@ +# +# MDEV-20749 corrupted BLOB metadata should report bad field length +# The server-side DBUG hook corrupts the BLOB metadata written in +# the table map event so mariadb-binlog --flashback cannot determine the +# field length while decoding the row image. +# +create table t1 (a int, b blob) engine=innodb; +set @old_dbug= @@debug_dbug; +set debug_dbug= "+d,flashback_corrupt_blob_metadata"; +insert into t1 values (1, repeat("a",3104)); +set debug_dbug= @old_dbug; +flush binary logs; +# MYSQL_BINLOG --result-file=RESULT_FILE -vvv --flashback MYSQLD_DATADIR/BINLOG_FILE 2>&1 + +Error decoding row image while converting event for --flashback (could not determine field length): event=Delete_rows_v1, column=1, column_type=252, metadata=5 +DROP TABLE t1; diff --git a/mysql-test/suite/rpl/r/mdev_20749_truncated.result b/mysql-test/suite/rpl/r/mdev_20749_truncated.result new file mode 100644 index 0000000000000..dd18962496430 --- /dev/null +++ b/mysql-test/suite/rpl/r/mdev_20749_truncated.result @@ -0,0 +1,17 @@ +# +# MDEV-20749 corrupted BLOB length prefix should report truncated row image +# The server-side DBUG hook corrupts the serialized row image written to +# the binary log by increasing the BLOB length prefix without changing +# the event size. mariadb-binlog --flashback should then report that the +# field extends past the row buffer while decoding the WRITE_ROWS_EVENT. +# +create table t1 (a int, b blob) engine=innodb; +set @old_dbug= @@debug_dbug; +set debug_dbug= "+d,flashback_corrupt_blob_length_prefix"; +insert into t1 values (1, repeat("a",3104)); +set debug_dbug= @old_dbug; +flush binary logs; +# MYSQL_BINLOG --result-file=RESULT_FILE -vvv --flashback MYSQLD_DATADIR/BINLOG_FILE 2>&1 + +Error decoding row image while converting event for --flashback (field extends past row buffer): event=Delete_rows_v1, column=1 +DROP TABLE t1; diff --git a/mysql-test/suite/rpl/t/mdev_20749_bad_field_length.test b/mysql-test/suite/rpl/t/mdev_20749_bad_field_length.test new file mode 100644 index 0000000000000..65b1271484550 --- /dev/null +++ b/mysql-test/suite/rpl/t/mdev_20749_bad_field_length.test @@ -0,0 +1,27 @@ +--echo # +--echo # MDEV-20749 corrupted BLOB metadata should report bad field length +--echo # The server-side DBUG hook corrupts the BLOB metadata written in +--echo # the table map event so mariadb-binlog --flashback cannot determine the +--echo # field length while decoding the row image. +--echo # + +--source include/have_innodb.inc +--source include/have_binlog_format_row.inc +--source include/have_debug.inc + +create table t1 (a int, b blob) engine=innodb; + +set @old_dbug= @@debug_dbug; +set debug_dbug= "+d,flashback_corrupt_blob_metadata"; +insert into t1 values (1, repeat("a",3104)); +set debug_dbug= @old_dbug; + +--let $MYSQLD_DATADIR= `select @@datadir` +--let $BINLOG_FILE= query_get_value(SHOW MASTER STATUS, File, 1) +flush binary logs; +--let $RESULT_FILE= $MYSQLTEST_VARDIR/tmp/mariadb_binlog_out.sql +--echo # MYSQL_BINLOG --result-file=RESULT_FILE -vvv --flashback MYSQLD_DATADIR/BINLOG_FILE 2>&1 +--error 1 +--exec $MYSQL_BINLOG --result-file=$RESULT_FILE -vvv --flashback $MYSQLD_DATADIR/$BINLOG_FILE 2>&1 + +DROP TABLE t1; diff --git a/mysql-test/suite/rpl/t/mdev_20749_truncated.test b/mysql-test/suite/rpl/t/mdev_20749_truncated.test new file mode 100644 index 0000000000000..88413700fe9b0 --- /dev/null +++ b/mysql-test/suite/rpl/t/mdev_20749_truncated.test @@ -0,0 +1,28 @@ +--echo # +--echo # MDEV-20749 corrupted BLOB length prefix should report truncated row image +--echo # The server-side DBUG hook corrupts the serialized row image written to +--echo # the binary log by increasing the BLOB length prefix without changing +--echo # the event size. mariadb-binlog --flashback should then report that the +--echo # field extends past the row buffer while decoding the WRITE_ROWS_EVENT. +--echo # + +--source include/have_innodb.inc +--source include/have_binlog_format_row.inc +--source include/have_debug.inc + +create table t1 (a int, b blob) engine=innodb; + +set @old_dbug= @@debug_dbug; +set debug_dbug= "+d,flashback_corrupt_blob_length_prefix"; +insert into t1 values (1, repeat("a",3104)); +set debug_dbug= @old_dbug; + +--let $MYSQLD_DATADIR= `select @@datadir` +--let $BINLOG_FILE= query_get_value(SHOW MASTER STATUS, File, 1) +flush binary logs; +--let $RESULT_FILE= $MYSQLTEST_VARDIR/tmp/mariadb_binlog_out.sql +--echo # MYSQL_BINLOG --result-file=RESULT_FILE -vvv --flashback MYSQLD_DATADIR/BINLOG_FILE 2>&1 +--error 1 +--exec $MYSQL_BINLOG --result-file=$RESULT_FILE -vvv --flashback $MYSQLD_DATADIR/$BINLOG_FILE 2>&1 + +DROP TABLE t1; diff --git a/sql/log_event.h b/sql/log_event.h index 629ffc23476eb..8b23b589007ec 100644 --- a/sql/log_event.h +++ b/sql/log_event.h @@ -4824,17 +4824,15 @@ class Rows_log_event : public Log_event /* not for direct call, each derived has its own ::print() */ bool print(FILE *file, PRINT_EVENT_INFO *print_event_info) override= 0; - void change_to_flashback_event(PRINT_EVENT_INFO *print_event_info, uchar *rows_buff, Log_event_type ev_type); + bool change_to_flashback_event(PRINT_EVENT_INFO *print_event_info, uchar *rows_buff, Log_event_type ev_type); bool print_verbose(IO_CACHE *file, PRINT_EVENT_INFO *print_event_info); size_t print_verbose_one_row(IO_CACHE *file, table_def *td, PRINT_EVENT_INFO *print_event_info, MY_BITMAP *cols_bitmap, const uchar *ptr, const uchar *prefix); - size_t calc_row_event_length(table_def *td, - MY_BITMAP *cols_bitmap, - const uchar *value, - Field_info *fields); + size_t calc_row_event_length(table_def *td, MY_BITMAP *cols_bitmap, + const uchar *value, Field_info *fields); void count_row_events(PRINT_EVENT_INFO *print_event_info); #endif diff --git a/sql/log_event_client.cc b/sql/log_event_client.cc index 468c196d8b6f2..f0214b3de9638 100644 --- a/sql/log_event_client.cc +++ b/sql/log_event_client.cc @@ -1124,7 +1124,7 @@ static uchar *fill_row_image(const MY_BITMAP *cols_bitmap, @param[in] rows_buff Packed event buff */ -void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_info, +bool Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_info, uchar *rows_buff, Log_event_type ev_type) { Table_map_log_event *map; @@ -1133,16 +1133,24 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf uchar *rows_pos= rows_buff + m_rows_before_size; Field_info *ai_fields= nullptr; Field_info *bi_fields= nullptr; + bool error= false; if (!(map= print_event_info->m_table_map.get_table(m_table_id)) || !(td= map->create_table_def())) - return; + return false; /* If the write rows event contained no values for the AI */ if (((get_general_type_code() == WRITE_ROWS_EVENT) && (m_rows_buf==m_rows_end))) - goto end; + goto err; - (void) my_init_dynamic_array(PSI_NOT_INSTRUMENTED, &rows_arr, sizeof(LEX_STRING), 8, 8, MYF(0)); + if (my_init_dynamic_array(PSI_NOT_INSTRUMENTED, &rows_arr, + sizeof(LEX_STRING), 8, 8, MYF(0))) + { + fprintf(stderr, "\nError: Out of memory. " + "Could not exchange to flashback event.\n"); + error= true; + goto err; + } if (get_general_type_code() == UPDATE_ROWS_EVENT || get_general_type_code() == UPDATE_ROWS_EVENT_V1) @@ -1159,7 +1167,8 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf { fprintf(stderr, "\nError: Out of memory. " "Could not exchange to flashback event.\n"); - exit(1); + error= true; + goto end; } } } @@ -1170,8 +1179,8 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf size_t length1= 0; if (!(length1= calc_row_event_length(td, &m_cols, value, bi_fields))) { - fprintf(stderr, "\nError row length: %zu\n", length1); - exit(1); + error= true; + goto end; } value+= length1; @@ -1182,8 +1191,8 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf { if (!(length2= calc_row_event_length(td, &m_cols_ai, value, ai_fields))) { - fprintf(stderr, "\nError row length: %zu\n", length2); - exit(1); + error= true; + goto end; } value+= length2; } @@ -1197,7 +1206,8 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf { fprintf(stderr, "\nError: Out of memory. " "Could not exchange to flashback event.\n"); - exit(1); + error= true; + goto end; } if (length2 != 0) // It has before and after image @@ -1237,7 +1247,9 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf { fprintf(stderr, "\nError: Out of memory. " "Could not push flashback event into array.\n"); - exit(1); + my_free(one_row.str); + error= true; + goto end; } } @@ -1250,15 +1262,24 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf rows_pos+= one_row->length; my_free(one_row->str); } - delete_dynamic(&rows_arr); - end: - if (bi_fields) + if (error) + { + for (size_t i= 0; i < rows_arr.elements; ++i) + { + LEX_STRING *one_row= dynamic_element(&rows_arr, i, LEX_STRING*); + my_free(one_row->str); + } + } + delete_dynamic(&rows_arr); +err: + if (ai_fields || bi_fields) { my_free(bi_fields); my_free(ai_fields); } delete td; + return error; } /** @@ -1389,11 +1410,10 @@ static size_t calc_field_event_length(const uchar *ptr, uint type, uint meta) @return length of the parsed row image if succeeds, otherwise 0 is returned. */ -size_t -Rows_log_event::calc_row_event_length(table_def *td, - MY_BITMAP *cols_bitmap, - const uchar *value, - Field_info *fields) +size_t Rows_log_event::calc_row_event_length(table_def *td, + MY_BITMAP *cols_bitmap, + const uchar *value, + Field_info *fields) { const uchar *value0= value; const uchar *null_bits= value; @@ -1417,15 +1437,33 @@ Rows_log_event::calc_row_event_length(table_def *td, if (!is_null) { size_t size; - size_t fsize= td->calc_field_size((uint)i, (uchar*) value); - if (value + fsize > m_rows_end) + const char *event_name= get_type_str(); + const bool IsUpdate= get_general_type_code() == UPDATE_ROWS_EVENT || + get_general_type_code() == UPDATE_ROWS_EVENT_V1; + const char *image_suffix= ""; + if (IsUpdate) + image_suffix= + (cols_bitmap == &m_cols_ai) ? " (after image)" : " (before image)"; + if (!(size= calc_field_event_length(value, td->type(i), + td->field_metadata(i)))) { - /* Corrupted replication event was detected, skipping entry */ + fprintf(stderr, + "\nError decoding row image while converting event for " + "--flashback (%s): event=%s%s, column=%u, column_type=%u, " + "metadata=%u\n", + "could not determine field length", event_name, image_suffix, + i, (uint) td->type(i), (uint) td->field_metadata(i)); return 0; } - if (!(size= calc_field_event_length(value, td->type(i), - td->field_metadata(i)))) + if (size > (size_t) (m_rows_end - value)) + { + /* corrupted replication event was detected, skipping entry */ + fprintf(stderr, + "\nError decoding row image while converting event for " + "--flashback (%s): event=%s%s, column=%u\n", + "field extends past row buffer", event_name, image_suffix, i); return 0; + } if (fields) { @@ -1693,6 +1731,7 @@ bool Log_event::print_base64(IO_CACHE* file, { uint tmp_size= size; Rows_log_event *ev= NULL; + bool error= false; Log_event_type ev_type = (enum Log_event_type) ptr[EVENT_TYPE_OFFSET]; if (read_checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF && read_checksum_alg != BINLOG_CHECKSUM_ALG_OFF) @@ -1702,36 +1741,35 @@ bool Log_event::print_base64(IO_CACHE* file, ptr[EVENT_TYPE_OFFSET]= DELETE_ROWS_EVENT; ev= new Delete_rows_log_event(ptr, tmp_size, glob_description_event); - ev->change_to_flashback_event(print_event_info, ptr, ev_type); break; case WRITE_ROWS_EVENT_V1: ptr[EVENT_TYPE_OFFSET]= DELETE_ROWS_EVENT_V1; ev= new Delete_rows_log_event(ptr, tmp_size, glob_description_event); - ev->change_to_flashback_event(print_event_info, ptr, ev_type); break; case DELETE_ROWS_EVENT: ptr[EVENT_TYPE_OFFSET]= WRITE_ROWS_EVENT; ev= new Write_rows_log_event(ptr, tmp_size, glob_description_event); - ev->change_to_flashback_event(print_event_info, ptr, ev_type); break; case DELETE_ROWS_EVENT_V1: ptr[EVENT_TYPE_OFFSET]= WRITE_ROWS_EVENT_V1; ev= new Write_rows_log_event(ptr, tmp_size, glob_description_event); - ev->change_to_flashback_event(print_event_info, ptr, ev_type); break; case UPDATE_ROWS_EVENT: case UPDATE_ROWS_EVENT_V1: ev= new Update_rows_log_event(ptr, tmp_size, glob_description_event); - ev->change_to_flashback_event(print_event_info, ptr, ev_type); break; default: break; } + if (ev) + error= ev->change_to_flashback_event(print_event_info, ptr, ev_type); delete ev; + if (unlikely(error)) + goto err; } if (do_print_encoded) diff --git a/sql/log_event_server.cc b/sql/log_event_server.cc index aea8028db1029..b222d4c1a230f 100644 --- a/sql/log_event_server.cc +++ b/sql/log_event_server.cc @@ -5845,6 +5845,35 @@ bool Rows_log_event::write_data_body_rows(Log_event_writer *writer, { uchar *from_ptr= m_rows_buf + from_offset; my_ptrdiff_t const data_size= len_to_write ? len_to_write : m_rows_cur - m_rows_buf; + +#ifndef DBUG_OFF + if (DBUG_IF("flashback_corrupt_blob_length_prefix") && from_offset == 0 && + get_general_type_code() == WRITE_ROWS_EVENT) + { + /* + Test-specific corruption for: + + create table t1 (a int, b blob) engine=innodb; + insert into t1 values (1, repeat("a", 3104)); + + Row image layout: + 1 byte null-bitmap + 4 bytes INT + 2 bytes BLOB length prefix + blob payload + + Bump the BLOB length prefix without changing the event length. This keeps + the event parseable but makes the client think the field extends past + m_rows_end during flashback decoding. + */ + uchar *p= from_ptr; + p+= 1; /* null bitmap */ + p+= 4; /* INT field */ + uint16 len= uint2korr(p); + int2store(p, len + 4); + } +#endif + DBUG_DUMP("rows", from_ptr, data_size); return write_data(writer, from_ptr, (size_t) data_size); } @@ -6849,18 +6878,30 @@ bool Table_map_log_event::write_data_body(Log_event_writer *writer) uchar mbuf[MAX_INT_WIDTH]; uchar *const mbuf_end= net_store_length(mbuf, m_field_metadata_size); - return write_data(writer, dbuf, sizeof(dbuf)) || - write_data(writer, m_dbnam, m_dblen+1) || - write_data(writer, tbuf, sizeof(tbuf)) || - write_data(writer, m_tblnam, m_tbllen+1) || +#ifndef DBUG_OFF + DBUG_EXECUTE_IF("flashback_corrupt_blob_metadata", { + if (m_dbnam && m_tblnam && m_dblen == 4 && + memcmp(m_dbnam, "test", 4) == 0 && m_tbllen == 2 && + memcmp(m_tblnam, "t1", 2) == 0 && m_colcnt == 2 && + m_field_metadata_size >= 1 && m_coltype[1] == MYSQL_TYPE_BLOB) + { + m_field_metadata[0]= 5; + } + }); +#endif + + return write_data(writer, dbuf, sizeof(dbuf)) || + write_data(writer, m_dbnam, m_dblen + 1) || + write_data(writer, tbuf, sizeof(tbuf)) || + write_data(writer, m_tblnam, m_tbllen + 1) || write_data(writer, cbuf, (size_t) (cbuf_end - cbuf)) || write_data(writer, m_coltype, m_colcnt) || write_data(writer, mbuf, (size_t) (mbuf_end - mbuf)) || - write_data(writer, m_field_metadata, m_field_metadata_size), + write_data(writer, m_field_metadata, m_field_metadata_size) || write_data(writer, m_null_bits, (m_colcnt + 7) / 8) || - write_data(writer, (const uchar*) m_metadata_buf.ptr(), - m_metadata_buf.length()); - } + write_data(writer, (const uchar *) m_metadata_buf.ptr(), + m_metadata_buf.length()); +} /** stores an integer into packed format.