問題描述

參考RocketMQ官方文檔在本地啟動(dòng)一個(gè)驗(yàn)證環(huán)境的時(shí)候遇到超時(shí)報(bào)錯(cuò)問題。

本地環(huán)境OS：CentOS Linux release 8.5.2111

首先，進(jìn)入到RocketMQ安裝目錄，如：~/opt/rocketmq-all-5.2.0-bin-release。

執(zhí)行如下命令啟動(dòng)NameServer：

$ sh bin/mqnamesrv

該命令執(zhí)行很慢，但是最終還是顯示啟動(dòng)NameServer成功了，輸出日志如下：

Java HotSpot(TM) 64-Bit Server VM warning: Using the DefNew young collector with the CMS collector is deprecated and will likely be removed in a future release
Java HotSpot(TM) 64-Bit Server VM warning: UseCMSCompactAtFullCollection is deprecated and will likely be removed in a future release.
The Name Server boot success. serializeType=JSON, address 0.0.0.0:9876

執(zhí)行jps命令也能看到相應(yīng)進(jìn)程：

$ jps
13730 NamesrvStartup

執(zhí)行如下命令啟動(dòng)Broker + Proxy：

$ sh bin/mqbroker -n localhost:9876 --enable-proxy

該命令執(zhí)行非常漫長，差不多要90s左右才會(huì)輸出如下日志：

Sat Feb 24 19:48:03 CST 2024 rocketmq-proxy startup successfully

在~/logs/rocketmqlogs/proxy.log日志中也能看到broker啟動(dòng)成功的日志：

2024-02-24 19:47:53 INFO main - The broker[broker-a, 192.168.88.135:10911] boot success. serializeType=JSON and name server is localhost:9876

注意：日志中的broker-a是在broker.conf文件中配置的brokerName參數(shù)，如下所示：

brokerClusterName = DefaultCluster
brokerName = broker-a # 配置的默認(rèn)brokerName參數(shù)
brokerId = 0
deleteWhen = 04
fileReservedTime = 48
brokerRole = ASYNC_MASTER
flushDiskType = ASYNC_FLUSH

再次執(zhí)行jps命令確認(rèn)相應(yīng)進(jìn)程是否已經(jīng)啟動(dòng)：

$ jps
jps
13730 NamesrvStartup
14410 ProxyStartup

一切似乎看起來都正常，從~/logs/rocketmqlogs/namesrv.log和~/logs/rocketmqlogs/proxy.log日志中也看不出明顯的異常。

但是在創(chuàng)建Topic時(shí)就會(huì)報(bào)錯(cuò)：

$ sh bin/mqadmin updatetopic -n localhost:9876 -t TestTopic -c DefaultCluster

該命令在執(zhí)行大約40s左右就會(huì)輸出如下報(bào)錯(cuò)日志：

org.apache.rocketmq.tools.command.SubCommandException: UpdateTopicSubCommand command failed
        at org.apache.rocketmq.tools.command.topic.UpdateTopicSubCommand.execute(UpdateTopicSubCommand.java:198)
        at org.apache.rocketmq.tools.command.MQAdminStartup.main0(MQAdminStartup.java:164)
        at org.apache.rocketmq.tools.command.MQAdminStartup.main(MQAdminStartup.java:114)
Caused by: org.apache.rocketmq.remoting.exception.RemotingTimeoutException: invokeSync call the addr[127.0.0.1:9876] timeout
        at org.apache.rocketmq.remoting.netty.NettyRemotingClient.invokeSync(NettyRemotingClient.java:549)
        at org.apache.rocketmq.client.impl.MQClientAPIImpl.getBrokerClusterInfo(MQClientAPIImpl.java:1961)
        at org.apache.rocketmq.tools.admin.DefaultMQAdminExtImpl.examineBrokerClusterInfo(DefaultMQAdminExtImpl.java:577)
        at org.apache.rocketmq.tools.admin.DefaultMQAdminExt.examineBrokerClusterInfo(DefaultMQAdminExt.java:318)
        at org.apache.rocketmq.tools.command.CommandUtil.fetchMasterAddrByClusterName(CommandUtil.java:94)
        at org.apache.rocketmq.tools.command.topic.UpdateTopicSubCommand.execute(UpdateTopicSubCommand.java:171)
        ... 2 more

從報(bào)錯(cuò)信息看似乎是無法連接127.0.0.1:9876，但是經(jīng)過驗(yàn)證發(fā)現(xiàn)該地址是一定可以連通的，再幾經(jīng)嘗試之后依然報(bào)錯(cuò)。

于是換了一臺(tái)Windows機(jī)器繼續(xù)驗(yàn)證，奇怪的是在Windows機(jī)器上一切正常，而且我注意到在Windows環(huán)境啟動(dòng)RocketMQ的時(shí)候brokerName使用是主機(jī)名，如下日志：

# zhangsan是主機(jī)名
The broker[zhangsan, 20.5.133.188:10911] boot success. serializeType=JSON and name server is localhost:9876

于是腦袋中突然閃現(xiàn)一個(gè)疑問，是不是因?yàn)闆]有在CentOS的/etc/hosts文件中映射主機(jī)名與127.0.0.1地址導(dǎo)致的。

驗(yàn)證后果然就正常的。

原因追蹤

根據(jù)相關(guān)報(bào)錯(cuò)日志梳理RocketMQ的源代碼，報(bào)錯(cuò)是因?yàn)樵贜ettyRemotingClient.invokeSync()方法中做了超時(shí)判斷。

@Override
public RemotingCommand invokeSync(String addr, final RemotingCommand request, long timeoutMillis)
    throws InterruptedException, RemotingConnectException, RemotingSendRequestException, RemotingTimeoutException {
    long beginStartTime = System.currentTimeMillis();
    final Channel channel = this.getAndCreateChannel(addr);
    String channelRemoteAddr = RemotingHelper.parseChannelRemoteAddr(channel);
    if (channel != null && channel.isActive()) {
        long left = timeoutMillis; // 默認(rèn)超時(shí)時(shí)長是5000ms
        try {
            long costTime = System.currentTimeMillis() - beginStartTime;
            left -= costTime;
            if (left <= 0) { // 當(dāng)執(zhí)行時(shí)長超過5s時(shí)直接拋出異常
                throw new RemotingTimeoutException("invokeSync call the addr[" + channelRemoteAddr + "] timeout");
            }
            RemotingCommand response = this.invokeSyncImpl(channel, request, left);
            updateChannelLastResponseTime(addr);
            return response;
        }
        //其他代碼省略...
    }
    //其他代碼省略...
}

由于是做了超時(shí)檢查拋出的異常，所以單純從日志信息看就會(huì)認(rèn)為是無法連接127.0.0.1:9876，實(shí)際上該地址是可以連通的。

進(jìn)一步追蹤發(fā)現(xiàn)，是在執(zhí)行Netty的ReflectiveChannelFactory.newChannel()方法耗時(shí)較長，約10s左右。

@Override
public T newChannel() {
    try {
        // constructor是NioSocketChannel.class
        // 所以本質(zhì)上這里是要通過反射的方式實(shí)例化一個(gè)NioSocketChannel對象
        T t = constructor.newInstance();
        return t;
    } catch (Throwable t) {
        throw new ChannelException("Unable to create Channel from class " + constructor.getDeclaringClass(), t);
    }
}

驗(yàn)證代碼如下：

long start = System.currentTimeMillis();
Constructor constructor = NioSocketChannel.class.getConstructor();
constructor.newInstance();
System.out.println(String.format("%s ms", System.currentTimeMillis() - start));

執(zhí)行后輸出日志：

10144 ms

奇怪的是，當(dāng)在/etc/hosts文件中明確指定主機(jī)名與127.0.0.1的映射關(guān)系后，執(zhí)行就非常快。

暫時(shí)還不清楚這個(gè)地方的深層次原因是什么，為什么通過反射方式實(shí)例化NioSocketChannel對象會(huì)跟主機(jī)名與127.0.0.1的映射有關(guān)系呢？

【參考資料】
Windows 啟動(dòng)RocketMQ

到此這篇關(guān)于本地啟動(dòng)RocketMQ未映射主機(jī)名產(chǎn)生的超時(shí)問題的文章就介紹到這了,更多相關(guān)RocketMQ未映射主機(jī)名超時(shí)內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

最新評論