Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(core): Expand crash recovery to cover queue mode #9676

Merged
merged 24 commits into from
Jun 18, 2024
Merged
Show file tree
Hide file tree
Changes from 21 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
9 changes: 9 additions & 0 deletions packages/cli/src/Queue.ts
Original file line number Diff line number Diff line change
Expand Up @@ -101,6 +101,15 @@ export class Queue {
return await this.jobQueue.getJobs(jobTypes);
}

/**
* Get IDs of executions that are currently in progress in the queue.
*/
async getInProgressExecutionIds() {
const inProgressJobs = await this.getJobs(['active', 'waiting']);

return new Set(inProgressJobs.map((job) => job.data.executionId));
}

async process(concurrency: number, fn: Bull.ProcessCallbackFunction<JobData>): Promise<void> {
return await this.jobQueue.process(concurrency, fn);
}
Expand Down
4 changes: 2 additions & 2 deletions packages/cli/src/commands/start.ts
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@ import type { IWorkflowExecutionDataProcess } from '@/Interfaces';
import { ExecutionService } from '@/executions/execution.service';
import { OwnershipService } from '@/services/ownership.service';
import { WorkflowRunner } from '@/WorkflowRunner';
import { ExecutionRecoveryService } from '@/executions/execution-recovery.service';

// eslint-disable-next-line @typescript-eslint/no-unsafe-assignment, @typescript-eslint/no-var-requires
const open = require('open');
Expand Down Expand Up @@ -65,8 +66,6 @@ export class Start extends BaseCommand {

protected server = Container.get(Server);

private pruningService: PruningService;

constructor(argv: string[], cmdConfig: Config) {
super(argv, cmdConfig);
this.setInstanceType('main');
Expand Down Expand Up @@ -294,6 +293,7 @@ export class Start extends BaseCommand {
await this.server.start();

Container.get(PruningService).init();
Container.get(ExecutionRecoveryService).init();

if (config.getEnv('executions.mode') === 'regular') {
await this.runEnqueuedExecutions();
Expand Down
15 changes: 15 additions & 0 deletions packages/cli/src/config/schema.ts
Original file line number Diff line number Diff line change
Expand Up @@ -371,6 +371,21 @@ export const schema = {
default: 10000,
env: 'EXECUTIONS_DATA_PRUNE_MAX_COUNT',
},

queueRecovery: {
interval: {
doc: 'How often (minutes) to check for queue recovery',
format: Number,
default: 180,
env: 'N8N_EXECUTIONS_QUEUE_RECOVERY_INTERVAL',
},
batchSize: {
doc: 'Size of batch of executions to check for queue recovery',
format: Number,
default: 100,
env: 'N8N_EXECUTIONS_QUEUE_RECOVERY_BATCH',
},
},
},

queue: {
Expand Down
18 changes: 15 additions & 3 deletions packages/cli/src/databases/repositories/execution.repository.ts
Original file line number Diff line number Diff line change
Expand Up @@ -275,9 +275,7 @@ export class ExecutionRepository extends Repository<ExecutionEntity> {
},
);

this.logger.info('[Execution Recovery] Marked executions as `crashed`', {
executionIds,
});
this.logger.info('Marked executions as `crashed`', { executionIds });
}

/**
Expand Down Expand Up @@ -773,4 +771,18 @@ export class ExecutionRepository extends Repository<ExecutionEntity> {

return executions.map(({ id }) => id);
}

/**
* Retrieve a batch of execution IDs with `new` or `running` status, in most recent order.
*/
async getInProgressExecutionIds(batchSize: number) {
const executions = await this.find({
select: ['id'],
where: { status: In(['new', 'running']) },
order: { startedAt: 'DESC' },
take: batchSize,
});

return executions.map(({ id }) => id);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -7,19 +7,23 @@ import { createWorkflow } from '@test-integration/db/workflows';
import { createExecution } from '@test-integration/db/executions';
import * as testDb from '@test-integration/testDb';

import { NodeConnectionType } from 'n8n-workflow';
import { mock } from 'jest-mock-extended';
import { OrchestrationService } from '@/services/orchestration.service';
import config from '@/config';
import { ExecutionRecoveryService } from '@/executions/execution-recovery.service';
import { ExecutionRepository } from '@/databases/repositories/execution.repository';

import { InternalHooks } from '@/InternalHooks';
import { Push } from '@/push';
import { ARTIFICIAL_TASK_DATA } from '@/constants';
import { NodeCrashedError } from '@/errors/node-crashed.error';
import { WorkflowCrashedError } from '@/errors/workflow-crashed.error';
import { EventMessageNode } from '@/eventbus/EventMessageClasses/EventMessageNode';
import { EventMessageWorkflow } from '@/eventbus/EventMessageClasses/EventMessageWorkflow';

import type { EventMessageTypes as EventMessage } from '@/eventbus/EventMessageClasses';
import type { WorkflowEntity } from '@/databases/entities/WorkflowEntity';
import { NodeConnectionType } from 'n8n-workflow';
import type { Logger } from '@/Logger';

/**
* Workflow producing an execution whose data will be truncated by an instance crash.
Expand Down Expand Up @@ -172,27 +176,98 @@ export const setupMessages = (executionId: string, workflowName: string): EventM
};

describe('ExecutionRecoveryService', () => {
let executionRecoveryService: ExecutionRecoveryService;
let push: Push;
let executionRecoveryService: ExecutionRecoveryService;
let orchestrationService: OrchestrationService;
let executionRepository: ExecutionRepository;

beforeAll(async () => {
await testDb.init();

mockInstance(InternalHooks);
push = mockInstance(Push);
executionRepository = Container.get(ExecutionRepository);
executionRecoveryService = new ExecutionRecoveryService(push, executionRepository);
orchestrationService = Container.get(OrchestrationService);

mockInstance(InternalHooks);
executionRecoveryService = new ExecutionRecoveryService(
mock<Logger>(),
push,
executionRepository,
orchestrationService,
);
});

afterEach(async () => {
config.load(config.default);
jest.restoreAllMocks();
await testDb.truncate(['Execution', 'ExecutionData', 'Workflow']);
});

afterAll(async () => {
await testDb.terminate();
});

describe('scheduleQueueRecovery', () => {
describe('queue mode', () => {
it('if leader, should schedule queue recovery', () => {
/**
* Arrange
*/
config.set('executions.mode', 'queue');
jest.spyOn(orchestrationService, 'isLeader', 'get').mockReturnValue(true);
const scheduleSpy = jest.spyOn(executionRecoveryService, 'scheduleQueueRecovery');

/**
* Act
*/
executionRecoveryService.init();

/**
* Assert
*/
expect(scheduleSpy).toHaveBeenCalled();
});

it('if follower, should do nothing', () => {
/**
* Arrange
*/
config.set('executions.mode', 'queue');
jest.spyOn(orchestrationService, 'isLeader', 'get').mockReturnValue(false);
const scheduleSpy = jest.spyOn(executionRecoveryService, 'scheduleQueueRecovery');

/**
* Act
*/
executionRecoveryService.init();

/**
* Assert
*/
expect(scheduleSpy).not.toHaveBeenCalled();
});
});

describe('regular mode', () => {
it('should do nothing', () => {
/**
* Arrange
*/
config.set('executions.mode', 'regular');
const scheduleSpy = jest.spyOn(executionRecoveryService, 'scheduleQueueRecovery');

/**
* Act
*/
executionRecoveryService.init();

/**
* Assert
*/
expect(scheduleSpy).not.toHaveBeenCalled();
});
});
});

describe('recoverFromLogs', () => {
describe('if no messages', () => {
test('should return `null` if no execution found', async () => {
Expand Down
130 changes: 128 additions & 2 deletions packages/cli/src/executions/execution-recovery.service.ts
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
import Container, { Service } from 'typedi';
import { Push } from '@/push';
import { sleep } from 'n8n-workflow';
import { jsonStringify, sleep } from 'n8n-workflow';
import { ExecutionRepository } from '@db/repositories/execution.repository';
import { getWorkflowHooksMain } from '@/WorkflowExecuteAdditionalData'; // @TODO: Dependency cycle
import { InternalHooks } from '@/InternalHooks'; // @TODO: Dependency cycle if injected
Expand All @@ -11,17 +11,48 @@ import type { IExecutionResponse } from '@/Interfaces';
import { NodeCrashedError } from '@/errors/node-crashed.error';
import { WorkflowCrashedError } from '@/errors/workflow-crashed.error';
import { ARTIFICIAL_TASK_DATA } from '@/constants';
import { Logger } from '@/Logger';
import config from '@/config';
import { OnShutdown } from '@/decorators/OnShutdown';
import type { QueueRecoverySettings } from './execution.types';
import { OrchestrationService } from '@/services/orchestration.service';

/**
* Service for recovering key properties in executions.
*/
@Service()
export class ExecutionRecoveryService {
constructor(
private readonly logger: Logger,
private readonly push: Push,
private readonly executionRepository: ExecutionRepository,
private readonly orchestrationService: OrchestrationService,
) {}

/**
* @important Requires `OrchestrationService` to be initialized on queue mode.
*/
init() {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I love how simple and easy this is to read now, thanks!

if (config.getEnv('executions.mode') === 'regular') return;

const { isLeader, isMultiMainSetupEnabled } = this.orchestrationService;

if (isLeader) this.scheduleQueueRecovery();

if (isMultiMainSetupEnabled) {
this.orchestrationService.multiMainSetup
.on('leader-takeover', () => this.scheduleQueueRecovery())
.on('leader-stepdown', () => this.stopQueueRecovery());
}
}

private readonly queueRecoverySettings: QueueRecoverySettings = {
batchSize: config.getEnv('executions.queueRecovery.batchSize'),
waitMs: config.getEnv('executions.queueRecovery.interval') * 60 * 1000,
};

private isShuttingDown = false;

/**
* Recover key properties of a truncated execution using event logs.
*/
Expand All @@ -30,6 +61,10 @@ export class ExecutionRecoveryService {

if (!amendedExecution) return null;

this.logger.info('[Recovery] Logs available, amended execution', {
executionId: amendedExecution.id,
});

await this.executionRepository.updateExistingExecution(executionId, amendedExecution);

await this.runHooks(amendedExecution);
Expand All @@ -42,12 +77,89 @@ export class ExecutionRecoveryService {
return amendedExecution;
}

/**
* Schedule a cycle to mark dangling executions as crashed in queue mode.
*/
scheduleQueueRecovery(waitMs = this.queueRecoverySettings.waitMs) {
ivov marked this conversation as resolved.
Show resolved Hide resolved
if (!this.shouldScheduleQueueRecovery()) return;

this.queueRecoverySettings.timeout = setTimeout(async () => {
try {
const nextWaitMs = await this.recoverFromQueue();
this.scheduleQueueRecovery(nextWaitMs);
} catch (error) {
const msg = this.toErrorMsg(error);

this.logger.error('[Recovery] Failed to recover dangling executions from queue', { msg });
this.logger.error('[Recovery] Retrying...');

this.scheduleQueueRecovery();
}
}, waitMs);

const wait = [this.queueRecoverySettings.waitMs / (60 * 1000), 'min'].join(' ');

this.logger.debug(`[Recovery] Scheduled queue recovery check for next ${wait}`);
}

stopQueueRecovery() {
clearTimeout(this.queueRecoverySettings.timeout);
}

@OnShutdown()
shutdown() {
this.isShuttingDown = true;
this.stopQueueRecovery();
}

// ----------------------------------
// private
// ----------------------------------

/**
* Amend `status`, `stoppedAt`, and (if possible) `data` properties of an execution.
* Mark in-progress executions as `crashed` if stored in DB as `new` or `running`
* but absent from the queue. Return time until next recovery cycle.
*/
private async recoverFromQueue() {
const { waitMs, batchSize } = this.queueRecoverySettings;

const storedIds = await this.executionRepository.getInProgressExecutionIds(batchSize);

if (storedIds.length === 0) {
this.logger.debug('[Recovery] Completed queue recovery check, no dangling executions');
return waitMs;
}

const { Queue } = await import('@/Queue');

const queuedIds = await Container.get(Queue).getInProgressExecutionIds();

if (queuedIds.size === 0) {
this.logger.debug('[Recovery] Completed queue recovery check, no dangling executions');
return waitMs;
}

const danglingIds = storedIds.filter((id) => !queuedIds.has(id));

if (danglingIds.length === 0) {
this.logger.debug('[Recovery] Completed queue recovery check, no dangling executions');
return waitMs;
}

await this.executionRepository.markAsCrashed(danglingIds);

this.logger.info('[Recovery] Completed queue recovery check, recovered dangling executions', {
danglingIds,
});

// if this cycle used up the whole batch size, it is possible for there to be
// dangling executions outside this check, so speed up next cycle

return storedIds.length >= this.queueRecoverySettings.batchSize ? waitMs / 2 : waitMs;
}

/**
* Amend `status`, `stoppedAt`, and (if possible) `data` of an execution using event logs.
*/
private async amend(executionId: string, messages: EventMessageTypes[]) {
if (messages.length === 0) return await this.amendWithoutLogs(executionId);
Expand Down Expand Up @@ -194,4 +306,18 @@ export class ExecutionRecoveryService {

await externalHooks.executeHookFunctions('workflowExecuteAfter', [run]);
}

private toErrorMsg(error: unknown) {
return error instanceof Error
? error.message
: jsonStringify(error, { replaceCircularRefs: true });
}

private shouldScheduleQueueRecovery() {
return (
config.getEnv('executions.mode') === 'queue' &&
config.getEnv('multiMainSetup.instanceType') === 'leader' &&
!this.isShuttingDown
);
}
}
Loading