MySQL Bugs: #115861: Issues with strcmp when binlog suffix number exceeds six digits

Bug #115861	Issues with strcmp when binlog suffix number exceeds six digits
Submitted:	19 Aug 2024 13:02	Modified:	13 May 2:01
Reporter:	Wuhao Cao (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.7, 8.0	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	Binlog suffix number, Contribution, Data Inconsistency, Replication delay

Description:
The binlog file naming convention in MySQL utilizes the prefix ‘mysql-bin.’ followed by a suffix number. When the suffix number is within six digits, it is zero-padded to maintain the length (e.g., mysql-bin.000001). However, once the suffix exceeds six digits, the number is not trimmed or padded, resulting in names such as mysql-bin.1000000 (1 followed by six zeros). During master-slave replication, the ActiveTranx::compare function, which is implemented using strcmp, compares the binlog positions. Since strcmp only returns the relationship of the first non-matching character, it may incorrectly determine that mysql-bin.1000000 is less than mysql-bin.999999.

This incorrect comparison can lead to a series of erroneous behaviors, such as the master no longer sending “confirmation-needed” data packets to the slave or waiting for confirmations from the slave. As the master stops waiting for slave acknowledgments, semi-synchronous replication effectively degrades to asynchronous replication, increasing the risk of data inconsistency. Additionally, by omitting the wait time, the master’s QPS increases, potentially causing the slave to lag and resulting in replication delay.

How to repeat:
1.Make the binlog suffix number quickly reach the critical value

i.In the binlog file directory, rename the latest binlog: mv mysql-bin.000002 mysql-bin.999997

ii.Quickly fill up the binlog files until the suffix of the latest binlog is 999998:

mysql> SET GLOBAL max_binlog_size=2*1024*1024;

mysql> CREATE DATABASE test1;
mysql> USE test1;
mysql> CREATE TABLE t1 (
    ->   id INT AUTO_INCREMENT PRIMARY KEY,
    ->   created_at TIMESTAMP DEFAULT CURRENT_TIMESTAMP
    -> );

mysql> DELIMITER //
mysql> CREATE PROCEDURE Insert10000TestData()
    -> BEGIN
    ->   DECLARE counter INT DEFAULT 0;
    ->   WHILE counter < 10000 DO
    ->     INSERT INTO t1 VALUES ();
    ->     SET counter = counter + 1;
    ->   END WHILE;
    -> END//
mysql> DELIMITER ;

mysql> CALL Insert10000TestData();

2.Set up master-slave synchronization with semi-synchronous replication, with the relevant parameters being:

rpl_semi_sync_master_timeout        = 7200000
rpl_semi_sync_master_wait_no_slave  = 1
rpl_semi_sync_master_wait_point     = AFTER_SYNC

binlog_format                       = row

3.Conduct testing through a custom stored procedure:

mysql> SET GLOBAL max_binlog_size=32*1024*1024;

mysql> CREATE DATABASE test2;
mysql> USE test2;
mysql> CREATE TABLE t2 (
    ->   id INT AUTO_INCREMENT PRIMARY KEY,
    ->   created_at TIMESTAMP DEFAULT CURRENT_TIMESTAMP
    -> );

mysql> DELIMITER //
mysql>   CREATE PROCEDURE InsertTestData()
    ->     WHILE true DO
    ->       INSERT INTO t2 VALUES ();
    ->     END WHILE;
    -> //
mysql> DELIMITER ;

mysql> CALL InsertTestData();

During the testing process, pay attention to the binlog suffix situation in the binlog file directory of the master server. Perform two tests around the number 1000000:

i.Execute “STOP SLAVE” on the slave server and observe whether the master server adheres to the principles of semi-synchronous replication:

mysql> STOP SLAVE;
mysql> START SLAVE;

It can be observed that once the suffix sequence number reaches 1,000,000, semi-synchronous replication transitions to asynchronous replication, and stopping the slave (with ‘STOP SLAVE’) will not affect the execution and commit on the master server.

ii.Execute “SHOW SLAVE STATUS\G” on the slave server and observe if there is any master-slave delay:

mysql> SHOW SLAVE STATUS\G

As it can be observed, after the suffix sequence number reaches 1,000,000, the Seconds_Behind_Master gradually increases, indicating that the master-slave latency is continuously growing.

Suggested fix:
In the ActiveTranx::compare function, when comparing the size relationship of binlog suffix sequence numbers, the length of the binlog filenames is compared first; if the lengths are identical, then comparison is made using strcmp.

For example:

int ActiveTranx::compare(const char *log_file_name1, my_off_t log_file_pos1,
			 const char *log_file_name2, my_off_t log_file_pos2)
{
  unsigned int len1 = strlen(log_file_name1);
  unsigned int len2 = strlen(log_file_name2);
  if (len1 > len2)
    return 1;
  else if (len1 < len2)
    return -1;
  
  DBUG_ASSERT(len1 == len2); 
  int cmp = strcmp(log_file_name1, log_file_name2);

  if (cmp != 0)
    return cmp;

  if (log_file_pos1 > log_file_pos2)
    return 1;
  else if (log_file_pos1 < log_file_pos2)
    return -1;
  return 0;
}

Thank you for the report

Fix the bug with comparing binlog suffix numbers of different lengths (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: fix_binlog_compare.patch (application/octet-stream, text), 710 bytes.

Documented fix as follows in the MySQL 8.0.43, 8.4.6, and 9.4.0 changelogs:

    During semisync replication, when the binary log suffix exceeded
    six digits (.999999) so that the next log file became, for
    example, mysql-bin.1000000, the replication protocol changed
    from semisynchronous to asynchronous.

Closed.

Hi Jon,

I’m a bit puzzled about why we didn’t go with the patch mentioned earlier and instead opted to switch semi-sync replication to async. Is there a concern about potential risks or other reasons behind this decision?

Thanks for shedding some light on this!

你好，

I think you have misunderstood. This merely describes the bad behaviour that was corrected. Our standard changelog entry format is:

1. State the problem that was fixed.

2. (OPTIONAL:) If necessary, describe the nature of the fix and/or any side effects the fix may have.

In this case, we have only (1).

多谢你明白了！

jon.

> I think you have misunderstood.

wuhao cao is in good company, because I also misunderstood at the 1st reading, and I have to confess that I was unhappy.  I set that aside for later to think about how to react, and then understood better that this was a statement of "the problem that was fixed".

> the replication protocol changed from semisynchronous to asynchronous

For non-native English speaker, it is very easy to confuse "changed" by "changes" in above.  I would suggest to pay a little more attention to the changelog entry format for such confusion to be less easy to make.  A simple improvement would be to add "incorrectly" (or other disambiguation adverb like those in [1]) to the changelog entry.

[1]: https://www.merriam-webster.com/thesaurus/incorrectly

The improved changelog  entry would read as follow.

"During semisync replication, when the binary log suffix exceeded six digits (.999999) so that the next log file became, for example, mysql-bin.1000000, the replication protocol incorrectly changed from semisynchronous to asynchronous."

Thank you all for your kind replies.

Updated changelog entry:

    During semisync replication, when the length of the binary log
    suffix exceeded six digits (.999999), so that the next log file
    became--for example--mysql-bin.1000000, the replication protocol
    unexpectedly changed from semisynchronous to asynchronous.

    Our thanks to Wuhao Cao for the contribution.

Status unchanged.