diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts index 5a50ed815a842..b45c47a729df3 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/create_security_rule_type_wrapper.ts +++ b/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, diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/build_alert_group_from_sequence.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/build_alert_group_from_sequence.ts index 851635bf86bed..6522344945bca 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/build_alert_group_from_sequence.ts +++ b/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: [] }; } diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/eql.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/eql.ts index 87496501ce356..d4543d443ef76 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/eql/eql.ts +++ b/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); diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/esql/esql.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/esql/esql.ts index cd72345409595..58abb0f2647f3 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/esql/esql.ts +++ b/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; } diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/factories/bulk_create_factory.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/factories/bulk_create_factory.ts index 524671096230f..6604973aa08e1 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/factories/bulk_create_factory.ts +++ b/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 ({ }); 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 ({ 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, diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_event_signal.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_event_signal.ts index eeb79fdd24ee5..89349a9731aba 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_event_signal.ts +++ b/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; }; diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signal.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signal.ts index e5b20455e488f..d510e616c4e92 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signal.ts +++ b/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; } diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signals.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signals.ts index f04996132e0dc..57319972eac48 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/create_threat_signals.ts +++ b/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>(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,8 +379,8 @@ 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({ @@ -391,6 +388,6 @@ export const createThreatSignals = async ({ signalsCount: results.createdSignalsCount, responseActions: completeRule.ruleParams.responseActions, }); - ruleExecutionLogger.debug('Indicator matching rule has completed'); + ruleExecutionLogger.trace('Indicator matching rule has completed'); return results; }; diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_allowed_fields_for_terms_query.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_allowed_fields_for_terms_query.ts index 4e1c50c72745c..c7eef7e36eb79 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_allowed_fields_for_terms_query.ts +++ b/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; } diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_event_count.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_event_count.ts index 990620e47d841..28c080feb944c 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_event_count.ts +++ b/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; }; diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_threat_list.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_threat_list.ts index ac27cd185dd5a..d2c4b21a05bc5 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/indicator_match/threat_mapping/get_threat_list.ts +++ b/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); diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.test.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.test.ts index fedfec6707fdf..69e2a89a92184 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.test.ts +++ b/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); }); diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.ts index a38ea441c99f8..00f6770d26b73 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/ml/ml.ts @@ -81,19 +81,19 @@ export const mlExecutor = async ({ jobSummaries.some((job) => !isJobStarted(job.jobState, job.datafeedState)) ) { const warningMessage = [ - 'Machine learning job(s) are not started:', + 'ML jobs are not started', ...jobSummaries.map((job) => [ - `job id: "${job.id}"`, - `job name: "${job?.customSettings?.security_app_display_name ?? job.id}"`, - `job status: "${job.jobState}"`, - `datafeed status: "${job.datafeedState}"`, - ].join(', ') + `Job ID: "${job.id}"`, + `Job name: "${job?.customSettings?.security_app_display_name ?? job.id}"`, + `Job status: "${job.jobState}"`, + `Datafeed status: "${job.datafeedState}"`, + ].join('. ') ), - ].join(' '); + ].join('\n'); result.warningMessages.push(warningMessage); - ruleExecutionLogger.warn(warningMessage); + ruleExecutionLogger.debug(warningMessage); result.warning = true; } @@ -139,7 +139,7 @@ export const mlExecutor = async ({ const anomalyCount = filteredAnomalyHits.length; if (anomalyCount) { - ruleExecutionLogger.debug(`Found ${anomalyCount} signals from ML anomalies`); + ruleExecutionLogger.info(`Alerts from ML anomalies: ${anomalyCount}`); } if ( diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/new_terms/multi_terms_composite.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/new_terms/multi_terms_composite.ts index 7750daed86073..7b5e2fae86b44 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/new_terms/multi_terms_composite.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/new_terms/multi_terms_composite.ts @@ -284,8 +284,8 @@ export const multiTermsComposite = async ( } retryBatchSize = retryBatchSize / 2; - ruleExecutionLogger.warn( - `New terms query for multiple fields failed due to too many clauses in query: ${e.message}. Retrying #${retryCount} with ${retryBatchSize} for composite aggregation` + ruleExecutionLogger.debug( + `New terms query failed due to too many clauses\nError: ${e.message}. Retrying #${retryCount} with ${retryBatchSize} for composite aggregation.` ); throw e; } diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/query/alert_suppression/group_and_bulk_create.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/query/alert_suppression/group_and_bulk_create.ts index 4ce9fff66356a..500795e90d442 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/query/alert_suppression/group_and_bulk_create.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/query/alert_suppression/group_and_bulk_create.ts @@ -282,8 +282,8 @@ export const groupAndBulkCreate = async ({ ruleType: 'query', }); addToSearchAfterReturn({ current: toReturn, next: bulkCreateResult }); - sharedParams.ruleExecutionLogger.debug( - `created ${bulkCreateResult.createdItemsCount} signals` + sharedParams.ruleExecutionLogger.info( + `Alerts created: ${bulkCreateResult.createdItemsCount}` ); } else { const bulkCreateResult = await bulkCreate({ @@ -298,8 +298,8 @@ export const groupAndBulkCreate = async ({ suppressedItemsCount: getNumberOfSuppressedAlerts(bulkCreateResult.createdItems, []), }, }); - sharedParams.ruleExecutionLogger.debug( - `created ${bulkCreateResult.createdItemsCount} signals` + sharedParams.ruleExecutionLogger.info( + `Alerts created: ${bulkCreateResult.createdItemsCount}` ); } diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/bulk_create_with_suppression.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/bulk_create_with_suppression.ts index 2679f7bcf6d26..d8ef3eb59e925 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/bulk_create_with_suppression.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/bulk_create_with_suppression.ts @@ -83,7 +83,7 @@ export const bulkCreateWithSuppression = async < }); return enrichedAlerts; } catch (error) { - ruleExecutionLogger.error(`Alerts enrichment failed: ${error}`); + ruleExecutionLogger.error(`Error enriching alerts\nError: ${error}.`); throw error; } finally { enrichmentsTimeFinish = performance.now(); @@ -112,7 +112,7 @@ export const bulkCreateWithSuppression = async < const end = performance.now(); - ruleExecutionLogger.debug(`Alerts bulk process took ${makeFloatString(end - start)} ms`); + ruleExecutionLogger.debug(`Bulk processing alerts took ${makeFloatString(end - start)}ms.`); // query rule type suppression does not happen in memory, so we can't just count createdAlerts and suppressedAlerts // for this rule type we need to look into alerts suppression properties, extract those values and sum up @@ -124,7 +124,7 @@ export const bulkCreateWithSuppression = async < : suppressedAlerts.length; 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, diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/create_set_to_filter_against.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/create_set_to_filter_against.ts index e419d13589a57..e5b518a57d8e8 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/create_set_to_filter_against.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/create_set_to_filter_against.ts @@ -36,8 +36,8 @@ export const createSetToFilterAgainst = async ({ return acc; }, new Set()); - ruleExecutionLogger.debug( - `number of distinct values from ${field}: ${[...valuesFromSearchResultField].length}` + ruleExecutionLogger.trace( + `Distinct values from field: ${[...valuesFromSearchResultField].length}` ); const matchedListItems = await listClient.searchListItemByValues({ @@ -47,7 +47,7 @@ export const createSetToFilterAgainst = async ({ }); ruleExecutionLogger.debug( - `number of matched items from list with id ${listId}: ${matchedListItems.length}` + `Matched items from list: ${matchedListItems.length}\nList ID: "${listId}".` ); return new Set( diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.test.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.test.ts index d5c566383ebba..ea79ac5b00a42 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.test.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.test.ts @@ -62,7 +62,7 @@ describe('filterEventsAgainstList', () => { expect(included.length).toEqual(4); expect(excluded.length).toEqual(0); expect(ruleExecutionLogger.debug.mock.calls[0][0]).toContain( - 'No exception items of type list found - return unfiltered events' + 'No exception items of type list found' ); }); diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.ts index 8a8f7d34aa3a8..f8629d8ba000b 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/large_list_filters/filter_events_against_list.ts @@ -47,7 +47,9 @@ export const filterEventsAgainstList = async ({ ); if (!atLeastOneLargeValueList) { - ruleExecutionLogger.debug('No exception items of type list found - return unfiltered events'); + ruleExecutionLogger.debug( + 'No exception items of type list found\nReturning unfiltered events.' + ); return [events, []]; } @@ -74,7 +76,7 @@ export const filterEventsAgainstList = async ({ fieldAndSetTuples, }); ruleExecutionLogger.debug( - `Exception with id ${exceptionItem.id} filtered out ${nextExcludedEvents.length} events` + `Events filtered by exception: ${nextExcludedEvents.length}\nException ID: "${exceptionItem.id}".` ); return [nextIncludedEvents, [...excludedEvents, ...nextExcludedEvents]]; }, diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/log_shard_failure.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/log_shard_failure.ts index a5110f7ea11bb..b846467ad3381 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/log_shard_failure.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/log_shard_failure.ts @@ -20,7 +20,7 @@ export const logShardFailures = ( isSequenceQuery, JSON.stringify(shardFailures) ); - ruleExecutionLogger.error(shardFailureMessage); + ruleExecutionLogger.error(`Shard failure\nError: ${shardFailureMessage}`); if (isSequenceQuery) { result.errors.push(shardFailureMessage); } else { diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/search_after_bulk_create_factory.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/search_after_bulk_create_factory.ts index 14d6ec2931669..208cc7cfd72f7 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/search_after_bulk_create_factory.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/search_after_bulk_create_factory.ts @@ -97,10 +97,10 @@ export const searchAfterAndBulkCreateFactory = async ({ while (toReturn.createdSignalsCount <= maxSignals) { const cycleNum = `cycle ${searchingIteration++}`; try { - ruleExecutionLogger.debug( - `[${cycleNum}] Searching events${ - sortIds ? ` after cursor ${JSON.stringify(sortIds)}` : '' - } in index pattern "${inputIndexPattern}"` + ruleExecutionLogger.trace( + `${cycleNum}: Searching events\nSearching events after cursor ${JSON.stringify( + sortIds + )} in index pattern "${inputIndexPattern}".` ); const searchAfterQuery = buildEventsSearchQuery({ @@ -152,17 +152,17 @@ export const searchAfterAndBulkCreateFactory = async ({ ); if (totalHits === 0 || searchResult.hits.hits.length === 0) { - ruleExecutionLogger.debug( - `[${cycleNum}] Found 0 events ${ - sortIds ? ` after cursor ${JSON.stringify(sortIds)}` : '' - }` + ruleExecutionLogger.trace( + `${cycleNum}: No results found\nFound 0 events after cursor ${JSON.stringify(sortIds)}.` ); break; } else { - ruleExecutionLogger.debug( - `[${cycleNum}] Found ${searchResult.hits.hits.length} of total ${totalHits} events${ - sortIds ? ` after cursor ${JSON.stringify(sortIds)}` : '' - }, last cursor ${JSON.stringify(lastSortIds)}` + ruleExecutionLogger.trace( + `${cycleNum}: Results found\nFound ${ + searchResult.hits.hits.length + } of total ${totalHits} events after cursor ${JSON.stringify( + sortIds + )}. Last cursor: ${JSON.stringify(lastSortIds)}.` ); } @@ -187,8 +187,8 @@ export const searchAfterAndBulkCreateFactory = async ({ toReturn, }); - ruleExecutionLogger.debug( - `[${cycleNum}] Created ${bulkCreateResult.createdItemsCount} alerts from ${enrichedEvents.length} events` + ruleExecutionLogger.trace( + `${cycleNum}: Created alerts from enriched events\nCreated ${bulkCreateResult.createdItemsCount} alerts from ${enrichedEvents.length} events.` ); sendAlertTelemetryEvents( @@ -212,13 +212,14 @@ export const searchAfterAndBulkCreateFactory = async ({ if (lastSortIds != null && lastSortIds.length !== 0 && !hasNegativeNumber) { sortIds = lastSortIds; } else { - ruleExecutionLogger.debug(`[${cycleNum}] Unable to fetch last event cursor`); + ruleExecutionLogger.trace(`${cycleNum}: Failed to fetch last event cursor`); break; } } catch (exc: unknown) { ruleExecutionLogger.error( - 'Unable to extract/process events or create alerts', - JSON.stringify(exc) + `${cycleNum}: Error extracting/processing events or creating alerts\nError: ${JSON.stringify( + exc + )}` ); return mergeReturns([ toReturn, @@ -229,7 +230,7 @@ export const searchAfterAndBulkCreateFactory = async ({ ]); } } - ruleExecutionLogger.debug(`Completed bulk indexing of ${toReturn.createdSignalsCount} alert`); + ruleExecutionLogger.debug(`Alerts created: ${toReturn.createdSignalsCount}`); if (isLoggedRequestsEnabled) { toReturn.loggedRequests = loggedRequests; diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/send_telemetry_events.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/send_telemetry_events.ts index c3c4f8c4d5f23..6733556046dac 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/send_telemetry_events.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/send_telemetry_events.ts @@ -78,6 +78,6 @@ export function sendAlertTelemetryEvents( ); eventsTelemetry.sendAsync(TelemetryChannel.ENDPOINT_ALERTS, filtered); } catch (exc) { - ruleExecutionLogger.error(`Queuing telemetry events failed: ${exc}`); + ruleExecutionLogger.debug(`Error queuing telemetry events\nError: ${exc}`); } } diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/single_search_after.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/single_search_after.ts index 3bd45d5ab85e8..b1cb35418324e 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/single_search_after.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/single_search_after.ts @@ -73,7 +73,7 @@ export const singleSearchAfter = async < loggedRequests, }; } catch (exc) { - ruleExecutionLogger.error(`Searching events operation failed: ${exc}`); + ruleExecutionLogger.error(`Error searching events\nError: ${exc}`); throw exc; } }); diff --git a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/utils.ts b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/utils.ts index 6389df5b5eb4b..0bed3fa13d3d4 100644 --- a/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/utils.ts +++ b/x-pack/solutions/security/plugins/security_solution/server/lib/detection_engine/rule_types/utils/utils.ts @@ -434,7 +434,7 @@ export const getRuleRangeTuples = async ({ const intervalDuration = parseInterval(interval); if (intervalDuration == null) { ruleExecutionLogger.error( - `Failed to compute gap between rule runs: could not parse rule interval "${JSON.stringify( + `Error computing gap between rule runs\nError: could not parse rule interval "${JSON.stringify( interval )}"` );