Added logging of slow {{#get}} helper uses (#10779)

no issue

- `{{#get}}` can slow down requests a lot if not used carefully, typically by using `limit="all"` or similar which can force a lot of data to be fetched and processed
- adds a warning log if we detect any `{{#get}}` helper call which takes longer than a certain threshold (default 200ms)
- allow log level and threshold to be configured via config to allow for different environments behaviours and requirements

New config options:
```
{
    "logging": {
        "slowHelper": {
            "level": "warn",
            "threshold": 200
        }
    }
}
```

Example output for `{{#get "tags" limit="all" order="name asc"}}` with a lot of tags:

```
[2019-06-07 10:35:52] WARN {{#get}} helper took 453ms to complete

{{#get}} helper took 453ms to complete

Error ID:
    062daed0-8910-11e9-8185-3b615ad8677d

Error Code:
    SLOW_GET_HELPER

Details:
    api:          v2.tagsPublic.browse
    apiOptions:
      order: name asc
      limit: all
    returnedRows: 1698
```

core/server/config/defaults.json

@@ -30,7 +30,11 @@
             "period": "1d",
             "count": 10
         },
-        "transports": ["stdout"]
+        "transports": ["stdout"],
+        "slowHelper": {
+            "level": "warn",
+            "threshold": 200
+        }
     },
     "spam": {
         "user_login": {

core/server/helpers/get.js

@@ -6,7 +6,9 @@ var proxy = require('./proxy'),
     Promise = require('bluebird'),
     jsonpath = require('jsonpath'),
 
+    config = proxy.config,
     logging = proxy.logging,
+    errors = proxy.errors,
     i18n = proxy.i18n,
     createFrame = proxy.hbs.handlebars.createFrame,
 
@@ -133,10 +135,12 @@ get = function get(resource, options) {
     options.data = options.data || {};
 
     const self = this;
+    const start = Date.now();
     const data = createFrame(options.data);
     const ghostGlobals = _.omit(data, ['_parent', 'root']);
     const apiVersion = _.get(data, 'root._locals.apiVersion');
     let apiOptions = options.hash;
+    let returnedRowsCount;
 
     if (!options.fn) {
         data.error = i18n.t('warnings.helpers.mustBeCalledAsBlock', {helperName: 'get'});
@@ -167,6 +171,9 @@ get = function get(resource, options) {
     return api[apiVersion][controller][action](apiOptions).then(function success(result) {
         var blockParams;
 
+        // used for logging details of slow requests
+        returnedRowsCount = result[resource] && result[resource].length;
+
         // block params allows the theme developer to name the data using something like
         // `{{#get "posts" as |result pageInfo|}}`
         blockParams = [result[resource]];
@@ -184,6 +191,21 @@ get = function get(resource, options) {
         logging.error(err);
         data.error = err.message;
         return options.inverse(self, {data: data});
+    }).finally(function () {
+        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: `${apiVersion}.${controller}.${action}`,
+                    apiOptions,
+                    returnedRows: returnedRowsCount
+                }
+            }));
+        }
     });
 };
 

core/server/lib/common/errors.js

@@ -54,6 +54,12 @@ const ghostErrors = {
             statusCode: 409,
             errorType: 'UpdateCollisionError'
         }, options));
+    },
+    HelperWarning: function HelperWarning(options) {
+        GhostError.call(this, merge({
+            errorType: 'HelperWarning',
+            hideStack: true
+        }, options));
     }
 };