MDEV-32628: Cryptic ERROR message & inconsistent behavior on incorrect SHOW BINLOG EVENTS FROM ...

Calling SHOW BINLOG EVENTS FROM <offset> with an invalid offset
writes error messages into the server log about invalid reads. The
read errors that occur from this command should only be relayed back
to the user though, and not written into the server log. This is
because they are read-only and have no impact on server operation,
and the client only need be informed to correct the parameter.

This patch fixes this by omitting binary log read errors from the
server when the invocation happens from SHOW BINLOG EVENTS.
Additionally, redundant error messages are omitted when calling the
string based read_log_event from the IO_Cache based read_log_event,
as the later already will report the error of the former.

Reviewed By:
============
Kristian Nielsen <knielsen@knielsen-hq.org>
Andrei Elkin <andrei.elkin@mariadb.com>

mysql-test/suite/binlog/r/binlog_show_binlog_events_invalid_offset_silent.result

+#
+# 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;

mysql-test/suite/binlog/t/binlog_show_binlog_events_invalid_offset_silent.test

+#
+#   Ensure that calling SHOW BINLOG EVENTS FROM <offset> 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;

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 @@ Log_event* Log_event::read_log_event(IO_CACHE* file,
     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 @@ Log_event* Log_event::read_log_event(IO_CACHE* file,
       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 @@ Log_event* Log_event::read_log_event(IO_CACHE* file,
 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
   }

sql/log_event.h

@@ -1322,7 +1322,8 @@ class Log_event
   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 @@ class Log_event
   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.
   */

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))