Cleaned up DB test-suite error-log noise (Stripe boot, 4xx, image-size, batch-sending)

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

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

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});
         }

ghost/core/core/shared/config/defaults.json

@@ -71,6 +71,7 @@
     },
     "logging": {
         "level": "info",
+        "logClientErrorsAsError": true,
         "useLocalTime": false,
         "rotation": {
             "enabled": false,

ghost/core/core/shared/config/env/config.testing-mysql.json

@@ -16,7 +16,8 @@
         }
     },
     "logging": {
-        "level": "error"
+        "level": "error",
+        "logClientErrorsAsError": false
     },
     "adapters": {
         "Redis": {

ghost/core/core/shared/config/env/config.testing.json

@@ -12,7 +12,8 @@
         "port": 2369
     },
     "logging": {
-        "level": "error"
+        "level": "error",
+        "logClientErrorsAsError": false
     },
     "adapters": {
         "Redis": {

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)

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

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({

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({

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/')}`)

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: [{

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

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]})

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}`))

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,

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,20 @@ 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 "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();
 
+        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}'`});