diff --git a/apps/tasks/src/diagnostics.ts b/apps/tasks/src/diagnostics.ts new file mode 100644 index 000000000..dd7a2e497 --- /dev/null +++ b/apps/tasks/src/diagnostics.ts @@ -0,0 +1,34 @@ +const bytesToMiB = (bytes: number) => Number((bytes / (1024 * 1024)).toFixed(2)); + +const getActiveHandlesCount = () => { + const processWithHandles = process as NodeJS.Process & { + _getActiveHandles?: () => unknown[]; + }; + return processWithHandles._getActiveHandles?.().length ?? null; +}; + +const getActiveRequestsCount = () => { + const processWithRequests = process as NodeJS.Process & { + _getActiveRequests?: () => unknown[]; + }; + return processWithRequests._getActiveRequests?.().length ?? null; +}; + +export const getTasksRuntimeDiagnostics = () => { + const memory = process.memoryUsage(); + const resources = process.resourceUsage(); + + return { + rssMiB: bytesToMiB(memory.rss), + heapUsedMiB: bytesToMiB(memory.heapUsed), + heapTotalMiB: bytesToMiB(memory.heapTotal), + externalMiB: bytesToMiB(memory.external), + arrayBuffersMiB: bytesToMiB(memory.arrayBuffers), + uptimeSeconds: Number(process.uptime().toFixed(0)), + userCpuMicros: resources.userCPUTime, + systemCpuMicros: resources.systemCPUTime, + maxRssKiB: resources.maxRSS, + activeHandles: getActiveHandlesCount(), + activeRequests: getActiveRequestsCount(), + }; +}; diff --git a/apps/tasks/src/main.ts b/apps/tasks/src/main.ts index 55416e689..9edbfc828 100644 --- a/apps/tasks/src/main.ts +++ b/apps/tasks/src/main.ts @@ -2,11 +2,41 @@ import "./overrides"; import { jobGroup } from "@homarr/cron-jobs"; +import { createLogger } from "@homarr/core/infrastructure/logs"; +import { getTasksRuntimeDiagnostics } from "./diagnostics"; import { onStartAsync } from "./on-start"; +const logger = createLogger({ module: "tasksMain" }); +const RUNTIME_DIAGNOSTICS_INTERVAL_MS = 60_000; + +const scheduleRuntimeDiagnostics = () => { + setInterval(() => { + logger.info("Tasks runtime diagnostics", { + diagnostics: getTasksRuntimeDiagnostics(), + }); + }, RUNTIME_DIAGNOSTICS_INTERVAL_MS).unref(); +}; + void (async () => { + logger.info("Tasks runtime bootstrap started", { + diagnostics: getTasksRuntimeDiagnostics(), + }); + await onStartAsync(); + logger.info("Tasks on-start hooks completed", { + diagnostics: getTasksRuntimeDiagnostics(), + }); + await jobGroup.initializeAsync(); + logger.info("Cron job group initialized in tasks runtime", { + diagnostics: getTasksRuntimeDiagnostics(), + }); + await jobGroup.startAllAsync(); + logger.info("Cron job group started in tasks runtime", { + diagnostics: getTasksRuntimeDiagnostics(), + jobs: jobGroup.getKeys(), + }); + scheduleRuntimeDiagnostics(); })(); diff --git a/apps/tasks/src/overrides.ts b/apps/tasks/src/overrides.ts index 684531f81..28be7e482 100644 --- a/apps/tasks/src/overrides.ts +++ b/apps/tasks/src/overrides.ts @@ -1,5 +1,8 @@ import { setGlobalDispatcher } from "undici"; import { UndiciHttpAgent } from "@homarr/core/infrastructure/http"; +import { createLogger } from "@homarr/core/infrastructure/logs"; +const logger = createLogger({ module: "tasksOverrides" }); setGlobalDispatcher(new UndiciHttpAgent()); +logger.info("Configured global undici dispatcher for tasks runtime"); diff --git a/packages/cron-jobs-core/src/creator.ts b/packages/cron-jobs-core/src/creator.ts index f693a054e..690e373cf 100644 --- a/packages/cron-jobs-core/src/creator.ts +++ b/packages/cron-jobs-core/src/creator.ts @@ -7,6 +7,7 @@ import { db } from "@homarr/db"; import type { Logger } from "./logger"; import type { ValidateCron } from "./validation"; +import { createProcessDiagnosticsDelta, createProcessDiagnosticsSnapshot } from "./diagnostics"; export interface CreateCronJobCreatorOptions { beforeCallback?: (name: TAllowedNames) => MaybePromise; @@ -33,19 +34,25 @@ const createCallback = MaybePromise) => { const catchingCallbackAsync = async () => { + const beforeExecutionSnapshot = createProcessDiagnosticsSnapshot(); try { creatorOptions.logger.logDebug("The callback of cron job started", { name, + diagnostics: beforeExecutionSnapshot, }); const stopwatch = new Stopwatch(); await creatorOptions.beforeCallback?.(name); const beforeCallbackTook = stopwatch.getElapsedInHumanWords(); await callback(); + const afterExecutionSnapshot = createProcessDiagnosticsSnapshot(); const callbackTook = stopwatch.getElapsedInHumanWords(); creatorOptions.logger.logDebug("The callback of cron job succeeded", { name, beforeCallbackTook, callbackTook, + diagnosticsBefore: beforeExecutionSnapshot, + diagnosticsAfter: afterExecutionSnapshot, + diagnosticsDelta: createProcessDiagnosticsDelta(beforeExecutionSnapshot, afterExecutionSnapshot), }); const durationInMillis = stopwatch.getElapsedInMilliseconds(); @@ -58,11 +65,15 @@ const createCallback = Number((bytes / (1024 * 1024)).toFixed(2)); + +const getActiveHandlesCount = () => { + const processWithHandles = process as NodeJS.Process & { + _getActiveHandles?: () => unknown[]; + }; + return processWithHandles._getActiveHandles?.().length ?? null; +}; + +const getActiveRequestsCount = () => { + const processWithRequests = process as NodeJS.Process & { + _getActiveRequests?: () => unknown[]; + }; + return processWithRequests._getActiveRequests?.().length ?? null; +}; + +export interface ProcessDiagnosticsSnapshot { + rssMiB: number; + heapUsedMiB: number; + heapTotalMiB: number; + externalMiB: number; + arrayBuffersMiB: number; + uptimeSeconds: number; + userCpuMicros: number; + systemCpuMicros: number; + maxRssKiB: number; + activeHandles: number | null; + activeRequests: number | null; +} + +export const createProcessDiagnosticsSnapshot = (): ProcessDiagnosticsSnapshot => { + const memory = process.memoryUsage(); + const resources = process.resourceUsage(); + + return { + rssMiB: bytesToMiB(memory.rss), + heapUsedMiB: bytesToMiB(memory.heapUsed), + heapTotalMiB: bytesToMiB(memory.heapTotal), + externalMiB: bytesToMiB(memory.external), + arrayBuffersMiB: bytesToMiB(memory.arrayBuffers), + uptimeSeconds: Number(process.uptime().toFixed(0)), + userCpuMicros: resources.userCPUTime, + systemCpuMicros: resources.systemCPUTime, + maxRssKiB: resources.maxRSS, + activeHandles: getActiveHandlesCount(), + activeRequests: getActiveRequestsCount(), + }; +}; + +export const createProcessDiagnosticsDelta = ( + before: ProcessDiagnosticsSnapshot, + after: ProcessDiagnosticsSnapshot, +) => { + return { + rssMiB: Number((after.rssMiB - before.rssMiB).toFixed(2)), + heapUsedMiB: Number((after.heapUsedMiB - before.heapUsedMiB).toFixed(2)), + heapTotalMiB: Number((after.heapTotalMiB - before.heapTotalMiB).toFixed(2)), + externalMiB: Number((after.externalMiB - before.externalMiB).toFixed(2)), + arrayBuffersMiB: Number((after.arrayBuffersMiB - before.arrayBuffersMiB).toFixed(2)), + uptimeSeconds: Number((after.uptimeSeconds - before.uptimeSeconds).toFixed(0)), + userCpuMicros: after.userCpuMicros - before.userCpuMicros, + systemCpuMicros: after.systemCpuMicros - before.systemCpuMicros, + maxRssKiB: after.maxRssKiB - before.maxRssKiB, + activeHandles: + before.activeHandles === null || after.activeHandles === null ? null : after.activeHandles - before.activeHandles, + activeRequests: + before.activeRequests === null || after.activeRequests === null + ? null + : after.activeRequests - before.activeRequests, + }; +}; diff --git a/packages/cron-jobs-core/src/group.ts b/packages/cron-jobs-core/src/group.ts index cfb024a9a..4815bd634 100644 --- a/packages/cron-jobs-core/src/group.ts +++ b/packages/cron-jobs-core/src/group.ts @@ -4,6 +4,7 @@ import { objectEntries, objectKeys } from "@homarr/common"; import { db } from "@homarr/db"; import type { JobCallback } from "./creator"; +import { createProcessDiagnosticsSnapshot } from "./diagnostics"; import type { Logger } from "./logger"; import { jobRegistry } from "./registry"; @@ -38,6 +39,10 @@ export const createJobGroupCreator = ( return { initializeAsync: async () => { + options.logger.logInfo("Initializing cron job group", { + registeredJobs: [...jobRegistry.keys()], + diagnostics: createProcessDiagnosticsSnapshot(), + }); const configurations = await db.query.cronJobConfigurations.findMany(); for (const job of jobRegistry.values()) { const configuration = configurations.find(({ name }) => name === job.name); @@ -51,7 +56,15 @@ export const createJobGroupCreator = ( const scheduledTask = await job.createTaskAsync(); tasks.set(job.name, scheduledTask); + options.logger.logDebug("Created scheduled task for cron job", { + name: job.name, + diagnostics: createProcessDiagnosticsSnapshot(), + }); } + options.logger.logInfo("Cron job group initialized", { + taskCount: tasks.size, + diagnostics: createProcessDiagnosticsSnapshot(), + }); }, startAsync: async (name: keyof TJobs) => { const job = jobRegistry.get(name as string); @@ -65,6 +78,10 @@ export const createJobGroupCreator = ( tasks.get(name as string)?.resume(); }, startAllAsync: async () => { + options.logger.logInfo("Starting all cron jobs", { + taskCount: tasks.size, + diagnostics: createProcessDiagnosticsSnapshot(), + }); for (const job of jobRegistry.values()) { if (!tasks.has(job.name)) { continue; @@ -76,6 +93,10 @@ export const createJobGroupCreator = ( await job.onStartAsync(); tasks.get(job.name)?.resume(); } + options.logger.logInfo("Started all cron jobs", { + taskCount: tasks.size, + diagnostics: createProcessDiagnosticsSnapshot(), + }); }, runManuallyAsync: async (name: keyof TJobs) => { const job = jobRegistry.get(name as string);