Kafka java.net.SocketTimeoutException

手上有一个消费Kafka的服务，这个服务每隔一段时间使用SimpleConsumer从kafka集群获取数据。Kafka的版本是0.8.21。今天这个服务一直在报错：SocketTimeoutException。异常信息如下：

2018-12-22 15:18:32 INFO  SimpleConsumer:68 - Reconnect due to socket error: java.net.SocketTimeoutException
2018-12-22 15:19:32 INFO  SimpleConsumer:68 - Reconnect due to socket error: java.net.SocketTimeoutException
java.net.SocketTimeoutException
	at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211)
	at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103)
	at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385)
	at kafka.utils.Utils$.read(Utils.scala:380)
	at kafka.network.BoundedByteBufferReceive.readFrom(BoundedByteBufferReceive.scala:54)
	at kafka.network.Receive$class.readCompletely(Transmission.scala:56)
	at kafka.network.BoundedByteBufferReceive.readCompletely(BoundedByteBufferReceive.scala:29)
	at kafka.network.BlockingChannel.receive(BlockingChannel.scala:111)
	at kafka.consumer.SimpleConsumer.liftedTree1$1(SimpleConsumer.scala:79)
	at kafka.consumer.SimpleConsumer.kafka$consumer$SimpleConsumer$$sendRequest(SimpleConsumer.scala:68)
	at kafka.consumer.SimpleConsumer.getOffsetsBefore(SimpleConsumer.scala:127)

从异常信息上来看是网络连接超时。翻看了一下任务的运行日志发现是在连接Kafka集群的k3节点时出的错。

尝试telnet连接k3节点的broker是可以的。这样子还报错就比较奇怪了。

使用glances查看了一下消费节点的本地运行环境，发现各项指标也都挺正常的。

登录到k3节点，查看kafka的运行日志也能够看到消费节点的连接记录：

[2018-12-21 21:00:47,531] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor)
[2018-12-21 21:00:50,189] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor)
[2018-12-21 21:00:58,296] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor)
[2018-12-21 21:00:59,007] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor)
[2018-12-21 21:01:00,782] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor)

查看了一下使用high-level consumer的其他服务也是正常的。

百思不得其解。但是问题还得解决，随手查看了一下k3节点的句柄数，发现一个进程的句柄数高得有点儿离谱哎：

[zhyea@k3]$ lsof|awk '{print $2}'|sort|uniq -c|sort -nr|more
 
 2776803 53466
     280 15671
     256 35292
     224 13903
     176 14305
     172 21177
      64 15692
      44 12061
      32 21191
      24 2648
      24 21135
      20 12073
      18 190059
      16 14453
      16 13872
      14 188621

k3节点每个进程可以打开的最大句柄数：

[zhyea@k3]$ cat /proc/sys/fs/file-max
3265156
[zhyea@k3]$ ulimit -n
3265156

53466就是k3节点上的kafka broker进程：

[zhyea@k3]$ jps -l 
53466 kafka.Kafka
190100 sun.tools.jps.Jps

此时有必要看下这个进程的网络连接了：

netstat -apn | grep 53466

发现有大量的CLOSE_WAIT和TIME_WAIT连接：

tcp        1      0 k3:9092      j0:51436       CLOSE_WAIT  53466/java
tcp        1      0 k3:9092      j0:51436       CLOSE_WAIT  53466/java
tcp        1      0 k3:9092      j0:51436       CLOSE_WAIT  53466/java
tcp        1      0 k3:9092      j0:51436       CLOSE_WAIT  53466/java
tcp        1      0 k3:9092      j0:51436       CLOSE_WAIT  53466/java

统计了下CLOSE_WAIT和TIME_WAIT连接的数量，好像有点儿多：

[zhyea@k3]$ netstat -apn | wc -l
12399
[zhyea@k3]$ netstat -apn | grep CLOSE_WAIT | wc -l 
8562
[zhyea@k3]$ netstat -apn | grep CLOSE_WAIT | grep j0 | wc -l 
8554
[zhyea@k3]$ netstat -apn | grep TIME_WAIT | wc -l 
1022

可以看出来所有连接中CLOSE_WAIT的记录占了绝大部分，和CLOSE_WAIT相关的连接又多是在j0节点上。

到j0节点查找和端口51436相关的进程，发现是一个kafka-manager服务。不是生产服务，直接关掉了事。

回到k3节点，重启该节点的broker。再进行测试，异常消失。持续观察几天，kafka的连接数是正常的，说明问题已经得到修复。

##########