[Security Solution] Improve rule execution logging (#166070)

**Relates to:** https://github.com/elastic/kibana/pull/126063

## Summary

This PR extends rule event log's filter and improves log messages.

## Details

We have Rule execution log feature hidden by a feature flag and disabled, it's shown on a rule details page when enabled.

<img width="1782" alt="image" src="71565d96-13aa-4275-b870-22118ac90335">

The feature is close to a releasable state but some tasks had to be addressed to make it usable. This PR addresses the following tasks to make rule execution log feature releasable

- Adds search bar to search for specific messages

<img width="1529" alt="image" src="4bd198de-60e8-4511-a96d-4d68ec53a7f2">

- Adds a date range filter by default set to show logs for last 24 hours

<img width="1529" alt="image" src="b9d7e658-a19a-402a-a039-28d225000952">

- Improves error, warning and debug messages
- Returns rule metrics in a message as a serialized JSON

<img width="1526" alt="image" src="7d9501b9-4a12-4d31-be99-6ce3c04b2b97">

- Adds `execution_id` to the response

<img width="1522" alt="image" src="92d1291e-0605-456c-abca-8c6fd329ade2">

### Tasks to address later

- [ ] Further improve logging messages. We have either error, warning or debug messages. In fact info or trace levels aren't used but it can give useful info.
- [ ] Add an OpenAPI spec for the rule execution log endpoint
This commit is contained in:
Maxim Palenov 2023-09-18 17:20:59 -07:00 committed by GitHub
parent a7e196d2a4
commit 6a96906f26
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
35 changed files with 398 additions and 132 deletions

View file

@ -18,8 +18,9 @@ const getMessageEvent = (props: Partial<RuleExecutionEvent> = {}): RuleExecution
timestamp: DEFAULT_TIMESTAMP,
sequence: DEFAULT_SEQUENCE_NUMBER,
level: LogLevel.debug,
execution_id: 'execution-id-1',
message: 'Some message',
// Overriden values
// Overridden values
...props,
// Mandatory values for this type of event
type: RuleExecutionEventType.message,
@ -31,8 +32,9 @@ const getRunningStatusChange = (props: Partial<RuleExecutionEvent> = {}): RuleEx
// Default values
timestamp: DEFAULT_TIMESTAMP,
sequence: DEFAULT_SEQUENCE_NUMBER,
execution_id: 'execution-id-1',
message: 'Rule changed status to "running"',
// Overriden values
// Overridden values
...props,
// Mandatory values for this type of event
level: LogLevel.info,
@ -47,8 +49,9 @@ const getPartialFailureStatusChange = (
// Default values
timestamp: DEFAULT_TIMESTAMP,
sequence: DEFAULT_SEQUENCE_NUMBER,
execution_id: 'execution-id-1',
message: 'Rule changed status to "partial failure". Unknown error',
// Overriden values
// Overridden values
...props,
// Mandatory values for this type of event
level: LogLevel.warn,
@ -61,8 +64,9 @@ const getFailedStatusChange = (props: Partial<RuleExecutionEvent> = {}): RuleExe
// Default values
timestamp: DEFAULT_TIMESTAMP,
sequence: DEFAULT_SEQUENCE_NUMBER,
execution_id: 'execution-id-1',
message: 'Rule changed status to "failed". Unknown error',
// Overriden values
// Overridden values
...props,
// Mandatory values for this type of event
level: LogLevel.error,
@ -75,8 +79,9 @@ const getSucceededStatusChange = (props: Partial<RuleExecutionEvent> = {}): Rule
// Default values
timestamp: DEFAULT_TIMESTAMP,
sequence: DEFAULT_SEQUENCE_NUMBER,
execution_id: 'execution-id-1',
message: 'Rule changed status to "succeeded". Rule executed successfully',
// Overriden values
// Overridden values
...props,
// Mandatory values for this type of event
level: LogLevel.info,
@ -89,8 +94,9 @@ const getExecutionMetricsEvent = (props: Partial<RuleExecutionEvent> = {}): Rule
// Default values
timestamp: DEFAULT_TIMESTAMP,
sequence: DEFAULT_SEQUENCE_NUMBER,
message: '',
// Overriden values
execution_id: 'execution-id-1',
message: JSON.stringify({ some_metric_ms: 10 }),
// Overridden values
...props,
// Mandatory values for this type of event
level: LogLevel.debug,

View file

@ -6,7 +6,7 @@
*/
import * as t from 'io-ts';
import { enumeration, IsoDateString } from '@kbn/securitysolution-io-ts-types';
import { enumeration, IsoDateString, NonEmptyString } from '@kbn/securitysolution-io-ts-types';
import { enumFromString } from '../../../../utils/enum_from_string';
import { TLogLevel } from './log_level';
@ -56,5 +56,6 @@ export const RuleExecutionEvent = t.type({
sequence: t.number,
level: TLogLevel,
type: TRuleExecutionEventType,
execution_id: NonEmptyString,
message: t.string,
});

View file

@ -8,7 +8,7 @@
import * as t from 'io-ts';
import { DefaultPerPage, DefaultPage } from '@kbn/securitysolution-io-ts-alerting-types';
import { defaultCsvArray, NonEmptyString } from '@kbn/securitysolution-io-ts-types';
import { defaultCsvArray, IsoDateString, NonEmptyString } from '@kbn/securitysolution-io-ts-types';
import { DefaultSortOrderDesc, PaginationResult } from '../../../model';
import { RuleExecutionEvent, TRuleExecutionEventType, TLogLevel } from '../../model';
@ -32,13 +32,20 @@ export type GetRuleExecutionEventsRequestQuery = t.TypeOf<
typeof GetRuleExecutionEventsRequestQuery
>;
export const GetRuleExecutionEventsRequestQuery = t.exact(
t.type({
event_types: defaultCsvArray(TRuleExecutionEventType),
log_levels: defaultCsvArray(TLogLevel),
sort_order: DefaultSortOrderDesc, // defaults to 'desc'
page: DefaultPage, // defaults to 1
per_page: DefaultPerPage, // defaults to 20
})
t.intersection([
t.partial({
search_term: NonEmptyString,
event_types: defaultCsvArray(TRuleExecutionEventType),
log_levels: defaultCsvArray(TLogLevel),
date_start: IsoDateString,
date_end: IsoDateString,
}),
t.type({
sort_order: DefaultSortOrderDesc, // defaults to 'desc'
page: DefaultPage, // defaults to 1
per_page: DefaultPerPage, // defaults to 20
}),
])
);
/**

View file

@ -32,6 +32,7 @@ export const api: jest.Mocked<IRuleMonitoringApiClient> = {
sequence: 0,
level: LogLevel.info,
type: RuleExecutionEventType['status-change'],
execution_id: 'execution-id-1',
message: 'Rule changed status to "succeeded". Rule execution completed without errors',
},
],

View file

@ -72,14 +72,51 @@ describe('Rule Monitoring API Client', () => {
);
});
it('calls API correctly with filter and pagination options', async () => {
const ISO_PATTERN = /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$/;
it.each([
[
'search term filter',
{ searchTerm: 'something to search' },
{ search_term: 'something to search' },
],
[
'event types filter',
{ eventTypes: [RuleExecutionEventType.message] },
{ event_types: 'message' },
],
[
'log level filter',
{ logLevels: [LogLevel.warn, LogLevel.error] },
{ log_levels: 'warn,error' },
],
[
'start date filter in relative format',
{ dateRange: { start: 'now-1d/d' } },
{ date_start: expect.stringMatching(ISO_PATTERN) },
],
[
'end date filter',
{ dateRange: { end: 'now-3d/d' } },
{ date_end: expect.stringMatching(ISO_PATTERN) },
],
[
'date range filter in relative format',
{ dateRange: { start: new Date().toISOString(), end: new Date().toISOString() } },
{
date_start: expect.stringMatching(ISO_PATTERN),
date_end: expect.stringMatching(ISO_PATTERN),
},
],
[
'pagination',
{ sortOrder: 'asc', page: 42, perPage: 146 } as const,
{ sort_order: 'asc', page: 42, per_page: 146 },
],
])('calls API correctly with %s', async (_, params, expectedParams) => {
await api.fetchRuleExecutionEvents({
ruleId: '42',
eventTypes: [RuleExecutionEventType.message],
logLevels: [LogLevel.warn, LogLevel.error],
sortOrder: 'asc',
page: 42,
perPage: 146,
...params,
});
expect(fetchMock).toHaveBeenCalledWith(
@ -87,11 +124,7 @@ describe('Rule Monitoring API Client', () => {
expect.objectContaining({
method: 'GET',
query: {
event_types: 'message',
log_levels: 'warn,error',
sort_order: 'asc',
page: 42,
per_page: 146,
...expectedParams,
},
})
);

View file

@ -5,6 +5,7 @@
* 2.0.
*/
import { omitBy, isUndefined } from 'lodash';
import dateMath from '@kbn/datemath';
import { KibanaServices } from '../../../common/lib/kibana';
@ -36,20 +37,38 @@ export const api: IRuleMonitoringApiClient = {
fetchRuleExecutionEvents: (
args: FetchRuleExecutionEventsArgs
): Promise<GetRuleExecutionEventsResponse> => {
const { ruleId, eventTypes, logLevels, sortOrder, page, perPage, signal } = args;
const {
ruleId,
searchTerm,
eventTypes,
logLevels,
dateRange,
sortOrder,
page,
perPage,
signal,
} = args;
const url = getRuleExecutionEventsUrl(ruleId);
const startDate = dateMath.parse(dateRange?.start ?? '')?.toISOString();
const endDate = dateMath.parse(dateRange?.end ?? '', { roundUp: true })?.toISOString();
return http().fetch<GetRuleExecutionEventsResponse>(url, {
method: 'GET',
version: '1',
query: {
event_types: eventTypes?.join(','),
log_levels: logLevels?.join(','),
sort_order: sortOrder,
page,
per_page: perPage,
},
query: omitBy(
{
search_term: searchTerm?.length ? searchTerm : undefined,
event_types: eventTypes?.length ? eventTypes.join(',') : undefined,
log_levels: logLevels?.length ? logLevels.join(',') : undefined,
date_start: startDate,
date_end: endDate,
sort_order: sortOrder,
page,
per_page: perPage,
},
isUndefined
),
signal,
});
},

View file

@ -46,12 +46,22 @@ export interface RuleMonitoringApiCallArgs {
signal?: AbortSignal;
}
export interface DateRange {
start?: string;
end?: string;
}
export interface FetchRuleExecutionEventsArgs extends RuleMonitoringApiCallArgs {
/**
* Saved Object ID of the rule (`rule.id`, not static `rule.rule_id`).
*/
ruleId: string;
/**
* Filter by event message. If set, result will include events matching the search term.
*/
searchTerm?: string;
/**
* Filter by event type. If set, result will include only events matching any of these.
*/
@ -62,6 +72,11 @@ export interface FetchRuleExecutionEventsArgs extends RuleMonitoringApiCallArgs
*/
logLevels?: LogLevel[];
/**
* Filter by date range. If set, result will include only events recorded in the specified date range.
*/
dateRange?: DateRange;
/**
* What order to sort by (e.g. `asc` or `desc`).
*/

View file

@ -0,0 +1,35 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import type { ChangeEvent } from 'react';
import React, { useCallback } from 'react';
import { EuiFieldSearch } from '@elastic/eui';
import * as i18n from './translations';
interface EventMessageFilterProps {
value: string;
onChange: (value: string) => void;
}
export function EventMessageFilter({ value, onChange }: EventMessageFilterProps): JSX.Element {
const handleChange = useCallback(
(e: ChangeEvent<HTMLInputElement>) => onChange(e.target.value),
[onChange]
);
return (
<EuiFieldSearch
aria-label={i18n.SEARCH_BY_EVENT_MESSAGE_ARIA_LABEL}
fullWidth
incremental={false}
placeholder={i18n.SEARCH_BY_EVENT_MESSAGE_PLACEHOLDER}
value={value}
onChange={handleChange}
data-test-subj="ruleEventLogMessageSearchField"
/>
);
}

View file

@ -0,0 +1,8 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
export * from './event_message_filter';

View file

@ -0,0 +1,22 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import { i18n } from '@kbn/i18n';
export const SEARCH_BY_EVENT_MESSAGE_ARIA_LABEL = i18n.translate(
'xpack.securitySolution.detectionEngine.rules.eventLog.searchAriaLabel',
{
defaultMessage: 'Search by event message',
}
);
export const SEARCH_BY_EVENT_MESSAGE_PLACEHOLDER = i18n.translate(
'xpack.securitySolution.detectionEngine.rules.eventLog.searchPlaceholder',
{
defaultMessage: 'Search by event message',
}
);

View file

@ -7,7 +7,13 @@
import React, { useCallback, useEffect, useMemo } from 'react';
import type { CriteriaWithPagination } from '@elastic/eui';
import { EuiBasicTable, EuiFlexGroup, EuiFlexItem, EuiPanel } from '@elastic/eui';
import {
EuiBasicTable,
EuiFlexGroup,
EuiFlexItem,
EuiPanel,
EuiSuperDatePicker,
} from '@elastic/eui';
import type { RuleExecutionEvent } from '../../../../../common/api/detection_engine/rule_monitoring';
@ -22,6 +28,7 @@ import { usePagination } from '../basic/tables/use_pagination';
import { useColumns } from './use_columns';
import { useExpandableRows } from '../basic/tables/use_expandable_rows';
import { useExecutionEvents } from './use_execution_events';
import { EventMessageFilter } from './event_message_filter';
import * as i18n from './translations';
@ -56,8 +63,10 @@ const ExecutionEventsTableComponent: React.FC<ExecutionEventsTableProps> = ({ ru
const executionEvents = useExecutionEvents({
ruleId,
searchTerm: filters.state.searchTerm,
eventTypes: filters.state.eventTypes,
logLevels: filters.state.logLevels,
dateRange: filters.state.dateRange,
sortOrder: sorting.state.sort.direction,
page: pagination.state.pageNumber,
perPage: pagination.state.pageSize,
@ -86,6 +95,9 @@ const ExecutionEventsTableComponent: React.FC<ExecutionEventsTableProps> = ({ ru
<EuiFlexItem grow={true}>
<HeaderSection title={i18n.TABLE_TITLE} subtitle={i18n.TABLE_SUBTITLE} />
</EuiFlexItem>
<EuiFlexItem grow>
<EventMessageFilter value={filters.state.searchTerm} onChange={filters.setSearchTerm} />
</EuiFlexItem>
<EuiFlexItem grow={false}>
<LogLevelFilter selectedItems={filters.state.logLevels} onChange={filters.setLogLevels} />
</EuiFlexItem>
@ -95,6 +107,14 @@ const ExecutionEventsTableComponent: React.FC<ExecutionEventsTableProps> = ({ ru
onChange={filters.setEventTypes}
/>
</EuiFlexItem>
<EuiFlexItem grow={false}>
<EuiSuperDatePicker
start={filters.state.dateRange.start}
end={filters.state.dateRange.end}
onTimeChange={filters.setDateRange}
showUpdateButton={false}
/>
</EuiFlexItem>
</EuiFlexGroup>
{/* Table with items */}

View file

@ -87,6 +87,7 @@ describe('useExecutionEvents', () => {
sequence: 0,
level: LogLevel.info,
type: RuleExecutionEventType['status-change'],
execution_id: 'execution-id-1',
message: 'Rule changed status to "succeeded". Rule execution completed without errors',
},
],

View file

@ -11,15 +11,29 @@ import type {
LogLevel,
RuleExecutionEventType,
} from '../../../../../common/api/detection_engine/rule_monitoring';
import type { DateRange } from '../../api';
export const useFilters = () => {
const [searchTerm, setSearchTerm] = useState<string>('');
const [logLevels, setLogLevels] = useState<LogLevel[]>([]);
const [eventTypes, setEventTypes] = useState<RuleExecutionEventType[]>([]);
const state = useMemo(() => ({ logLevels, eventTypes }), [logLevels, eventTypes]);
const [dateRange, setDateRange] = useState<DateRange>({
start: 'now-24h',
end: 'now',
});
const state = useMemo(
() => ({ searchTerm, logLevels, eventTypes, dateRange }),
[searchTerm, logLevels, eventTypes, dateRange]
);
return useMemo(
() => ({ state, setLogLevels, setEventTypes }),
[state, setLogLevels, setEventTypes]
() => ({
state,
setSearchTerm,
setLogLevels,
setEventTypes,
setDateRange,
}),
[state, setSearchTerm, setLogLevels, setEventTypes, setDateRange]
);
};

View file

@ -196,7 +196,7 @@ export class CheckMetadataTransformsTask {
if (attempts > MAX_ATTEMPTS) {
this.logger.warn(
`transform ${transform.id} has failed to restart ${attempts} times. stopping auto restart attempts.`
`Transform ${transform.id} has failed to restart ${attempts} times. stopping auto restart attempts.`
);
return {
attempts,

View file

@ -236,7 +236,7 @@ export class EndpointMetadataService {
fleetAgent = await this.getFleetAgent(fleetServices.agent, fleetAgentId);
} catch (error) {
if (error instanceof FleetAgentNotFoundError) {
this.logger?.warn(`agent with id ${fleetAgentId} not found`);
this.logger?.warn(`Agent with id ${fleetAgentId} not found`);
} else {
throw error;
}

View file

@ -32,8 +32,8 @@ const validateEndpointIntegrationConfig = (
logger: Logger
): void => {
if (!config?.endpointConfig?.preset) {
logger.warn('missing endpointConfig preset');
throwError('invalid endpointConfig preset');
logger.warn('Missing endpointConfig preset');
throwError('Invalid endpointConfig preset');
}
if (
![
@ -43,8 +43,8 @@ const validateEndpointIntegrationConfig = (
ENDPOINT_CONFIG_PRESET_DATA_COLLECTION,
].includes(config.endpointConfig.preset)
) {
logger.warn(`invalid endpointConfig preset: ${config.endpointConfig.preset}`);
throwError('invalid endpointConfig preset');
logger.warn(`Invalid endpointConfig preset: ${config.endpointConfig.preset}`);
throwError('Invalid endpointConfig preset');
}
};
const validateCloudIntegrationConfig = (config: PolicyCreateCloudConfig, logger: Logger): void => {
@ -56,7 +56,7 @@ const validateCloudIntegrationConfig = (config: PolicyCreateCloudConfig, logger:
}
if (typeof config.eventFilters?.nonInteractiveSession !== 'boolean') {
logger.warn(
`missing or invalid value for eventFilters nonInteractiveSession: ${config.eventFilters?.nonInteractiveSession}`
`Missing or invalid value for eventFilters nonInteractiveSession: ${config.eventFilters?.nonInteractiveSession}`
);
throwError('invalid value for eventFilters nonInteractiveSession');
}

View file

@ -54,8 +54,11 @@ export const getRuleExecutionEventsRoute = (router: SecuritySolutionPluginRouter
const executionLog = ctx.securitySolution.getRuleExecutionLog();
const executionEventsResponse = await executionLog.getExecutionEvents({
ruleId: params.ruleId,
searchTerm: query.search_term,
eventTypes: query.event_types,
logLevels: query.log_levels,
dateStart: query.date_start,
dateEnd: query.date_end,
sortOrder: query.sort_order,
page: query.page,
perPage: query.per_page,

View file

@ -10,6 +10,7 @@
export const TIMESTAMP = `@timestamp` as const;
export const MESSAGE = 'message' as const;
export const EVENT_PROVIDER = 'event.provider' as const;
export const EVENT_ACTION = 'event.action' as const;
export const EVENT_SEQUENCE = 'event.sequence' as const;

View file

@ -39,11 +39,20 @@ export interface GetExecutionEventsArgs {
/** Saved object id of the rule (`rule.id`). */
ruleId: RuleObjectId;
/** Include events of the specified types. If empty, all types of events will be included. */
eventTypes: RuleExecutionEventType[];
/** Include events of matching the search term. If omitted, all events will be included. */
searchTerm?: string;
/** Include events having these log levels. If empty, events of all levels will be included. */
logLevels: LogLevel[];
/** Include events of the specified types. If omitted, all types of events will be included. */
eventTypes?: RuleExecutionEventType[];
/** Include events having these log levels. If omitted, events of all levels will be included. */
logLevels?: LogLevel[];
/** Include events recorded starting from the specified moment. If omitted, all events will be included. */
dateStart?: string;
/** Include events recorded till the specified moment. If omitted, all events will be included. */
dateEnd?: string;
/** What order to sort by (e.g. `asc` or `desc`). */
sortOrder: SortOrder;

View file

@ -9,6 +9,7 @@ import type * as estypes from '@elastic/elasticsearch/lib/api/typesWithBodyKey';
import type { IEventLogClient, IValidatedEvent } from '@kbn/event-log-plugin/server';
import { MAX_EXECUTION_EVENTS_DISPLAYED } from '@kbn/securitysolution-rules';
import { prepareKQLStringParam } from '../../../../../../../common/utils/kql';
import type {
GetRuleExecutionEventsResponse,
GetRuleExecutionResultsResponse,
@ -53,20 +54,30 @@ export const createEventLogReader = (eventLog: IEventLogClient): IEventLogReader
async getExecutionEvents(
args: GetExecutionEventsArgs
): Promise<GetRuleExecutionEventsResponse> {
const { ruleId, eventTypes, logLevels, sortOrder, page, perPage } = args;
const {
ruleId,
searchTerm,
eventTypes,
logLevels,
dateStart,
dateEnd,
sortOrder,
page,
perPage,
} = args;
const soType = RULE_SAVED_OBJECT_TYPE;
const soIds = [ruleId];
// TODO: include Framework events
const kqlFilter = kqlAnd([
`${f.EVENT_PROVIDER}:${RULE_EXECUTION_LOG_PROVIDER}`,
eventTypes.length > 0 ? `${f.EVENT_ACTION}:(${kqlOr(eventTypes)})` : '',
logLevels.length > 0 ? `${f.LOG_LEVEL}:(${kqlOr(logLevels)})` : '',
]);
const findResult = await withSecuritySpan('findEventsBySavedObjectIds', () => {
return eventLog.findEventsBySavedObjectIds(soType, soIds, {
filter: kqlFilter,
// TODO: include Framework events
filter: buildEventLogKqlFilter({
searchTerm,
eventTypes,
logLevels,
dateStart,
dateEnd,
}),
sort: [
{ sort_field: f.TIMESTAMP, sort_order: sortOrder },
{ sort_field: f.EVENT_SEQUENCE, sort_order: sortOrder },
@ -173,9 +184,10 @@ const normalizeEvent = (rawEvent: IValidatedEvent): RuleExecutionEvent => {
const sequence = normalizeEventSequence(rawEvent);
const level = normalizeLogLevel(rawEvent);
const type = normalizeEventType(rawEvent);
const executionId = normalizeExecutionId(rawEvent);
const message = normalizeEventMessage(rawEvent, type);
return { timestamp, sequence, level, type, message };
return { timestamp, sequence, level, type, message, execution_id: executionId };
};
type RawEvent = NonNullable<IValidatedEvent>;
@ -230,9 +242,64 @@ const normalizeEventMessage = (event: RawEvent, type: RuleExecutionEventType): s
}
if (type === RuleExecutionEventType['execution-metrics']) {
return '';
invariant(
event.kibana?.alert?.rule?.execution?.metrics,
'Required "kibana.alert.rule.execution.metrics" field is not found'
);
return JSON.stringify(event.kibana.alert.rule.execution.metrics);
}
assertUnreachable(type);
return '';
};
const normalizeExecutionId = (event: RawEvent): string => {
invariant(
event.kibana?.alert?.rule?.execution?.uuid,
'Required "kibana.alert.rule.execution.uuid" field is not found'
);
return event.kibana.alert.rule.execution.uuid;
};
const buildEventLogKqlFilter = ({
searchTerm,
eventTypes,
logLevels,
dateStart,
dateEnd,
}: Pick<
GetExecutionEventsArgs,
'searchTerm' | 'eventTypes' | 'logLevels' | 'dateStart' | 'dateEnd'
>) => {
const filters = [`${f.EVENT_PROVIDER}:${RULE_EXECUTION_LOG_PROVIDER}`];
if (searchTerm?.length) {
filters.push(`${f.MESSAGE}:${prepareKQLStringParam(searchTerm)}`);
}
if (eventTypes?.length) {
filters.push(`${f.EVENT_ACTION}:(${kqlOr(eventTypes)})`);
}
if (logLevels?.length) {
filters.push(`${f.LOG_LEVEL}:(${kqlOr(logLevels)})`);
}
const dateRangeFilter: string[] = [];
if (dateStart) {
dateRangeFilter.push(`${f.TIMESTAMP} >= ${prepareKQLStringParam(dateStart)}`);
}
if (dateEnd) {
dateRangeFilter.push(`${f.TIMESTAMP} <= ${prepareKQLStringParam(dateEnd)}`);
}
if (dateRangeFilter.length) {
filters.push(kqlAnd(dateRangeFilter));
}
return kqlAnd(filters);
};

View file

@ -175,8 +175,7 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
const refresh = actions.length ? 'wait_for' : false;
ruleExecutionLogger.debug('[+] Starting Signal Rule execution');
ruleExecutionLogger.debug(`interval: ${interval}`);
ruleExecutionLogger.debug(`Starting Security Rule execution (interval: ${interval})`);
await ruleExecutionLogger.logStatusChange({
newStatus: RuleExecutionStatus.running,
@ -455,11 +454,15 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
const createdSignalsCount = result.createdSignals.length;
if (result.success) {
ruleExecutionLogger.debug('[+] Signal Rule execution completed.');
ruleExecutionLogger.debug('Security Rule execution completed');
ruleExecutionLogger.debug(
`[+] Finished indexing ${createdSignalsCount} signals into ${ruleDataClient.indexNameWithNamespace(
`Finished indexing ${createdSignalsCount} alerts into ${ruleDataClient.indexNameWithNamespace(
spaceId
)}`
)} ${
!isEmpty(tuples)
? `searched between date ranges ${JSON.stringify(tuples, null, 2)}`
: ''
}`
);
if (!hasError && !wroteWarningStatus && !result.warning) {
@ -473,18 +476,10 @@ export const createSecurityRuleTypeWrapper: CreateSecurityRuleTypeWrapper =
},
});
}
ruleExecutionLogger.debug(
`[+] Finished indexing ${createdSignalsCount} ${
!isEmpty(tuples)
? `signals searched between date ranges ${JSON.stringify(tuples, null, 2)}`
: ''
}`
);
} else {
await ruleExecutionLogger.logStatusChange({
newStatus: RuleExecutionStatus.failed,
message: `Bulk Indexing of signals failed: ${truncateList(result.errors).join()}`,
message: `Bulk Indexing of alerts failed: ${truncateList(result.errors).join()}`,
metrics: {
searchDurations: result.searchAfterTimes,
indexingDurations: result.bulkCreateTimes,

View file

@ -69,7 +69,7 @@ export const bulkCreateFactory =
const enrichedAlerts = await enrichAlerts(alerts, params, experimentalFeatures);
return enrichedAlerts;
} catch (error) {
ruleExecutionLogger.error(`Enrichments failed ${error}`);
ruleExecutionLogger.error(`Alerts enrichment failed: ${error}`);
throw error;
} finally {
enrichmentsTimeFinish = performance.now();
@ -90,13 +90,11 @@ export const bulkCreateFactory =
const end = performance.now();
ruleExecutionLogger.debug(
`individual bulk process time took: ${makeFloatString(end - start)} milliseconds`
);
ruleExecutionLogger.debug(`Alerts bulk process took ${makeFloatString(end - start)} ms`);
if (!isEmpty(errors)) {
ruleExecutionLogger.debug(
`[-] bulkResponse had errors with responses of: ${JSON.stringify(errors)}`
ruleExecutionLogger.warn(
`Alerts bulk process finished with errors: ${JSON.stringify(errors)}`
);
return {
errors: Object.keys(errors),

View file

@ -74,7 +74,7 @@ export const bulkCreateWithSuppression = async <
const enrichedAlerts = await enrichAlerts(alerts, params);
return enrichedAlerts;
} catch (error) {
ruleExecutionLogger.error(`Enrichments failed ${error}`);
ruleExecutionLogger.error(`Alerts enrichment failed: ${error}`);
throw error;
} finally {
enrichmentsTimeFinish = performance.now();
@ -94,14 +94,10 @@ export const bulkCreateWithSuppression = async <
const end = performance.now();
ruleExecutionLogger.debug(
`individual bulk process time took: ${makeFloatString(end - start)} milliseconds`
);
ruleExecutionLogger.debug(`Alerts bulk process took ${makeFloatString(end - start)} ms`);
if (!isEmpty(errors)) {
ruleExecutionLogger.debug(
`[-] bulkResponse had errors with responses of: ${JSON.stringify(errors)}`
);
ruleExecutionLogger.warn(`Alerts bulk process finished with errors: ${JSON.stringify(errors)}`);
return {
errors: Object.keys(errors),
success: false,

View file

@ -89,7 +89,7 @@ export const createSingleFieldMatchEnrichment: CreateFieldsMatchEnrichment = asy
);
return eventsMapById;
} catch (error) {
logger.error(`Enrichment ${name}: throw error ${error}`);
logger.error(`Enrichment ${name} failed: ${error}`);
return {};
}
};

View file

@ -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 - returning original search result'
'No exception items of type list found - return unfiltered events'
);
});

View file

@ -47,9 +47,7 @@ export const filterEventsAgainstList = async <T>({
);
if (!atLeastOneLargeValueList) {
ruleExecutionLogger.debug(
'no exception items of type list found - returning original search result'
);
ruleExecutionLogger.debug('No exception items of type list found - return unfiltered events');
return [events, []];
}

View file

@ -49,13 +49,18 @@ export const searchAfterAndBulkCreate = async ({
}: SearchAfterAndBulkCreateParams): Promise<SearchAfterAndBulkCreateReturnType> => {
return withSecuritySpan('searchAfterAndBulkCreate', async () => {
let toReturn = createSearchAfterReturnType();
let searchingIteration = 0;
// sortId tells us where to start our next consecutive search_after query
let sortIds: estypes.SortResults | undefined;
let hasSortId = true; // default to true so we execute the search on initial run
if (tuple == null || tuple.to == null || tuple.from == null) {
ruleExecutionLogger.error(`[-] malformed date tuple`);
ruleExecutionLogger.error(
`missing run options fields: ${!tuple.to ? '"tuple.to"' : ''}, ${
!tuple.from ? '"tuple.from"' : ''
}`
);
return createSearchAfterReturnType({
success: false,
errors: ['malformed date tuple'],
@ -63,9 +68,14 @@ export const searchAfterAndBulkCreate = async ({
}
while (toReturn.createdSignalsCount <= tuple.maxSignals) {
const cycleNum = `cycle ${searchingIteration++}`;
try {
let mergedSearchResults = createSearchResultReturnType();
ruleExecutionLogger.debug(`sortIds: ${sortIds}`);
ruleExecutionLogger.debug(
`[${cycleNum}] Searching events${
sortIds ? ` after cursor ${JSON.stringify(sortIds)}` : ''
} in index pattern "${inputIndexPattern}"`
);
if (hasSortId) {
const { searchResult, searchDuration, searchErrors } = await singleSearchAfter({
@ -97,9 +107,29 @@ export const searchAfterAndBulkCreate = async ({
}),
]);
// determine if there are any candidate signals to be processed
const totalHits = getTotalHitsValue(mergedSearchResults.hits.total);
const lastSortIds = getSafeSortIds(
searchResult.hits.hits[searchResult.hits.hits.length - 1]?.sort
);
if (totalHits === 0 || mergedSearchResults.hits.hits.length === 0) {
ruleExecutionLogger.debug(
`[${cycleNum}] Found 0 events ${
sortIds ? ` after cursor ${JSON.stringify(sortIds)}` : ''
}`
);
break;
} else {
ruleExecutionLogger.debug(
`[${cycleNum}] Found ${
mergedSearchResults.hits.hits.length
} of total ${totalHits} events${
sortIds ? ` after cursor ${JSON.stringify(sortIds)}` : ''
}, last cursor ${JSON.stringify(lastSortIds)}`
);
}
if (lastSortIds != null && lastSortIds.length !== 0) {
sortIds = lastSortIds;
hasSortId = true;
@ -108,22 +138,6 @@ export const searchAfterAndBulkCreate = async ({
}
}
// determine if there are any candidate signals to be processed
const totalHits = getTotalHitsValue(mergedSearchResults.hits.total);
ruleExecutionLogger.debug(`totalHits: ${totalHits}`);
ruleExecutionLogger.debug(
`searchResult.hit.hits.length: ${mergedSearchResults.hits.hits.length}`
);
if (totalHits === 0 || mergedSearchResults.hits.hits.length === 0) {
ruleExecutionLogger.debug(
`${
totalHits === 0 ? 'totalHits' : 'searchResult.hits.hits.length'
} was 0, exiting early`
);
break;
}
// filter out the search results that match with the values found in the list.
// the resulting set are signals to be indexed, given they are not duplicates
// of signals already present in the signals index.
@ -158,9 +172,9 @@ export const searchAfterAndBulkCreate = async ({
addToSearchAfterReturn({ current: toReturn, next: bulkCreateResult });
ruleExecutionLogger.debug(`created ${bulkCreateResult.createdItemsCount} signals`);
ruleExecutionLogger.debug(`signalsCreatedCount: ${toReturn.createdSignalsCount}`);
ruleExecutionLogger.debug(`enrichedEvents.hits.hits: ${enrichedEvents.length}`);
ruleExecutionLogger.debug(
`[${cycleNum}] Created ${bulkCreateResult.createdItemsCount} alerts from ${enrichedEvents.length} events`
);
sendAlertTelemetryEvents(
enrichedEvents,
@ -171,11 +185,14 @@ export const searchAfterAndBulkCreate = async ({
}
if (!hasSortId) {
ruleExecutionLogger.debug('ran out of sort ids to sort on');
ruleExecutionLogger.debug(`[${cycleNum}] Unable to fetch last event cursor`);
break;
}
} catch (exc: unknown) {
ruleExecutionLogger.error(`[-] search_after_bulk_create threw an error ${exc}`);
ruleExecutionLogger.error(
'Unable to extract/process events or create alerts',
JSON.stringify(exc)
);
return mergeReturns([
toReturn,
createSearchAfterReturnType({
@ -185,7 +202,7 @@ export const searchAfterAndBulkCreate = async ({
]);
}
}
ruleExecutionLogger.debug(`[+] completed bulk index of ${toReturn.createdSignalsCount}`);
ruleExecutionLogger.debug(`Completed bulk indexing of ${toReturn.createdSignalsCount} alert`);
return toReturn;
});
};

View file

@ -72,6 +72,6 @@ export function sendAlertTelemetryEvents(
try {
eventsTelemetry.queueTelemetryEvents(selectedEvents);
} catch (exc) {
ruleExecutionLogger.error(`[-] queing telemetry events failed ${exc}`);
ruleExecutionLogger.error(`Queuing telemetry events failed: ${exc}`);
}
}

View file

@ -104,14 +104,12 @@ export const singleSearchAfter = async <
searchErrors,
};
} catch (exc) {
ruleExecutionLogger.error(`[-] nextSearchAfter threw an error ${exc}`);
ruleExecutionLogger.error(`Searching events operation failed: ${exc}`);
if (
exc.message.includes(`No mapping found for [${primaryTimestamp}] in order to sort on`) ||
(secondaryTimestamp &&
exc.message.includes(`No mapping found for [${secondaryTimestamp}] in order to sort on`))
) {
ruleExecutionLogger.error(`[-] failure reason: ${exc.message}`);
const searchRes: SignalSearchResponse<TAggregations> = {
took: 0,
timed_out: false,

View file

@ -734,7 +734,7 @@ describe('utils', () => {
expect(ruleExecutionLogger.logStatusChange).toHaveBeenCalledWith({
newStatus: RuleExecutionStatus['partial failure'],
message:
'This rule is attempting to query data from Elasticsearch indices listed in the "Index pattern" section of the rule definition, however no index matching: ["logs-endpoint.alerts-*"] was found. This warning will continue to appear until a matching index is created or this rule is disabled. If you have recently enrolled agents enabled with Endpoint Security through Fleet, this warning should stop once an alert is sent from an agent.',
'This rule is attempting to query data from Elasticsearch indices listed in the "Index patterns" section of the rule definition, however no index matching: ["logs-endpoint.alerts-*"] was found. This warning will continue to appear until a matching index is created or this rule is disabled. If you have recently enrolled agents enabled with Endpoint Security through Fleet, this warning should stop once an alert is sent from an agent.',
});
});
@ -768,7 +768,7 @@ describe('utils', () => {
expect(ruleExecutionLogger.logStatusChange).toHaveBeenCalledWith({
newStatus: RuleExecutionStatus['partial failure'],
message:
'This rule is attempting to query data from Elasticsearch indices listed in the "Index pattern" section of the rule definition, however no index matching: ["logs-endpoint.alerts-*"] was found. This warning will continue to appear until a matching index is created or this rule is disabled.',
'This rule is attempting to query data from Elasticsearch indices listed in the "Index patterns" section of the rule definition, however no index matching: ["logs-endpoint.alerts-*"] was found. This warning will continue to appear until a matching index is created or this rule is disabled.',
});
});
});

View file

@ -91,7 +91,7 @@ export const hasReadIndexPrivileges = async (args: {
const indexesString = JSON.stringify(indexesWithNoReadPrivileges);
await ruleExecutionLogger.logStatusChange({
newStatus: RuleExecutionStatus['partial failure'],
message: `This rule may not have the required read privileges to the following indices/index patterns: ${indexesString}`,
message: `This rule may not have the required read privileges to the following index patterns: ${indexesString}`,
});
return true;
}
@ -112,7 +112,7 @@ export const hasTimestampFields = async (args: {
const { ruleName } = ruleExecutionLogger.context;
if (isEmpty(timestampFieldCapsResponse.body.indices)) {
const errorString = `This rule is attempting to query data from Elasticsearch indices listed in the "Index pattern" section of the rule definition, however no index matching: ${JSON.stringify(
const errorString = `This rule is attempting to query data from Elasticsearch indices listed in the "Index patterns" section of the rule definition, however no index matching: ${JSON.stringify(
inputIndices
)} was found. This warning will continue to appear until a matching index is created or this rule is disabled. ${
ruleName === 'Endpoint Security'
@ -432,7 +432,9 @@ export const getRuleRangeTuples = ({
const intervalDuration = parseInterval(interval);
if (intervalDuration == null) {
ruleExecutionLogger.error(
'Failed to compute gap between rule runs: could not parse rule interval'
`Failed to compute gap between rule runs: could not parse rule interval "${JSON.stringify(
interval
)}"`
);
return { tuples, remainingGap: moment.duration(0) };
}

View file

@ -25,7 +25,7 @@ export const createIndex = async ({
index: options.index,
});
if (isIndexExist) {
logger.info('${options.index} already exist');
logger.info(`${options.index} already exist`);
return;
}

View file

@ -82,7 +82,7 @@ export default ({ getService }: FtrProviderContext) => {
// TODO: https://github.com/elastic/kibana/pull/121644 clean up, make type-safe
expect(body?.execution_summary?.last_execution.message).to.eql(
`This rule may not have the required read privileges to the following indices/index patterns: ["${index[0]}"]`
`This rule may not have the required read privileges to the following index patterns: ["${index[0]}"]`
);
await deleteUserAndRole(getService, ROLES.detections_admin);
@ -121,7 +121,7 @@ export default ({ getService }: FtrProviderContext) => {
// TODO: https://github.com/elastic/kibana/pull/121644 clean up, make type-safe
expect(body?.execution_summary?.last_execution.message).to.eql(
`This rule may not have the required read privileges to the following indices/index patterns: ["${index[0]}"]`
`This rule may not have the required read privileges to the following index patterns: ["${index[0]}"]`
);
await deleteUserAndRole(getService, ROLES.detections_admin);

View file

@ -165,7 +165,7 @@ export default ({ getService }: FtrProviderContext) => {
// TODO: https://github.com/elastic/kibana/pull/121644 clean up, make type-safe
expect(rule?.execution_summary?.last_execution.status).to.eql('partial failure');
expect(rule?.execution_summary?.last_execution.message).to.eql(
'This rule is attempting to query data from Elasticsearch indices listed in the "Index pattern" section of the rule definition, however no index matching: ["does-not-exist-*"] was found. This warning will continue to appear until a matching index is created or this rule is disabled.'
'This rule is attempting to query data from Elasticsearch indices listed in the "Index patterns" section of the rule definition, however no index matching: ["does-not-exist-*"] was found. This warning will continue to appear until a matching index is created or this rule is disabled.'
);
});

View file

@ -126,7 +126,7 @@ export default ({ getService }: FtrProviderContext) => {
expect(response.body.events[0].security_status).to.eql('partial failure');
expect(
response.body.events[0].security_message.startsWith(
'This rule is attempting to query data from Elasticsearch indices listed in the "Index pattern" section of the rule definition, however no index matching: ["no-name-index"] was found.'
'This rule is attempting to query data from Elasticsearch indices listed in the "Index patterns" section of the rule definition, however no index matching: ["no-name-index"] was found.'
)
).to.eql(true);
});