From 00388a68da717bbac12b82a3778aa5a19a8f65c4 Mon Sep 17 00:00:00 2001 From: Steve Larson <9larsons@gmail.com> Date: Thu, 25 Jun 2026 11:27:15 -0500 Subject: [PATCH 1/4] Cleaned up DB test-suite error logging (Stripe boot + batch-sending) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit no ref - the DB-backed test suites logged hundreds of expected errors per run, burying real failures in stdout - stripe-service: webhookManager/billingPortalManager.start() hit Stripe endpoints the test mock doesn't implement (webhook_endpoints, billing_portal/configurations) -> 500 -> error-logged on every boot; skip both under testEnv (tests dispatch webhook events directly via the mocker; prod/dev unchanged) — ~266 fewer lines/run - batch-sending.test.js: two tests deliberately trip the "not pending or failed" guards; stub logging.error and assert the expected message instead of printing — 206 -> 2 lines - explore-ping: gate the background phone-home ping to dev/prod only (matching update-check) so it doesn't run in tests --- .../server/services/explore-ping/index.js | 8 ++++++ .../server/services/stripe/stripe-service.js | 13 ++++++++-- .../email-service/batch-sending.test.js | 25 +++++++++++++++++++ 3 files changed, 44 insertions(+), 2 deletions(-) diff --git a/ghost/core/core/server/services/explore-ping/index.js b/ghost/core/core/server/services/explore-ping/index.js index 08099016a86..8873d7eadd4 100644 --- a/ghost/core/core/server/services/explore-ping/index.js +++ b/ghost/core/core/server/services/explore-ping/index.js @@ -25,6 +25,14 @@ module.exports.createService = function createService() { }; module.exports.init = async function init() { + // The explore ping is a background "phone home" request. It should not run + // in the test environment (cf. the update-check service, which gates on the + // same environments), where there is no explore URL configured. + const allowedEnvironments = ['development', 'production']; + if (!allowedEnvironments.includes(config.get('env'))) { + return; + } + const explorePingService = module.exports.createService(); // The final intention is to have this run on a schedule diff --git a/ghost/core/core/server/services/stripe/stripe-service.js b/ghost/core/core/server/services/stripe/stripe-service.js index 24ef8a18cab..d777ac97a23 100644 --- a/ghost/core/core/server/services/stripe/stripe-service.js +++ b/ghost/core/core/server/services/stripe/stripe-service.js @@ -206,11 +206,20 @@ module.exports = class StripeService { webhookSecret: config.webhookSecret, webhookHandlerUrl: config.webhookHandlerUrl }); - await this.webhookManager.start(); this.billingPortalManager.configure({ siteUrl: config.siteUrl }); - await this.billingPortalManager.start(); + + // In the test env there is no real Stripe to register against: the mock + // returns 500 for webhook_endpoints and billing_portal/configurations, so + // these network-registration calls only error-log on every boot — tests + // dispatch webhook events directly through the mocker and never need a + // registered endpoint or portal configuration. Skip them under test; prod + // and dev register exactly as before. + if (!config.testEnv) { + await this.webhookManager.start(); + await this.billingPortalManager.start(); + } } }; diff --git a/ghost/core/test/integration/services/email-service/batch-sending.test.js b/ghost/core/test/integration/services/email-service/batch-sending.test.js index 46775205011..71c3898f561 100644 --- a/ghost/core/test/integration/services/email-service/batch-sending.test.js +++ b/ghost/core/test/integration/services/email-service/batch-sending.test.js @@ -2,6 +2,7 @@ const {agentProvider, fixtureManager, mockManager} = require('../../../utils/e2e const moment = require('moment'); const models = require('../../../../core/server/models'); const sinon = require('sinon'); +const logging = require('@tryghost/logging'); const assert = require('node:assert/strict'); const jobManager = require('../../../../core/server/services/jobs/job-service'); const _ = require('lodash'); @@ -184,6 +185,11 @@ describe('Batch sending tests', function () { }); it('Protects the email job from being run multiple times at the same time', async function () { + // The lock means only one job wins; every other concurrent attempt hits + // the "not pending or failed" guard and logs an expected error. Stub the + // logger so we can assert that guard fired instead of spamming stdout. + const errorLog = sinon.stub(logging, 'error'); + // Prepare a post and email model const {emailModel} = await sendEmail(agent); @@ -215,6 +221,12 @@ describe('Batch sending tests', function () { // Did we create batches? const batches = await models.EmailBatch.findAll({filter: `email_id:'${emailModel.id}'`}); assert.equal(batches.models.length, 1); + + // The losing attempts logged the expected guard error + sinon.assert.called(errorLog); + for (const call of errorLog.getCalls()) { + assert.match(call.args[0], /Tried sending email that is not pending or failed/); + } }); it('Doesn\'t include members created after the email in the batches', async function () { @@ -478,9 +490,22 @@ describe('Batch sending tests', function () { let memberIds = emailRecipients.map(recipient => recipient.get('member_id')); assert.equal(memberIds.length, _.uniq(memberIds).length); + // On retry, the 3 already-submitted batches hit the "not pending or + // failed" guard and log an expected error; only the previously-failed + // batch is re-sent. Stub the logger to assert that guard instead of + // spamming stdout. Scoped to the retry so the genuine failure error + // logged by the initial send above stays visible. + const errorLog = sinon.stub(logging, 'error'); + await retryEmail(agent, emailModel.id); await jobManager.allSettled(); + sinon.assert.called(errorLog); + for (const call of errorLog.getCalls()) { + assert.match(call.args[0], /Tried sending email batch that is not pending or failed/); + } + errorLog.restore(); + await emailModel.refresh(); batches = await models.EmailBatch.findAll({filter: `email_id:'${emailModel.id}'`}); From 83e313ddaa6f1bb445068ce97233a5a61d0b8d45 Mon Sep 17 00:00:00 2001 From: Steve Larson <9larsons@gmail.com> Date: Thu, 25 Jun 2026 12:36:18 -0500 Subject: [PATCH 2/4] Cleaned up 4xx request-error log noise in DB test suites MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit no ref - the DB test suites deliberately exercise hundreds of 4xx responses (validation/auth/rate-limit, asserted via expectStatus); the request logger logs every non-404 error at error level, so each produced a redundant error line — ~300 per run - added a logging:logClientErrorsAsError flag (default true; false in the testing configs) so the request logger demotes 4xx client errors to warn in the test env only — production and dev keep 4xx at error (monitored in Elastic) - moved the logging.error stubs to warn in the 27 tests that capture+assert their 4xx request log - added a log-request unit test pinning the contract (5xx/no-status -> error; 4xx -> error by default, warn when configured; 404 -> info) --- .../web/parent/middleware/log-request.js | 13 +++- ghost/core/core/shared/config/defaults.json | 1 + .../config/env/config.testing-mysql.json | 3 +- .../shared/config/env/config.testing.json | 3 +- .../test/e2e-api/admin/activity-feed.test.js | 4 +- .../admin/custom-theme-settings.test.js | 4 +- .../test/e2e-api/admin/email-previews.test.js | 4 +- ghost/core/test/e2e-api/admin/images.test.js | 12 +-- .../e2e-api/admin/key-authentication.test.js | 6 +- ghost/core/test/e2e-api/admin/labels.test.js | 6 +- ghost/core/test/e2e-api/admin/media.test.js | 2 +- ghost/core/test/e2e-api/admin/members.test.js | 2 +- .../test/e2e-api/admin/posts-legacy.test.js | 8 +- .../core/test/e2e-api/admin/settings.test.js | 6 +- .../web/parent/middleware/log-request.test.js | 78 +++++++++++++++++++ 15 files changed, 122 insertions(+), 30 deletions(-) create mode 100644 ghost/core/test/unit/server/web/parent/middleware/log-request.test.js diff --git a/ghost/core/core/server/web/parent/middleware/log-request.js b/ghost/core/core/server/web/parent/middleware/log-request.js index bc1391eaf61..ad57c34e78e 100644 --- a/ghost/core/core/server/web/parent/middleware/log-request.js +++ b/ghost/core/core/server/web/parent/middleware/log-request.js @@ -1,4 +1,5 @@ const logging = require('@tryghost/logging'); +const config = require('../../../../shared/config'); /** * @TODO: move this middleware to Framework monorepo? @@ -15,7 +16,17 @@ module.exports = function logRequest(req, res, next) { req.userId = req.user ? (req.user.id ? req.user.id : req.user) : null; if (req.err && req.err.statusCode !== 404) { - logging.error({req: req, res: res, err: req.err}); + // 4xx are client errors (validation, auth, rate limit), not server + // faults. Production keeps them at error (they're monitored); the test + // env sets logging:logClientErrorsAsError=false to demote them to warn, + // where every deliberate error-response assertion (expectStatus(4xx)) + // would otherwise log a redundant line. + const isClientError = req.err.statusCode >= 400 && req.err.statusCode < 500; + if (isClientError && config.get('logging:logClientErrorsAsError') === false) { + logging.warn({req: req, res: res, err: req.err}); + } else { + logging.error({req: req, res: res, err: req.err}); + } } else { logging.info({req: req, res: res}); } diff --git a/ghost/core/core/shared/config/defaults.json b/ghost/core/core/shared/config/defaults.json index b2b97252fda..0717c04a14e 100644 --- a/ghost/core/core/shared/config/defaults.json +++ b/ghost/core/core/shared/config/defaults.json @@ -71,6 +71,7 @@ }, "logging": { "level": "info", + "logClientErrorsAsError": true, "useLocalTime": false, "rotation": { "enabled": false, diff --git a/ghost/core/core/shared/config/env/config.testing-mysql.json b/ghost/core/core/shared/config/env/config.testing-mysql.json index 56e0b7206de..84450f98d0a 100644 --- a/ghost/core/core/shared/config/env/config.testing-mysql.json +++ b/ghost/core/core/shared/config/env/config.testing-mysql.json @@ -16,7 +16,8 @@ } }, "logging": { - "level": "error" + "level": "error", + "logClientErrorsAsError": false }, "adapters": { "Redis": { diff --git a/ghost/core/core/shared/config/env/config.testing.json b/ghost/core/core/shared/config/env/config.testing.json index feeb2a7f73b..d7b5b5daf72 100644 --- a/ghost/core/core/shared/config/env/config.testing.json +++ b/ghost/core/core/shared/config/env/config.testing.json @@ -12,7 +12,8 @@ "port": 2369 }, "logging": { - "level": "error" + "level": "error", + "logClientErrorsAsError": false }, "adapters": { "Redis": { diff --git a/ghost/core/test/e2e-api/admin/activity-feed.test.js b/ghost/core/test/e2e-api/admin/activity-feed.test.js index ae963d2e7f9..a0853f0e6ea 100644 --- a/ghost/core/test/e2e-api/admin/activity-feed.test.js +++ b/ghost/core/test/e2e-api/admin/activity-feed.test.js @@ -120,7 +120,7 @@ describe('Activity Feed API', function () { it('Cannot combine type filter with OR filter', async function () { // This query is not allowed because we need to split the filter in two AND filters - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .get(`/members/events?filter=type:comment_event,data.post_id:123`) .expectStatus(400) @@ -139,7 +139,7 @@ describe('Activity Feed API', function () { }); it('Can only combine type and other filters at the root level', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .get(`/members/events?filter=${encodeURIComponent('(type:comment_event+data.post_id:123)+data.post_id:123')}`) .expectStatus(400) diff --git a/ghost/core/test/e2e-api/admin/custom-theme-settings.test.js b/ghost/core/test/e2e-api/admin/custom-theme-settings.test.js index e376b4f3869..2ffdbbbd318 100644 --- a/ghost/core/test/e2e-api/admin/custom-theme-settings.test.js +++ b/ghost/core/test/e2e-api/admin/custom-theme-settings.test.js @@ -114,7 +114,7 @@ describe('Custom Theme Settings API', function () { value: 'Not gonna work' }]; - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .put(`custom_theme_settings/`) .body({custom_theme_settings}) @@ -138,7 +138,7 @@ describe('Custom Theme Settings API', function () { value: 'Not gonna work' }]; - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .put(`custom_theme_settings/`) .body({custom_theme_settings}) diff --git a/ghost/core/test/e2e-api/admin/email-previews.test.js b/ghost/core/test/e2e-api/admin/email-previews.test.js index 7c9a50c677b..11d8512c898 100644 --- a/ghost/core/test/e2e-api/admin/email-previews.test.js +++ b/ghost/core/test/e2e-api/admin/email-previews.test.js @@ -403,7 +403,7 @@ describe('Email Preview API', function () { }); it('cannot send test email', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .post(`email_previews/posts/${fixtureManager.get('posts', 0).id}/`) .body({ @@ -429,7 +429,7 @@ describe('Email Preview API', function () { }); it('cannot send test email', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .post(`email_previews/posts/${fixtureManager.get('posts', 0).id}/`) .body({ diff --git a/ghost/core/test/e2e-api/admin/images.test.js b/ghost/core/test/e2e-api/admin/images.test.js index da1eb8e8f41..2eef471b9dc 100644 --- a/ghost/core/test/e2e-api/admin/images.test.js +++ b/ghost/core/test/e2e-api/admin/images.test.js @@ -247,7 +247,7 @@ describe('Images API', function () { it('Will error when filename is too long', async function () { const originalFilePath = p.join(__dirname, '/../../utils/fixtures/images/ghost-logo.png'); const fileContents = await fs.readFile(originalFilePath); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await uploadImageRequest({fileContents, filename: `${'a'.repeat(300)}.png`, contentType: 'image/png'}) .expectStatus(400) .matchBodySnapshot({ @@ -261,7 +261,7 @@ describe('Images API', function () { it('Can not upload a json file', async function () { const originalFilePath = p.join(__dirname, '/../../utils/fixtures/data/redirects.json'); const fileContents = await fs.readFile(originalFilePath); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await uploadImageRequest({fileContents, filename: 'redirects.json', contentType: 'application/json'}) .expectStatus(415) .matchBodySnapshot({ @@ -275,7 +275,7 @@ describe('Images API', function () { it('Can not upload a file without extension', async function () { const originalFilePath = p.join(__dirname, '/../../utils/fixtures/data/redirects.json'); const fileContents = await fs.readFile(originalFilePath); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await uploadImageRequest({fileContents, filename: 'redirects', contentType: 'image/png'}) .expectStatus(415) .matchBodySnapshot({ @@ -289,7 +289,7 @@ describe('Images API', function () { it('Can not upload a json file with image mime type', async function () { const originalFilePath = p.join(__dirname, '/../../utils/fixtures/data/redirects.json'); const fileContents = await fs.readFile(originalFilePath); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await uploadImageRequest({fileContents, filename: 'redirects.json', contentType: 'image/gif'}) .expectStatus(415) .matchBodySnapshot({ @@ -303,7 +303,7 @@ describe('Images API', function () { it('Can not upload a json file with image file extension', async function () { const originalFilePath = p.join(__dirname, '/../../utils/fixtures/data/redirects.json'); const fileContents = await fs.readFile(originalFilePath); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await uploadImageRequest({fileContents, filename: 'redirects.png', contentType: 'application/json'}) .expectStatus(415) .matchBodySnapshot({ @@ -465,7 +465,7 @@ describe('Images API', function () { const originalFilePath = p.join(__dirname, '/../../utils/fixtures/images/ghost-logo.png'); const fileContents = await fs.readFile(originalFilePath); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await uploadImageRequest({fileContents, filename: 'test.png', contentType: 'image/png'}) .expectStatus(400) .matchBodySnapshot({ diff --git a/ghost/core/test/e2e-api/admin/key-authentication.test.js b/ghost/core/test/e2e-api/admin/key-authentication.test.js index 32fef5b550f..4de97282b15 100644 --- a/ghost/core/test/e2e-api/admin/key-authentication.test.js +++ b/ghost/core/test/e2e-api/admin/key-authentication.test.js @@ -22,7 +22,7 @@ describe('Admin API key authentication', function () { }); it('Can not access endpoint without a token header', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await request.get(localUtils.API.getApiQuery('posts/')) .set('Authorization', `Ghost`) .expect('Content-Type', /json/) @@ -32,7 +32,7 @@ describe('Admin API key authentication', function () { }); it('Can not access endpoint with a wrong endpoint token', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await request.get(localUtils.API.getApiQuery('posts/')) .set('Authorization', `Ghost ${localUtils.getValidAdminToken('https://wrong.com')}`) .expect('Content-Type', /json/) @@ -109,7 +109,7 @@ describe('Admin API key authentication', function () { await testUtils.initFixtures('integrations'); await testUtils.initFixtures('api_keys'); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); const firstResponse = await request.get(localUtils.API.getApiQuery('posts/')) .set('Authorization', `Ghost ${localUtils.getValidAdminToken('/admin/')}`) diff --git a/ghost/core/test/e2e-api/admin/labels.test.js b/ghost/core/test/e2e-api/admin/labels.test.js index 419d0eda13f..82368b5b3b1 100644 --- a/ghost/core/test/e2e-api/admin/labels.test.js +++ b/ghost/core/test/e2e-api/admin/labels.test.js @@ -51,7 +51,7 @@ describe('Labels API', function () { }); it('Errors when adding label with the same name', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .post('labels') .body({labels: [{ @@ -112,7 +112,7 @@ describe('Labels API', function () { }); it('Errors when editing label to a name that already exists', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); const {body: targetBody} = await agent .post('labels') @@ -155,7 +155,7 @@ describe('Labels API', function () { }); it('Errors when adding label with a name over the schema limit', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .post('labels') .body({labels: [{ diff --git a/ghost/core/test/e2e-api/admin/media.test.js b/ghost/core/test/e2e-api/admin/media.test.js index 5e0216cdbaa..7a390c9f3fa 100644 --- a/ghost/core/test/e2e-api/admin/media.test.js +++ b/ghost/core/test/e2e-api/admin/media.test.js @@ -175,7 +175,7 @@ describe('Media API', function () { }); it('Rejects non-media file type', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); const res = await request.post(localUtils.API.getApiQuery('media/upload')) .set('Origin', config.get('url')) .expect('Content-Type', /json/) diff --git a/ghost/core/test/e2e-api/admin/members.test.js b/ghost/core/test/e2e-api/admin/members.test.js index 9e9c6827910..84ba63fb63b 100644 --- a/ghost/core/test/e2e-api/admin/members.test.js +++ b/ghost/core/test/e2e-api/admin/members.test.js @@ -1325,7 +1325,7 @@ describe('Members API', function () { const newMember = await createMemberThroughApi({member, agent}); // Cannot add same member twice - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await agent .post(`/members/`) .body({members: [member]}) diff --git a/ghost/core/test/e2e-api/admin/posts-legacy.test.js b/ghost/core/test/e2e-api/admin/posts-legacy.test.js index 99363b0f794..263dea3a757 100644 --- a/ghost/core/test/e2e-api/admin/posts-legacy.test.js +++ b/ghost/core/test/e2e-api/admin/posts-legacy.test.js @@ -144,7 +144,7 @@ describe('Posts API', function () { }); it('Returns a validation error when unknown filter key is used', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await request.get(localUtils.API.getApiQuery('posts/?filter=page:true')) .set('Origin', config.get('url')) .expect('Content-Type', /json/) @@ -624,7 +624,7 @@ describe('Posts API', function () { const updatedPost = res.body.posts[0]; updatedPost.status = 'published'; - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); await request .put(localUtils.API.getApiQuery('posts/' + id + '/?newsletter=' + newsletterSlug)) @@ -688,7 +688,7 @@ describe('Posts API', function () { .rejects(new errors.HostLimitError({ message: 'Email sending is temporarily disabled' })); - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); // Attempt to publish the scheduled email-only post scheduledPost.status = 'published'; @@ -1927,7 +1927,7 @@ describe('Posts API', function () { const newsletterSlug = testUtils.DataGenerator.Content.newsletters[1].slug; - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); const response = await request .put(localUtils.API.getApiQuery(`posts/${draftPost.id}/?newsletter=${newsletterSlug}`)) diff --git a/ghost/core/test/e2e-api/admin/settings.test.js b/ghost/core/test/e2e-api/admin/settings.test.js index efb72238ae5..934ccda578c 100644 --- a/ghost/core/test/e2e-api/admin/settings.test.js +++ b/ghost/core/test/e2e-api/admin/settings.test.js @@ -320,7 +320,7 @@ describe('Settings API', function () { }); it('fails to edit setting with unsupported announcement_visibility value', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); const settingsToChange = [ { key: 'announcement_visibility', @@ -349,7 +349,7 @@ describe('Settings API', function () { }); it('fails to edit setting with unsupported announcement_background value', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); const settingsToChange = [ { key: 'announcement_background', @@ -483,7 +483,7 @@ describe('Settings API', function () { }); it('cannot update invalid keys via token', async function () { - const loggingStub = sinon.stub(logging, 'error'); + const loggingStub = sinon.stub(logging, 'warn'); const token = await (new SingleUseTokenProvider({ SingleUseTokenModel: models.SingleUseToken, validityPeriod: 24 * 60 * 60 * 1000, diff --git a/ghost/core/test/unit/server/web/parent/middleware/log-request.test.js b/ghost/core/test/unit/server/web/parent/middleware/log-request.test.js new file mode 100644 index 00000000000..6d229955d00 --- /dev/null +++ b/ghost/core/test/unit/server/web/parent/middleware/log-request.test.js @@ -0,0 +1,78 @@ +const {EventEmitter} = require('node:events'); +const sinon = require('sinon'); + +const logging = require('@tryghost/logging'); +const config = require('../../../../../../core/shared/config'); + +const logRequest = require('../../../../../../core/server/web/parent/middleware/log-request'); + +describe('Log request middleware', function () { + let configGetStub; + + beforeEach(function () { + sinon.stub(logging, 'error'); + sinon.stub(logging, 'warn'); + sinon.stub(logging, 'info'); + configGetStub = sinon.stub(config, 'get'); + }); + + afterEach(function () { + sinon.restore(); + }); + + function createReq({statusCode} = {}) { + const req = {}; + if (statusCode !== undefined) { + req.err = {statusCode}; + } + return req; + } + + function run(req) { + // res behaves like the real Express response: an EventEmitter that the + // middleware subscribes to, then fires logResponse on 'finish'. + const res = new EventEmitter(); + const next = sinon.stub(); + + logRequest(req, res, next); + res.emit('finish'); + + return {res, next}; + } + + it('logs a 500 request error via logging.error', function () { + run(createReq({statusCode: 500})); + + sinon.assert.calledOnce(logging.error); + sinon.assert.notCalled(logging.warn); + sinon.assert.notCalled(logging.info); + }); + + it('logs a 4xx request error via logging.warn when logClientErrorsAsError is false', function () { + configGetStub.withArgs('logging:logClientErrorsAsError').returns(false); + + run(createReq({statusCode: 422})); + + sinon.assert.calledOnce(logging.warn); + sinon.assert.notCalled(logging.error); + sinon.assert.notCalled(logging.info); + }); + + it('logs a 4xx request error via logging.error when logClientErrorsAsError is true', function () { + configGetStub.withArgs('logging:logClientErrorsAsError').returns(true); + + run(createReq({statusCode: 422})); + + sinon.assert.calledOnce(logging.error); + sinon.assert.notCalled(logging.warn); + sinon.assert.notCalled(logging.info); + }); + + it('logs a 404 request error via logging.info', function () { + run(createReq({statusCode: 404})); + + sinon.assert.calledOnce(logging.info); + sinon.assert.notCalled(logging.error); + sinon.assert.notCalled(logging.warn); + }); +}); From d233eaf0c7243cf320923cbea3c7714a89aa4378 Mon Sep 17 00:00:00 2001 From: Steve Larson <9larsons@gmail.com> Date: Thu, 25 Jun 2026 12:57:18 -0500 Subject: [PATCH 3/4] Cleaned up image-size fetch log noise in DB test suites MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit no ref - frontend/email meta rendering fetches external image dimensions via the image lib cache; those images are nock-blocked in tests, so every render logged "Unknown Request error" (~250 lines per run) - disableNetwork() now captures the real cachedImageSizeFromUrl.getImageSizeFromUrl once and swaps in a no-op (dimensions omitted — same outcome as the blocked fetch, minus the error); allowImageSize() restores it - cards.test.js opts back in for the two tests that exercise the lookup itself --- .../services/email-service/cards.test.js | 8 +++++ .../test/utils/e2e-framework-mock-manager.js | 35 +++++++++++++++++++ 2 files changed, 43 insertions(+) diff --git a/ghost/core/test/integration/services/email-service/cards.test.js b/ghost/core/test/integration/services/email-service/cards.test.js index f592b8f1fdf..a51fecfa27a 100644 --- a/ghost/core/test/integration/services/email-service/cards.test.js +++ b/ghost/core/test/integration/services/email-service/cards.test.js @@ -258,6 +258,10 @@ describe('Can send cards via email', function () { }); it('uses URL-based dimension lookup for CDN images', async function () { + // This test stubs ImageSize internals and asserts the URL lookup chain + // runs, so restore the real cache method (disableNetwork no-ops it globally). + mockManager.allowImageSize(); + const cdnImageUrl = 'https://cdn.com/uuid/content/images/image.jpg'; const imageSizeFromUrlStub = sinon.stub(ImageSize.prototype, '_imageSizeFromUrl').resolves({ @@ -284,6 +288,10 @@ describe('Can send cards via email', function () { }); it('does not use storage-path lookup for CDN post content images', async function () { + // This test stubs ImageSize internals and asserts the URL lookup chain + // runs, so restore the real cache method (disableNetwork no-ops it globally). + mockManager.allowImageSize(); + const cdnImageUrl = 'https://cdn.com/uuid/content/images/post-image.jpg'; const urlStub = sinon.stub(ImageSize.prototype, '_imageSizeFromUrl').resolves({width: 1200, height: 800}); diff --git a/ghost/core/test/utils/e2e-framework-mock-manager.js b/ghost/core/test/utils/e2e-framework-mock-manager.js index c35353da01d..cba05ea3417 100644 --- a/ghost/core/test/utils/e2e-framework-mock-manager.js +++ b/ghost/core/test/utils/e2e-framework-mock-manager.js @@ -37,6 +37,12 @@ let allowedNetworkDomains = []; const originalLabsIsSet = labs.isSet; const stripeMocker = new StripeMocker(); +// The image-size cache holds a bound copy of getImageSizeFromUrl, captured once +// here so disableNetwork can swap in a no-op (external image lookups are +// nock-blocked in tests, so the real fetch only produces "Unknown Request +// error." log noise) and allowImageSize can put the real method back. +let realCachedImageSizeFromUrl = null; + /** * Stripe Mocks */ @@ -49,6 +55,8 @@ const disableStripe = async () => { await stripeService.disconnect(); }; +const imageSizeNoop = () => Promise.resolve(); + const disableNetwork = () => { nock.disableNetConnect(); @@ -80,6 +88,32 @@ const disableNetwork = () => { } return false; }); + + // External image dimension lookups are nock-blocked in tests, so the real + // fetch always fails and logs "Unknown Request error." on every render. + // Replace the cache's bound lookup with a no-op that resolves undefined + // (same outcome as the blocked fetch — dimensions omitted — but no log). + // The image lib is required lazily because it's only loaded once Ghost has + // booted, after which disableNetwork runs in every afterEach. + const imageLib = require('../../core/server/lib/image'); + const cachedImageSize = imageLib.cachedImageSizeFromUrl; + // Capture the real method once, guarded so re-entry doesn't capture the no-op. + if (!realCachedImageSizeFromUrl && cachedImageSize.getImageSizeFromUrl !== imageSizeNoop) { + realCachedImageSizeFromUrl = cachedImageSize.getImageSizeFromUrl; + } + // Use a plain function (not a sinon stub) so it survives per-test sinon.restore(). + cachedImageSize.getImageSizeFromUrl = imageSizeNoop; +}; + +/** + * Restore the real image-size cache lookup so tests that exercise the lookup + * mechanism itself (and stub its internals) run against the real chain. + */ +const allowImageSize = () => { + if (realCachedImageSizeFromUrl) { + const imageLib = require('../../core/server/lib/image'); + imageLib.cachedImageSizeFromUrl.getImageSizeFromUrl = realCachedImageSizeFromUrl; + } }; const allowStripe = () => { @@ -405,6 +439,7 @@ module.exports = { mockLimitService, restoreLimitService, disableNetwork, + allowImageSize, restore, stripeMocker, assert: { From 3148b38e14b8108cca378cbff577b2a44a294aa9 Mon Sep 17 00:00:00 2001 From: Steve Larson <9larsons@gmail.com> Date: Thu, 25 Jun 2026 13:39:04 -0500 Subject: [PATCH 4/4] Fixed batch-sending retry test after #27822 split the guard log no ref - #27822 (a1ba8ea8bf, on main after this branch was first pushed) split the single "Tried sending email batch that is not pending or failed" error into two paths: already-submitted batches now log info ("already submitted on a prior run; skipping"), only stuck submitting orphans still error - the retry test for "One failed batch marks the email as failed" still stubbed logging.error and asserted the old message, so the assertion failed on the GHA merge commit even though the branch passed locally - repoint the stub at logging.info with the new message text; same scoped pattern (stub for the retry call only, restore before assert) --- .../email-service/batch-sending.test.js | 20 +++++++++---------- 1 file changed, 9 insertions(+), 11 deletions(-) diff --git a/ghost/core/test/integration/services/email-service/batch-sending.test.js b/ghost/core/test/integration/services/email-service/batch-sending.test.js index 71c3898f561..5d1957effaa 100644 --- a/ghost/core/test/integration/services/email-service/batch-sending.test.js +++ b/ghost/core/test/integration/services/email-service/batch-sending.test.js @@ -490,21 +490,19 @@ describe('Batch sending tests', function () { let memberIds = emailRecipients.map(recipient => recipient.get('member_id')); assert.equal(memberIds.length, _.uniq(memberIds).length); - // On retry, the 3 already-submitted batches hit the "not pending or - // failed" guard and log an expected error; only the previously-failed - // batch is re-sent. Stub the logger to assert that guard instead of - // spamming stdout. Scoped to the retry so the genuine failure error - // logged by the initial send above stays visible. - const errorLog = sinon.stub(logging, 'error'); + // On retry, the 3 already-submitted batches hit the "already submitted + // on a prior run" branch in #sendBatch and log info; only the + // previously-failed batch is re-sent. Stub logging.info just for the + // retry so the genuine failure error logged by the initial send above + // stays visible, then assert at least one of those skip logs fired. + const infoLog = sinon.stub(logging, 'info'); await retryEmail(agent, emailModel.id); await jobManager.allSettled(); - sinon.assert.called(errorLog); - for (const call of errorLog.getCalls()) { - assert.match(call.args[0], /Tried sending email batch that is not pending or failed/); - } - errorLog.restore(); + const skipLogs = infoLog.getCalls().filter(call => /already submitted on a prior run; skipping/.test(call.args[0])); + infoLog.restore(); + assert.ok(skipLogs.length > 0, 'expected at least one "already submitted on a prior run; skipping" info log'); await emailModel.refresh(); batches = await models.EmailBatch.findAll({filter: `email_id:'${emailModel.id}'`});