Converted initial outbox logs to structured logging#26599
Conversation
Standardized the already-running outbox guard log to emit a system object and message, and added an in-memory logging test that asserts the real Bunyan JSON output.
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review infoConfiguration used: Path: .coderabbit.yaml Review profile: CHILL Plan: Pro 📒 Files selected for processing (1)
🚧 Files skipped from review as they are similar to previous changes (1)
WalkthroughStructured logging was added to the outbox service: the member-created handler and outbox index now emit structured log payloads with system event fields ( 🚥 Pre-merge checks | ✅ 2 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (2 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing Touches
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
There was a problem hiding this comment.
🧹 Nitpick comments (1)
ghost/core/test/unit/server/services/outbox/index.test.js (1)
51-55: Consider asserting the emitted message text too.You already validate
system.event; adding a strictinfoLog.msgassertion would fully lock in the intended structured-log contract for this guard path.Suggested assertion
const infoLog = findByEvent(logCapture.output, 'outbox.processing.skipped_already_running'); assert.ok(infoLog); assert.deepEqual(infoLog.system, { event: 'outbox.processing.skipped_already_running' }); + assert.equal(infoLog.msg, 'Outbox job already running, skipping');🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed. In `@ghost/core/test/unit/server/services/outbox/index.test.js` around lines 51 - 55, Add an assertion that the log message text is exactly what we expect for the skipped-already-running guard: after obtaining infoLog via findByEvent(logCapture.output, 'outbox.processing.skipped_already_running') in the test, assert that infoLog.msg strictly equals the expected message string (use the same human-readable text used elsewhere in outbox processing) so the test checks both system.event and msg fields of the emitted structured log; update the assertion near the existing assert.deepEqual(infoLog.system, {...}) in index.test.js accordingly.
🤖 Prompt for all review comments with AI agents
Verify each finding against the current code and only fix it if needed.
Nitpick comments:
In `@ghost/core/test/unit/server/services/outbox/index.test.js`:
- Around line 51-55: Add an assertion that the log message text is exactly what
we expect for the skipped-already-running guard: after obtaining infoLog via
findByEvent(logCapture.output, 'outbox.processing.skipped_already_running') in
the test, assert that infoLog.msg strictly equals the expected message string
(use the same human-readable text used elsewhere in outbox processing) so the
test checks both system.event and msg fields of the emitted structured log;
update the assertion near the existing assert.deepEqual(infoLog.system, {...})
in index.test.js accordingly.
ℹ️ Review info
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (5)
ghost/core/core/server/services/outbox/handlers/member-created.jsghost/core/core/server/services/outbox/index.jsghost/core/test/unit/server/services/outbox/handlers/member-created.test.jsghost/core/test/unit/server/services/outbox/index.test.jsghost/core/test/utils/logging-utils.js
ghost/core/test/unit/server/services/outbox/handlers/member-created.test.js
Show resolved
Hide resolved
| const errorLog = findByEvent(logCapture.output, 'outbox.member_created.track_send_failed'); | ||
| assert.ok(errorLog); | ||
| assert.ok(errorLog.msg.startsWith('Failed to track automated email send')); |
There was a problem hiding this comment.
Queries the captured logs by event, then asserts on the actual JSON from the log
ghost/core/test/unit/server/services/outbox/handlers/member-created.test.js
Show resolved
Hide resolved
There was a problem hiding this comment.
🧹 Nitpick comments (2)
ghost/core/core/server/services/outbox/handlers/member-created.js (1)
26-26: Consider converting this log for consistency.This warning log at line 26 still uses the legacy
LOG_KEYprefix format while the other two logs in this handler have been converted to structured logging. For consistency within this file, consider converting it as well.That said, if the intent is to limit scope per the PR description, this can be deferred.
🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed. In `@ghost/core/core/server/services/outbox/handlers/member-created.js` at line 26, The log line using logging.warn with the legacy LOG_KEY prefix should be converted to structured logging like the other messages in this handler: replace the logging.warn(`${LOG_KEY} No automated email found for slug: ${slug}`) call with a structured logging call (e.g., logging.warn or logging.info depending on severity) that passes an object including the slug and a clear message property so it matches the pattern used elsewhere in this module (refer to the existing structured logs in this handler for field names and severity).ghost/core/test/utils/logging-utils.js (1)
16-22: Consider adding error handling for malformed JSON in tests.If a log line contains malformed JSON (e.g., from a test misconfiguration or unexpected output),
JSON.parsewill throw with a generic syntax error, making debugging harder.🔧 Proposed fix to improve test diagnostics
for (const line of lines) { if (!line.trim()) { continue; } - output.push(JSON.parse(line)); + try { + output.push(JSON.parse(line)); + } catch (err) { + throw new Error(`Failed to parse log line: ${line}\n${err.message}`); + } }🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed. In `@ghost/core/test/utils/logging-utils.js` around lines 16 - 22, The loop that parses log lines using JSON.parse in this test helper can throw on malformed JSON; update the parsing in the function that iterates "for (const line of lines)" to catch JSON parse errors (surround the JSON.parse(line) call with try/catch) and instead of letting the exception propagate, push a diagnostic object into output that includes the raw line and the parse error message (e.g., {__parseError__: err.message, raw: line}) so tests fail with clearer diagnostics; reference the code that currently calls JSON.parse(line) in logging-utils.js to implement the try/catch and diagnostic push.
🤖 Prompt for all review comments with AI agents
Verify each finding against the current code and only fix it if needed.
Nitpick comments:
In `@ghost/core/core/server/services/outbox/handlers/member-created.js`:
- Line 26: The log line using logging.warn with the legacy LOG_KEY prefix should
be converted to structured logging like the other messages in this handler:
replace the logging.warn(`${LOG_KEY} No automated email found for slug:
${slug}`) call with a structured logging call (e.g., logging.warn or
logging.info depending on severity) that passes an object including the slug and
a clear message property so it matches the pattern used elsewhere in this module
(refer to the existing structured logs in this handler for field names and
severity).
In `@ghost/core/test/utils/logging-utils.js`:
- Around line 16-22: The loop that parses log lines using JSON.parse in this
test helper can throw on malformed JSON; update the parsing in the function that
iterates "for (const line of lines)" to catch JSON parse errors (surround the
JSON.parse(line) call with try/catch) and instead of letting the exception
propagate, push a diagnostic object into output that includes the raw line and
the parse error message (e.g., {__parseError__: err.message, raw: line}) so
tests fail with clearer diagnostics; reference the code that currently calls
JSON.parse(line) in logging-utils.js to implement the try/catch and diagnostic
push.
ℹ️ Review info
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (5)
ghost/core/core/server/services/outbox/handlers/member-created.jsghost/core/core/server/services/outbox/index.jsghost/core/test/unit/server/services/outbox/handlers/member-created.test.jsghost/core/test/unit/server/services/outbox/index.test.jsghost/core/test/utils/logging-utils.js
| assert.equal(errorCall.args[0].err, dbError); | ||
| const errorLog = findByEvent(logCapture.output, 'outbox.member_created.track_send_failed'); | ||
| assert.ok(errorLog); | ||
| assert.ok(errorLog.msg.startsWith('Failed to track automated email send')); |
There was a problem hiding this comment.
better to not assert the message in a test (here and elsewhere)
| event: 'outbox.member_created.no_slug_mapping', | ||
| member_status: payload.status | ||
| } | ||
| }, 'No automated email slug found for member status'); |
There was a problem hiding this comment.
consider adding the log key back so it's easier to see stuff when developing locally. also consider tweaking the log key to more closely match the event above
| * | ||
| * @returns {{output: Array<object>, restore: () => void}} Capture handle. | ||
| */ | ||
| function captureLoggerOutput() { |
There was a problem hiding this comment.
captureLoggerOutput doesn't preserve serializers
The replacement bunyan logger in the capture utility doesn't use the same serializers as the original Ghost logger. This means the captured JSON may differ from production output for objects that have custom serialization (like err objects). For the current test cases this doesn't matter, but as this utility gets used more broadly it could cause subtle differences between test and production log output. Worth a comment or future enhancement.
Each test should focus on a single concern — the 'sends email even when tracking fails' test now only verifies the email was sent.
Not imported anywhere — can be re-added when needed.
There was a problem hiding this comment.
🧹 Nitpick comments (2)
ghost/core/test/unit/server/services/outbox/handlers/member-created.test.js (2)
72-73: Strengthen the error-path assertion beyond event presence.Right now the test only checks that an event exists. Consider also asserting core structured fields (for example
system.eventand presence oferr) so regressions in error payload shape don’t slip through.Suggested tightening
const errorLog = findByEvent(logCapture.output, 'outbox.member_created.track_send_failed'); assert.ok(errorLog); + assert.equal(errorLog.system?.event, 'outbox.member_created.track_send_failed'); + assert.ok(errorLog.err);🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed. In `@ghost/core/test/unit/server/services/outbox/handlers/member-created.test.js` around lines 72 - 73, The test currently only asserts that findByEvent(logCapture.output, 'outbox.member_created.track_send_failed') returns a truthy errorLog; strengthen this by asserting the structured payload shape: after obtaining errorLog (from findByEvent/logCapture.output), assert that the event name exists (e.g. errorLog.system.event or errorLog.data.system.event equals 'outbox.member_created.track_send_failed') and that an error object or message is present (e.g. errorLog.err or errorLog.data.err is truthy), so update the assertions around the errorLog variable in the member-created.test.js to check both the system.event field and presence of err in the returned payload.
38-39: Make test cleanup resilient to partial setup failures.If setup fails before
logCaptureis initialized, or ifrestore()throws, cleanup can mask the original failure. A guarded restore withfinallykeeps teardown safer.Safer teardown pattern
afterEach(function () { - logCapture.restore(); - sinon.restore(); + try { + logCapture?.restore(); + } finally { + sinon.restore(); + } });🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed. In `@ghost/core/test/unit/server/services/outbox/handlers/member-created.test.js` around lines 38 - 39, Make the test teardown resilient by guarding calls to logCapture.restore() and ensuring sinon.restore() always runs: in the afterEach/teardown replace the direct calls to logCapture.restore() and sinon.restore() with a try/finally that checks for logCapture existence (and restore method) before calling logCapture.restore(), then calls sinon.restore() in the finally block so a failure in logCapture.restore() cannot mask the original error; refer to the existing logCapture.restore() and sinon.restore() calls when making this change.
🤖 Prompt for all review comments with AI agents
Verify each finding against the current code and only fix it if needed.
Nitpick comments:
In `@ghost/core/test/unit/server/services/outbox/handlers/member-created.test.js`:
- Around line 72-73: The test currently only asserts that
findByEvent(logCapture.output, 'outbox.member_created.track_send_failed')
returns a truthy errorLog; strengthen this by asserting the structured payload
shape: after obtaining errorLog (from findByEvent/logCapture.output), assert
that the event name exists (e.g. errorLog.system.event or
errorLog.data.system.event equals 'outbox.member_created.track_send_failed') and
that an error object or message is present (e.g. errorLog.err or
errorLog.data.err is truthy), so update the assertions around the errorLog
variable in the member-created.test.js to check both the system.event field and
presence of err in the returned payload.
- Around line 38-39: Make the test teardown resilient by guarding calls to
logCapture.restore() and ensuring sinon.restore() always runs: in the
afterEach/teardown replace the direct calls to logCapture.restore() and
sinon.restore() with a try/finally that checks for logCapture existence (and
restore method) before calling logCapture.restore(), then calls sinon.restore()
in the finally block so a failure in logCapture.restore() cannot mask the
original error; refer to the existing logCapture.restore() and sinon.restore()
calls when making this change.
ℹ️ Review info
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (2)
ghost/core/test/unit/server/services/outbox/handlers/member-created.test.jsghost/core/test/utils/logging-utils.js
🚧 Files skipped from review as they are similar to previous changes (1)
- ghost/core/test/utils/logging-utils.js
ref https://linear.app/ghost/issue/NY-1020 Follows up on #26599 to convert the remaining logging statements in the outbox service, process-entries, process-outbox, and member welcome email service to use structured logging with system.event fields
ref https://linear.app/ghost/issue/NY-1020 Follows up on #26599 to convert the remaining logging statements in the outbox service, process-entries, process-outbox, and member welcome email service to use structured logging with system.event fields
…26660) closes https://linear.app/ghost/issue/NY-1020/convert-outbox-logs-to-structured-logs ## Summary - Follows up on #26599 to convert the remaining logging statements in the outbox and member welcome email services to structured logging with `system.event` fields - Adds structured metadata (entry IDs, event types, batch stats, durations) to each log for easier dashboard filtering and debugging - No behavioral changes — only logging call formats are changed ## New structured events | Event | Level | File | |-------|-------|------| | `outbox.processing.error` | error | `outbox/index.js` | | `outbox.entry.no_handler` | warn | `process-entries.js` | | `outbox.entry.payload_parse_failed` | error | `process-entries.js` | | `outbox.entry.send_failed` | error | `process-entries.js` | | `outbox.entry.delete_failed` | error | `process-entries.js` | | `outbox.init.failed` | error | `process-outbox.js` | | `outbox.batch.complete` | info | `process-outbox.js` | | `outbox.member_created.no_automated_email` | warn | `member-created.js` | | `member_welcome_email.sending` | info | `service.js` | ## Note for reviewer The `logging.info(statusMessage)` in `outbox/index.js` is left as-is — `processOutbox()` returns a string that the caller logs. Converting this one would require changing the return value contract. Worth discussing whether the return-for-logging pattern should be refactored in a separate PR. ## Test plan - [x] All 11 outbox unit tests passing (3 index + 4 member-created + 4 new process-entries) - [x] Lint passes on all modified files - [ ] Integration test `process-outbox.test.js` still passes (exercises full pipeline) ref https://linear.app/ghost/issue/NY-1020 <!-- CURSOR_SUMMARY --> --- > [!NOTE] > **Low Risk** > Logging-only changes across outbox processing and member welcome emails; low risk aside from potential differences in log output/alerting and added metadata payload size. > > **Overview** > Converts remaining outbox processing and member welcome email log lines to **structured logs** with `system.event` fields, and attaches useful metadata such as `member_status`, `slug`, `event_type`, `entry_id`, and batch timing/counts. > > Standardizes error/warn reporting in `outbox/index.js`, `process-outbox.js`, `process-entries.js`, `handlers/member-created.js`, and `member-welcome-emails/service.js` (including passing the caught `err` object), and expands unit tests to assert the new structured events (plus adds a new `process-entries` unit test suite). > > <sup>Written by [Cursor Bugbot](https://cursor.com/dashboard?tab=bugbot) for commit dd730e7. This will update automatically on new commits. Configure [here](https://cursor.com/dashboard?tab=bugbot).</sup> <!-- /CURSOR_SUMMARY -->
refs https://linear.app/ghost/issue/NY-1020/convert-outbox-logs-to-structured-logs
Summary
systemobject and message second argument@tryghost/loggingBunyan JSON output in-memory and asserts structured fieldsghost/core/test/utils/logging-utils.js) with JSDoc and updated outbox unit tests to use top-level capture hooksReviewer 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.