[Security Solution] Adjust log level and wording of logs written from rule executors

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts

@@ -217,7 +217,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
 
           const refresh = isPreview ? false : true;
 
-          ruleExecutionLogger.debug(`Starting Security Rule execution (interval: ${interval})`);
+          ruleExecutionLogger.debug(`Starting execution with interval: ${interval}`);
 
           await ruleExecutionLogger.logStatusChange({
             newStatus: RuleExecutionStatusEnum.running,
@@ -279,13 +279,13 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
               if (SavedObjectsErrorHelpers.isNotFoundError(exc)) {
                 await ruleExecutionLogger.logStatusChange({
                   newStatus: RuleExecutionStatusEnum.failed,
-                  message: `Data View not found ${exc}`,
+                  message: `Data view is not found.\nError: ${exc}`,
                   userError: true,
                 });
               } else {
                 await ruleExecutionLogger.logStatusChange({
                   newStatus: RuleExecutionStatusEnum.failed,
-                  message: `Check for indices to search failed ${exc}`,
+                  message: `Check for indices to search failed.\nError: ${exc}`,
                 });
               }
 
@@ -589,12 +589,12 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
               });
             } else if (!(result.warningMessages.length > 0) && !(wrapperWarnings.length > 0)) {
               ruleExecutionLogger.debug('Security Rule execution completed');
-              ruleExecutionLogger.debug(
-                `Finished indexing ${createdSignalsCount} alerts into ${ruleDataClient.indexNameWithNamespace(
+              ruleExecutionLogger.info(
+                `Alerts created: ${createdSignalsCount}\nFinished indexing ${createdSignalsCount} alerts into "${ruleDataClient.indexNameWithNamespace(
                   spaceId
-                )} ${
+                )}".${
                   !isEmpty(tuples)
-                    ? `searched between date ranges ${JSON.stringify(tuples, null, 2)}`
+                    ? ` Searched between date ranges: ${JSON.stringify(tuples, null, 2)}.`
                     : ''
                 }`
               );
@@ -614,7 +614,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
 
             await ruleExecutionLogger.logStatusChange({
               newStatus: RuleExecutionStatusEnum.failed,
-              message: `An error occurred during rule execution: message: "${errorMessage}"`,
+              message: `An error occurred during rule execution. ${errorMessage}`,
               userError: checkErrorDetails(errorMessage).isUserError,
               metrics: {
                 searchDurations: result.searchAfterTimes,

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/build_alert_group_from_sequence.ts

@@ -106,7 +106,7 @@ export const buildAlertGroupFromSequence = ({
       })
     );
   } catch (error) {
-    ruleExecutionLogger.error(error);
+    ruleExecutionLogger.debug(`Error transforming matched events to alerts\nError: ${error}`);
     return { shellAlert: undefined, buildingBlocks: [] };
   }
 

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/eql.ts

@@ -98,7 +98,7 @@ export const eqlExecutor = async ({
       tiebreakerField: ruleParams.tiebreakerField,
     });
 
-    ruleExecutionLogger.debug(`EQL query request: ${JSON.stringify(request)}`);
+    ruleExecutionLogger.trace(`EQL query to execute\n${JSON.stringify(request)}`);
     const exceptionsWarning = getUnprocessedExceptionsWarnings(sharedParams.unprocessedExceptions);
     if (exceptionsWarning) {
       result.warningMessages.push(exceptionsWarning);

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/esql/esql.ts

@@ -145,7 +145,7 @@ export const esqlExecutor = async ({
         };
         const hasLoggedRequestsReachedLimit = iteration >= 2;
 
-        ruleExecutionLogger.debug(`ES|QL query request: ${JSON.stringify(esqlRequest)}`);
+        ruleExecutionLogger.trace(`ES|QL query to execute\n${JSON.stringify(esqlRequest)}`);
         const exceptionsWarning = getUnprocessedExceptionsWarnings(unprocessedExceptions);
         if (exceptionsWarning) {
           result.warningMessages.push(exceptionsWarning);
@@ -166,8 +166,8 @@ export const esqlExecutor = async ({
         const esqlSearchDuration = performance.now() - esqlSignalSearchStart;
         result.searchAfterTimes.push(makeFloatString(esqlSearchDuration));
 
-        ruleExecutionLogger.debug(
-          `ES|QL query request for ${iteration} iteration took: ${esqlSearchDuration}ms`
+        ruleExecutionLogger.trace(
+          `ES|QL query iteration\nIteration: ${iteration}. Search took: ${esqlSearchDuration}ms.`
         );
 
         const results = response.values.map((row) => rowToDocument(response.columns, row));
@@ -235,9 +235,8 @@ export const esqlExecutor = async ({
             maxNumberOfAlertsMultiplier: 1,
           });
 
-          ruleExecutionLogger.debug(
-            `Created ${bulkCreateResult.createdItemsCount} alerts. Suppressed ${bulkCreateResult.suppressedItemsCount} alerts`
-          );
+          ruleExecutionLogger.info(`Alerts created: ${bulkCreateResult.createdItemsCount}`);
+          ruleExecutionLogger.info(`Alerts suppressed: ${bulkCreateResult.suppressedItemsCount}`);
 
           updateExcludedDocuments({
             excludedDocuments,
@@ -268,7 +267,7 @@ export const esqlExecutor = async ({
           });
 
           addToSearchAfterReturn({ current: result, next: bulkCreateResult });
-          ruleExecutionLogger.debug(`Created ${bulkCreateResult.createdItemsCount} alerts`);
+          ruleExecutionLogger.info(`Alerts created: ${bulkCreateResult.createdItemsCount}`);
 
           updateExcludedDocuments({
             excludedDocuments,
@@ -293,8 +292,8 @@ export const esqlExecutor = async ({
 
         // no more results will be found
         if (response.values.length < size) {
-          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}.`
           );
           break;
         }

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/factories/bulk_create_factory.ts

@@ -71,7 +71,7 @@ export const bulkCreate = async <T extends DetectionAlertLatest>({
       });
       return enrichedAlerts;
     } catch (error) {
-      ruleExecutionLogger.error(`Alerts enrichment failed: ${error}`);
+      ruleExecutionLogger.error(`Error enriching alerts\nError: ${error}`);
       throw error;
     } finally {
       enrichmentsTimeFinish = performance.now();
@@ -91,10 +91,10 @@ export const bulkCreate = async <T extends DetectionAlertLatest>({
 
   const end = performance.now();
 
-  ruleExecutionLogger.debug(`Alerts bulk process took ${makeFloatString(end - start)} ms`);
+  ruleExecutionLogger.debug(`Bulk processing alerts took ${makeFloatString(end - start)}ms.`);
 
   if (!isEmpty(errors)) {
-    ruleExecutionLogger.warn(`Alerts bulk process finished with errors: ${JSON.stringify(errors)}`);
+    ruleExecutionLogger.warn(`Error bulk processing alerts\nError: ${JSON.stringify(errors)}`);
     return {
       errors: Object.keys(errors),
       success: false,

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_event_signal.ts

@@ -106,7 +106,7 @@ export const createEventSignal = async ({
     loadFields: true,
   });
 
-  ruleExecutionLogger.debug(`${ids?.length} matched signals found`);
+  ruleExecutionLogger.debug(`Matched events found: ${ids?.length}`);
 
   const enrichment = threatEnrichmentFactory({
     signalIdToMatchedQueriesMap,
@@ -138,12 +138,12 @@ export const createEventSignal = async ({
   } else {
     createResult = await searchAfterAndBulkCreate(searchAfterBulkCreateParams);
   }
-  ruleExecutionLogger.debug(
-    `${
+  ruleExecutionLogger.trace(
+    `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): ${
       createResult.searchAfterTimes.length !== 0 ? createResult.searchAfterTimes : '(unknown) '
-    }ms`
+    }.`
   );
   return createResult;
 };

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signal.ts

@@ -56,7 +56,7 @@ export const createThreatSignal = async ({
   if (!threatFilter.query || threatFilter.query?.bool.should.length === 0) {
     // empty threat list and we do not want to return everything as being
     // a hit so opt to return the existing result.
-    ruleExecutionLogger.debug(
+    ruleExecutionLogger.trace(
       'Indicator items are empty after filtering for missing data, returning without attempting a match'
     );
     return currentResult;
@@ -74,7 +74,7 @@ export const createThreatSignal = async ({
       loadFields: true,
     });
 
-    ruleExecutionLogger.debug(
+    ruleExecutionLogger.trace(
       `${threatFilter.query?.bool.should.length} indicator items are being checked for existence of matches`
     );
 
@@ -115,12 +115,12 @@ export const createThreatSignal = async ({
       result = await searchAfterAndBulkCreate(searchAfterBulkCreateParams);
     }
 
-    ruleExecutionLogger.debug(
-      `${
+    ruleExecutionLogger.trace(
+      `Match checks completed\n${
         threatFilter.query?.bool.should.length
-      } items have completed match checks and the total times to search were ${
+      } items have completed match checks. Search times (ms): ${
         result.searchAfterTimes.length !== 0 ? result.searchAfterTimes : '(unknown) '
-      }ms`
+      }.`
     );
     return result;
   }

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signals.ts

@@ -77,7 +77,7 @@ export const createThreatSignals = async ({
   });
 
   const params = completeRule.ruleParams;
-  ruleExecutionLogger.debug('Indicator matching rule starting');
+  ruleExecutionLogger.trace('Indicator matching rule starting');
   const perPage = concurrentSearches * itemsPerSearch;
   const verifyExecutionCanProceed = buildExecutionIntervalValidator(
     completeRule.ruleConfig.schedule.interval
@@ -185,7 +185,7 @@ export const createThreatSignals = async ({
     while (list.hits.hits.length !== 0) {
       verifyExecutionCanProceed();
       const chunks = chunk(chunkPage, list.hits.hits);
-      ruleExecutionLogger.debug(`${chunks.length} concurrent indicator searches are starting.`);
+      ruleExecutionLogger.trace(`${chunks.length} concurrent indicator searches are starting.`);
       const concurrentSearchesPerformed =
         chunks.map<Promise<SearchAfterAndBulkCreateReturnType>>(createSignal);
       const searchesPerformed = await Promise.all(concurrentSearchesPerformed);
@@ -205,8 +205,8 @@ export const createThreatSignals = async ({
         // allowed by elasticsearch. The sliced chunk is used in createSignal to generate
         // threat filters.
         chunkPage = maxClauseCountValue;
-        ruleExecutionLogger.warn(
-          `maxClauseCount error received from elasticsearch, setting IM rule page size to ${maxClauseCountValue}`
+        ruleExecutionLogger.debug(
+          `Max clause count error received from Elasticsearch. Setting rule page size to ${maxClauseCountValue}.`
         );
 
         // only store results + errors that are not related to maxClauseCount
@@ -231,11 +231,8 @@ export const createThreatSignals = async ({
         results = combineConcurrentResults(results, searchesPerformed);
       }
       documentCount -= list.hits.hits.length;
-      ruleExecutionLogger.debug(
-        `Concurrent indicator match searches completed with ${results.createdSignalsCount} signals found`,
-        `search times of ${results.searchAfterTimes}ms,`,
-        `bulk create times ${results.bulkCreateTimes}ms,`,
-        `all successes are ${results.success}`
+      ruleExecutionLogger.trace(
+        `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}.`
       );
 
       // if alerts suppressed it means suppression enabled, so suppression alert limit should be applied (5 * max_signals)
@@ -246,7 +243,7 @@ export const createThreatSignals = async ({
           results.warningMessages.push(getMaxSignalsWarning());
         }
         ruleExecutionLogger.debug(
-          `Indicator match has reached its max signals count ${params.maxSignals}. Additional documents not checked are ${documentCount}`
+          `Max alerts per run reached\n${params.maxSignals}. Additional ${documentCount} documents are not checked.`
         );
         break;
       } else if (
@@ -257,15 +254,15 @@ export const createThreatSignals = async ({
       ) {
         // 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 alerts count ${
             MAX_SIGNALS_SUPPRESSION_MULTIPLIER * params.maxSignals
-          }. Additional documents not checked are ${documentCount}`
+          }. Additional ${documentCount} documents are not checked.`
         );
         break;
       }
-      ruleExecutionLogger.debug(`Documents items left to check are ${documentCount}`);
+      ruleExecutionLogger.trace(`Documents items left to check: ${documentCount}`);
       if (maxClauseCountValue > Number.NEGATIVE_INFINITY) {
-        ruleExecutionLogger.debug(`Re-running search since we hit max clause count error`);
+        ruleExecutionLogger.trace(`Re-running search due to max clause count error`);
 
         // re-run search with smaller max clause count;
         list = await getDocumentList({ searchAfter: undefined });
@@ -280,8 +277,8 @@ export const createThreatSignals = async ({
         const hasNegativeDateSort = sortIds?.some((val) => Number(val) < 0);
 
         if (hasNegativeDateSort) {
-          ruleExecutionLogger.debug(
-            `Negative date sort id value encountered: ${sortIds}. Threat search stopped.`
+          ruleExecutionLogger.trace(
+            `Negative date sort ID encountered\nValue: ${sortIds}. Threat search stopped.`
           );
 
           break;
@@ -382,15 +379,15 @@ export const createThreatSignals = async ({
     await services.scopedClusterClient.asCurrentUser.closePointInTime({ id: threatPitId });
   } catch (error) {
     // Don't fail due to a bad point in time closure. We have seen failures in e2e tests during nominal operations.
-    ruleExecutionLogger.warn(
-      `Error trying to close point in time: "${threatPitId}", it will expire within "${THREAT_PIT_KEEP_ALIVE}". Error is: "${error}"`
+    ruleExecutionLogger.debug(
+      `Error trying to close point in time\nPIT ID: "${threatPitId}". It will expire within "${THREAT_PIT_KEEP_ALIVE}". Error: "${error}".`
     );
   }
   scheduleNotificationResponseActionsService({
     signals: results.createdSignals,
     signalsCount: results.createdSignalsCount,
     responseActions: completeRule.ruleParams.responseActions,
   });
-  ruleExecutionLogger.debug('Indicator matching rule has completed');
+  ruleExecutionLogger.trace('Indicator matching rule has completed');
   return results;
 };

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_allowed_fields_for_terms_query.ts

@@ -69,7 +69,7 @@ export const getAllowedFieldsForTermQuery = async ({
       ),
     };
   } catch (e) {
-    ruleExecutionLogger.debug(`Can't get allowed fields for terms query: ${e}`);
+    ruleExecutionLogger.debug(`Error getting allowed fields for the terms query\nError: ${e}`);
     return allowedFieldsForTermsQuery;
   }
 

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_event_count.ts

@@ -40,8 +40,8 @@ export const getEventList = async ({
     throw new TypeError('perPage cannot exceed the size of 10000');
   }
 
-  ruleExecutionLogger.debug(
-    `Querying the events items from the index: "${sharedParams.inputIndex}" with searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items`
+  ruleExecutionLogger.trace(
+    `Querying events\nIndex: "${sharedParams.inputIndex}", searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items.`
   );
 
   const queryFilter = getQueryFilter({
@@ -75,7 +75,7 @@ export const getEventList = async ({
     ruleExecutionLogger,
   });
 
-  ruleExecutionLogger.debug(`Retrieved events items of size: ${searchResult.hits.hits.length}`);
+  ruleExecutionLogger.debug(`Events retrieved: ${searchResult.hits.hits.length}`);
   return searchResult;
 };
 

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_threat_list.ts

@@ -54,7 +54,7 @@ export const getThreatList = async ({
   });
 
   ruleExecutionLogger.debug(
-    `Querying the indicator items from the index: "${threatIndex}" with searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items`
+    `Querying indicator items\nIndex: "${threatIndex}", searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items.`
   );
 
   const response = await esClient.search<
@@ -74,7 +74,7 @@ export const getThreatList = async ({
     pit: { id: pitId },
   });
 
-  ruleExecutionLogger.debug(`Retrieved indicator items of size: ${response.hits.hits.length}`);
+  ruleExecutionLogger.debug(`Indicator items retrieved: ${response.hits.hits.length}`);
 
   reassignPitId(response.pit_id);
 

x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.test.ts

@@ -98,10 +98,8 @@ describe('ml_executor', () => {
       isAlertSuppressionActive: true,
       scheduleNotificationResponseActionsService: mockScheduledNotificationResponseAction,
     });
-    expect(ruleExecutionLogger.warn).toHaveBeenCalled();
-    expect(ruleExecutionLogger.warn.mock.calls[0][0]).toContain(
-      'Machine learning job(s) are not started'
-    );
+    expect(ruleExecutionLogger.debug).toHaveBeenCalled();
+    expect(ruleExecutionLogger.debug.mock.calls[0][0]).toContain('ML jobs are not started');
     expect(result.warningMessages.length).toEqual(1);
   });
 
@@ -122,10 +120,8 @@ describe('ml_executor', () => {
       isAlertSuppressionActive: true,
       scheduleNotificationResponseActionsService: mockScheduledNotificationResponseAction,
     });
-    expect(ruleExecutionLogger.warn).toHaveBeenCalled();
-    expect(ruleExecutionLogger.warn.mock.calls[0][0]).toContain(
-      'Machine learning job(s) are not started'
-    );
+    expect(ruleExecutionLogger.debug).toHaveBeenCalled();
+    expect(ruleExecutionLogger.debug.mock.calls[0][0]).toContain('ML jobs are not started');
     expect(result.warningMessages.length).toEqual(1);
   });