diff --git a/ghost/core/core/server/data/importer/import-manager.js b/ghost/core/core/server/data/importer/import-manager.js index ef2e5de90c0b..25c47255da60 100644 --- a/ghost/core/core/server/data/importer/import-manager.js +++ b/ghost/core/core/server/data/importer/import-manager.js @@ -9,7 +9,6 @@ const { extract } = require('@tryghost/zip'); const tpl = require('@tryghost/tpl'); const debug = require('@tryghost/debug')('import-manager'); const logging = require('@tryghost/logging'); -const jobLogging = require('../../services/jobs/job-logging'); const errors = require('@tryghost/errors'); const ImageHandler = require('./handlers/image'); const ImporterContentFileHandler = require('./handlers/importer-content-file-handler'); @@ -545,11 +544,11 @@ class ImportManager { const env = config.get('env'); if (!env?.startsWith('testing') && !importOptions.runningInJob) { - jobLogging.info('[Background Job] site-content-import queued'); + logging.info('[Background Job] site-content-import queued'); return jobManager.addJob({ job: async () => { const startedAt = Date.now(); - jobLogging.info('[Background Job] site-content-import started'); + logging.info('[Background Job] site-content-import started'); try { const result = await this.importFromFile( file, @@ -561,17 +560,17 @@ class ImportManager { // importFromFile swallows its own failures and returns undefined, // so an absent result is the only signal that the import failed. if (result === undefined) { - jobLogging.info( + logging.info( `[Background Job] site-content-import failed after ${Date.now() - startedAt}ms`, ); } else { - jobLogging.info( + logging.info( `[Background Job] site-content-import completed in ${Date.now() - startedAt}ms`, ); } return result; } catch (err) { - jobLogging.error( + logging.error( err, `[Background Job] site-content-import failed after ${Date.now() - startedAt}ms`, ); @@ -596,7 +595,7 @@ class ImportManager { return importResult; } catch (err) { - jobLogging.error(err, '[Background Job] site-content-import error'); + logging.error(err, '[Background Job] site-content-import error'); const errorDetails = err.errorDetails || [err]; importResult = { data: { errors: errorDetails } }; } finally { diff --git a/ghost/core/core/server/services/email-analytics/email-analytics-service-wrapper.ts b/ghost/core/core/server/services/email-analytics/email-analytics-service-wrapper.ts index 22612e9b321d..7f9d8e984cbd 100644 --- a/ghost/core/core/server/services/email-analytics/email-analytics-service-wrapper.ts +++ b/ghost/core/core/server/services/email-analytics/email-analytics-service-wrapper.ts @@ -14,8 +14,6 @@ import type { BatchEventProcessor } from './batch-event-processor'; import type { Queries } from './lib/queries'; import { fetchMailgunEvents } from './fetch-mailgun-events'; -const jobLogging = require('../jobs/job-logging'); - export class EmailAnalyticsServiceWrapper { #logName: string; #config?: Pick; @@ -157,7 +155,7 @@ export class EmailAnalyticsServiceWrapper { `Events: opened=${result.opened} delivered=${result.delivered} failed=${result.permanentFailed + result.temporaryFailed} unprocessable=${result.unprocessable}`, ].join(' | '); - jobLogging.info(logMessage); + logging.info(logMessage); // We're only concerned with open throughput as this is displayed to users and is most sensitive to being up to date if (jobType === 'latest-opened') { @@ -255,7 +253,7 @@ export class EmailAnalyticsServiceWrapper { try { await this.service.restoreScheduled(); } catch (e) { - jobLogging.error( + logging.error( e, `[Background Job] ${this.#backgroundJobName} failed while restoring scheduled events after ${Date.now() - startedAt}ms`, ); @@ -264,7 +262,7 @@ export class EmailAnalyticsServiceWrapper { } if (this.#fetching) { - jobLogging.info( + logging.info( `[Background Job] ${this.#backgroundJobName} skipped because a fetch is already running`, ); return; @@ -301,26 +299,26 @@ export class EmailAnalyticsServiceWrapper { return; } - jobLogging.info( + logging.info( `[Background Job] ${this.#backgroundJobName} completed in ${Date.now() - startedAt}ms with ${c1 + c2 + c3 + c4} events | ${this.#logPrefix}`, ); this.#fetching = false; } catch (e) { - jobLogging.error( + logging.error( e, `[Background Job] ${this.#backgroundJobName} failed after ${Date.now() - startedAt}ms`, ); // Log again only the error, otherwise we lose the stack trace - jobLogging.error(e); + logging.error(e); } this.#fetching = false; } _restartFetch(reason: string): void { this.#fetching = false; - jobLogging.info(`[Background Job] ${this.#backgroundJobName} continuing due to ${reason}`); + logging.info(`[Background Job] ${this.#backgroundJobName} continuing due to ${reason}`); this.startFetch(); } } diff --git a/ghost/core/core/server/services/email-analytics/jobs/email-analytics-job-scheduler.ts b/ghost/core/core/server/services/email-analytics/jobs/email-analytics-job-scheduler.ts index fdcc2d4fa429..f8e21a1b562a 100644 --- a/ghost/core/core/server/services/email-analytics/jobs/email-analytics-job-scheduler.ts +++ b/ghost/core/core/server/services/email-analytics/jobs/email-analytics-job-scheduler.ts @@ -1,7 +1,7 @@ import * as path from 'node:path'; import moment from 'moment'; -const jobLogging = require('../../jobs/job-logging'); +const logging = require('@tryghost/logging'); type CountableQuery = { where(column: string, operator: string, value: unknown): CountableQuery; @@ -92,7 +92,7 @@ export class EmailAnalyticsJobScheduler { if (emailCount > 0 && !this.#hasScheduledNewslettersJob) { const at = randomFiveMinuteCron(); - jobLogging.info(`[Background Job] email-analytics-fetch-latest scheduled at ${at}`); + logging.info(`[Background Job] email-analytics-fetch-latest scheduled at ${at}`); this.#jobManager.addJob({ at, job: path.resolve(__dirname, 'fetch-latest/index.js'), @@ -125,7 +125,7 @@ export class EmailAnalyticsJobScheduler { } const at = randomFiveMinuteCron(); - jobLogging.info(`[Background Job] email-analytics-automation-fetch-latest scheduled at ${at}`); + logging.info(`[Background Job] email-analytics-automation-fetch-latest scheduled at ${at}`); this.#jobManager.addJob({ at, job: path.resolve(__dirname, 'automation-fetch-latest/index.js'), @@ -155,7 +155,7 @@ export class EmailAnalyticsJobScheduler { } const at = randomFiveMinuteCron(); - jobLogging.info(`[Background Job] email-analytics-gift-fetch-latest scheduled at ${at}`); + logging.info(`[Background Job] email-analytics-gift-fetch-latest scheduled at ${at}`); this.#jobManager.addJob({ at, job: path.resolve(__dirname, 'gift-fetch-latest/index.js'), diff --git a/ghost/core/core/server/services/email-service/batch-sending-service.js b/ghost/core/core/server/services/email-service/batch-sending-service.js index 411c420c5c19..ddb970c94b06 100644 --- a/ghost/core/core/server/services/email-service/batch-sending-service.js +++ b/ghost/core/core/server/services/email-service/batch-sending-service.js @@ -1,5 +1,4 @@ const logging = require('@tryghost/logging'); -const jobLogging = require('../jobs/job-logging'); const ObjectID = require('bson-objectid').default; const errors = require('@tryghost/errors'); const tpl = require('@tryghost/tpl'); @@ -198,7 +197,7 @@ class BatchSendingService { * @returns {void} */ scheduleEmail(email) { - jobLogging.info(`[Background Job] batch-sending-service-job queued for email ${email.id}`); + logging.info(`[Background Job] batch-sending-service-job queued for email ${email.id}`); return this.#jobsService.addJob({ name: 'batch-sending-service-job', job: this.emailJob.bind(this), @@ -212,7 +211,7 @@ class BatchSendingService { * @param {{emailId: string}} data Data passed from the job service. We only need the emailId because we need to refetch the email anyway to make sure the status is right and 'locked'. */ async emailJob({ emailId }) { - jobLogging.info(`[Background Job] batch-sending-service-job started for email ${emailId}`); + logging.info(`[Background Job] batch-sending-service-job started for email ${emailId}`); const startTime = Date.now(); @@ -233,14 +232,14 @@ class BatchSendingService { }, ); } catch (err) { - jobLogging.error( + logging.error( err, `[Background Job] batch-sending-service-job failed while acquiring the status lock after ${Date.now() - startTime}ms`, ); throw err; } if (!email) { - jobLogging.error( + logging.error( `[Background Job] batch-sending-service-job skipped because email ${emailId} is not pending or failed`, ); return; @@ -273,7 +272,7 @@ class BatchSendingService { }, { ...this.#getAfterRetryConfig(), description: `email ${emailId} -> submitted` }, ); - jobLogging.info( + logging.info( `[Background Job] batch-sending-service-job completed for email ${emailId} in ${Date.now() - startTime}ms`, ); } catch (e) { @@ -281,7 +280,7 @@ class BatchSendingService { // collapsed budgets surface transient errors as hard failures, and `failed` // drops the email out of the boot resume scan. if ((e && e.code === SHUTDOWN_CODE) || this.#shuttingDown) { - jobLogging.info( + logging.info( `[Background Job] batch-sending-service-job send stopped because the container is shutting down — leaving email ${email.id} status=submitting so it can resume on next boot`, ); return; @@ -292,7 +291,7 @@ class BatchSendingService { message: `Error sending email ${email.id}`, }); - jobLogging.error( + logging.error( ghostError, `[Background Job] batch-sending-service-job failed for email ${emailId} after ${Date.now() - startTime}ms`, ); diff --git a/ghost/core/core/server/services/gifts/index.ts b/ghost/core/core/server/services/gifts/index.ts index ace8d47b0e31..e452c39813e8 100644 --- a/ghost/core/core/server/services/gifts/index.ts +++ b/ghost/core/core/server/services/gifts/index.ts @@ -41,7 +41,6 @@ export async function init(options: GiftServiceInitOptions): Promise { const staffService = require('../staff'); const DomainEvents = require('@tryghost/domain-events'); const logging = require('@tryghost/logging'); - const jobLogging = require('../jobs/job-logging'); const { SubscriptionActivatedEvent } = require('../../../shared/events'); const StartGiftReminderFlushEvent = require('./events/start-gift-reminder-flush-event'); const StartGiftCleanupEvent = require('./events/start-gift-cleanup-event'); @@ -131,15 +130,15 @@ export async function init(options: GiftServiceInitOptions): Promise { DomainEvents.subscribe(StartGiftReminderFlushEvent, async () => { const start = Date.now(); - jobLogging.info('[Background Job] send-gift-reminders started'); + logging.info('[Background Job] send-gift-reminders started'); try { const { remindedCount, skippedCount, failedCount } = await giftService.processReminders(); - jobLogging.info( + logging.info( `[Background Job] send-gift-reminders completed in ${Date.now() - start}ms: ${remindedCount} sent, ${skippedCount} not due, ${failedCount} rejected`, ); } catch (err) { - jobLogging.error( + logging.error( err, `[Background Job] send-gift-reminders failed after ${Date.now() - start}ms`, ); @@ -158,56 +157,53 @@ export async function init(options: GiftServiceInitOptions): Promise { DomainEvents.subscribe(StartGiftCleanupEvent, async () => { const cleanupStart = Date.now(); - jobLogging.info('[Background Job] clean-gifts started'); + logging.info('[Background Job] clean-gifts started'); const checkoutStart = Date.now(); try { const { deletedCount } = await giftService.processAbandonedCheckouts(); - jobLogging.info( + logging.info( `[Background Job] clean-gifts processed abandoned checkouts: deleted ${deletedCount} in ${Date.now() - checkoutStart}ms`, ); } catch (err) { - jobLogging.error(err, '[Background Job] clean-gifts error processing abandoned checkouts'); + logging.error(err, '[Background Job] clean-gifts error processing abandoned checkouts'); } const consumedStart = Date.now(); try { const { consumedCount, updatedMemberCount } = await giftService.processConsumed(); - jobLogging.info( + logging.info( `[Background Job] clean-gifts processed consumed gifts: consumed ${consumedCount}, updated ${updatedMemberCount} members in ${Date.now() - consumedStart}ms`, ); } catch (err) { - jobLogging.error(err, '[Background Job] clean-gifts error processing consumed gifts'); + logging.error(err, '[Background Job] clean-gifts error processing consumed gifts'); } const expiredStart = Date.now(); try { const { expiredCount } = await giftService.processExpired(); - jobLogging.info( + logging.info( `[Background Job] clean-gifts processed expired gifts: expired ${expiredCount} in ${Date.now() - expiredStart}ms`, ); } catch (err) { - jobLogging.error(err, '[Background Job] clean-gifts error processing expired gifts'); + logging.error(err, '[Background Job] clean-gifts error processing expired gifts'); } try { const { sentCount, skippedCount, failedCount } = await giftDeliveryService.recoverPending(); if (sentCount + skippedCount + failedCount > 0) { - jobLogging.info( + logging.info( `[Background Job] clean-gifts processed pending gift deliveries: ${sentCount} sent, ${skippedCount} not due, ${failedCount} rejected`, ); } } catch (err) { - jobLogging.error( - err, - '[Background Job] clean-gifts error processing pending gift deliveries', - ); + logging.error(err, '[Background Job] clean-gifts error processing pending gift deliveries'); } - jobLogging.info(`[Background Job] clean-gifts completed in ${Date.now() - cleanupStart}ms`); + logging.info(`[Background Job] clean-gifts completed in ${Date.now() - cleanupStart}ms`); }); jobs.scheduleGiftCleanupJob(); diff --git a/ghost/core/core/server/services/gifts/jobs/index.js b/ghost/core/core/server/services/gifts/jobs/index.js index 815f923b91e8..1c52483a60b0 100644 --- a/ghost/core/core/server/services/gifts/jobs/index.js +++ b/ghost/core/core/server/services/gifts/jobs/index.js @@ -1,5 +1,5 @@ const path = require('path'); -const jobLogging = require('../../jobs/job-logging'); +const logging = require('@tryghost/logging'); const jobsService = require('../../jobs'); let hasScheduled = { @@ -21,7 +21,7 @@ function scheduleJob(key, name, jobFile) { const at = `${s} ${m} ${h} * * *`; - jobLogging.info(`[Background Job] ${name} scheduled at ${at}`); + logging.info(`[Background Job] ${name} scheduled at ${at}`); jobsService.addJob({ at, job: path.resolve(__dirname, jobFile), diff --git a/ghost/core/core/server/services/jobs-service/jobs-service.ts b/ghost/core/core/server/services/jobs-service/jobs-service.ts index 52155bc4efdc..6126037f90d7 100644 --- a/ghost/core/core/server/services/jobs-service/jobs-service.ts +++ b/ghost/core/core/server/services/jobs-service/jobs-service.ts @@ -11,7 +11,6 @@ import { Job, JobConstructor, JobHandler } from './job'; export interface JobsLogger { error(...args: unknown[]): void; info(...args: unknown[]): void; - warn(...args: unknown[]): void; } export interface JobsErrorReporter { @@ -112,11 +111,30 @@ export class JobsService { return; } + const startedAt = Date.now(); + this.#logging.info(`[Background Job] ${envelope.type} started`); + try { await deliver(envelope.payload); } catch (err) { + this.#logging.error( + err, + `[Background Job] ${envelope.type} failed after ${Date.now() - startedAt}ms`, + ); this.#sentry?.captureException(err, { tags: { job_type: envelope.type } }); throw err; } + + const durationMs = Date.now() - startedAt; + this.#logging.info( + { + system: { + event: 'job.completed', + job_type: envelope.type, + duration_ms: durationMs, + }, + }, + `[Background Job] ${envelope.type} completed in ${durationMs}ms`, + ); } } diff --git a/ghost/core/core/server/services/jobs-service/register-job-handlers.ts b/ghost/core/core/server/services/jobs-service/register-job-handlers.ts index 664b3ca38028..8aef20f6e29f 100644 --- a/ghost/core/core/server/services/jobs-service/register-job-handlers.ts +++ b/ghost/core/core/server/services/jobs-service/register-job-handlers.ts @@ -2,35 +2,13 @@ import { getInstance } from './index'; import CleanTokensJob from '../members/jobs/clean-tokens-job'; import cleanTokens from '../members/jobs/clean-tokens-task'; -const jobLogging = require('../jobs/job-logging'); +const logging = require('@tryghost/logging'); export default function registerJobHandlers(): void { const jobsService = getInstance(); const db = require('../../data/db'); jobsService.handle(CleanTokensJob, async () => { - const startedAt = Date.now(); - jobLogging.info('[Background Job] clean-tokens started'); - - try { - const deletedCount = await cleanTokens({ db }); - const durationMs = Date.now() - startedAt; - jobLogging.info( - { - system: { - event: 'clean_tokens.completed', - deleted_count: deletedCount, - duration_ms: durationMs, - }, - }, - `[Background Job] clean-tokens completed in ${durationMs}ms: removed ${deletedCount} tokens older than 24 hours`, - ); - } catch (error) { - jobLogging.error( - error, - `[Background Job] clean-tokens failed after ${Date.now() - startedAt}ms`, - ); - throw error; - } + await cleanTokens({ db, logging }); }); } diff --git a/ghost/core/core/server/services/jobs/job-logging.ts b/ghost/core/core/server/services/jobs/job-logging.ts deleted file mode 100644 index 0cfd1b264143..000000000000 --- a/ghost/core/core/server/services/jobs/job-logging.ts +++ /dev/null @@ -1,19 +0,0 @@ -import logging from '@tryghost/logging'; - -type LogMethod = 'info' | 'error'; - -function bestEffort(method: LogMethod, args: unknown[]): void { - try { - logging[method](...args); - } catch { - // Observability must not control background-job execution. - } -} - -export function info(...args: unknown[]): void { - bestEffort('info', args); -} - -export function error(...args: unknown[]): void { - bestEffort('error', args); -} diff --git a/ghost/core/core/server/services/jobs/job-service.js b/ghost/core/core/server/services/jobs/job-service.js index a979b603fdc4..adbc2b239769 100644 --- a/ghost/core/core/server/services/jobs/job-service.js +++ b/ghost/core/core/server/services/jobs/job-service.js @@ -5,14 +5,13 @@ const JobManager = require('@tryghost/job-manager'); const logging = require('@tryghost/logging'); -const jobLogging = require('./job-logging'); const models = require('../../models'); const sentry = require('../../../shared/sentry'); const domainEvents = require('@tryghost/domain-events'); const config = require('../../../shared/config'); const WorkerModelEventBridge = require('./worker-model-event-bridge'); const errorHandler = (error, workerMeta) => { - jobLogging.error(error, `[Background Job] ${workerMeta.name} failed`); + logging.error(error, `[Background Job] ${workerMeta.name} failed`); sentry.captureException(error); }; const events = require('../../lib/common/events'); @@ -27,7 +26,7 @@ const workerMessageHandler = ({ name, message }) => { } if (typeof message === 'string' && !['done', 'cancelled'].includes(message)) { - jobLogging.info(`[Background Job] ${name}: ${message}`); + logging.info(`[Background Job] ${name}: ${message}`); } }; diff --git a/ghost/core/core/server/services/media-inliner/service.js b/ghost/core/core/server/services/media-inliner/service.js index c2f0959bb3ef..33ebee883048 100644 --- a/ghost/core/core/server/services/media-inliner/service.js +++ b/ghost/core/core/server/services/media-inliner/service.js @@ -2,7 +2,7 @@ module.exports = { async init() { const debug = require('@tryghost/debug')('mediaInliner'); const MediaInliner = require('./external-media-inliner'); - const jobLogging = require('../jobs/job-logging'); + const logging = require('@tryghost/logging'); const models = require('../../models'); const jobsService = require('../jobs'); const adapterManager = require('../../services/adapter-manager').default; @@ -42,20 +42,20 @@ module.exports = { // @NOTE: the job is "inline" (aka non-offloaded into a thread), because usecases are currently // limited to migrational, so there is no expectations for site's availability etc. - jobLogging.info('[Background Job] external-media-inliner queued'); + logging.info('[Background Job] external-media-inliner queued'); await jobsService.addJob({ name: 'external-media-inliner', job: async (data) => { const startedAt = Date.now(); - jobLogging.info('[Background Job] external-media-inliner started'); + logging.info('[Background Job] external-media-inliner started'); try { const result = await mediaInliner.inline(data.domains); - jobLogging.info( + logging.info( `[Background Job] external-media-inliner completed in ${Date.now() - startedAt}ms`, ); return result; } catch (err) { - jobLogging.error( + logging.error( err, `[Background Job] external-media-inliner failed after ${Date.now() - startedAt}ms`, ); diff --git a/ghost/core/core/server/services/members/import-export/import/importer.ts b/ghost/core/core/server/services/members/import-export/import/importer.ts index 5104bca7d4dd..e4fa7f97c6ec 100644 --- a/ghost/core/core/server/services/members/import-export/import/importer.ts +++ b/ghost/core/core/server/services/members/import-export/import/importer.ts @@ -8,7 +8,7 @@ import type { RowSpool, SpooledRows } from './spool'; const metrics = require('@tryghost/metrics'); const errors = require('@tryghost/errors'); -const jobLogging = require('../../../jobs/job-logging'); +const logging = require('@tryghost/logging'); const tpl = require('@tryghost/tpl'); // The members CSV importer, sliced into one concern per method. Two entry points by @@ -305,7 +305,7 @@ class MembersCSVImporter { const emailRecipient: string = requestUserEmail ?? (await this._email.getDefaultRecipient()); const spooled = await this._spool.write(rows); - jobLogging.info('[Background Job] members-import queued'); + logging.info('[Background Job] members-import queued'); this._addJob({ job: () => this.runImportJob(spooled, { labelName, extraLabels, emailRecipient }, verificationTrigger), @@ -326,7 +326,7 @@ class MembersCSVImporter { verificationTrigger: VerificationTrigger, ): Promise { const startedAt = Date.now(); - jobLogging.info('[Background Job] members-import started'); + logging.info('[Background Job] members-import started'); // Null until the import produces one: parsing and mapping already happened inside // the request, so anything failing from here is ours rather than the file's. let result: ImportResult | null = null; @@ -354,11 +354,11 @@ class MembersCSVImporter { ); if (result) { - jobLogging.info( + logging.info( `[Background Job] members-import completed in ${Date.now() - startedAt}ms: imported ${result.imported}, ${result.errors.length} row(s) rejected`, ); } else { - jobLogging.info(`[Background Job] members-import failed after ${Date.now() - startedAt}ms`); + logging.info(`[Background Job] members-import failed after ${Date.now() - startedAt}ms`); } } diff --git a/ghost/core/core/server/services/members/jobs/clean-tokens-task.ts b/ghost/core/core/server/services/members/jobs/clean-tokens-task.ts index eef48a6a047d..b9d93c27c72b 100644 --- a/ghost/core/core/server/services/members/jobs/clean-tokens-task.ts +++ b/ghost/core/core/server/services/members/jobs/clean-tokens-task.ts @@ -4,15 +4,26 @@ const moment = require('moment'); interface CleanTokensDeps { db: { knex: Knex }; + logging: { info(...args: unknown[]): void }; } -async function cleanTokens({ db }: CleanTokensDeps): Promise { +async function cleanTokens({ db, logging }: CleanTokensDeps): Promise { const d = moment.utc().subtract(24, 'hours'); const deletedTokens = await db .knex('tokens') .where('created_at', '<', d.format('YYYY-MM-DD HH:mm:ss')) // we need to be careful about the type here. .format() is the only thing that works across SQLite and MySQL .delete(); + logging.info( + { + system: { + event: 'clean_tokens.completed', + deleted_count: deletedTokens, + }, + }, + `[Background Job] clean-tokens removed ${deletedTokens} tokens older than 24 hours`, + ); + return deletedTokens; } diff --git a/ghost/core/core/server/services/members/jobs/index.js b/ghost/core/core/server/services/members/jobs/index.js index af0a7f7be8d0..a3e56730ec32 100644 --- a/ghost/core/core/server/services/members/jobs/index.js +++ b/ghost/core/core/server/services/members/jobs/index.js @@ -1,5 +1,5 @@ const path = require('path'); -const jobLogging = require('../../jobs/job-logging'); +const logging = require('@tryghost/logging'); const jobsService = require('../../jobs'); const CleanTokensJob = require('./clean-tokens-job').default; @@ -30,7 +30,7 @@ function scheduleJob(key, name, jobFile, maxHour = 6) { const at = `${s} ${m} ${h} * * *`; - jobLogging.info(`[Background Job] ${name} scheduled at ${at}`); + logging.info(`[Background Job] ${name} scheduled at ${at}`); jobsService.addJob({ at, job: path.resolve(__dirname, jobFile), @@ -54,7 +54,7 @@ module.exports = { const classBasedJobs = require('../../jobs-service').getInstance(); const cron = randomDailyCron(); - jobLogging.info(`[Background Job] clean-tokens scheduled at ${cron}`); + logging.info(`[Background Job] clean-tokens scheduled at ${cron}`); await classBasedJobs.scheduleRecurring(new CleanTokensJob(), { cron }); hasScheduled.tokens = true; diff --git a/ghost/core/core/server/services/members/service.js b/ghost/core/core/server/services/members/service.js index f5aa3db88700..52a643009295 100644 --- a/ghost/core/core/server/services/members/service.js +++ b/ghost/core/core/server/services/members/service.js @@ -9,7 +9,6 @@ const { resolveInlineThreshold } = require('./import-export/config'); const MembersStats = require('./stats/members-stats'); const memberJobs = require('./jobs'); const logging = require('@tryghost/logging'); -const jobLogging = require('../jobs/job-logging'); const urlUtils = require('../../../shared/url-utils').default; const settingsCache = require('../../../shared/settings-cache'); const config = require('../../../shared/config'); @@ -187,21 +186,21 @@ module.exports = { if (!env?.startsWith('testing')) { const membersMigrationJobName = 'members-migrations'; if (!(await jobsService.hasExecutedSuccessfully(membersMigrationJobName))) { - jobLogging.info(`[Background Job] ${membersMigrationJobName} queued`); + logging.info(`[Background Job] ${membersMigrationJobName} queued`); jobsService.addOneOffJob({ name: membersMigrationJobName, offloaded: false, job: async () => { const startedAt = Date.now(); - jobLogging.info(`[Background Job] ${membersMigrationJobName} started`); + logging.info(`[Background Job] ${membersMigrationJobName} started`); try { const result = await stripeService.migrations.execute(); - jobLogging.info( + logging.info( `[Background Job] ${membersMigrationJobName} completed in ${Date.now() - startedAt}ms`, ); return result; } catch (err) { - jobLogging.error( + logging.error( err, `[Background Job] ${membersMigrationJobName} failed after ${Date.now() - startedAt}ms`, ); @@ -212,7 +211,7 @@ module.exports = { await jobsService.awaitOneOffCompletion(membersMigrationJobName); } else { - jobLogging.info( + logging.info( `[Background Job] ${membersMigrationJobName} skipped because it has already run`, ); } diff --git a/ghost/core/core/server/services/mentions-jobs/job-service.js b/ghost/core/core/server/services/mentions-jobs/job-service.js index bfe5f675462d..70a6bb6533e1 100644 --- a/ghost/core/core/server/services/mentions-jobs/job-service.js +++ b/ghost/core/core/server/services/mentions-jobs/job-service.js @@ -5,19 +5,18 @@ const JobManager = require('@tryghost/job-manager'); const logging = require('@tryghost/logging'); -const jobLogging = require('../jobs/job-logging'); const models = require('../../models'); const sentry = require('../../../shared/sentry'); const domainEvents = require('@tryghost/domain-events'); const errorHandler = (error, workerMeta) => { - jobLogging.error(error, `[Background Job] ${workerMeta.name} failed`); + logging.error(error, `[Background Job] ${workerMeta.name} failed`); sentry.captureException(error); }; const workerMessageHandler = ({ name, message }) => { if (typeof message === 'string' && !['done', 'cancelled'].includes(message)) { - jobLogging.info(`[Background Job] ${name}: ${message}`); + logging.info(`[Background Job] ${name}: ${message}`); } }; diff --git a/ghost/core/core/server/services/mentions/service.js b/ghost/core/core/server/services/mentions/service.js index 8df40609c45f..989388bf7919 100644 --- a/ghost/core/core/server/services/mentions/service.js +++ b/ghost/core/core/server/services/mentions/service.js @@ -14,7 +14,7 @@ const outputSerializerUrlUtil = require('../../../server/api/endpoints/utils/ser const urlService = require('../url'); const settingsCache = require('../../../shared/settings-cache'); const DomainEvents = require('@tryghost/domain-events'); -const jobLogging = require('../jobs/job-logging'); +const logging = require('@tryghost/logging'); const jobsService = require('../mentions-jobs'); // Serializes a post model to the data the URL service needs, loading the @@ -44,21 +44,18 @@ function getPostUrl(id, postData) { function makeLoggingJobService() { return { async addJob(name, fn) { - jobLogging.info(`[Background Job] ${name} queued`); + logging.info(`[Background Job] ${name} queued`); jobsService.addJob({ name, job: async () => { const startedAt = Date.now(); - jobLogging.info(`[Background Job] ${name} started`); + logging.info(`[Background Job] ${name} started`); try { const result = await fn(); - jobLogging.info(`[Background Job] ${name} completed in ${Date.now() - startedAt}ms`); + logging.info(`[Background Job] ${name} completed in ${Date.now() - startedAt}ms`); return result; } catch (err) { - jobLogging.error( - err, - `[Background Job] ${name} failed after ${Date.now() - startedAt}ms`, - ); + logging.error(err, `[Background Job] ${name} failed after ${Date.now() - startedAt}ms`); throw err; } }, diff --git a/ghost/core/core/server/services/update-check/index.js b/ghost/core/core/server/services/update-check/index.js index ac02a9224eea..41e24a291808 100644 --- a/ghost/core/core/server/services/update-check/index.js +++ b/ghost/core/core/server/services/update-check/index.js @@ -1,6 +1,6 @@ const api = require('../../api').endpoints; const config = require('../../../shared/config'); -const jobLogging = require('../jobs/job-logging'); +const logging = require('@tryghost/logging'); const urlUtils = require('../../../shared/url-utils').default; const jobsService = require('../jobs'); @@ -73,7 +73,7 @@ module.exports.scheduleRecurringJobs = () => { const h = Math.floor(Math.random() * 24); // 0-23 const at = `${s} ${m} ${h} * * *`; - jobLogging.info(`[Background Job] update-check scheduled at ${at}`); + logging.info(`[Background Job] update-check scheduled at ${at}`); jobsService.addJob({ at, // Every day job: require('path').resolve(__dirname, 'run-update-check.js'), @@ -82,7 +82,7 @@ module.exports.scheduleRecurringJobs = () => { }; module.exports.scheduleBootJob = () => { - jobLogging.info('[Background Job] update-check-boot queued'); + logging.info('[Background Job] update-check-boot queued'); jobsService.addJob({ job: require('path').resolve(__dirname, 'run-update-check.js'), name: 'update-check-boot', diff --git a/ghost/core/test/integration/services/members/clean-tokens.test.js b/ghost/core/test/integration/services/members/clean-tokens.test.js index b41ee21997b1..e28026723131 100644 --- a/ghost/core/test/integration/services/members/clean-tokens.test.js +++ b/ghost/core/test/integration/services/members/clean-tokens.test.js @@ -57,11 +57,19 @@ describe('Job: Clean tokens', function () { const secondTokenExists = await models.SingleUseToken.findOne({ id: secondToken.id }); assert.ok(secondTokenExists, 'Second token (younger than 24h) should still exist'); - const completionLog = loggingInfoSpy.getCalls().find((call) => { + const taskLog = loggingInfoSpy.getCalls().find((call) => { return call.args[0]?.system?.event === 'clean_tokens.completed'; }); - assert.ok(completionLog, 'The handler logs a structured clean_tokens.completed event'); - assert.equal(typeof completionLog.args[0].system.deleted_count, 'number'); - assert.equal(typeof completionLog.args[0].system.duration_ms, 'number'); + assert.ok(taskLog, 'The task logs a structured clean_tokens.completed event'); + assert.equal(typeof taskLog.args[0].system.deleted_count, 'number'); + + const lifecycleLog = loggingInfoSpy.getCalls().find((call) => { + return ( + call.args[0]?.system?.event === 'job.completed' && + call.args[0]?.system?.job_type === 'clean-tokens' + ); + }); + assert.ok(lifecycleLog, 'The jobs service logs a structured job.completed lifecycle event'); + assert.equal(typeof lifecycleLog.args[0].system.duration_ms, 'number'); }); }); diff --git a/ghost/core/test/unit/server/services/email-analytics/email-analytics-service-wrapper.test.ts b/ghost/core/test/unit/server/services/email-analytics/email-analytics-service-wrapper.test.ts index c2257dddbbfc..88d36d6ba3d6 100644 --- a/ghost/core/test/unit/server/services/email-analytics/email-analytics-service-wrapper.test.ts +++ b/ghost/core/test/unit/server/services/email-analytics/email-analytics-service-wrapper.test.ts @@ -114,29 +114,6 @@ describe('EmailAnalyticsServiceWrapper', function () { ); }); - it('does not let completion logging failures interrupt event processing', function () { - const wrapper = logLatestOpenedJob('newsletters'); - sinon.stub(logging, 'info').throws(new Error('Logger unavailable')); - - assert.doesNotThrow(() => - wrapper._logJobCompletion( - 'latest-opened', - { - eventCount: 10, - apiPollingTimeMs: 500, - processingTimeMs: 1000, - aggregationTimeMs: 500, - emailAggregationTimeMs: 300, - memberAggregationTimeMs: 200, - result: new EventProcessingResult(), - }, - 2000, - ), - ); - - assert.equal(metricStub.callCount, 2); - }); - it('logs and preserves initial schedule restoration failures', async function () { const errorLog = sinon.stub(logging, 'error'); const wrapper = logLatestOpenedJob('newsletters'); @@ -178,15 +155,6 @@ describe('EmailAnalyticsServiceWrapper', function () { ); }); - it('does not let failure logging escape the fetch error handler', async function () { - const wrapper = logLatestOpenedJob('newsletters'); - sinon.stub(logging, 'error').throws(new Error('Logger unavailable')); - sinon.stub(wrapper.service, 'restoreScheduled').resolves(); - sinon.stub(wrapper, 'fetchLatestOpenedEvents').rejects(new Error('Fetch failed')); - - await assert.doesNotReject(wrapper.startFetch()); - }); - it('skips opened event polling when the cursor seed has no opened column', async function () { const wrapper = new EmailAnalyticsServiceWrapper({ logName: 'gifts' }); wrapper.init({ diff --git a/ghost/core/test/unit/server/services/email-service/batch-sending-service.test.js b/ghost/core/test/unit/server/services/email-service/batch-sending-service.test.js index dc16b48f8786..cda0fb8868c9 100644 --- a/ghost/core/test/unit/server/services/email-service/batch-sending-service.test.js +++ b/ghost/core/test/unit/server/services/email-service/batch-sending-service.test.js @@ -14,11 +14,10 @@ const simulateSleep = async (ms, clock) => { describe('Batch Sending Service', function () { let errorLog; - let infoLog; beforeEach(function () { errorLog = sinon.stub(logging, 'error'); - infoLog = sinon.stub(logging, 'info'); + sinon.stub(logging, 'info'); }); afterEach(function () { @@ -138,33 +137,6 @@ describe('Batch Sending Service', function () { assert.equal(afterEmailModel.get('error'), null); }); - it('keeps the email submitted when completion logging fails', async function () { - const Email = createModelClass({ - findOne: { - status: 'pending', - }, - }); - const service = new BatchSendingService({ - models: { Email }, - }); - let emailModel; - sinon.stub(service, 'sendEmail').callsFake((email) => { - emailModel = email; - return Promise.resolve(); - }); - infoLog.callsFake((message) => { - if (message.startsWith('[Background Job] batch-sending-service-job completed')) { - throw new Error('Logger unavailable'); - } - }); - - await service.emailJob({ emailId: '123' }); - - assert.equal(emailModel.get('status'), 'submitted'); - assert.equal(emailModel.get('error'), null); - sinon.assert.notCalled(errorLog); - }); - it('saves error state if sending fails', async function () { const Email = createModelClass({ findOne: { diff --git a/ghost/core/test/unit/server/services/jobs-service/jobs-service.test.ts b/ghost/core/test/unit/server/services/jobs-service/jobs-service.test.ts index 32f40549681e..55221fdfd3e5 100644 --- a/ghost/core/test/unit/server/services/jobs-service/jobs-service.test.ts +++ b/ghost/core/test/unit/server/services/jobs-service/jobs-service.test.ts @@ -45,7 +45,7 @@ class FakeBackend implements JobsBackendBase { } function makeLogger() { - const calls = { error: [] as unknown[][], info: [] as unknown[][], warn: [] as unknown[][] }; + const calls = { error: [] as unknown[][], info: [] as unknown[][] }; const logging: JobsLogger = { error: (...args) => { calls.error.push(args); @@ -53,9 +53,6 @@ function makeLogger() { info: (...args) => { calls.info.push(args); }, - warn: (...args) => { - calls.warn.push(args); - }, }; return { logging, calls }; } @@ -163,10 +160,11 @@ describe('JobsService', function () { assert.equal(captured.length, 1); assert.equal(captured[0]!.err, boom); assert.deepEqual(captured[0]!.context, { tags: { job_type: 'greet' } }); - assert.equal( - logger.calls.error.length, - 0, - 'delivery failures are logged by the backend, not the service', + assert.equal(logger.calls.error.length, 1); + assert.equal(logger.calls.error[0]![0], boom); + assert.match( + String(logger.calls.error[0]![1]), + /^\[Background Job\] greet failed after \d+ms$/, ); }); @@ -181,6 +179,43 @@ describe('JobsService', function () { }); }); + describe('lifecycle logging', function () { + it('logs started and a structured completed event around a successful delivery', async function () { + const service = makeService(); + service.handle(GreetJob, async () => {}); + await service.start(); + + await service.dispatch(new GreetJob({ name: 'Ada' })); + await backend.deliver(); + + assert.equal(logger.calls.info.length, 2); + assert.equal(logger.calls.info[0]![0], '[Background Job] greet started'); + + const [event, message] = logger.calls.info[1]! as [ + { system: { event: string; job_type: string; duration_ms: number } }, + string, + ]; + assert.equal(event.system.event, 'job.completed'); + assert.equal(event.system.job_type, 'greet'); + assert.equal(typeof event.system.duration_ms, 'number'); + assert.match(String(message), /^\[Background Job\] greet completed in \d+ms$/); + }); + + it('does not log a completed event for a failed delivery', async function () { + const service = makeService(); + service.handle(GreetJob, async () => { + throw new Error('handler exploded'); + }); + await service.start(); + + await service.dispatch(new GreetJob({ name: 'Ada' })); + await assert.rejects(() => backend.deliver(), /handler exploded/); + + assert.equal(logger.calls.info.length, 1, 'only the started line is logged'); + assert.equal(logger.calls.error.length, 1); + }); + }); + describe('scheduleRecurring', function () { it('hands the backend an envelope and schedule', async function () { const service = makeService(); diff --git a/ghost/core/test/unit/server/services/jobs/job-logging.test.ts b/ghost/core/test/unit/server/services/jobs/job-logging.test.ts deleted file mode 100644 index 2dff2524d9f7..000000000000 --- a/ghost/core/test/unit/server/services/jobs/job-logging.test.ts +++ /dev/null @@ -1,32 +0,0 @@ -import assert from 'node:assert/strict'; -import sinon from 'sinon'; -import logging from '@tryghost/logging'; -import * as jobLogging from '../../../../../core/server/services/jobs/job-logging'; - -describe('Background job logging', function () { - afterEach(function () { - sinon.restore(); - }); - - it('forwards lifecycle logs to the Ghost logger', function () { - const info = sinon.stub(logging, 'info'); - const error = sinon.stub(logging, 'error'); - const failure = new Error('Job failed'); - - jobLogging.info('[Background Job] test-job started'); - jobLogging.error(failure, '[Background Job] test-job failed'); - - sinon.assert.calledOnceWithExactly(info, '[Background Job] test-job started'); - sinon.assert.calledOnceWithExactly(error, failure, '[Background Job] test-job failed'); - }); - - it('does not let synchronous logger failures escape into job execution', function () { - sinon.stub(logging, 'info').throws(new Error('Info logger unavailable')); - sinon.stub(logging, 'error').throws(new Error('Error logger unavailable')); - - assert.doesNotThrow(() => jobLogging.info('[Background Job] test-job started')); - assert.doesNotThrow(() => - jobLogging.error(new Error('Job failed'), '[Background Job] test-job failed'), - ); - }); -}); diff --git a/ghost/core/test/unit/server/services/jobs/job-service.test.js b/ghost/core/test/unit/server/services/jobs/job-service.test.js index 1a736707a293..ad07602f19fc 100644 --- a/ghost/core/test/unit/server/services/jobs/job-service.test.js +++ b/ghost/core/test/unit/server/services/jobs/job-service.test.js @@ -5,7 +5,6 @@ const sinon = require('sinon'); describe('JobService', function () { const jobServicePath = '../../../../../core/server/services/jobs/job-service'; const mentionsJobServicePath = '../../../../../core/server/services/mentions-jobs/job-service'; - const jobLoggingPath = '../../../../../core/server/services/jobs/job-logging'; let originalLoad; let workerMessageHandler; let workerErrorHandler; @@ -73,7 +72,6 @@ describe('JobService', function () { }; delete require.cache[require.resolve(jobServicePath)]; - delete require.cache[require.resolve(jobLoggingPath)]; require(jobServicePath); }); @@ -81,7 +79,6 @@ describe('JobService', function () { Module._load = originalLoad; delete require.cache[require.resolve(jobServicePath)]; delete require.cache[require.resolve(mentionsJobServicePath)]; - delete require.cache[require.resolve(jobLoggingPath)]; sinon.restore(); }); @@ -129,14 +126,6 @@ describe('JobService', function () { sinon.assert.notCalled(info); }); - it('does not let worker status logging failures escape', function () { - info.throws(new Error('Logger unavailable')); - - assert.doesNotThrow(() => - workerMessageHandler({ name: 'clean-tokens', message: 'execution started' }), - ); - }); - it('adds the common marker to worker failures', function () { const error = new Error('Job failed'); @@ -145,19 +134,6 @@ describe('JobService', function () { sinon.assert.calledOnceWithExactly(errorLog, error, '[Background Job] clean-tokens failed'); sinon.assert.notCalled(info); }); - - it('does not let worker failure logging failures escape either job manager', function () { - errorLog.throws(new Error('Logger unavailable')); - - assert.doesNotThrow(() => - workerErrorHandler(new Error('Job failed'), { name: 'clean-tokens' }), - ); - - require(mentionsJobServicePath); - assert.doesNotThrow(() => - workerErrorHandler(new Error('Job failed'), { name: 'send-webmentions' }), - ); - }); }); describe('JobService model-event bridge wiring', function () { diff --git a/ghost/core/test/unit/server/services/members/jobs/clean-tokens.test.ts b/ghost/core/test/unit/server/services/members/jobs/clean-tokens.test.ts index 5c8c7d6b53e6..f4917c1d3e30 100644 --- a/ghost/core/test/unit/server/services/members/jobs/clean-tokens.test.ts +++ b/ghost/core/test/unit/server/services/members/jobs/clean-tokens.test.ts @@ -23,13 +23,31 @@ describe('clean-tokens job', function () { }; }); - const deleted = await cleanTokens({ db: { knex: knex as never } }); + const deleted = await cleanTokens({ + db: { knex: knex as never }, + logging: { info: sinon.stub() }, + }); assert.equal(capturedWhere[0], 'created_at'); assert.equal(capturedWhere[1], '<'); assert.match(capturedWhere[2]!, /^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}$/); assert.equal(deleted, 3); }); + + it('logs a structured clean_tokens.completed event with the deleted count', async function () { + const knex = sinon.stub().returns({ + where: () => ({ delete: sinon.stub().resolves(3) }), + }); + const infoStub = sinon.stub(); + + await cleanTokens({ db: { knex: knex as never }, logging: { info: infoStub } }); + + const completionLog = infoStub + .getCalls() + .find((call) => call.args[0]?.system?.event === 'clean_tokens.completed'); + assert.ok(completionLog, 'the task logs a structured clean_tokens.completed event'); + assert.equal(completionLog!.args[0].system.deleted_count, 3); + }); }); describe('CleanTokensJob', function () { diff --git a/ghost/core/test/unit/server/services/members/jobs/schedule-token-cleanup.test.ts b/ghost/core/test/unit/server/services/members/jobs/schedule-token-cleanup.test.ts index 0b0a1f167761..4d7a05981575 100644 --- a/ghost/core/test/unit/server/services/members/jobs/schedule-token-cleanup.test.ts +++ b/ghost/core/test/unit/server/services/members/jobs/schedule-token-cleanup.test.ts @@ -30,9 +30,9 @@ describe('member jobs: token cleanup scheduling', function () { assert.ok(scheduleStub.notCalled, 'token cleanup must not be scheduled under NODE_ENV=test*'); }); - it('schedules a daily clean-tokens job outside the test environment even when logging fails', async function () { + it('schedules a daily clean-tokens job outside the test environment', async function () { const originalEnv = process.env.NODE_ENV; - sinon.stub(logging, 'info').throws(new Error('Logger unavailable')); + sinon.stub(logging, 'info'); process.env.NODE_ENV = 'production'; try { await memberJobs.scheduleTokenCleanupJob();