apache / apache/incubator-seata

seata集群AT模式下,服务发生错误回滚时,RPC timeout,wait response error:cost 30002 ms

Open
#4,296 8 comments 0 reactions 0 assignees View on GitHub
Dominant language
Java
Stars
26k
Forks
8.8k
Avg merge
1d 8h
Merged PRs (30d)
4

Description

### Ⅰ. Issue Description
A服务 调用 B服务,A服务发生失败
然后开始回滚,此时要么A服务会出现rpc timeout,要么B服务会出现rpc timeout

而且是seata集群模式情况下,有可能会出现此错误,概率性挺高的,而且通常是项目刚启动的时候

### Ⅱ. Describe what happened

**A服务发生如下报错:**

```
2022-01-15 17:54:00.518 ERROR 23828 --- [io-10001-exec-4] i.s.c.r.n.AbstractNettyRemotingClient : wait response error:cost 30002 ms,ip:10.180.41.23:8091,request:xid=10.180.41.23:8091:8169750104099594487,extraData=null
2022-01-15 17:54:00.521 ERROR 23828 --- [io-10001-exec-4] i.seata.tm.api.DefaultGlobalTransaction : Failed to report global rollback [10.180.41.23:8091:8169750104099594487],Retry Countdown: 5, reason: RPC timeout

2022-01-15 17:55:40.556 ERROR 27940 --- [h_RMROLE_1_2_12] i.s.c.e.AbstractExceptionHandler : Catch RuntimeException while do RPC, request: xid=10.180.41.23:8091:8169750104099594487,branchId=531645134559981799,branchType=AT,resourceId=jdbc:mysql://10.180.8.109:3306/club,applicationData=null
```

**B服务发生如下报错:**
```
io.seata.common.exception.ShouldNeverHappenException: null
at io.seata.rm.datasource.DataSourceManager.branchRollback(DataSourceManager.java:149) ~[seata-all-1.4.0.jar:1.4.0]
at io.seata.rm.AbstractRMHandler.doBranchRollback(AbstractRMHandler.java:125) [seata-all-1.4.0.jar:1.4.0]
at io.seata.rm.AbstractRMHandler$2.execute(AbstractRMHandler.java:67) ~[seata-all-1.4.0.jar:1.4.0]
at io.seata.rm.AbstractRMHandler$2.execute(AbstractRMHandler.java:63) ~[seata-all-1.4.0.jar:1.4.0]
at io.seata.core.exception.AbstractExceptionHandler.exceptionHandleTemplate(AbstractExceptionHandler.java:116) ~[seata-all-1.4.0.jar:1.4.0]
at io.seata.rm.AbstractRMHandler.handle(AbstractRMHandler.java:63) [seata-all-1.4.0.jar:1.4.0]
at io.seata.rm.DefaultRMHandler.handle(DefaultRMHandler.java:62) [seata-all-1.4.0.jar:1.4.0]
at io.seata.core.protocol.transaction.BranchRollbackRequest.handle(BranchRollbackRequest.java:35) [seata-all-1.4.0.jar:1.4.0]
at io.seata.rm.AbstractRMHandler.onRequest(AbstractRMHandler.java:150) [seata-all-1.4.0.jar:1.4.0]
at io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.handleBranchRollback(RmBranchRollbackProcessor.java:63) [seata-all-1.4.0.jar:1.4.0]
at io.seata.core.rpc.processor.client.RmBranchRollbackProcessor.process(RmBranchRollbackProcessor.java:58) [seata-all-1.4.0.jar:1.4.0]
at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:278) [seata-all-1.4.0.jar:1.4.0]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_201]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.67.Final.jar:4.1.67.Final]
at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_201]

2022-01-15 17:55:40.557 ERROR 27940 --- [ctor_RMROLE_1_1] i.s.core.rpc.netty.v1.ProtocolV1Encoder : Encode request error!

java.lang.NullPointerException: null
at io.seata.serializer.seata.protocol.transaction.AbstractBranchEndResponseCodec.encode(AbstractBranchEndResponseCodec.java:55) ~[seata-all-1.4.0.jar:1.4.0]
at io.seata.serializer.seata.SeataSerializer.serialize(SeataSerializer.java:47) ~[seata-all-1.4.0.jar:1.4.0]
at io.seata.core.rpc.netty.v1.ProtocolV1Encoder.encode(ProtocolV1Encoder.java:96) ~[seata-all-1.4.0.jar:1.4.0]
at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107) [netty-codec-4.1.67.Final.jar:4.1.67.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717) [netty-transport-4.1.67.Final.jar:4.1.67.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:764) [netty-transport-4.1.67.Final.jar:4.1.67.Final]
at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071) [netty-transport-4.1.67.Final.jar:4.1.67.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:164) [netty-common-4.1.67.Final.jar:4.1.67.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java) [netty-common-4.1.67.Final.jar:4.1.67.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) [netty-common-4.1.67.Final.jar:4.1.67.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [netty-transport-4.1.67.Final.jar:4.1.67.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [netty-common-4.1.67.Final.jar:4.1.67.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.67.Final.jar:4.1.67.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.67.Final.jar:4.1.67.Final]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_201]
```

**seata发生如下报错**

```
17:55:40.551 INFO --- [ RetryRollbacking_1_1] io.seata.core.rpc.netty.ChannelManager : Choose [id: 0xd9b16e43, L:/10.180.41.23:8091 - R:/10.180.41.23:57860] on the same IP[10.180.41.23] as alternative of seata-server:10.180.41.23:58135
17:55:40.557 ERROR --- [ttyServerNIOWorker_1_8_12] i.s.c.rpc.netty.AbstractNettyRemoting : This rpcMessage body[null] is not MessageTypeAware type.
17:56:10.556 ERROR --- [ RetryRollbacking_1_1] i.s.c.rpc.netty.AbstractNettyRemoting : wait response error:cost 30004 ms,ip:/10.180.41.23:57860,request:xid=10.180.41.23:8091:8169750104099594487,branchId=531645134559981799,branchType=AT,resourceId=jdbc:mysql://10.180.8.109:3306/club,applicationData=null
17:56:10.558 ERROR --- [ RetryRollbacking_1_1] io.seata.server.session.SessionHelper : handle global session failed: 10.180.41.23:8091:8169750104099594487
==>
java.lang.ArrayStoreException: io.seata.core.exception.BranchTransactionException
at io.seata.core.logger.StackTraceLogger.buildNewArgs(StackTraceLogger.java:82) ~[seata-core-1.4.2.jar:na]
at io.seata.core.logger.StackTraceLogger.error(StackTraceLogger.java:61) ~[seata-core-1.4.2.jar:na]
at io.seata.server.coordinator.DefaultCore.lambda$doGlobalRollback$3(DefaultCore.java:332) ~[seata-server-1.4.2.jar:na]
at io.seata.server.session.SessionHelper.forEach(SessionHelper.java:182) ~[seata-server-1.4.2.jar:na]
at io.seata.server.coordinator.DefaultCore.doGlobalRollback(DefaultCore.java:307) ~[seata-server-1.4.2.jar:na]
at io.seata.server.coordinator.DefaultCoordinator.lambda$handleRetryRollbacking$2(DefaultCoordinator.java:301) [seata-server-1.4.2.jar:na]
at io.seata.server.session.SessionHelper.forEach(SessionHelper.java:161) ~[seata-server-1.4.2.jar:na]
at io.seata.server.coordinator.DefaultCoordinator.handleRetryRollbacking(DefaultCoordinator.java:281) [seata-server-1.4.2.jar:na]
at io.seata.server.coordinator.DefaultCoordinator.lambda$init$5(DefaultCoordinator.java:403) [seata-server-1.4.2.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[na:1.8.0_201]
at java.util.concurrent.FutureTask.runAndReset(Unknown Source) ~[na:1.8.0_201]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source) ~[na:1.8.0_201]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) ~[na:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.8.0_201]
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(Unknown Source) ~[na:1.8.0_201]
<==
```

### Ⅲ. Environment:

- JDK version : JDK 8
- Seata version: 1.4.2
- OS : centos/win 都一样

Contributor guide

Open the contributing guide

Research direction

Start with the reported stack traces in DataSourceManager.java, AbstractRMHandler.java, and AbstractBranchEndResponseCodec.java, then trace the rollback response through DefaultCore.java and StackTraceLogger.java. Reproduce the cluster AT-mode rollback timeout if possible and determine the failure path across client and server. Done means the rollback response completes without the reported RPC timeout, null body, or subsequent logging error.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.