Add enrichment event log time (#141433) (#142079)

* Add enrichment event log time * fix types * Fix test * Add avg field * Fix enrichments event log * Add telemetry * Update schema Co-authored-by: Kibana Machine <[email protected]> (cherry picked from commit 5f057ff) Co-authored-by: Khristinin Nikita <[email protected]>
elastic · Sep 29, 2022 · 069c122 · 069c122
1 parent 60b55b6
commit 069c122
Show file tree

Hide file tree

Showing 30 changed files with 1,394 additions and 37 deletions.
diff --git a/x-pack/plugins/event_log/README.md b/x-pack/plugins/event_log/README.md
@@ -159,6 +159,7 @@ Below is a document in the expected structure, with descriptions of the fields:
             es_search_duration_ms: "total time spent performing ES searches as measured by Elasticsearch",
             total_search_duration_ms: "total time spent performing ES searches as measured by Kibana; includes network latency and time spent serializing/deserializing request/response",
             total_indexing_duration_ms: "total time spent indexing documents during current rule execution cycle",
+            total_enrichment_duration_ms: "total time spent enriching documents during current rule execution cycle",
             execution_gap_duration_s: "duration in seconds of execution gap"
           }
         }

diff --git a/x-pack/plugins/event_log/generated/mappings.json b/x-pack/plugins/event_log/generated/mappings.json
@@ -347,6 +347,9 @@
                                                 },
                                                 "total_run_duration_ms": {
                                                     "type": "long"
+                                                },
+                                                "total_enrichment_duration_ms": {
+                                                    "type": "long"
                                                 }
                                             }
                                         }

diff --git a/x-pack/plugins/event_log/generated/schemas.ts b/x-pack/plugins/event_log/generated/schemas.ts
@@ -150,6 +150,7 @@ export const EventSchema = schema.maybe(
                         claim_to_start_duration_ms: ecsStringOrNumber(),
                         prepare_rule_duration_ms: ecsStringOrNumber(),
                         total_run_duration_ms: ecsStringOrNumber(),
+                        total_enrichment_duration_ms: ecsStringOrNumber(),
                       })
                     ),
                   })

diff --git a/x-pack/plugins/event_log/scripts/mappings.js b/x-pack/plugins/event_log/scripts/mappings.js
@@ -130,6 +130,9 @@ exports.EcsCustomPropertyMappings = {
                       total_run_duration_ms: {
                         type: 'long',
                       },
+                      total_enrichment_duration_ms: {
+                        type: 'long',
+                      },
                     },
                   },
                 },

diff --git a/...gins/security_solution/common/detection_engine/rule_monitoring/model/execution_metrics.ts b/...gins/security_solution/common/detection_engine/rule_monitoring/model/execution_metrics.ts
@@ -12,8 +12,17 @@ export type DurationMetric = t.TypeOf<typeof DurationMetric>;
 export const DurationMetric = PositiveInteger;
 
 export type RuleExecutionMetrics = t.TypeOf<typeof RuleExecutionMetrics>;
+
+/**
+  @property total_search_duration_ms - "total time spent performing ES searches as measured by Kibana; 
+  includes network latency and time spent serializing/deserializing request/response",
+  @property total_indexing_duration_ms - "total time spent indexing documents during current rule execution cycle",
+  @property total_enrichment_duration_ms - total time spent enriching documents during current rule execution cycle
+  @property execution_gap_duration_s - "duration in seconds of execution gap"
+*/
 export const RuleExecutionMetrics = t.partial({
   total_search_duration_ms: DurationMetric,
   total_indexing_duration_ms: DurationMetric,
+  total_enrichment_duration_ms: DurationMetric,
   execution_gap_duration_s: DurationMetric,
 });
diff --git a/.../detection_engine/rule_monitoring/logic/rule_execution_log/client_for_executors/client.ts b/.../detection_engine/rule_monitoring/logic/rule_execution_log/client_for_executors/client.ts
@@ -222,6 +222,7 @@ const normalizeStatusChangeArgs = (args: StatusChangeArgs): NormalizedStatusChan
       ? {
           total_search_duration_ms: normalizeDurations(metrics.searchDurations),
           total_indexing_duration_ms: normalizeDurations(metrics.indexingDurations),
+          total_enrichment_duration_ms: normalizeDurations(metrics.enrichmentDurations),
           execution_gap_duration_s: normalizeGap(metrics.executionGap),
         }
       : undefined,

diff --git a/..._engine/rule_monitoring/logic/rule_execution_log/client_for_executors/client_interface.ts b/..._engine/rule_monitoring/logic/rule_execution_log/client_for_executors/client_interface.ts
@@ -115,5 +115,6 @@ export interface StatusChangeArgs {
 export interface MetricsArgs {
   searchDurations?: string[];
   indexingDurations?: string[];
+  enrichmentDurations?: string[];
   executionGap?: Duration;
 }
diff --git a/...ine/rule_monitoring/logic/rule_execution_log/execution_saved_object/saved_objects_type.ts b/...ine/rule_monitoring/logic/rule_execution_log/execution_saved_object/saved_objects_type.ts
@@ -58,6 +58,9 @@ const ruleExecutionMappings: SavedObjectsType['mappings'] = {
             total_indexing_duration_ms: {
               type: 'long',
             },
+            total_enrichment_duration_ms: {
+              type: 'long',
+            },
             execution_gap_duration_s: {
               type: 'long',
             },

diff --git a/...rity_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts b/...rity_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts
@@ -343,6 +343,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
                 const warningMessages = result.warningMessages.concat(runResult.warningMessages);
                 result = {
                   bulkCreateTimes: result.bulkCreateTimes.concat(runResult.bulkCreateTimes),
+                  enrichmentTimes: result.enrichmentTimes.concat(runResult.enrichmentTimes),
                   createdSignals,
                   createdSignalsCount: createdSignals.length,
                   errors: result.errors.concat(runResult.errors),
@@ -358,6 +359,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
             } else {
               result = {
                 bulkCreateTimes: [],
+                enrichmentTimes: [],
                 createdSignals: [],
                 createdSignalsCount: 0,
                 errors: [],
@@ -434,6 +436,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
                   metrics: {
                     searchDurations: result.searchAfterTimes,
                     indexingDurations: result.bulkCreateTimes,
+                    enrichmentDurations: result.enrichmentTimes,
                   },
                 });
               }
@@ -452,6 +455,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
                 metrics: {
                   searchDurations: result.searchAfterTimes,
                   indexingDurations: result.bulkCreateTimes,
+                  enrichmentDurations: result.enrichmentTimes,
                 },
               });
             }
@@ -464,6 +468,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
               metrics: {
                 searchDurations: result.searchAfterTimes,
                 indexingDurations: result.bulkCreateTimes,
+                enrichmentDurations: result.enrichmentTimes,
               },
             });
 

diff --git a/...security_solution/server/lib/detection_engine/rule_types/factories/bulk_create_factory.ts b/...security_solution/server/lib/detection_engine/rule_types/factories/bulk_create_factory.ts
@@ -21,6 +21,7 @@ import type {
 export interface GenericBulkCreateResponse<T extends BaseFieldsLatest> {
   success: boolean;
   bulkCreateDuration: string;
+  enrichmentDuration: string;
   createdItemsCount: number;
   createdItems: Array<AlertWithCommonFieldsLatest<T> & { _id: string; _index: string }>;
   errors: string[];
@@ -45,6 +46,7 @@ export const bulkCreateFactory =
       return {
         errors: [],
         success: true,
+        enrichmentDuration: '0',
         bulkCreateDuration: '0',
         createdItemsCount: 0,
         createdItems: [],
@@ -54,6 +56,24 @@ export const bulkCreateFactory =
 
     const start = performance.now();
 
+    let enrichmentsTimeStart = 0;
+    let enrichmentsTimeFinish = 0;
+    let enrichAlertsWrapper: typeof enrichAlerts;
+    if (enrichAlerts) {
+      enrichAlertsWrapper = async (alerts, params) => {
+        enrichmentsTimeStart = performance.now();
+        try {
+          const enrichedAlerts = await enrichAlerts(alerts, params);
+          return enrichedAlerts;
+        } catch (error) {
+          ruleExecutionLogger.error(`Enrichments failed ${error}`);
+          throw error;
+        } finally {
+          enrichmentsTimeFinish = performance.now();
+        }
+      };
+    }
+
     const { createdAlerts, errors, alertsWereTruncated } = await alertWithPersistence(
       wrappedDocs.map((doc) => ({
         _id: doc._id,
@@ -62,7 +82,7 @@ export const bulkCreateFactory =
       })),
       refreshForBulkCreate,
       maxAlerts,
-      enrichAlerts
+      enrichAlertsWrapper
     );
 
     const end = performance.now();
@@ -78,6 +98,7 @@ export const bulkCreateFactory =
       return {
         errors: Object.keys(errors),
         success: false,
+        enrichmentDuration: makeFloatString(enrichmentsTimeFinish - enrichmentsTimeStart),
         bulkCreateDuration: makeFloatString(end - start),
         createdItemsCount: createdAlerts.length,
         createdItems: createdAlerts,
@@ -88,6 +109,7 @@ export const bulkCreateFactory =
         errors: [],
         success: true,
         bulkCreateDuration: makeFloatString(end - start),
+        enrichmentDuration: makeFloatString(enrichmentsTimeFinish - enrichmentsTimeStart),
         createdItemsCount: createdAlerts.length,
         createdItems: createdAlerts,
         alertsWereTruncated,

diff --git a/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/types.ts b/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/types.ts
@@ -42,6 +42,7 @@ import type { IRuleExecutionLogForExecutors, IRuleExecutionLogService } from '..
 
 export interface SecurityAlertTypeReturnValue<TState extends RuleTypeState> {
   bulkCreateTimes: string[];
+  enrichmentTimes: string[];
   createdSignalsCount: number;
   createdSignals: unknown[];
   errors: string[];

diff --git a/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/utils/index.ts b/x-pack/plugins/security_solution/server/lib/detection_engine/rule_types/utils/index.ts
@@ -10,6 +10,7 @@ import type { SecurityAlertTypeReturnValue } from '../types';
 
 export const createResultObject = <TState extends RuleTypeState>(state: TState) => {
   const result: SecurityAlertTypeReturnValue<TState> = {
+    enrichmentTimes: [],
     bulkCreateTimes: [],
     createdSignalsCount: 0,
     createdSignals: [],

diff --git a/...rity_solution/server/lib/detection_engine/signals/threat_mapping/create_threat_signals.ts b/...rity_solution/server/lib/detection_engine/signals/threat_mapping/create_threat_signals.ts
@@ -65,6 +65,7 @@ export const createThreatSignals = async ({
   let results: SearchAfterAndBulkCreateReturnType = {
     success: true,
     warning: false,
+    enrichmentTimes: [],
     bulkCreateTimes: [],
     searchAfterTimes: [],
     lastLookBackDate: null,