MySQL Replication--开启GTID模式下匿名事务异常

错误环境:

OS: CentOS release 6.5 (Final)

MySQL: MySQL 5.7.19

主从参数配置:

master_info_repository      = TABLE
relay_log_info_repository   = TABLE
gtid_mode		    = on
enforce-gtid-consistency    = true
log_slave_updates           = 1
slave-parallel-workers      = 8
slave-parallel-type         = LOGICAL_CLOCK
slave_preserve_commit_order = 0

错误描述:

从库SQL进程异常停止(从库在此前刚因内存异常重启),报错内容为:

Last_Errno: 1782
Last_Error: Error executing row event: '@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.'

出库执行位点:

Relay_Master_Log_File: mysql-bin.001204
  Exec_Master_Log_Pos: 52454628
    Executed_Gtid_Set: 6b5be2cf-b1ad-11e7-aeb2-246e965aa709:1432389-825991260

按照位点信息去主库上解析binlog

/export/servers/mysql/bin/mysqlbinlog -vvv /export/data/mysql/data/mysql-bin.001204 --start_position=52454628 |more

输出内容为:

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#190518  1:05:08 server id 60863  end_log_pos 123 CRC32 0x0545d99b 	Start: binlog v 4, server v 5.7.19-log created 190518  1:05:08
BINLOG '
xOneXA+/7QAAdwAAAHsAAAAAAAQANS43LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AZvZRQU=
'/*!*/;
# at 52454628
#190518  2:56:10 server id 60863  end_log_pos 52455702 CRC32 0x24c5219e 	Update_rows: table id 27578 flags: STMT_END_F

BINLOG '
ygPfXB+/7QAAMgQAABZpIAMAALprAAAAAAEAAgBX/////////////////////////////6ABAyBw
D8B8ALyAPfUdAAAAAAABMQwxMDAwMDAwMTc1NTmMAOWuieWwlOmbhSBBTkVSWUEg5pel5byP5ZWG
6LaF5ZCM5qy+IOaHkuS6uuaymeWPkeixhuiii+aXoOWNsOWIm+aEj+aRh+aRh+akheS8kemXsuWM
l+asp+amu+amu+exs+WNleS6uuWkmuWKn+iDveW4g+iJuuaymeWPkSDnj4rnkZrok50g5aSn5qy+
ATCAAAAABROIATABMAQAaHpyegYxMzQxNzAJAOa1meaxn+ecgQExATABMAEwATABMAEwBDk4NzAB
MAwAMTAwMDAwMDE3NTU5ATABMACZogdLxFzbUkQDMzAxEWdvb2RzSW5mb0Rvd25sb2FkEWdvb2Rz
SW5mb0Rvd25sb2FkDAAxMDAwMDAwMTc1NTmAAAAAAAAAATABMAEwATCAAAAAAAAAATCAAAAAAAAA
gAAAAAAAAIAAAAAAAACAAAAAAAAAgAAAAAAAAAEwAzY1MQEzAIAAAAKeAACAAAACXQAAgAAAAlgA
AAEwATABMAABMD4AamZzL3QzMDM4Mi8yMzgvMjIwMzM3MzU1LzI4MzAzMi8zNjJjODZiNy81YmVi
YjI5N05lMWE5MjZmYy5qcGcBADElzoqzagEAAAPnrrEAAIAAAAAAAACAAAAAAAAAoAEDIHAPwHwA
vIA99R0AAAAAAAExDDEwMDAwMDAxNzU1OYwA5a6J5bCU6ZuFIEFORVJZQSDml6XlvI/llYbotoXl
kIzmrL4g5oeS5Lq65rKZ5Y+R6LGG6KKL5peg5Y2w5Yib5oSP5pGH5pGH5qSF5LyR6Zey5YyX5qyn
5qa75qa757Gz5Y2V5Lq65aSa5Yqf6IO95biD6Im65rKZ5Y+RIOePiueRmuiTnSDlpKfmrL4BMIAA
AAAFE4gBMAEwBABoenJ6BjEzNDE3MAkA5rWZ5rGf55yBATEBMAEwATABMAEwATAEOTg3MAEwDAAx
MDAwMDAwMTc1NTkBMAEwAJmiB0vEXN8DygMzMDERZ29vZHNJbmZvRG93bmxvYWQRZ29vZHNJbmZv
RG93bmxvYWQMADEwMDAwMDAxNzU1OYAAAAAAAAABMAEwATABMIAAAAAAAAABMIAAAAAAAACAAAAA
AAAAgAAAAAAAAIAAAAAAAACAAAAAAAAAATADNjUxATMAgAAAAp4AAIAAAAJdAACAAAACWAAAATAB
MAEwAAEwPgBqZnMvdDMwMzgyLzIzOC8yMjAzMzczNTUvMjgzMDMyLzM2MmM4NmI3LzViZWJiMjk3
TmUxYTkyNmZjLmpwZwEAMSOx2cNqAQAAA+eusQAAgAAAAAAAAIAAAAAAAACeIcUk
'/*!*/;
### Row event for unknown table #27578# at 52455702
#190518  2:56:10 server id 60863  end_log_pos 52455733 CRC32 0xb829837d 	Xid = 8647697161
COMMIT/*!*/;
# at 52455733
#190518  2:56:10 server id 60863  end_log_pos 52455798 CRC32 0x02c73826 	GTID	last_committed=21489	sequence_number=21490 -rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990109'/*!*/;
# at 52455798
#190518  2:56:10 server id 60863  end_log_pos 52455871 CRC32 0x1863b7ae 	Query	thread_id=7254910	exec_time=0	error_c
ode=0
SET TIMESTAMP=1558119370/*!*/;
SET @@session.pseudo_thread_id=7254910/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1411383296/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 52455871

网上关于错误“Row event for unknown table”的资料较少,查到资料解释大意是在建立table map信息丢失导致。

参考链接:

https://bugs.mysql.com/bug.php?id=60964
https://www.jianshu.com/p/4e28f09b3ce5

从上面的解析结果发现,该事务设置GTID_NEXT,难道真的是匿名事务?

通过指定时间段方式来解析:

/export/servers/mysql/bin/mysqlbinlog -vvv /export/data/mysql/data/mysql-bin.001204 --start_datetime='2019-05-18 2:56:09' --stop_datetime='2019-05-18 2:56:11'

解析结果包含如下信息:

# at 52454142
#190518  2:56:10 server id 60863  end_log_pos 52454173 CRC32 0xb0e1832b 	Xid = 8647697160
COMMIT/*!*/;
### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990107的事务提交
# at 52454173
#190518  2:56:10 server id 60863  end_log_pos 52454238 CRC32 0x83d1552a 	GTID	last_committed=21486	sequence_number=21489	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108的事务开始
SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108'/*!*/;
# at 52454238
#190518  2:56:10 server id 60863  end_log_pos 52454314 CRC32 0xb78b3241 	Query	thread_id=7172612	exec_time=0	error_code=0
SET TIMESTAMP=1558119370/*!*/;
BEGIN
/*!*/;
# at 52454314
#190518  2:56:10 server id 60863  end_log_pos 52454628 CRC32 0x643ab683 	Table_map: `report`.`bs_itembase` mapped to number 27578
# at 52454628
#190518  2:56:10 server id 60863  end_log_pos 52455702 CRC32 0x24c5219e 	Update_rows: table id 27578 flags: STMT_END_F

BINLOG '
ygPfXBO/7QAAOgEAAORkIAMAALprAAAAAAEABnJlcG9ydAALYnNfaXRlbWJhc2UAVwgPDw8PD/b2
Dw8PDw8PDw8PDw8PDw8PDw8PDw8PDxIRDw8PDw8PD/YPDw8PDw8PD/YP9vb29g8P9g8PDw8PDw8P
Afb29g8PDwEPDw8PDw8PDwgPARD29qKWAFoA3AUDAB4ADwQPBB4AAwCWACwBlgAAAwMAAwAeAB4A
AwADAAMAAwADAJYAAwBYAgMAAwCWAAADAAB4ADwAPABYAgMAAwB4AA8EeAB4AHgAeAADAAMAAwAD
AA8EAwAPBA8EDwQPBB4AHgAPBAMAAwADAB4AHgAeADwAPAAPBA8EDwQDAAMAAwADAHgA3AVYAiwB
WALcBVgCPAABAA8EDwT+//8/////////H4O2OmQ=
ygPfXB+/7QAAMgQAABZpIAMAALprAAAAAAEAAgBX/////////////////////////////6ABAyBw
D8B8ALyAPfUdAAAAAAABMQwxMDAwMDAwMTc1NTmMAOWuieWwlOmbhSBBTkVSWUEg5pel5byP5ZWG
6LaF5ZCM5qy+IOaHkuS6uuaymeWPkeixhuiii+aXoOWNsOWIm+aEj+aRh+aRh+akheS8kemXsuWM
l+asp+amu+amu+exs+WNleS6uuWkmuWKn+iDveW4g+iJuuaymeWPkSDnj4rnkZrok50g5aSn5qy+
ATCAAAAABROIATABMAQAaHpyegYxMzQxNzAJAOa1meaxn+ecgQExATABMAEwATABMAEwBDk4NzAB
MAwAMTAwMDAwMDE3NTU5ATABMACZogdLxFzbUkQDMzAxEWdvb2RzSW5mb0Rvd25sb2FkEWdvb2Rz
SW5mb0Rvd25sb2FkDAAxMDAwMDAwMTc1NTmAAAAAAAAAATABMAEwATCAAAAAAAAAATCAAAAAAAAA
gAAAAAAAAIAAAAAAAACAAAAAAAAAgAAAAAAAAAEwAzY1MQEzAIAAAAKeAACAAAACXQAAgAAAAlgA
AAEwATABMAABMD4AamZzL3QzMDM4Mi8yMzgvMjIwMzM3MzU1LzI4MzAzMi8zNjJjODZiNy81YmVi
YjI5N05lMWE5MjZmYy5qcGcBADElzoqzagEAAAPnrrEAAIAAAAAAAACAAAAAAAAAoAEDIHAPwHwA
vIA99R0AAAAAAAExDDEwMDAwMDAxNzU1OYwA5a6J5bCU6ZuFIEFORVJZQSDml6XlvI/llYbotoXl
kIzmrL4g5oeS5Lq65rKZ5Y+R6LGG6KKL5peg5Y2w5Yib5oSP5pGH5pGH5qSF5LyR6Zey5YyX5qyn
5qa75qa757Gz5Y2V5Lq65aSa5Yqf6IO95biD6Im65rKZ5Y+RIOePiueRmuiTnSDlpKfmrL4BMIAA
AAAFE4gBMAEwBABoenJ6BjEzNDE3MAkA5rWZ5rGf55yBATEBMAEwATABMAEwATAEOTg3MAEwDAAx
MDAwMDAwMTc1NTkBMAEwAJmiB0vEXN8DygMzMDERZ29vZHNJbmZvRG93bmxvYWQRZ29vZHNJbmZv
RG93bmxvYWQMADEwMDAwMDAxNzU1OYAAAAAAAAABMAEwATABMIAAAAAAAAABMIAAAAAAAACAAAAA
AAAAgAAAAAAAAIAAAAAAAACAAAAAAAAAATADNjUxATMAgAAAAp4AAIAAAAJdAACAAAACWAAAATAB
MAEwAAEwPgBqZnMvdDMwMzgyLzIzOC8yMjAzMzczNTUvMjgzMDMyLzM2MmM4NmI3LzViZWJiMjk3
TmUxYTkyNmZjLmpwZwEAMSOx2cNqAQAAA+eusQAAgAAAAAAAAIAAAAAAAACeIcUk
'/*!*/;
### UPDATE `report`.`xxxx`
### WHERE
### 更新语句...

# at 52455702
#190518  2:56:10 server id 60863  end_log_pos 52455733 CRC32 0xb829837d 	Xid = 8647697161
COMMIT/*!*/;
### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108的事务提交
# at 52455733
#190518  2:56:10 server id 60863  end_log_pos 52455798 CRC32 0x02c73826 	GTID	last_committed=21489	sequence_number=21490	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990109的事务开始
SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990109'/*!*/;
# at 52455798
#190518  2:56:10 server id 60863  end_log_pos 52455871 CRC32 0x1863b7ae 	Query	thread_id=7254910	exec_time=0	error_code=0
SET TIMESTAMP=1558119370/*!*/;
SET @@session.sql_mode=1411383296/*!*/;
BEGIN
/*!*/;
# at 52455871
#190518  2:56:10 server id 60863  end_log_pos 52455941 CRC32 0xb9e2e221 	Table_map: `dcomb`.`snapshot_position` mapped to number 30731
# at 52455941
#190518  2:56:10 server id 60863  end_log_pos 52456099 CRC32 0xea181383 	Update_rows: table id 30731 flags: STMT_END_F

从上面解析内容可以发现事务中包含有GTID信息,但由于从库复制使用基于位点方式搭建,且从库开启多线程复制,因此Exec_Master_Log_Pos=52454628信息记录并不准确,而从该位置点开始应用BINLOG,没有执行该位点上面的内容(标黄部分):

#190518  2:56:10 server id 60863  end_log_pos 52454238 CRC32 0x83d1552a  GTID last_committed=21486 sequence_number=21489 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
### GTID为6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108的事务开始
SET @@SESSION.GTID_NEXT= '6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108'/*!*/;
# at 52454238
#190518  2:56:10 server id 60863  end_log_pos 52454314 CRC32 0xb78b3241  Query thread_id=7172612 exec_time=0 error_code=0
SET TIMESTAMP=1558119370/*!*/;
BEGIN
/*!*/;
# at 52454314
#190518  2:56:10 server id 60863  end_log_pos 52454628 CRC32 0x643ab683  Table_map: `report`.`bs_itembase` mapped to number 27578
# at 52454628
#190518  2:56:10 server id 60863  end_log_pos 52455702 CRC32 0x24c5219e  Update_rows: table id 27578 flags: STMT_END_F

当执行到COMMIT时,由于没有设置GTID_NEXT,因此MySQL认为该事务未匿名事务,SQL线程异常停止。

上面的情况是跳过"SET @@SESSION.GTID_NEXT" 和"BEGIN"两部分,而如果只跳过"SET @@SESSION.GTID_NEXT",则执行BEGIN时,会报如下错误:

Last_Errno: 1782
Last_Error: Error '@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.' on query. Default database: ''. Query: 'BEGIN'

位于该错误位点的GTID为“6b5be2cf-b1ad-11e7-aeb2-246e965aa709:825990108”,而从库执行过的GTID为“6b5be2cf-b1ad-11e7-aeb2-246e965aa709:1432389-825991260”,由于缺少GTID_NEXT标识事务,从库无法判定该事务是否已在从库上执行,也就无法自动跳过该事务。

由于参数relay_log_recovery默认值为OFF,从库服务器上未明确设置参数relay_log_recovery=ON,还需验证该参数对上述异常的影响,未完待续。

原文地址:https://www.cnblogs.com/gaogao67/p/10885858.html