Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
1 task
sfsflm opened this issue Oct 17, 2024 · 14 comments
Open
1 task

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

sfsflm opened this issue Oct 17, 2024 · 14 comments

Comments

@sfsflm
Copy link

sfsflm commented Oct 17, 2024

  • 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
Copy link
Contributor

基本上就是时区问题，不要这么肯定的回答，你还没调用就回滚了，能不是时区导致的？
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
Copy link
Contributor

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

@sfsflm
Copy link
Author

sfsflm commented Oct 18, 2024 •
edited
Loading

我检查了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
Copy link
Contributor

看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
Copy link
Contributor

另一个简单验证的方法,起一个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
Copy link
Author

sfsflm commented Oct 21, 2024 •
edited
Loading

你好，我将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]
<==

@slievrly
Copy link
Member

The issue here has been confirmed, is that the default timeout configuration does not take effect.

@funky-eyes
Copy link
Contributor

你的client是如何配置nacos为配置中心的？client.tm.defaultGlobalTransactionTimeout 是属于client的配置，而不是server的配置？
How do you configure Nacos as a configuration center for the client? Is client.tm.defaultGlobalTransactionTimeout a configuration for the client rather than the server?

@funky-eyes
Copy link
Contributor

可以尝试给将server启动命令增加 -Duser.timezone=Asia/Shanghai 参数
You can try adding the -Duser.timezone = Asia/Shanghai parameter to the server start command

@sfsflm
Copy link
Author

sfsflm commented Nov 3, 2024

你的client是如何配置nacos为配置中心的？client.tm.defaultGlobalTransactionTimeout 是属于client的配置，而不是server的配置？ How do you configure Nacos as a configuration center for the client? Is client.tm.defaultGlobalTransactionTimeout a configuration for the client rather than the server?

是的，是我弄错了，修改后，没有重启业务pod。

@sfsflm
Copy link
Author

sfsflm commented Nov 3, 2024

可以尝试给将server启动命令增加 -Duser.timezone=Asia/Shanghai 参数 You can try adding the -Duser.timezone = Asia/Shanghai parameter to the server start command

我采用了docker部署，部署的时候添加了将-Duser.timezone=Asia/Shanghai 添加到JAVA_OPTS，试验了下，时区没有生效。
我现在将seata与数据库部署在了同一台机器上去测试，还是会存在问题。我的数据库镜像采用的是bitnami/mariadb:10.5.11-debian-10-r0，我的seata部署时试验了不另外增加时区、增加时区两种方式，部署后验证均会出现错误 io.seata.core.exception.GlobalTransactionException: Could not register branch into global session xid = 192.168.xxx.xxx:8091:18596739506278412 status = TimeoutRollbacking while expecting Begin：
docker run -d --name seata
--privileged=true
--restart=always
-p 8091:8091
-e SEATA_IP=192.168.xxx.xxx
-e SEATA_CONFIG_NAME=file:/root/seata-config/registry
-v /data/docker/config:/root/seata-config
seataio/seata-server:1.4.2

docker run -d --name seata
--privileged=true
--restart=always
-p 8091:8091
-e TZ=Asia/Shanghai
-e SET_CONTAINER_TIMEZONE=true
-e CONTAINER_TIMEZONE=Asia/Shanghai
-e SEATA_IP=192.168.xxx.xxx
-e SEATA_CONFIG_NAME=file:/root/seata-config/registry
-v /docker/config:/root/seata-config
seataio/seata-server:1.4.2

@funky-eyes
Copy link
Contributor

弄一台vm机器测试吧,别放docker里了

@sfsflm
Copy link
Author

sfsflm commented Nov 3, 2024

弄一台vm机器测试吧,别放docker里了

现在就是在虚拟机里。您的意思是在虚拟机里直接部署seata，不使用容器部署是吧？

@funky-eyes
Copy link
Contributor

对

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@slievrly @funky-eyes @sfsflm