Elastisearch query rule type hits contains only one document

Elastic Observability Logs
1

Rule type: Elastisearch query
Connector: Index

context.hits always contain only one document, evethough there are multiple documents that match the query at that point in time. Context.value is always 1.

Test query (in the Rule edit) shows correct hit count in that minute.

Query matched 2 documents in the last 1m.

RULE

Name alert log
Tags (optional)
Check every 50 seconds
Notify Every time alert is active

Select an index and size
INDEX logs-apps
SIZE 10

When number of matches
IS ABOVE 0
FOR THE LAST 1 minute

Expected: context.hits contain multiple documents (that matched the query)

Can someone help me identify the issue.

2

Sometime indexed doc does have multipe docs in hits.

3

Hi @bravo,

Can you turn on debug logging and provide the logs from the stackAlerts plugin? (this can be done by setting logging.root.level: debug in your kibana.yml configuration. See here for details).

This will provide the query with a specific time range, results, etc, to help us debug.

4

@mikecote, Thank you for the reply. We have enabled debug logging in Kibana and the concerned log lines are below

We are trying to alert when a document match the search filters. So, we are running the alert EVERY 1 MINUTE and match IS ABOVE 0 FOR THE LAST 1 minute.

It seems, eventhough there are matching documents in the target index, stackAlerts elasticsearch query do not find it, most of the time. Please see below.

E.g.
document at @15:07:36.395 is not hit by query at 2021-07-14T15:07:55+05:30
document at @15:07:56.174 is missed by query at 2021-07-14T15:08:58+05:30
Was expecting the THE LAST 1 minute verb will hit the documents of the past 1 minute, is this correct?

> tail -f /var/log/kibana/kibana.log | grep --line-buffered '"debug","plugins","stackAlerts"'

{"type":"log","@timestamp":"2021-07-14T14:57:25+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T09:27:25.342Z\",\"gte\":\"2021-07-14T09:26:25.342Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T14:57:25+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-14T15:04:46+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T09:34:46.380Z\",\"gte\":\"2021-07-14T09:33:46.380Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T15:04:46+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-14T15:07:55+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T09:37:55.432Z\",\"gte\":\"2021-07-14T09:36:55.432Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T15:07:55+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":1,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-14T15:08:58+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T09:38:58.433Z\",\"gte\":\"2021-07-14T09:37:58.433Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T15:08:58+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":1,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-14T15:10:01+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T09:40:01.430Z\",\"gte\":\"2021-07-14T09:39:01.430Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T15:10:01+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":8,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-14T15:12:07+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T09:42:07.568Z\",\"gte\":\"2021-07-14T09:41:07.568Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T15:12:07+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-14T15:13:10+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T09:43:10.469Z\",\"gte\":\"2021-07-14T09:42:10.469Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T15:13:10+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":2,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}

Have removed some log entries to reduce reply size.

The documents are available, as seen in the Discover for the above tested log time

Jul 14, 2021 @ 15:13:59.869	login	login	XXX
Jul 14, 2021 @ 15:09:00.240	login	login	XXX
Jul 14, 2021 @ 15:07:56.174	login	login	XXX
Jul 14, 2021 @ 15:07:36.395	login	login	XXX
Jul 14, 2021 @ 15:03:56.566	login	login	XXX
Jul 14, 2021 @ 14:47:47.021	login	login	XXX

During this testing period, the only following document was matched and alerted

Time	message.model	message.action	agent.id
Jul 14, 2021 @ 15:34:14.550	login	login	XXX

{"type":"log","@timestamp":"2021-07-14T15:35:13+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-events-xx\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"must_not\":[{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T07:17:04.204Z\"}}}]}}]}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-14T10:05:13.797Z\",\"gte\":\"2021-07-14T10:04:13.797Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-14T15:35:14+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:XXX \"alert events login\" result - {\"took\":612,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":1,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[DOCUMENT]},\"sort\":[1626257054550]}]}}"}

So, our alert rules do not raise any alert for the matching documents, but only for a few. Can you please help debug?

5

Hi @bravo,

What query are you using for the Elasticsearch query rule?

I see the following attached to every query which seems it would filter out any record?

"range": {
    "@timestamp": {
        "lte": "2021-07-14T07:17:04.204Z"
    }
}

Also to make sure, have you set "Notify" to "Every time alert is active" instead of the default "Only on status change" for the rule? Documentation. If not, this may explain why the index action is only called at rare occasions (it would only call it the first time the result is > 0 and not again until the result returns 0 and back to > 0 again.

6

Thank you @mikecote for the reply.

I could not find the RANGE filter anywhere in the settings, including the query rule.
Elasticsearch query rule

{
    "query": {
        "bool": {
            "must": [
                {
                    "term": {
                        "message.model": "login"
                    }
                },
                {
                    "term": {
                        "message.action": "login"
                    }
                }
            ]
        }
    }
}

Notify is already set to "Every time alert is active".

Is it possible that RANGE filter is automatically atached due to the below option

**When number of matches**
IS ABOVE 0
FOR THE LAST 1 minute

Please find the screenshot, incase something is amiss.

Screenshot from 2021-07-20 14-57-30

Screenshot from 2021-07-20 14-57-46
Screenshot from 2021-07-20 14-57-46559×628 31.6 KB

Screenshot from 2021-07-20 14-57-59
Screenshot from 2021-07-20 14-57-59507×507 25.8 KB

7

Hmm, I'm not sure how the extra range query got added, it shouldn't be part of the query. Do you get the same problem if you create a new rule?

My recommendation would be to run the queries (from the logs) against Elasticsearch yourself where the rule doesn't detect any hits. If you do see results, is the query running as the same user who created / last updated the rule? If you do not see results, what happens when you start removing elements from the query (like the extra range query), do the results start to return?

This could potentially be a mapping issue, playing with the queries as stated above will help uncover what may be happening. I've extracted below one of the queries you mentioned that didn't work. I would recommend playing with that query and removing things until results start to appear, this will help identify if the issue is around @timestamp, message.model or message.action mappings / data.

{
    "allow_no_indices": true,
    "index":[
        "logs-events-xx"
    ],
    "size": 10,
    "ignore_unavailable": true,
    "track_total_hits": true,
    "body": {
        "docvalue_fields": [
            {
                "field": "@timestamp",
                "format": "strict_date_optional_time"
            }
        ],
        "query": {
            "bool": {
                "filter": [
                    {
                        "bool": {
                            "filter": [
                                {
                                    "bool": {
                                        "must": [
                                            {
                                                "term": {
                                                    "message.model": "login"
                                                }
                                            },
                                            {
                                                "term": {
                                                    "message.action": "login"
                                                }
                                            }
                                        ]
                                    }
                                },
                                {
                                    "bool": {
                                        "must_not": [
                                            {
                                                "bool": {
                                                    "filter": [
                                                        {
                                                            "range": {
                                                                "@timestamp": {
                                                                    "lte": "2021-07-14T07:17:04.204Z"
                                                                }
                                                            }
                                                        }
                                                    ]
                                                }
                                            }
                                        ]
                                    }
                                }
                            ]
                        }
                    },
                    {
                        "bool": {
                            "filter": [
                                {
                                    "range": {
                                        "@timestamp": {
                                            "lte": "2021-07-14T09:37:55.432Z",
                                            "gte": "2021-07-14T09:36:55.432Z",
                                            "format": "strict_date_optional_time"
                                        }
                                    }
                                }
                            ]
                        }
                    },
                    {
                        "match_all": {}
                    }
                ]
            }
        },
        "sort": [
            {
                "@timestamp": {
                    "order": "desc"
                }
            }
        ]
    }
}
8

@bravo @mikecote

The extra range query is appended automatically as part of the ES query rule in order to perform de-duplication of documents so that you won't get notified multiple times about the same document.

The first time the ES query rule runs, it takes the latest timestamp from the matching documents and uses that in the next run of the rule to filter out documents it already matched on. It seems like the latest timestamp that is being used was from 2 hours previous to the current rule execution run.

Is it possible that the rule used to have a larger time window than 1 minute (a few hours maybe?) and it was changed to 1 minute to match the schedule? That would explain why there is this extra filter. This does seem like a bug and I will file an issue for it. In the meantime, can you try disabling and the re-enabling the rule to clear the state?

9

Yes, do remember tweaking the rule run many times (upto few hours) during testing to get older docs.

  1. disabled and enabled the rule (after few mins) and still docs missed.
  2. created a new similar rule with 1 min rule run and still docs missed. Please find the Kibana logs of the newly created rule.
{"type":"log","@timestamp":"2021-07-25T15:14:18+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-nb\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-25T09:44:18.995Z\",\"gte\":\"2021-07-25T09:43:18.995Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-25T15:14:18+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-25T15:15:21+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-nb\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-25T09:45:21.947Z\",\"gte\":\"2021-07-25T09:44:21.947Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-25T15:15:21+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-25T15:16:24+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-nb\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-25T09:46:24.975Z\",\"gte\":\"2021-07-25T09:45:24.975Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-25T15:16:24+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-25T15:17:27+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-nb\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-25T09:47:27.991Z\",\"gte\":\"2021-07-25T09:46:27.991Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-25T15:17:27+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
{"type":"log","@timestamp":"2021-07-25T15:18:30+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" query - {\"allow_no_indices\":true,\"index\":[\"logs-nb\"],\"size\":10,\"ignore_unavailable\":true,\"track_total_hits\":true,\"body\":{\"docvalue_fields\":[{\"field\":\"@timestamp\",\"format\":\"strict_date_optional_time\"}],\"query\":{\"bool\":{\"filter\":[{\"bool\":{\"must\":[{\"term\":{\"message.model\":\"login\"}},{\"term\":{\"message.action\":\"login\"}}]}},{\"bool\":{\"filter\":[{\"range\":{\"@timestamp\":{\"lte\":\"2021-07-25T09:48:30.983Z\",\"gte\":\"2021-07-25T09:47:30.983Z\",\"format\":\"strict_date_optional_time\"}}}]}},{\"match_all\":{}}]}},\"sort\":[{\"@timestamp\":{\"order\":\"desc\"}}]}}"}
{"type":"log","@timestamp":"2021-07-25T15:18:30+05:30","tags":["debug","plugins","stackAlerts"],"pid":18575,"message":"alert .es-query:25e52410-ed2c-11eb-80d4-9bfacf4c6768 \"alert events login\" result - {\"took\":0,\"timed_out\":false,\"_shards\":{\"total\":1,\"successful\":1,\"skipped\":0,\"failed\":0},\"hits\":{\"total\":{\"value\":0,\"relation\":\"eq\"},\"max_score\":null,\"hits\":[]}}"}
10

@bravo, Looking at the queries that were run, none of them have the extra timestamp filter, just the range filter for the 1 minute time window specified by the rule. You should be able to copy those queries to the console. When you run them in the console against the logs-nb index, you are seeing more than 1 result?

Pretty-printing one of the queries for context.

GET logs-nb/_search
{
	"query": {
		"bool": {
			"filter": [{
				"bool": {
					"must": [{
						"term": {
							"message.model": "login"
						}
					}, {
						"term": {
							"message.action": "login"
						}
					}]
				}
			}, {
				"bool": {
					"filter": [{
						"range": {
							"@timestamp": {
								"lte": "2021-07-25T09:44:18.995Z",
								"gte": "2021-07-25T09:43:18.995Z",
								"format": "strict_date_optional_time"
							}
						}
					}]
				}
			}, {
				"match_all": {}
			}]
		}
	}
}
11

@ying.mao

Thank you for the response and sorry for the late reply.

Running the above query does generate results with multiple docs as below

{
  "took" : 9,
  "timed_out" : false,
  "_shards" : {
    "total" : 1,
    "successful" : 1,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : {
      "value" : 2,
      "relation" : "eq"
    },
    "max_score" : 0.0,
    "hits" : [
12

@bravo The only thing I can think of is whether there is any lag between the time of ingest and the document timestamp?

Time 1:00 Document 1 gets ingested with timestamp 0:58
Time 1:30 Rule executor runs and queries for documents with timestamp 0:30 - 1:30, gets 1 match
Time 1:35 Document 2 gets ingested with timestamp 1:00

...Sometime later, dev console query is run for timestamp 0:30 - 1:30 and gets 2 matches

13

@ying.mao Lag is possible. The document @timestamp is when the event happened, so there might be lag by the time FileBeat (using Fleet Agent) ingests that document.

Should we have a seperate field with ingest time and use that timestamp for the rule?

Thank you for this insight.

14

@bravo I believe that having a separate ingest timestamp if ingest time lags behind the timestamp would help, especially if the lag is significant.

15

@bravo You could also try expanding the time window searched to more than 1 minute to try to capture documents that were ingested late. I think that is what you had originally but changing from a larger window to a smaller window in the same active rule was causing documents to be missed because of leftover state. Could you try creating the rule with a 1 minute schedule and a 5 minute window? (Or whatever window you feel might cover the lag time?)

1 Like
16

@ying.mao @mikecote

Thank you very much for your time to look into this. Got this working!

As per @ying.mao, we have modified the elasticcearch query filter time FOR THE LAST from 1 min to 5 min and disabled/ enabled the rule (did not need to create new rule).

Left the Rule runs every 1 min as it is.

2 Likes
17

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