MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when --stop-datetime is specified #3670

XiaochuanCui · 2024-11-30T01:21:11Z

Description

Fix regression introduced by commits 9588526 and 242b67f which attempted to address MDEV-27037. With the regression, mariadb-binlog cannot process multiple log files when --stop-datetime is specified.

Remove the code to set retval as OK_STOP if mariadb-binlog finished processing current log file but not reached specified --stop-datetime or --stop-position, to make it possible to continue process following log files.

Release Notes

N/A

How can this PR be tested?

The change in PR has been manually tested to verify that it can process multiple log files for command like below:

mariadb-binlog --stop-datetime="2024-11-30 18:52:00" mariadb-bin.000001 mariadb-bin.000002 mariadb-bin.000003

While before the change, the same command can only process the first log file.

Basing the PR against the correct MariaDB version

This change should apply to all minor versions these 2 commits 9588526 and 242b67f are merged in

Copyright

All new code of the whole pull request, including one or several files that are either new files or modified ones, are contributed under the BSD-new license. I am contributing on behalf of my employer Amazon Web Services, Inc.

…-stop-datetime is specified Fix regression introduced by commits 9588526 and 242b67f which attempted to address MDEV-27037. With the regression, mariadb-binlog cannot process multiple log files when --stop-datetime is specified. Remove the code to set retval as OK_STOP if mariadb-binlog finished processing current log file but not reached specified --stop-datetime or --stop-position, to make it possible to continue process following log files. All new code of the whole pull request, including one or several files that are either new files or modified ones, are contributed under the BSD-new license. I am contributing on behalf of my employer Amazon Web Services, Inc.

CLAassistant · 2024-11-30T01:21:21Z

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
_{You have signed the CLA already but the status is still pending? Let us recheck it.}

bnestere

Hi @XiaochuanCui , thank you for a great report, as well as taking on the fix 😄

See my note below; also, I've also taken some liberty and adjusted our MTR tests to account for this regression, that I'd like you to apply. Test cases 2.d, 2.e, and 2.f are best effort, as I don't have a fix and wasn't able to validate them, but please adjust if needed (as well as extend/enhance in any other ways you may see fit). It was taken with git diff, which you should be able to copy-paste into a file (say mdev_35528.patch) and apply as git apply mdev_35528.patch.

diff --git a/mysql-test/suite/binlog/r/binlog_mysqlbinlog_warn_stop_datetime.result b/mysql-test/suite/binlog/r/binlog_mysqlbinlog_warn_stop_datetime.result
deleted file mode 100644
index 6ce0f2d63e5..00000000000
--- a/mysql-test/suite/binlog/r/binlog_mysqlbinlog_warn_stop_datetime.result
+++ /dev/null
@@ -1,23 +0,0 @@
-
-# MDEV-27037 mysqlbinlog emits a warning when reaching EOF before stop-datetime
-
-set timestamp=1000000000;
-CREATE TABLE t1(word VARCHAR(20));
-set timestamp=1000000010;
-INSERT INTO t1 VALUES ("abirvalg");
-set timestamp=1000000020;
-INSERT INTO t1 SELECT * FROM t1;
-flush logs;
-Case: Default, must not see warning.
-# MYSQL_BINLOG --short-form MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
-Case: Stop datetime before EOF, must not see warning.
-# MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:50' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
-Case: Stop datetime between records, must not see warning.
-# MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:55' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
-Case: Stop datetime at EOF, must not see warning.
-# MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:55' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
-Case: Stop datetime after EOF, must see warning.
-# MYSQL_BINLOG --short-form --stop-datetime='2035-01-19 03:14:05' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
-WARNING: Did not reach stop datetime '2035-01-19 03:14:05' before end of input
-DROP TABLE t1;
-# End of binlog_mysqlbinlog_warn_stop_datetime.test
diff --git a/mysql-test/suite/binlog/r/binlog_mysqlbinlog_warn_stop_position.result b/mysql-test/suite/binlog/r/binlog_mysqlbinlog_warn_stop_position.result
deleted file mode 100644
index 5b99d30bd84..00000000000
--- a/mysql-test/suite/binlog/r/binlog_mysqlbinlog_warn_stop_position.result
+++ /dev/null
@@ -1,13 +0,0 @@
-
-# MDEV-27037 mysqlbinlog emits a warning when reaching EOF before stop-condition
-
-Case: Default stop position, WARNING must not appear
-# MYSQL_BINLOG --short-form --start-position=4 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
-Case: Stop position before EOF, WARNING must not appear
-# MYSQL_BINLOG --short-form --start-position=4 --stop-position=97 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
-Case: Stop position at EOF, WARNING must not appear
-# MYSQL_BINLOG --short-form --start-position=4 --stop-position=98 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
-Case: Stop position after EOF, WARNING must appear
-# MYSQL_BINLOG --short-form --start-position=4 --stop-position=99 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
-WARNING: Did not reach stop position 99 before end of input
-# End of binlog_mysqlbinlog_warn_stop_position.test
diff --git a/mysql-test/suite/binlog/t/binlog_mysqlbinlog_warn_stop_datetime.test b/mysql-test/suite/binlog/t/binlog_mysqlbinlog_warn_stop_datetime.test
deleted file mode 100644
index 9d30544c5f4..00000000000
--- a/mysql-test/suite/binlog/t/binlog_mysqlbinlog_warn_stop_datetime.test
+++ /dev/null
@@ -1,42 +0,0 @@
---echo
---echo # MDEV-27037 mysqlbinlog emits a warning when reaching EOF before stop-datetime
---echo
-
---source include/have_binlog_format_statement.inc
-
---let ignored_output_file= $MYSQLTEST_VARDIR/tmp/warn_pos_test_file.out
-
-set timestamp=1000000000;
-CREATE TABLE t1(word VARCHAR(20));
-set timestamp=1000000010;
-INSERT INTO t1 VALUES ("abirvalg");
-set timestamp=1000000020;
-INSERT INTO t1 SELECT * FROM t1;
---let MYSQLD_DATADIR= `select @@datadir;`
-flush logs;
-
---echo Case: Default, must not see warning.
---echo # MYSQL_BINLOG --short-form MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
---exec $MYSQL_BINLOG --short-form $MYSQLD_DATADIR/master-bin.000001 --result-file=$ignored_output_file 2>&1
-
---echo Case: Stop datetime before EOF, must not see warning.
---echo # MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:50' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
---exec $MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:50' $MYSQLD_DATADIR/master-bin.000001 --result-file=$ignored_output_file 2>&1
-
---echo Case: Stop datetime between records, must not see warning.
---echo # MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:55' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
---exec $MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:55' $MYSQLD_DATADIR/master-bin.000001 --result-file=$ignored_output_file 2>&1
-
---echo Case: Stop datetime at EOF, must not see warning.
---echo # MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:55' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
---exec $MYSQL_BINLOG --short-form --stop-datetime='2001-09-08 21:46:55' $MYSQLD_DATADIR/master-bin.000001 --result-file=$ignored_output_file 2>&1
-
---echo Case: Stop datetime after EOF, must see warning.
---echo # MYSQL_BINLOG --short-form --stop-datetime='2035-01-19 03:14:05' MYSQLD_DATADIR/master-bin.000001 --result-file=ignored_output_file
---exec $MYSQL_BINLOG --short-form --stop-datetime='2035-01-19 03:14:05' $MYSQLD_DATADIR/master-bin.000001 --result-file=$ignored_output_file 2>&1
-
-DROP TABLE t1;
-
---remove_file $ignored_output_file
-
---echo # End of binlog_mysqlbinlog_warn_stop_datetime.test
diff --git a/mysql-test/suite/binlog/t/binlog_mysqlbinlog_warn_stop_position.test b/mysql-test/suite/binlog/t/binlog_mysqlbinlog_warn_stop_position.test
index 97fabfc6513..0bc63606938 100644
--- a/mysql-test/suite/binlog/t/binlog_mysqlbinlog_warn_stop_position.test
+++ b/mysql-test/suite/binlog/t/binlog_mysqlbinlog_warn_stop_position.test
@@ -1,26 +1,211 @@
 --echo
 --echo # MDEV-27037 mysqlbinlog emits a warning when reaching EOF before stop-condition
 --echo
+--source include/have_binlog_format_row.inc
 
---let assert_file= $MYSQLTEST_VARDIR/tmp/warn_pos_test_file.out
---let data_file= $MYSQLTEST_VARDIR/std_data/master-bin.000001
+--let $binlog_out_relpath=tmp/warn_pos_test_file.out
+--let $binlog_out= $MYSQLTEST_VARDIR/$binlog_out_relpath
 
---echo Case: Default stop position, WARNING must not appear
---echo # MYSQL_BINLOG --short-form --start-position=4 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
---exec $MYSQL_BINLOG --short-form --start-position=4 $data_file --result-file=$assert_file 2>&1
+--let $b1_timestamp1= 2024-12-01 10:20:30.123456
+--let $b1_timestamp2= 2024-12-02 10:20:30.123456
+--let $b1_timestamp3= 2024-12-03 10:20:30.123456
+--let $b2_timestamp1= 2024-12-04 10:20:30.123456
+--let $b2_timestamp2= 2024-12-05 10:20:30.123456
+--let $b2_timestamp3= 2024-12-06 10:20:30.123456
+--let $b2_timestamp_not_reached= 2024-12-07 10:20:30.123456
+--eval SET TIMESTAMP=UNIX_TIMESTAMP('$b1_timestamp1')
+--let $binlog_f1=  query_get_value(SHOW MASTER STATUS, File, 1)
+create table t1 (a int);
+insert into t1 values (1);
+--eval SET TIMESTAMP=UNIX_TIMESTAMP('$b1_timestamp2')
+insert into t1 values (2);
+--eval SET TIMESTAMP=UNIX_TIMESTAMP('$b1_timestamp3')
+--let $binlog_f1_pre_rotate= query_get_value(SHOW MASTER STATUS, Position, 1)
+flush binary logs;
+--let $binlog_f2=  query_get_value(SHOW MASTER STATUS, File, 1)
+--eval SET TIMESTAMP=UNIX_TIMESTAMP('$b2_timestamp1')
+insert into t1 values (3);
+--echo # Tag binlog_f2_mid
+--let $binlog_f2_mid= query_get_value(SHOW MASTER STATUS, Position, 1)
+insert into t1 values (4);
+--eval SET TIMESTAMP=UNIX_TIMESTAMP('$b2_timestamp2')
+--let $binlog_f2_gtid_after_midpoint= `SELECT @@GLOBAL.gtid_binlog_pos`
+insert into t1 values (5);
+insert into t1 values (6);
+insert into t1 values (7);
+--let $binlog_f2_last_gtid= `SELECT @@GLOBAL.gtid_binlog_pos`
+--let $binlog_f2_pre_rot= query_get_value(SHOW MASTER STATUS, Position, 1)
+--eval SET TIMESTAMP=UNIX_TIMESTAMP('$b2_timestamp3')
+flush binary logs;
+drop table t1;
 
---echo Case: Stop position before EOF, WARNING must not appear
---echo # MYSQL_BINLOG --short-form --start-position=4 --stop-position=97 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
---exec $MYSQL_BINLOG --short-form --start-position=4 --stop-position=97 $data_file --result-file=$assert_file 2>&1
 
---echo Case: Stop position at EOF, WARNING must not appear
---echo # MYSQL_BINLOG --short-form --start-position=4 --stop-position=98 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
---exec $MYSQL_BINLOG --short-form --start-position=4 --stop-position=98 $data_file --result-file=$assert_file 2>&1
+--let $binlog_f1_show= query_get_value(SHOW BINARY LOGS, Log_name, 1)
+--let $binlog_f1_end= query_get_value(SHOW BINARY LOGS, File_size, 1)
+if (`SELECT strcmp('$binlog_f1','$binlog_f1_show') != 0`)
+{
+  --echo # Real binlog_f1: $binlog_f1
+  --echo # First binlog in SHOW BINLOG FILES: $binlog_f1_show
+  --die Wrong order of binary log files in SHOW BINARY LOGS
+}
+--let $binlog_f2_show= query_get_value(SHOW BINARY LOGS, Log_name, 2)
+--let $binlog_f2_end= query_get_value(SHOW BINARY LOGS, File_size, 2)
+if (`SELECT strcmp('$binlog_f2','$binlog_f2_show') != 0`)
+{
+  --echo # Real binlog_f2: $binlog_f2
+  --echo # First binlog in SHOW BINLOG FILES: $binlog_f2_show
+  --die Wrong order of binary log files in SHOW BINARY LOGS
+}
 
---echo Case: Stop position after EOF, WARNING must appear
---echo # MYSQL_BINLOG --short-form --start-position=4 --stop-position=99 mysql-test/std_data/master-bin.000001 --result-file=warn_pos_test_file.out 2>&1
---exec $MYSQL_BINLOG --short-form --start-position=4 --stop-position=99 $data_file --result-file=$assert_file 2>&1
+--let $MYSQLD_DATADIR= `select @@datadir`
 
---remove_file $assert_file
+--echo #
+--echo # --stop-position tests
+--echo #
+
+--echo #  Case 1.a) With one binlog file, a --stop-position before the end of
+--echo # the file should not result in a warning
+--echo # MYSQL_BINLOG --stop-position=binlog_f1_pre_rotate MYSQLD_DATADIR/binlog_f1 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-position=$binlog_f1_pre_rotate $MYSQLD_DATADIR/$binlog_f1 --result-file=$binlog_out 2>&1
+
+--echo #  Case 1.b) With one binlog file, a --stop-position at the exact end of
+--echo # the file should not result in a warning
+--echo # MYSQL_BINLOG --stop-position=binlog_f1_end MYSQLD_DATADIR/binlog_f1 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-position=$binlog_f1_end $MYSQLD_DATADIR/$binlog_f1 --result-file=$binlog_out 2>&1
+
+--echo #  Case 1.c) With one binlog file, a --stop-position past the end of the
+--echo # file should(!) result in a warning
+--let $binlog_f1_over_eof= `SELECT $binlog_f1_end + 10`
+--echo # MYSQL_BINLOG --short-form --stop-position=binlog_f1_over_eof MYSQLD_DATADIR/binlog_f1 --result-file=$binlog_out_relpath 2>&1
+--replace_result $binlog_f1_over_eof <BINLOG_F1_OVER_EOF>
+--exec $MYSQL_BINLOG --short-form --stop-position=$binlog_f1_over_eof $MYSQLD_DATADIR/$binlog_f1 --result-file=$binlog_out 2>&1
+
+--echo #  Case 1.d) With two binlog files, a --stop-position targeting b2 which
+--echo # exists in the size of b1 should:
+--echo #    1) not provide any warnings
+--echo #    2) not prevent b2 from outputting its desired events before the
+--echo #       stop position
+
+--echo # Ensuring binlog_f2_mid < binlog_f1_end
+if ($binlog_f2_mid > $binlog_f1_end)
+{
+  --echo # Binlog 1 end: $binlog_f1:$binlog_f1_end
+  --echo # Binlog 2 stop point: $binlog_f2:$binlog_f2_mid
+  --die Mid point chosen to end in binlog 2 does not exist in earlier binlog
+}
+
+--echo # MYSQL_BINLOG --stop-position=binlog_f2_mid MYSQLD_DATADIR/binlog_f1 MYSQLD_DATADIR/binlog_f2 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-position=$binlog_f2_mid $MYSQLD_DATADIR/$binlog_f1 $MYSQLD_DATADIR/$binlog_f2 --result-file=$binlog_out 2>&1
+
+--let $server_id= `SELECT @@GLOBAL.server_id`
+--let $domain_id= `SELECT @@GLOBAL.gtid_domain_id`
+--let $assert_file= $binlog_out
+--let $assert_text= Ensure all intended GTIDs are present
+--let $assert_select= GTID $domain_id-$server_id-
+--let $assert_count= 4
+--source include/assert_grep.inc
+
+--let $assert_text= Ensure the next GTID binlogged is _not_ present
+--let $assert_select= GTID $binlog_f2_gtid_after_midpoint
+--let $assert_count= 0
+--source include/assert_grep.inc
+
+--echo #  Case 1.e) With two binlog files, a --stop-position targeting the end
+--echo # of binlog 2 should:
+--echo #    1) not provide any warnings
+--echo #    2) not prevent b2 from outputting its entire binary log
+--echo # MYSQL_BINLOG --stop-position=binlog_f2_end MYSQLD_DATADIR/binlog_f1 MYSQLD_DATADIR/binlog_f2 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-position=$binlog_f2_end $MYSQLD_DATADIR/$binlog_f1 $MYSQLD_DATADIR/$binlog_f2 --result-file=$binlog_out 2>&1
+
+--let $server_id= `SELECT @@GLOBAL.server_id`
+--let $domain_id= `SELECT @@GLOBAL.gtid_domain_id`
+--let $assert_text= Ensure a GTID exists for each transaction
+--let $assert_select= GTID $domain_id-$server_id-
+--let $assert_count= 8
+--source include/assert_grep.inc
+
+--let $assert_text= Ensure the last GTID binlogged is present
+--let $assert_select= GTID $binlog_f2_last_gtid
+--let $assert_count= 1
+--source include/assert_grep.inc
+
+--echo #  Case 1.f) With two binlog files, a --stop-position targeting beyond
+--echo # the eof of binlog 2 should:
+--echo #    1) provide a warning that the stop position was not reached
+--echo #    2) not prevent b2 from outputting its entire binary log
+--let $binlog_f2_over_eof= `SELECT $binlog_f2_end + 10`
+--echo # MYSQL_BINLOG --stop-position=binlog_f2_over_eof MYSQLD_DATADIR/binlog_f1 MYSQLD_DATADIR/binlog_f2 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-position=$binlog_f2_over_eof $MYSQLD_DATADIR/$binlog_f1 $MYSQLD_DATADIR/$binlog_f2 --result-file=$binlog_out 2>&1
+
+--let $server_id= `SELECT @@GLOBAL.server_id`
+--let $domain_id= `SELECT @@GLOBAL.gtid_domain_id`
+--let $assert_text= Ensure a GTID exists for each transaction
+--let $assert_select= GTID $domain_id-$server_id-
+--let $assert_count= 8
+--source include/assert_grep.inc
+
+
+--echo #
+--echo # --stop-datetime tests
+--echo # Note: MDEV-35528 reported that mysqlbinlog would fail on tests cases
+--echo # 2.4, 2.5, and 2.6.
+--echo #
+
+--echo #  Case 2.a) With one binlog file, a --stop-datetime before the end of
+--echo # the file should not result in a warning
+--echo # MYSQL_BINLOG --stop-datetime='$b1_timestamp2' MYSQLD_DATADIR/binlog_f1 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-datetime='$b1_timestamp2' $MYSQLD_DATADIR/$binlog_f1 --result-file=$binlog_out 2>&1
+
+--echo #  Case 2.b) With one binlog file, a --stop-datetime at the end of the
+--echo # file should not result in a warning
+--echo # MYSQL_BINLOG --stop-datetime='$b1_timestamp3' MYSQLD_DATADIR/binlog_f1 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-datetime='$b1_timestamp3' $MYSQLD_DATADIR/$binlog_f1 --result-file=$binlog_out 2>&1
+
+--echo #  Case 2.c) With one binlog file, a --stop-datetime beyond the end of
+--echo # the file should(!) result in a warning
+--echo # MYSQL_BINLOG --stop-datetime='$b2_timestamp1' MYSQLD_DATADIR/binlog_f1 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-datetime='$b2_timestamp1' $MYSQLD_DATADIR/$binlog_f1 --result-file=$binlog_out 2>&1
+
+--echo #  Case 2.d) With two binlog files, a --stop-datetime within the
+--echo # timespan of binlog 2 should:
+--echo #    1) not provide any warnings
+--echo #    2) not prevent binlog 1 or 2 from outputting the desired events
+
+--echo # MYSQL_BINLOG --stop-datetime='$b2_timestamp2' MYSQLD_DATADIR/binlog_f1 MYSQLD_DATADIR/binlog_f2 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-datetime='$b2_timestamp2' $MYSQLD_DATADIR/$binlog_f1 $MYSQLD_DATADIR/$binlog_f2 --result-file=$binlog_out 2>&1
+
+--let $assert_text= Ensure all intended GTIDs are present
+--let $assert_select= GTID $domain_id-$server_id-
+--let $assert_count= 4
+--source include/assert_grep.inc
+
+--let $assert_text= Ensure the next GTID binlogged is _not_ present
+--let $assert_select= GTID $binlog_f2_gtid_after_midpoint
+--let $assert_count= 0
+--source include/assert_grep.inc
+
+--echo #  Case 2.e) With two binlog files, a --stop-datetime at the end of
+--echo # binlog 2 should:
+--echo #    1) not provide any warnings
+--echo #    2) not prevent binlog 1 or 2 from outputting all events
+--echo # MYSQL_BINLOG --stop-datetime='$b2_timestamp3' MYSQLD_DATADIR/binlog_f1 MYSQLD_DATADIR/binlog_f2 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-datetime='$b2_timestamp3' $MYSQLD_DATADIR/$binlog_f1 $MYSQLD_DATADIR/$binlog_f2 --result-file=$binlog_out 2>&1
+
+--let $assert_text= Ensure a GTID exists for each transaction
+--let $assert_select= GTID $domain_id-$server_id-
+--let $assert_count= 8
+--source include/assert_grep.inc
+
+--echo #  Case 2.f) With two binlog files, a --stop-datetime beyond the end of
+--echo # binlog 2 should:
+--echo #    1) provide a warning that the stop datetime was not reached
+--echo #    2) not prevent binlog 1 or 2 from outputting all events
+--echo # MYSQL_BINLOG --stop-datetime='$b2_timestamp3' MYSQLD_DATADIR/binlog_f1 MYSQLD_DATADIR/binlog_f2 --result-file=$binlog_out_relpath 2>&1
+--exec $MYSQL_BINLOG --stop-datetime='$b2_timestamp3' $MYSQLD_DATADIR/$binlog_f1 $MYSQLD_DATADIR/$binlog_f2 --result-file=$binlog_out 2>&1
+
+--let $assert_text= Ensure a GTID exists for each transaction
+--let $assert_select= GTID $domain_id-$server_id-
+--let $assert_count= 8
+--source include/assert_grep.inc
 
 --echo # End of binlog_mysqlbinlog_warn_stop_position.test

bnestere · 2024-11-30T16:47:50Z

client/mysqlbinlog.cc

@@ -2948,7 +2948,6 @@ static Exit_status dump_local_log_entries(PRINT_EVENT_INFO *print_event_info,
      if (((longlong)stop_position != stop_position_default) &&
          stop_position > my_b_tell(file))
      {
-          retval = OK_STOP;


--stop-position actually isn't broken. Looking in the main() loop, before iterating the binary log files, the input stop position is saved as save_stop_position, and then on the last binary log, stop_position is reset to the value, so stop_position is only applied to the last binary log. We can't follow that pattern for --stop-datetime though, as that is applicable to all binary logs passed in (whereas --stop-position is only valid for the last log). So instead, I think we either need to

Have a global flag for is_last_log (set when save_stop_position is restored in main()), and restrict the stop_datetime check to also check that, or

Move these error messages to happen after the dump_log_entries() loop, and cache the last read stop_position and stop_datetime (when applicable) to compare against.

I'm ok either way, and also open to other ideas. Though the removal of this OK_STOP is problematic for --stop-datetime, as it will output warnings at the end of each log, and continue processing.

Hi @bnestere, Thank you for your quick feedback. I have several questions on your comments. Could you take a look?

Agree that --stop-position is not impacted since the check only applies to last file, but do you think it makes sense to still remove the line retval = OK_STOP for stop_position check given the definition for OK_STOP is not same as this situation.

Also agree that simply removing OK_STOP is not good for --stop-datetime due to warnings for each file (Good catch). I prefer option 1 to add a global variable is_last_log, and I will go ahead to add the logic. Again, do you agree that we should remove retval = OK_STOP?

Thanks for modifying tests to cover cases for multiple files. Just want to confirm is it fine to combine cases for stop-position and stop-datetime to one file as in your change, given we want to reuse same preset binlog files. Also do you expect us to create result file accordingly since both result files are deleted in the change?

We will publish a new revision once these are clarified. Thanks for your comments!

In looking to answer your questions 1 & 2, I was going through the old PR's discussion around this (here, for reference); and I'm thinking we should go with option 2 actually:

Move these error messages to happen after the dump_log_entries() loop, and cache the last read stop_position and stop_datetime (when applicable) to compare against

because it

is more general (i.e. it will apply to dump_remote_log_entries() as well, though we should extend the test with that. Though I can take it on, and the current test I provided is fine enough for you to get started on coding (although you're welcome to take it on as well, if you'd prefer)),

is more consistent with where one would expect to find the warning (i.e. a warning about last thing processed would make sense to be checked only after all logs have been processed, rather than after each log has been processed, and

lessens the number of conditionals (always good 😄)

Note the reason this wasn't done initially, is that the original thought was to use condition retval != OK_STOP; however, retval can be changed after it is set to OK_STOP (at the end of dump_local_log_entries(), so the warning might be swallowed. But if we cache the last binlog position and event time, then we won't worry about the retval status being swallowed).

Then to your third question: correct, let's just have them in the same file for consistency.

hi @bnestere , that makes sense.

I will go ahead to make changes in dump_local_log_entries to keep tracking last position and datetime with 2 new global variables. And after the dump_log_entries loop, decide if need to emit the warning based on those and requested --stop_position and --stop_datetime. As you said, your test cases will help validate the change.

For dump_remote_log_entries, it is not that clear for me at which point we should track last position and datetime after reading code, and not sure how to test, so I will not modify that for now, but I will make sure for the check after dump_log_entries loop, it will not emit warning for dump_remote_log_entries, which is same as current implementation.

Thanks @XiaochuanCui !

As to

For dump_remote_log_entries, it is not that clear for me at which point we should track last position and datetime after reading code

I think both local and remote can use the same spot. That is, in process_event(), at the end label:

end: rec_count++; // here

Then here are updated test files that should verify both local and remote behavior. All I did was split the actual validation checks into a .inc file with a parameter use_local_logs, which sets mysqlbinlog up to either use local logs, or use --read-from-remote-server.

mysql-test/suite/rpl/t/binlog_mysqlbinlog_warn_stop_position.test:

# # Test ensures that stop conditions (--stop-position and --stop-datetime) # work correctly for mysqlbinlog. This high level test sets up the binary log # (and tags certain locations for comparison), and the helper file # binlog_mysqlbinlog_warn_stop_position.inc performs the actual tests. # # References: # MDEV-27037: mysqlbinlog emits a warning when reaching EOF before # stop-condition # MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when # --stop-datetime is specified # --source include/have_binlog_format_row.inc --let $binlog_out_relpath=tmp/warn_pos_test_file.out --let $binlog_out= $MYSQLTEST_VARDIR/$binlog_out_relpath --let $b1_timestamp1= 2024-12-01 10:20:30.123456 --let $b1_timestamp2= 2024-12-02 10:20:30.123456 --let $b1_timestamp3= 2024-12-03 10:20:30.123456 --let $b2_timestamp1= 2024-12-04 10:20:30.123456 --let $b2_timestamp2= 2024-12-05 10:20:30.123456 --let $b2_timestamp3= 2024-12-06 10:20:30.123456 --let $b2_timestamp_not_reached= 2024-12-07 10:20:30.123456 --eval SET TIMESTAMP=UNIX_TIMESTAMP('$b1_timestamp1') --let $binlog_f1= query_get_value(SHOW MASTER STATUS, File, 1) create table t1 (a int); insert into t1 values (1); --eval SET TIMESTAMP=UNIX_TIMESTAMP('$b1_timestamp2') insert into t1 values (2); --eval SET TIMESTAMP=UNIX_TIMESTAMP('$b1_timestamp3') --let $binlog_f1_pre_rotate= query_get_value(SHOW MASTER STATUS, Position, 1) flush binary logs; --let $binlog_f2= query_get_value(SHOW MASTER STATUS, File, 1) --eval SET TIMESTAMP=UNIX_TIMESTAMP('$b2_timestamp1') insert into t1 values (3); --echo # Tag binlog_f2_mid --let $binlog_f2_mid= query_get_value(SHOW MASTER STATUS, Position, 1) insert into t1 values (4); --eval SET TIMESTAMP=UNIX_TIMESTAMP('$b2_timestamp2') --let $binlog_f2_gtid_after_midpoint= `SELECT @@GLOBAL.gtid_binlog_pos` insert into t1 values (5); insert into t1 values (6); insert into t1 values (7); --let $binlog_f2_last_gtid= `SELECT @@GLOBAL.gtid_binlog_pos` --let $binlog_f2_pre_rot= query_get_value(SHOW MASTER STATUS, Position, 1) --eval SET TIMESTAMP=UNIX_TIMESTAMP('$b2_timestamp3') flush binary logs; drop table t1; --echo # Ensuring binary log order is correct --let $binlog_f1_show= query_get_value(SHOW BINARY LOGS, Log_name, 1) --let $binlog_f1_end= query_get_value(SHOW BINARY LOGS, File_size, 1) if (`SELECT strcmp('$binlog_f1','$binlog_f1_show') != 0`) { --echo # Real binlog_f1: $binlog_f1 --echo # First binlog in SHOW BINLOG FILES: $binlog_f1_show --die Wrong order of binary log files in SHOW BINARY LOGS } --let $binlog_f2_show= query_get_value(SHOW BINARY LOGS, Log_name, 2) --let $binlog_f2_end= query_get_value(SHOW BINARY LOGS, File_size, 2) if (`SELECT strcmp('$binlog_f2','$binlog_f2_show') != 0`) { --echo # Real binlog_f2: $binlog_f2 --echo # First binlog in SHOW BINLOG FILES: $binlog_f2_show --die Wrong order of binary log files in SHOW BINARY LOGS } --echo # Ensuring file offset of binlog_f2_mid < binlog_f1_end (see test 1.d) if ($binlog_f2_mid > $binlog_f1_end) { --echo # Binlog 1 end: $binlog_f1:$binlog_f1_end --echo # Binlog 2 stop point: $binlog_f2:$binlog_f2_mid --die Mid point chosen to end in binlog 2 does not exist in earlier binlog } --echo # --echo # --echo # Test using --read-from-remote-server --echo # --let $use_local_files= 0 --source binlog_mysqlbinlog_warn_stop_position.inc --echo # --echo # --echo # Test using local binlog files --echo # --let $use_local_files= 1 --source binlog_mysqlbinlog_warn_stop_position.inc --echo # End of binlog_mysqlbinlog_warn_stop_position.test

And its helper file
mysql-test/suite/rpl/t/binlog_mysqlbinlog_warn_stop_position.inc:

# # Helper file that ensures mysqlbinlog --stop-position and --stop-datetime # behavior for local files or a remote server # # Parameters: # use_local_files (bool): A boolean that changes which source to use for # mysqlbinlog. When true, uses local files; when false, reads remotely. # --connection default --let $MYSQLD_DATADIR= `select @@datadir` # PARAM_READ_FROM_REMOTE is used as a parameter to mysqlbinlog (_OUT suffix is # output in echo commands). If using local files, they are blank; if reading # from remote server, it is overridden to the correct values. --let $PARAM_READ_FROM_REMOTE= # Used in echo statements to remove potentially changing values --let $PARAM_READ_FROM_REMOTE_OUT= if (!$use_local_files) { --let $PARAM_READ_FROM_REMOTE= --read-from-remote-server --user=root --host=127.0.0.1 --port=$MASTER_MYPORT --let $PARAM_READ_FROM_REMOTE_OUT= --read-from-remote-server # binlog files in --read-from-remote-server don't use file system path --let $binlog_f1_full= $binlog_f1 --let $binlog_f2_full= $binlog_f2 } if ($use_local_files) { # If using local files, file system path to the binlog files is needed --let $binlog_f1_full= $MYSQLD_DATADIR/$binlog_f1 --let $binlog_f2_full= $MYSQLD_DATADIR/$binlog_f2 } --echo # --echo # --stop-position tests --echo # --echo # Case 1.a) With one binlog file, a --stop-position before the end of --echo # the file should not result in a warning --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-position=binlog_f1_pre_rotate binlog_f1_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-position=$binlog_f1_pre_rotate $binlog_f1_full --result-file=$binlog_out 2>&1 --echo # Case 1.b) With one binlog file, a --stop-position at the exact end of --echo # the file should not result in a warning --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-position=binlog_f1_end binlog_f1_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-position=$binlog_f1_end $binlog_f1_full --result-file=$binlog_out 2>&1 --echo # Case 1.c) With one binlog file, a --stop-position past the end of the --echo # file should(!) result in a warning --let $binlog_f1_over_eof= `SELECT $binlog_f1_end + 10` --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --short-form --stop-position=binlog_f1_over_eof binlog_f1_full --result-file=$binlog_out_relpath 2>&1 --replace_result $binlog_f1_over_eof <BINLOG_F1_OVER_EOF> --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --short-form --stop-position=$binlog_f1_over_eof $binlog_f1_full --result-file=$binlog_out 2>&1 --echo # Case 1.d) With two binlog files, a --stop-position targeting b2 which --echo # exists in the size of b1 should: --echo # 1) not provide any warnings --echo # 2) not prevent b2 from outputting its desired events before the --echo # stop position --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-position=binlog_f2_mid binlog_f1_full binlog_f2_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-position=$binlog_f2_mid $binlog_f1_full $binlog_f2_full --result-file=$binlog_out 2>&1 --let $server_id= `SELECT @@GLOBAL.server_id` --let $domain_id= `SELECT @@GLOBAL.gtid_domain_id` --let $assert_file= $binlog_out --let $assert_text= Ensure all intended GTIDs are present --let $assert_select= GTID $domain_id-$server_id- --let $assert_count= 4 --source include/assert_grep.inc --let $assert_text= Ensure the next GTID binlogged is _not_ present --let $assert_select= GTID $binlog_f2_gtid_after_midpoint --let $assert_count= 0 --source include/assert_grep.inc --echo # Case 1.e) With two binlog files, a --stop-position targeting the end --echo # of binlog 2 should: --echo # 1) not provide any warnings --echo # 2) not prevent b2 from outputting its entire binary log --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-position=binlog_f2_end binlog_f1_full binlog_f2_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-position=$binlog_f2_end $binlog_f1_full $binlog_f2_full --result-file=$binlog_out 2>&1 --let $server_id= `SELECT @@GLOBAL.server_id` --let $domain_id= `SELECT @@GLOBAL.gtid_domain_id` --let $assert_text= Ensure a GTID exists for each transaction --let $assert_select= GTID $domain_id-$server_id- --let $assert_count= 8 --source include/assert_grep.inc --let $assert_text= Ensure the last GTID binlogged is present --let $assert_select= GTID $binlog_f2_last_gtid --let $assert_count= 1 --source include/assert_grep.inc --echo # Case 1.f) With two binlog files, a --stop-position targeting beyond --echo # the eof of binlog 2 should: --echo # 1) provide a warning that the stop position was not reached --echo # 2) not prevent b2 from outputting its entire binary log --let $binlog_f2_over_eof= `SELECT $binlog_f2_end + 10` --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-position=binlog_f2_over_eof binlog_f1_full binlog_f2_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-position=$binlog_f2_over_eof $binlog_f1_full $binlog_f2_full --result-file=$binlog_out 2>&1 --let $server_id= `SELECT @@GLOBAL.server_id` --let $domain_id= `SELECT @@GLOBAL.gtid_domain_id` --let $assert_text= Ensure a GTID exists for each transaction --let $assert_select= GTID $domain_id-$server_id- --let $assert_count= 8 --source include/assert_grep.inc --echo # --echo # --stop-datetime tests --echo # Note: MDEV-35528 reported that mysqlbinlog would fail on tests cases --echo # 2.d, 2.e, and 2.f. --echo # --echo # Case 2.a) With one binlog file, a --stop-datetime before the end of --echo # the file should not result in a warning --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-datetime='$b1_timestamp2' binlog_f1_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-datetime='$b1_timestamp2' $binlog_f1_full --result-file=$binlog_out 2>&1 --echo # Case 2.b) With one binlog file, a --stop-datetime at the end of the --echo # file should not result in a warning --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-datetime='$b1_timestamp3' binlog_f1_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-datetime='$b1_timestamp3' $binlog_f1_full --result-file=$binlog_out 2>&1 --echo # Case 2.c) With one binlog file, a --stop-datetime beyond the end of --echo # the file should(!) result in a warning --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-datetime='$b2_timestamp1' binlog_f1_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-datetime='$b2_timestamp1' $binlog_f1_full --result-file=$binlog_out 2>&1 --echo # Case 2.d) With two binlog files, a --stop-datetime within the --echo # timespan of binlog 2 should: --echo # 1) not provide any warnings --echo # 2) not prevent binlog 1 or 2 from outputting the desired events --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-datetime='$b2_timestamp2' binlog_f1_full binlog_f2_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-datetime='$b2_timestamp2' $binlog_f1_full $binlog_f2_full --result-file=$binlog_out 2>&1 --let $assert_text= Ensure all intended GTIDs are present --let $assert_select= GTID $domain_id-$server_id- --let $assert_count= 4 --source include/assert_grep.inc --let $assert_text= Ensure the next GTID binlogged is _not_ present --let $assert_select= GTID $binlog_f2_gtid_after_midpoint --let $assert_count= 0 --source include/assert_grep.inc --echo # Case 2.e) With two binlog files, a --stop-datetime at the end of --echo # binlog 2 should: --echo # 1) not provide any warnings --echo # 2) not prevent binlog 1 or 2 from outputting all events --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-datetime='$b2_timestamp3' binlog_f1_full binlog_f2_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-datetime='$b2_timestamp3' $binlog_f1_full $binlog_f2_full --result-file=$binlog_out 2>&1 --let $assert_text= Ensure a GTID exists for each transaction --let $assert_select= GTID $domain_id-$server_id- --let $assert_count= 8 --source include/assert_grep.inc --echo # Case 2.f) With two binlog files, a --stop-datetime beyond the end of --echo # binlog 2 should: --echo # 1) provide a warning that the stop datetime was not reached --echo # 2) not prevent binlog 1 or 2 from outputting all events --echo # MYSQL_BINLOG $PARAM_READ_FROM_REMOTE_OUT --stop-datetime='$b2_timestamp3' binlog_f1_full binlog_f2_full --result-file=$binlog_out_relpath 2>&1 --exec $MYSQL_BINLOG $PARAM_READ_FROM_REMOTE --stop-datetime='$b2_timestamp3' $binlog_f1_full $binlog_f2_full --result-file=$binlog_out 2>&1 --let $assert_text= Ensure a GTID exists for each transaction --let $assert_select= GTID $domain_id-$server_id- --let $assert_count= 8 --source include/assert_grep.inc

--source include/have_binlog_format_row.inc

Why don’t we test all binlog formats?

Hi @bnestere, good point for tracking last position and datetime at the end of process_event().

I thought we cannot do this since I noticed there is a branch handle_event_raw_mode in dump_remote_log_entries which does not call process_event(). If that is not a problem. I will move the tracking logic to process_event() as your suggested.

Thank you for writing the test cases. I will test with them and also check if we can test other format as @ParadoxV5 suggested.

@XiaochuanCui Right, it is not a problem in raw mode. --stop-position and --stop-datetime are not actually used in raw mode (which our documentation also is consistent with).

Then for @ParadoxV5 's question

Why don’t we test all binlog formats?

--stop-position and --stop-datetime should be binlog format independent, but it doesn't hurt to verify :) And I don't think the test result is reliant on any specific binlog offset values, so it shouldn't need any additional modification to work for all, other than changing

---source include/have_binlog_format_row.inc +--source include/have_log_bin.inc

XiaochuanCui changed the base branch from main to 10.5 November 30, 2024 01:23

XiaochuanCui changed the title ~~MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when --stop-datetime is specified inlog~~ MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when --stop-datetime is specified Nov 30, 2024

bnestere self-requested a review November 30, 2024 16:31

bnestere self-assigned this Nov 30, 2024

bnestere requested changes Nov 30, 2024

View reviewed changes

cvicentiu added the External Contribution All PRs from entities outside of MariaDB Foundation, Corporation, Codership agreements. label Dec 3, 2024

ParadoxV5 mentioned this pull request Dec 5, 2024

[MDEV-34614] mysqlbinlog warn on EOF before GTID in --stop-position #3600

Draft

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when --stop-datetime is specified #3670

MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when --stop-datetime is specified #3670

XiaochuanCui commented Nov 30, 2024

CLAassistant commented Nov 30, 2024 •

edited

Loading

bnestere left a comment

bnestere Nov 30, 2024

XiaochuanCui Dec 3, 2024

bnestere Dec 3, 2024

XiaochuanCui Dec 4, 2024

bnestere Dec 5, 2024

ParadoxV5 Dec 5, 2024

XiaochuanCui Dec 6, 2024

bnestere Dec 10, 2024

MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when --stop-datetime is specified #3670

Are you sure you want to change the base?

MDEV-35528: mariadb-binlog cannot process more than 1 logfiles when --stop-datetime is specified #3670

Conversation

XiaochuanCui commented Nov 30, 2024

Description

Release Notes

How can this PR be tested?

Basing the PR against the correct MariaDB version

Copyright

CLAassistant commented Nov 30, 2024 • edited Loading

bnestere left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

CLAassistant commented Nov 30, 2024 •

edited

Loading