最近,开发环境服务频繁打印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"/>

 

该问题暂时告一段落,有方案或者有思路的朋友请在评论区留言,欢迎指教。针对文中有描述错误的地方也非常欢迎大家指正,谢谢。

Logo

旨在为数千万中国开发者提供一个无缝且高效的云端环境,以支持学习、使用和贡献开源项目。

更多推荐