Merge pull request #6086 from ember-cli/use-structured-logging

Use heimdalljs for structured instrumentation & structured logging

PERF_GUIDE.md

@@ -170,9 +170,10 @@ We would love a PR improving this guide.
 
 ### DEBUG logging
 
-We use the more or less standard [debug](https://github.com/visionmedia/debug)
-node_module for instrumentation. Often times this can be used, to quickly
-discover obviously wrong things.
+We use [heimdalljs-logger](https://github.com/heimdalljs/heimdalljs-logger) for
+logging, which supports the same usage as the de facto standard
+[debug](https://github.com/visionmedia/debug).  Quite often this can be used to
+quickly discover obviously wrong things.
 
 Usage:
 
@@ -182,8 +183,13 @@ Usage:
 * `DEBUG=broccoli* ember s` for all broccoli logging
 * `DEBUG=broccoli*,ember-cli* ember s` for both broccoli and ember-cli loggin
 
-The above patterns will be very verbose, a currated set of performance related
-logging flags are:
+The above patterns will be very verbose.  But to make them even more verbose you
+can set the log level via `DEBUG_LEVEL`
+
+* `DEBUG=* DEBUG_LEVEL=debug ember s`
+
+To make them a bit less verbose, a currated set of performance related logging
+flags are:
 
 + `DEBUG=broccoli-caching-writer:* ember s`
 + `DEBUG=broccoli-funnel:* ember s`
@@ -195,6 +201,27 @@ logging flags are:
 + `DEBUG=broccoli-merge-trees:compileTemplates* ember s`
 + `DEBUG=broccoli-merge-trees:compileTemplates* ember s`
 
+Because many plugins are used repeatedly it may be difficult to see the context
+for log entries.  By default, 3 nodes of context are shown.
+
+```
+DEBUG_LEVEL=debug DEBUG=broccoli-merge-trees: ember build
+broccoli-merge-trees: [TreeMerger (testFiles)#777 -> ConcatWithMaps#782 -> BroccoliMergeTrees#783] deriving patches
+```
+
+To show more (or fewer) lines of context, specify the environment variable
+`DEBUG_DEPTH`.
+
+```
+DEBUG_DEPTH=5 DEBUG_LEVEL=debug DEBUG=broccoli-merge-trees: ember build
+# => broccoli-merge-trees: [TreeMerger (allTrees)#1 -> BroccoliMergeTrees#668 -> TreeMerger (testFiles)#777 -> ConcatWithMaps#782 -> BroccoliMergeTrees#783]
+```
+
+`[... ConcatWithMaps#782 -> BroccoliMergeTrees#783]` means that the log entry
+occurred in broccoli merge-trees node with id 783, whose parent was a concat
+with maps node with id 782.  These ids are shown in the visualization graph.
+See [Visualization](#Visualization) for details.
+
 ... more on what to look for ...
 
 ### `broccoli-viz`
@@ -205,11 +232,17 @@ To visualize build tree, we use [graphviz](http://www.graphviz.org/). To
 install it run `brew install graphviz` or download it directly from
 [here](http://www.graphviz.org/Download.php).
 
+You will also need to install
+[broccoli-viz](https://github.com/stefanpenner/broccoli-viz) version `3.0.3` or
+higher.  `npm install -g broccoli-viz@^3.0.3`.
+
 To generate visualization:
 
 + `BROCCOLI_VIZ=true ember build`
-+ `dot -Tpng graph.<version>.dot > out.png` (each build, will generate an
-  additional graph.<build-number>.dot  graph.<build-number>.json)
++ `broccoli-viz broccoli-viz.0.json > broccoli-viz.0.dot`
++ `dot -Tpng broccoli-viz.0.dot > broccoli-viz.0.png`
+
+Each build will generate an additional graph, `broccoli-viz.<build-number>.json`
 
 #### in-depth look
 

lib/cli/cli.js

@@ -3,8 +3,8 @@
 var lookupCommand = require('./lookup-command');
 var Promise       = require('../ext/promise');
 var getOptionArgs = require('../utilities/get-option-args');
-var debug         = require('debug')('ember-cli:cli');
-var debugTesting  = require('debug')('ember-cli:testing');
+var logger        = require('heimdalljs-logger')('ember-cli:cli');
+var loggerTesting = require('heimdalljs-logger')('ember-cli:testing');
 
 /**
  * @private
@@ -58,7 +58,7 @@ function CLI(options) {
    */
   this.npmPackage = options.npmPackage;
 
-  debug('testing %o', !!this.testing);
+  logger.info('testing %o', !!this.testing);
 }
 
 module.exports = CLI;
@@ -110,7 +110,7 @@ CLI.prototype.run = function(environment) {
       }
     }
 
-    debug('command: %s', commandName);
+    logger.info('command: %s', commandName);
 
     if (!this.testing) {
       process.chdir(environment.project.root);
@@ -124,7 +124,7 @@ CLI.prototype.run = function(environment) {
     command.beforeRun(commandArgs);
 
     return Promise.resolve().then(function() {
-      debugTesting('cli: command.validateAndRun');
+      loggerTesting.info('cli: command.validateAndRun');
       return command.validateAndRun(commandArgs);
     }).then(function(result) {
       // if the help option was passed, call the help command
@@ -140,7 +140,7 @@ CLI.prototype.run = function(environment) {
 
       return result;
     }.bind(this)).then(function(exitCode) {
-      debugTesting('cli: command run complete. exitCode: ' + exitCode);
+      loggerTesting.info('cli: command run complete. exitCode: ' + exitCode);
       // TODO: fix this
       // Possibly this issue: https://github.com/joyent/node/issues/8329
       // Wait to resolve promise when running on windows.

lib/cli/index.js

@@ -3,7 +3,7 @@
 // Main entry point
 var requireAsHash = require('../utilities/require-as-hash');
 var packageConfig = require('../../package.json');
-var debug         = require('debug')('ember-cli:cli/index');
+var logger        = require('heimdalljs-logger')('ember-cli:cli/index');
 var merge         = require('ember-cli-lodash-subset').merge;
 var path          = require('path');
 
@@ -44,6 +44,14 @@ function clientId() {
   }
 }
 
+function configureLogger(env) {
+  var depth = Number(env['DEBUG_DEPTH']);
+  if (depth) {
+    var logConfig = require('heimdalljs').configFor('logging');
+    logConfig.depth = depth;
+  }
+}
+
 // Options: Array cliArgs, Stream inputStream, Stream outputStream
 module.exports = function(options) {
   var UI = options.UI || require('../ui');
@@ -52,6 +60,8 @@ module.exports = function(options) {
   var Leek = options.Leek || require('leek');
   var Project = require('../models/project');
 
+  configureLogger(process.env);
+
   // TODO: one UI (lib/models/project.js also has one for now...)
   var ui = new UI({
     inputStream:  options.inputStream,
@@ -92,7 +102,7 @@ module.exports = function(options) {
     leekOptions = defaultLeekOptions;
   }
 
-  debug('leek: %o', leekOptions);
+  logger.info('leek: %o', leekOptions);
 
   var leek = new Leek(leekOptions);
 

lib/commands/init.js

@@ -8,7 +8,7 @@ var SilentError           = require('silent-error');
 var validProjectName      = require('../utilities/valid-project-name');
 var normalizeBlueprint    = require('../utilities/normalize-blueprint-option');
 var mergeBlueprintOptions = require('../utilities/merge-blueprint-options');
-var debug                 = require('debug')('ember-cli:command:init');
+var logger                = require('heimdalljs-logger')('ember-cli:command:init');
 
 module.exports = Command.extend({
   name: 'init',
@@ -98,10 +98,10 @@ module.exports = Command.extend({
       return Promise.reject(new SilentError('We currently do not support a name of `' + packageName + '`.'));
     }
 
-    debug('before:installblueprint');
+    logger.info('before:installblueprint');
     return installBlueprint.run(blueprintOpts)
       .then(function() {
-        debug('after:installblueprint');
+        logger.info('after:installblueprint');
         if (commandOptions.skipGit === false) {
           return gitInit.run(commandOptions, rawArgs);
         }

lib/models/addon-discovery.js

@@ -5,7 +5,7 @@
 */
 
 var assign     = require('ember-cli-lodash-subset').assign;
-var debug      = require('debug')('ember-cli:addon-discovery');
+var logger     = require('heimdalljs-logger')('ember-cli:addon-discovery');
 var existsSync = require('exists-sync');
 var path       = require('path');
 var CoreObject = require('core-object');
@@ -65,7 +65,7 @@ var AddonDiscovery = CoreObject.extend({
     @method discoverProjectAddons
   */
   discoverChildAddons: function(addon) {
-    debug('discoverChildAddons: %s(%s)', addon.name, addon.root);
+    logger.info('discoverChildAddons: %s(%s)', addon.name, addon.root);
     var dependencyAddons = this.discoverFromDependencies(addon.root, addon.nodeModulesPath, addon.pkg, true);
     var inRepoAddons = this.discoverInRepoAddons(addon.root, addon.pkg);
     var addons = dependencyAddons.concat(inRepoAddons);
@@ -201,28 +201,28 @@ var AddonDiscovery = CoreObject.extend({
    */
   discoverAtPath: function(addonPath) {
     var pkgPath = path.join(addonPath, 'package.json');
-    debug('attemping to add: %s',  addonPath);
+    logger.info('attemping to add: %s',  addonPath);
 
     if (existsSync(pkgPath)) {
       var addonPkg = require(pkgPath);
       var keywords = addonPkg.keywords || [];
-      debug(' - module found: %s', addonPkg.name);
+      logger.info(' - module found: %s', addonPkg.name);
 
       addonPkg['ember-addon'] = addonPkg['ember-addon'] || {};
 
       if (keywords.indexOf('ember-addon') > -1) {
-        debug(' - is addon, adding...');
+        logger.info(' - is addon, adding...');
         var addonInfo = {
           name: addonPkg.name,
           path: addonPath,
           pkg: addonPkg,
         };
         return addonInfo;
       } else {
-        debug(' - no ember-addon keyword, not including.');
+        logger.info(' - no ember-addon keyword, not including.');
       }
     } else {
-      debug(' - no package.json (looked at ' + pkgPath + ').');
+      logger.info(' - no package.json (looked at ' + pkgPath + ').');
     }
 
     return null;

lib/models/addon.js

@@ -8,7 +8,7 @@ var existsSync   = require('exists-sync');
 var path         = require('path');
 var assign       = require('ember-cli-lodash-subset').assign;
 var SilentError  = require('silent-error');
-var debug        = require('debug')('ember-cli:addon');
+var logger       = require('heimdalljs-logger')('ember-cli:addon');
 
 var nodeModulesPath = require('node-modules-path');
 
@@ -226,13 +226,13 @@ var Addon = CoreObject.extend({
     }
     this._addonsInitialized = true;
 
-    debug('initializeAddons for: %s', this.name);
+    logger.info('initializeAddons for: %s', this.name);
 
     this.discoverAddons();
     this.addons = this.addonsFactory.initializeAddons(this.addonPackages);
 
     this.addons.forEach(function(addon) {
-      debug('addon: %s', addon.name);
+      logger.info('addon: %s', addon.name);
     });
   },
 

lib/models/addons-factory.js

@@ -6,7 +6,7 @@
 
 var CoreObject = require('core-object');
 var DAG        = require('../utilities/DAG');
-var debug      = require('debug')('ember-cli:addons-factory');
+var logger     = require('heimdalljs-logger')('ember-cli:addons-factory');
 
 /**
   AddonsFactory is responsible for instantiating a collection of addons, in the right order.
@@ -30,8 +30,8 @@ var AddonsFactory = CoreObject.extend({
     var Addon       = require('../models/addon');
     var addonInfo, emberAddonConfig;
 
-    debug('initializeAddons for: ', typeof addonParent.name === 'function' ? addonParent.name() : addonParent.name);
-    debug('     addon names are:', Object.keys(addonPackages));
+    logger.info('initializeAddons for: ', typeof addonParent.name === 'function' ? addonParent.name() : addonParent.name);
+    logger.info('     addon names are:', Object.keys(addonPackages));
 
     for (var name in addonPackages) {
       addonInfo        = addonPackages[name];
@@ -58,7 +58,7 @@ var AddonsFactory = CoreObject.extend({
       }
     });
 
-    debug(' addon info %o', addons.map(function(addon) {
+    logger.info(' addon info %o', addons.map(function(addon) {
       return {
         name: addon.name,
         times: {

lib/models/blueprint.js

@@ -23,7 +23,7 @@ var SilentError         = require('silent-error');
 var CoreObject          = require('core-object');
 var EOL                 = require('os').EOL;
 var bowEpParser         = require('bower-endpoint-parser');
-var debug               = require('debug')('ember-cli:blueprint');
+var logger              = require('heimdalljs-logger')('ember-cli:blueprint');
 var normalizeEntityName = require('ember-cli-normalize-entity-name');
 
 var stat                = Promise.denodeify(fs.stat);
@@ -436,14 +436,14 @@ var Blueprint = CoreObject.extend({
     this._checkForPod(options.verbose);
     this._checkInRepoAddonExists(options.inRepoAddon);
 
-    debug('START: processing blueprint: `%s`', this.name);
+    logger.info('START: processing blueprint: `%s`', this.name);
     var start = new Date();
     return this._process(
       options,
       this.beforeInstall,
       this.processFiles,
       this.afterInstall).finally(function() {
-        debug('END: processing blueprint: `%s` in (%dms)', this.name, new Date() - start);
+        logger.info('END: processing blueprint: `%s` in (%dms)', this.name, new Date() - start);
       }.bind(this));
   },