# Determining reason for stuck grok filter

**URL:** https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257
**Category:** Logstash
**Created:** [July 18, 2019, 5:09pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257 "2019-07-18T17:09:45Z")
**Posts on this page:** 10
**Page:** 1

<div class="post-metadata">

### Author: ![victor73](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/victor73/32/50538_2.png) [@victor73](https://discuss.elastic.co/u/victor73)
#### Post date: [July 18, 2019, 5:09pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/1 "2019-07-18T17:09:46Z")

</div>

Hi all,

I've tried using logstash versions 6.8.1, 7.0 and 7.2 and, regardless of version, logstash seems to stop it's processing and begin consuming all the available CPU. It seems to be stuck with the grok filter. I suspect this is the case, because when I shut down logstash, I get messages regarding the org.logstash.execution.ShutdownWatcherExt and stalling\_threads\_info that contain my actual grok patterns that I'm using.

In addition, the tail end of those stalling\_threads\_info messages look like this:

`"name"=>"[main]>worker0", "current_call"=>"[...]/vendor/bundle/jruby/2.5.0/gems/jls-grok-0.11.5/lib/grok-pure.rb:182:in \`match'"}, {"thread\_id"=\>28, "name"=\>"[main]\>worker1", "current\_call"=\>"[...]/vendor/bundle/jruby/2.5.0/gems/jls-grok-0.11.5/lib/grok-pure.rb:182:in `match'"}]}}`

Is there someway to determine, what input/log event is causing the regular expression, or pattern, to go crazy like this? Is there a recommended approach to resolve issues such as this?

---

<div class="post-metadata">

### Author: ![Badger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/badger/32/25190_2.png) [@Badger](https://discuss.elastic.co/u/Badger)
#### Post date: [July 18, 2019, 5:12pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/2 "2019-07-18T17:12:53Z")

</div>

What does your grok pattern look like? I suspect that there is excessive backtracking occurring.

---

<div class="post-metadata">

### Author: ![victor73](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/victor73/32/50538_2.png) [@victor73](https://discuss.elastic.co/u/victor73)
#### Post date: [July 18, 2019, 5:45pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/3 "2019-07-18T17:45:00Z")

</div>

Here is one. The YESNO is a custom pattern definition that's defined as "yes|no|YES|NO":

%{FASP\_DATE:timestamp} %{WORD:hostname} ascp[%{POSINT:pid}]: LOG FASP Session Params uuid=%{UUID:uuid} userid=%{NUMBER:userid} user="%{WORD:remote\_user}" targetrate=%{NONNEGINT:targetrate} minrate=%{INT:minrate} rate\_policy=%{WORD:rate\_policy} cipher=%{DATA:cipher} resume=%{INT:resume} create=%{INT:create} ovr=%{INT:ovr} times=%{INT:times} precalc=%{WORD:precalc} mf=%{INT:mf} mf\_path=%{DATA:mf\_path} mf\_suffix=%{DATA:mf\_suffix} partial\_file\_suffix=%{DATA:partial\_file\_suffix} files\_encrypt=%{YESNO:files\_encrypt} files\_decrypt=%{YESNO:files\_decrypt} file\_csum=%{WORD:file\_csum} dgram\_sz=%{NUMBER:dgram\_sz} prepostcmd=%{DATA:prepostcmd} tcp\_mode=%{YESNO:tcp\_mode} rtt\_auto=%{YESNO:rtt\_auto} cookie="%{DATA:cookie}" vl\_proto\_ver=%{NUMBER:vl\_proto\_ver} peer\_vl\_proto\_ver=%{NUMBER:peer\_vl\_proto\_ver} vl\_local=%{NUMBER:vl\_local} vlink\_remote=%{NUMBER:vlink\_remote} vl\_sess\_id=%{DATA:vl\_sess\_id} srcbase=%{DATA:srcbase} rd\_sz=%{NUMBER:rd\_size} wr\_sz=%{NUMBER:wr\_sz} cluster\_num\_nodes=%{NONNEGINT:cluster\_num\_nodes} cluster\_node\_id=%{INT:cluster\_node\_id} cluster\_multi\_session\_threshold=%{INT:cluster\_multi\_session\_threshold} range=%{DATA:range} keepalive=%{YESNO:keepalive} test\_login=%{YESNO:test\_login} proxy\_ip=%{DATA:proxy\_ip} net\_rc\_alg=%{WORD:net\_rc\_alg} exclude\_older/newer\_than=%{NUMBER:exclude\_older}/%{NUMBER:newer\_than}

I do have another one that makes use of multiple "GREEDYDATA" fields...

%{FASP\_DATE:timestamp} %{WORD:hostname} ascp[%{POSINT:pid}]: LOG FASP Session Stop uuid=%{UUID:uuid} op=%{WORD:operation} status=%{FASP\_STATUS:status} errcode=%{NUMBER:errcode} errstr="%{GREEDYDATA:errstr}" source=%{DATA:source} dest=%{DATA:dest} source\_prefix=%{DATA:source\_prefix} local=%{IP:local\_ip}:%{NUMBER:port} peer=%{IP:client\_ip}:%{NUMBER:client\_port} tcp\_port=%{NUMBER:tcp\_port} os="%{GREEDYDATA:os}" ver=%{DATA:ver} lic=%{DATA:lic} peeros="%{GREEDYDATA:client\_os}" peerver=%{DATA:client\_ver} peerlic=%{DATA:client\_lic} proto\_sess=%{NUMBER:proto\_sess} proto\_udp=%{NUMBER:proto\_udp} proto\_bwmeas=%{NUMBER:proto\_bwmeas} proto\_data=%{WORD:proto\_data}

---

<div class="post-metadata">

### Author: ![Badger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/badger/32/25190_2.png) [@Badger](https://discuss.elastic.co/u/Badger)
#### Post date: [July 18, 2019, 5:58pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/4 "2019-07-18T17:58:58Z")

</div>

That first pattern has 9 DATA patterns in it. It is going to be very expensive for it to determine that it does not match a field. Whereever possible, replace DATA with something else. If a field cannot contain a space then replace %{DATA:cipher} with

```
(?<cipher>[^]+)

```

and so on. Ideally you should only have one DATA or GREEDYDATA and it should be the last item in the pattern.

Also, most importantly, anchor your patterns. Read [this](https://www.elastic.co/blog/do-you-grok-grok) elastic blog entry. If you are matching the whole of a line there is a massive performance difference between the cost of

```
%{FASP_DATE:timestamp} %{WORD:hostname} ascp[%{POSINT:pid}]: LOG FASP Session Params uuid=%{UUID:uuid} userid=%{NUMBER:userid} user="%{WORD:remote_user}"

```

and

```
^%{FASP_DATE:timestamp} %{WORD:hostname} ascp[%{POSINT:pid}]: LOG FASP Session Params uuid=%{UUID:uuid} userid=%{NUMBER:userid} user="%{WORD:remote_user}"

```

when they do _not_ match.

Also, grok looks like the wrong approach to me. I would try using to grok with this

```
^%{FASP_DATE:timestamp} %{WORD:hostname} ascp[%{POSINT:pid}]: LOG FASP Session %{WORD:operation} %{GREEDYDATA:restOfLine}

```

and then use a kv filter to parse restOfLine.

---

<div class="post-metadata">

### Author: ![victor73](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/victor73/32/50538_2.png) [@victor73](https://discuss.elastic.co/u/victor73)
#### Post date: [July 18, 2019, 6:25pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/5 "2019-07-18T18:25:19Z")

</div>

Thanks very much. You've given me a whole bunch of leads to track down. Some outstanding recommendations and tips here. Thank you!

---

<div class="post-metadata">

### Author: ![victor73](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/victor73/32/50538_2.png) [@victor73](https://discuss.elastic.co/u/victor73)
#### Post date: [July 18, 2019, 9:44pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/6 "2019-07-18T21:44:50Z")

</div>

So far I've eliminated the use of DATA and GREEDYDATA to see if there is an improvement in the CPU consumption, but so far the situation is unchanged. I've also added a timeout\_millis setting (set to 300) in order to skip events that cause the regular expression engine to take too long. Unfortunately, this ALSO doesn't seem to have any effect and the CPU still get's completely consumed. I would have expected to start seeing the events in my input (redis) go down over time since I've asked logstash to skip slow events, but it just stalls after several hundred events are removed. Any suggestions about what to try next?

---

<div class="post-metadata">

### Author: ![Badger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/badger/32/25190_2.png) [@Badger](https://discuss.elastic.co/u/Badger)
#### Post date: [July 18, 2019, 9:59pm UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/7 "2019-07-18T21:59:05Z")

</div>

Are you absolutely sure you are running with the modified configuration?

---

<div class="post-metadata">

### Author: ![victor73](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/victor73/32/50538_2.png) [@victor73](https://discuss.elastic.co/u/victor73)
#### Post date: [July 19, 2019, 2:05am UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/8 "2019-07-19T02:05:43Z")

</div>

Just to be sure, I introduced an obvious typo into the configuration and restarted. Sure enough, a LogStash::ConfigurationError was thrown in the logs. So, since I have two inputs, I decided to turn one of them off by commenting it out. That helped quite a bit and the CPU usage came down to the single digits. Therefore, the other input (redis) must contain the events that are causing the high CPU condition, which I confirmed by reactivating it and observing 100% CPU again... I suppose the next thing to try is the kv filter technique you suggested earlier, but I'm a little disheartened that the timeout\_millis setting didn't seem to do anything...

---

<div class="post-metadata">

### Author: ![victor73](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/victor73/32/50538_2.png) [@victor73](https://discuss.elastic.co/u/victor73)
#### Post date: [July 20, 2019, 12:17am UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/9 "2019-07-20T00:17:22Z")

</div>

Looks like removing the multitude of grok patterns and using just one followed by the use of the kv filter, was the key to resolving this problem. Many thanks!

---

<div class="post-metadata">

### Author: ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)
#### Post date: [August 17, 2019, 12:17am UTC](https://discuss.elastic.co/t/determining-reason-for-stuck-grok-filter/191257/10 "2019-08-17T00:17:30Z")

</div>

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