偶尔出现 RST-500407: RSocket close by peer: tcp://127.0.0.1:9999 #95

pc859107393 · 2020-11-27T10:45:19Z

问题描述
在线上环境上面，偶尔出现这个错误，详细描述如下：

2020-11-26 10:41:43,349 [parallel-5] ERROR [c.alibaba.rsocket.loadbalance.LoadBalancedRSocket] LoadBalancedRSocket.java:333 - RST-500407: RSocket close by peer: tcp://127.0.0.1:9999

环境变量

Alibaba RSocket Broker version: 具体版本忘记了，上一次我那边合并分支是到master的update to grpc-spring-boot-starter 4.0.0 这里
Operating System version: Ubuntu 20.04.1 LTS
Java version: 1.8.0

后续产生问题

当丢失broker后，没有即时释放的Payload会产生错误：io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
后续的微服务调用中会产生服务名称为*的错误

部分异常信息如下：

2020-11-26 10:41:43,349 [parallel-5] ERROR [c.alibaba.rsocket.loadbalance.LoadBalancedRSocket] LoadBalancedRSocket.java:333 - RST-500407: RSocket close by peer: tcp://127.0.0.1:9999
2020-11-26 10:41:43,356 [parallel-5] WARN  [io.netty.util.ReferenceCountUtil] ReferenceCountUtil.java:115 - Failed to release a message: io.rsocket.util.ByteBufPayload@417e69ba
io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
        at io.netty.util.internal.ReferenceCountUpdater.toLiveRealRefCnt(ReferenceCountUpdater.java:74)
        at io.netty.util.internal.ReferenceCountUpdater.release(ReferenceCountUpdater.java:138)
        at io.netty.util.AbstractReferenceCounted.release(AbstractReferenceCounted.java:76)
        at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:88)
        at io.netty.util.ReferenceCountUtil.safeRelease(ReferenceCountUtil.java:113)
        at com.alibaba.rsocket.loadbalance.LoadBalancedRSocket.requestResponse(LoadBalancedRSocket.java:188)
        at com.alibaba.rsocket.loadbalance.LoadBalancedRSocket.lambda$requestResponse$8(LoadBalancedRSocket.java:195)
        at reactor.core.publisher.Mono.lambda$onErrorResume$31(Mono.java:3361)
        at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:88)
        at reactor.core.publisher.FluxContextStart$ContextStartSubscriber.onError(FluxContextStart.java:110)
        at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onError(MonoSubscribeOn.java:150)
        at io.rsocket.core.RequestOperator.onError(RequestOperator.java:142)
        at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:87)
        at reactor.core.publisher.UnicastProcessor.checkTerminated(UnicastProcessor.java:354)
        at reactor.core.publisher.UnicastProcessor.drainRegular(UnicastProcessor.java:239)
        at reactor.core.publisher.UnicastProcessor.drain(UnicastProcessor.java:331)
        at reactor.core.publisher.UnicastProcessor.onError(UnicastProcessor.java:423)
        at io.rsocket.core.RSocketRequester.lambda$terminate$15(RSocketRequester.java:800)
        at java.lang.Iterable.forEach(Iterable.java:75)
        at io.rsocket.core.RSocketRequester.terminate(RSocketRequester.java:797)
        at io.rsocket.core.RSocketRequester.lambda$tryShutdown$14(RSocketRequester.java:786)
        at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84)
        at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)


reactor.core.Exceptions$ReactiveException: com.alibaba.rsocket.loadbalance.NoAvailableConnectionException: RST-200404: Upstream RSocket not found for *
        at reactor.core.Exceptions.propagate(Exceptions.java:393)
        at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:97)
        at reactor.core.publisher.Mono.block(Mono.java:1679)
        at cn.yunjivip.trans.gateway.juhe.wsJson.service.impl.AtTransServiceImpl.execute(AtTransServiceImpl.kt:97)
        at cn.yunjivip.trans.gateway.juhe.wsJson.wsEndpoint.MyWebsocket.onMessage(MyWebsocket.kt:61)
        at sun.reflect.GeneratedMethodAccessor56.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at cn.yunjivip.netty.pojo.PojoEndpointServer.doOnMessage(PojoEndpointServer.java:184)
        at cn.yunjivip.netty.standard.WebSocketServerHandler.handleWebSocketFrame(WebSocketServerHandler.java:42)
        at cn.yunjivip.netty.standard.WebSocketServerHandler.channelRead0(WebSocketServerHandler.java:22)
        at cn.yunjivip.netty.standard.WebSocketServerHandler.channelRead0(WebSocketServerHandler.java:11)
        at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:311)
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:425)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
        Suppressed: java.lang.Exception: #block terminated with an error
                at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:99)
                ... 34 common frames omitted
Caused by: com.alibaba.rsocket.loadbalance.NoAvailableConnectionException: RST-200404: Upstream RSocket not found for *
        at com.alibaba.rsocket.loadbalance.LoadBalancedRSocket.requestResponse(LoadBalancedRSocket.java:189)
        at com.alibaba.rsocket.invocation.RSocketRequesterRpcProxy.remoteRequestResponse(RSocketRequesterRpcProxy.java:277)
        at com.alibaba.rsocket.invocation.RSocketRequesterRpcProxy.invoke(RSocketRequesterRpcProxy.java:231)
        at ChannelSelectorServiceRSocketStub.atChannelSelector(Unknown Source)
        ... 33 common frames omitted

The text was updated successfully, but these errors were encountered:

linux-china · 2020-11-28T00:33:21Z

这个错误会出现的，如broker服务器不可用的时候，但是客户端会尝试重新连接RSocket Broker服务器。 * 代码表匹配所有服务，其实就是broker。
如果你上次合并 grpc-spring-boot-starter 4.0.0 ，那么应该比较早啦，那是9月份版本，能看能否合并最新的版本的试试。

pc859107393 · 2020-11-28T03:05:03Z

我把最新的代码合并看一看，但是严格说来应该是不会出现这个问题，因为目前这些服务都是在同一台服务器上。我这边再持续观察一下。目前还没定位到具体发生问题的原因是什么。而且我这边核对项目记录，貌似最新的这一块的代码也没有涉及到这一块相关的东西。我这边先整合一下再持续观察一下。

pc859107393 · 2020-11-28T03:11:57Z

而且这个问题目前出现的症状比较奇怪的在于，其他的服务都链接的上，而且这个链接断开的服务前面也是正常使用的。在这个服务断开的时候，其他的服务还是正常使用的。

linux-china · 2020-11-28T03:53:47Z

你观察一下，将步骤记录一下，也可能是bug，但是不用担心，都能修复的 :)

pc859107393 · 2020-12-20T17:17:34Z

关于这个问题的回顾，目前我这边大概是每秒钟最大通过broker的数据量有2300个请求左右。而且我这边主要是一些音频或者视频分片数据的透传场景，每秒钟数据大概是20m/s左右broker稳定。超过后会导致broker转发到其他服务的时候异常（出现xxx服务链接超时，可能是单个链接的性能极限）。再超过50m/s的数据后，broker会出现很多问题，严重可能导致broker崩溃。具体的我这边需要后续采集数据再回馈。目前我这边有一些改造broker的一些思路。

linux-china · 2020-12-20T18:56:24Z

@pc859107393 最好能观测一下网络的情况，在图片和视频的场景，网络很大程度上成为瓶颈，我之前就遇到多次。举一个例子，如果操作的是图片，一个图平均10M的话，那么QPS根本就不可能上的去，网络带宽和网卡的瓶颈就在那里，仅提供参考。

linux-china · 2021-04-24T06:17:01Z

新的LoadBalancedRSocket添加了连接错误重试机制，如一些网络的问题，或者服务器的一些问题，客户端SDK会进行重连。

pc859107393 · 2021-04-25T03:01:15Z

@linux-china 好的，我这边同步一下。谢谢大佬

hupeiD · 2022-02-22T08:48:36Z

请问这个问题还有后续么，我这边也遇到相同的问题，也是传输图片分片数据，然后断开了。目前的链路是这样的provider->broker->consumer，三者部署在同一台服务器上。但是很奇怪的是，provider应用没有断开，consumer应用反而断开了。其次，consumer应用断开后，虽然报了RST-500407，但是却并没有重连操作，Broker的服务端和客户端的版本均是1.1.2。

pc859107393 · 2022-02-22T09:04:58Z

@hupeiD 我是自己实现了直连，轻松解决问题。

linux-china · 2022-02-22T18:44:39Z

请问这个问题还有后续么，我这边也遇到相同的问题，也是传输图片分片数据，然后断开了。目前的链路是这样的provider->broker->consumer，三者部署在同一台服务器上。但是很奇怪的是，provider应用没有断开，consumer应用反而断开了。其次，consumer应用断开后，虽然报了RST-500407，但是却并没有重连操作，Broker的服务端和客户端的版本均是1.1.2。

这个经常出现还是偶发的？能重现吗？

hupeiD · 2022-02-23T02:20:37Z

@hupeiD 我是自己实现了直连，轻松解决问题。

我这边要动态的分配到不同的节点，所以没法用p2p去实现。

hupeiD · 2022-02-23T02:21:02Z

请问这个问题还有后续么，我这边也遇到相同的问题，也是传输图片分片数据，然后断开了。目前的链路是这样的provider->broker->consumer，三者部署在同一台服务器上。但是很奇怪的是，provider应用没有断开，consumer应用反而断开了。其次，consumer应用断开后，虽然报了RST-500407，但是却并没有重连操作，Broker的服务端和客户端的版本均是1.1.2。

这个经常出现还是偶发的？能重现吗？

是必现的，我简单说一下场景，希望可以帮助你分析。

现在将provider、broker和consumer部署在不同服务器上，产生的图片分片数据，通过provider经由broker转发给consumer，监控流量，大概在15Mb/s~20Mb/s左右，consumer就断开连接了。consumer应用仍在运行，但是与Broker已断连，有不断打印心跳超时的日志，但是无重连日志，期间检测到consumer的CPU使用率暴涨到96%左右，具体哪个线程还需要分析。

linux-china · 2022-02-23T16:59:01Z

@hupeiD 图片的分片大小是多少？ 5M，10M还是15M？能否给一个拆分后图片具体的大小？主要是RSocket有16M的大小限制。除了图片分片的场景，通过provider经由broker转发给consumer，如果发送一个Hello world，这个能成功吧？这个请求是request/stream还是request/response？

你能传一个简单的样例到github上吗？这样方便排查问题。

另外仅仅是个人建议：对于这种传输大量二进制数据的场景，如图片视频等，可以考虑如数据接收方将数据保存到一个中心存储上，如AWS S3，Aliyun OSS，当然内部搭建也可以。数据保存后获得对于的URL或者UUID，然后再将该信息发送给对应的数据处理方，而不是将这些二进制数据作为消息的一部分发送出去。如你使用Kafka，发送一个32M的消息，这个Kafka也是非常难承受的，而且存储和网络压力都非常大，虽然这些消息类产品也能做这个事情，但是会有非常高的风险。 Broker不适合传输这种大的二进制数据，网络压力就非常大。这些仅供参考。

hupeiD · 2022-02-24T06:51:28Z

@linux-china 图片大小其实只有5KB左右，并发请求不到400。是用request/response发送的，按我理解，经过broker的话，request/stream和request/response似乎区别不是很大。

也考虑过保存到中心存储，但是由于实时性要求高，所以并不是第一方案。由于网络是内部搭建的，网络资源上倒是还好。关于RSocket的16M的大小限制，这点我确实不太清楚，方便的话能说一下具体的情况么，或者这是可以调整的。如果无法调整，那可能要考虑中心存储或者其他方案了。

样例其实比较简单，就是consumer提供一个接口上传图片，对同一组图片做二次处理，然后到存储就是了。demo如果需要，我花点时间稍晚点再上传。：)

linux-china · 2022-02-24T16:21:36Z

@hupeiD 明白啦，感谢说明。如果有一个demo能重现问题，这个是最好解决的。

hupeiD · 2022-08-01T13:50:12Z

基本能确定是因为用户线程使用不当，长时间压测导致的消息堆积，使Netty的工作线程阻塞，最后引发心跳超时。

看源码，应该是没有另外指定线程池的，那client和server的通信另外指定线程池会不会更好呢？

linux-china closed this as completed Apr 24, 2021

linux-china reopened this Feb 25, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

偶尔出现 RST-500407: RSocket close by peer: tcp://127.0.0.1:9999 #95

偶尔出现 RST-500407: RSocket close by peer: tcp://127.0.0.1:9999 #95

pc859107393 commented Nov 27, 2020 •

edited

linux-china commented Nov 28, 2020

pc859107393 commented Nov 28, 2020

pc859107393 commented Nov 28, 2020

linux-china commented Nov 28, 2020

pc859107393 commented Dec 20, 2020

linux-china commented Dec 20, 2020

linux-china commented Apr 24, 2021

pc859107393 commented Apr 25, 2021

hupeiD commented Feb 22, 2022

pc859107393 commented Feb 22, 2022

linux-china commented Feb 22, 2022

hupeiD commented Feb 23, 2022

hupeiD commented Feb 23, 2022

linux-china commented Feb 23, 2022 •

edited

hupeiD commented Feb 24, 2022

linux-china commented Feb 24, 2022

hupeiD commented Aug 1, 2022

偶尔出现 RST-500407: RSocket close by peer: tcp://127.0.0.1:9999 #95

偶尔出现 RST-500407: RSocket close by peer: tcp://127.0.0.1:9999 #95

Comments

pc859107393 commented Nov 27, 2020 • edited

环境变量

后续产生问题

部分异常信息如下：

linux-china commented Nov 28, 2020

pc859107393 commented Nov 28, 2020

pc859107393 commented Nov 28, 2020

linux-china commented Nov 28, 2020

pc859107393 commented Dec 20, 2020

linux-china commented Dec 20, 2020

linux-china commented Apr 24, 2021

pc859107393 commented Apr 25, 2021

hupeiD commented Feb 22, 2022

pc859107393 commented Feb 22, 2022

linux-china commented Feb 22, 2022

hupeiD commented Feb 23, 2022

hupeiD commented Feb 23, 2022

linux-china commented Feb 23, 2022 • edited

hupeiD commented Feb 24, 2022

linux-china commented Feb 24, 2022

hupeiD commented Aug 1, 2022

pc859107393 commented Nov 27, 2020 •

edited

linux-china commented Feb 23, 2022 •

edited