incubator-seata icon indicating copy to clipboard operation
incubator-seata copied to clipboard
verified publisher icon apache

s.c.rpc.netty.AbstractNettyRemoting : 0104 ==> java.lang.RuntimeException: channel is error.

Open xujiliang opened this issue 3 years ago • 3 comments

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

Ⅰ. Issue Description

项目中使用seata解决分布式事务，使用过程中会经常出现该问题，在全局事务开始时就出现RPC timeout 30000，导致全局事务开启失败； 项目中使用dubbo实现分布式服务间服务调用，nacos做注册中心，seata解决分布式事务；

Ⅱ. Describe what happened

项目中使用seata解决分布式事务，使用过程中会经常出现该问题，在全局事务开始时就出现RPC timeout 30000；

seata client 报错如下：wait response error:cost 30000，导致全局事务开启失败。 Seata server报错如下： 2022-08-23 19:50:39.847 INFO --- [ ServerHandlerThread_1_46_500] i.s.s.coordinator.DefaultCoordinator : Begin new global transaction applicationId: A-Service,transactionServiceGroup: aaa_tx_group, transactionName: saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map),timeout:300000,xid:172.1.1.1:8091:1567543182094449370 2022-08-23 19:50:39.847 INFO --- [ ServerHandlerThread_1_31_500] i.s.s.coordinator.DefaultCoordinator : Begin new global transaction applicationId: A-Service,transactionServiceGroup: aaa_tx_group, transactionName: saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map),timeout:300000,xid:172.1.1.1:8091:1567543182094449406 2022-08-23 19:50:39.847 ERROR --- [ ServerHandlerThread_1_46_500] i.s.c.rpc.netty.AbstractNettyRemoting : 0104 ==> java.lang.RuntimeException: channel is error. at io.seata.core.rpc.netty.AbstractNettyRemotingServer.sendAsyncResponse(AbstractNettyRemotingServer.java:104) ~[seata-core-1.4.2.jar:na] at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:120) ~[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] <==

2022-08-23 19:50:39.847 ERROR --- [ ServerHandlerThread_1_31_500] i.s.c.rpc.netty.AbstractNettyRemoting : 0104 ==> java.lang.RuntimeException: channel is error. at io.seata.core.rpc.netty.AbstractNettyRemotingServer.sendAsyncResponse(AbstractNettyRemotingServer.java:104) ~[seata-core-1.4.2.jar:na] at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:120) ~[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] <==

Just paste your stack trace here!

2022-08-23 19:50:39.847  INFO --- [  ServerHandlerThread_1_46_500] i.s.s.coordinator.DefaultCoordinator     : Begin new global transaction applicationId: A-Service,transactionServiceGroup: aaa_tx_group, transactionName: saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map),timeout:300000,xid:172.1.1.1:8091:1567543182094449370
2022-08-23 19:50:39.847  INFO --- [  ServerHandlerThread_1_31_500] i.s.s.coordinator.DefaultCoordinator     : Begin new global transaction applicationId: A-Service,transactionServiceGroup: aaa_tx_group, transactionName: saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map),timeout:300000,xid:172.1.1.1:8091:1567543182094449406
2022-08-23 19:50:39.847 ERROR --- [  ServerHandlerThread_1_46_500] i.s.c.rpc.netty.AbstractNettyRemoting    : 0104
==>
java.lang.RuntimeException: channel is error.
	at io.seata.core.rpc.netty.AbstractNettyRemotingServer.sendAsyncResponse(AbstractNettyRemotingServer.java:104) ~[seata-core-1.4.2.jar:na]
	at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:120) ~[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]
<==

2022-08-23 19:50:39.847 ERROR --- [  ServerHandlerThread_1_31_500] i.s.c.rpc.netty.AbstractNettyRemoting    : 0104
==>
java.lang.RuntimeException: channel is error.
	at io.seata.core.rpc.netty.AbstractNettyRemotingServer.sendAsyncResponse(AbstractNettyRemotingServer.java:104) ~[seata-core-1.4.2.jar:na]
	at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:120) ~[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

开启全局事务时seata client 报错如下：wait response error:cost 30000，导致全局事务开启失败。

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

  1. xxx
  2. xxx
  3. xxx

Ⅴ. Anything else we need to know?

Ⅵ. Environment:

  • JDK version 1.8:
  • Seata version 1.4.2:
  • OS 阿里云平台:
  • Others:

xujiliang avatar Aug 24 '22 01:08 xujiliang

如果是tm到tc timeout30s，建议根据日志打印时间去看下tc端是否发生了异常导致没有正常响应，如果是tc到rm那么反过来去看，先确认下问题是什么 另外1.5以上的版本支持设置rpc的timeout，避免业务线程被阻塞30s才释放 transport.rpcRmRequestTimeout=30000 transport.rpcTmRequestTimeout=30000 transport.rpcTcRequestTimeout=30000

funky-eyes avatar Aug 24 '22 02:08 funky-eyes

在tm开始全局事务时，tm与tc的通信过程中出现改错误：以下是tc报错日志： 2022-08-23 19:50:29.797 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage timeout=300000,transactionName=saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map) ,clientIp:172.0.0.116,vgroup:aaa_tx_group 2022-08-23 19:50:29.907 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage xid=172.0.0.199:8091:4098566172688203632,branchType=AT,resourceId=jdbc:postgresql://172.0.0.152:5432/testdb?currentSchema=aaa,lockKey=TABLE_A_B_VER:1562044604516298753,1562044605086724097,1562044605086724098,1562044605086724099,1562044605090918402,1562044605090918403 ,clientIp:172.0.0.122,vgroup:aaa_tx_group 2022-08-23 19:50:32.782 INFO --- [ batchLoggerPrint_1_1] i.s.c.r.p.server.BatchLogHandler : SeataMergeMessage timeout=300000,transactionName=saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map) ,clientIp:172.0.0.116,vgroup:aaa_tx_group 2022-08-23 19:50:35.504 INFO --- [ NettyServerNIOWorker_1_2_2] i.s.c.r.n.AbstractNettyRemotingServer : 172.0.0.104:60034 to server channel inactive. 2022-08-23 19:50:35.504 INFO --- [ NettyServerNIOWorker_1_2_2] i.s.c.r.n.AbstractNettyRemotingServer : remove channel:[id: 0x5c54a684, L:/172.0.0.174:8091 ! R:/172.0.0.104:60034]context:RpcContext{applicationId='b-service', transactionServiceGroup='aaa_tx_group', clientId='b-service:172.0.0.104:60034', channel=[id: 0x5c54a684, L:/172.0.0.174:8091 ! R:/172.0.0.104:60034], resourceSets=[]} 2022-08-23 19:50:36.401 INFO --- [ NettyServerNIOWorker_1_2_2] i.s.c.r.n.AbstractNettyRemotingServer : 172.0.0.116:54882 to server channel inactive. 2022-08-23 19:50:36.401 INFO --- [ NettyServerNIOWorker_1_2_2] i.s.c.r.n.AbstractNettyRemotingServer : remove channel:[id: 0xdbd4d2f4, L:/172.0.0.174:8091 ! R:/172.0.0.116:54882]context:RpcContext{applicationId='a-center', transactionServiceGroup='aaa_tx_group', clientId='a-center:172.0.0.116:54882', channel=[id: 0xdbd4d2f4, L:/172.0.0.174:8091 ! R:/172.0.0.116:54882], resourceSets=null} 2022-08-23 19:50:36.540 INFO --- [ NettyServerNIOWorker_1_2_2] i.s.c.r.n.AbstractNettyRemotingServer : 172.0.0.122:54908 to server channel inactive. 2022-08-23 19:50:36.540 INFO --- [ NettyServerNIOWorker_1_2_2] i.s.c.r.n.AbstractNettyRemotingServer : remove channel:[id: 0x821773d6, L:/172.0.0.174:8091 ! R:/172.0.0.122:54908]context:RpcContext{applicationId='PCenter', transactionServiceGroup='aaa_tx_group', clientId='PCenter:172.0.0.122:54908', channel=[id: 0x821773d6, L:/172.0.0.174:8091 ! R:/172.0.0.122:54908], resourceSets=[]} 2022-08-23 19:50:37.231 INFO --- [ ServerHandlerThread_1_4_500] io.seata.server.coordinator.DefaultCore : Rollback branch transaction successfully, xid = 172.16.1.199:8091:4098566172688203625 branchId = 4098566172688203627 2022-08-23 19:50:37.233 INFO --- [ ServerHandlerThread_1_7_500] io.seata.server.coordinator.DefaultCore : Rollback branch transaction fail and will retry, xid = 172.0.0.154:8091:1387399197000508991 branchId = 4098566172688203624 2022-08-23 19:50:39.847 INFO --- [ ServerHandlerThread_1_46_500] i.s.s.coordinator.DefaultCoordinator : Begin new global transaction applicationId: a-center,transactionServiceGroup: aaa_tx_group, transactionName: saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map),timeout:300000,xid:172.0.0.174:8091:1567543182094449370 2022-08-23 19:50:39.847 INFO --- [ ServerHandlerThread_1_31_500] i.s.s.coordinator.DefaultCoordinator : Begin new global transaction applicationId: a-center,transactionServiceGroup: aaa_tx_group, transactionName: saveData(com.aaa.bbb.ccc.vo.PowerModelGroupVo, java.util.Map, java.util.Map),timeout:300000,xid:172.0.0.174:8091:1567543182094449406 2022-08-23 19:50:39.847 ERROR --- [ ServerHandlerThread_1_46_500] i.s.c.rpc.netty.AbstractNettyRemoting : 0104 ==> java.lang.RuntimeException: channel is error. at io.seata.core.rpc.netty.AbstractNettyRemotingServer.sendAsyncResponse(AbstractNettyRemotingServer.java:104) ~[seata-core-1.4.2.jar:na] at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:120) ~[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] <==

2022-08-23 19:50:39.847 ERROR --- [ ServerHandlerThread_1_31_500] i.s.c.rpc.netty.AbstractNettyRemoting : 0104

xujiliang avatar Aug 24 '22 09:08 xujiliang

tm在开启全局事务之前没有报错，开启全局事务的时候TC端有如上报错，并且这种报错不是一直会有，一段时间内会出现大量这种问题。请教一下，会是什么原因导致的该问题

xujiliang avatar Aug 24 '22 13:08 xujiliang

tm在开启全局事务之前没有报错，开启全局事务的时候TC端有如上报错，并且这种报错不是一直会有，一段时间内会出现大量这种问题。请教一下，会是什么原因导致的该问题

问题解决了吗？我这也经常出现。

superleo-cn avatar Oct 11 '22 06:10 superleo-cn

tm在开启全局事务之前没有报错，开启全局事务的时候TC端有如上报错，并且这种报错不是一直会有，一段时间内会出现大量这种问题。请教一下，会是什么原因导致的该问题

可能是因为用的xa模式或者tcc模式，请升级1.5及以上版本

funky-eyes avatar Feb 01 '23 07:02 funky-eyes

tm在开启全局事务之前没有报错，开启全局事务的时候TC端有如上报错，并且这种报错不是一直会有，一段时间内会出现大量这种问题。请教一下，会是什么原因导致的该问题

可能是因为用的xa模式或者tcc模式，请升级1.5及以上版本

1.4.2版本，saga 模式，同样报错，是啥问题呢？

yop-wdc avatar May 07 '23 03:05 yop-wdc

tm在开启全局事务之前没有报错，开启全局事务的时候TC端有如上报错，并且这种报错不是一直会有，一段时间内会出现大量这种问题。请教一下，会是什么原因导致的该问题

可能是因为用的xa模式或者tcc模式，请升级1.5及以上版本

1.4.2版本，saga 模式，同样报错，是啥问题呢？

saga跟这个没有关系，错误可能都不是一个，不要搞混，有问题提issue

funky-eyes avatar May 07 '23 04:05 funky-eyes

Ⅰ. Issue Description 项目中使用seata解决分布式事务，使用过程中偶现该问题，在全局事务开始时就出现RPC timeout 30000，导致全局事务开启失败； 项目中使用restful实现分布式服务间服务调用，nacos做注册中心，seata解决分布式事务；

Ⅱ. Describe what happened 项目中使用seata解决分布式事务，使用过程中会经常出现该问题，在全局事务开始时就出现RPC timeout 30000；

seata client 报错如下：wait response error:cost 30000，导致全局事务开启失败。 Seata server报错如下：

00:20:21.830 INFO --- [ batchLoggerPrint_1_1] [ocessor.server.BatchLogHandler] [ run] [] : receive msg[single]: GlobalBeginRequest{transactionName='wo.op.report.picking.return.create', timeout=6000000}, clientIp: 10.192.23.34, vgroup: default_tx_group 00:20:28.930 INFO --- [ettyServerNIOWorker_1_4_8] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : 10.192.23.34:48020 to server channel inactive. 00:20:28.930 INFO --- [ettyServerNIOWorker_1_4_8] [ty.AbstractNettyRemotingServer] [ handleDisconnect] [] : remove channel:[id: 0x06609bc3, L:/10.192.19.108:8091 ! R:/10.192.23.34:48020]context:RpcContext{applicationId='APC', transactionServiceGroup='default_tx_group', clientId='APC:10.192.23.34:48020', channel=[id: 0x06609bc3, L:/10.192.19.108:8091 ! R:/10.192.23.34:48020], resourceSets=null} 00:20:30.354 INFO --- [verHandlerThread_1_42_500] [coordinator.DefaultCoordinator] [ doGlobalBegin] [10.192.19.108:8091:6296547817037284291] : Begin new global transaction applicationId: APC,transactionServiceGroup: default_tx_group, transactionName: wo.op.report.picking.return.create,timeout:6000000,xid:10.192.19.108:8091:6296547817037284291 00:20:30.355 ERROR --- [verHandlerThread_1_42_500] [pc.netty.AbstractNettyRemoting] [bda$processMessage$2] [10.192.19.108:8091:6296547817037284291] : 0104 ==> java.lang.RuntimeException: channel is error. at io.seata.core.rpc.netty.AbstractNettyRemotingServer.sendAsyncResponse(AbstractNettyRemotingServer.java:106) ~[seata-core-1.7.0.jar:1.7.0] at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.onRequestMessage(ServerOnRequestProcessor.java:207) ~[seata-core-1.7.0.jar:1.7.0] at io.seata.core.rpc.processor.server.ServerOnRequestProcessor.process(ServerOnRequestProcessor.java:122) ~[seata-core-1.7.0.jar:1.7.0] at io.seata.core.rpc.netty.AbstractNettyRemoting.lambda$processMessage$2(AbstractNettyRemoting.java:281) ~[seata-core-1.7.0.jar:1.7.0] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_342] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_342] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.76.Final.jar:4.1.76.Final] at java.lang.Thread.run(Thread.java:750) ~[na:1.8.0_342] <==

JDK version 1.8: Seata version 1.7.0: OS微软云平台:

seataAT模式，seata版本1.7.0

lu1235353884 avatar Apr 30 '24 03:04 lu1235353884