diff --git a/ghost/core/core/frontend/helpers/get.js b/ghost/core/core/frontend/helpers/get.js index d984795ed9..f531826303 100644 --- a/ghost/core/core/frontend/helpers/get.js +++ b/ghost/core/core/frontend/helpers/get.js @@ -117,9 +117,59 @@ function parseOptions(globals, data, options) { return options; } +/** + * + * @param {String} resource + * @param {String} controllerName + * @param {String} action + * @param {Object} apiOptions + * @returns {Promise} + */ +async function makeAPICall(resource, controllerName, action, apiOptions) { + const controller = api[controllerName]; + + let timer; + + try { + let response; + + if (config.get('optimization:getHelper:timeout:threshold')) { + const logLevel = config.get('optimization:getHelper:timeout:level') || 'error'; + const threshold = config.get('optimization:getHelper:timeout:threshold'); + + const apiResponse = controller[action](apiOptions); + + const timeout = new Promise((resolve) => { + timer = setTimeout(() => { + logging[logLevel](new errors.HelperWarning({ + message: `{{#get}} took longer than ${threshold}ms and was aborted`, + code: 'ABORTED_GET_HELPER', + errorDetails: { + api: `${controllerName}.${action}`, + apiOptions + } + })); + + resolve({[resource]: []}); + }, threshold); + }); + + response = await Promise.race([apiResponse, timeout]); + clearTimeout(timer); + } else { + response = await controller[action](apiOptions); + } + + return response; + } catch (err) { + clearTimeout(timer); + throw err; + } +} + /** * ## Get - * @param {Object} resource + * @param {String} resource * @param {Object} options * @returns {Promise} */ @@ -149,7 +199,6 @@ module.exports = async function get(resource, options) { } const controllerName = RESOURCES[resource].alias; - const controller = api[controllerName]; const action = isBrowse(apiOptions) ? 'browse' : 'read'; // Parse the options we're going to pass to the API @@ -157,7 +206,7 @@ module.exports = async function get(resource, options) { apiOptions.context = {member: data.member}; try { - const response = await controller[action](apiOptions); + const response = await makeAPICall(resource, controllerName, action, apiOptions); // prepare data properties for use with handlebars if (response[resource] && response[resource].length) { @@ -185,19 +234,21 @@ module.exports = async function get(resource, options) { data.error = error.message; return options.inverse(self, {data: data}); } finally { - const totalMs = Date.now() - start; - const logLevel = config.get('logging:slowHelper:level'); - const threshold = config.get('logging:slowHelper:threshold'); - if (totalMs > threshold) { - logging[logLevel](new errors.HelperWarning({ - message: `{{#get}} helper took ${totalMs}ms to complete`, - code: 'SLOW_GET_HELPER', - errorDetails: { - api: `${controllerName}.${action}`, - apiOptions, - returnedRows: returnedRowsCount - } - })); + if (config.get('optimization:getHelper:notify:threshold')) { + const totalMs = Date.now() - start; + const logLevel = config.get('optimization:getHelper:notify:level') || 'warn'; + const threshold = config.get('optimization:getHelper:notify:threshold'); + if (totalMs > threshold) { + logging[logLevel](new errors.HelperWarning({ + message: `{{#get}} helper took ${totalMs}ms to complete`, + code: 'SLOW_GET_HELPER', + errorDetails: { + api: `${controllerName}.${action}`, + apiOptions, + returnedRows: returnedRowsCount + } + })); + } } } }; diff --git a/ghost/core/core/shared/config/defaults.json b/ghost/core/core/shared/config/defaults.json index efe713b07f..0ff94a923c 100644 --- a/ghost/core/core/shared/config/defaults.json +++ b/ghost/core/core/shared/config/defaults.json @@ -58,11 +58,7 @@ }, "transports": [ "stdout" - ], - "slowHelper": { - "level": "warn", - "threshold": 200 - } + ] }, "spam": { "user_login": { @@ -145,6 +141,18 @@ "maxAge": 0 } }, + "optimization": { + "getHelper": { + "timeout": { + "threshold": 5000, + "level": "error" + }, + "notify": { + "threshold": 200, + "level": "warn" + } + } + }, "imageOptimization": { "resize": true, "srcsets": true diff --git a/ghost/core/test/unit/frontend/helpers/get.test.js b/ghost/core/test/unit/frontend/helpers/get.test.js index 9a9d607c3b..2853415668 100644 --- a/ghost/core/test/unit/frontend/helpers/get.test.js +++ b/ghost/core/test/unit/frontend/helpers/get.test.js @@ -2,6 +2,8 @@ const should = require('should'); const sinon = require('sinon'); const Promise = require('bluebird'); const {SafeString} = require('../../../../core/frontend/services/handlebars'); +const configUtils = require('../../../utils/configUtils'); +const logging = require('@tryghost/logging'); // Stuff we are testing const get = require('../../../../core/frontend/helpers/get'); @@ -319,4 +321,60 @@ describe('{{#get}} helper', function () { browseStub.firstCall.args[0].context.member.should.eql(member); }); }); + + describe('optimization', function () { + beforeEach(function () { + sinon.spy(logging, 'error'); + sinon.spy(logging, 'warn'); + + sinon.stub(api, 'postsPublic').get(() => { + return { + browse: () => { + return new Promise((resolve) => { + setTimeout(() => { + resolve({posts: [{id: 'abcd1234'}]}); + }, 5); + }); + } + }; + }); + }); + afterEach(function () { + configUtils.restore(); + }); + + it('should log a warning if it hits the notify threshold', async function () { + configUtils.set('optimization:getHelper:notify:threshold', 1); + + await get.call( + {}, + 'posts', + {hash: {}, data: locals, fn: fn, inverse: inverse} + ); + + // A log message will be output + logging.warn.calledOnce.should.be.true(); + // The get helper will return as per usual + fn.calledOnce.should.be.true(); + fn.firstCall.args[0].should.be.an.Object().with.property('posts'); + fn.firstCall.args[0].posts.should.be.an.Array().with.lengthOf(1); + }); + + it('should log an error and return safely if it hits the timeout threshold', async function () { + configUtils.set('optimization:getHelper:timeout:threshold', 1); + + await get.call( + {}, + 'posts', + {hash: {}, data: locals, fn: fn, inverse: inverse} + ); + + // A log message will be output + logging.error.calledOnce.should.be.true(); + // The get helper gets called with an empty array of results + fn.calledOnce.should.be.true(); + fn.firstCall.args[0].should.be.an.Object().with.property('posts'); + fn.firstCall.args[0].posts.should.be.an.Array().with.lengthOf(0); + }); + }); });