Changed to use debug not console in acceptance tests

- In an ideal world, our acceptance tests would be much, much faster
- ATM we output how much time is spent on reloading Ghost for each suite, but this is output with console
- Changed this to use DEBUG, so we don't clutter the UI normally
- Added further debug statements, and a cumulative time, so we can see where time is spent/wasted
- Added a DEBUG command for running acceptance tests with this output
- This shows us that reloading Ghost accounts for 50% of the test time

package.json

@@ -28,6 +28,7 @@
     "build": "grunt build",
     "test": "mocha --require=test/utils/overrides.js --exit --trace-warnings --recursive --timeout=60000",
     "test:all": "yarn test:unit && yarn test:acceptance && yarn test:regression",
+    "test:debug": "DEBUG=ghost:test* yarn test",
     "test:unit": "mocha --require=test/utils/overrides.js --exit --trace-warnings './test/unit/**/*_spec.js' --timeout=7000",
     "test:acceptance": "mocha --require=test/utils/overrides.js --exit --trace-warnings './test/api-acceptance/**/*_spec.js' './test/frontend-acceptance/**/*_spec.js' --timeout=10000",
     "test:regression": "mocha --require=test/utils/overrides.js --exit --trace-warnings  './test/regression/**/*_spec.js' --timeout=60000",

test/utils/acceptance-utils.js

@@ -1,4 +1,5 @@
 // Utility Packages
+const debug = require('@tryghost/debug')('test');
 const Promise = require('bluebird');
 const _ = require('lodash');
 const fs = require('fs-extra');
@@ -29,6 +30,7 @@ const context = require('./fixtures/context');
 
 let ghostServer;
 let existingData = {};
+let totalStartTime = 0;
 
 /**
  * Because we use ObjectID we don't know the ID of fixtures ahead of time
@@ -95,26 +97,29 @@ const prepareContentFolder = (options) => {
 // - re-run default fixtures
 // - reload affected services
 const restartModeGhostStart = async () => {
-    console.log('Restart Mode'); // eslint-disable-line no-console
+    debug('Reload Mode');
-
     // Teardown truncates all tables and also calls urlServiceUtils.reset();
     await dbUtils.teardown();
 
     // The tables have been truncated, this runs the fixture init task (init file 2) to re-add our default fixtures
     await knexMigrator.init({only: 2});
+    debug('init done');
 
     // Reset the settings cache
     await settingsService.init();
+    debug('settings done');
 
     // Reload the frontend
     await frontendSettingsService.init();
     await themeService.init();
+    debug('frontend done');
 
     // Reload the URL service & wait for it to be ready again
     // @TODO: why/how is this different to urlService.resetGenerators?
     urlServiceUtils.reset();
     urlServiceUtils.init();
     await urlServiceUtils.isFinished();
+    debug('routes done');
     // @TODO: why does this happen _after_ URL service
     web.shared.middlewares.customRedirects.reload();
 
@@ -135,9 +140,9 @@ const bootGhost = async () => {
 // - Start Ghost: Uses OLD Boot process
 const freshModeGhostStart = async (options) => {
     if (options.forceStart) {
-        console.log('Force Start Mode'); // eslint-disable-line no-console
+        debug('Forced Restart Mode');
     } else {
-        console.log('Fresh Start Mode'); // eslint-disable-line no-console
+        debug('Fresh Start Mode');
     }
 
     // Reset the DB
@@ -171,7 +176,8 @@ const freshModeGhostStart = async (options) => {
 };
 
 const startGhost = async (options) => {
-    console.time('Start Ghost'); // eslint-disable-line no-console
+    const startTime = Date.now();
+    debug('Start Ghost');
     options = _.merge({
         redirectsFile: true,
         redirectsFileExt: '.json',
@@ -194,7 +200,12 @@ const startGhost = async (options) => {
 
     // Expose fixture data, wrap-up and return
     await exposeFixtures();
-    console.timeEnd('Start Ghost'); // eslint-disable-line no-console
+
+    // Reporting
+    const totalTime = Date.now() - startTime;
+    totalStartTime += totalTime;
+    debug(`Started Ghost in ${totalTime / 1000}s`);
+    debug(`Accumulated start time is ${totalStartTime / 1000}s`);
     return ghostServer;
 };