🎨 configurable logging with bunyan (#7431)

- 🛠  add bunyan and prettyjson, remove morgan

- ✨  add logging module
  - GhostLogger class that handles setup of bunyan
  - PrettyStream for stdout

- ✨  config for logging
  - @todo: testing level fatal?

- ✨  log each request via GhostLogger (express middleware)
  - @todo: add errors to output

- 🔥  remove errors.updateActiveTheme
  - we can read the value from config

- 🔥  remove 15 helper functions in core/server/errors/index.js
  - all these functions get replaced by modules:
    1. logging
    2. error middleware handling for html/json
    3. error creation (which will be part of PR #7477)

- ✨  add express error handler for html/json
  - one true error handler for express responses
  - contains still some TODO's, but they are not high priority for first implementation/integration
  - this middleware only takes responsibility of either rendering html responses or return json error responses

- 🎨  use new express error handler in middleware/index
  - 404 and 500 handling

- 🎨  return error instead of error message in permissions/index.js
  - the rule for error handling should be: if you call a unit, this unit should return a custom Ghost error

- 🎨  wrap serve static module
  - rule: if you call a module/unit, you should always wrap this error
  - it's always the same rule
  - so the caller never has to worry about what comes back
  - it's always a clear error instance
  - in this case: we return our notfounderror if serve static does not find the resource
  - this avoid having checks everywhere

- 🎨  replace usages of errors/index.js functions and adapt tests
  - use logging.error, logging.warn
  - make tests green
  - remove some usages of logging and throwing api errors -> because when a request is involved, logging happens automatically

- 🐛  return errorDetails to Ghost-Admin
  - errorDetails is used for Theme error handling

- 🎨  use 500er error for theme is missing error in theme-handler

- 🎨  extend file rotation to 1w

core/server/api/authentication.js

@@ -8,6 +8,7 @@ var _                = require('lodash'),
     globalUtils      = require('../utils'),
     utils            = require('./utils'),
     errors           = require('../errors'),
+    logging          = require('../logging'),
     models           = require('../models'),
     events           = require('../events'),
     config           = require('../config'),
@@ -488,14 +489,10 @@ authentication = {
                             }]
                         };
 
-                    apiMail.send(payload, {context: {internal: true}}).catch(function (error) {
-                        errors.logError(
-                            error.message,
-                            i18n.t(
-                                'errors.api.authentication.unableToSendWelcomeEmail'
-                            ),
-                            i18n.t('errors.api.authentication.checkEmailConfigInstructions', {url: 'http://support.ghost.org/mail/'})
-                        );
+                    apiMail.send(payload, {context: {internal: true}}).catch(function (err) {
+                        err.context = i18n.t('errors.api.authentication.unableToSendWelcomeEmail');
+                        err.help = i18n.t('errors.api.authentication.checkEmailConfigInstructions', {url: 'http://support.ghost.org/mail/'});
+                        logging.error(err);
                     });
                 })
                 .return(setupUser);

core/server/api/invites.js

@@ -8,6 +8,7 @@ var _ = require('lodash'),
     globalUtils = require('../utils'),
     utils = require('./utils'),
     errors = require('../errors'),
+    logging = require('../logging'),
     config = require('../config'),
     i18n = require('../i18n'),
     docName = 'invites',
@@ -144,8 +145,7 @@ invites = {
                     if (error && error.errorType === 'EmailError') {
                         error.message = i18n.t('errors.api.invites.errorSendingEmail.error', {message: error.message}) + ' ' +
                             i18n.t('errors.api.invites.errorSendingEmail.help');
-
-                        errors.logWarn(error.message);
+                        logging.warn(error.message);
                     }
 
                     return Promise.reject(error);

core/server/api/settings.js

@@ -6,6 +6,7 @@ var _            = require('lodash'),
     config       = require('../config'),
     canThis      = require('../permissions').canThis,
     errors       = require('../errors'),
+    logging      = require('../logging'),
     utils        = require('./utils'),
     i18n         = require('../i18n'),
 
@@ -36,17 +37,16 @@ var _            = require('lodash'),
 * @private
 */
 updateConfigCache = function () {
-    var errorMessages = [
-        i18n.t('errors.api.settings.invalidJsonInLabs'),
-        i18n.t('errors.api.settings.labsColumnCouldNotBeParsed'),
-        i18n.t('errors.api.settings.tryUpdatingLabs')
-    ], labsValue = {};
+    var labsValue = {};
 
     if (settingsCache.labs && settingsCache.labs.value) {
         try {
             labsValue = JSON.parse(settingsCache.labs.value);
-        } catch (e) {
-            errors.logError.apply(this, errorMessages);
+        } catch (err) {
+            err.message = i18n.t('errors.api.settings.invalidJsonInLabs');
+            err.context = i18n.t('errors.api.settings.labsColumnCouldNotBeParsed');
+            err.help = i18n.t('errors.api.settings.tryUpdatingLabs');
+            logging.error(err);
         }
     }
 

core/server/api/themes.js

@@ -7,6 +7,7 @@ var Promise = require('bluebird'),
     config = require('../config'),
     errors = require('../errors'),
     events = require('../events'),
+    logging = require('../logging'),
     storage = require('../storage'),
     settings = require('./settings'),
     apiUtils = require('./utils'),
@@ -103,15 +104,15 @@ themes = {
                 // happens in background
                 Promise.promisify(fs.removeSync)(zip.path)
                     .catch(function (err) {
-                        errors.logError(err);
+                        logging.error(err);
                     });
 
                 // remove extracted dir from gscan
                 // happens in background
                 if (theme) {
                     Promise.promisify(fs.removeSync)(theme.path)
                         .catch(function (err) {
-                            errors.logError(err);
+                            logging.error(err);
                         });
                 }
             });

core/server/api/users.js

@@ -164,8 +164,8 @@ users = {
                         return options;
                     });
                 });
-            }).catch(function handleError(error) {
-                return errors.formatAndRejectAPIError(error, i18n.t('errors.api.users.noPermissionToEditUser'));
+            }).catch(function handleError(err) {
+                return Promise.reject(new errors.NoPermissionError(err.message, i18n.t('errors.api.users.noPermissionToEditUser')));
             });
         }
 
@@ -214,8 +214,8 @@ users = {
             return canThis(options.context).destroy.user(options.id).then(function permissionGranted() {
                 options.status = 'all';
                 return options;
-            }).catch(function handleError(error) {
-                return errors.formatAndRejectAPIError(error, i18n.t('errors.api.users.noPermissionToDestroyUser'));
+            }).catch(function handleError(err) {
+                return Promise.reject(new errors.NoPermissionError(err.message, i18n.t('errors.api.users.noPermissionToDestroyUser')));
             });
         }
 
@@ -235,8 +235,8 @@ users = {
                 ]).then(function () {
                     return dataProvider.User.destroy(options);
                 }).return(null);
-            }).catch(function (error) {
-                return errors.formatAndRejectAPIError(error);
+            }).catch(function (err) {
+                return Promise.reject(new errors.NoPermissionError(err.message));
             });
         }
 
@@ -270,8 +270,8 @@ users = {
         function handlePermissions(options) {
             return canThis(options.context).edit.user(options.data.password[0].user_id).then(function permissionGranted() {
                 return options;
-            }).catch(function (error) {
-                return errors.formatAndRejectAPIError(error, i18n.t('errors.api.users.noPermissionToChangeUsersPwd'));
+            }).catch(function (err) {
+                return Promise.reject(new errors.NoPermissionError(err.message, i18n.t('errors.api.users.noPermissionToChangeUsersPwd')));
             });
         }
 
@@ -322,8 +322,6 @@ users = {
                 return canThis(options.context).assign.role(ownerRole);
             }).then(function () {
                 return options;
-            }).catch(function (error) {
-                return errors.formatAndRejectAPIError(error);
             });
         }
 
@@ -348,8 +346,6 @@ users = {
         // Pipeline calls each task passing the result of one to be the arguments for the next
         return pipeline(tasks, object, options).then(function formatResult(result) {
             return Promise.resolve({users: result});
-        }).catch(function (error) {
-            return errors.formatAndRejectAPIError(error);
         });
     }
 };

core/server/api/utils.js

@@ -91,7 +91,7 @@ utils = {
                 }
 
                 // For now, we can only handle showing the first validation error
-                return errors.logAndRejectError(validationErrors[0]);
+                return Promise.reject(validationErrors[0]);
             }
 
             // If we got an object, check that too
@@ -187,8 +187,6 @@ utils = {
 
             return permsPromise.then(function permissionGranted() {
                 return options;
-            }).catch(function handleError(error) {
-                return errors.formatAndRejectAPIError(error);
             });
         };
     },
@@ -218,8 +216,6 @@ utils = {
                 error.message = i18n.t('errors.api.utils.noPermissionToCall', {method: method, docName: docName});
                 // forward error to next catch()
                 return Promise.reject(error);
-            }).catch(function handleError(error) {
-                return errors.formatAndRejectAPIError(error);
             });
         };
     },
@@ -275,7 +271,7 @@ utils = {
      */
     checkObject: function (object, docName, editId) {
         if (_.isEmpty(object) || _.isEmpty(object[docName]) || _.isEmpty(object[docName][0])) {
-            return errors.logAndRejectError(new errors.BadRequestError(i18n.t('errors.api.utils.noRootKeyProvided', {docName: docName})));
+            return Promise.reject(new errors.BadRequestError(i18n.t('errors.api.utils.noRootKeyProvided', {docName: docName})));
         }
 
         // convert author property to author_id to match the name in the database
@@ -296,7 +292,7 @@ utils = {
         });
 
         if (editId && object[docName][0].id && parseInt(editId, 10) !== parseInt(object[docName][0].id, 10)) {
-            return errors.logAndRejectError(new errors.BadRequestError(i18n.t('errors.api.utils.invalidIdProvided')));
+            return Promise.reject(new errors.BadRequestError(i18n.t('errors.api.utils.invalidIdProvided')));
         }
 
         return Promise.resolve(object);

core/server/apps/amp/lib/helpers/amp_content.js

@@ -12,7 +12,7 @@ var hbs                  = require('express-hbs'),
     moment               = require('moment'),
     sanitizeHtml         = require('sanitize-html'),
     config               = require('../../../../config'),
-    errors               = require('../../../../errors'),
+    logging              = require('../../../../logging'),
     makeAbsoluteUrl      = require('../../../../utils/make-absolute-urls'),
     cheerio              = require('cheerio'),
     amperize             = new Amperize(),
@@ -126,9 +126,10 @@ function getAmperizeHTML(html, post) {
             amperize.parse(html, function (err, res) {
                 if (err) {
                     if (err.src) {
-                        errors.logError(err.message, 'AMP HTML couldn\'t get parsed: ' + err.src);
+                        err.context = 'AMP HTML couldn\'t get parsed: ' + err.src;
+                        logging.error(err);
                     } else {
-                        errors.logError(err);
+                        logging.error(err);
                     }
 
                     // save it in cache to prevent multiple calls to Amperize until

core/server/apps/index.js

@@ -1,7 +1,7 @@
 
 var _           = require('lodash'),
     Promise     = require('bluebird'),
-    errors      = require('../errors'),
+    logging     = require('../logging'),
     api         = require('../api'),
     loader      = require('./loader'),
     i18n        = require('../i18n'),
@@ -46,12 +46,11 @@ module.exports = {
 
                 appsToLoad = appsToLoad.concat(config.get('internalApps'));
             });
-        } catch (e) {
-            errors.logError(
-                i18n.t('errors.apps.failedToParseActiveAppsSettings.error', {message: e.message}),
-                i18n.t('errors.apps.failedToParseActiveAppsSettings.context'),
-                i18n.t('errors.apps.failedToParseActiveAppsSettings.help')
-            );
+        } catch (err) {
+            err.message = i18n.t('errors.apps.failedToParseActiveAppsSettings.error', {message: err.message});
+            err.help = i18n.t('errors.apps.failedToParseActiveAppsSettings.context');
+            err.context = i18n.t('errors.apps.failedToParseActiveAppsSettings.help');
+            logging.error(err);
 
             return Promise.resolve();
         }
@@ -88,11 +87,9 @@ module.exports = {
                 // Extend the loadedApps onto the available apps
                 _.extend(availableApps, loadedApps);
             }).catch(function (err) {
-                errors.logError(
-                    err.message || err,
-                    i18n.t('errors.apps.appWillNotBeLoaded.error'),
-                    i18n.t('errors.apps.appWillNotBeLoaded.help')
-                );
+                err.context = i18n.t('errors.apps.appWillNotBeLoaded.error');
+                err.help = i18n.t('errors.apps.appWillNotBeLoaded.help');
+                logging.error(err);
             });
         });
     },

core/server/apps/private-blogging/index.js

@@ -1,21 +1,26 @@
 var config     = require('../../config'),
     utils      = require('../../utils'),
-    errors     = require('../../errors'),
+    logging    = require('../../logging'),
     i18n       = require('../../i18n'),
     middleware = require('./lib/middleware'),
     router     = require('./lib/router');
 
 module.exports = {
     activate: function activate() {
+        var err, paths;
+
         if (utils.url.getSubdir()) {
-            var paths = utils.url.getSubdir().split('/');
+            paths = utils.url.getSubdir().split('/');
 
             if (paths.pop() === config.get('routeKeywords').private) {
-                errors.logErrorAndExit(
-                    new Error(i18n.t('errors.config.urlCannotContainPrivateSubdir.error')),
-                    i18n.t('errors.config.urlCannotContainPrivateSubdir.description'),
-                    i18n.t('errors.config.urlCannotContainPrivateSubdir.help')
-                );
+                err = new Error();
+                err.message = i18n.t('errors.config.urlCannotContainPrivateSubdir.error');
+                err.context = i18n.t('errors.config.urlCannotContainPrivateSubdir.description');
+                err.help = i18n.t('errors.config.urlCannotContainPrivateSubdir.help');
+                logging.error(err);
+
+                // @TODO: why?
+                process.exit(0);
             }
         }
     },

core/server/apps/private-blogging/lib/middleware.js

@@ -1,12 +1,13 @@
 var _           = require('lodash'),
     fs          = require('fs'),
-    config      = require('../../../config'),
+    session     = require('cookie-session'),
     crypto      = require('crypto'),
     path        = require('path'),
-    api         = require('../../../api'),
     Promise     = require('bluebird'),
+    config      = require('../../../config'),
+    api         = require('../../../api'),
     errors      = require('../../../errors'),
-    session     = require('cookie-session'),
+    logging     = require('../../../logging'),
     utils       = require('../../../utils'),
     i18n        = require('../../../i18n'),
     privateRoute = '/' + config.get('routeKeywords').private + '/',
@@ -55,7 +56,7 @@ privateBlogging = {
         if (req.path.lastIndexOf('/rss/', 0) === 0 ||
             req.path.lastIndexOf('/rss/') === req.url.length - 5 ||
             (req.path.lastIndexOf('/sitemap', 0) === 0 && req.path.lastIndexOf('.xml') === req.path.length - 4)) {
-            return errors.error404(req, res, next);
+            return next(new errors.NotFoundError(i18n.t('errors.errors.pageNotFound')));
         } else if (req.url.lastIndexOf('/robots.txt', 0) === 0) {
             fs.readFile(path.resolve(__dirname, '../', 'robots.txt'), function readFile(err, buf) {
                 if (err) {
@@ -145,7 +146,8 @@ privateBlogging = {
             ipCount = '',
             message = i18n.t('errors.middleware.spamprevention.tooManyAttempts'),
             deniedRateLimit = '',
-            password = req.body.password;
+            password = req.body.password,
+            err;
 
         if (password) {
             protectedSecurity.push({ip: remoteAddress, time: currentTime});
@@ -165,15 +167,19 @@ privateBlogging = {
         deniedRateLimit = (ipCount[remoteAddress] > rateProtectedAttempts);
 
         if (deniedRateLimit) {
-            errors.logError(
-                i18n.t('errors.middleware.spamprevention.forgottenPasswordIp.error', {rfa: rateProtectedAttempts, rfp: rateProtectedPeriod}),
-                i18n.t('errors.middleware.spamprevention.forgottenPasswordIp.context')
-            );
+            err = new Error();
+            err.message = i18n.t('errors.middleware.spamprevention.forgottenPasswordIp.error', {rfa: rateProtectedAttempts, rfp: rateProtectedPeriod});
+            err.context = i18n.t('errors.middleware.spamprevention.forgottenPasswordIp.context');
+            logging.error(err);
+
             message += rateProtectedPeriod === 3600 ? i18n.t('errors.middleware.spamprevention.waitOneHour') : i18n.t('errors.middleware.spamprevention.tryAgainLater');
+
+            // @TODO: why?
             res.error = {
                 message: message
             };
         }
+
         return next();
     }
 };