Merge pull request #5 from appscot/console_parity

Console parity

Author: dmarcelino

README.md

@@ -9,6 +9,9 @@ A thin wrapper for visionmedia/debug logger, adding levels and colored output.
 [visionmedia/debug](https://github.com/visionmedia/debug) is a ubitiquous logging library with 1000+ dependants. Given how widespread it is and the convenience of namespaces it is a great logger for library modules.
 `debug-logger` is a convenience wrapper around `debug` that adds level based coloured output. Each instance of `debug-logger` will lazily instantiate several instances of `debug` such as `namespace:info`, `namespace:warn`, `namespace:error`, etc. All these are configurable. `debug-logger` has no dependencies besides `debug`.
 
+`debug-logger` uses the same syntax as [node.js console](https://nodejs.org/api/console.html) so you can use it as drop in replacement. 
+Check and run [examples/console.parity.js](https://github.com/appscot/debug-logger/blob/master/examples/console.parity.js) for more details.
+
 At AppsCot we use `debug-logger` in [waterline-orientdb](https://github.com/appscot/waterline-orientdb).
 
 ## Instalation
@@ -105,6 +108,66 @@ log.warn("util.format style string: %s, number: %d and json: %j.", "foo", 13, {
 ```
 ![multiple arguments](https://raw.githubusercontent.com/wiki/appscot/debug-logger/arguments.png)
 
+### Measure code execution time
+```javascript
+log.time('100-elements');
+for (var i = 0; i < 100; i++) {
+  ;
+}
+log.timeEnd('100-elements');
+
+log.time('setTimeout');
+setTimeout(function(){
+  var diff = log.timeEnd('setTimeout', 'debug');
+  log.trace('log.timeEnd returns diff so it can be reused:', diff);
+}, 262);
+```
+![code time](https://raw.githubusercontent.com/wiki/appscot/debug-logger/time.png)
+
+### Inspect object
+```javascript
+log.dir({ foo: { bar: 1 } });
+log.dir({ foo: { bar: 1 } }, { depth: 0 }, 'warn');
+```
+![dir inspect](https://raw.githubusercontent.com/wiki/appscot/debug-logger/dir.png)
+
+### Assert condition
+```javascript
+log.assert(1 == 0);
+
+// More elaborate example
+var log = require('..').config({
+  levels: { 
+    fatal: {
+      color : 5,  //magenta
+      prefix : '',
+      namespaceSuffix : ':fatal',
+      level : 6
+    }
+  }
+})('myapp');
+log.assert(1 == 0, 'testing %s %d', 'log.assert', 666, 'fatal');
+```
+![assert](https://raw.githubusercontent.com/wiki/appscot/debug-logger/assert.png)
+
+### stderr vs stdout
+By default trace, debug, log and info output to stdout while warn and error output to stderr.
+This is configurable, [example](https://github.com/appscot/debug-logger/blob/master/examples/stdout_stderr.js):
+```javascript
+var log = require('debug')('myapp');
+log.trace("goes to stdout!");
+log.debug("goes to stdout!");
+log.log("goes to stdout!");
+log.info("goes to stdout!");
+log.warn("goes to stderr");
+log.error("goes to stderr");
+
+// outputting only to stdout
+var stdout = require('debug').config({ levels: { warn: { fd: 1 }, error: { fd: 1 } } })('stdoutapp');
+stdout.warn("goes to stdout!");
+stdout.error("goes to stdout!");
+```
+
 ### Filter by log level (instead of namespace)
 ```sh
 export DEBUG_LEVEL=info
@@ -132,12 +195,33 @@ Prints the data prepended by log level. If the terminal supports colors, each le
 ```
 This function can take multiple arguments in a printf()-like way, if formatting elements are not found in the first string then util.inspect is used on each argument.
 
+#### `log([message][, ...])`
+Outputs the message using the root/default `debug` instance, without the level suffix. Example:
+```
+  myapp I'm a root/default debug instance output +0ms
+```
+
 #### `log[level].logger()`
-Returns the default debug instance used by `level`.
+Returns the default `debug` instance used by `level`.
 
 #### `log[level].enabled()`
 Boolean indicating if `level`'s logger is enabled.
 
+#### `log.time(label)`
+Mark a time.
+
+#### `log.timeEnd(label[, level])`
+Finish timer, record output. `level` will determine the logger used to output the result (defaults to 'log').
+Return duration in ms.
+
+#### `log.dir(obj[, options][, level])`
+Uses util.inspect on obj and prints resulting string to the appropriate logger. This function bypasses any custom inspect() function on obj. An optional [options object](https://nodejs.org/api/console.html#console_console_dir_obj_options) may be passed that alters certain aspects of the formatted string.
+`level` will determine the logger used to output the result (defaults to 'log').
+
+#### `log.assert(value[, message][, ...][, level])`
+Similar to [console.assert()](https://nodejs.org/api/console.html#console_console_assert_value_message). 
+Additionally it outputs the error using the appropriate logger set by `level` (defaults to 'error').
+
 ### Module
 
 #### `.config(obj)`

debug-logger.js

@@ -40,25 +40,29 @@ exports.levels = {
     color : exports.colors.cyan,
     prefix : '',
     namespaceSuffix : ':trace',
-    level : 0
+    level : 0,
+    fd : 1  // currently only 1 (stdout) is supported. stderr is debug's standard
   },
   debug : {
     color : exports.colors.blue,
     prefix : '',
     namespaceSuffix : ':debug',
-    level : 1
+    level : 1,
+    fd : 1
   },
   log : {
     color : '',
     prefix : '  ',
     namespaceSuffix : ':log',
-    level : 2
+    level : 2,
+    fd : 1
   },
   info : {
     color : exports.colors.green,
     prefix : ' ',
     namespaceSuffix : ':info',
-    level : 3
+    level : 3,
+    fd : 1
   },
   warn : {
     color : exports.colors.yellow,
@@ -79,6 +83,50 @@ exports.styles = {
 };
 
 
+function time(label){
+  this.timeLabels[label] = process.hrtime();
+}
+
+function timeEnd(label, level){
+  level = level || 'log';
+  var diff = process.hrtime(this.timeLabels[label]);
+  var diffMs = (diff[0] * 1e9 + diff[1]) / 1e6;
+  this[level](label + ':', diffMs + 'ms');
+  return diffMs;
+}
+
+function dir(obj, options, level){
+  if(!level && this[options]){
+    level = options;
+    options = undefined;
+  }
+  options = options || exports.inspectOptions;
+  level = level || 'log';
+  this[level](util.inspect(obj, options));
+}
+
+function assert(expression){
+  if (!expression) {
+    var level = 'error';
+    var arr = Array.prototype.slice.call(arguments, 1);
+    if(this[arr[arr.length-1]]){
+      level = arr[arr.length-1];
+      arr = arr.slice(0, -1);
+    }
+    var assrt = require('assert');
+    var err = new assrt.AssertionError({
+      message: util.format.apply(this, arr),
+      actual: false,
+      expected: true,
+      operator: '==',
+      stackStartFunction: assert
+    });
+    this[level](err);
+    throw err;
+  }
+}
+
+
 var ensureNewlineEnabled = false;
 var fd = parseInt(process.env.DEBUG_FD, 10) || 2;
 function ensureNewline(){
@@ -210,10 +258,21 @@ function getForeColor(color){
   return color;
 }
 
+function disableColors(loggerLevel, disable){
+  if(disable){
+    loggerLevel.color = '';
+    loggerLevel.reset = '';
+    loggerLevel.inspectionHighlight = '';
+  }
+}
+
 var debugInstances = {};
-function getDebugInstance(namespace, color){
+function getDebugInstance(namespace, color, fd){
   if(!debugInstances[namespace]){
     debugInstances[namespace] = vmDebug(namespace);
+    if(fd === 1 && isNaN(parseInt(process.env.DEBUG_FD))){
+      debugInstances[namespace].log = console.log.bind(console);
+    }
     if(!isNaN(color)){
       debugInstances[namespace].color = color;
     }
@@ -224,29 +283,41 @@ function getDebugInstance(namespace, color){
 
 function debugLogger(namespace) {
   var levels = exports.levels;
-  var debugLoggers = { 'default': getDebugInstance.bind(this, namespace) };
+  var debugLoggers = { 'default': getDebugInstance.bind(this, namespace, '') };
 
-  var logger = {};
+  var logger = function(){
+    debugLoggers['default']().apply(this, arguments);
+  };
   logger.logLevel = getLogLevel(namespace);
 
+  logger.timeLabels = {};
+  logger.time = time;
+  logger.timeEnd = timeEnd;
+  logger.dir = dir;
+  logger.assert = assert;
+  
   Object.keys(levels).forEach(function(levelName) {
     var loggerNamespaceSuffix = levels[levelName].namespaceSuffix ? levels[levelName].namespaceSuffix : 'default';
     if(!debugLoggers[loggerNamespaceSuffix]){
-      debugLoggers[loggerNamespaceSuffix] = getDebugInstance.bind(this, namespace + loggerNamespaceSuffix, levels[levelName].color);
+      debugLoggers[loggerNamespaceSuffix] = getDebugInstance.bind(this, namespace + loggerNamespaceSuffix, levels[levelName].color, levels[levelName].fd);
     }
     var levelLogger = debugLoggers[loggerNamespaceSuffix];
-    var color = vmDebug.useColors ? getForeColor(levels[levelName].color) : '';
-    var reset = vmDebug.useColors ? exports.colorReset : '';
-    var inspectionHighlight = vmDebug.useColors ? exports.styles.underline : '';
+    
+    var initialized = false;
 
     function logFn() {
       if (logger.logLevel > logger[levelName].level) { return; }
 
       var levelLog = levelLogger();
       if(!levelLog.enabled) { return; }
 
+      if(!initialized){
+        initialized = true;
+        disableColors(logger[levelName], !levelLog.useColors);
+      }
+      
       if (isString(arguments[0]) && hasFormattingElements(arguments[0])){
-        arguments[0] = color + levels[levelName].prefix + reset + arguments[0];
+        arguments[0] = logger[levelName].color + levels[levelName].prefix + logger[levelName].reset + arguments[0];
         return levelLog.apply(this, arguments);
       }
 
@@ -263,14 +334,14 @@ function debugLogger(namespace) {
         param = errorStrings[i];
         message += i === 0 ? param[0] : ' ' + param[0];
         if (param.length > 1) {
-          var highlightStack = param[1].indexOf('Stack') >= 0 ? color : '';
+          var highlightStack = param[1].indexOf('Stack') >= 0 ? logger[levelName].color : '';
           inspections += '\n' +
-            inspectionHighlight + '___' + param[1] + ' #' + n++ + '___' + reset +'\n' +
-            highlightStack + param[2] + reset;
+            logger[levelName].inspectionHighlight + '___' + param[1] + ' #' + n++ + '___' + logger[levelName].reset +'\n' +
+            highlightStack + param[2] + logger[levelName].reset;
         }
       };
 
-      levelLog(color + levels[levelName].prefix + reset + message + inspections);
+      levelLog(logger[levelName].color + levels[levelName].prefix + logger[levelName].reset + message + inspections);
     };
 
     function logNewlineFn() {
@@ -280,10 +351,13 @@ function debugLogger(namespace) {
       logFn.apply(logFn, arguments);
     };
 
-    logger[levelName] = ensureNewlineEnabled ? logNewlineFn : logFn;    
+    logger[levelName] = ensureNewlineEnabled ? logNewlineFn : logFn;
     logger[levelName].level = levels[levelName].level;
     logger[levelName].logger  = function(){ return levelLogger(); };
     logger[levelName].enabled = function(){ return logger.logLevel <= logger[levelName].level && levelLogger().enabled; };
+    logger[levelName].color = getForeColor(levels[levelName].color);
+    logger[levelName].reset = exports.colorReset;
+    logger[levelName].inspectionHighlight = exports.styles.underline;
   });
 
   return logger;

examples/console.parity.js

@@ -0,0 +1,55 @@
+// The below only shows up if environment variable DEBUG includes "myapp:*" namespace
+// e.g.: export DEBUG=$DEBUG,myapp:*
+var log = require('..')('myapp');
+
+var count = 5;
+console.log('count: %d', count);
+log.log('count: %d', count);
+
+br();
+count++;
+console.info('count:', count, '...');
+log.info('count:', count, '...');
+
+br();
+count++;
+console.error('count: %d', count);
+log.error('count: %d', count);
+
+br();
+console.warn('plain message');
+log.warn('plain message');
+
+br();
+console.dir({ foo: { bar: 1 } }, { depth: 0 });
+log.dir({ foo: { bar: 1 } }, { depth: 0 });
+
+br();
+console.time('100-elements');
+log.time('100-elements');
+for (var i = 0; i < 100; i++) {
+  ;
+}
+console.timeEnd('100-elements');
+log.timeEnd('100-elements');
+
+br();
+count++;
+// log.trace accepts similar input as console.log but it behaves more like log4j's TRACE as it prints a finer level of events
+console.trace('count: %d', count);
+log.trace('count: %d', count);
+
+br();
+try{
+  console.assert(1 == 0, 'Wrong value');
+} catch(err){}
+try{
+  log.assert(1 == 0, 'Wrong value');
+} catch(err){}
+
+
+
+br();
+function br(){
+  console.log();
+}