Grok filter for mysql-slow-logs produces grokparsefailure but passes tests

Elastic Stack Logstash
1

I created a grok filter using the excellent grok constructor online. I pulled an example message string from a parsed mysql-slow-log and tested it using the grok pattern tester and it passed that test. When I apply it within logstash it produces _grokparsefailures every time and I'm not sure why. Here is how I'm testing it:

input {
  stdin {
    codec => multiline {
      pattern => "^# User@Host:"
      negate => true
      what => previous
    }
  }
}

filter {
    grok {
      match => [ "message", "%{MYSQLSLOWLOG}" ]
    }
    date {
      match => [ "timestamp", "UNIX"]
    }
}

output {stdout { codec => rubydebug } }

The MYSQLSLOWLOG pattern:

MYSQLSLOWLOG # User@Host: %{NOTSPACE} @ %{HOSTNAME} \[%{IP}]%{SPACE}Id:%{SPACE}%{BASE10NUM}\\n# Schema: %{WORD}%{SPACE}Last_errno:%{SPACE}%{NUMBER}%{SPACE}Killed: %{BASE10NUM}\\n# Query_time:%{SPACE}%{BASE16FLOAT}%{SPACE}Lock_time: %{BASE16FLOAT}%{SPACE}Rows_sent:%{SPACE}%{BASE10NUM}%{SPACE}Rows_examined: %{BASE10NUM}%{SPACE}Rows_affected: %{BASE10NUM}\\n# Bytes_sent: %{BASE10NUM}\\nSET timestamp=%{BASE10NUM:timestamp};\\n%{GREEDYDATA:query}

An example output from the ruby debug plugin:

{
    "@timestamp" => "2016-07-16T03:51:38.192Z",
       "message" => "# User@Host: username[username] @ host.company.com [xx.xx.xx.xx]  Id:   809\n# Schema:     company  Last_errno: 0  Killed: 0\n# Query_time: 3.708624  Lock_time: 0.000156  Rows_sent: 1  Rows_examined: 21172  Rows_affected: 0\n# Bytes_sent: 201\nSET timestamp=1466799648;\nSELECT SUM(IF(needs_review = \"Y\" AND vote_score > 0, 1, 0)) as edit,SUM(IF(needs_review = \"Y\" AND vote_score = 0, 1, 0)) as new,SUM(IF(needs_review != \"Y\" AND vote_score < 2.5, 1, 0)) as nmajc,SUM(IF(needs_review != \"Y\" AND vote_score >= 3.5, 1, 0)) as correct,SUM(IF(needs_review != \"Y\" AND vote_score >= 2.5 AND vote_score < 3.5, 1, 0)) as nminc\n            FROM mysql_table r\n                JOIN _mysql_table r2a ON r2a.table_id = r.table_id\n            WHERE r2a.mysql_table=634;\n#  Time: 160624 13:20:50",
      "@version" => "1",
          "tags" => [
        [0] "multiline",
        [1] "_grokparsefailure"
    ],
          "host" => "logstash-elk.company.com"
}

I tried testing the grok filter by pasting everything between the quotes in the "message" column into the tester and applying the pattern and it seems to work. I'm not sure what else to try.

2

I tried that on http://grokdebug.herokuapp.com/ and it didn't match :frowning:
Not sure if that is your obfuscation or not, but cross check it there?

3

Yeah it must be the obfuscation. I had originally tried it at http://grokconstructor.appspot.com where it worked. It also works at http://grokdebug.herokuapp.com.

4

This ended up having something to do with the # User@Host: at the beginning of the pattern in the file. I solved it by moving that section to the grok filter itself:

filter {
    grok {
      match => [ "message", "^# User@Host: %{MYSQLSLOWLOG}" ]
    }
    date {
      match => [ "timestamp", "UNIX"]
    }
}

Pattern:

MYSQLSLOWLOG %{NOTSPACE} @ %{HOSTNAME} \[%{IP}]%{SPACE}Id:%{SPACE}%{BASE10NUM}\\n# Schema: %{WORD}%{SPACE}Last_errno:%{SPACE}%{NUMBER}%{SPACE}Killed: %{BASE10NUM}\\n# Query_time:%{SPACE}%{BASE16FLOAT}%{SPACE}Lock_time: %{BASE16FLOAT}%{SPACE}Rows_sent:%{SPACE}%{BASE10NUM}%{SPACE}Rows_examined: %{BASE10NUM}%{SPACE}Rows_affected: %{BASE10NUM}\\n# Bytes_sent: %{BASE10NUM}\\nSET timestamp=%{BASE10NUM:timestamp};\\n%{GREEDYDATA:query}
5

It'd be awesome if you made a PR with that pattern against https://github.com/markwalkom/community-logstash-grok-patterns :smiley: