Converted initial outbox logs to structured logging

ghost/core/core/server/services/outbox/handlers/member-created.js

@@ -12,7 +12,12 @@ async function handle({payload}) {
     try {
         const slug = MEMBER_WELCOME_EMAIL_SLUGS[payload.status];
         if (!slug) {
-            logging.warn(`${LOG_KEY} No automated email slug found for member status: ${payload.status}`);
+            logging.warn({
+                system: {
+                    event: 'outbox.member_created.no_slug_mapping',
+                    member_status: payload.status
+                }
+            }, `${LOG_KEY} No automated email slug found for member status`);
             return;
         }
 
@@ -31,9 +36,11 @@ async function handle({payload}) {
         });
     } catch (err) {
         logging.error({
-            message: `${LOG_KEY} Failed to track automated email send`,
+            system: {
+                event: 'outbox.member_created.track_send_failed'
+            },
             err
-        });
+        }, `${LOG_KEY} Failed to track automated email send`);
     }
 }
 

ghost/core/core/server/services/outbox/index.js

@@ -24,7 +24,11 @@ class OutboxServiceWrapper {
 
     async startProcessing() {
         if (this.processing) {
-            logging.info(`${OUTBOX_LOG_KEY}: Outbox job already running, skipping`);
+            logging.info({
+                system: {
+                    event: 'outbox.processing.skipped_already_running'
+                }
+            }, `${OUTBOX_LOG_KEY}: Outbox job already running, skipping`);
             return;
         }
         this.processing = true;

ghost/core/test/unit/server/services/outbox/handlers/member-created.test.js

@@ -1,13 +1,14 @@
 const assert = require('node:assert/strict');
 const sinon = require('sinon');
 const rewire = require('rewire');
+const {captureLoggerOutput, findByEvent} = require('../../../../../utils/logging-utils');
 
 describe('member-created handler', function () {
     let handler;
     let memberWelcomeEmailServiceStub;
-    let loggingStub;
     let AutomatedEmailStub;
     let AutomatedEmailRecipientStub;
+    let logCapture;
 
     beforeEach(function () {
         handler = rewire('../../../../../../core/server/services/outbox/handlers/member-created.js');
@@ -18,11 +19,6 @@ describe('member-created handler', function () {
             }
         };
 
-        loggingStub = {
-            warn: sinon.stub(),
-            error: sinon.stub()
-        };
-
         AutomatedEmailStub = {
             findOne: sinon.stub().resolves({id: 'ae123'})
         };
@@ -31,13 +27,15 @@ describe('member-created handler', function () {
             add: sinon.stub().resolves()
         };
 
+        logCapture = captureLoggerOutput();
+
         handler.__set__('memberWelcomeEmailService', memberWelcomeEmailServiceStub);
-        handler.__set__('logging', loggingStub);
         handler.__set__('AutomatedEmail', AutomatedEmailStub);
         handler.__set__('AutomatedEmailRecipient', AutomatedEmailRecipientStub);
     });
 
     afterEach(function () {
+        logCapture.restore();
         sinon.restore();
     });
 
@@ -55,7 +53,6 @@ describe('member-created handler', function () {
         });
 
         sinon.assert.calledOnce(memberWelcomeEmailServiceStub.api.send);
-        sinon.assert.calledOnce(loggingStub.error);
     });
 
     it('logs error when tracking fails', async function () {
@@ -72,10 +69,8 @@ describe('member-created handler', function () {
             }
         });
 
-        sinon.assert.calledOnce(loggingStub.error);
-        const errorCall = loggingStub.error.getCall(0);
-        assert.ok(errorCall.args[0].message.includes('Failed to track automated email send'));
-        assert.equal(errorCall.args[0].err, dbError);
+        const errorLog = findByEvent(logCapture.output, 'outbox.member_created.track_send_failed');
+        assert.ok(errorLog);
     });
 
     it('logs warning when status has no slug mapping', async function () {
@@ -90,8 +85,12 @@ describe('member-created handler', function () {
         });
 
         sinon.assert.calledOnce(memberWelcomeEmailServiceStub.api.send);
-        sinon.assert.calledOnce(loggingStub.warn);
-        assert.ok(loggingStub.warn.getCall(0).args[0].includes('No automated email slug found'));
+        const warningLog = findByEvent(logCapture.output, 'outbox.member_created.no_slug_mapping');
+        assert.ok(warningLog);
+        assert.deepEqual(warningLog.system, {
+            event: 'outbox.member_created.no_slug_mapping',
+            member_status: 'comped'
+        });
         sinon.assert.notCalled(AutomatedEmailRecipientStub.add);
     });
 });

ghost/core/test/unit/server/services/outbox/index.test.js

@@ -1,27 +1,29 @@
+const assert = require('node:assert/strict');
 const sinon = require('sinon');
 const rewire = require('rewire');
 const DomainEvents = require('@tryghost/domain-events');
+const {captureLoggerOutput, findByEvent} = require('../../../../utils/logging-utils');
 const StartOutboxProcessingEvent = require('../../../../../core/server/services/outbox/events/start-outbox-processing-event');
 
 describe('Outbox Service', function () {
     let service;
     let processOutboxStub;
-    let loggingStub;
     let jobsStub;
+    let logCapture;
 
     beforeEach(function () {
         service = rewire('../../../../../core/server/services/outbox/index.js');
 
         processOutboxStub = sinon.stub().resolves('Processed');
-        loggingStub = {info: sinon.stub(), error: sinon.stub()};
         jobsStub = {scheduleOutboxJob: sinon.stub()};
+        logCapture = captureLoggerOutput();
 
         service.__set__('processOutbox', processOutboxStub);
-        service.__set__('logging', loggingStub);
         service.__set__('jobs', jobsStub);
     });
 
     afterEach(async function () {
+        logCapture.restore();
         sinon.restore();
         await DomainEvents.allSettled();
     });
@@ -46,7 +48,11 @@ describe('Outbox Service', function () {
             await service.startProcessing();
 
             sinon.assert.notCalled(processOutboxStub);
-            sinon.assert.calledOnce(loggingStub.info);
+            const infoLog = findByEvent(logCapture.output, 'outbox.processing.skipped_already_running');
+            assert.ok(infoLog);
+            assert.deepEqual(infoLog.system, {
+                event: 'outbox.processing.skipped_already_running'
+            });
         });
     });
 });

ghost/core/test/utils/logging-utils.js

@@ -0,0 +1,84 @@
+const bunyan = require('bunyan');
+const {PassThrough} = require('stream');
+const logging = require('@tryghost/logging');
+
+/**
+ * Parse newline-delimited JSON log records from a buffered string.
+ *
+ * @param {string} buffer - Buffered log text that may contain multiple records.
+ * @param {Array<object>} output - Collected parsed log records.
+ * @returns {string} Remaining partial record that did not end with a newline.
+ */
+function parseBufferedJsonLogs(buffer, output) {
+    const lines = buffer.split('\n');
+    const remaining = lines.pop();
+
+    for (const line of lines) {
+        if (!line.trim()) {
+            continue;
+        }
+
+        output.push(JSON.parse(line));
+    }
+
+    return remaining;
+}
+
+/**
+ * Temporarily redirects Ghost logger streams to an in-memory Bunyan stream.
+ *
+ * This allows tests to assert on real serialized JSON output from
+ * `@tryghost/logging` without stubbing logger methods.
+ *
+ * @returns {{output: Array<object>, restore: () => void}} Capture handle.
+ */
+function captureLoggerOutput() {
+    const output = [];
+    const stream = new PassThrough();
+    let buffered = '';
+
+    stream.on('data', (chunk) => {
+        buffered += chunk.toString();
+        buffered = parseBufferedJsonLogs(buffered, output);
+    });
+
+    const originalStreams = logging.streams;
+    logging.streams = {
+        capture: {
+            name: 'capture',
+            log: bunyan.createLogger({
+                name: 'test-logger',
+                streams: [{
+                    type: 'stream',
+                    stream,
+                    level: 'trace'
+                }]
+            })
+        }
+    };
+
+    return {
+        output,
+        restore() {
+            buffered = parseBufferedJsonLogs(buffered, output);
+            logging.streams = originalStreams;
+            stream.destroy();
+        }
+    };
+}
+
+/**
+ * Find the first structured log record matching a system event.
+ *
+ * @param {Array<object>} output - Captured log records.
+ * @param {string} event - Structured event name to match.
+ * @returns {object|undefined} First matching log record.
+ */
+function findByEvent(output, event) {
+    return output.find(log => log.system?.event === event);
+}
+
+module.exports = {
+    captureLoggerOutput,
+    findByEvent
+};