Kafka brokers throwing packet length IOExceptions

[lenin-joseph]

Hi,

We use Strimzi 0.31.1 (Kafka 3.2.3) where we have been seeing packet length IOexceptions in brokers w.r.to the zookeeper connection in one of the clusters and it seems that there are frequent updates in the znodes (related to /config/changes).

We see a PR(#1787) for a similar issue, but that was not merged. So could you take a look and advise if there is any configuration change required to address this issue?

Unexpected throwable java.io.IOException: Packet len 4636860 is out of range!|\tat org.apache.zookeeper.ClientCnxnSocket.readLength(ClientCnxnSocket.java:121)|\tat org.apache.zookeeper.ClientCnxnSocketNetty$ZKClientHandler.channelRead0(ClientCnxnSocketNetty.java:500)|\tat org.apache.zookeeper.ClientCnxnSocketNetty$ZKClientHandler.channelRead0(ClientCnxnSocketNetty.java:463)|\tat io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)|\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)|\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)|\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)|\tat io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1373)|\tat io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1236)|\tat io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1285)|\tat io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:510)|\tat io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:449)|\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279)|\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)|\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)|\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)|\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)|\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)|\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)|\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)|\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)|\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)|\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)|\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)|\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)|\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)|\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)|\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)|\tat java.base/java.lang.Thread.run(Thread.java:829)",

Output from ZKCli:

Welcome to ZooKeeper!
JLine support is disabled

WATCHER::

WatchedEvent state:SyncConnected type:None path:null
ls /config
[brokers, changes, clients, ips, topics, users]
ls /config/changes
[config_change_0000000130, config_change_0000000131, config_change_0000000132]

[scholzj]

You should probably start by sharing the full configuration and log. Sharing just an exception does not help anyone because we have no idea where do you actually get it.

[scholzj]

Hmm, sorry, no idea what it means. The log around it does not seem to say much. The Kafka custom resource seems to contain many fields that are not valid. But no idea if it is related in any way.

[lenin-joseph]

Hi @scholzj , here are the steps that we used to reproduce the issue.

1. Two Kafka clusters(ClusterA and ClusterB) are enabled with Bi-directional replication using Mirrormaker2. The data is being replicated for two topics.
2. The sync.topic.configs.interval.seconds in the source-connector of MM2 is set to 60 seconds.
3. We tainted nodes to move Kafka and ZK pods of ClusterA to the pending state(To mimic cluster down scenario)
4. Brought up ClusterA KF and ZK pods after 60 min.

Observations:
The moment we brought the ClusterA back up, the znodes in ClusterB suddenly increased by 180 ( 60 min * 3 (two external topics + one internal(heartbeats) topic)

When we tried a similar exercise with 100 topics and by bringing down ClusterA for 24 hrs, the moment we bought up ClusterA, there was a sudden flooding of znodes in ClusterB, and that caused packet length errors in Kafka pods of ClusterB.

Question:
Seeing the above behavior, even if we set sync.topic.configs.interval.seconds to 10 min(default), we will mostly end up in the same situation if the source Cluster is down for a longer time. Is there a way to avoid this?

[lenin-joseph]

This is for the 60-minute downtime scenario.

Znodes in clusterB (when ClusterA is down)

zookeeper-shell.sh localhost:12181 ls /config/changes
[config_change_0000000557, config_change_0000000558, config_change_0000000559, config_change_0000000560, config_change_0000000561, config_change_0000000562, config_change_0000000563, config_change_0000000564, config_change_0000000565, config_change_0000000566, config_change_0000000567, config_change_0000000568, config_change_0000000569, config_change_0000000570, config_change_0000000571, config_change_0000000572, config_change_0000000573, config_change_0000000574, config_change_0000000575, config_change_0000000576, config_change_0000000577, config_change_0000000578, config_change_0000000579, config_change_0000000580, config_change_0000000581, config_change_0000000582, config_change_0000000583]

Znodes in clusterB (as soon as ClusterA is brought back up)

zookeeper-shell.sh localhost:12181 ls /config/changes
[config_change_0000000584, config_change_0000000585, config_change_0000000586, config_change_0000000587, config_change_0000000588, config_change_0000000589, config_change_0000000590, config_change_0000000591, config_change_0000000592, config_change_0000000593, config_change_0000000594, config_change_0000000595, config_change_0000000596, config_change_0000000597, config_change_0000000598, config_change_0000000599, config_change_0000000600, config_change_0000000601, config_change_0000000602, config_change_0000000603, config_change_0000000604, config_change_0000000605, config_change_0000000606, config_change_0000000607, config_change_0000000608, config_change_0000000609, config_change_0000000610, config_change_0000000611, config_change_0000000612, config_change_0000000613, config_change_0000000614, config_change_0000000615, config_change_0000000616, config_change_0000000617, config_change_0000000618, config_change_0000000619, config_change_0000000620, config_change_0000000621, config_change_0000000622, config_change_0000000623, config_change_0000000624, config_change_0000000625, config_change_0000000626, config_change_0000000627, config_change_0000000628, config_change_0000000629, config_change_0000000630, config_change_0000000631, config_change_0000000632, config_change_0000000633, config_change_0000000634, config_change_0000000635, config_change_0000000636, config_change_0000000637, config_change_0000000638, config_change_0000000639, config_change_0000000640, config_change_0000000641, config_change_0000000642, config_change_0000000643, config_change_0000000644, config_change_0000000645, config_change_0000000646, config_change_0000000647, config_change_0000000648, config_change_0000000649, config_change_0000000650, config_change_0000000651, config_change_0000000652, config_change_0000000653, config_change_0000000654, config_change_0000000655, config_change_0000000656, config_change_0000000657, config_change_0000000658, config_change_0000000659, config_change_0000000660, config_change_0000000661, config_change_0000000662, config_change_0000000663, config_change_0000000664, config_change_0000000665, config_change_0000000666, config_change_0000000667, config_change_0000000668, config_change_0000000669, config_change_0000000670, config_change_0000000671, config_change_0000000672, config_change_0000000673, config_change_0000000674, config_change_0000000675, config_change_0000000676, config_change_0000000677, config_change_0000000678, config_change_0000000679, config_change_0000000680, config_change_0000000681, config_change_0000000682, config_change_0000000683, config_change_0000000684, config_change_0000000685, config_change_0000000686, config_change_0000000687, config_change_0000000688, config_change_0000000689, config_change_0000000690, config_change_0000000691, config_change_0000000692, config_change_0000000693, config_change_0000000694, config_change_0000000695, config_change_0000000696, config_change_0000000697, config_change_0000000698, config_change_0000000699, config_change_0000000700, config_change_0000000701, config_change_0000000702, config_change_0000000703, config_change_0000000704, config_change_0000000705, config_change_0000000706, config_change_0000000707, config_change_0000000708, config_change_0000000709, config_change_0000000710, config_change_0000000711, config_change_0000000712, config_change_0000000713, config_change_0000000714, config_change_0000000715, config_change_0000000716, config_change_0000000717, config_change_0000000718, config_change_0000000719, config_change_0000000720, config_change_0000000721, config_change_0000000722, config_change_0000000723, config_change_0000000724, config_change_0000000725, config_change_0000000726, config_change_0000000727, config_change_0000000728, config_change_0000000729, config_change_0000000730, config_change_0000000731, config_change_0000000732, config_change_0000000733, config_change_0000000734, config_change_0000000735, config_change_0000000736, config_change_0000000737, config_change_0000000738, config_change_0000000739, config_change_0000000740, config_change_0000000741, config_change_0000000742, config_change_0000000743, config_change_0000000744, config_change_0000000745, config_change_0000000746, config_change_0000000747, config_change_0000000748, config_change_0000000749, config_change_0000000750, config_change_0000000751, config_change_0000000752, config_change_0000000753, config_change_0000000754, config_change_0000000755, config_change_0000000756, config_change_0000000757, config_change_0000000758, config_change_0000000759, config_change_0000000760, config_change_0000000761, config_change_0000000762, config_change_0000000763]

[lenin-joseph]

We repeated the exercise, but this time, we restarted the MM2 pod(ClusterB is the connect-cluster) before bringing up ClusterA, and only three znodes were created. so it seems that MM2 keeps adding tasks to the thread while there are delays in processing or when the source Cluster is not reachable and subsequently it floods the Kafka Cluster with requests to create znodes.

WATCHER::

WatchedEvent state:SyncConnected type:None path:null
[config_change_0000000860, config_change_0000000861, config_change_0000000862]

[scholzj]

Mirror Maker does not use ZooKeeper directly in any way. So this has to happen through Kafka. But I'm not aware of anyone else raising this, so this has to be caused by something what is happening in our environment I guess? You should maybe check what things change while the MM2 is down. But as I said, I never saw this before and do not really know what it means ... so it is mostly just guessing. Sorry.