Logstash two different log types

Elastic Stack Logstash
1

Hello there

I've been experimenting with logstash but ran into a problem when trying to parse haproxy logs.
The issue is as follows, I've been able to implement a grok parser function for the most common logs but sometimes a different type of line appears in the log which can't be parsed:

GROK function:
match => ["message", "%{SYSLOGTIMESTAMP:timestamp} %{IPORHOST} %{PROG}(?:[%{POSINT}])?: %{IPORHOST:source}:%{POSINT:port} | {%{DATA:tenant}|%{DATA:userAgent}} | %{NOTSPACE:frontend} %{NOTSPACE:backend}/%{NOTSPACE:server} %{INT:timeClientRequest}/%{INT:timeQueue}/%{INT:timeTCP}/%{INT:timeServer}/%{INT:timeTotal} %{INT:statusCode} %{INT:bytes} %{INT:connectionsProcess}/%{INT:concurrentConnectionsFrontend}/%{INT:concurrentConnectionsBackend}/%{INT:concurrentConnectionsServer}/%{INT:retries} %{INT:connectionsServer}/%{INT:connectionsBackend} "%{DATA:verb} %{DATA:request}""]

Types of lines:
Mar 21 03:25:02 localhost haproxy[14415]: 188.93.156.49:50499 | {header1|Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; Trident/6.0)} | main~ server_2.2/appServer02 1/0/0/1/2 302 165 3/3/0/1/0 0/0 "GET /server-2.2 HTTP/1.1"

Mar 22 01:27:39 localhost haproxy[14415]: Server updates/appServer02 is UP, reason: Layer7 check passed, code: 200, info: "OK", check duration: 3ms. 2 active and 0 backup servers online. 0 sessions requeued, 0 total in queue.

Mar 22 00:16:13 localhost haproxy[14415]: 64.41.200.105:60240 [22/Mar/2018:00:16:13.574] main/1: SSL handshake failure

Now my question is the following:

  • Is there a possibility to detect if the log is the normal format (see logline 1) and if not to just apply GREEDYDATA to it.

Thank you

2

Sure you can. However you have to get the first pattern spot on correct because the second pattern will match all so you will not see a _grokparsefailure tag.
Make sure you anchor the start with ^ and escape the pipe and square brackets | and [].

input {
  generator {
    lines => [
      'Mar 21 03:25:02 localhost haproxy[14415]: 188.93.156.49:50499 | {header1|Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; Trident/6.0)} | main~ server_2.2/appServer02 1/0/0/1/2 302 165 3/3/0/1/0 0/0 "GET /server-2.2 HTTP/1.1"',
      'Mar 22 01:27:39 localhost haproxy[14415]: Server updates/appServer02 is UP, reason: Layer7 check passed, code: 200, info: "OK", check duration: 3ms. 2 active and 0 backup servers online. 0 sessions requeued, 0 total in queue.',
      'Mar 22 00:16:13 localhost haproxy[14415]: 64.41.200.105:60240 [22/Mar/2018:00:16:13.574] main/1: SSL handshake failure'
    ]
    count => 1
  }
}

filter {
  grok {
    match => {
      "message" => [
        '^%{SYSLOGTIMESTAMP:timestamp} %{IPORHOST} %{PROG}(?:\[%{POSINT}\])?: %{IPORHOST:source}:%{POSINT:port} \| {%{DATA:tenant}\|%{DATA:userAgent}} \| %{NOTSPACE:frontend} %{NOTSPACE:backend}/%{NOTSPACE:server} %{INT:timeClientRequest}/%{INT:timeQueue}/%{INT:timeTCP}/%{INT:timeServer}/%{INT:timeTotal} %{INT:statusCode} %{INT:bytes} %{INT:connectionsProcess}/%{INT:concurrentConnectionsFrontend}/%{INT:concurrentConnectionsBackend}/%{INT:concurrentConnectionsServer}/%{INT:retries} %{INT:connectionsServer}/%{INT:connectionsBackend} "%{DATA:verb} %{DATA:request}"',
        '^%{SYSLOGTIMESTAMP:timestamp} %{IPORHOST} %{PROG}(?:\[%{POSINT}\])?: %{GREEDYDATA:unexpected_message}'
      ]
    }
    break_on_match => true
  }
}

output {
  stdout {
    codec => rubydebug
  }
}

Gives:

{
              "message" => "Mar 22 00:16:13 localhost haproxy[14415]: 64.41.200.105:60240 [22/Mar/2018:00:16:13.574] main/1: SSL handshake failure",
             "sequence" => 0,
            "timestamp" => "Mar 22 00:16:13",
           "@timestamp" => 2018-04-30T11:30:25.906Z,
                 "host" => "Elastics-MacBook-Pro.local",
             "@version" => "1",
    "unexpected_message" => "64.41.200.105:60240 [22/Mar/2018:00:16:13.574] main/1: SSL handshake failure"
}
{
                        "timestamp" => "Mar 21 03:25:02",
                          "timeTCP" => "0",
                        "timeTotal" => "2",
      "concurrentConnectionsServer" => "1",
                            "bytes" => "165",
                          "retries" => "0",
               "connectionsBackend" => "0",
               "connectionsProcess" => "3",
                "connectionsServer" => "0",
                       "statusCode" => "302",
                          "backend" => "server_2.2",
                       "timeServer" => "1",
    "concurrentConnectionsFrontend" => "3",
                             "host" => "Elastics-MacBook-Pro.local",
                          "message" => "Mar 21 03:25:02 localhost haproxy[14415]: 188.93.156.49:50499 | {header1|Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; Trident/6.0)} | main~ server_2.2/appServer02 1/0/0/1/2 302 165 3/3/0/1/0 0/0 \"GET /server-2.2 HTTP/1.1\"",
                          "request" => "/server-2.2 HTTP/1.1",
                       "@timestamp" => 2018-04-30T11:30:25.773Z,
                           "tenant" => "header1",
                        "userAgent" => "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; Trident/6.0)",
                "timeClientRequest" => "1",
                             "verb" => "GET",
                         "@version" => "1",
                         "sequence" => 0,
                        "timeQueue" => "0",
                             "port" => "50499",
                         "frontend" => "main~",
                           "source" => "188.93.156.49",
     "concurrentConnectionsBackend" => "0",
                           "server" => "appServer02"
}
{
              "message" => "Mar 22 01:27:39 localhost haproxy[14415]: Server updates/appServer02 is UP, reason: Layer7 check passed, code: 200, info: \"OK\", check duration: 3ms. 2 active and 0 backup servers online. 0 sessions requeued, 0 total in queue.",
             "sequence" => 0,
            "timestamp" => "Mar 22 01:27:39",
           "@timestamp" => 2018-04-30T11:30:25.904Z,
                 "host" => "Elastics-MacBook-Pro.local",
             "@version" => "1",
    "unexpected_message" => "Server updates/appServer02 is UP, reason: Layer7 check passed, code: 200, info: \"OK\", check duration: 3ms. 2 active and 0 backup servers online. 0 sessions requeued, 0 total in queue."
}
3

Thanks, this works

1 Like
4

Hello there

I've implemented this in our logstash configuration using a total of 3 different expressions but now our Logstash server uses all of it's CPU (8 cores).
I've also enabled x-pack for logstash and there I can see (in the pipelines schema) that this grok expression uses 75% cpu and has a latency of 122ms/e.
Is this a known issue when using multiple grok expressions because the grok expression isn't that complex?
I read somewhere that when a grok expression doesn't match the logs it could take up more CPU but I don't know if that's true.

Any help or tips would be extreme helpful and appreciated

Thank you

5

What version of LS and Grok are you using?

We did have a problem when patterns did not match but IIRC this is much better in the most recent versions of grok.

6

We are using the latest version of logstash -> 6.2.4
I don't know how to find the version number of grok, I assume this is equal to the logstash version.

EDIT -> Grok version: 4.0.2

7

That version includes the "much better" code.

Did you read this blog post from my colleague Joao?

8

I just read the post and I see what it could be, I didn't close the logentry with a $ sign so I suppose grok tries too much instead of just going to the next grok parser

I'll try this out

Thank you

9

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