Grok pattern(s) working in debugger but not used in logstash?

Hello,

I try to get Sophos Firewall logs into logstash (which is working) but my grok filter to get the logline separated into fields is not working. The test via grok debugger is working...

Here are my logstash conf files:
Input (/etc/logstash/conf.d/02-sophos.conf):

input {
  beats {
     port => 5044
  }
}

Filter (/etc/logstash/conf.d/03-sophos.conf):

filter {
 grok {
 break_on_match => true
 match => ["message",'(%{MONTHNUM}):(?:%{MONTHDAY})-(?:%{HOUR}):(?:%{MINUTE}):(?:%{SECOND}) (?:%{SYSLOGHOST}) (?:%{SYSLOGPROG}): id=\"%{INT:utm_id}\" .* sub=\"%{DATA:utm_sub}\"']
 match => ["message",'(%{MONTHNUM}):(?:%{MONTHDAY})-(?:%{HOUR}):(?:%{MINUTE}):(?:%{SECOND}) (?:%{SYSLOGHOST}) (?:%{SYSLOGPROG}): id=\"%{INT:utm_id}\"']
 match => ["message",'(%{MONTHNUM}):(?:%{MONTHDAY})-(?:%{HOUR}):(?:%{MINUTE}):(?:%{SECOND}) (?:%{SYSLOGHOST}) (?:%{SYSLOGPROG}): \[%{DATA:utm_security2}:.*\]']
        overwrite => ["MONTHNUM", "MONTHDAY", "HOUR", "MINUTE", "SECOND", "SYSLOGHOST", "SYSLOGPROG", "id"]
        tag_on_failure => []
     }

if [program] == "ulogd" {
  if [utm_sub] == "packetfilter" {
    grok {
       match => ["message", '.* sys=\"%{DATA:utm_sys}\" sub=\"%{DATA}\" name=\"%{DATA:utm_name}\" action=\"%{DATA:utm_action}\" fwrule=\"%{INT:utm_fwrule}\" ?(initf=\"%{DATA:utm_initf}\")? ?(outitf=\"%{DATA:utm_outif}\")? ?(srcmac=\"%{MAC:utm_srcmac}\")? ?(dstmac=\"%{MAC:utm_dstmac}\")? srcip=\"%{IP:utm_srcip}\" dstip=\"%{IP:utm_dstip}\" proto=\"%{INT:utm_protocol}\" length=\"%{INT:utm_ulogd_pkglength}\" tos=\"%{DATA:utm_ulogd_tos}\" prec=\"%{DATA:utm_ulogd_prec}\" ttl=\"%{INT:utm_ttl}\" srcport=\"%{INT:utm_srcport}\" dstport=\"%{INT:utm_dstport}\" ?(tcpflags=\"%{DATA:utm_tcpflags}\")? ?(info=\"%{DATA:utm_info}\")?']
    }
  }

 }
}

Output (/etc/logstash/conf.d/99-output.conf):

output {
  elasticsearch {
    hosts => ["http://localhost:9200"]
  }
}

The pipeline gets loaded and there is no error in syslog for logstash:

Jun 1 10:47:29 MYHOST logstash[7904]: [2021-06-01T10:47:29,294][INFO ][logstash.javapipeline ][main] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>4, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>500, "pipeline.sources"=>["/etc/logstash/conf.d/02-sophos.conf", "/etc/logstash/conf.d/03-sophos.conf", "/etc/logstash/conf.d/99-output.conf"], :thread=>"#<Thread:0x5f92f38f run>"}
Jun 1 11:00:24 MYHOSTis logstash[9416]: [2021-06-01T11:00:24,946][INFO ][logstash.javapipeline ][main] Pipeline Java execution initialization time {"seconds"=>0.76}
Jun 1 11:00:24 MYHOSTis logstash[9416]: [2021-06-01T11:00:24,965][INFO ][logstash.inputs.beats ][main] Starting input listener {:address=>"0.0.0.0:5044"}
Jun 1 11:00:24 MYHOSTis logstash[9416]: [2021-06-01T11:00:24,978][INFO ][logstash.javapipeline ][main] Pipeline started {"pipeline.id"=>"main"}
Jun 1 11:00:25 MYHOSTis logstash[9416]: [2021-06-01T11:00:25,056][INFO ][logstash.agent ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>}
Jun 1 11:00:25 MYHOSTis logstash[9416]: [2021-06-01T11:00:25,064][INFO ][org.logstash.beats.Server][main][50bff7b0728f6691dc1728677b53f476bf52dd2357237c2832559249e7b4872b] Starting server on port: 5044

(MYHOSTis my anonymized elk stack hostname)

How can I debug this?

Regards
3lastic

Hi,

Because you are using single quotes you don't have to escape double quotes in the grok pattern.

So you have to replace single quotes with double quotes or remove all backslash.

Cad.

Ok, I removed all backslashes but same as before...
Do I need to reload the indices in any way?

I changed the logstash configs and restarted logstash. Sorry I'm quite new :slight_smile:

Can you add stdout { } in the output.
And tell me what is print.

Cad.

Here it is:

Jun  1 12:37:50 MYELKHOST logstash[9288]: {
Jun  1 12:37:50 MYELKHOST logstash[9288]:            "ecs" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "version" => "1.9.0"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:            "rsa" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "internal" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:             "messageid" => ""MYFIREWALLNAME  ulogd"
Jun  1 12:37:50 MYELKHOST logstash[9288]:         }
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:        "service" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "type" => "sophos"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:       "@version" => "1",
Jun  1 12:37:50 MYELKHOST logstash[9288]:          "input" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "type" => "udp"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:     "@timestamp" => 2021-06-01T10:37:26.296Z,
Jun  1 12:37:50 MYELKHOST logstash[9288]:          "event" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:             "code" => "MYFIREWALLNAME ulogd",
Jun  1 12:37:50 MYELKHOST logstash[9288]:          "dataset" => "sophos.utm",
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "original" => "<30>2021:06:01-12:37:26 MYFIREWALLNAME ulogd[13461]: id=\"2014\" severity=\"info\" sys=\"SecureNet\" sub=\"packetfilter\" name=\"DNS request\" action=\"DNS request\" fwrule=\"60011\" initf=\"lag0.10\" srcmac=\"SRCMAC\" dstmac=\"DSTMAC\" srcip=\"SRCIP\" dstip=\"DSTIP\" proto=\"17\" length=\"120\" tos=\"0x00\" prec=\"0x00\" ttl=\"128\" srcport=\"51392\" dstport=\"53\" \n",
Jun  1 12:37:50 MYELKHOST logstash[9288]:           "module" => "sophos"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:            "log" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "source" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:             "address" => "MYFIREWALLIP:32221"
Jun  1 12:37:50 MYELKHOST logstash[9288]:         },
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "syslog" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:             "priority" => 30,
Jun  1 12:37:50 MYELKHOST logstash[9288]:             "severity" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:                 "code" => 6
Jun  1 12:37:50 MYELKHOST logstash[9288]:             },
Jun  1 12:37:50 MYELKHOST logstash[9288]:             "facility" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:                 "code" => 3
Jun  1 12:37:50 MYELKHOST logstash[9288]:             }
Jun  1 12:37:50 MYELKHOST logstash[9288]:         }
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:          "agent" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:                   "id" => "211e6732-7b43-4c09-b664-803015ea67c6",
Jun  1 12:37:50 MYELKHOST logstash[9288]:                 "name" => "MYHOSTNAME",
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "ephemeral_id" => "6c46ca93-46e7-4ca3-9464-54aae60e7ade",
Jun  1 12:37:50 MYELKHOST logstash[9288]:                 "type" => "filebeat",
Jun  1 12:37:50 MYELKHOST logstash[9288]:             "hostname" => "MYHOSTNAME",
Jun  1 12:37:50 MYELKHOST logstash[9288]:              "version" => "7.13.0"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:           "tags" => [
Jun  1 12:37:50 MYELKHOST logstash[9288]:         [0] "sophos.utm",
Jun  1 12:37:50 MYELKHOST logstash[9288]:         [1] "forwarded",
Jun  1 12:37:50 MYELKHOST logstash[9288]:         [2] "beats_input_raw_event"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     ],
Jun  1 12:37:50 MYELKHOST logstash[9288]:        "fileset" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "name" => "utm"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:        "process" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "pid" => 13461
Jun  1 12:37:50 MYELKHOST logstash[9288]:     },
Jun  1 12:37:50 MYELKHOST logstash[9288]:       "observer" => {
Jun  1 12:37:50 MYELKHOST logstash[9288]:            "type" => "Firewall",
Jun  1 12:37:50 MYELKHOST logstash[9288]:         "product" => "UTM",
Jun  1 12:37:50 MYELKHOST logstash[9288]:          "vendor" => "Sophos"
Jun  1 12:37:50 MYELKHOST logstash[9288]:     }
Jun  1 12:37:50 MYELKHOST logstash[9288]: }

The uppercase words are anonymized data.

It seems that the values you want to retrieve are not stored in the message field but in the original field.

I can't see a message field. Should there be one?

EDIT
Ok, tried to access the original field. But looks like I can't use this field...

Do I need to configure the message field in filebeat?

Hi

In your first message you match the grok pattern with the message field.
The message field is like a default field. It's where most input plugins place the payload that they receive from the network, read from a file, ...

After having reread your first message, i realized that the syntax for the match is not correct. It shoul be something like this:

filter {
  grok {
    match=>{
      "original" => [
        'pattern1',
        'pattern2',
        'pattern3'
      ]
    }
  }
}

So now it looks exactly like this:

filter {
   grok {
     break_on_match => true
     match => {
                "original" => [
                 '(%{MONTHNUM}):(?:%{MONTHDAY})-(?:%{HOUR}):(?:%{MINUTE}):(?:%{SECOND}) (?:%{SYSLOGHOST}) (?:%{SYSLOGPROG}): id="%{INT:utm_id}" .* sub="%{DATA:utm_sub}"',
                 '(%{MONTHNUM}):(?:%{MONTHDAY})-(?:%{HOUR}):(?:%{MINUTE}):(?:%{SECOND}) (?:%{SYSLOGHOST}) (?:%{SYSLOGPROG}): id="%{INT:utm_id}"',
                 '(%{MONTHNUM}):(?:%{MONTHDAY})-(?:%{HOUR}):(?:%{MINUTE}):(?:%{SECOND}) (?:%{SYSLOGHOST}) (?:%{SYSLOGPROG}): \[%{DATA:utm_security2}:.*\]'
                ]
              }
   }
}

But it isn't working :frowning:
No change...

Ok, so lets try this :

First, go in the logstash installation directory which normally is /usr/share/logstash.
In this directory run sudo bin/logstash --config.test_and_exit -f <path_to_config_file> if it doesn't return Configuration OK then the syntax of the config file is not valid.

If it is ok, edit stdout to stdout { codec => rubydebug }. Open another terminal print sudo tail -f /var/log/logstash/logstash.log. And restart logstash in the first terminal.
What is print ?

Cad.

Syntax looks good:

Config Validation Result: OK. Exiting Logstash

This is the output:

Jun  2 13:36:33 MYELKHOST logstash[176279]: {
Jun  2 13:36:33 MYELKHOST logstash[176279]:          "input" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "type" => "udp"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:        "fileset" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "name" => "utm"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:            "log" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "syslog" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:             "severity" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:                 "code" => 6
Jun  2 13:36:33 MYELKHOST logstash[176279]:             },
Jun  2 13:36:33 MYELKHOST logstash[176279]:             "facility" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:                 "code" => 3
Jun  2 13:36:33 MYELKHOST logstash[176279]:             },
Jun  2 13:36:33 MYELKHOST logstash[176279]:             "priority" => 30
Jun  2 13:36:33 MYELKHOST logstash[176279]:         },
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "source" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:             "address" => "MYFIREWALLIP:32221"
Jun  2 13:36:33 MYELKHOST logstash[176279]:         }
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:          "agent" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:                 "name" => "MYELKHOST",
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "ephemeral_id" => "6c46ca93-46e7-4ca3-9464-54aae60e7ade",
Jun  2 13:36:33 MYELKHOST logstash[176279]:             "hostname" => "MYELKHOST",
Jun  2 13:36:33 MYELKHOST logstash[176279]:                 "type" => "filebeat",
Jun  2 13:36:33 MYELKHOST logstash[176279]:              "version" => "7.13.0",
Jun  2 13:36:33 MYELKHOST logstash[176279]:                   "id" => "211e6732-7b43-4c09-b664-803015ea67c6"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:       "@version" => "1",
Jun  2 13:36:33 MYELKHOST logstash[176279]:       "observer" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:            "type" => "Firewall",
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "product" => "UTM",
Jun  2 13:36:33 MYELKHOST logstash[176279]:          "vendor" => "Sophos"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:          "event" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:             "code" => "MYFIREWALLHOSTNAME ulogd",
Jun  2 13:36:33 MYELKHOST logstash[176279]:          "dataset" => "sophos.utm",
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "original" => "<30>2021:06:02-13:25:19 MYFIREWALLHOSTNAME ulogd[12023]: id=\"2002\" severity=\"info\" sys=\"SecureNet\" sub=\"packetfilter\" name=\"Packet accepted\" action=\"accept\" fwrule=\"210\" initf=\"eth2\" outitf=\"lag0.10\" srcmac=\"SRCMAC\" dstmac=\"DSTMAC\" srcip=\"SRCIP\" dstip=\"DSTIP\" proto=\"6\" length=\"60\" tos=\"0x00\" prec=\"0x00\" ttl=\"63\" srcport=\"44946\" dstport=\"443\" tcpflags=\"SYN\" \n",
Jun  2 13:36:33 MYELKHOST logstash[176279]:           "module" => "sophos"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:        "process" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "pid" => 12023
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:        "service" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "type" => "sophos"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:           "tags" => [
Jun  2 13:36:33 MYELKHOST logstash[176279]:         [0] "sophos.utm",
Jun  2 13:36:33 MYELKHOST logstash[176279]:         [1] "forwarded",
Jun  2 13:36:33 MYELKHOST logstash[176279]:         [2] "beats_input_raw_event",
Jun  2 13:36:33 MYELKHOST logstash[176279]:         [3] "_grokparsefailure"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     ],
Jun  2 13:36:33 MYELKHOST logstash[176279]:            "ecs" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "version" => "1.9.0"
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:            "rsa" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:         "internal" => {
Jun  2 13:36:33 MYELKHOST logstash[176279]:             "messageid" => "MYFIREWALLHOSTNAME ulogd"
Jun  2 13:36:33 MYELKHOST logstash[176279]:         }
Jun  2 13:36:33 MYELKHOST logstash[176279]:     },
Jun  2 13:36:33 MYELKHOST logstash[176279]:     "@timestamp" => 2021-06-02T11:25:19.348Z
Jun  2 13:36:33 MYELKHOST logstash[176279]: }

So this line show us that now, unlike yesterday, the grok is executed but it result to a failure.
On this page https://www.elastic.co/fr/blog/do-you-grok-grok you can find a method to debug a grokparsefailure.

Cad.

My Grok filter also fails with the simplest filter... I really don't know how to debug this.

Example:

filter {
  grok {
    match => { "original" => "123" }
  }
}

You do not have an [original] field, you have [event][original]

1 Like

Thats it. Works.

Thanks both of you @Badger and @Cad :slight_smile:

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