Timeout executing grok using pipe symbol

Hey all,

I'm getting a grok timeout warning with a very specific format of log. Here is my grok filter:

grok {
  match => { "message" => "fs_log: %{TIMESTAMP_ISO8601:timestamp} \|\| %{UNIXPATH:filename} \|\| %{WORD:caller} \|\| %{NUMBER:lineno} \|\| %{DATA:message} \|\| %{WORD:event} \|\| %{WORD:module} \|\| %{NOTSPACE:instance_id}" }
  overwrite => [ "message" ]
  keep_empty_captures => true
  add_tag => [ "fs_log" ]
}

As you can see, I am using two pipes || to delineate the fields to be parsed by grok.
This works the vast majority of the time. However, there are two instances where I consistently get a grok timeout:

fs_log: 2019-04-12 17:28:24.434573 || /path/file.py || func_name || 338 || Subprocess call Failed: ERROR 2: CPLRealloc(): Out of memory allocating 423383040 bytes.
fs_log: 2019-04-12 17:28:29.940564 || /path/file.py || func_name || 338 || Subprocess call Failed: ERROR 2: ogrlinestring.cpp, 446: cannot allocate 732672016 bytes

These lines are obviously not supposed to match regardless, but then why is there a timeout? Here is a sample message of the warning:

[2019-04-12T17:31:21,999][WARN ][logstash.filters.grok    ] Timeout executing grok 'fs_log: %{TIMESTAMP_ISO8601:timestamp} \|\| %{UNIXPATH:filename} \|\| %{WORD:caller} \|\| %{NUMBER:lineno} \|\| %{DATA:message} \|\| %{WORD:event} \|\| %{WORD:module} \|\| %{NOTSPACE:instance_id}' against field 'message' with value 'fs_log: 2019-04-12 17:28:29.940564 || /path/file.py || func_name || 338 || Subprocess call Failed: ERROR 2: ogrlinestring.cpp, 446: cannot allocate 732672016 bytes'!

And just to clarify, logstash is running on a different machine than the one that generates the log, so the fact that the log references memory allocation issues has nothing to do with the grok timeout.

Any help would be greatly appreciated!

UNIXPATH is notoriously expensive. Do not use it.

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