Skip to content

Commit

Permalink
[Alerting & Actions ] More debug logging (#85149)
Browse files Browse the repository at this point in the history 
* Adding debug messages

* Adding timestamp to action execution log

* Jest tests

* Merging in master

* PR fixes

* Cleanup

* PR fixes

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>
  • Loading branch information
@ymao1 @kibanamachine
ymao1 and kibanamachine authored Dec 8, 2020
1 parent 11470ac commit 18a99fc
Show file tree
Hide file tree
Showing 4 changed files with 311 additions and 42 deletions.
2 changes: 2 additions & 0 deletions x-pack/plugins/actions/server/lib/action_executor.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -105,6 +105,8 @@ test('successfully executes', async () => {
},
params: { foo: true },
});

expect(loggerMock.debug).toBeCalledWith('executing action test:1: 1');
});

test('provides empty config when config and / or secrets is empty', async () => {
Expand Down
2 changes: 2 additions & 0 deletions x-pack/plugins/actions/server/lib/action_executor.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -120,6 +120,8 @@ export class ActionExecutor {
}

const actionLabel = `${actionTypeId}:${actionId}: ${name}`;
logger.debug(`executing action ${actionLabel}`);

const event: IEvent = {
event: { action: EVENT_LOG_ACTIONS.execute },
kibana: {
Expand Down
191 changes: 191 additions & 0 deletions x-pack/plugins/alerts/server/task_runner/task_runner.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -190,6 +190,14 @@ describe('Task Runner', () => {
expect(call.services.callCluster).toBeTruthy();
expect(call.services).toBeTruthy();

const logger = taskRunnerFactoryInitializerParams.logger;
expect(logger.debug).toHaveBeenCalledTimes(2);
expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z');
expect(logger.debug).nthCalledWith(
2,
'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"ok"}'
);

const eventLogger = taskRunnerFactoryInitializerParams.eventLogger;
expect(eventLogger.logEvent).toHaveBeenCalledTimes(1);
expect(eventLogger.logEvent.mock.calls[0][0]).toMatchInlineSnapshot(`
Expand Down Expand Up @@ -261,6 +269,18 @@ describe('Task Runner', () => {
]
`);

const logger = taskRunnerFactoryInitializerParams.logger;
expect(logger.debug).toHaveBeenCalledTimes(3);
expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z');
expect(logger.debug).nthCalledWith(
2,
`alert test:1: 'alert-name' has 1 active alert instances: [{\"instanceId\":\"1\",\"actionGroup\":\"default\"}]`
);
expect(logger.debug).nthCalledWith(
3,
'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}'
);

const eventLogger = taskRunnerFactoryInitializerParams.eventLogger;
expect(eventLogger.logEvent).toHaveBeenCalledTimes(4);
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, {
Expand Down Expand Up @@ -352,6 +372,161 @@ describe('Task Runner', () => {
});
});

test('actionsPlugin.execute is skipped if muteAll is true', async () => {
taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true);
taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true);
alertType.executor.mockImplementation(
({ services: executorServices }: AlertExecutorOptions) => {
executorServices.alertInstanceFactory('1').scheduleActions('default');
}
);
const taskRunner = new TaskRunner(
alertType,
mockedTaskInstance,
taskRunnerFactoryInitializerParams
);
alertsClient.get.mockResolvedValue({
...mockedAlertTypeSavedObject,
muteAll: true,
});
encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({
id: '1',
type: 'alert',
attributes: {
apiKey: Buffer.from('123:abc').toString('base64'),
},
references: [],
});
await taskRunner.run();
expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(0);

const logger = taskRunnerFactoryInitializerParams.logger;
expect(logger.debug).toHaveBeenCalledTimes(4);
expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z');
expect(logger.debug).nthCalledWith(
2,
`alert test:1: 'alert-name' has 1 active alert instances: [{\"instanceId\":\"1\",\"actionGroup\":\"default\"}]`
);
expect(logger.debug).nthCalledWith(
3,
`no scheduling of actions for alert test:1: 'alert-name': alert is muted.`
);
expect(logger.debug).nthCalledWith(
4,
'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}'
);

const eventLogger = taskRunnerFactoryInitializerParams.eventLogger;
expect(eventLogger.logEvent).toHaveBeenCalledTimes(3);
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, {
event: {
action: 'new-instance',
},
kibana: {
alerting: {
action_group_id: 'default',
instance_id: '1',
},
saved_objects: [
{
id: '1',
namespace: undefined,
rel: 'primary',
type: 'alert',
},
],
},
message: "test:1: 'alert-name' created new instance: '1'",
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, {
event: {
action: 'active-instance',
},
kibana: {
alerting: {
instance_id: '1',
action_group_id: 'default',
},
saved_objects: [
{
id: '1',
namespace: undefined,
rel: 'primary',
type: 'alert',
},
],
},
message: "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'",
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute',
outcome: 'success',
},
kibana: {
alerting: {
status: 'active',
},
saved_objects: [
{
id: '1',
namespace: undefined,
rel: 'primary',
type: 'alert',
},
],
},
message: "alert executed: test:1: 'alert-name'",
});
});

test('skips firing actions for active instance if instance is muted', async () => {
taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true);
taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true);
alertType.executor.mockImplementation(
({ services: executorServices }: AlertExecutorOptions) => {
executorServices.alertInstanceFactory('1').scheduleActions('default');
executorServices.alertInstanceFactory('2').scheduleActions('default');
}
);
const taskRunner = new TaskRunner(
alertType,
mockedTaskInstance,
taskRunnerFactoryInitializerParams
);
alertsClient.get.mockResolvedValue({
...mockedAlertTypeSavedObject,
mutedInstanceIds: ['2'],
});
encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({
id: '1',
type: 'alert',
attributes: {
apiKey: Buffer.from('123:abc').toString('base64'),
},
references: [],
});
await taskRunner.run();
expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(1);

const logger = taskRunnerFactoryInitializerParams.logger;
expect(logger.debug).toHaveBeenCalledTimes(4);
expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z');
expect(logger.debug).nthCalledWith(
2,
`alert test:1: 'alert-name' has 2 active alert instances: [{\"instanceId\":\"1\",\"actionGroup\":\"default\"},{\"instanceId\":\"2\",\"actionGroup\":\"default\"}]`
);
expect(logger.debug).nthCalledWith(
3,
`skipping scheduling of actions for '2' in alert test:1: 'alert-name': instance is muted`
);
expect(logger.debug).nthCalledWith(
4,
'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}'
);
});

test('includes the apiKey in the request used to initialize the actionsClient', async () => {
taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true);
taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true);
Expand Down Expand Up @@ -567,6 +742,22 @@ describe('Task Runner', () => {
}
`);

const logger = taskRunnerFactoryInitializerParams.logger;
expect(logger.debug).toHaveBeenCalledTimes(4);
expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z');
expect(logger.debug).nthCalledWith(
2,
`alert test:1: 'alert-name' has 1 active alert instances: [{\"instanceId\":\"1\",\"actionGroup\":\"default\"}]`
);
expect(logger.debug).nthCalledWith(
3,
`alert test:1: 'alert-name' has 1 recovered alert instances: [\"2\"]`
);
expect(logger.debug).nthCalledWith(
4,
'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}'
);

const eventLogger = taskRunnerFactoryInitializerParams.eventLogger;
expect(eventLogger.logEvent).toHaveBeenCalledTimes(5);
expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(2);
Expand Down
Loading

0 comments on commit 18a99fc

Please sign in to comment.