util: Add debuglog, deprecate console lookalikes

doc/api/util.markdown

@@ -2,9 +2,46 @@
 
     Stability: 5 - Locked
 
-These functions are in the module `'util'`. Use `require('util')` to access
+These functions are in the module `'util'`. Use `require('util')` to
-them.
+access them.
 
+The `util` module is primarily designed to support the needs of Node's
+internal APIs.  Many of these utilities are useful for your own
+programs.  If you find that these functions are lacking for your
+purposes, however, you are encouraged to write your own utilities.  We
+are not interested in any future additions to the `util` module that
+are unnecessary for Node's internal functionality.
+
+## util.debuglog(section)
+
+* `section` {String} The section of the program to be debugged
+* Returns: {Function} The logging function
+
+This is used to create a function which conditionally writes to stderr
+based on the existence of a `NODE_DEBUG` environment variable.  If the
+`section` name appears in that environment variable, then the returned
+function will be similar to `console.error()`.  If not, then the
+returned function is a no-op.
+
+For example:
+
+```javascript
+var debuglog = util.debuglog('foo');
+
+var bar = 123;
+debuglog('hello from foo [%d]', bar);
+```
+
+If this program is run with `NODE_DEBUG=foo` in the environment, then
+it will output something like:
+
+    FOO 3245: hello from foo [123]
+
+where `3245` is the process id.  If it is not run with that
+environment variable set, then it will not print anything.
+
+You may separate multiple `NODE_DEBUG` environment variables with a
+comma.  For example, `NODE_DEBUG=fs,net,tls`.
 
 ## util.format(format, [...])
 
@@ -37,35 +74,12 @@ Each argument is converted to a string with `util.inspect()`.
     util.format(1, 2, 3); // '1 2 3'
 
 
-## util.debug(string)
-
-A synchronous output function. Will block the process and
-output `string` immediately to `stderr`.
-
-    require('util').debug('message on stderr');
-
-## util.error([...])
-
-Same as `util.debug()` except this will output all arguments immediately to
-`stderr`.
-
-## util.puts([...])
-
-A synchronous output function. Will block the process and output all arguments
-to `stdout` with newlines after each argument.
-
-## util.print([...])
-
-A synchronous output function. Will block the process, cast each argument to a
-string then output to `stdout`. Does not place newlines after each argument.
-
 ## util.log(string)
 
 Output with timestamp on `stdout`.
 
     require('util').log('Timestamped message.');
 
-
 ## util.inspect(object, [options])
 
 Return a string representation of `object`, which is useful for debugging.
@@ -94,6 +108,8 @@ Example of inspecting all properties of the `util` object:
 
 ### Customizing `util.inspect` colors
 
+<!-- type=misc -->
+
 Color output (if enabled) of `util.inspect` is customizable globally
 via `util.inspect.styles` and `util.inspect.colors` objects.
 
@@ -116,6 +132,8 @@ There are also `bold`, `italic`, `underline` and `inverse` codes.
 
 ### Custom `inspect()` function on Objects
 
+<!-- type=misc -->
+
 Objects also may define their own `inspect(depth)` function which `util.inspect()`
 will invoke and use the result of when inspecting the object:
 
@@ -198,17 +216,6 @@ Returns `true` if the given "object" is an `Error`. `false` otherwise.
       // false
 
 
-## util.pump(readableStream, writableStream, [callback])
-
-    Stability: 0 - Deprecated: Use readableStream.pipe(writableStream)
-
-Read the data from `readableStream` and send it to the `writableStream`.
-When `writableStream.write(data)` returns `false` `readableStream` will be
-paused until the `drain` event occurs on the `writableStream`. `callback` gets
-an error as its only argument and is called when `writableStream` is closed or
-when an error occurs.
-
-
 ## util.inherits(constructor, superConstructor)
 
 Inherit the prototype methods from one
@@ -241,3 +248,35 @@ through the `constructor.super_` property.
         console.log('Received data: "' + data + '"');
     })
     stream.write("It works!"); // Received data: "It works!"
+
+
+## util.debug(string)
+
+    Stability: 0 - Deprecated: use console.error() instead.
+
+Deprecated predecessor of `console.error`.
+
+## util.error([...])
+
+    Stability: 0 - Deprecated: Use console.error() instead.
+
+Deprecated predecessor of `console.error`.
+
+## util.puts([...])
+
+    Stability: 0 - Deprecated: Use console.log() instead.
+
+Deprecated predecessor of `console.log`.
+
+## util.print([...])
+
+    Stability: 0 - Deprecated: Use `console.log` instead.
+
+Deprecated predecessor of `console.log`.
+
+
+## util.pump(readableStream, writableStream, [callback])
+
+    Stability: 0 - Deprecated: Use readableStream.pipe(writableStream)
+
+Deprecated predecessor of `stream.pipe()`.

lib/_http_client.js

@@ -205,7 +205,7 @@ function socketErrorListener(err) {
   var socket = this;
   var parser = socket.parser;
   var req = socket._httpMessage;
-  debug('HTTP SOCKET ERROR: ' + err.message + '\n' + err.stack);
+  debug('SOCKET ERROR:', err.message, err.stack);
 
   if (req) {
     req.emit('error', err);
@@ -325,7 +325,7 @@ function parserOnIncomingClient(res, shouldKeepAlive) {
   // to the content-length of the entity-body had the request
   // been a GET.
   var isHeadResponse = req.method == 'HEAD';
-  debug('AGENT isHeadResponse ' + isHeadResponse);
+  debug('AGENT isHeadResponse', isHeadResponse);
 
   if (res.statusCode == 100) {
     // restart the parser, as this is a continue message.

lib/_http_common.js

@@ -28,12 +28,7 @@ var readStart = incoming.readStart;
 var readStop = incoming.readStop;
 
 
-var debug;
+var debug = require('util').debuglog('http');
-if (process.env.NODE_DEBUG && /http/.test(process.env.NODE_DEBUG)) {
-  debug = function(x) { console.error('HTTP: %s', x); };
-} else {
-  debug = function() { };
-}
 exports.debug = debug;
 
 exports.CRLF = '\r\n';

lib/module.js

@@ -62,12 +62,7 @@ Module.wrap = NativeModule.wrap;
 
 var path = NativeModule.require('path');
 
-Module._debug = function() {};
+Module._debug = NativeModule.require('util').debuglog('module');
-if (process.env.NODE_DEBUG && /module/.test(process.env.NODE_DEBUG)) {
-  Module._debug = function(x) {
-    console.error(x);
-  };
-}
 
 
 // We use this alias for the preprocessor that filters it out

lib/net.js

@@ -51,20 +51,7 @@ function createHandle(fd) {
 }
 
 
-var debug;
+var debug = util.debuglog('net');
-if (process.env.NODE_DEBUG && /net/.test(process.env.NODE_DEBUG)) {
-  var pid = process.pid;
-  debug = function(x) {
-    // if console is not set up yet, then skip this.
-    if (!console.error)
-      return;
-    console.error('NET: %d', pid,
-                  util.format.apply(util, arguments).slice(0, 500));
-  };
-} else {
-  debug = function() { };
-}
-
 
 function isPipeName(s) {
   return typeof s === 'string' && toNumber(s) === false;

lib/timers.js

@@ -26,12 +26,7 @@ var assert = require('assert').ok;
 // Timeout values > TIMEOUT_MAX are set to 1.
 var TIMEOUT_MAX = 2147483647; // 2^31-1
 
-var debug;
+var debug = require('util').debuglog('timer');
-if (process.env.NODE_DEBUG && /timer/.test(process.env.NODE_DEBUG)) {
-  debug = function() { require('util').error.apply(this, arguments); };
-} else {
-  debug = function() { };
-}
 
 
 // IDLE TIMEOUTS
@@ -78,17 +73,17 @@ function listOnTimeout() {
   var msecs = this.msecs;
   var list = this;
 
-  debug('timeout callback ' + msecs);
+  debug('timeout callback %d', msecs);
 
   var now = Date.now();
-  debug('now: ' + now);
+  debug('now: %s', now);
 
   var first;
   while (first = L.peek(list)) {
     var diff = now - first._idleStart;
     if (diff < msecs) {
       list.start(msecs - diff, 0);
-      debug(msecs + ' list wait because diff is ' + diff);
+      debug('%d list wait because diff is %d', msecs, diff);
       return;
     } else {
       L.remove(first);
@@ -121,7 +116,7 @@ function listOnTimeout() {
     }
   }
 
-  debug(msecs + ' list empty');
+  debug('%d list empty', msecs);
   assert(L.isEmpty(list));
   list.close();
   delete lists[msecs];

lib/tls.js

@@ -52,13 +52,7 @@ exports.getCiphers = function() {
 };
 
 
-var debug;
+var debug = util.debuglog('tls');
-if (process.env.NODE_DEBUG && /tls/.test(process.env.NODE_DEBUG)) {
-  debug = function(a) { console.error('TLS:', a); };
-} else {
-  debug = function() { };
-}
-
 
 var Connection = null;
 try {
@@ -328,10 +322,10 @@ CryptoStream.prototype._write = function write(data, encoding, cb) {
     // Write current buffer now
     var written;
     if (this === this.pair.cleartext) {
-      debug('cleartext.write called with ' + data.length + ' bytes');
+      debug('cleartext.write called with %d bytes', data.length);
       written = this.pair.ssl.clearIn(data, 0, data.length);
     } else {
-      debug('encrypted.write called with ' + data.length + ' bytes');
+      debug('encrypted.write called with %d bytes', data.length);
       written = this.pair.ssl.encIn(data, 0, data.length);
     }
 
@@ -354,9 +348,9 @@ CryptoStream.prototype._write = function write(data, encoding, cb) {
     // Whole buffer was written
     if (written === data.length) {
       if (this === this.pair.cleartext) {
-        debug('cleartext.write succeed with ' + data.length + ' bytes');
+        debug('cleartext.write succeed with %d bytes', data.length);
       } else {
-        debug('encrypted.write succeed with ' + data.length + ' bytes');
+        debug('encrypted.write succeed with %d bytes', data.length);
       }
 
       return cb(null);
@@ -375,9 +369,9 @@ CryptoStream.prototype._write = function write(data, encoding, cb) {
   this._pendingCallback = cb;
 
   if (this === this.pair.cleartext) {
-    debug('cleartext.write queued with ' + data.length + ' bytes');
+    debug('cleartext.write queued with %d bytes', data.length);
   } else {
-    debug('encrypted.write queued with ' + data.length + ' bytes');
+    debug('encrypted.write queued with %d bytes', data.length);
   }
 };
 
@@ -404,10 +398,10 @@ CryptoStream.prototype._read = function read(size) {
 
   var out;
   if (this === this.pair.cleartext) {
-    debug('cleartext.read called with ' + size + ' bytes');
+    debug('cleartext.read called with %d bytes', size);
     out = this.pair.ssl.clearOut;
   } else {
-    debug('encrypted.read called with ' + size + ' bytes');
+    debug('encrypted.read called with %d bytes', size);
     out = this.pair.ssl.encOut;
   }
 
@@ -437,9 +431,9 @@ CryptoStream.prototype._read = function read(size) {
   assert(bytesRead >= 0);
 
   if (this === this.pair.cleartext) {
-    debug('cleartext.read succeed with ' + bytesRead + ' bytes');
+    debug('cleartext.read succeed with %d bytes', bytesRead);
   } else {
-    debug('encrypted.read succeed with ' + bytesRead + ' bytes');
+    debug('encrypted.read succeed with %d bytes', bytesRead);
   }
 
   // Try writing pending data

lib/util.js

@@ -81,29 +81,22 @@ exports.deprecate = function(fn, msg) {
 };
 
 
-exports.print = function() {
+var debugs = {};
-  for (var i = 0, len = arguments.length; i < len; ++i) {
+var debugEnviron = process.env.NODE_DEBUG || '';
-    process.stdout.write(String(arguments[i]));
+exports.debuglog = function(set) {
+  set = set.toUpperCase();
+  if (!debugs[set]) {
+    if (new RegExp('\\b' + set + '\\b', 'i').test(debugEnviron)) {
+      var pid = process.pid;
+      debugs[set] = function() {
+        var msg = exports.format.apply(exports, arguments);
+        console.error('%s %d: %s', set, pid, msg);
+      };
+    } else {
+      debugs[set] = function() {};
     }
-};
-
-
-exports.puts = function() {
-  for (var i = 0, len = arguments.length; i < len; ++i) {
-    process.stdout.write(arguments[i] + '\n');
-  }
-};
-
-
-exports.debug = function(x) {
-  process.stderr.write('DEBUG: ' + x + '\n');
-};
-
-
-var error = exports.error = function(x) {
-  for (var i = 0, len = arguments.length; i < len; ++i) {
-    process.stderr.write(arguments[i] + '\n');
   }
+  return debugs[set];
 };
 
 
@@ -466,13 +459,6 @@ function objectToString(o) {
 }
 
 
-exports.p = exports.deprecate(function() {
-  for (var i = 0, len = arguments.length; i < len; ++i) {
-    error(exports.inspect(arguments[i]));
-  }
-}, 'util.p: Use console.error() instead.');
-
-
 function pad(n) {
   return n < 10 ? '0' + n.toString(10) : n.toString(10);
 }
@@ -497,51 +483,6 @@ exports.log = function() {
 };
 
 
-exports.exec = exports.deprecate(function() {
-  return require('child_process').exec.apply(this, arguments);
-}, 'util.exec is now called `child_process.exec`.');
-
-
-function pump(readStream, writeStream, callback) {
-  var callbackCalled = false;
-
-  function call(a, b, c) {
-    if (callback && !callbackCalled) {
-      callback(a, b, c);
-      callbackCalled = true;
-    }
-  }
-
-  readStream.addListener('data', function(chunk) {
-    if (writeStream.write(chunk) === false) readStream.pause();
-  });
-
-  writeStream.addListener('drain', function() {
-    readStream.resume();
-  });
-
-  readStream.addListener('end', function() {
-    writeStream.end();
-  });
-
-  readStream.addListener('close', function() {
-    call();
-  });
-
-  readStream.addListener('error', function(err) {
-    writeStream.end();
-    call(err);
-  });
-
-  writeStream.addListener('error', function(err) {
-    readStream.destroy();
-    call(err);
-  });
-}
-exports.pump = exports.deprecate(pump,
-    'util.pump() is deprecated. Use readableStream.pipe() instead.');
-
-
 /**
  * Inherit the prototype methods from one constructor into another.
  *
@@ -582,3 +523,81 @@ exports._extend = function(origin, add) {
 function hasOwnProperty(obj, prop) {
   return Object.prototype.hasOwnProperty.call(obj, prop);
 }
+
+
+// Deprecated old stuff.
+
+exports.p = exports.deprecate(function() {
+  for (var i = 0, len = arguments.length; i < len; ++i) {
+    console.error(exports.inspect(arguments[i]));
+  }
+}, 'util.p: Use console.error() instead');
+
+
+exports.exec = exports.deprecate(function() {
+  return require('child_process').exec.apply(this, arguments);
+}, 'util.exec is now called `child_process.exec`.');
+
+
+exports.print = exports.deprecate(function() {
+  for (var i = 0, len = arguments.length; i < len; ++i) {
+    process.stdout.write(String(arguments[i]));
+  }
+}, 'util.print: Use console.log instead');
+
+
+exports.puts = exports.deprecate(function() {
+  for (var i = 0, len = arguments.length; i < len; ++i) {
+    process.stdout.write(arguments[i] + '\n');
+  }
+}, 'util.puts: Use console.log instead');
+
+
+exports.debug = exports.deprecate(function(x) {
+  process.stderr.write('DEBUG: ' + x + '\n');
+}, 'util.debug: Use console.error instead');
+
+
+exports.error = exports.deprecate(function(x) {
+  for (var i = 0, len = arguments.length; i < len; ++i) {
+    process.stderr.write(arguments[i] + '\n');
+  }
+}, 'util.error: Use console.error instead');
+
+
+exports.pump = exports.deprecate(function(readStream, writeStream, callback) {
+  var callbackCalled = false;
+
+  function call(a, b, c) {
+    if (callback && !callbackCalled) {
+      callback(a, b, c);
+      callbackCalled = true;
+    }
+  }
+
+  readStream.addListener('data', function(chunk) {
+    if (writeStream.write(chunk) === false) readStream.pause();
+  });
+
+  writeStream.addListener('drain', function() {
+    readStream.resume();
+  });
+
+  readStream.addListener('end', function() {
+    writeStream.end();
+  });
+
+  readStream.addListener('close', function() {
+    call();
+  });
+
+  readStream.addListener('error', function(err) {
+    writeStream.end();
+    call(err);
+  });
+
+  writeStream.addListener('error', function(err) {
+    readStream.destroy();
+    call(err);
+  });
+}, 'util.pump(): Use readableStream.pipe() instead');

test/message/stack_overflow.js

@@ -27,7 +27,7 @@ var assert = require('assert');
 
 Error.stackTraceLimit = 0;
 
-common.error('before');
+console.error('before');
 
 // stack overflow
 function stackOverflow() {
@@ -35,4 +35,4 @@ function stackOverflow() {
 }
 stackOverflow();
 
-common.error('after');
+console.error('after');

test/message/throw_custom_error.js

@@ -25,9 +25,9 @@
 var common = require('../common');
 var assert = require('assert');
 
-common.error('before');
+console.error('before');
 
 // custom error throwing
 throw ({ name: 'MyCustomError', message: 'This is a custom message' });
 
-common.error('after');
+console.error('after');

test/message/throw_in_line_with_tabs.js

@@ -25,11 +25,11 @@
 var common = require('../common');
 var assert = require('assert');
 
-common.error('before');
+console.error('before');
 
 (function () {
 	// these lines should contain tab!
 	throw ({ foo: 'bar' });
 })();
 
-common.error('after');
+console.error('after');

test/message/throw_non_error.js

@@ -25,9 +25,9 @@
 var common = require('../common');
 var assert = require('assert');
 
-common.error('before');
+console.error('before');
 
 // custom error throwing
 throw ({ foo: 'bar' });
 
-common.error('after');
+console.error('after');

test/message/undefined_reference_in_new_context.js

@@ -25,7 +25,7 @@
 var common = require('../common');
 var assert = require('assert');
 
-common.error('before');
+console.error('before');
 
 var Script = process.binding('evals').NodeScript;
 
@@ -33,4 +33,4 @@ var Script = process.binding('evals').NodeScript;
 var script = new Script('foo.bar = 5;');
 script.runInNewContext();
 
-common.error('after');
+console.error('after');

test/simple/test-deprecation-flags.js

@@ -33,7 +33,7 @@ execFile(node, normal, function(er, stdout, stderr) {
   console.error('normal: show deprecation warning');
   assert.equal(er, null);
   assert.equal(stdout, '');
-  assert.equal(stderr, 'util.p: Use console.error() instead.\n\'This is deprecated\'\n');
+  assert.equal(stderr, 'util.p: Use console.error() instead\n\'This is deprecated\'\n');
   console.log('normal ok');
 });
 

test/simple/test-http-proxy.js

@@ -37,20 +37,20 @@ var headers = {'content-type': 'text/plain',
                 'hello': 'world' };
 
 var backend = http.createServer(function(req, res) {
-  common.debug('backend request');
+  console.error('backend request');
   res.writeHead(200, headers);
   res.write('hello world\n');
   res.end();
 });
 
 var proxy = http.createServer(function(req, res) {
-  common.debug('proxy req headers: ' + JSON.stringify(req.headers));
+  console.error('proxy req headers: ' + JSON.stringify(req.headers));
   var proxy_req = http.get({
     port: BACKEND_PORT,
     path: url.parse(req.url).pathname
   }, function(proxy_res) {
 
-    common.debug('proxy res headers: ' + JSON.stringify(proxy_res.headers));
+    console.error('proxy res headers: ' + JSON.stringify(proxy_res.headers));
 
     assert.equal('world', proxy_res.headers['hello']);
     assert.equal('text/plain', proxy_res.headers['content-type']);
@@ -64,7 +64,7 @@ var proxy = http.createServer(function(req, res) {
 
     proxy_res.on('end', function() {
       res.end();
-      common.debug('proxy res');
+      console.error('proxy res');
     });
   });
 });
@@ -80,7 +80,7 @@ function startReq() {
     port: PROXY_PORT,
     path: '/test'
   }, function(res) {
-    common.debug('got res');
+    console.error('got res');
     assert.equal(200, res.statusCode);
 
     assert.equal('world', res.headers['hello']);
@@ -92,16 +92,16 @@ function startReq() {
     res.on('end', function() {
       proxy.close();
       backend.close();
-      common.debug('closed both');
+      console.error('closed both');
     });
   });
-  common.debug('client req');
+  console.error('client req');
 }
 
-common.debug('listen proxy');
+console.error('listen proxy');
 proxy.listen(PROXY_PORT, startReq);
 
-common.debug('listen backend');
+console.error('listen backend');
 backend.listen(BACKEND_PORT, startReq);
 
 process.on('exit', function() {

test/simple/test-util-debug.js

@@ -0,0 +1,87 @@
+// Copyright Joyent, Inc. and other Node contributors.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a
+// copy of this software and associated documentation files (the
+// "Software"), to deal in the Software without restriction, including
+// without limitation the rights to use, copy, modify, merge, publish,
+// distribute, sublicense, and/or sell copies of the Software, and to permit
+// persons to whom the Software is furnished to do so, subject to the
+// following conditions:
+//
+// The above copyright notice and this permission notice shall be included
+// in all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS
+// OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+// MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN
+// NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM,
+// DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR
+// OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE
+// USE OR OTHER DEALINGS IN THE SOFTWARE.
+
+var common = require('../common');
+var assert = require('assert');
+
+if (process.argv[2] === 'child')
+  child();
+else
+  parent();
+
+function parent() {
+  test('foo,tud,bar', true);
+  test('foo,tud', true);
+  test('tud,bar', true);
+  test('tud', true);
+  test('foo,bar', false);
+  test('', false);
+}
+
+function test(environ, shouldWrite) {
+  var expectErr = '';
+  if (shouldWrite) {
+    expectErr = 'TUD %PID%: this { is: \'a\' } /debugging/\n' +
+                'TUD %PID%: number=1234 string=asdf obj={"foo":"bar"}\n';
+  }
+  var expectOut = 'ok\n';
+  var didTest = false;
+
+  var spawn = require('child_process').spawn;
+  var child = spawn(process.execPath, [__filename, 'child'], {
+    env: { NODE_DEBUG: environ }
+  });
+
+  expectErr = expectErr.split('%PID%').join(child.pid);
+
+  var err = '';
+  child.stderr.setEncoding('utf8');
+  child.stderr.on('data', function(c) {
+    err += c;
+  });
+
+  var out = '';
+  child.stdout.setEncoding('utf8');
+  child.stdout.on('data', function(c) {
+    out += c;
+  });
+
+  child.on('close', function(c) {
+    assert(!c);
+    assert.equal(err, expectErr);
+    assert.equal(out, expectOut);
+    didTest = true;
+    console.log('ok %j %j', environ, shouldWrite);
+  });
+
+  process.on('exit', function() {
+    assert(didTest);
+  });
+}
+
+
+function child() {
+  var util = require('util');
+  var debug = util.debug('tud');
+  debug('this', { is: 'a' }, /debugging/);
+  debug('number=%d string=%s obj=%j', 1234, 'asdf', { foo: 'bar' });
+  console.log('ok');
+}