n8n/packages/cli/test/unit/Telemetry.test.ts
Michael Auerswald b67f803cbe
feat: Add global event bus (#4860)
* fix branch

* fix deserialize, add filewriter

* add catchAll eventGroup/Name

* adding simple Redis sender and receiver to eventbus

* remove native node threads

* improve eventbus

* refactor and simplify

* more refactoring and syslog client

* more refactor, improved endpoints and eventbus

* remove local broker and receivers from mvp

* destination de/serialization

* create MessageEventBusDestinationEntity

* db migrations, load destinations at startup

* add delete destination endpoint

* pnpm merge and circular import fix

* delete destination fix

* trigger log file shuffle after size reached

* add environment variables for eventbus

* reworking event messages

* serialize to thread fix

* some refactor and lint fixing

* add emit to eventbus

* cleanup and fix sending unsent

* quicksave frontend trial

* initial EventTree vue component

* basic log streaming settings in vue

* http request code merge

* create destination settings modals

* fix eventmessage options types

* credentials are loaded

* fix and clean up frontend code

* move request code to axios

* update lock file

* merge fix

* fix redis build

* move destination interfaces into workflow pkg

* revive sentry as destination

* migration fixes and frontend cleanup

* N8N-5777 / N8N-5789 N8N-5788

* N8N-5784

* N8N-5782 removed event levels

* N8N-5790 sentry destination cleanup

* N8N-5786 and refactoring

* N8N-5809 and refactor/cleanup

* UI fixes and anonymize renaming

* N8N-5837

* N8N-5834

* fix no-items UI issues

* remove card / settings label in modal

* N8N-5842 fix

* disable webhook auth for now and update ui

* change sidebar to tabs

* remove payload option

* extend audit events with more user data

* N8N-5853 and UI revert to sidebar

* remove redis destination

* N8N-5864 / N8N-5868 / N8N-5867 / N8N-5865

* ui and licensing fixes

* add node events and info bubbles to frontend

* ui wording changes

* frontend tests

* N8N-5896 and ee rename

* improves backend tests

* merge fix

* fix backend test

* make linter happy

* remove unnecessary cfg / limit  actions to owners

* fix multiple sentry DSN and anon bug

* eslint fix

* more tests and fixes

* merge fix

* fix workflow audit events

* remove 'n8n.workflow.execution.error' event

* merge fix

* lint fix

* lint fix

* review fixes

* fix merge

* prettier fixes

* merge

* review changes

* use loggerproxy

* remove catch from internal hook promises

* fix tests

* lint fix

* include review PR changes

* review changes

* delete duplicate lines from a bad merge

* decouple log-streaming UI options from public API

* logstreaming -> log-streaming for consistency

* do not make unnecessary api calls when log streaming is disabled

* prevent sentryClient.close() from being called if init failed

* fix the e2e test for log-streaming

* review changes

* cleanup

* use `private` for one last private property

* do not use node prefix package names.. just yet

* remove unused import

* fix the tests

because there is a folder called `events`, tsc-alias is messing up all imports for native events module.
https://github.com/justkey007/tsc-alias/issues/152

Co-authored-by: कारतोफ्फेलस्क्रिप्ट™ <aditya@netroy.in>
2023-01-04 09:47:48 +01:00

430 lines
13 KiB
TypeScript

import { Telemetry } from '@/telemetry';
import config from '@/config';
import { flushPromises } from './Helpers';
jest.unmock('@/telemetry');
jest.mock('@/license/License.service', () => {
return {
LicenseService: {
getActiveTriggerCount: async () => 0,
},
};
});
describe('Telemetry', () => {
let startPulseSpy: jest.SpyInstance;
const spyTrack = jest.spyOn(Telemetry.prototype, 'track').mockName('track');
let telemetry: Telemetry;
const n8nVersion = '0.0.0';
const instanceId = 'Telemetry unit test';
const testDateTime = new Date('2022-01-01 00:00:00');
beforeAll(() => {
startPulseSpy = jest
.spyOn(Telemetry.prototype as any, 'startPulse')
.mockImplementation(() => {});
jest.useFakeTimers();
jest.setSystemTime(testDateTime);
config.set('diagnostics.enabled', true);
config.set('deployment.type', 'n8n-testing');
});
afterAll(() => {
jest.clearAllTimers();
jest.useRealTimers();
startPulseSpy.mockRestore();
telemetry.trackN8nStop();
});
beforeEach(() => {
spyTrack.mockClear();
telemetry = new Telemetry(instanceId, n8nVersion);
(telemetry as any).rudderStack = {
flush: () => {},
identify: () => {},
track: () => {},
};
});
afterEach(() => {
telemetry.trackN8nStop();
});
describe('trackN8nStop', () => {
test('should call track method', () => {
telemetry.trackN8nStop();
expect(spyTrack).toHaveBeenCalledTimes(1);
});
});
describe('trackWorkflowExecution', () => {
beforeEach(() => {
jest.setSystemTime(testDateTime);
});
test('should count executions correctly', async () => {
const payload = {
workflow_id: '1',
is_manual: true,
success: true,
error_node_type: 'custom-nodes-base.node-type',
};
payload.is_manual = true;
payload.success = true;
const execTime1 = fakeJestSystemTime('2022-01-01 12:00:00');
await telemetry.trackWorkflowExecution(payload);
fakeJestSystemTime('2022-01-01 12:30:00');
await telemetry.trackWorkflowExecution(payload);
payload.is_manual = false;
payload.success = true;
const execTime2 = fakeJestSystemTime('2022-01-01 13:00:00');
await telemetry.trackWorkflowExecution(payload);
fakeJestSystemTime('2022-01-01 12:30:00');
await telemetry.trackWorkflowExecution(payload);
payload.is_manual = true;
payload.success = false;
const execTime3 = fakeJestSystemTime('2022-01-01 14:00:00');
await telemetry.trackWorkflowExecution(payload);
fakeJestSystemTime('2022-01-01 12:30:00');
await telemetry.trackWorkflowExecution(payload);
payload.is_manual = false;
payload.success = false;
const execTime4 = fakeJestSystemTime('2022-01-01 15:00:00');
await telemetry.trackWorkflowExecution(payload);
fakeJestSystemTime('2022-01-01 12:30:00');
await telemetry.trackWorkflowExecution(payload);
expect(spyTrack).toHaveBeenCalledTimes(0);
const execBuffer = telemetry.getCountsBuffer();
expect(execBuffer['1'].manual_success?.count).toBe(2);
expect(execBuffer['1'].manual_success?.first).toEqual(execTime1);
expect(execBuffer['1'].prod_success?.count).toBe(2);
expect(execBuffer['1'].prod_success?.first).toEqual(execTime2);
expect(execBuffer['1'].manual_error?.count).toBe(2);
expect(execBuffer['1'].manual_error?.first).toEqual(execTime3);
expect(execBuffer['1'].prod_error?.count).toBe(2);
expect(execBuffer['1'].prod_error?.first).toEqual(execTime4);
});
test('should fire "Workflow execution errored" event for failed executions', async () => {
const payload = {
workflow_id: '1',
is_manual: true,
success: false,
error_node_type: 'custom-nodes-base.node-type',
};
const execTime1 = fakeJestSystemTime('2022-01-01 12:00:00');
await telemetry.trackWorkflowExecution(payload);
fakeJestSystemTime('2022-01-01 12:30:00');
await telemetry.trackWorkflowExecution(payload);
let execBuffer = telemetry.getCountsBuffer();
// should not fire event for custom nodes
expect(spyTrack).toHaveBeenCalledTimes(0);
expect(execBuffer['1'].manual_error?.count).toBe(2);
expect(execBuffer['1'].manual_error?.first).toEqual(execTime1);
payload.error_node_type = 'n8n-nodes-base.node-type';
fakeJestSystemTime('2022-01-01 13:00:00');
await telemetry.trackWorkflowExecution(payload);
fakeJestSystemTime('2022-01-01 12:30:00');
await telemetry.trackWorkflowExecution(payload);
execBuffer = telemetry.getCountsBuffer();
// should fire event for custom nodes
expect(spyTrack).toHaveBeenCalledTimes(2);
expect(spyTrack).toHaveBeenCalledWith('Workflow execution errored', payload);
expect(execBuffer['1'].manual_error?.count).toBe(4);
expect(execBuffer['1'].manual_error?.first).toEqual(execTime1);
});
test('should track production executions count correctly', async () => {
const payload = {
workflow_id: '1',
is_manual: false,
success: true,
error_node_type: 'node_type',
};
// successful execution
const execTime1 = fakeJestSystemTime('2022-01-01 12:00:00');
await telemetry.trackWorkflowExecution(payload);
expect(spyTrack).toHaveBeenCalledTimes(0);
let execBuffer = telemetry.getCountsBuffer();
expect(execBuffer['1'].manual_error).toBeUndefined();
expect(execBuffer['1'].manual_success).toBeUndefined();
expect(execBuffer['1'].prod_error).toBeUndefined();
expect(execBuffer['1'].prod_success?.count).toBe(1);
expect(execBuffer['1'].prod_success?.first).toEqual(execTime1);
// successful execution n8n node
payload.error_node_type = 'n8n-nodes-base.merge';
payload.workflow_id = '2';
await telemetry.trackWorkflowExecution(payload);
expect(spyTrack).toHaveBeenCalledTimes(0);
execBuffer = telemetry.getCountsBuffer();
expect(execBuffer['1'].manual_error).toBeUndefined();
expect(execBuffer['1'].manual_success).toBeUndefined();
expect(execBuffer['1'].prod_error).toBeUndefined();
expect(execBuffer['1'].prod_success?.count).toBe(1);
expect(execBuffer['2'].prod_success?.count).toBe(1);
expect(execBuffer['1'].prod_success?.first).toEqual(execTime1);
expect(execBuffer['2'].prod_success?.first).toEqual(execTime1);
// additional successful execution
payload.error_node_type = 'n8n-nodes-base.merge';
payload.workflow_id = '2';
await telemetry.trackWorkflowExecution(payload);
payload.error_node_type = 'n8n-nodes-base.merge';
payload.workflow_id = '1';
await telemetry.trackWorkflowExecution(payload);
expect(spyTrack).toHaveBeenCalledTimes(0);
execBuffer = telemetry.getCountsBuffer();
expect(execBuffer['1'].manual_error).toBeUndefined();
expect(execBuffer['1'].manual_success).toBeUndefined();
expect(execBuffer['1'].prod_error).toBeUndefined();
expect(execBuffer['2'].manual_error).toBeUndefined();
expect(execBuffer['2'].manual_success).toBeUndefined();
expect(execBuffer['2'].prod_error).toBeUndefined();
expect(execBuffer['1'].prod_success?.count).toBe(2);
expect(execBuffer['2'].prod_success?.count).toBe(2);
expect(execBuffer['1'].prod_success?.first).toEqual(execTime1);
expect(execBuffer['2'].prod_success?.first).toEqual(execTime1);
// failed execution
const execTime2 = fakeJestSystemTime('2022-01-01 12:00:00');
payload.error_node_type = 'custom-package.custom-node';
payload.success = false;
await telemetry.trackWorkflowExecution(payload);
expect(spyTrack).toHaveBeenCalledTimes(0);
execBuffer = telemetry.getCountsBuffer();
expect(execBuffer['1'].manual_error).toBeUndefined();
expect(execBuffer['1'].manual_success).toBeUndefined();
expect(execBuffer['2'].manual_error).toBeUndefined();
expect(execBuffer['2'].manual_success).toBeUndefined();
expect(execBuffer['2'].prod_error).toBeUndefined();
expect(execBuffer['1'].prod_error?.count).toBe(1);
expect(execBuffer['1'].prod_success?.count).toBe(2);
expect(execBuffer['2'].prod_success?.count).toBe(2);
expect(execBuffer['1'].prod_error?.first).toEqual(execTime2);
expect(execBuffer['1'].prod_success?.first).toEqual(execTime1);
expect(execBuffer['2'].prod_success?.first).toEqual(execTime1);
// failed execution n8n node
payload.success = false;
payload.error_node_type = 'n8n-nodes-base.merge';
await telemetry.trackWorkflowExecution(payload);
expect(spyTrack).toHaveBeenCalledTimes(1);
execBuffer = telemetry.getCountsBuffer();
expect(execBuffer['1'].manual_error).toBeUndefined();
expect(execBuffer['1'].manual_success).toBeUndefined();
expect(execBuffer['2'].manual_error).toBeUndefined();
expect(execBuffer['2'].manual_success).toBeUndefined();
expect(execBuffer['2'].prod_error).toBeUndefined();
expect(execBuffer['1'].prod_success?.count).toBe(2);
expect(execBuffer['1'].prod_error?.count).toBe(2);
expect(execBuffer['2'].prod_success?.count).toBe(2);
expect(execBuffer['1'].prod_error?.first).toEqual(execTime2);
expect(execBuffer['1'].prod_success?.first).toEqual(execTime1);
expect(execBuffer['2'].prod_success?.first).toEqual(execTime1);
});
});
describe('pulse', () => {
let pulseSpy: jest.SpyInstance;
beforeAll(() => {
startPulseSpy.mockRestore();
});
beforeEach(() => {
fakeJestSystemTime(testDateTime);
pulseSpy = jest.spyOn(Telemetry.prototype as any, 'pulse').mockName('pulseSpy');
});
afterEach(() => {
pulseSpy.mockClear();
});
xtest('should trigger pulse in intervals', async () => {
expect(pulseSpy).toBeCalledTimes(0);
jest.advanceTimersToNextTimer();
await flushPromises();
expect(pulseSpy).toBeCalledTimes(1);
expect(spyTrack).toHaveBeenCalledTimes(1);
expect(spyTrack).toHaveBeenCalledWith('pulse', {
plan_name_current: 'Community',
quota: -1,
usage: 0,
});
jest.advanceTimersToNextTimer();
await flushPromises();
expect(pulseSpy).toBeCalledTimes(2);
expect(spyTrack).toHaveBeenCalledTimes(2);
expect(spyTrack).toHaveBeenCalledWith('pulse', {
plan_name_current: 'Community',
quota: -1,
usage: 0,
});
});
xtest('should track workflow counts correctly', async () => {
expect(pulseSpy).toBeCalledTimes(0);
let execBuffer = telemetry.getCountsBuffer();
// expect clear counters on start
expect(Object.keys(execBuffer).length).toBe(0);
const payload = {
workflow_id: '1',
is_manual: true,
success: true,
error_node_type: 'custom-nodes-base.node-type',
};
await telemetry.trackWorkflowExecution(payload);
await telemetry.trackWorkflowExecution(payload);
payload.is_manual = false;
payload.success = true;
await telemetry.trackWorkflowExecution(payload);
await telemetry.trackWorkflowExecution(payload);
payload.is_manual = true;
payload.success = false;
await telemetry.trackWorkflowExecution(payload);
await telemetry.trackWorkflowExecution(payload);
payload.is_manual = false;
payload.success = false;
await telemetry.trackWorkflowExecution(payload);
await telemetry.trackWorkflowExecution(payload);
payload.workflow_id = '2';
await telemetry.trackWorkflowExecution(payload);
await telemetry.trackWorkflowExecution(payload);
expect(spyTrack).toHaveBeenCalledTimes(0);
expect(pulseSpy).toBeCalledTimes(0);
jest.advanceTimersToNextTimer();
execBuffer = telemetry.getCountsBuffer();
await flushPromises();
expect(pulseSpy).toBeCalledTimes(1);
expect(spyTrack).toHaveBeenCalledTimes(3);
expect(spyTrack).toHaveBeenNthCalledWith(
1,
'Workflow execution count',
{
event_version: '2',
workflow_id: '1',
user_id: undefined,
manual_error: {
count: 2,
first: testDateTime,
},
manual_success: {
count: 2,
first: testDateTime,
},
prod_error: {
count: 2,
first: testDateTime,
},
prod_success: {
count: 2,
first: testDateTime,
},
},
{ withPostHog: true },
);
expect(spyTrack).toHaveBeenNthCalledWith(
2,
'Workflow execution count',
{
event_version: '2',
workflow_id: '2',
user_id: undefined,
prod_error: {
count: 2,
first: testDateTime,
},
},
{ withPostHog: true },
);
expect(spyTrack).toHaveBeenNthCalledWith(3, 'pulse', {
plan_name_current: 'Community',
quota: -1,
usage: 0,
});
expect(Object.keys(execBuffer).length).toBe(0);
// Adding a second step here because we believe PostHog may use timers for sending data
// and adding posthog to the above metric was causing the pulseSpy timer to not be ran
jest.advanceTimersToNextTimer();
execBuffer = telemetry.getCountsBuffer();
expect(Object.keys(execBuffer).length).toBe(0);
// @TODO: Flushing promises here is not working
// expect(pulseSpy).toBeCalledTimes(2);
// expect(spyTrack).toHaveBeenCalledTimes(4);
// expect(spyTrack).toHaveBeenNthCalledWith(4, 'pulse', {
// plan_name_current: 'Community',
// quota: -1,
// usage: 0,
// });
});
});
});
const fakeJestSystemTime = (dateTime: string | Date): Date => {
const dt = new Date(dateTime);
jest.setSystemTime(dt);
return dt;
};