Skip to content

Commit c42aadc

Browse files
bnesterebnestere
committed
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>
1 parent f5fdb9c commit c42aadc

File tree

5 files changed

+110
-14
lines changed

5 files changed

+110
-14
lines changed

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

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,21 @@
1+
#
2+
# Initialize test data
3+
set @save_master_verify_checksum = @@global.master_verify_checksum;
4+
set @@global.master_verify_checksum = 1;
5+
create table t1 (a int);
6+
insert into t1 values (1);
7+
insert into t1 values (2);
8+
SHOW BINLOG EVENTS FROM invalid_pos;
9+
ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error
10+
include/assert_grep.inc [Ensure the client error is not in the server log]
11+
SHOW BINLOG EVENTS FROM 500;
12+
ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error
13+
include/assert_grep.inc [Ensure the client error is not in the server log]
14+
SHOW BINLOG EVENTS FROM 498;
15+
ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error
16+
include/assert_grep.inc [Ensure the client error is not in the server log]
17+
include/assert_grep.inc [Ensure there is not a specific checksum failure error]
18+
#
19+
# Cleanup
20+
set @@global.master_verify_checksum = @save_master_verify_checksum;
21+
drop table t1;

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

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,53 @@
1+
#
2+
# Ensure that calling SHOW BINLOG EVENTS FROM <offset> with an invalid offset
3+
# will not result in error messages in the server log. That is, this call is a
4+
# read operation for a user, and if it fails due to invalid usage, that is not
5+
# a server error, but only one to report to the user.
6+
#
7+
# References:
8+
# MDEV-32628: Cryptic ERROR message & inconsistent behavior on incorrect
9+
# SHOW BINLOG EVENTS FROM ...
10+
#
11+
--source include/have_binlog_format_row.inc
12+
13+
--echo #
14+
--echo # Initialize test data
15+
set @save_master_verify_checksum = @@global.master_verify_checksum;
16+
set @@global.master_verify_checksum = 1;
17+
create table t1 (a int);
18+
insert into t1 values (1);
19+
--let $middle_binlog_pos= query_get_value(SHOW BINARY LOGS, File_size, 1)
20+
insert into t1 values (2);
21+
22+
--let $assert_text= Ensure the client error is not in the server log
23+
--let $assert_select= Error in Log_event
24+
--let $assert_file= $MYSQLTEST_VARDIR/log/mysqld.1.err
25+
--let $assert_count= 0
26+
--let $assert_only_after = CURRENT_TEST:
27+
28+
29+
# Pre MDEV-32628, this would write an event truncated error in the logs
30+
--let $invalid_pos= `SELECT $middle_binlog_pos - 1`
31+
--replace_result $invalid_pos invalid_pos
32+
--error 1220
33+
--eval SHOW BINLOG EVENTS FROM $invalid_pos
34+
--source include/assert_grep.inc
35+
36+
# Pre MDEV-32628, this would write an event too big error in the logs
37+
--error 1220
38+
SHOW BINLOG EVENTS FROM 500;
39+
--source include/assert_grep.inc
40+
41+
42+
# Pre MDEV-32628, this would write a checksum verification failed error in the logs
43+
--error 1220
44+
SHOW BINLOG EVENTS FROM 498;
45+
--source include/assert_grep.inc
46+
--let $assert_text= Ensure there is not a specific checksum failure error
47+
--let $assert_select= Replication event checksum verification failed while reading from a log file
48+
--source include/assert_grep.inc
49+
50+
--echo #
51+
--echo # Cleanup
52+
set @@global.master_verify_checksum = @save_master_verify_checksum;
53+
drop table t1;

‎sql/log_event.cc

Lines changed: 25 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1916,7 +1916,8 @@ int Log_event::read_log_event(IO_CACHE* file, String* packet,
19161916

19171917
Log_event* Log_event::read_log_event(IO_CACHE* file,
19181918
const Format_description_log_event *fdle,
1919-
my_bool crc_check)
1919+
my_bool crc_check,
1920+
my_bool print_errors)
19201921
{
19211922
DBUG_ENTER("Log_event::read_log_event(IO_CACHE*,Format_description_log_event*...)");
19221923
DBUG_ASSERT(fdle != 0);
@@ -1955,8 +1956,12 @@ Log_event* Log_event::read_log_event(IO_CACHE* file,
19551956
goto err;
19561957
}
19571958

1959+
/*
1960+
print_errors is false to prevent redundant error messages cluttering up the
1961+
log, as it will be printed below (if _our_ print_errors is true)
1962+
*/
19581963
if ((res= read_log_event(event.ptr(), event.length(),
1959-
&error, fdle, crc_check)))
1964+
&error, fdle, crc_check, false)))
19601965
res->register_temp_buf(event.release(), true);
19611966

19621967
err:
@@ -1967,13 +1972,7 @@ Log_event* Log_event::read_log_event(IO_CACHE* file,
19671972
if (force_opt)
19681973
DBUG_RETURN(new Unknown_log_event());
19691974
#endif
1970-
if (event.length() >= OLD_HEADER_LEN)
1971-
sql_print_error("Error in Log_event::read_log_event(): '%s',"
1972-
" data_len: %lu, event_type: %u", error,
1973-
(ulong) uint4korr(&event[EVENT_LEN_OFFSET]),
1974-
(uint) (uchar)event[EVENT_TYPE_OFFSET]);
1975-
else
1976-
sql_print_error("Error in Log_event::read_log_event(): '%s'", error);
1975+
19771976
/*
19781977
The SQL slave thread will check if file->error<0 to know
19791978
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,
19831982
only corrupt the slave's databases. So stop.
19841983
*/
19851984
file->error= -1;
1985+
1986+
#ifndef MYSQL_CLIENT
1987+
if (!print_errors)
1988+
DBUG_RETURN(res);
1989+
#endif
1990+
1991+
if (event.length() >= OLD_HEADER_LEN)
1992+
sql_print_error("Error in Log_event::read_log_event(): '%s',"
1993+
" data_len: %lu, event_type: %u", error,
1994+
(ulong) uint4korr(&event[EVENT_LEN_OFFSET]),
1995+
(uint) (uchar)event[EVENT_TYPE_OFFSET]);
1996+
else
1997+
sql_print_error("Error in Log_event::read_log_event(): '%s'", error);
19861998
}
19871999
DBUG_RETURN(res);
19882000
}
@@ -1996,7 +2008,8 @@ Log_event* Log_event::read_log_event(IO_CACHE* file,
19962008
Log_event* Log_event::read_log_event(const char* buf, uint event_len,
19972009
const char **error,
19982010
const Format_description_log_event *fdle,
1999-
my_bool crc_check)
2011+
my_bool crc_check,
2012+
my_bool print_errors)
20002013
{
20012014
Log_event* ev;
20022015
enum enum_binlog_checksum_alg alg;
@@ -2065,7 +2078,8 @@ Log_event* Log_event::read_log_event(const char* buf, uint event_len,
20652078
DBUG_RETURN(NULL);
20662079
#else
20672080
*error= ER_THD_OR_DEFAULT(current_thd, ER_BINLOG_READ_EVENT_CHECKSUM_FAILURE);
2068-
sql_print_error("%s", *error);
2081+
if (print_errors)
2082+
sql_print_error("%s", *error);
20692083
DBUG_RETURN(NULL);
20702084
#endif
20712085
}

‎sql/log_event.h

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1322,7 +1322,8 @@ class Log_event
13221322
static Log_event* read_log_event(IO_CACHE* file,
13231323
const Format_description_log_event
13241324
*description_event,
1325-
my_bool crc_check);
1325+
my_bool crc_check,
1326+
my_bool print_errors= 1);
13261327

13271328
/**
13281329
Reads an event from a binlog or relay log. Used by the dump thread
@@ -1465,7 +1466,8 @@ class Log_event
14651466
static Log_event* read_log_event(const char* buf, uint event_len,
14661467
const char **error,
14671468
const Format_description_log_event
1468-
*description_event, my_bool crc_check);
1469+
*description_event, my_bool crc_check,
1470+
my_bool print_errors= 1);
14691471
/**
14701472
Returns the human readable name of the given event type.
14711473
*/

‎sql/sql_repl.cc

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4208,11 +4208,17 @@ bool mysql_show_binlog_events(THD* thd)
42084208
}
42094209
}
42104210

4211+
/*
4212+
Omit error messages from server log in Log_event::read_log_event. That
4213+
is, we only need to notify the client to correct their 'from' offset;
4214+
writing about this in the server log would be confusing as it isn't
4215+
related to server operational status.
4216+
*/
42114217
for (event_count = 0;
42124218
(ev = Log_event::read_log_event(&log,
42134219
description_event,
42144220
(opt_master_verify_checksum ||
4215-
verify_checksum_once))); )
4221+
verify_checksum_once), false)); )
42164222
{
42174223
if (event_count >= limit_start &&
42184224
ev->net_send(protocol, linfo.log_file_name, pos))

0 commit comments

Comments
 (0)