Bug #112256 The event thread_id of source changed after write to local
Submitted: 5 Sep 2023 8:00 Modified: 7 Sep 2023 11:11
Reporter: yuxiang jiang (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:8.0.30 and above, 8.0.34 OS:Any
Assigned to: CPU Architecture:Any
Tags: contributions, replication thread id

[5 Sep 2023 8:00] yuxiang jiang
Description:
After turning on log_replica_updates, when the source event is logged to replica binlog, the thread_id is changed.

On 5.7, the thread id is the same after writing down to replica binlog.

After starting replication, if the first event is in row format, the source binlog event's thread_id is replication worker thread's thread_id. 

The first query event will replace the work thread's THD's pseudo_thread_id with its own. But the following row format event will always use this thread id until next query event.

Whether this change from 5.7 to 8.0.30 is expected?

How to repeat:
prepare on both source and replica
create database tdb;
use tdb;
create table t1(f1 int, primary key);

reset master on source and build a replication between source and replica, this is for simplify the binlog to check.

on source
=========
session 1
insert into t1 values (1);

session 2
set binlog_format='statement';
insert into t1 values (2);

session 1
insert into t1 values (3);
=========

the result is below

source binlog

#230905 15:34:45 server id 2  end_log_pos 313 CRC32 0xebe0ac22 	Query	thread_id=12	exec_time=0	error_code=0
SET TIMESTAMP=1693899285/*!*/;
SET @@session.pseudo_thread_id=12/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
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=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 313
#230905 15:34:45 server id 2  end_log_pos 363 CRC32 0x92cdde48 	Table_map: `tdb_pt`.`t1` mapped to number 96
# at 363
#230905 15:34:45 server id 2  end_log_pos 403 CRC32 0x7fce1c41 	Write_rows: table id 96 flags: STMT_END_F

BINLOG '
Fdr2ZBMCAAAAMgAAAGsBAAAAAGAAAAAAAAEABnRkYl9wdAACdDEAAQMAAAEBAEjezZI=
Fdr2ZB4CAAAAKAAAAJMBAAAAAGAAAAAAAAEAAgAB/wABAAAAQRzOfw==
'/*!*/;
### INSERT INTO `tdb_pt`.`t1`
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
# at 403
#230905 15:34:45 server id 2  end_log_pos 434 CRC32 0x0314442e 	Xid = 39
COMMIT/*!*/;
# at 434
#230905 15:34:51 server id 2  end_log_pos 513 CRC32 0xed6841df 	GTID	last_committed=1	sequence_number=2	rbr_only=no	original_committed_timestamp=1693899291661595	immediate_commit_timestamp=1693899291661595	transaction_length=302
# original_commit_timestamp=1693899291661595 (2023-09-05 15:34:51.661595 CST)
# immediate_commit_timestamp=1693899291661595 (2023-09-05 15:34:51.661595 CST)
/*!80001 SET @@session.original_commit_timestamp=1693899291661595*//*!*/;
/*!80014 SET @@session.original_server_version=80030*//*!*/;
/*!80014 SET @@session.immediate_server_version=80030*//*!*/;
SET @@SESSION.GTID_NEXT= 'd5a731cc-08ef-11ee-8a33-525400683dd8:2'/*!*/;
# at 513
#230905 15:34:51 server id 2  end_log_pos 599 CRC32 0x1c7e8d17 	Query	thread_id=14	exec_time=0	error_code=0
SET TIMESTAMP=1693899291/*!*/;
BEGIN
/*!*/;
# at 599
#230905 15:34:51 server id 2  end_log_pos 705 CRC32 0x6097935c 	Query	thread_id=14	exec_time=0	error_code=0
use `tdb_pt`/*!*/;
SET TIMESTAMP=1693899291/*!*/;
insert into t1 values (2)
/*!*/;
# at 705
#230905 15:34:51 server id 2  end_log_pos 736 CRC32 0x13eabeaf 	Xid = 41
COMMIT/*!*/;
# at 736
#230905 15:35:00 server id 2  end_log_pos 815 CRC32 0xc425f32e 	GTID	last_committed=2	sequence_number=3	rbr_only=yes	original_committed_timestamp=1693899300159944	immediate_commit_timestamp=1693899300159944	transaction_length=277
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1693899300159944 (2023-09-05 15:35:00.159944 CST)
# immediate_commit_timestamp=1693899300159944 (2023-09-05 15:35:00.159944 CST)
/*!80001 SET @@session.original_commit_timestamp=1693899300159944*//*!*/;
/*!80014 SET @@session.original_server_version=80030*//*!*/;
/*!80014 SET @@session.immediate_server_version=80030*//*!*/;
SET @@SESSION.GTID_NEXT= 'd5a731cc-08ef-11ee-8a33-525400683dd8:3'/*!*/;
# at 815
#230905 15:35:00 server id 2  end_log_pos 892 CRC32 0x71011ee8 	Query	thread_id=12	exec_time=0	error_code=0
SET TIMESTAMP=1693899300/*!*/;
BEGIN
/*!*/;
# at 892
#230905 15:35:00 server id 2  end_log_pos 942 CRC32 0xf94d7d73 	Table_map: `tdb_pt`.`t1` mapped to number 96
# at 942
#230905 15:35:00 server id 2  end_log_pos 982 CRC32 0x08b03b0d 	Write_rows: table id 96 flags: STMT_END_F

BINLOG '
JNr2ZBMCAAAAMgAAAK4DAAAAAGAAAAAAAAEABnRkYl9wdAACdDEAAQMAAAEBAHN9Tfk=
JNr2ZB4CAAAAKAAAANYDAAAAAGAAAAAAAAEAAgAB/wADAAAADTuwCA==
'/*!*/;
### INSERT INTO `tdb_pt`.`t1`
### SET
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
# at 982
#230905 15:35:00 server id 2  end_log_pos 1013 CRC32 0x50285f3b 	Xid = 42
COMMIT/*!*/;

=======
the replica binlog

#230905 15:34:45 server id 2  end_log_pos 315 CRC32 0x555b1007 	Query	thread_id=19	exec_time=0	error_code=0
SET TIMESTAMP=1693899285/*!*/;
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=524288/*!*/;
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=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 315
#230905 15:34:45 server id 2  end_log_pos 365 CRC32 0xb8a4cad0 	Table_map: `tdb_pt`.`t1` mapped to number 94
# at 365
#230905 15:34:45 server id 2  end_log_pos 405 CRC32 0xead23d2a 	Write_rows: table id 94 flags: STMT_END_F

BINLOG '
Fdr2ZBMCAAAAMgAAAG0BAAAAAF4AAAAAAAEABnRkYl9wdAACdDEAAQMAAAEBANDKpLg=
Fdr2ZB4CAAAAKAAAAJUBAAAAAF4AAAAAAAEAAgAB/wABAAAAKj3S6g==
'/*!*/;
### INSERT INTO `tdb_pt`.`t1`
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
# at 405
#230905 15:34:45 server id 2  end_log_pos 436 CRC32 0x550f7881 	Xid = 11
COMMIT/*!*/;
# at 436
#230905 15:34:51 server id 2  end_log_pos 522 CRC32 0xc5b8886a 	GTID	last_committed=1	sequence_number=2	rbr_only=yes	original_committed_timestamp=1693899291661595	immediate_commit_timestamp=1693899291666121	transaction_length=284
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1693899291661595 (2023-09-05 15:34:51.661595 CST)
# immediate_commit_timestamp=1693899291666121 (2023-09-05 15:34:51.666121 CST)
/*!80001 SET @@session.original_commit_timestamp=1693899291661595*//*!*/;
/*!80014 SET @@session.original_server_version=80030*//*!*/;
/*!80014 SET @@session.immediate_server_version=80030*//*!*/;
SET @@SESSION.GTID_NEXT= 'd5a731cc-08ef-11ee-8a33-525400683dd8:2'/*!*/;
# at 522
#230905 15:34:51 server id 2  end_log_pos 599 CRC32 0xb4786c88 	Query	thread_id=14	exec_time=0	error_code=0
SET TIMESTAMP=1693899291/*!*/;
SET @@session.sql_mode=0/*!*/;
BEGIN
/*!*/;
# at 599
#230905 15:34:51 server id 2  end_log_pos 649 CRC32 0xf8df0f28 	Table_map: `tdb_pt`.`t1` mapped to number 94
# at 649
#230905 15:34:51 server id 2  end_log_pos 689 CRC32 0x7ac6d45d 	Write_rows: table id 94 flags: STMT_END_F

BINLOG '
G9r2ZBMCAAAAMgAAAIkCAAAAAF4AAAAAAAEABnRkYl9wdAACdDEAAQMAAAEBACgP3/g=
G9r2ZB4CAAAAKAAAALECAAAAAF4AAAAAAAEAAgAB/wACAAAAXdTGeg==
'/*!*/;
### INSERT INTO `tdb_pt`.`t1`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
# at 689
#230905 15:34:51 server id 2  end_log_pos 720 CRC32 0xc50096b7 	Xid = 13
COMMIT/*!*/;
# at 720
#230905 15:35:00 server id 2  end_log_pos 806 CRC32 0xe9187e79 	GTID	last_committed=2	sequence_number=3	rbr_only=yes	original_committed_timestamp=1693899300159944	immediate_commit_timestamp=1693899300163501	transaction_length=279
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1693899300159944 (2023-09-05 15:35:00.159944 CST)
# immediate_commit_timestamp=1693899300163501 (2023-09-05 15:35:00.163501 CST)
/*!80001 SET @@session.original_commit_timestamp=1693899300159944*//*!*/;
/*!80014 SET @@session.original_server_version=80030*//*!*/;
/*!80014 SET @@session.immediate_server_version=80030*//*!*/;
SET @@SESSION.GTID_NEXT= 'd5a731cc-08ef-11ee-8a33-525400683dd8:3'/*!*/;
# at 806
#230905 15:35:00 server id 2  end_log_pos 878 CRC32 0x2b6eff86 	Query	thread_id=14	exec_time=0	error_code=0
SET TIMESTAMP=1693899300/*!*/;
SET @@session.sql_mode=524288/*!*/;
BEGIN
/*!*/;
# at 878
#230905 15:35:00 server id 2  end_log_pos 928 CRC32 0xbfc1e832 	Table_map: `tdb_pt`.`t1` mapped to number 94
# at 928
#230905 15:35:00 server id 2  end_log_pos 968 CRC32 0x9c67df0c 	Write_rows: table id 94 flags: STMT_END_F

BINLOG '
JNr2ZBMCAAAAMgAAAKADAAAAAF4AAAAAAAEABnRkYl9wdAACdDEAAQMAAAEBADLowb8=
JNr2ZB4CAAAAKAAAAMgDAAAAAF4AAAAAAAEAAgAB/wADAAAADN9nnA==
'/*!*/;
### INSERT INTO `tdb_pt`.`t1`
### SET
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
# at 968
#230905 15:35:00 server id 2  end_log_pos 999 CRC32 0x6662cbc8 	Xid = 15
COMMIT/*!*/;

Suggested fix:
--- a/sql/log_event.cc
+++ b/sql/log_event.cc
@@ -5110,7 +5110,6 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
       thd->rpl_thd_ctx.post_filters_actions().push_back(f);
     }
 
-    thd->variables.pseudo_thread_id = thread_id;
     thd->set_time(&(common_header->when));
     thd->set_query(query_arg, q_len_arg);
     thd->set_query_for_display(query_arg, q_len_arg);
[6 Sep 2023 15:20] yuxiang jiang
fixup 

diff --git a/sql/log_event.cc b/sql/log_event.cc
index dcad777..dee0cde 100644
--- a/sql/log_event.cc
+++ b/sql/log_event.cc
@@ -5103,13 +5103,13 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
           thd->is_slave_error = true;
           return true;
         }
-        thd->variables.pseudo_thread_id = thread_id;  // for temp tables
         attach_temp_tables_worker(thd, rli);
         return false;
       };
       thd->rpl_thd_ctx.post_filters_actions().push_back(f);
     }
 
+    thd->variables.pseudo_thread_id = thread_id;  // for temp tables
     thd->set_time(&(common_header->when));
     thd->set_query(query_arg, q_len_arg);
     thd->set_query_for_display(query_arg, q_len_arg);
[6 Sep 2023 15:22] yuxiang jiang
solution for this problem

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: 0001-Problem.patch (application/octet-stream, text), 1.58 KiB.

[7 Sep 2023 11:11] MySQL Verification Team
Hello yuxiang jiang,

Thank you for the report and contribution.
Verified as described.

regards,
Umesh
[7 Oct 2023 13:28] huahua xu
Hi, All:

The phenomenon has occurred since the commit: https://github.com/mysql/mysql-server/commit/3e25f4f876761b706ebeea6d9f416091b779dd71.