Bug #101450 mysqlbinlog with --start-position option not show right FDE position

• Submitted: 4 Nov 2020 6:58
• Modified: 6 Nov 2020 13:32
• Reporter: sifang Zhao (OCA)
• Status: Verified
• Category: MySQL Utilities: Binlog Events
• Severity: S3 (Non-critical)
• OS: Any
• CPU Architecture: Any

[4 Nov 2020 6:58] sifang Zhao

Description:
When specify the --start-position=N to the the events that begin at position N and after, the output doesn't give the right Format_description_log_event start postion. See the difference in `How to repeat section`

The reason for this lay in read_fdle function. Since this function going to work for both binlog and relay-log, after read the first FDE, it continue to read some events(PREVIOUS_GTIDS_LOG_EVENT or ROTATE_EVENT) until it see another FDE or some other event. So if this is a binlog, problem occurs, the code will forward the 
field `m_event_start_pos` that bigger than 4.

How to repeat:
without --start-position

[root@localhost data]# mysqlbinlog --hexdump binlog.000001 | head -n20
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#201103  7:15:08 server id 1  end_log_pos 125 CRC32 0xfc7e724a 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
# 00000004 cc 49 a1 5f   0f   01 00 00 00   79 00 00 00   7d 00 00 00   01 00
# 00000017 04 00 38 2e 30 2e 32 32  2d 64 65 62 75 67 00 00 |..8.0.22.debug..|
# 00000027 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
# 00000037 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
# 00000047 00 00 00 00 cc 49 a1 5f  13 00 0d 00 08 00 00 00 |.....I..........|
# 00000057 00 04 00 04 00 00 00 61  00 04 1a 08 00 00 00 08 |.......a........|
# 00000067 08 08 02 00 00 00 0a 0a  0a 2a 2a 00 12 34 00 0a |.............4..|
# 00000077 28 01 4a 72 7e fc                                |..Jr..|
# 	Start: binlog v 4, server v 8.0.22-debug created 201103  7:15:08 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
zEmhXw8BAAAAeQAAAH0AAAABAAQAOC4wLjIyLWRlYnVnAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAADMSaFfEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA
[root@localhost data]# 

with --start-position

[root@localhost data]#  mysqlbinlog --start-position=523 binlog.000001 | head -n20
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 156
#201103  7:15:08 server id 1  end_log_pos 125 CRC32 0xfc7e724a 	Start: binlog v 4, server v 8.0.22-debug created 201103  7:15:08 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
zEmhXw8BAAAAeQAAAH0AAAABAAQAOC4wLjIyLWRlYnVnAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAADMSaFfEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA
CigBSnJ+/A==
'/*!*/;
# at 523
#201103  7:22:30 server id 1  end_log_pos 640 CRC32 0x048ab7b8 	Query	thread_id=11	exec_time=0	error_code=0	Xid = 10
SET TIMESTAMP=1604406150/*!*/;
SET @@session.pseudo_thread_id=11/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
[root@localhost data]# 

Suggested fix:
--- a/sql/binlog_reader.h
+++ b/sql/binlog_reader.h
@@ -377,6 +377,8 @@ class Basic_binlog_file_reader {
       [Rotate_event]           : In the case rotating relaylog, no Rotate here
       Format_description_event : master's Format_description_event
     */
+    int fdl_cnt = 0;
+    my_off_t first_fde_pos = position();
     while (position() < offset) {
       m_event_start_pos = position();
 
@@ -385,6 +387,7 @@ class Basic_binlog_file_reader {
 
       if (ev == nullptr) break;
       if (ev->get_type_code() == binary_log::FORMAT_DESCRIPTION_EVENT) {
+        fdl_cnt++;
         delete fdle;
         fdle = dynamic_cast<Format_description_log_event *>(ev);
         m_fde = *fdle;
@@ -400,6 +403,9 @@ class Basic_binlog_file_reader {
       delete fdle;
       return nullptr;
     }
+    if (fdl_cnt == 1 && first_fde_pos != m_event_start_pos) {
+      m_event_start_pos = first_fde_pos;
+    }
     return fdle;
   }
 };

[6 Nov 2020 5:06] MySQL Verification Team

Thank you very much for your patch contribution, we appreciate it!

In order for us to continue the process of reviewing your contribution to MySQL, please send us a signed copy of the Oracle Contributor Agreement (OCA) as outlined in http://www.oracle.com/technetwork/community/oca-486395.html

Signing an OCA needs to be done only once and it's valid for all other Oracle governed Open Source projects as well.

Getting a signed/approved OCA on file will help us facilitate your contribution - this one, and others in the future.  

Please let me know, if you have any questions.

Thank you for your interest in MySQL.

[6 Nov 2020 11:52] sifang Zhao

Hi,

I've already send the signed OCA to [e-mail].

Please help to check ;)

[10 Nov 2020 18:57] Omer Barnir

Thanks - OCA received

[17 Nov 2020 18:08] OCA Admin

Contribution submitted via Github - Bug#101450 mysqlbinlog with start-position not show right FDE pos 
(*) Contribution by sifang Zhao (Github zhjwpku, mysql-server/pull/313#issuecomment-728677624): I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: git_patch_515744310.txt (text/plain), 4.34 KiB.