想必不少人都遇到过这种场景,明明昨天环境还好好的,今天怎么就不行了呢?关键是这种情况,有时候连重启大法都不管用了,顿时陷入了毫无头绪的茫然中。。。
好了,聊回话题本身,因为升级程序,会自动重启zookeeper和kafka。程序升级成功之后,zookeeper服务正常,kafka服务未正常启动。查看其日志,显示连接zookeeper超时,然后自动退出程序。因为对kafka service设置了服务失败时自动重启,所以,kafka就一直在那无限重启。以下是kafka启动失败以及自动重启的日志:
[2024-08-15 12:15:46,799] ERROR Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
kafka.zookeeper.ZooKeeperClientTimeoutException: Timed out waiting for connection while in state: CONNECTING
at kafka.zookeeper.ZooKeeperClient.waitUntilConnected(ZooKeeperClient.scala:254)
at kafka.zookeeper.ZooKeeperClient.<init>(ZooKeeperClient.scala:108)
at kafka.zk.KafkaZkClient$.apply(KafkaZkClient.scala:1980)
at kafka.server.KafkaServer.initZkClient(KafkaServer.scala:500)
at kafka.server.KafkaServer.startup(KafkaServer.scala:203)
at kafka.Kafka$.main(Kafka.scala:109)
at kafka.Kafka.main(Kafka.scala)
[2024-08-15 12:15:46,800] INFO shutting down (kafka.server.KafkaServer)
[2024-08-15 12:15:46,805] INFO App info kafka.server for 0 unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-08-15 12:15:46,806] INFO shut down completed (kafka.server.KafkaServer)
[2024-08-15 12:15:46,806] ERROR Exiting Kafka. (kafka.Kafka$)
[2024-08-15 12:15:46,808] INFO shutting down (kafka.server.KafkaServer)
[2024-08-15 12:15:48,120] INFO Registered kafka:type=kafka.Log4jController MBean (kafka.utils.Log4jControllerRegistration$)
[2024-08-15 12:15:48,480] INFO Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation (org.apache.zookeeper.common.X509Util)
[2024-08-15 12:15:48,592] INFO Registered signal handlers for TERM, INT, HUP (org.apache.kafka.common.utils.LoggingSignalHandler)
[2024-08-15 12:15:48,596] INFO starting (kafka.server.KafkaServer)
说明一下,当前的zookeeper和kafka的连接是使用了SASL机制。最开始怀疑是不是SASL的配置升级时被破坏了,导致问题发生。于是,从其他正常的环境将zookeeper和kafka的相关配置文件都复制过来,再重启,看下是否正常。很不幸,不是配置的问题。
继续翻看日志的时候,发现了这行日志:
[2024-08-15 12:15:46,679] INFO Session establishment complete on server 10.10.10.1/10.10.10.1:2181, session id = 0x10071c4a84a000b, negotiated timeout = 18000 (org.apache.zookeeper.ClientCnxn)
协商时间是18000毫秒,也就是18s,既然你报连接超时,那我就把这个时间配置大一点,再看看你报什么错。找到kafka的配置文件server.properties,然后修改这个参数:
# Timeout in ms for connecting to zookeeper
# zookeeper.connection.timeout.ms=18000
zookeeper.connection.timeout.ms=60000
我直接将默认的18s给改到60s,然后重启kafka。神奇的事情发生了。。。kafka连上zookeeper了,不再报超时的错误了。
虽然连上了,但是这个并正常啊,zookeeper和kafka都是本机运行的,他们之间通信哪里需要那么长的时间啊,默认的18s都足够长了,一定是系统哪里设置的不对,影响到了kafka与zookeeper的网络连接。
这时候,想起之前也遇到过类似的情况,当时好像还通过打断点的方式跟踪了代码的执行情况。详细的过程就不讲了,只说一下,当时怀疑是/etc/resolv.conf配置文件,里面配置了谷歌的域名解析服务器地址。如下:
search localdomain
nameserver 8.8.8.8
nameserver 8.8.4.4
由于机房并未通外网,所以,当前主机ping这两个域名服务器的地址是ping不通的。既然ping不通,那就不要使用它了,而且,我们的程序都是使用的ip地址,不是域名,也用不到域名服务器进行解析。我选择屏蔽这两个地址,如下:
search localdomain
#nameserver 8.8.8.8
#nameserver 8.8.4.4
修改完了之后,为了保证生效,我是直接reboot的操作系统,最开始是systemctl restart network来重启的网卡,但好像没生效。系统重启好了之后,再将kafka的service.properties配置改为默认的18s:
# Timeout in ms for connecting to zookeeper
zookeeper.connection.timeout.ms=18000
# zookeeper.connection.timeout.ms=60000
然后重启kafka,看下日志,是否还会提示连接超时。理论上,kafka应该恢复了正常。
回头想想,因为/etc/resolv.conf导致类似的问题,在我身上发生了不止一次,这次也是定位了半天,才想到可能是它导致的。公共环境,大家都在用,也不知道是谁,什么时候加上去的,只能说,太坑了。。。
而且,我想不明白的是,记得当时断点跟踪代码时,使用的ip连接网络的时候,底层还是要会找域名服务器解析一下?这已经超过我的业务能力了,搞不懂。。。