[Security Solution] Adjust log level and wording of logs written from rule executors#252374
Conversation
|
Pinging @elastic/security-detections-response (Team:Detections and Resp) |
|
Pinging @elastic/security-solution (Team: SecuritySolution) |
|
Pinging @elastic/security-detection-rule-management (Team:Detection Rule Management) |
|
@vitaliidm I switched reviewers to @dhurley14 as he's leading the effort on our end. |
c401d62 to
a52bbba
Compare
maximpn
left a comment
There was a problem hiding this comment.
@nikitaindik Thanks for improving the event log messages 🙏
I left some comments regarding inconsistencies and still unclear messages. While some of the comments are open-ended mostly we should stick to the document terms and make the messages as simple as possible so our customers may follow the rule execution path when necessary.
| ); | ||
| } catch (error) { | ||
| ruleExecutionLogger.error(error); | ||
| ruleExecutionLogger.debug(`Error building alert group from sequence\nError: ${error}`); |
There was a problem hiding this comment.
Shouldn't it be somethting like this Error transforming matched events to alerts\nError: ${error}?
| ruleExecutionLogger.debug( | ||
| `ES|QL query request for ${iteration} iteration took: ${esqlSearchDuration}ms` | ||
| ruleExecutionLogger.trace( | ||
| `ES|QL query iteration\nIteration: ${iteration}. Search took: ${esqlSearchDuration}ms.` |
There was a problem hiding this comment.
"took some ms" sounds like a message for the metrics event. I'm OK to leave it as is for now and deligate it to the DE team to decide how to properly handle this.
There was a problem hiding this comment.
We'll rework this at a later stage to output a single event with all the metrics at the end of rule execution. I'll create a ticket.
| ruleExecutionLogger.info( | ||
| `Alerts created: ${bulkCreateResult.createdItemsCount}. Alerts suppressed: ${bulkCreateResult.suppressedItemsCount}.` | ||
| ); |
There was a problem hiding this comment.
We could split this message in two
N alerts has been createdM alerts has been suppressed
Message details could shed more light on the alerts.
| ruleExecutionLogger.debug( | ||
| `End of search: Found ${response.values.length} results with page size ${size}` | ||
| ruleExecutionLogger.trace( | ||
| `End of search. Found ${response.values.length} results\nPage size ${size}.` |
There was a problem hiding this comment.
This message doesn't provide clear answers without knowing the executor implementation details. I'd suggest the following
- log each found portion size right below
responsehas been fetched. Something like<iteration>: Fetched N source events, page size M - in this
ifblock either log nothing or log that the execution has completed the execution. CheckoutIndicator matching rule has completedmessage as an example.
The main logic of the logs is providing clear an trackable rule execution path. Without the details the path is kind of trivial and looks like fetch source event -> apply exceptions -> generate alerts -> suppress some of the alerts. It means logging messages this way we could make the log really straightforward.
There was a problem hiding this comment.
message doesn't provide clear answers without knowing the executor implementation details
Yes, I agree. This seems like a low-level info that's useful to devs, but not users, so I moved it to the trace level.
fetch source event -> apply exceptions -> generate alerts -> suppress some of the alerts
For this sort of high-level logging, I'll add more logs at the INFO level in a follow-up PR.
| // warning should be already set | ||
| ruleExecutionLogger.debug( | ||
| `Indicator match has reached its max signals count ${ | ||
| `Max alerts per run reached\nIndicator match has reached its max signals count ${ |
There was a problem hiding this comment.
Again signals is used but it seems a to be a non documented term. This message contains a mix of alert and signal terms.
a52bbba to
7600c4a
Compare
7600c4a to
e414519
Compare
## Summary I accidentally merged a commit in PR [elastic#252168](elastic#252168) that was destined for another PR elastic#252374. 🤦♂️ The commit adjusted log levels for rule executors. Opening this PR to revert the unwanted commit.
💔 Build Failed
Failed CI StepsMetrics [docs]
History
cc @nikitaindik |
…/detection_engine/rule_types/indicator_match/threat_mapping/create_event_signal.ts Co-authored-by: Devin W. Hurley <snowmiser111@gmail.com>
…/detection_engine/rule_types/utils/search_after_bulk_create_factory.ts Co-authored-by: Devin W. Hurley <snowmiser111@gmail.com>
…/detection_engine/rule_types/utils/utils.ts Co-authored-by: Devin W. Hurley <snowmiser111@gmail.com>
…/detection_engine/rule_types/utils/single_search_after.ts Co-authored-by: Devin W. Hurley <snowmiser111@gmail.com>
…/detection_engine/rule_types/utils/send_telemetry_events.ts Co-authored-by: Devin W. Hurley <snowmiser111@gmail.com>
7456152 to
c61ab66
Compare
nikitaindik
left a comment
There was a problem hiding this comment.
Thanks for review, everyone! I'll open a follow-up that adds more info-level logging later today.
| `search times of ${results.searchAfterTimes}ms,`, | ||
| `bulk create times ${results.bulkCreateTimes}ms,`, | ||
| `all successes are ${results.success}` | ||
| `Alert candidates found: ${results.createdSignalsCount}.\nConcurrent indicator match searches completed. Search took: ${results.searchAfterTimes}ms. Bulk create times (ms): ${results.bulkCreateTimes}. Are all operations successful: ${results.success}.` |
There was a problem hiding this comment.
This message is logged in a loop, logs intermediate values and is very technical in general. I think it just makes sense to move this to the trace level, since this info is mostly for devs.
| ruleExecutionLogger.debug( | ||
| `End of search: Found ${response.values.length} results with page size ${size}` | ||
| ruleExecutionLogger.trace( | ||
| `End of search. Found ${response.values.length} results\nPage size ${size}.` |
There was a problem hiding this comment.
message doesn't provide clear answers without knowing the executor implementation details
Yes, I agree. This seems like a low-level info that's useful to devs, but not users, so I moved it to the trace level.
fetch source event -> apply exceptions -> generate alerts -> suppress some of the alerts
For this sort of high-level logging, I'll add more logs at the INFO level in a follow-up PR.
| ruleExecutionLogger.debug( | ||
| `ES|QL query request for ${iteration} iteration took: ${esqlSearchDuration}ms` | ||
| ruleExecutionLogger.trace( | ||
| `ES|QL query iteration\nIteration: ${iteration}. Search took: ${esqlSearchDuration}ms.` |
There was a problem hiding this comment.
We'll rework this at a later stage to output a single event with all the metrics at the end of rule execution. I'll create a ticket.
| `Match checks completed\n${ | ||
| currentEventList.length | ||
| } items have completed match checks and the total times to search were ${ | ||
| } items have completed match checks. Search times (ms): ${ |
There was a problem hiding this comment.
Yup. Moved it to trace for now. But we'll rework the approach later based on Marshall's suggestion here. Will create a ticket.
maximpn
left a comment
There was a problem hiding this comment.
@nikitaindik Thanks for addressing my comments 🙏
I'm really excited to see logging segregation based on the Marshall's comment. I'm quite sure APM provides really elaborated tools for toubleshooting.
… rule executors (elastic#252374) **Resolves: elastic#251211 ## Summary We'd like to provide a user-friendly way to view rule execution events to our customers, so that they could do some basic rule execution troubleshooting. To achieve this we are currently working ([PR](elastic#252168)) on improving the "Execution events" tab on the Rule Details page (currently hidden behind a feature flag). The "Execution events" tab would show execution events logged to event log, filtered by selected log levels. Ideally, we'd like to give users the most helpful information right away (like which indices are queried, how many alerts were created, how many were filtered by exceptions, etc) and let. Currently, we don't log a lot of info useful for customers, but we do log a lot of developer-useful info. <details> <summary>Screenshot of how "Execution events" messages look currently</summary> <img width="2932" height="675" alt="Screenshot 2026-02-09 at 17 33 56" src="https://github.com/user-attachments/assets/5ec58dd8-6032-49f3-83ec-bfbd13a6fa03" /> </details> <details> <summary>Screenshot of how "Execution events" would look after we apply changes from this PR (much cleaner)</summary> <img width="2291" height="854" alt="Screenshot 2026-02-12 at 12 07 04" src="https://github.com/user-attachments/assets/da74a5da-e6d5-4a07-885c-39ed3a55a132" /> </details> **Changes** This PR adjusts "message" logs written to event log from rule executors: - No new logs added, no information was removed. - Updated log levels: "info" for less technical user-useful info, "debug" for rule execution stages and basic stats, "trace" is for very small details, mostly useful for devs. - Updated the wording to be a bit more UI friendly and consistent. - Edited long log messages to have a summary/most useful piece of info in the first sentence, then details, separated by a newline char. We could show the first line in the "Execution events" table right away and the full message with all the details in the expandable section. > **NOTE**: You'll need to enable these Advanced Settings in Kibana config to write logs of all levels. ``` uiSettings.overrides: 'securitySolution:extendedRuleExecutionLoggingEnabled': true 'securitySolution:extendedRuleExecutionLoggingMinLevel': 'trace' ``` --------- Co-authored-by: Devin W. Hurley <snowmiser111@gmail.com>
Resolves: #251211
Summary
We'd like to provide a user-friendly way to view rule execution events to our customers, so that they could do some basic rule execution troubleshooting. To achieve this we are currently working (PR) on improving the "Execution events" tab on the Rule Details page (currently hidden behind a feature flag).
The "Execution events" tab would show execution events logged to event log, filtered by selected log levels. Ideally, we'd like to give users the most helpful information right away (like which indices are queried, how many alerts were created, how many were filtered by exceptions, etc) and let. Currently, we don't log a lot of info useful for customers, but we do log a lot of developer-useful info.
Screenshot of how "Execution events" messages look currently
Screenshot of how "Execution events" would look after we apply changes from this PR (much cleaner)
Changes
This PR adjusts "message" logs written to event log from rule executors: