num_events for a frequency rule

[gminogiannis]

Hello!
We 've been using a frequency rule with a configuration similar to the below:

type: frequency
scan_entire_timeframe: True
index: logs-*

num_events: 10
timeframe:
  minutes: 5

filter:
- query_string:
    analyze_wildcard: true
    query: 'level: (ERROR OR WARN) AND NOT message: ("test msg" OR "testing rule")'


alert:
  - "command"

realert:
 minutes: 30

command: ["/opt/scripts/send-sms.sh"]

The rule is executed every minute and is expected to check if more than 10 documents during the last 5 minutes match the query.
Nevertheless, we have seen several cases whereby the alert is triggered even if less than 10 documents match the query.

Is there a way to troubleshoot this ?

P.S: ElastAlert2 is launched as a Docker container via the following command:

sudo docker run \
--name elastalert2 \
--net="host" \
-v /opt/elastalert/config.yaml:/opt/elastalert/config.yaml \
-v /opt/elastalert/rules:/opt/elastalert/rules \
jertel/elastalert2:2.12.0

P.S2: We are still using 2.12.0 because newer versions fail to start. That's something for another discussion thread, though.

---

[jertel]

You should review the debug logs, looking at hits vs matches on each rule run, and compare that to the timeline of the matching documents' @timestamp fields.

[gminogiannis]

Valid point @jertel !
I forgot to mention that the index elastalert_status indicates there's a match even if the hits are less than num_events.

See also the attachments:

1. The file frequency-records.csv is a CSV export from the index logs-2024.05.21. There are 9 records generated at 12:59:30
2. The file frequency-alerts.csv is a CSV export from the indices elastalert*. There are 3 records generated at 13:03:26. Those records indicate that the hits where 9 (less than num_events which were set to 10) and that an alert was triggered.

Could you please help us with that ?

[jertel]

scan_entire_timeframe: True tells ElastAlert 2 to rescan the full timeframe (5 minutes) on each rule run.

• During minutes M0 through M3, nothing occurs.
• 9 records are ingested at minute M4
• Rule runs at minute M5, ElastAlert 2 finds 9 hits during minute M4, since timeframe is set to 5 minutes. No alert is sent because 9 < 10. But it still internally remembers that it found 9 hits. Because if the next rule run finds another hit, then the threshold is breached within the configured 5 minute timeframe.
• Rule runs a minute later, at M6. Since scan_entire_timeframe is True, it will re-query minutes M2, M3, M4, M5, and M6. It finds the same 9 records at minute M4 that it had already found on the previous run. So it accumulates the new hits with the old hits and now has 18 hits, which exceeds the threshold of 10. An alert is sent.
• For the next couple of minutes no alerts are sent beause the realert setting hasn't been exceeded.

If you don't want this behavior you must disable scan_entire_timeframe.

[gminogiannis]

Clear!
IMHO, the documentation could probably mention that duplicate matches (and not just duplicate alerts) will definitely occur in case this setting is enabled.

Now, moving forward, we performed the following tests with scan_entire_timeframe: False:

• 9 hits within 5 minutes
  • started on 08:39:14
  • no matches (as expected)
• 10 hits within 5 minutes
  • started on 08:45:22
  • 1 match (as expected) on 08:45:58
• 9+1 hits within 5 minutes
  • started on 08:51:24
  • 1 match (as expected) on 08:53:14
• 10 hits within 5 minutes + wait for realert to expire + 10 hits within 5 minutes
  • started on 08:58:27
  • 1 match (NOT as expected) on 08:58:30

Attaching also the relevant logs: elastalert-20240524.log
@jertel shouldn't we have 2 matches for the last scenario ?

---

[jertel]

I see 10 hits at 8:58:30, and an alert was sent. I don't see any further hits found in ES after that. From what I see in the log it's working as expected.

The documentation already mentions the risk of duplicate alerts, and specifically mentions that there are drawbacks to using this with certain rule types. Further, it explains when this setting is useful: For flatline alerts, and cautions of problems with Frequency alerts.

[gminogiannis]

I see 10 hits at 8:58:30, and an alert was sent. I don't see any further hits found in ES after that

That's the problem and that's why we need your help and expertise.
For some reason, the additional 10 records are not being recorded (as "hits") in the ElastAlert logs even though they exist in ES:

$ curl -s "localhost:9200/logs-*/_count" -H "content-type: application/json" \
  -d '{"query":{"bool":{"must":[{"range":{"@timestamp":{"gte":"2024-05-24T09:03:27","lte":"2024-05-24T09:08:27"}}},{"term":{"level":"error"}}]}}}'

{"count":10,"_shards":{"total":1,"successful":1,"skipped":0,"failed":0}}

Any ideas ?
Would you like me to prepare something automated so that you can give it a go ?

---

[jertel]

Provide the debug ElastAlert 2 logs, with timestamps.

Provide evidence showing the records exist in Elasticsearch along with each record's @timestamp field.

[gminogiannis]

Let's archive this discussion until more evidence is gathered.