Converted initial outbox logs to structured logging (#26599)

refs
https://linear.app/ghost/issue/NY-1020/convert-outbox-logs-to-structured-logs

## Summary

- converted the outbox missing-slug warning and outbox already-running
guard logs to structured logging with a top-level `system` object and
message second argument
- added red/green unit coverage that captures real `@tryghost/logging`
Bunyan JSON output in-memory and asserts structured fields
- extracted shared test log capture utility
(`ghost/core/test/utils/logging-utils.js`) with JSDoc and updated outbox
unit tests to use top-level capture hooks

## Reviewer notes

Mostly I'm looking for feedback on the new testing pattern introduced
here. The new `captureLoggerOutput()` test helper redirects the actual
JSON logs emitted by @tryghost/logging into an in-memory stream. This
way we can assert on the _actual_ JSON that is output by the logger,
which feels more useful to me than asserting on which arguments we pass
to the logger.

This doesn't cover all the logs that I want to change to structured logs
for the referenced issue, but I wanted to align on the pattern here
while keeping the PR relatively small; once we're aligned on the
approach I can extend it to the other outbox/welcome email logs in a
follow up PR.

Author: cmraible

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,86 @@
+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;
+    const originalSerializerSource = Object.values(originalStreams)[0]?.log?.serializers;
+    logging.streams = {
+        capture: {
+            name: 'capture',
+            log: bunyan.createLogger({
+                name: 'test-logger',
+                serializers: originalSerializerSource || logging.serializers,
+                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
+};