pulsar阻塞导致logstash无法接入日志

# 背景

在logstash中，input管道接收tcp和udp的日志，然后再通过output管道将日志输出到pulsar中，如下图所示：

当前的问题是，在使用tcp和udp接入方式接入一段时间日志之后，日志突然无法接入了，在pulsar中的对应topic没有新的日志生产进来了。

# 检查网络情况

在容器中抓包，判断数据包是否进入到容器中

因为服务都是容器化部署的，所以可以使用nsenter -t $Pid -n来进入到容器的network namespace中，然后再使用tcpdump -i any port 514 -vvnn来抓取514端口的数据包。

通过抓包是可以抓到数据包，并且看三次握手和数据包都是正常的，说明流量已经进入到容器中了。

查看tcp和udp缓存队列

使用netstat -anp查看tcp和upd缓存队列，发现Recv-Q是一直有堆积的，也就是说，服务端没有在从缓存队列中消费日志，服务端卡住了。

# netstat -anp
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name  
tcp   286138      0 14.2.19.144:514         10.65.132.32:46778      ESTABLISHED 538152/java   
udp   152543      0 14.2.19.144:514         10.65.132.32:46774      ESTABLISHED 538152/java

1
2
3
4
5

# 检查logstash管道信息

进入到容器中执行以下命令来获取logstash对应管道的信息

curl -XGET 'localhost:9600/_node/stats/pipelines/syslog?pretty'

可以看到input管道中tcp插件的out的数量一直保持不变，说明已经没有接收新的数据包了。

{
    "id": "d1a2689850bcefed823d25f0ae0ee7b863f3843474c6eafd3d3fe5aa7babcded",
    "name": "tcp",
    "events": {
        "queue_push_duration_in_millis": 3728,
        "out": 6680
    }
}

1
2
3
4
5
6
7
8

再看output管道的pulsar插件信息，可以看到in比out多了150，这是因为pipeline.batch.size=50，并且pipeline.workers=3，所以一共有150条日志阻塞在队列中，pulsar-client法发送出去，阻塞了。

{
    "id": "4acf48fc134b333ecb24218723c8fd36d54dc3713cbe66bd199ce4ccb09f2cd1",
    "name": "pulsar",
    "events": {
        "duration_in_millis": 9923,
        "in": 6529,
        "out": 6379
    }
}

1
2
3
4
5
6
7
8
9

通过查看pulsar服务的状态和日志发现其并没有任何异常，手动去生产日志也是可以的，所以暂时排除了pulsar本身的问题。

# 从堆栈中找到蛛丝马迹

通过以下命令来查看logstash的线程堆栈信息

# curl -XGET 'localhost:9600/_node/hot_threads?pretty'

"java.base@11.0.15/jdk.internal.misc.Unsafe.park(Native Method)", "java.base@11.0.15/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)", "java.base@11.0.15/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)", "org.apache.pulsar.client.impl.MemoryLimitController.reserveMemory(MemoryLimitController.java:88)", ...

1
2
3

通过上面的堆栈信息去google上搜索，找到了下面这个链接，发现是pulsar的官方bug，在开启压缩时，并且内存限制的越小，越容易触发该BUG，从而导致pulsar-client发生阻塞。

https://lists.apache.org/thread/76jn7k01ldgkl54n0bpgw3sf2kxqq5q9

# 复现

这里用的是开源的pulsar插件：logstash-output-pulsar (opens new window)

其并没有内存限制配置参数，通过修改源码将pulsar-client的memory_limit参数暴露出来，并将其设置成1，开启压缩，持续构造日志进来，会发现稳定快速复现该问题。

# 修复

查看logstash-output-pulsar项目下的build.gradle文件，其pulsar版本为2.10.2，而在https://github.com/apache/pulsar/pull/21790 提交可以看到在3.2.0版本修复的。

修改项目中pulsar-client版本号，打包出来，再按照上面的复现步骤，发现不会再进行阻塞了。

# 总结

善于利用组件提供的各种工具得到其指标，分析原因，找到蛛丝马迹，再利用google去搜索。

#logstash #计算机网络 #pular

上次更新: 2025/02/09, 23:47:02