Logstash UDP Input Data Lost

Posted on | Edited on | In

Regarding Logstash introduction recaps, please have a look at Elastic Stack Quick Start

Issue description: Over the past few months, we have been seeing some logs that were indeed generated, but they lost in Elasticsearch database, which result in false PD alert as the alert expression relies on these missing logs.

The data path is common and typical:

1
2
3
4
5
Data source 
=> Logstash(UDP input + filter + Kafka output)
=> Kafka 
=> Logstash(Kafka input + filter + Elasticsearch output) 
=> Elasticsearch(Kibana)

The lost could happen in transit at any point, let’s check and narrow the scope down.

At very beginning, I just suspected the data lost on Kafka without any proof and adjusted the ack level on Logstash Kafka output plugin, it turns out not the case.

Does The UDP Packet Reach VM?

As UDP transfer is not reliable, the packets could be lost before they reached Logstash VM, we can have background tcpdump to sniff the UDP packets from target host and port to verify, for example:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
# time limit the process run
# -k/--kill-after: send kill after 5s if TERM signal does not work
# 12h: duration, run tcpdump 12 hours
timeout -k 5 12h \
# -i: interface
# -nn: don't convert protocol and port numbers to name
# -w: write to pcap file
# -U: with -w, write packet to file immediately
# -C: rollover file size limit: 200MB
tcpdump -i eth0 \
# filter capturing with src IP started from 172.16 and port 514 only
-nn src 172.16 and port 514 \
-wU /home/example/logstash-0.pcap \
-C 200 \
&> /dev/null &

It is important to limit the pcap file size and roll over new file if necessary, for example, the pcap file generated from above command will be:

1
2
3
4
5
# suffix number starts from 1, auto appended.
/home/example/logstash-0.pcap
/home/example/logstash-0.pcap1
/home/example/logstash-0.pcap2
/home/example/logstash-0.pcap3

Each will have file size <= 200MB as -C specified.

Then you can use Wireshark or tcpdump itself to read/filter the pcap file:

1
2
3
4
5
6
7
8
# -r: read pcap file
# -v: show verbose packet info
tcpdump -r /home/example/logstash-0.pcap2 \
# filter expression
src 172.16.53.4 and port 514 \
-nn \
-v  \
| grep "target info"

Then we know the UDP packets actually reached the VM, move to the next question.

Other tcpdump Usages

If you want to have file creation in a strict time interval manner:

1
2
3
4
5
6
# -G: rotated every 1800s duration
# must use strftime filename, otherwise new file will overwrite the previous
tcpdump -i eth0 -G 1800 -w /tmp/trace-%Y-%m-%d-%H:%M:%S.pcap
# -W: limit the file number to 3, and exit 0
# so it will only create 3 files and each 30 mins
tcpdump -i eth0 -W 3 -G 1800 -w /tmp/trace-%Y-%m-%d-%H:%M:%S.pcap

We can have -C(size) and -G(time) together, but need the timestamp file name! For example:

1
tcpdump -i eth0 -w /tmp/trace-%Y-%m-%d-%H:%M:%S.pcap -G 3 -C 2

The file creation is either every 3s or 2MB, whichever comes first, look the size rollover is within each time interval:

1
2
3
4
5
6
7
8
9
-rw-r--r--. 1 tcpdump              2.0M May  2 06:30 trace-2022-05-02-06:30:20.pcap
-rw-r--r--. 1 tcpdump              2.0M May  2 06:30 trace-2022-05-02-06:30:20.pcap1
-rw-r--r--. 1 tcpdump             1003K May  2 06:30 trace-2022-05-02-06:30:20.pcap2
-rw-r--r--. 1 tcpdump              2.0M May  2 06:30 trace-2022-05-02-06:30:23.pcap
-rw-r--r--. 1 tcpdump              2.0M May  2 06:30 trace-2022-05-02-06:30:23.pcap1
-rw-r--r--. 1 tcpdump              1.1M May  2 06:30 trace-2022-05-02-06:30:23.pcap2
-rw-r--r--. 1 tcpdump              1.5M May  2 06:30 trace-2022-05-02-06:30:26.pcap
-rw-r--r--. 1 tcpdump              1.7M May  2 06:30 trace-2022-05-02-06:30:29.pcap
-rw-r--r--. 1 tcpdump              301K May  2 06:30 trace-2022-05-02-06:30:32.pcap

You can rotate the file by size and limit the number of file created,

1
2
3
# -W: file count limit 3
# -C: rollover file size limit: 2MB
tcpdump -i eth0 -w /tmp/trace.pcap -W 3 -C 2

The result could be:

1
2
3
4
# rotated among these 3 files
-rw-r--r--. 1 tcpdump             tcpdump             2.0M May  2 06:55 trace.pcap1
-rw-r--r--. 1 tcpdump             tcpdump             2.0M May  2 06:55 trace.pcap2
-rw-r--r--. 1 tcpdump             tcpdump             1.5M May  2 06:55 trace.pcap0

or by time and size both, note that rotation happens only within the timeslice: every 3s when the size exceeds!

1
2
# must use timestamp file name
tcpdump -i eth0 -w /tmp/trace-%Y-%m-%d-%H:%M:%S.pcap -W 5 -C 2 -G 3

Does Logstash UDP Input Drop Packet?

This can be verified by adding another output plugin file to store target info to a local file, for example in logstash config file:

1
2
3
4
5
6
7
8
9
10
11
12
input {}
filter {}

output {
    kafka {}
    if "target info" in [message] {
      file {
        # 'sourceip' is a field from record
        path => "/var/log/logstash/highlight/%{sourceip}.log"
      }
    }
}

By checking the log file, I know the output does not send the message out, plus the filter is good, so it must be input {} UDP dropped the data.

Why Does UDP Drop Packet?

UDP is not a reliable transport. By design, it will drop messages if it does not have space to buffer them.

There is a blog talks about the UDP packer error and UDP receive buffer error, see from netstat -us, they are the first-hand indicator for packet drop.

How to Solve It?

Luckly, we can increase the queue size and buffer size, for example:

1
2
3
4
5
6
7
8
9
input {
  udp {
    port => 514
    type => syslog
    queue_size => 100000 # default is 2000
    receive_buffer_bytes => 16777216 # 16 MB, default uses system sysctl value
    workers => 4 # depends on the vcpu number, default is 2
  }
}

The value really depends on your traffc, you can run sar -n DEV 1 to find a reasonable estimation. Moreover, you need to uplift system socket receive buffer in order to set Logstash receive_buffer_bytes correctly if it is larger than system default buffer, for example:

1
2
echo "net.core.rmem_max=16777216" >> /etc/sysctl.conf
sysctl -p

Finally, increase the Logstash JVM heap size accordingly, usually half of the RAM size for both Xms and Xmx.

Then restart and check the status of new config:

1
2
3
systemctl restart logstash
# verbose to see the config change
systemctl status logstash -l

Horizontal Scaling

If the traffic is heavy, vertical scaling on cpu core or RAM is not enough and the packet drop continues. It turns out the Logtash does not scale will the increasing CPU cores, see this comment.

So in this case you have to do horizontal scaling.

Monitoring/Alert

It is helpful to have Grafana dashboard to display drop rate as to inbound traffic, for example:

1
2
3
4
5
label_replace(rate(node_netstat_Udp_InErrors{instance=~".*-example-.*"}[5m])
/ on(instance)
rate(node_network_receive_packets_total{device="eth0", instance=~".*-example-.*"}[5m])
, "new_name", "$1", "instance", "prefix-(.+)") 
* 100

There is the list of metrics exposed by node exporter.

Postscript

There are other things I practiced:

  1. Logstash config and syntax for input, filter, output plugin.
  2. Using nc as UDP client to test Logstash UDP input and filter.
  3. Revisit Kafka config and know possible data loss in Kafka side.
  4. Revisit PromQL

最后把系统优化中的网络部分又看了一遍加深印象:D

0%