RocketMq closeChannel: close the connection to remote address[] 排查记录
最近,开发环境服务频繁打印rocketmq日志:NettyClientSelector_1 [RocketmqRemoting:95] - closeChannel: close the connection to remote address[] result: true。
尽管是info级别日志,但由于过于频繁,我们还是进行了一次排查。
首先搜索引擎薅了一圈,大概总结下来有两种。1、端口未开放;2、版本不匹配。
鉴于我们只是部分服务报出此类问题,且所有服务公用一套rocketmq ,因此端口问题可以排除。
关于版本问题,由于服务client使用4.7.1版本,name server使用4.5.0版本,尝试降低本地版本,日志问题依然存在。
因此推断并非上述两点原因。
由于日志仅提示connection close,并未有其他的异常,因此我们只能首先去定位到日志打印的代码块。
日志中RocketmqRemoting并非一个真实的对象,因此我们去参考github上wiki,我们在#2285rocketmq INFO closeChannel: close the connection to remote address[192.168.8.185:30911] result: true · Issue #2285 · apache/rocketmq · GitHub中找到一些可能的提示。
接下来,我们找到
RemotingUtil.closeChannel(channel)方法。
此处,便是日志打印的代码块。
那么,该代码块是如何触发的呢。
通过搜到相关方法(后来下载了源码),发现在
NettyRemotingClient对象中存在大量对该方法的调用。
通过断点,我们发现频繁的日志打印是通过NettyRemotingClient.
closeChannel()触发。
那么该方法又是如何触发的呢,接下来我们继续排查。
通过方法调用,我们发现NettyRemotingClient.NettyConnectManageHandler.close()触发了closeChannel的调用。
而通过分析 NettyRemotingClient源码我们发现,producer和consumer启动时候均会调用start方法,而该方法在client中最终实现均为体现在NettyRemotingClient的start方法中。
根据netty channel原理,通道关闭时,会触发
NettyConnectManageHandler的
close()方法,因此会触发上述日志的打印。
由于对netty了解并不太深刻,且name-server服务正常,目前没有分析出是何种情况触发了channel的close事件,后续将在进一步完善netty及rocketmq netty等相关知识后再做进一步的分析。
由于该日志不影响服务及业务,暂时我们可以通过屏蔽该日志去解决,您可在您的log4j.xml中新增如下配置。
<logger name="RocketmqRemoting" level="warn" additivity="false"/>
该问题暂时告一段落,有方案或者有思路的朋友请在评论区留言,欢迎指教。针对文中有描述错误的地方也非常欢迎大家指正,谢谢。
更多推荐
所有评论(0)