UDP netflow packets arrive, netflow does not process them

I have two servers, getting logs from the same sources, parallel streams of netflow and syslog.

64Gb RAM, 8 cores, 500Gb SSD VMs running on ESXI 6.7.

I build the servers using Ansible and Cobbler so they are "identical".
I run diffs against their configs, ELK and Red Hat, identical

I have logstash listening on four ports, 2x netflow and 2x syslog

I can do tcpdumps and I see the incoming UDP messages
I check IPTABLES and the ports are allowed

One server 1 I can see all FOUR of logs being processed into elastic
One server 2 I can see only ONE logs being processed into elastic

Of the logs I am missing, I dont even see the logstash debug telling me that netflow has not recieved a template yet.
So I am guessing that the UDP messages are not getting to the input filter, or the input filter is not processing them

So pick one of the missing logs and strip my config down to just one, cisco netflow ....

input {
# Netflow from Cisco routers for BGAN only
udp {
port => 2100
type => "cisco"
add_field => { "[@metadata][fingerprint]" => "" }
add_field => { "IsFlow" => "True" }
add_field => { "subtype" => "netflow" }
codec => netflow {
versions => [1, 5, 9, 10]
}
}
}
filter {
}
output {

For debug only, CAREFUL LOG DIRECTORY DOES NOT FILL UP

if [type] == "cisco" {
  file {
    path => "/var/log/logstash/message-%{type}-%{+YYYY.MM.dd}.log" 
    codec => rubydebug
  }

}
}

Starts ok ...

[2019-03-05T22:54:05,929][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}
[2019-03-05T23:03:04,276][WARN ][logstash.runner ] SIGTERM received. Shutting down.
[2019-03-05T23:03:05,683][INFO ][logstash.pipeline ] Pipeline has terminated {:pipeline_id=>"main", :thread=>"#<Thread:0x55d0a32a run>"}
[2019-03-05T23:03:51,160][INFO ][logstash.runner ] Starting Logstash {"logstash.version"=>"6.5.3"}
[2019-03-05T23:03:57,458][INFO ][logstash.pipeline ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2019-03-05T23:03:57,567][INFO ][logstash.pipeline ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x1e0ff11f run>"}
[2019-03-05T23:03:57,605][INFO ][logstash.inputs.udp ] Starting UDP listener {:address=>"0.0.0.0:2100"}
[2019-03-05T23:03:57,640][INFO ][logstash.agent ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>}
[2019-03-05T23:03:57,681][INFO ][logstash.inputs.udp ] UDP listener started {:address=>"0.0.0.0:2100", :receive_buffer_bytes=>"106496", :queue_size=>"2000"}
[2019-03-05T23:03:57,866][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}

Port there

$ netstat -lnp | grep 2100
udp 0 0 0.0.0.0:2100 0.0.0.0:* 614/java

Firewall open

$ iptables -nL | grep 2100
ACCEPT udp -- 0.0.0.0/0 0.0.0.0/0 udp dpts:2100:2103 ctstate NEW

Packets arriving

$ tcpdump -l -c 1 -nn -i eth0 -X udp port 2100 | head -7
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
23:02:12.333000 IP A.B.C.D.62979 > W.X.Y.Z.2100: UDP, length 1349
0x0000: 4500 0561 6e35 0000 fe11 1c59 0a6e 0f0b E..an5.....Y.n..
0x0010: 0a6e 0917 f603 0834 054d 5571 0009 0019 .n.....4.MUq....
0x0020: a34c 7c7c 5c7e fff4 0065 41ad 0000 0000 .L||~...eA.....
0x0030: 0108 0531 bcac c68f 0a1c 7c1c 0000 0000 ...1......|.....
0x0040: 0000 0014 1732 1776 0006 001d 1800 0000 .....2.v........
0x0050: 000a 6e47 0300 0000 4000 0000 01a3 4c3d ..nG....@.....L=

lets look for the log file ....

$ ls -l
total 108
-rw-r--r-- 1 logstash logstash 110002 Mar 5 23:03 logstash-plain.log
-rw-r--r-- 1 logstash logstash 0 Mar 5 13:28 logstash-slowlog-plain.log

Not there !

CPU and MEMORY ok

top - 23:11:53 up 8 min, 3 users, load average: 0.14, 0.15, 0.12
Tasks: 176 total, 2 running, 174 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.2 us, 0.1 sy, 0.6 ni, 99.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 65810316 total, 56674440 free, 7719880 used, 1415996 buff/cache
KiB Swap: 8388604 total, 8388604 free, 0 used. 57856488 avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
601 logstash 39 19 9389564 1.078g 16476 S 5.6 1.7 2:01.07 java
1320 elastic+ 20 0 13.894g 5.595g 30328 S 1.3 8.9 0:53.01 java

disk ok

$ df
Filesystem 1K-blocks Used Available Use% Mounted on
/dev/sda3 1022282036 8744476 1013537560 1% /
devtmpfs 32895740 0 32895740 0% /dev
tmpfs 32905156 0 32905156 0% /dev/shm
tmpfs 32905156 8740 32896416 1% /run
tmpfs 32905156 0 32905156 0% /sys/fs/cgroup
/dev/sda7 10475520 1027972 9447548 10% /var/log
/dev/sda5 10475520 32928 10442592 1% /home
/dev/sda6 10475520 33072 10442448 1% /tmp
/dev/sda8 10475520 35044 10440476 1% /var/log/audit
/dev/sda2 520876 121080 399796 24% /boot
/dev/sda10 96050 0 96050 0% /boot/efi
tmpfs 6581032 0 6581032 0% /run/user/0

I would try --log.level trace, which I think will get you a

[DEBUG][logstash.pipeline        ] filter received [...]

message if the udp filter sends anything into the pipeline. I do not see any debug logging in the udp filter that is likely to help (a couple of messages at startup, nothing per event).

Startup "looks" normal, no logs though ...


[2019-03-06T00:05:44,367][DEBUG][logstash.agent           ] Executing action {:action=>LogStash::PipelineAction::Create/pipeline_id:main}
[2019-03-06T00:05:46,396][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"netflow", :type=>"codec", :class=>LogStash::Codecs::Netflow}
[2019-03-06T00:05:46,528][DEBUG][logstash.codecs.netflow  ] config LogStash::Codecs::Netflow/@versions = [1, 5, 9, 10]
[2019-03-06T00:05:46,529][DEBUG][logstash.codecs.netflow  ] config LogStash::Codecs::Netflow/@id = "f497e7b2-684a-4f46-bcb6-2f56600e1924"
[2019-03-06T00:05:46,529][DEBUG][logstash.codecs.netflow  ] config LogStash::Codecs::Netflow/@enable_metric = true
[2019-03-06T00:05:46,529][DEBUG][logstash.codecs.netflow  ] config LogStash::Codecs::Netflow/@cache_ttl = 4000
[2019-03-06T00:05:46,530][DEBUG][logstash.codecs.netflow  ] config LogStash::Codecs::Netflow/@target = "netflow"
[2019-03-06T00:05:46,530][DEBUG][logstash.codecs.netflow  ] config LogStash::Codecs::Netflow/@include_flowset_id = false
[2019-03-06T00:05:47,749][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"udp", :type=>"input", :class=>LogStash::Inputs::Udp}
[2019-03-06T00:05:47,772][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@add_field = {"[@metadata][fingerprint]"=>"", "IsFlow"=>"True", "subtype"=>"netflow"}
[2019-03-06T00:05:47,782][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@codec = <LogStash::Codecs::Netflow versions=>[1, 5, 9, 10], id=>"f497e7b2-684a-4f46-bcb6-2f56600e1924", enable_metric=>true, cache_ttl=>4000, target=>"netflow", inclu
de_flowset_id=>false>
[2019-03-06T00:05:47,782][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@id = "94c0d3aa1be3df40fbe2208198c8e0129f72ad5a1be8e1df71b0b16a35ea8b89"
[2019-03-06T00:05:47,782][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@type = "cisco"
[2019-03-06T00:05:47,782][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@port = 2100
[2019-03-06T00:05:47,782][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@enable_metric = true
[2019-03-06T00:05:47,783][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@host = "0.0.0.0"
[2019-03-06T00:05:47,783][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@buffer_size = 65536
[2019-03-06T00:05:47,783][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@workers = 2
[2019-03-06T00:05:47,783][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@queue_size = 2000
[2019-03-06T00:05:47,783][DEBUG][logstash.inputs.udp      ] config LogStash::Inputs::Udp/@source_ip_fieldname = "host"
[2019-03-06T00:05:47,793][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"file", :type=>"output", :class=>LogStash::Outputs::File}
[2019-03-06T00:05:47,807][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"rubydebug", :type=>"codec", :class=>LogStash::Codecs::RubyDebug}
[2019-03-06T00:05:47,817][DEBUG][logstash.codecs.rubydebug] config LogStash::Codecs::RubyDebug/@id = "rubydebug_45594861-6010-4efd-b35c-b1e25aae7dbe"
[2019-03-06T00:05:47,817][DEBUG][logstash.codecs.rubydebug] config LogStash::Codecs::RubyDebug/@enable_metric = true
[2019-03-06T00:05:47,817][DEBUG][logstash.codecs.rubydebug] config LogStash::Codecs::RubyDebug/@metadata = false
[2019-03-06T00:05:49,613][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2019-03-06T00:05:49,614][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2019-03-06T00:05:49,700][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@path = "/var/log/logstash/message-%{type}-%{+YYYY.MM.dd}.log"
[2019-03-06T00:05:49,702][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@codec = <LogStash::Codecs::RubyDebug id=>"rubydebug_45594861-6010-4efd-b35c-b1e25aae7dbe", enable_metric=>true, metadata=>false>
[2019-03-06T00:05:49,703][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@id = "1d04e9d0618b5d7398e6a2cdc40fdb336bda9686fa5d83d3e360e5709dd76849"
[2019-03-06T00:05:49,703][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@enable_metric = true
[2019-03-06T00:05:49,704][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@workers = 1
[2019-03-06T00:05:49,704][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@flush_interval = 2
[2019-03-06T00:05:49,705][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@gzip = false
[2019-03-06T00:05:49,705][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@filename_failure = "_filepath_failures"
[2019-03-06T00:05:49,705][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@create_if_deleted = true
[2019-03-06T00:05:49,706][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@dir_mode = -1
[2019-03-06T00:05:49,706][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@file_mode = -1
[2019-03-06T00:05:49,707][DEBUG][logstash.outputs.file    ] config LogStash::Outputs::File/@write_behavior = "append"
[2019-03-06T00:05:49,841][INFO ][logstash.pipeline        ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2019-03-06T00:05:50,076][INFO ][logstash.pipeline        ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x6f4018ce run>"}
[2019-03-06T00:05:50,105][DEBUG][logstash.inputs.udp      ] Starting UDP worker thread {:worker=>1}
[2019-03-06T00:05:50,109][DEBUG][logstash.inputs.udp      ] Starting UDP worker thread {:worker=>2}
[2019-03-06T00:05:50,120][TRACE][logstash.agent           ] Converge results {:success=>true, :failed_actions=>[], :successful_actions=>["id: main, action_type: LogStash::PipelineAction::Create"]}
[2019-03-06T00:05:50,126][INFO ][logstash.inputs.udp      ] Starting UDP listener {:address=>"0.0.0.0:2100"}
[2019-03-06T00:05:50,173][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}

Try explicitly binding to an IP address using the host option, do not use the default 0.0.0.0.

1 Like

Firstly, I really appreciate your support in this.

I'll have a go at the binding change. But also I have discovered some problems at network level ...

Mar 6 12:00:53 elka kernel: ll header: 00000000: 00 50 56 26 47 00 00 09 0f 09 00 00 08 00 .PV&G.........
Mar 6 12:00:53 elka kernel: IPv4: martian source X.X.X.X from Y.Y.Y.Y, on dev eth0

This has to be a network problem somwhere in the stack ...

john

GOT IT !

logstash UDP messages were arriving on eth0 from sources which had routes via eth1.

The syslog/netflows are unidirectional connection-less, so no need to route anything back to the sources.

Linux did not like packets arriving on eth0 when it thought they should arrive on eth1.

So although you can see the packets in tcpdump, the Linux network stack was ignoring them.

Once I added routes to the sources via eth0, everything kicked into life !

@Badger thanks for giving me the nudge along to solve this.

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.