Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Security Solution][Detections] Add error handling to Rule Execution Log #119595

Closed
Tracked by #118324
banderror opened this issue Nov 24, 2021 · 0 comments · Fixed by #120157 or #120200
Closed
Tracked by #118324

[Security Solution][Detections] Add error handling to Rule Execution Log #119595

banderror opened this issue Nov 24, 2021 · 0 comments · Fixed by #120157 or #120200
Assignees
Labels
Feature:Rule Monitoring Security Solution Detection Rule Monitoring Team:Detection Rule Management Security Detection Rule Management Team Team:Detections and Resp Security Detection Response Team Team: SecuritySolution Security Solutions Team working on SIEM, Endpoint, Timeline, Resolver, etc. technical debt Improvement of the software architecture and operational architecture v8.0.0

Comments

@banderror
Copy link
Contributor

banderror commented Nov 24, 2021

Parent ticket: #118324

Summary

Logging methods of IRuleExecutionLog should be safe to use and should not throw. Add try-catch and log exceptions to Kibana logs via the system logger.

@botelastic botelastic bot added the needs-team Issues missing a team label label Nov 24, 2021
@banderror banderror added technical debt Improvement of the software architecture and operational architecture Team:Detections and Resp Security Detection Response Team Team: SecuritySolution Security Solutions Team working on SIEM, Endpoint, Timeline, Resolver, etc. v8.1.0 Team:Detection Rule Management Security Detection Rule Management Team labels Nov 24, 2021
@botelastic botelastic bot removed the needs-team Issues missing a team label label Nov 24, 2021
@banderror banderror added the Feature:Rule Monitoring Security Solution Detection Rule Monitoring label Nov 24, 2021
@banderror banderror self-assigned this Nov 29, 2021
@banderror banderror added v8.0.0 and removed v8.1.0 labels Dec 1, 2021
banderror added a commit that referenced this issue Dec 2, 2021
…ethods of Rule Execution Log (#120157)

**Ticket:** #119595

## Summary

With this PR, calling `IRuleExecutionLog.logStatusChange()` is now safe for callers (rule executors or route handlers). It doesn't throw and writes any exceptions being caught to Kibana logs.

Example error in the logs:

```
[2021-12-01T20:05:36.620+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:05:37.591+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:91:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22)
[2021-12-01T20:05:37.591+01:00][DEBUG][plugins.securitySolution] ...
```

## Additional log metadata

For debugging purposes, rule execution log client writes additional log metadata with any caught exception. It's not visible in Kibana console logs by default, but can be enabled in Kibana config.

I used the following config to test it:

```yaml
logging:
  appenders:
    custom_console:
      type: console
      layout:
        type: pattern
        highlight: true
        pattern: "[%date][%level][%logger] %message %meta"
  root:
    appenders: [custom_console]
    level: warn
  loggers:
    - name: config
      level: info
    - name: plugins
      level: warn
    - name: plugins.securitySolution
      level: debug
    - name: plugins.ruleRegistry
      level: info
    - name: plugins.alerting
      level: info
    - name: plugins.taskManager
      level: info
    - name: savedobjects-service
      level: info
    - name: elasticsearch-service
      level: off
    - name: elasticsearch
      level: off
    - name: elasticsearch.query
      level: off
    - name: server
      level: fatal
    - name: optimize
      level: info
    - name: metrics.ops
      level: off
```

Error in the logs with additional metadata (find it after the stack trace):

```
[2021-12-01T20:03:30.807+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:03:31.812+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:93:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22) {"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
[2021-12-01T20:03:31.812+01:00][DEBUG][plugins.securitySolution] ...
```

Here it is extracted from the log:

```
{"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
```

More info on the layout configuration: https://www.elastic.co/guide/en/kibana/master/logging-configuration.html#pattern-layout
I couldn't decently pretty print it with the config options that are available 😞 

I was thinking what to include in the log metadata and what to include in the regular log message, and my thoughts so far were:

- It could be useful to add important attributes like correlation ids (rule id etc) and details of the original exception directly into the log message, because that's what is going to be logged out of the box with the default logging configuration.
- Log meta could be used for logging optional attributes that could be useful when digging deeper into an issue when debugging Security app and Detection Engine.

### Checklist

- [ ] [Unit or functional tests](https://www.elastic.co/guide/en/kibana/master/development-tests.html) were updated or added to match the most common scenarios
banderror added a commit to banderror/kibana that referenced this issue Dec 2, 2021
…ethods of Rule Execution Log (elastic#120157)

**Ticket:** elastic#119595

## Summary

With this PR, calling `IRuleExecutionLog.logStatusChange()` is now safe for callers (rule executors or route handlers). It doesn't throw and writes any exceptions being caught to Kibana logs.

Example error in the logs:

```
[2021-12-01T20:05:36.620+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:05:37.591+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:91:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22)
[2021-12-01T20:05:37.591+01:00][DEBUG][plugins.securitySolution] ...
```

## Additional log metadata

For debugging purposes, rule execution log client writes additional log metadata with any caught exception. It's not visible in Kibana console logs by default, but can be enabled in Kibana config.

I used the following config to test it:

```yaml
logging:
  appenders:
    custom_console:
      type: console
      layout:
        type: pattern
        highlight: true
        pattern: "[%date][%level][%logger] %message %meta"
  root:
    appenders: [custom_console]
    level: warn
  loggers:
    - name: config
      level: info
    - name: plugins
      level: warn
    - name: plugins.securitySolution
      level: debug
    - name: plugins.ruleRegistry
      level: info
    - name: plugins.alerting
      level: info
    - name: plugins.taskManager
      level: info
    - name: savedobjects-service
      level: info
    - name: elasticsearch-service
      level: off
    - name: elasticsearch
      level: off
    - name: elasticsearch.query
      level: off
    - name: server
      level: fatal
    - name: optimize
      level: info
    - name: metrics.ops
      level: off
```

Error in the logs with additional metadata (find it after the stack trace):

```
[2021-12-01T20:03:30.807+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:03:31.812+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:93:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22) {"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
[2021-12-01T20:03:31.812+01:00][DEBUG][plugins.securitySolution] ...
```

Here it is extracted from the log:

```
{"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
```

More info on the layout configuration: https://www.elastic.co/guide/en/kibana/master/logging-configuration.html#pattern-layout
I couldn't decently pretty print it with the config options that are available 😞 

I was thinking what to include in the log metadata and what to include in the regular log message, and my thoughts so far were:

- It could be useful to add important attributes like correlation ids (rule id etc) and details of the original exception directly into the log message, because that's what is going to be logged out of the box with the default logging configuration.
- Log meta could be used for logging optional attributes that could be useful when digging deeper into an issue when debugging Security app and Detection Engine.

### Checklist

- [ ] [Unit or functional tests](https://www.elastic.co/guide/en/kibana/master/development-tests.html) were updated or added to match the most common scenarios
banderror added a commit that referenced this issue Dec 2, 2021
…ethods of Rule Execution Log (#120157) (#120200)

**Ticket:** #119595

## Summary

With this PR, calling `IRuleExecutionLog.logStatusChange()` is now safe for callers (rule executors or route handlers). It doesn't throw and writes any exceptions being caught to Kibana logs.

Example error in the logs:

```
[2021-12-01T20:05:36.620+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:05:37.591+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:91:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22)
[2021-12-01T20:05:37.591+01:00][DEBUG][plugins.securitySolution] ...
```

## Additional log metadata

For debugging purposes, rule execution log client writes additional log metadata with any caught exception. It's not visible in Kibana console logs by default, but can be enabled in Kibana config.

I used the following config to test it:

```yaml
logging:
  appenders:
    custom_console:
      type: console
      layout:
        type: pattern
        highlight: true
        pattern: "[%date][%level][%logger] %message %meta"
  root:
    appenders: [custom_console]
    level: warn
  loggers:
    - name: config
      level: info
    - name: plugins
      level: warn
    - name: plugins.securitySolution
      level: debug
    - name: plugins.ruleRegistry
      level: info
    - name: plugins.alerting
      level: info
    - name: plugins.taskManager
      level: info
    - name: savedobjects-service
      level: info
    - name: elasticsearch-service
      level: off
    - name: elasticsearch
      level: off
    - name: elasticsearch.query
      level: off
    - name: server
      level: fatal
    - name: optimize
      level: info
    - name: metrics.ops
      level: off
```

Error in the logs with additional metadata (find it after the stack trace):

```
[2021-12-01T20:03:30.807+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:03:31.812+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:93:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22) {"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
[2021-12-01T20:03:31.812+01:00][DEBUG][plugins.securitySolution] ...
```

Here it is extracted from the log:

```
{"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
```

More info on the layout configuration: https://www.elastic.co/guide/en/kibana/master/logging-configuration.html#pattern-layout
I couldn't decently pretty print it with the config options that are available 😞 

I was thinking what to include in the log metadata and what to include in the regular log message, and my thoughts so far were:

- It could be useful to add important attributes like correlation ids (rule id etc) and details of the original exception directly into the log message, because that's what is going to be logged out of the box with the default logging configuration.
- Log meta could be used for logging optional attributes that could be useful when digging deeper into an issue when debugging Security app and Detection Engine.

### Checklist

- [ ] [Unit or functional tests](https://www.elastic.co/guide/en/kibana/master/development-tests.html) were updated or added to match the most common scenarios
TinLe pushed a commit to TinLe/kibana that referenced this issue Dec 22, 2021
…ethods of Rule Execution Log (elastic#120157)

**Ticket:** elastic#119595

## Summary

With this PR, calling `IRuleExecutionLog.logStatusChange()` is now safe for callers (rule executors or route handlers). It doesn't throw and writes any exceptions being caught to Kibana logs.

Example error in the logs:

```
[2021-12-01T20:05:36.620+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:05:37.591+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:91:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22)
[2021-12-01T20:05:37.591+01:00][DEBUG][plugins.securitySolution] ...
```

## Additional log metadata

For debugging purposes, rule execution log client writes additional log metadata with any caught exception. It's not visible in Kibana console logs by default, but can be enabled in Kibana config.

I used the following config to test it:

```yaml
logging:
  appenders:
    custom_console:
      type: console
      layout:
        type: pattern
        highlight: true
        pattern: "[%date][%level][%logger] %message %meta"
  root:
    appenders: [custom_console]
    level: warn
  loggers:
    - name: config
      level: info
    - name: plugins
      level: warn
    - name: plugins.securitySolution
      level: debug
    - name: plugins.ruleRegistry
      level: info
    - name: plugins.alerting
      level: info
    - name: plugins.taskManager
      level: info
    - name: savedobjects-service
      level: info
    - name: elasticsearch-service
      level: off
    - name: elasticsearch
      level: off
    - name: elasticsearch.query
      level: off
    - name: server
      level: fatal
    - name: optimize
      level: info
    - name: metrics.ops
      level: off
```

Error in the logs with additional metadata (find it after the stack trace):

```
[2021-12-01T20:03:30.807+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:03:31.812+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:93:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22) {"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
[2021-12-01T20:03:31.812+01:00][DEBUG][plugins.securitySolution] ...
```

Here it is extracted from the log:

```
{"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
```

More info on the layout configuration: https://www.elastic.co/guide/en/kibana/master/logging-configuration.html#pattern-layout
I couldn't decently pretty print it with the config options that are available 😞 

I was thinking what to include in the log metadata and what to include in the regular log message, and my thoughts so far were:

- It could be useful to add important attributes like correlation ids (rule id etc) and details of the original exception directly into the log message, because that's what is going to be logged out of the box with the default logging configuration.
- Log meta could be used for logging optional attributes that could be useful when digging deeper into an issue when debugging Security app and Detection Engine.

### Checklist

- [ ] [Unit or functional tests](https://www.elastic.co/guide/en/kibana/master/development-tests.html) were updated or added to match the most common scenarios
gbamparop pushed a commit to gbamparop/kibana that referenced this issue Jan 12, 2022
…ethods of Rule Execution Log (elastic#120157)

**Ticket:** elastic#119595

## Summary

With this PR, calling `IRuleExecutionLog.logStatusChange()` is now safe for callers (rule executors or route handlers). It doesn't throw and writes any exceptions being caught to Kibana logs.

Example error in the logs:

```
[2021-12-01T20:05:36.620+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:05:37.591+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:91:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22)
[2021-12-01T20:05:37.591+01:00][DEBUG][plugins.securitySolution] ...
```

## Additional log metadata

For debugging purposes, rule execution log client writes additional log metadata with any caught exception. It's not visible in Kibana console logs by default, but can be enabled in Kibana config.

I used the following config to test it:

```yaml
logging:
  appenders:
    custom_console:
      type: console
      layout:
        type: pattern
        highlight: true
        pattern: "[%date][%level][%logger] %message %meta"
  root:
    appenders: [custom_console]
    level: warn
  loggers:
    - name: config
      level: info
    - name: plugins
      level: warn
    - name: plugins.securitySolution
      level: debug
    - name: plugins.ruleRegistry
      level: info
    - name: plugins.alerting
      level: info
    - name: plugins.taskManager
      level: info
    - name: savedobjects-service
      level: info
    - name: elasticsearch-service
      level: off
    - name: elasticsearch
      level: off
    - name: elasticsearch.query
      level: off
    - name: server
      level: fatal
    - name: optimize
      level: info
    - name: metrics.ops
      level: off
```

Error in the logs with additional metadata (find it after the stack trace):

```
[2021-12-01T20:03:30.807+01:00][DEBUG][plugins.securitySolution] ...
[2021-12-01T20:03:31.812+01:00][ERROR][plugins.securitySolution.ruleExecution] Error logging rule execution status change; status: "succeeded", rule id: "abea42f0-489b-11ec-83fa-1bde56c47ca8", rule name: "SDH-247 my loooooong loooooong name"; Error: TESTING ERROR HANDLING
    at EventLogAdapter.logStatusChangeToSavedObjects (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:91:11)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Promise.all (index 0)
    at EventLogAdapter.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/event_log_adapter/event_log_adapter.ts:83:5)
    at RuleExecutionLogClient.logStatusChange (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_execution_log/rule_execution_log_client.ts:93:7)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts:345:15)
    at Object.executor (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/rule_registry/server/utils/create_persistence_rule_type_wrapper.ts:20:23)
    at TaskRunner.executeAlertInstances (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:316:31)
    at promiseResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/lib/result_type.ts:47:17)
    at TaskRunner.loadAlertAttributesAndRun (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:569:14)
    at errorAsAlertTaskRunResult (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:1119:12)
    at TaskRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/alerting/server/task_runner/task_runner.ts:635:33)
    at TaskManagerRunner.run (/Users/georgii/Code/elastic/kibana-main/x-pack/plugins/task_manager/server/task_running/task_runner.ts:297:22) {"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
[2021-12-01T20:03:31.812+01:00][DEBUG][plugins.securitySolution] ...
```

Here it is extracted from the log:

```
{"rule":{"id":"abea42f0-489b-11ec-83fa-1bde56c47ca8","name":"SDH-247 my loooooong loooooong name","type":"siem.queryRule","execution":{"status":"succeeded"}},"kibana":{"spaceId":"default"}}
```

More info on the layout configuration: https://www.elastic.co/guide/en/kibana/master/logging-configuration.html#pattern-layout
I couldn't decently pretty print it with the config options that are available 😞 

I was thinking what to include in the log metadata and what to include in the regular log message, and my thoughts so far were:

- It could be useful to add important attributes like correlation ids (rule id etc) and details of the original exception directly into the log message, because that's what is going to be logged out of the box with the default logging configuration.
- Log meta could be used for logging optional attributes that could be useful when digging deeper into an issue when debugging Security app and Detection Engine.

### Checklist

- [ ] [Unit or functional tests](https://www.elastic.co/guide/en/kibana/master/development-tests.html) were updated or added to match the most common scenarios
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Feature:Rule Monitoring Security Solution Detection Rule Monitoring Team:Detection Rule Management Security Detection Rule Management Team Team:Detections and Resp Security Detection Response Team Team: SecuritySolution Security Solutions Team working on SIEM, Endpoint, Timeline, Resolver, etc. technical debt Improvement of the software architecture and operational architecture v8.0.0
Projects
None yet
1 participant