From 272311e2f9e4b43e03608bfd90a412b6c0a33178 Mon Sep 17 00:00:00 2001 From: monthdev Date: Mon, 9 Mar 2026 15:45:12 -0700 Subject: [PATCH] MDEV-20749 Improve error reporting of mysqlbinlog --flashback Print row decode failures directly in calc_row_event_length() so the diagnostic can include decoder-local context such as image kind, offsets, and field/type metadata. Pass event context from the flashback caller so the message can report the row event type and end_log_pos. Add MTR coverage for truncated row image and bad field length failures using DBUG fault injection in mariadb-binlog. --- .../rpl/r/mdev_20749_bad_field_length.result | 6 ++ .../suite/rpl/r/mdev_20749_truncated.result | 6 ++ .../rpl/t/mdev_20749_bad_field_length.test | 12 +++ .../suite/rpl/t/mdev_20749_truncated.test | 12 +++ sql/log_event.h | 9 +- sql/log_event_client.cc | 91 +++++++++++++++++-- 6 files changed, 122 insertions(+), 14 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/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..b1bcaff2e9daa --- /dev/null +++ b/mysql-test/suite/rpl/r/mdev_20749_bad_field_length.result @@ -0,0 +1,6 @@ +# +# MDEV-20749 improve flashback row decode diagnostics (bad field length) +# +create table t1 (a int, b blob) engine=innodb; +insert into t1 values (1, repeat("a",3104)); +Error decoding row image while converting event for --flashback: event=WRITE_ROWS_EVENT, image=row image, end_log_pos=0, column=0, row_offset=0, field_offset=1, column_type=3, metadata=0, reason=could not determine field length 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..46e6959254404 --- /dev/null +++ b/mysql-test/suite/rpl/r/mdev_20749_truncated.result @@ -0,0 +1,6 @@ +# +# MDEV-20749 improve flashback row decode diagnostics +# +create table t1 (a int, b blob) engine=innodb; +insert into t1 values (1, repeat("a",3104)); +Error decoding row image while converting event for --flashback: event=WRITE_ROWS_EVENT, image=row image, end_log_pos=0, column=0, row_offset=0, field_offset=1, expected_field_size=4, remaining_bytes=3110, reason=field extends past row buffer 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..753cf6c471b22 --- /dev/null +++ b/mysql-test/suite/rpl/t/mdev_20749_bad_field_length.test @@ -0,0 +1,12 @@ +--echo # +--echo # MDEV-20749 improve flashback row decode diagnostics (bad field length) +--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; +insert into t1 values (1, repeat("a",3104)); + +--exec sh -c '$MYSQL_BINLOG --debug="d,flashback_force_row_decode_bad_field_length" -vvv --flashback $MYSQLTEST_VARDIR/mysqld.1/data/master-bin.000001 2>&1 || true' | grep "Error decoding row image" 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..8afecfc11a1cb --- /dev/null +++ b/mysql-test/suite/rpl/t/mdev_20749_truncated.test @@ -0,0 +1,12 @@ +--echo # +--echo # MDEV-20749 improve flashback row decode diagnostics +--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; +insert into t1 values (1, repeat("a",3104)); + +--exec sh -c '$MYSQL_BINLOG --debug="d,flashback_force_row_decode_truncated" -vvv --flashback $MYSQLTEST_VARDIR/mysqld.1/data/master-bin.000001 2>&1 || true' | grep "Error decoding row image" diff --git a/sql/log_event.h b/sql/log_event.h index 629ffc23476eb..ded1d6c7f212c 100644 --- a/sql/log_event.h +++ b/sql/log_event.h @@ -4831,10 +4831,11 @@ class Rows_log_event : public Log_event 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, + Log_event_type ev_type= UNKNOWN_EVENT, + const char *image_name= nullptr, + ulonglong event_log_pos= 0); 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..c9059097e72b5 100644 --- a/sql/log_event_client.cc +++ b/sql/log_event_client.cc @@ -1168,9 +1168,12 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf { uchar *start_pos= value; size_t length1= 0; - if (!(length1= calc_row_event_length(td, &m_cols, value, bi_fields))) + const bool IsUpdate= + ev_type == UPDATE_ROWS_EVENT || ev_type == UPDATE_ROWS_EVENT_V1; + const char *image1_name= IsUpdate ? "before image" : "row image"; + if (!(length1= calc_row_event_length(td, &m_cols, value, bi_fields, + ev_type, image1_name, this->log_pos))) { - fprintf(stderr, "\nError row length: %zu\n", length1); exit(1); } value+= length1; @@ -1180,9 +1183,10 @@ void Rows_log_event::change_to_flashback_event(PRINT_EVENT_INFO *print_event_inf if (ev_type == UPDATE_ROWS_EVENT || ev_type == UPDATE_ROWS_EVENT_V1) { - if (!(length2= calc_row_event_length(td, &m_cols_ai, value, ai_fields))) + if (!(length2= + calc_row_event_length(td, &m_cols_ai, value, ai_fields, + ev_type, "after image", this->log_pos))) { - fprintf(stderr, "\nError row length: %zu\n", length2); exit(1); } value+= length2; @@ -1378,6 +1382,24 @@ static size_t calc_field_event_length(const uchar *ptr, uint type, uint meta) return 0; } +static const char *rows_event_name(Log_event_type type) +{ + switch (type) + { + case WRITE_ROWS_EVENT: + case WRITE_ROWS_EVENT_V1: + return "WRITE_ROWS_EVENT"; + case UPDATE_ROWS_EVENT: + case UPDATE_ROWS_EVENT_V1: + return "UPDATE_ROWS_EVENT"; + case DELETE_ROWS_EVENT: + case DELETE_ROWS_EVENT_V1: + return "DELETE_ROWS_EVENT"; + default: + return "ROWS_EVENT"; + } +} + /** It parses a row image and returns its length and information of columns if 'fields' is not null. @@ -1389,11 +1411,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, Log_event_type ev_type, const char *image_name, + ulonglong event_log_pos) { const uchar *value0= value; const uchar *null_bits= value; @@ -1418,14 +1439,64 @@ Rows_log_event::calc_row_event_length(table_def *td, { size_t size; size_t fsize= td->calc_field_size((uint)i, (uchar*) value); +#ifndef DBUG_OFF + if (DBUG_IF("flashback_force_row_decode_truncated")) + { + fprintf(stderr, + "\nError decoding row image while converting event for " + "--flashback: event=%s, image=%s, end_log_pos=%llu, " + "column=%u, row_offset=%zu, field_offset=%zu, " + "expected_field_size=%zu, remaining_bytes=%zu, " + "reason=field extends past row buffer\n", + rows_event_name(ev_type), image_name, event_log_pos, i, + (size_t) (value0 - m_rows_buf), (size_t) (value - value0), + fsize, (size_t) (m_rows_end - value)); + return 0; + } + + if (DBUG_IF("flashback_force_row_decode_bad_field_length")) + { + fprintf(stderr, + "\nError decoding row image while converting event for " + "--flashback: event=%s, image=%s, end_log_pos=%llu, " + "column=%u, row_offset=%zu, field_offset=%zu, " + "column_type=%u, metadata=%u, " + "reason=could not determine field length\n", + rows_event_name(ev_type), image_name, event_log_pos, i, + (size_t) (value0 - m_rows_buf), (size_t) (value - value0), + (uint) td->type(i), (uint) td->field_metadata(i)); + return 0; + } +#endif if (value + fsize > m_rows_end) { - /* Corrupted replication event was detected, skipping entry */ + /* corrupted replication event was detected, skipping entry */ + fprintf(stderr, + "\nError decoding row image while converting event for " + "--flashback: " + "event=%s, image=%s, log_pos=%llu, column=%u, " + "row_offset=%zu, field_offset=%zu, expected_field_size=%zu, " + "remaining_bytes=%zu, reason=field extends past row buffer\n", + rows_event_name(ev_type), image_name, event_log_pos, i, + (size_t) (value0 - m_rows_buf), (size_t) (value - value0), + fsize, (size_t) (m_rows_end - value)); return 0; } if (!(size= calc_field_event_length(value, td->type(i), td->field_metadata(i)))) + { + fprintf( + stderr, + "\nError decoding row image while converting event for " + "--flashback: " + "event=%s, image=%s, log_pos=%llu, column=%u, " + "row_offset=%zu, field_offset=%zu, column_type=%u, metadata=%u, " + "reason=could not determine field length\n", + rows_event_name(ev_type), image_name, event_log_pos, i, + (size_t) (value0 - m_rows_buf), (size_t) (value - value0), + (uint) td->type(i), (uint) td->field_metadata(i)); return 0; + } if (fields) {