diff --git a/mysql-test/suite/binlog/r/binlog_show_binlog_events_invalid_offset_silent.result b/mysql-test/suite/binlog/r/binlog_show_binlog_events_invalid_offset_silent.result new file mode 100644 index 00000000000..ec86cc8ea16 --- /dev/null +++ b/mysql-test/suite/binlog/r/binlog_show_binlog_events_invalid_offset_silent.result @@ -0,0 +1,21 @@ +# +# Initialize test data +set @save_master_verify_checksum = @@global.master_verify_checksum; +set @@global.master_verify_checksum = 1; +create table t1 (a int); +insert into t1 values (1); +insert into t1 values (2); +SHOW BINLOG EVENTS FROM invalid_pos; +ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error +include/assert_grep.inc [Ensure the client error is not in the server log] +SHOW BINLOG EVENTS FROM 500; +ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error +include/assert_grep.inc [Ensure the client error is not in the server log] +SHOW BINLOG EVENTS FROM 498; +ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error +include/assert_grep.inc [Ensure the client error is not in the server log] +include/assert_grep.inc [Ensure there is not a specific checksum failure error] +# +# Cleanup +set @@global.master_verify_checksum = @save_master_verify_checksum; +drop table t1; diff --git a/mysql-test/suite/binlog/t/binlog_show_binlog_events_invalid_offset_silent.test b/mysql-test/suite/binlog/t/binlog_show_binlog_events_invalid_offset_silent.test new file mode 100644 index 00000000000..d3b31596051 --- /dev/null +++ b/mysql-test/suite/binlog/t/binlog_show_binlog_events_invalid_offset_silent.test @@ -0,0 +1,53 @@ +# +# Ensure that calling SHOW BINLOG EVENTS FROM with an invalid offset +# will not result in error messages in the server log. That is, this call is a +# read operation for a user, and if it fails due to invalid usage, that is not +# a server error, but only one to report to the user. +# +# References: +# MDEV-32628: Cryptic ERROR message & inconsistent behavior on incorrect +# SHOW BINLOG EVENTS FROM ... +# +--source include/have_binlog_format_row.inc + +--echo # +--echo # Initialize test data +set @save_master_verify_checksum = @@global.master_verify_checksum; +set @@global.master_verify_checksum = 1; +create table t1 (a int); +insert into t1 values (1); +--let $middle_binlog_pos= query_get_value(SHOW BINARY LOGS, File_size, 1) +insert into t1 values (2); + +--let $assert_text= Ensure the client error is not in the server log +--let $assert_select= Error in Log_event +--let $assert_file= $MYSQLTEST_VARDIR/log/mysqld.1.err +--let $assert_count= 0 +--let $assert_only_after = CURRENT_TEST: + + +# Pre MDEV-32628, this would write an event truncated error in the logs +--let $invalid_pos= `SELECT $middle_binlog_pos - 1` +--replace_result $invalid_pos invalid_pos +--error 1220 +--eval SHOW BINLOG EVENTS FROM $invalid_pos +--source include/assert_grep.inc + +# Pre MDEV-32628, this would write an event too big error in the logs +--error 1220 +SHOW BINLOG EVENTS FROM 500; +--source include/assert_grep.inc + + +# Pre MDEV-32628, this would write a checksum verification failed error in the logs +--error 1220 +SHOW BINLOG EVENTS FROM 498; +--source include/assert_grep.inc +--let $assert_text= Ensure there is not a specific checksum failure error +--let $assert_select= Replication event checksum verification failed while reading from a log file +--source include/assert_grep.inc + +--echo # +--echo # Cleanup +set @@global.master_verify_checksum = @save_master_verify_checksum; +drop table t1; diff --git a/sql/log_event.cc b/sql/log_event.cc index 10bf569d636..6a59a021efc 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -1916,7 +1916,8 @@ int Log_event::read_log_event(IO_CACHE* file, String* packet, Log_event* Log_event::read_log_event(IO_CACHE* file, const Format_description_log_event *fdle, - my_bool crc_check) + my_bool crc_check, + my_bool print_errors) { DBUG_ENTER("Log_event::read_log_event(IO_CACHE*,Format_description_log_event*...)"); DBUG_ASSERT(fdle != 0); @@ -1955,8 +1956,12 @@ Log_event* Log_event::read_log_event(IO_CACHE* file, goto err; } + /* + print_errors is false to prevent redundant error messages cluttering up the + log, as it will be printed below (if _our_ print_errors is true) + */ if ((res= read_log_event(event.ptr(), event.length(), - &error, fdle, crc_check))) + &error, fdle, crc_check, false))) res->register_temp_buf(event.release(), true); err: @@ -1967,13 +1972,7 @@ err: if (force_opt) DBUG_RETURN(new Unknown_log_event()); #endif - if (event.length() >= OLD_HEADER_LEN) - sql_print_error("Error in Log_event::read_log_event(): '%s'," - " data_len: %lu, event_type: %u", error, - (ulong) uint4korr(&event[EVENT_LEN_OFFSET]), - (uint) (uchar)event[EVENT_TYPE_OFFSET]); - else - sql_print_error("Error in Log_event::read_log_event(): '%s'", error); + /* The SQL slave thread will check if file->error<0 to know if there was an I/O error. Even if there is no "low-level" I/O errors @@ -1983,6 +1982,19 @@ err: only corrupt the slave's databases. So stop. */ file->error= -1; + +#ifndef MYSQL_CLIENT + if (!print_errors) + DBUG_RETURN(res); +#endif + + if (event.length() >= OLD_HEADER_LEN) + sql_print_error("Error in Log_event::read_log_event(): '%s'," + " data_len: %lu, event_type: %u", error, + (ulong) uint4korr(&event[EVENT_LEN_OFFSET]), + (uint) (uchar)event[EVENT_TYPE_OFFSET]); + else + sql_print_error("Error in Log_event::read_log_event(): '%s'", error); } DBUG_RETURN(res); } @@ -1996,7 +2008,8 @@ err: Log_event* Log_event::read_log_event(const char* buf, uint event_len, const char **error, const Format_description_log_event *fdle, - my_bool crc_check) + my_bool crc_check, + my_bool print_errors) { Log_event* ev; enum enum_binlog_checksum_alg alg; @@ -2065,7 +2078,8 @@ Log_event* Log_event::read_log_event(const char* buf, uint event_len, DBUG_RETURN(NULL); #else *error= ER_THD_OR_DEFAULT(current_thd, ER_BINLOG_READ_EVENT_CHECKSUM_FAILURE); - sql_print_error("%s", *error); + if (print_errors) + sql_print_error("%s", *error); DBUG_RETURN(NULL); #endif } diff --git a/sql/log_event.h b/sql/log_event.h index 5cd303e288c..79e24f15751 100644 --- a/sql/log_event.h +++ b/sql/log_event.h @@ -1322,7 +1322,8 @@ public: static Log_event* read_log_event(IO_CACHE* file, const Format_description_log_event *description_event, - my_bool crc_check); + my_bool crc_check, + my_bool print_errors= 1); /** Reads an event from a binlog or relay log. Used by the dump thread @@ -1465,7 +1466,8 @@ public: static Log_event* read_log_event(const char* buf, uint event_len, const char **error, const Format_description_log_event - *description_event, my_bool crc_check); + *description_event, my_bool crc_check, + my_bool print_errors= 1); /** Returns the human readable name of the given event type. */ diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc index 0d2e61f7f59..437c594450d 100644 --- a/sql/sql_repl.cc +++ b/sql/sql_repl.cc @@ -4208,11 +4208,17 @@ bool mysql_show_binlog_events(THD* thd) } } + /* + Omit error messages from server log in Log_event::read_log_event. That + is, we only need to notify the client to correct their 'from' offset; + writing about this in the server log would be confusing as it isn't + related to server operational status. + */ for (event_count = 0; (ev = Log_event::read_log_event(&log, description_event, (opt_master_verify_checksum || - verify_checksum_once))); ) + verify_checksum_once), false)); ) { if (event_count >= limit_start && ev->net_send(protocol, linfo.log_file_name, pos))