Could not register branch into global session status = TimeoutRollbacking while expecting Begin

[sfsflm]

• I have searched the issues of this repository and believe that this is not a duplicate.

Ⅰ. Issue Description

无法注册分支事务。（偶尔报错）
有时候接口是正常的，有时候接口报错，接口内部还没调用到其他服务就出错了。而且没有超过超时时间，超时时间设置了3分钟，但是接口执行几百毫秒就出错了。检查了seata-server的时区、数据库mariadb的时区、服务器时区、业务pod时区，都一致，时钟也同步。

Ⅱ. Describe what happened

io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 192.168.130.21:8091:18590791467253775 status = TimeoutRollbacking while expecting Begin
at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) ~[classes/:na]
at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) ~[classes/:na]
at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:194) ~[classes/:na]
at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:331) ~[classes/:na]
at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) ~[classes/:na]
at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:100) ~[classes/:na]
at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:199) [classes/:na]
at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) ~[classes/:na]
at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) ~[classes/:na]
at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:124) ~[seata-core-1.4.2.jar:na]
at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) [classes/:na]
at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) [seata-core-1.4.2.jar:na]
at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:473) [classes/:na]
at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:116) [seata-core-1.4.2.jar:na]
at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.process(ServerOnRequestProcessor.java:77) [seata-core-1.4.2.jar:na]
at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:279) [seata-core-1.4.2.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_212]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_212]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_212]

Ⅲ. Describe what you expected to happen

Ⅳ. How to reproduce it (as minimally and precisely as possible)

1. xxx
2. xxx
3. xxx

Minimal yet complete reproducer code (or URL to code):

Ⅴ. Anything else we need to know?

Ⅵ. Environment:

JDK version : 1.8
Seata version: 1.4.2
OS : linux centos 7
Others:

[funky-eyes]

基本上就是时区问题，不要这么肯定的回答，你还没调用就回滚了，能不是时区导致的？
It's basically a timezone issue. Don't be so certain in your response; you rolled back before even calling. Could it not be caused by the timezone?

[funky-eyes]

看看server日志，再看看实际的时区，而不是仅靠date进行判断
Check the server logs and the actual timezone, rather than just relying on the date command for judgment

[sfsflm]

我检查了seata-server、数据库mariadb、业务容器内的时区，是Asia/Shanghai，下面截图里时间不一致是因为执行命令的时间不同。

seata-server 容器内：
/seata-server # date
Fri Oct 18 10:18:02 CST 2024
/seata-server # echo $TZ
Asia/Shanghai

数据库maridab容器内：
$ date
Fri Oct 18 10:17:48 CST 2024
$ echo $TZ
Asia/Shanghai

业务容器：
bash-4.2# date
Fri Oct 18 10:22:53 CST 2024
bash-4.2# echo $TZ
Asia/Shanghai

报错的时候，seata-server的日志：
10:28:16.810 ERROR --- [rverHandlerThread_1_4_500] i.s.c.e.AbstractExceptionHandler : Catch TransactionException while do RPC, request: xid=192.168.150.81:8091:18590791467254237,branchType=AT,resourceId=jdbc:mysql://10.233.36.134:3306/user,lockKey=base_group_member_info:2196
==>
io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 192.168.150.81:8091:18590791467254237 status = TimeoutRollbacking while expecting Begin
at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) ~[classes/:na]
at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) ~[classes/:na]
at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:194) ~[classes/:na]
at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:331) ~[classes/:na]
at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) ~[classes/:na]
at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:100) ~[classes/:na]
at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:199) [classes/:na]
at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) ~[classes/:na]
at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) ~[classes/:na]
at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:124) ~[seata-core-1.4.2.jar:na]
at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) [classes/:na]
at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) [seata-core-1.4.2.jar:na]

业务的日志是：
2024-10-18 10:28:16.818 ERROR [user,,,] 1 --[b81b1f99-f297-4431-b281-ff0d6fed3199]-[1] i.s.r.d.exec.AbstractDMLBaseExecutor : execute executeAutoCommitTrue error:io.seata.core.exception.RmTransactionException: Response[ TransactionException[Could not register branch into global session xid = 192.168.130.21:8091:18590791467254237 status = TimeoutRollbacking while expecting Begin] ]

java.sql.SQLException: io.seata.core.exception.RmTransactionException: Response[ TransactionException[Could not register branch into global session xid = 192.168.130.21:8091:18590791467254237 status = TimeoutRollbacking while expecting Begin] ]
at io.seata.rm.datasource.ConnectionProxy.recognizeLockKeyConflictException(ConnectionProxy.java:161)
at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:252)
at io.seata.rm.datasource.ConnectionProxy.doCommit(ConnectionProxy.java:230)
at io.seata.rm.datasource.ConnectionProxy.lambda$commit$0(ConnectionProxy.java:188)
at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.execute(ConnectionProxy.java:333)
at io.seata.rm.datasource.ConnectionProxy.commit(ConnectionProxy.java:187)
at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.lambda$executeAutoCommitTrue$2(AbstractDMLBaseExecutor.java:141)
at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:343)
at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor$LockRetryPolicy.execute(AbstractDMLBaseExecutor.java:184)
at io.seata.rm.datasource.exec.AbstractDMLBaseExecutor.executeAutoCommitTrue(AbstractDMLBaseExecutor.java:139)

[funky-eyes]

看server日志是不是输出过timeoutrollbacking类似的日志信息，如果有就是时区导致查出来对不上，可以考虑在jdbcurl上知道时区等方式试试能否解决
Check the server logs to see if there are any log messages like 'timeout rolling back.' If there are, it could be a timezone issue causing the mismatch. Consider specifying the timezone in the JDBC URL or other methods to see if that resolves the issue

[funky-eyes]

另一个简单验证的方法,起一个seata-server 用file模式.对这个server进行压测,如果再也没出现这个问题,换成db模式就会出现这个问题,说明一定是时区问题
Another simple way to verify, start a seata-server with file mode. Perform torture testing on this server. If this problem does not occur again, this problem will occur when changing to db mode, indicating that it must be a time zone problem

[sfsflm]

你好，我将store.mode改成file后试验了，没有出现错误。然后将store.mode改为db试验后，还是会出现错误。我又检查了数据库里时区，执行show variables like '%time_zone%'; 输出：
system_time_zone CST
time_zone SYSTEM

store.db.url中配置的serverTimezone本来是UTC，我以为是这个导致的，将UTC改成了Asia/Shanghai尝试了下，还是会出错误。

另外还有个疑问，我在nacos上修改配置项是client.tm.defaultGlobalTransactionTimeout，为什么我几次修改这个配置项后，删掉seata容器再重新创建，打印的日志中SeataMergeMessage timeout=240000，timeout一直是240000，并不是我修改后的client.tm.defaultGlobalTransactionTimeout。而其他配置项，例如store.mode、store.db.url、store.db.password修改后，再重新创建seata容器能生效。

现在我的疑问就是问题大概率是时区问题导致的，但暂时找不到到底哪里的时区不一致。linux服务器是CST、业务pod是Asia/Shanghai、seata容器是Asia/Shanghai、mysql容器Asia/Shanghai、业务pod里jdbc连接串serverTimezone=GMT+8、seata中store.db.url：jdbc连接串serverTimezone=Asia/Shanghai

ps：跟我所有的容器都部署在虚拟机里有关系吗？隔壁部门在物理机上部署了一套相同的服务，没有遇到问题。

下面是出错时候seata控制台打印的日志：
16:52:39.396 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage timeout=240000,transactionName=urbancpnRegister(com.github.wxiaoqi.security.modules.auth.vo.ApiRegisterUser)
,clientIp:192.168.150.83,vgroup:isbahn-usercenter-tx-group
16:52:39.404 INFO --- [verHandlerThread_1_18_500] i.s.s.coordinator.DefaultCoordinator : Begin new global transaction applicationId: isbahn-usercenter,transactionServiceGroup: isbahn-usercenter-tx-group, transactionName: urbancpnRegister(com.github.wxiaoqi.security.modules.auth.vo.ApiRegisterUser),timeout:240000,xid:192.168.150.81:8091:18592202941997071
16:52:39.432 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage xid=192.168.150.81:8091:18592202941997071,branchType=AT,resourceId=jdbc:mysql://10.233.36.134:3306/isbahn_usercenter,lockKey=base_user:2209
,clientIp:192.168.150.83,vgroup:isbahn-usercenter-tx-group
16:52:39.446 INFO --- [verHandlerThread_1_19_500] i.seata.server.coordinator.AbstractCore : Register branch successfully, xid = 192.168.150.81:8091:18592202941997071, branchId = 18592202941997073, resourceId = jdbc:mysql://10.233.36.134:3306/isbahn_usercenter ,lockKeys = base_user:2209
16:52:39.473 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage xid=192.168.150.81:8091:18592202941997071,branchType=AT,resourceId=jdbc:mysql://10.233.36.134:3306/isbahn_usercenter,lockKey=base_group_member_info:2295
,clientIp:192.168.150.83,vgroup:isbahn-usercenter-tx-group
16:52:39.475 ERROR --- [verHandlerThread_1_20_500] i.s.c.e.AbstractExceptionHandler : Catch TransactionException while do RPC, request: xid=192.168.150.81:8091:18592202941997071,branchType=AT,resourceId=jdbc:mysql://10.233.36.134:3306/isbahn_usercenter,lockKey=base_group_member_info:2295
==>
io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 192.168.150.81:8091:18592202941997071 status = TimeoutRollbacking while expecting Begin
at io.seata.server.coordinator.AbstractCore.globalSessionStatusCheck(AbstractCore.java:108) ~[classes/:na]
at io.seata.server.coordinator.AbstractCore.lambda$branchRegister$0(AbstractCore.java:78) ~[classes/:na]
at io.seata.server.storage.db.session.DataBaseSessionManager.lockAndExecute(DataBaseSessionManager.java:194) ~[classes/:na]
at io.seata.server.session.SessionHolder.lockAndExecute(SessionHolder.java:331) ~[classes/:na]
at io.seata.server.coordinator.AbstractCore.branchRegister(AbstractCore.java:77) ~[classes/:na]
at io.seata.server.coordinator.DefaultCore.branchRegister(DefaultCore.java:100) ~[classes/:na]
at io.seata.server.coordinator.DefaultCoordinator.doBranchRegister(DefaultCoordinator.java:199) [classes/:na]
at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:184) ~[classes/:na]
at io.seata.server.AbstractTCInboundHandler$4.execute(AbstractTCInboundHandler.java:179) ~[classes/:na]
at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:124) ~[seata-core-1.4.2.jar:na]
at io.seata.server.AbstractTCInboundHandler.handle(AbstractTCInboundHandler.java:179) [classes/:na]
at io.seata.core.protocol.transaction.BranchRegisterRequest.handle(BranchRegisterRequest.java:136) [seata-core-1.4.2.jar:na]
at io.seata.server.coordinator.DefaultCoordinator.onRequest(DefaultCoordinator.java:473) [classes/:na]
at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:116) [seata-core-1.4.2.jar:na]
at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.process(ServerOnRequestProcessor.java:77) [seata-core-1.4.2.jar:na]
at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:279) [seata-core-1.4.2.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_212]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_212]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_212]
<==