Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -217,7 +217,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =

const refresh = isPreview ? false : true;

ruleExecutionLogger.debug(`Starting execution with interval: ${interval}`);
ruleExecutionLogger.debug(`Starting Security Rule execution (interval: ${interval})`);

await ruleExecutionLogger.logStatusChange({
newStatus: RuleExecutionStatusEnum.running,
Expand Down Expand Up @@ -279,13 +279,13 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
if (SavedObjectsErrorHelpers.isNotFoundError(exc)) {
await ruleExecutionLogger.logStatusChange({
newStatus: RuleExecutionStatusEnum.failed,
message: `Data view is not found.\nError: ${exc}`,
message: `Data View not found ${exc}`,
userError: true,
});
} else {
await ruleExecutionLogger.logStatusChange({
newStatus: RuleExecutionStatusEnum.failed,
message: `Check for indices to search failed.\nError: ${exc}`,
message: `Check for indices to search failed ${exc}`,
});
}

Expand Down Expand Up @@ -589,12 +589,12 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
});
} else if (!(result.warningMessages.length > 0) && !(wrapperWarnings.length > 0)) {
ruleExecutionLogger.debug('Security Rule execution completed');
ruleExecutionLogger.info(
`Alerts created: ${createdSignalsCount}\nFinished indexing ${createdSignalsCount} alerts into "${ruleDataClient.indexNameWithNamespace(
ruleExecutionLogger.debug(
`Finished 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)}`
: ''
}`
);
Expand All @@ -614,7 +614,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =

await ruleExecutionLogger.logStatusChange({
newStatus: RuleExecutionStatusEnum.failed,
message: `An error occurred during rule execution. ${errorMessage}`,
message: `An error occurred during rule execution: message: "${errorMessage}"`,
userError: checkErrorDetails(errorMessage).isUserError,
metrics: {
searchDurations: result.searchAfterTimes,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -106,7 +106,7 @@ export const buildAlertGroupFromSequence = ({
})
);
} catch (error) {
ruleExecutionLogger.debug(`Error building alert group from sequence\nError: ${error}`);
ruleExecutionLogger.error(error);
return { shellAlert: undefined, buildingBlocks: [] };
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -98,7 +98,7 @@ export const eqlExecutor = async ({
tiebreakerField: ruleParams.tiebreakerField,
});

ruleExecutionLogger.trace(`EQL query to execute\n${JSON.stringify(request)}`);
ruleExecutionLogger.debug(`EQL query request: ${JSON.stringify(request)}`);
const exceptionsWarning = getUnprocessedExceptionsWarnings(sharedParams.unprocessedExceptions);
if (exceptionsWarning) {
result.warningMessages.push(exceptionsWarning);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,7 @@ export const esqlExecutor = async ({
};
const hasLoggedRequestsReachedLimit = iteration >= 2;

ruleExecutionLogger.trace(`ES|QL query to execute\n${JSON.stringify(esqlRequest)}`);
ruleExecutionLogger.debug(`ES|QL query request: ${JSON.stringify(esqlRequest)}`);
const exceptionsWarning = getUnprocessedExceptionsWarnings(unprocessedExceptions);
if (exceptionsWarning) {
result.warningMessages.push(exceptionsWarning);
Expand All @@ -166,8 +166,8 @@ export const esqlExecutor = async ({
const esqlSearchDuration = performance.now() - esqlSignalSearchStart;
result.searchAfterTimes.push(makeFloatString(esqlSearchDuration));

ruleExecutionLogger.trace(
`ES|QL query iteration\nIteration: ${iteration}. Search took: ${esqlSearchDuration}ms.`
ruleExecutionLogger.debug(
`ES|QL query request for ${iteration} iteration took: ${esqlSearchDuration}ms`
);

const results = response.values.map((row) => rowToDocument(response.columns, row));
Expand Down Expand Up @@ -235,8 +235,8 @@ export const esqlExecutor = async ({
maxNumberOfAlertsMultiplier: 1,
});

ruleExecutionLogger.info(
`Alerts created: ${bulkCreateResult.createdItemsCount}. Alerts suppressed: ${bulkCreateResult.suppressedItemsCount}.`
ruleExecutionLogger.debug(
`Created ${bulkCreateResult.createdItemsCount} alerts. Suppressed ${bulkCreateResult.suppressedItemsCount} alerts`
);

updateExcludedDocuments({
Expand Down Expand Up @@ -268,7 +268,7 @@ export const esqlExecutor = async ({
});

addToSearchAfterReturn({ current: result, next: bulkCreateResult });
ruleExecutionLogger.info(`Alerts created: ${bulkCreateResult.createdItemsCount}.`);
ruleExecutionLogger.debug(`Created ${bulkCreateResult.createdItemsCount} alerts`);

updateExcludedDocuments({
excludedDocuments,
Expand All @@ -293,8 +293,8 @@ export const esqlExecutor = async ({

// no more results will be found
if (response.values.length < size) {
ruleExecutionLogger.trace(
`End of search. Found ${response.values.length} results\nPage size ${size}.`
ruleExecutionLogger.debug(
`End of search: Found ${response.values.length} results with page size ${size}`
);
break;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -71,7 +71,7 @@ export const bulkCreate = async <T extends DetectionAlertLatest>({
});
return enrichedAlerts;
} catch (error) {
ruleExecutionLogger.error(`Error enriching alerts\nError: ${error}`);
ruleExecutionLogger.error(`Alerts enrichment failed: ${error}`);
throw error;
} finally {
enrichmentsTimeFinish = performance.now();
Expand All @@ -91,10 +91,10 @@ export const bulkCreate = async <T extends DetectionAlertLatest>({

const end = performance.now();

ruleExecutionLogger.debug(`Bulk processing alerts took ${makeFloatString(end - start)}ms.`);
ruleExecutionLogger.debug(`Alerts bulk process took ${makeFloatString(end - start)} ms`);

if (!isEmpty(errors)) {
ruleExecutionLogger.warn(`Error bulk processing alerts\nError: ${JSON.stringify(errors)}`);
ruleExecutionLogger.warn(`Alerts bulk process finished with errors: ${JSON.stringify(errors)}`);
return {
errors: Object.keys(errors),
success: false,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -106,7 +106,7 @@ export const createEventSignal = async ({
loadFields: true,
});

ruleExecutionLogger.debug(`Matched signals found: ${ids?.length}`);
ruleExecutionLogger.debug(`${ids?.length} matched signals found`);

const enrichment = threatEnrichmentFactory({
signalIdToMatchedQueriesMap,
Expand Down Expand Up @@ -138,12 +138,12 @@ export const createEventSignal = async ({
} else {
createResult = await searchAfterAndBulkCreate(searchAfterBulkCreateParams);
}
ruleExecutionLogger.trace(
`Match checks completed\n${
ruleExecutionLogger.debug(
`${
currentEventList.length
} items have completed match checks. Search times (ms): ${
} items have completed match checks and the total times to search were ${
createResult.searchAfterTimes.length !== 0 ? createResult.searchAfterTimes : '(unknown) '
}.`
}ms`
);
return createResult;
};
Original file line number Diff line number Diff line change
Expand Up @@ -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.trace(
ruleExecutionLogger.debug(
'Indicator items are empty after filtering for missing data, returning without attempting a match'
);
return currentResult;
Expand All @@ -74,7 +74,7 @@ export const createThreatSignal = async ({
loadFields: true,
});

ruleExecutionLogger.trace(
ruleExecutionLogger.debug(
`${threatFilter.query?.bool.should.length} indicator items are being checked for existence of matches`
);

Expand Down Expand Up @@ -115,12 +115,12 @@ export const createThreatSignal = async ({
result = await searchAfterAndBulkCreate(searchAfterBulkCreateParams);
}

ruleExecutionLogger.trace(
`Match checks completed\n${
ruleExecutionLogger.debug(
`${
threatFilter.query?.bool.should.length
} items have completed match checks. Search times (ms): ${
} items have completed match checks and the total times to search were ${
result.searchAfterTimes.length !== 0 ? result.searchAfterTimes : '(unknown) '
}.`
}ms`
);
return result;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,7 @@ export const createThreatSignals = async ({
});

const params = completeRule.ruleParams;
ruleExecutionLogger.trace('Indicator matching rule starting');
ruleExecutionLogger.debug('Indicator matching rule starting');
const perPage = concurrentSearches * itemsPerSearch;
const verifyExecutionCanProceed = buildExecutionIntervalValidator(
completeRule.ruleConfig.schedule.interval
Expand Down Expand Up @@ -185,7 +185,7 @@ export const createThreatSignals = async ({
while (list.hits.hits.length !== 0) {
verifyExecutionCanProceed();
const chunks = chunk(chunkPage, list.hits.hits);
ruleExecutionLogger.trace(`${chunks.length} concurrent indicator searches are starting.`);
ruleExecutionLogger.debug(`${chunks.length} concurrent indicator searches are starting.`);
const concurrentSearchesPerformed =
chunks.map<Promise<SearchAfterAndBulkCreateReturnType>>(createSignal);
const searchesPerformed = await Promise.all(concurrentSearchesPerformed);
Expand All @@ -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.debug(
`Max clause count error received from Elasticsearch. Setting rule page size to ${maxClauseCountValue}.`
ruleExecutionLogger.warn(
`maxClauseCount error received from elasticsearch, setting IM rule page size to ${maxClauseCountValue}`
);

// only store results + errors that are not related to maxClauseCount
Expand All @@ -232,7 +232,10 @@ export const createThreatSignals = async ({
}
documentCount -= list.hits.hits.length;
ruleExecutionLogger.debug(
`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}.`
`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}`
);

// if alerts suppressed it means suppression enabled, so suppression alert limit should be applied (5 * max_signals)
Expand All @@ -243,7 +246,7 @@ export const createThreatSignals = async ({
results.warningMessages.push(getMaxSignalsWarning());
}
ruleExecutionLogger.debug(
`Max alerts per run reached\n${params.maxSignals}. Additional ${documentCount} documents are not checked.`
`Indicator match has reached its max signals count ${params.maxSignals}. Additional documents not checked are ${documentCount}`
);
break;
} else if (
Expand All @@ -254,15 +257,15 @@ export const createThreatSignals = async ({
) {
// warning should be already set
ruleExecutionLogger.debug(
`Max alerts per run reached\nIndicator match has reached its max signals count ${
`Indicator match has reached its max signals count ${
MAX_SIGNALS_SUPPRESSION_MULTIPLIER * params.maxSignals
}. Additional ${documentCount} documents are not checked.`
}. Additional documents not checked are ${documentCount}`
);
break;
}
ruleExecutionLogger.trace(`Documents items left to check: ${documentCount}`);
ruleExecutionLogger.debug(`Documents items left to check are ${documentCount}`);
if (maxClauseCountValue > Number.NEGATIVE_INFINITY) {
ruleExecutionLogger.trace(`Re-running search due to max clause count error`);
ruleExecutionLogger.debug(`Re-running search since we hit max clause count error`);

// re-run search with smaller max clause count;
list = await getDocumentList({ searchAfter: undefined });
Expand All @@ -277,8 +280,8 @@ export const createThreatSignals = async ({
const hasNegativeDateSort = sortIds?.some((val) => Number(val) < 0);

if (hasNegativeDateSort) {
ruleExecutionLogger.trace(
`Negative date sort ID encountered\nValue: ${sortIds}. Threat search stopped.`
ruleExecutionLogger.debug(
`Negative date sort id value encountered: ${sortIds}. Threat search stopped.`
);

break;
Expand Down Expand Up @@ -379,15 +382,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.debug(
`Error trying to close point in time\nPIT ID: "${threatPitId}". It will expire within "${THREAT_PIT_KEEP_ALIVE}". Error: "${error}".`
ruleExecutionLogger.warn(
`Error trying to close point in time: "${threatPitId}", it will expire within "${THREAT_PIT_KEEP_ALIVE}". Error is: "${error}"`
);
}
scheduleNotificationResponseActionsService({
signals: results.createdSignals,
signalsCount: results.createdSignalsCount,
responseActions: completeRule.ruleParams.responseActions,
});
ruleExecutionLogger.trace('Indicator matching rule has completed');
ruleExecutionLogger.debug('Indicator matching rule has completed');
return results;
};
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,7 @@ export const getAllowedFieldsForTermQuery = async ({
),
};
} catch (e) {
ruleExecutionLogger.debug(`Error getting allowed fields for the terms query\nError: ${e}`);
ruleExecutionLogger.debug(`Can't get allowed fields for terms query: ${e}`);
return allowedFieldsForTermsQuery;
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -40,8 +40,8 @@ export const getEventList = async ({
throw new TypeError('perPage cannot exceed the size of 10000');
}

ruleExecutionLogger.trace(
`Querying events\nIndex: "${sharedParams.inputIndex}", searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items.`
ruleExecutionLogger.debug(
`Querying the events items from the index: "${sharedParams.inputIndex}" with searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items`
);

const queryFilter = getQueryFilter({
Expand Down Expand Up @@ -75,7 +75,7 @@ export const getEventList = async ({
ruleExecutionLogger,
});

ruleExecutionLogger.debug(`Events retrieved: ${searchResult.hits.hits.length}`);
ruleExecutionLogger.debug(`Retrieved events items of size: ${searchResult.hits.hits.length}`);
return searchResult;
};

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -54,7 +54,7 @@ export const getThreatList = async ({
});

ruleExecutionLogger.debug(
`Querying indicator items\nIndex: "${threatIndex}", searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items.`
`Querying the indicator items from the index: "${threatIndex}" with searchAfter: "${searchAfter}" for up to ${calculatedPerPage} indicator items`
);

const response = await esClient.search<
Expand All @@ -74,7 +74,7 @@ export const getThreatList = async ({
pit: { id: pitId },
});

ruleExecutionLogger.debug(`Indicator items retrieved: ${response.hits.hits.length}`);
ruleExecutionLogger.debug(`Retrieved indicator items of size: ${response.hits.hits.length}`);

reassignPitId(response.pit_id);

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

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

Expand Down
Loading
Loading