Pfelk: OPNsense filterlog not parsed - logstash exception

[collse]

Describe the bug
I have just installed pfelk manually onto an existing SELKS and the filterlog ingestion seems to throw an exception.

To Reproduce
Steps to reproduce the behavior:

1. install manually as advised
2. see logstash-plain.log for errors

Screenshots
-

Firewall System (please complete the following information):

• OPNsense
• OPNsense 20.7.7_1-amd64

Operating System (please complete the following information):

• OS (printf "$(uname -srm)\n$(cat /etc/os-release)\n"):
• Debian GNU/Linux 10 (buster)

Installation method (manual, ansible-playbook, docker, script):
manual

Elasticsearch, Logstash, Kibana (please complete the following information):

• Version of ELK components (dpkg -l [elasticsearch]|[logstash]|[kibana])
  ii elasticsearch 7.10.1 amd64 Distributed RESTful search engine built for the cloud
  ii logstash 1:7.10.1-1 amd64 An extensible logging pipeline
  ii kibana 7.10.1 amd64 Explore and visualize your Elasticsearch data

Elasticsearch, Logstash, Kibana logs:

• Logstash logs (tail -f /var/log/logstash/logstash-plain.log)
  [2021-01-06T11:58:42,314][WARN ][logstash.outputs.elasticsearch][main][aebab63d6c807b755605817f64b565a5acf79922d782116bb4493612778292d5] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-2021.01.06", :routing=>nil, :_type=>"_doc"}, #<LogStash::Event:0xe040c53>], :response=>{"index"=>{"_index"=>"logstash-2021.01.06", "_type"=>"_doc", "_id"=>"90eQ13YBZ6VBe8q4OpWF", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse field [host] of type [text] in document with id '90eQ13YBZ6VBe8q4OpWF'. Preview of field's value: '{name=server.domain.org}'", "caused_by"=>{"type"=>"illegal_state_exception", "reason"=>"Can't get text on a START_OBJECT at 1:9"}}}}}

example logformat as received:
<134>Jan 6 12:10:17 server.domain.org filterlog[58514]: 77,,,0,pppoe0,match,pass,out,4,0x0,,63,19696,0,DF,1,icmp,84,62.208.39.18,8.8.8.8,datalength=64

Additional context
I assume this is a parsing error, however I am not sure what is causing this

unbound logs as an example parse just fine

[a3ilson]

@collse - Thanks for providing sufficient details to decipher this particular issue!

Based on the provided details, it appears that a log (firewall log) is not parsing due to the existence of the host field.

Explanation of the log process specific to the host field:

• The host field is automatically created during the input of any log (created during the 01-inputs.conf stage)
• The 02-filter.conf at line 11 renames the host to observer.ip
  
  
  
  • The host field is not supported in ECS as it is an object
  
  
  • The pfelk-mappings.ecs template utilizing ECS v2.0.0-Dev which identify host as an object not natively capable of storing values
  
  
  • We could amend the template but to align with ECS chose to rename to the most appropriate ECS field
  
  

Required Follow-up

• Please confirm step 12 was accomplished and the existence of 02-filter.conf is present on your system
  
  
  
  • Based on the error, it appears this file may be missing resulting in the host field being present and causing the error
  
  

[collse]

thanks for the speedy response - I think this confirms being the case - I did fetch all the files probably 6hrs ago

wget https://raw.githubusercontent.com/pfelk/pfelk/master/etc/logstash/conf.d/02-types.conf -P /data

comparing the current file on repo to on disk

diff /data/02-types.conf /etc/logstash/conf.d/02-types.conf
9c9
< add_field => [ "[observer][product]", "Supermicro" ]
vs > add_field => [ "[observer][product]", "VMware" ]

so only my changes differ.

checking the rename

cat -n /etc/logstash/conf.d/02-types.conf | grep host
11 rename => { "host" => "[observer][ip]" }
22 rename => { "host" => "[observer][ip]" }
33 remove_field => [ "host" ]
44 rename => { "host" => "[observer][ip]" }

the rename is indeed present

let me know what else to check.

here is a tcpdump on lo port 9200 grep'ing for filterlog:

{"host":{"name":"server.domain.org"},"ecs":{"version":"1.7.0"},"@version":"1","network":{"type":"ipv4","direction":"inbound","iana_number":"6","transport":"tcp"},"pf":{"transport":{"data_length":"0"},"tcp":{"window":"65228","options":["mss","nop","wscale","sackOK","TS\n"],"sequence_number":"2808978161","flags":"S"},"packet":{"length":"60"},"ipv4":{"tos":"0x0","packet":{"id":"0"},"ttl":"64","offset":"0","flags":"DF"}},"source":{"ip":"127.0.0.1","port":"7842"},"rule":{"ruleset":"72","description":"Link-Local: 72","alias":"72","uuid":"0"},"tags":["pf","IP_Private_Source","IP_Private_Destination"],"interface":{"name":"lo0","alias":"Link-Local"},"observer":{"name":"OPNsense","type":"firewall","serial_number":"001","ip":"192.168.1.1","product":"VMware"},"process":{"name":"filterlog","pid":"8309"},"log":{"syslog":{"priority":"134"}},"destination":{"service":"wap-wsp","ip":"127.0.0.1","port":"9200"},"event":{"original":"<134>Jan 6 17:06:34 server.domain.org filterlog[8309]: 72,,,0,lo0,match,pass,in,4,0x0,,64,0,0,DF,6,tcp,60,127.0.0.1,127.0.0.1,7842,9200,0,S,2808978161,,65228,,mss;nop;wscale;sackOK;TS\n","created":"2021-01-06T17:06:34.000Z","action":"pass","reason":"match"},"@timestamp":"2021-01-06T17:06:34.174Z"}

seems like the rename is not happening ...

[a3ilson]

That's boggling as to why the host field is not being renamed/amended.

Let's give this a try:
-Amend 45-outputs.conf as follows:

# 45-cleanup.conf
# Update as needed to remove unwanted logs based on the process.pid field
filter {
#  if [process][pid] in ["78", "46", "45", "43"] {
#   drop { }
#  }
  mutate {
    remove_field => ["pfelk_message"]
    remove_field => ["filter_message"]
    remove_field => ["type"]
    split => { "[pf][tcp][options]" => ";" }
    rename => { "message" => "[event][original]" }
    remove_field => [ "host" ]
  }
}

This is the final conf file before being sent to elasticsearch and should remove the field, host

[a3ilson]

thanks for the speedy response - I think this confirms being the case - I did fetch all the files probably 6hrs ago

wget https://raw.githubusercontent.com/pfelk/pfelk/master/etc/logstash/conf.d/02-types.conf -P /data

comparing the current file on repo to on disk

diff /data/02-types.conf /etc/logstash/conf.d/02-types.conf
9c9
< add_field => [ "[observer][product]", "Supermicro" ]
vs > add_field => [ "[observer][product]", "VMware" ]

so only my changes differ.

checking the rename

cat -n /etc/logstash/conf.d/02-types.conf | grep host
11 rename => { "host" => "[observer][ip]" }
22 rename => { "host" => "[observer][ip]" }
33 remove_field => [ "host" ]
44 rename => { "host" => "[observer][ip]" }

the rename is indeed present

let me know what else to check.

here is a tcpdump on lo port 9200 grep'ing for filterlog:

{"host":{"name":"server.domain.org"},"ecs":{"version":"1.7.0"},"@Version":"1","network":{"type":"ipv4","direction":"inbound","iana_number":"6","transport":"tcp"},"pf":{"transport":{"data_length":"0"},"tcp":{"window":"65228","options":["mss","nop","wscale","sackOK","TS\n"],"sequence_number":"2808978161","flags":"S"},"packet":{"length":"60"},"ipv4":{"tos":"0x0","packet":{"id":"0"},"ttl":"64","offset":"0","flags":"DF"}},"source":{"ip":"127.0.0.1","port":"7842"},"rule":{"ruleset":"72","description":"Link-Local: 72","alias":"72","uuid":"0"},"tags":["pf","IP_Private_Source","IP_Private_Destination"],"interface":{"name":"lo0","alias":"Link-Local"},"observer":{"name":"OPNsense","type":"firewall","serial_number":"001","ip":"192.168.1.1","product":"VMware"},"process":{"name":"filterlog","pid":"8309"},"log":{"syslog":{"priority":"134"}},"destination":{"service":"wap-wsp","ip":"127.0.0.1","port":"9200"},"event":{"original":"<134>Jan 6 17:06:34 server.domain.org filterlog[8309]: 72,,,0,lo0,match,pass,in,4,0x0,,64,0,0,DF,6,tcp,60,127.0.0.1,127.0.0.1,7842,9200,0,S,2808978161,,65228,,mss;nop;wscale;sackOK;TS\n","created":"2021-01-06T17:06:34.000Z","action":"pass","reason":"match"},"@timestamp":"2021-01-06T17:06:34.174Z"}

seems like the rename is not happening ...

That's even more interesting...rename does appear to be applied as the amended field is host.name = server.domain.org

[a3ilson]

When did you start sending pf/opnsense logs? before or after installing the templates/dashboards?

I would try this next:

• Stop logstash (systemctl stop logstash.service)
• Delete all saved indices (Data>>Index Management>>Indices)
• Delete all saved objects (Kibana>>Saved Objects & Kibana>>Index Patterns)
• Reload all saved objects
• Start logstash (systemctl start logstash.service)

[collse]

ok, so I didnt add any changes to 45-outputs.conf, stopped and purged as advised (which is actually pretty painful if you have quite some content in there), then re-added everything as previously

it was throwing errors initially

[2021-01-06T19:53:11,751][WARN ][logstash.outputs.elasticsearch][main][0c9001f35928d8e6dfc34c6237ed2b8f61b454fe7b2e3ab583d4cf1d0271c49d] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"pfelk-firewall-2021.01", :routing=>nil, :_type=>"_doc"}, #], :response=>{"index"=>{"_index"=>"pfelk-firewall-2021.01", "_type"=>"_doc", "_id"=>"14hC2XYBZ6VBe8q4ns5l", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"object mapping for [host] tried to parse field [host] as object, but found a concrete value"}}}}

but after a while it stopped and seems to work now as expected - which is odd.

To answer your question, I only started to ingest after everything was completed - as I obviously still needed to set the log target rules after I had modified the SELKS install ...

well, working now - much appreciated, but I wonder why it initially didnt work ... puzzled

[a3ilson]

Glad it's working and I was baffled too... I amended the 45-cleanup.conf file to remove occur aces of the host field and hopefully prevent future occurrences.

[a3ilson]

Issue resolved