[pull] main from TryGhost:main

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 {

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<ConfigInstance, 'get'>;
@@ -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();
   }
 }

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'),

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,15 +272,15 @@ 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) {
       // Any failure while shutting down counts as interrupted, not failed:
       // 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`,
       );

ghost/core/core/server/services/gifts/index.ts

@@ -41,7 +41,6 @@ export async function init(options: GiftServiceInitOptions): Promise<void> {
   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<void> {
 
   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<void> {
 
   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();

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),

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`,
+    );
   }
 }