[MDEV-32628] Cryptic ERROR message & inconsistent behavior on incorrect SHOW BINLOG EVENTS FROM ... Created: 2023-10-31  Updated: 2023-12-15  Resolved: 2023-11-17

Status: Closed
Project: MariaDB Server
Component/s: Binary Protocol
Affects Version/s: 10.4, 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1, 11.2, 11.3, 11.4
Fix Version/s: 10.4.33, 10.5.24, 10.6.17, 10.11.7, 11.0.5, 11.1.4, 11.2.3

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Brandon Nesterenko
Resolution: Fixed Votes: 0
Labels: affects-tests, sporadic

Issue Links:
Relates
relates to MDEV-21839 Handle crazy offset to SHOW BINLOG EV... Closed

 Description    

# mysqld options required for replay: --log-bin
 
SHOW BINLOG EVENTS FROM 500;

Leads to, on the client:

11.3.0 126157061b4376496c034a809ea4943e863d1465 (Optimized)

 
11.3.0-opt>SHOW BINLOG EVENTS FROM 500;
 
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

Which is easy to understand and correct. However the error log shows, on optimized builds:

11.3.0 126157061b4376496c034a809ea4943e863d1465 (Optimized)

 
2023-10-31 16:00:27 5 [ERROR] Error in Log_event::read_log_event(): 'Event too big', data_len: 117440512, event_type: 0

Here there is no correlation between what actually happened (a harmless SQL statement failure) and the error shown in the error log (which looks like an important binlog failure & possible corruption).
The debug log shows:

11.3.0 126157061b4376496c034a809ea4943e863d1465 (Debug)

 
2023-10-31 15:58:56 5 [ERROR] Replication event checksum verification failed while reading from a log file
 
2023-10-31 15:58:56 5 [ERROR] Error in Log_event::read_log_event(): 'Replication event checksum verification failed while reading from a log file', data_len: 41, event_type: 0

10.4 Optimized shows the same output as debug in later versions:

10.4.32 e52777f1a4df20ffd3ae743b7b64f5e645090cd8 (Optimized)

 
2023-10-31 16:06:21 10 [ERROR] Replication event checksum verification failed while reading from a log file
 
2023-10-31 16:06:21 10 [ERROR] Error in Log_event::read_log_event(): 'Replication event checksum verification failed while reading from a log file', data_len: 41, event_type: 0

Which again looks severe but is harmless. It would be good if we can improve the output to show it was a harmless issue.

 Comments   
Comment by Roel Van de Paar [ 2023-10-31 ]

There are some additional incosistency issues. When using a MTR testcase as follows:

--source include/have_binlog_format_mixed.inc
 
--error ER_ERROR_WHEN_EXECUTING_COMMAND
 
SHOW BINLOG EVENTS FROM 500;

No error shows up in the mariadbd (as started by MTR) error log. Potentially this is due to some MTR internal check mechanism given the MTR output:

11.3.0 126157061b4376496c034a809ea4943e863d1465

 
ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Invalid pos specified. Requested from pos:500 is greater than actual file size:329

However, when using mtr --start-and-exit we see the same error:

./mtr 1st --start-and-exit --mysqld=--log-bin && ../bin/mariadb -uroot -S./var/tmp/mysqld.1.sock test

11.3.0 126157061b4376496c034a809ea4943e863d1465

 
MariaDB [test]> SHOW BINLOG EVENTS FROM 500;
 
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Invalid pos specified. Requested from pos:500 is greater than actual file size:329

As this is the client being used directly, it is odd that the ERROR, whilst the same number is different from the

11.3.0 126157061b4376496c034a809ea4943e863d1465

 
11.3.0-opt>SHOW BINLOG EVENTS FROM 500;
 
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

Seen when using the client directly (without MTR). This could be an additional shortcoming in MTR, especially as here too the error never makes it to the error log, which could mean some failures are being missed in MTR.

Comment by Roel Van de Paar [ 2023-11-02 ]

There is another error which can be reproduced with this testcase at the CLI:

# mysqld options required for replay: --log-bin
 
RESET MASTER;
 
DROP TABLE IF EXISTS t1;
 
CREATE TABLE t1 (c INT) ENGINE=MEMORY;
 
CREATE TABLE t2 (d INT) ENGINE=MyISAM;
 
SHOW BINLOG EVENTS FROM 504;

Leads to:

11.3.0 76e20f00772148fa928c6c6e42401f38ca89abf0 (Optimized or Debug)

 
11.3.0-opt>SHOW BINLOG EVENTS FROM 504;
 
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

The error log in this case reads:

11.3.0 76e20f00772148fa928c6c6e42401f38ca89abf0 (Optimized or Debug)

 
2023-11-02 16:03:58 5 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 139008, event_type: 0

During testing there are also many of other event types that are seen, as can be seen from this non-exhaustive list sorted by event_type:

2023-10-29  1:55:38 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 10496, event_type: 0
 
2023-10-29  9:50:33 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 524288, event_type: 0
 
2023-10-28  4:06:03 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 655360, event_type: 0
 
2023-10-30 12:39:53 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 196608, event_type: 0
 
2023-10-27  6:26:11 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 262144, event_type: 0
 
2023-10-29 11:27:56 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934205, event_type: 2
 
2023-10-28  5:48:07 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 4
 
2023-10-30 18:47:43 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934207, event_type: 4
 
2023-10-26 23:16:55 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 6
 
2023-10-29  5:26:36 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934205, event_type: 8
 
2023-10-28 22:19:31 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 11
 
2023-10-26 23:53:50 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 12
 
2023-10-28 10:59:01 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 12
 
2023-10-27 23:03:24 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 107077, event_type: 16
 
2023-10-27  6:34:39 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 16
 
2023-10-30  8:31:54 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 36
 
2023-10-27 10:06:02 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 38
 
2023-10-30 13:22:50 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934207, event_type: 45
 
2023-10-30 13:22:37 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934207, event_type: 45
 
2023-10-28  8:26:47 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 55
 
2023-10-28  2:44:12 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 61
 
2023-10-30  6:31:11 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 63
 
2023-10-27  8:49:01 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 66
 
2023-10-28 13:22:02 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 67
 
2023-10-30  2:58:10 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 77
 
2023-10-27 17:36:41 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 79
 
2023-10-27 19:07:00 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 80
 
2023-10-26 23:37:28 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 84
 
2023-10-28  8:24:48 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 85
 
2023-10-27  6:08:09 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 90
 
2023-10-27  6:23:49 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 93
 
2023-10-29 22:02:59 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 101
 
2023-10-27  8:00:49 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 110
 
2023-10-28 21:40:10 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 112
 
2023-10-30  5:36:38 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 116
 
2023-10-27 22:38:01 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 120
 
2023-10-30  7:15:34 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 122
 
2023-10-29  9:50:01 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934205, event_type: 135
 
2023-10-26 22:55:35 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 148
 
2023-10-30 20:08:40 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934207, event_type: 162
 
2023-10-29 21:54:10 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 163
 
2023-10-26 22:51:52 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 164
 
2023-10-26 22:46:34 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 166
 
2023-10-28  3:33:43 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 177
 
2023-10-29 22:27:51 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 184
 
2023-10-30  9:08:39 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 186
 
2023-10-29 19:32:05 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 196
 
2023-10-29 18:14:05 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 215
 
2023-10-29  9:31:13 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934205, event_type: 219
 
2023-10-29 22:57:07 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 226
 
2023-10-27  7:04:02 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 232
 
2023-10-27 14:51:53 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 173
 
2023-10-28 15:23:21 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 149
 
2023-10-27 14:33:26 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 196
 
2023-10-29 19:25:35 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 196
 
2023-10-27  9:49:58 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934202, event_type: 215
 
2023-10-28  2:34:42 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934203, event_type: 219
 
2023-10-30  5:30:14 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934206, event_type: 221
 
2023-10-28 11:57:23 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 232
 
2023-10-29 10:20:23 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934205, event_type: 244
 
2023-10-28  7:55:25 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 245
 
2023-10-28 15:25:28 8 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 16934204, event_type: 254

Comment by Roel Van de Paar [ 2023-11-02 ]

Some of these are confirmed sporadic, or are hard to reproduce, or require a specific setup (for example client with direct copy/paste versus any other automated method), etc.

Comment by Andrei Elkin [ 2023-11-02 ]

roel, the matter of the report belongs to MDEV-21839. That fixes idea is still to treat the provided offset as the beginning of an event, try to
find its checksum and verify the event against it. Yet when offset is "super- crazy" so that its checksum field can't be reached, Event too big is un-avoidable.
The error message of course can be improved to suggest about a possibly incorrect offset.

Comment by Kristian Nielsen [ 2023-11-15 ]

Note: Now that gtid indexes (MDEV-4991) will be in 11.4, it is possible to fix this better.
The user-specified offset can be looked up in the index to check that it refers to the start of an event; and a specific error can be given for offsets that are invalid (point into the middle of an event).

Comment by Brandon Nesterenko [ 2023-11-15 ]

Hi Andrei,

This is ready for review: PR-2844

Comment by Andrei Elkin [ 2023-11-16 ]

Approved on GH.

Comment by Brandon Nesterenko [ 2023-11-17 ]

Pushed into 10.4 as c42aadc3.

Merge conflicts observed in 10.6, 11.0, and 11.2 with resolutions in the respective branches:

Generated at Thu Feb 08 10:32:47 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.