[Security Solution][Detections] Add basic error handling to logging methods of Rule Execution Log

[banderror]

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:

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 were updated or added to match the most common scenarios

[elasticmachine]

Pinging @elastic/security-detections-response (Team:Detections and Resp)

[elasticmachine]

Pinging @elastic/security-solution (Team: SecuritySolution)

[kibana-ci]

💚 Build Succeeded

• Buildkite Build
• Commit: bd24153
• Storybooks Preview

Metrics [docs]

✅ unchanged

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

cc @banderror

[spong]

Checked out, tested locally verifying exception in logs, and code reviewed -- LGTM! 👍

I didn't realize we could append additional metadata like this with the logger, really cool! While a bummer about the formatting, at least we have another tool in the toolbox for expanding the detail of logs and it'll work on cloud too! 🙂

[banderror]

Auto-backport hasn't been done for some reason. A manual one: #120200