Description:
Hi,
this is a test-case for Bug#91812 which was closed as "Not a Bug" (it should probably have been closed as "Can't repeat"). See details in "How to repeat" for details.
The problem manifests itself when mysqlbinlog | mysql is producing the error below.
ERROR 1766 (HY000) at line 41: The system variable explicit_defaults_for_timestamp cannot be set when there is an ongoing transaction.
I suspect this is caused by a combination of using mysqlbinlog | mysql, GTIDs, replication filters and explicit_defaults_for_timestamp. When filtering transactions with GTID enabled, the binary log produced by the filtering replica needs to contain an empty transaction to propagate the GTID of the filtered transaction. When combined with a table that has defaults for timestamps, mysqlbinlog will output "SET @@session.explicit_defaults_for_timestamp=0/*!*/;" before the COMMIT (and after the BEGIN). When piping this to mysql, we get the error below.
ERROR 1766 (HY000) at line 41: The system variable explicit_defaults_for_timestamp cannot be set when there is an ongoing transaction.
The "How to repeat" below is for MySQL 8.0.23, but this also affects 5.7.33.
Many thanks for looking into this,
Jean-François Gagné
How to repeat:
# Create a replicated 8.0.23 sandbox with 4 replica and GTID enabled.
dbdeployer deploy replication mysql_8.0.23 --gtid -n 5
# Create a schema, 2 tables, insert data in these tables, and show it replicates correctly (the sleep is to make sure data has the time to replicate).
./m <<< "create database test_jfg"; \
./m test_jfg <<< "
create table t1(id bigint not null auto_increment primary key, v bigint not null);
create table t2(id bigint not null auto_increment primary key, v bigint not null);
insert into t1(v) values(1);
insert into t2(v) values(1)"; \
sleep 1 && ./s1 test_jfg <<< "select * from t1; select * from t2"
id v
1 1
id v
1 1
# Make s3 replicate from s2, add replication filters on s2, and stop replication on s4 (we will use mysqlbinlog | mysql to keep s4 up-to-date).
./s3 <<< "stop slave; change master to master_port = $(./s2 -N <<< "select @@port"); start slave"; \
./s2 <<< "stop slave; CHANGE REPLICATION FILTER REPLICATE_DO_TABLE = (test_jfg.t1); start slave"; \
./s4 <<< "stop slave"
# Check that we get what we expect in this setup: s1 gets inserts in t1 and t2, and s3 and s4 only get inserts in t1.
./s2 <<< "flush binary logs"; \
./m test_jfg <<< "
insert into t1(v) values(2);
insert into t2(v) values(2)"; \
sleep 1; ~/opt/mysql/mysql_8.0.23/bin/mysqlbinlog node2/data/mysql-bin.000002 | ./s4; \
echo s1; ./s1 test_jfg <<< "select * from t1; select * from t2"; \
echo s3; ./s3 test_jfg <<< "select * from t1; select * from t2"; \
echo s4; ./s4 test_jfg <<< "select * from t1; select * from t2"
s1
id v
1 1
2 2
id v
1 1
2 2
s3
id v
1 1
2 2
id v
1 1
s4
id v
1 1
2 2
id v
1 1
# Generate a simple CREATE TABLE without defaults for timestamp, and everything still works.
./s2 <<< "flush binary logs"; \
./m test_jfg <<< "
create table t3(id bigint not null auto_increment primary key, v bigint not null);
insert into t1(v) values(3);
insert into t2(v) values(3)"; \
sleep 1; ~/opt/mysql/mysql_8.0.23/bin/mysqlbinlog node2/data/mysql-bin.000003 | ./s4; \
echo s1; ./s1 test_jfg <<< "select * from t1; select * from t2"; \
echo s3; ./s3 test_jfg <<< "select * from t1; select * from t2"; \
echo s4; ./s4 test_jfg <<< "select * from t1; select * from t2"
s1
id v
1 1
2 2
3 3
id v
1 1
2 2
3 3
s3
id v
1 1
2 2
3 3
id v
1 1
s4
id v
1 1
2 2
3 3
id v
1 1
# A CREATE TABLE with defaults does not work with mysqlbinlog | mysql.
./s2 <<< "flush binary logs"; \
./m test_jfg <<< "
create table t4(id bigint not null auto_increment primary key, v bigint not null, last_update timestamp not null DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP);
insert into t1(v) values(4);
insert into t2(v) values(4)"; \
sleep 1; ~/opt/mysql/mysql_8.0.23/bin/mysqlbinlog node2/data/mysql-bin.000004 | ./s4
ERROR 1766 (HY000) at line 41: The system variable explicit_defaults_for_timestamp cannot be set when there is an ongoing transaction.
# But this was correctly replicated to s3 via normal MySQL replication, which makes things clearly point to a problem with mysqlbinlog | mysql.
echo s1; ./s1 test_jfg <<< "select * from t1; select * from t2"; \
echo s3; ./s3 test_jfg <<< "select * from t1; select * from t2"; \
echo s4; ./s4 test_jfg <<< "select * from t1; select * from t2"
s1
id v
1 1
2 2
3 3
4 4
id v
1 1
2 2
3 3
4 4
s3
id v
1 1
2 2
3 3
4 4
id v
1 1
s4
id v
1 1
2 2
3 3
id v
1 1
# And the mysqlbinlog output for the CREATE TABLE in question (the first is not filtered and the second is filtered, observe the explicit_defaults_for_timestamp in the middle of the transaction for the filtered binlog).
# at 11059
#210315 18:52:13 server id 21324 end_log_pos 11138 CRC32 0x10803157 GTID last_committed=43 sequence_number=44 rbr_only=no original_committed_timestamp=1615834333714257 immediate_commit_timestamp=1615834333714257 transaction_length=344
# original_commit_timestamp=1615834333714257 (2021-03-15 18:52:13.714257 UTC)
# immediate_commit_timestamp=1615834333714257 (2021-03-15 18:52:13.714257 UTC)
/*!80001 SET @@session.original_commit_timestamp=1615834333714257*//*!*/;
/*!80014 SET @@session.original_server_version=80023*//*!*/;
/*!80014 SET @@session.immediate_server_version=80023*//*!*/;
SET @@SESSION.GTID_NEXT= '00021324-1111-1111-1111-111111111111:44'/*!*/;
# at 11138
#210315 18:52:13 server id 21324 end_log_pos 11403 CRC32 0xe60ae783 Query thread_id=19 exec_time=0 error_code=0 Xid = 111
SET TIMESTAMP=1615834333/*!*/;
SET @@session.explicit_defaults_for_timestamp=1/*!*/;
/*!80013 SET @@session.sql_require_primary_key=0*//*!*/;
create table t4(id bigint not null auto_increment primary key, v bigint not null, last_update timestamp not null DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP)
/*!*/;
# at 196
#210315 18:52:13 server id 21324 end_log_pos 280 CRC32 0x2abf6e07 GTID last_committed=0 sequence_number=1 rbr_only=no original_committed_timestamp=1615834333714257 immediate_commit_timestamp=1615834333717691 transaction_length=247
# original_commit_timestamp=1615834333714257 (2021-03-15 18:52:13.714257 UTC)
# immediate_commit_timestamp=1615834333717691 (2021-03-15 18:52:13.717691 UTC)
/*!80001 SET @@session.original_commit_timestamp=1615834333714257*//*!*/;
/*!80014 SET @@session.original_server_version=80023*//*!*/;
/*!80014 SET @@session.immediate_server_version=80023*//*!*/;
SET @@SESSION.GTID_NEXT= '00021324-1111-1111-1111-111111111111:44'/*!*/;
# at 280
#210315 18:52:13 server id 21324 end_log_pos 361 CRC32 0x88599bf4 Query thread_id=19 exec_time=0 error_code=0
SET TIMESTAMP=1615834333/*!*/;
SET @@session.pseudo_thread_id=19/*!*/;
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 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
SET @@session.explicit_defaults_for_timestamp=1/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 361
#210315 18:52:13 server id 21324 end_log_pos 443 CRC32 0x40353dff Query thread_id=19 exec_time=0 error_code=0
SET TIMESTAMP=1615834333/*!*/;
SET @@session.explicit_defaults_for_timestamp=1/*!*/;
COMMIT
/*!*/;
Suggested fix:
A very ugly patch would be to have mysqlbinlog not output the explicit_defaults_for_timestamp line for a COMMIT.
IMHO, the problem is in the way the empty transaction is generated. When generating an empty transaction from a DDL, MySQL should probably reset the bits that make mysqlbinlog output explicit_defaults_for_timestamp.
