⏱ 🛠 Add debug@2.2.0 & wire up in key places (#7469)

refs #2001, #7116

- added debug and wired it up:
  - across several key parts of the boot process
  - throughout the middleware loading
  - for requests
  - at render points for key routes

core/server/controllers/admin.js

@@ -1,4 +1,5 @@
-var _             = require('lodash'),
+var debug         = require('debug')('ghost:admin:controller'),
+    _             = require('lodash'),
     Promise       = require('bluebird'),
     api           = require('../api'),
     config        = require('../config'),
@@ -12,6 +13,7 @@ adminControllers = {
     // Path: /ghost/
     // Method: GET
     index: function index(req, res) {
+        debug('index called');
         /*jslint unparam:true*/
 
         function renderIndex() {
@@ -36,6 +38,7 @@ adminControllers = {
                     configuration.ghostAuthId = {value: result.patronus.uuid, type: 'string'};
                 }
 
+                debug('rendering default template');
                 res.render('default', {
                     configuration: configuration
                 });

core/server/controllers/frontend/index.js

@@ -4,7 +4,8 @@
 
 /*global require, module */
 
-var api         = require('../../api'),
+var debug = require('debug')('ghost:channels:single'),
+    api         = require('../../api'),
     utils       = require('../../utils'),
     filters     = require('../../filters'),
     templates   = require('./templates'),
@@ -23,11 +24,13 @@ var api         = require('../../api'),
 * Returns a function that takes the post to be rendered.
 */
 function renderPost(req, res) {
+    debug('renderPost called');
     return function renderPost(post) {
         var view = templates.single(req.app.get('activeTheme'), post),
             response = formatResponse.single(post);
 
         setResponseContext(req, res, response);
+        debug('Rendering view: ' + view);
         res.render(view, response);
     };
 }

core/server/controllers/frontend/render-channel.js

@@ -1,4 +1,5 @@
-var _           = require('lodash'),
+var debug = require('debug')('ghost:channels:render'),
+    _           = require('lodash'),
     errors      = require('../../errors'),
     filters     = require('../../filters'),
     safeString  = require('../../utils/index').safeString,
@@ -11,6 +12,7 @@ var _           = require('lodash'),
     templates          = require('./templates');
 
 function renderChannel(req, res, next) {
+    debug('renderChannel called');
     // Parse the parameters we need from the URL
     var channelOpts = req.channelConfig,
         pageParam = req.params.page !== undefined ? req.params.page : 1,
@@ -53,6 +55,7 @@ function renderChannel(req, res, next) {
             result.posts = posts;
             result = formatResponse.channel(result);
             setResponseContext(req, res);
+            debug('Rendering view: ' + view);
             res.render(view, result);
         });
     }).catch(handleError(next));

core/server/ghost-server.js

@@ -1,6 +1,7 @@
 // # Ghost Server
 // Handles the creation of an HTTP Server for Ghost
-var Promise = require('bluebird'),
+var debug = require('debug')('ghost:server'),
+    Promise = require('bluebird'),
     chalk = require('chalk'),
     fs = require('fs'),
     path = require('path'),
@@ -36,6 +37,7 @@ function GhostServer(rootApp) {
  * @return {Promise} Resolves once Ghost has started
  */
 GhostServer.prototype.start = function (externalApp) {
+    debug('Starting...');
     var self = this,
         rootApp = externalApp ? externalApp : self.rootApp,
         socketConfig, socketValues = {
@@ -89,6 +91,7 @@ GhostServer.prototype.start = function (externalApp) {
         });
         self.httpServer.on('connection', self.connection.bind(self));
         self.httpServer.on('listening', function () {
+            debug('...Started');
             self.logStartMessages();
             resolve(self);
         });

core/server/index.js

@@ -13,7 +13,8 @@
 require('./overrides');
 
 // Module dependencies
-var express = require('express'),
+var debug = require('debug')('ghost:boot:init'),
+    express = require('express'),
     uuid = require('node-uuid'),
     Promise = require('bluebird'),
     i18n = require('./i18n'),
@@ -60,6 +61,7 @@ function initDbHashAndFirstRun() {
 // Sets up the express server instances, runs init on a bunch of stuff, configures views, helpers, routes and more
 // Finally it returns an instance of GhostServer
 function init(options) {
+    debug('Init Start...');
     options = options || {};
 
     var ghostServer, parentApp;
@@ -71,11 +73,14 @@ function init(options) {
 
     // Initialize Internationalization
     i18n.init();
+    debug('I18n done');
 
     return readDirectory(config.getContentPath('apps')).then(function loadThemes(result) {
         config.set('paths:availableApps', result);
         return api.themes.loadThemes();
     }).then(function () {
+        debug('Themes & apps done');
+
         models.init();
         // @TODO: this is temporary, replace migrations with a warning if a DB exists
         return db.bootUp();
@@ -83,13 +88,16 @@ function init(options) {
         // Populate any missing default settings
         return models.Settings.populateDefaults();
     }).then(function () {
+        debug('Models & database done');
         // Initialize the settings cache
         return api.init();
     }).then(function () {
+        debug('API done');
         // Initialize the permissions actions and objects
         // NOTE: Must be done before initDbHashAndFirstRun calls
         return permissions.init();
     }).then(function () {
+        debug('Permissions done');
         return Promise.join(
             // Check for or initialise a dbHash.
             initDbHashAndFirstRun(),
@@ -101,11 +109,12 @@ function init(options) {
             slack.listen()
         );
     }).then(function () {
+        debug('Apps, XMLRPC, Slack done');
         // Get reference to an express app instance.
         parentApp = express();
-
         // ## Middleware and Routing
         middleware(parentApp);
+        debug('Express done');
 
         // Log all theme errors and warnings
         validateThemes(config.getContentPath('themes'))
@@ -125,12 +134,14 @@ function init(options) {
                 parentApp.use(response.auth);
             });
     }).then(function () {
+        debug('Auth done');
         return new GhostServer(parentApp);
     }).then(function (_ghostServer) {
         ghostServer = _ghostServer;
 
         // scheduling can trigger api requests, that's why we initialize the module after the ghost server creation
         // scheduling module can create x schedulers with different adapters
+        debug('Server done');
         return scheduling.init({
             active: config.get('scheduling').active,
             apiUrl: utils.url.apiUrl(),
@@ -138,6 +149,8 @@ function init(options) {
             contentPath: config.getContentPath('scheduling')
         });
     }).then(function () {
+        debug('Scheduling done');
+        debug('...Init End');
         return ghostServer;
     });
 }

core/server/middleware/index.js

@@ -1,4 +1,5 @@
-var bodyParser      = require('body-parser'),
+var debug           = require('debug')('ghost:middleware'),
+    bodyParser      = require('body-parser'),
     compress        = require('compression'),
     config          = require('../config'),
     errors          = require('../errors'),
@@ -48,6 +49,7 @@ middleware = {
 };
 
 setupMiddleware = function setupMiddleware(blogApp) {
+    debug('Middleware start');
     var logging = config.get('logging'),
         corePath = config.get('paths').corePath,
         adminApp = express(),
@@ -67,9 +69,11 @@ setupMiddleware = function setupMiddleware(blogApp) {
     // Create a hbs instance for admin and init view engine
     adminApp.set('view engine', 'hbs');
     adminApp.engine('hbs', adminHbs.express3({}));
+    debug('Views done');
 
     // Load helpers
     helpers.loadCoreHelpers(adminHbs);
+    debug('Helpers done');
 
     // Make sure 'req.secure' is valid for proxied requests
     // (X-Forwarded-Proto header will be checked, if present)
@@ -84,6 +88,17 @@ setupMiddleware = function setupMiddleware(blogApp) {
         }
     }
 
+    if (debug.enabled) {
+        // debug keeps a timer, so this is super useful
+        blogApp.use((function () {
+            var reqDebug = require('debug')('ghost:req');
+            return function debugLog(req, res, next) {
+                reqDebug('Request', req.originalUrl);
+                next();
+            };
+        })());
+    }
+
     // Preload link headers
     if (config.get('preloadHeaders')) {
         blogApp.use(netjet({
@@ -111,6 +126,7 @@ setupMiddleware = function setupMiddleware(blogApp) {
         {maxAge: utils.ONE_YEAR_MS, fallthrough: false}
     ));
 
+    debug('Static content done');
     // First determine whether we're serving admin or theme content
     blogApp.use(decideIsAdmin);
     blogApp.use(themeHandler.updateActiveTheme);
@@ -131,6 +147,7 @@ setupMiddleware = function setupMiddleware(blogApp) {
 
     // Theme only config
     blogApp.use(staticTheme());
+    debug('Themes done');
 
     // setup middleware for internal apps
     // @TODO: refactor this to be a proper app middleware hook for internal & external apps
@@ -140,6 +157,7 @@ setupMiddleware = function setupMiddleware(blogApp) {
             app.setupMiddleware(blogApp);
         }
     });
+    debug('Internal apps done');
 
     // Serve sitemap.xsl file
     blogApp.use(serveSharedFile('sitemap.xsl', 'text/xsl', utils.ONE_DAY_S));
@@ -173,6 +191,8 @@ setupMiddleware = function setupMiddleware(blogApp) {
     // local data
     blogApp.use(themeHandler.ghostLocals);
 
+    debug('General middleware done');
+
     // ### Routing
     // Set up API routes
     blogApp.use(routes.apiBaseUri, routes.api(middleware));
@@ -181,8 +201,8 @@ setupMiddleware = function setupMiddleware(blogApp) {
     adminApp.use(redirectToSetup);
     adminApp.use(maintenance);
     adminApp.use(routes.admin());
-
     blogApp.use('/ghost', adminApp);
+    debug('Admin app & api done');
 
     // send 503 error page in case of maintenance
     blogApp.use(maintenance);
@@ -196,6 +216,7 @@ setupMiddleware = function setupMiddleware(blogApp) {
 
     // 500 Handler
     blogApp.use(errors.error500);
+    debug('Middleware end');
 };
 
 module.exports = setupMiddleware;

index.js

@@ -1,16 +1,18 @@
 // # Ghost Startup
 // Orchestrates the startup of Ghost when run from command line.
-
 var ghost = require('./core'),
+    debug = require('debug')('ghost:boot:index'),
     express = require('express'),
     errors = require('./core/server/errors'),
     utils = require('./core/server/utils'),
     parentApp = express();
 
+debug('Initialising Ghost');
 ghost().then(function (ghostServer) {
     // Mount our Ghost instance on our desired subdirectory path if it exists.
     parentApp.use(utils.url.getSubdir(), ghostServer.rootApp);
 
+    debug('Starting Ghost');
     // Let Ghost handle starting our server instance.
     ghostServer.start(parentApp);
 }).catch(function (err) {

package.json

@@ -38,6 +38,7 @@
     "cookie-session": "1.2.0",
     "cors": "2.8.1",
     "csv-parser": "1.11.0",
+    "debug": "2.2.0",
     "downsize": "0.0.8",
     "express": "4.14.0",
     "express-hbs": "1.0.3",