issue #48: add USDT DTrace support via node-dtrace-provider

Author: bcantrill

README.md

@@ -517,6 +517,99 @@ This example emits:
         v: 0 } ]
 
 
+# DTrace support
+
+On systems that support DTrace (e.g., MacOS, FreeBSD, illumos derivatives
+like SmartOS and OmniOS), Bunyan will create a DTrace provider (`bunyan`)
+that makes available the following probes:
+
+    log-trace
+    log-debug
+    log-info
+    log-warn
+    log-error
+    log-fatal
+
+Each of these probes has a single arugment: the string that would be 
+written to the log.  Note that when a probe is enabled, it will
+fire whenever the corresponding function is called, even if the level of
+the log message is less than that of any stream.
+
+## DTrace examples
+
+Trace all log messages coming from any Bunyan module on the system:
+
+    dtrace -qn 'bunyan*:::log-*{printf("%d: %s: %s", pid, probefunc, copyinstr(arg0))}'
+
+Trace all log messages coming from the "wuzzle" component:
+
+    dtrace -qn 'bunyan*:::log-*/strstr(this->str = copyinstr(arg0), "\"component\":\"wuzzle\"") != NULL/{printf("%s", this->str)}'
+
+Aggregate debug messages from process 1234, by message:
+
+    dtrace -n 'bunyan1234:::log-debug{@[copyinstr(arg0)] = count()}'
+
+On systems that support the `jstack` action via a node.js helper, get
+a stack backtrace for any debug message that includes the string 
+"danger!":
+
+    dtrace -qn 'log-debug/strstr(copyinstr(arg0), "danger!") != NULL/{printf("\n%s", copyinstr(arg0)); jstack()}'
+
+Output of the above might be:
+
+    {"name":"foo","hostname":"763bf293-d65c-42d5-872b-4abe25d5c4c7.local","pid":12747,"level":20,"msg":"danger!","time":"2012-10-30T18:28:57.115Z","v":0}
+
+              node`0x87e2010
+              DTraceProviderBindings.node`usdt_fire_probe+0x32
+              DTraceProviderBindings.node`_ZN4node11DTraceProbe5_fireEN2v85LocalINS1_5ValueEEE+0x32d
+              DTraceProviderBindings.node`_ZN4node11DTraceProbe4FireERKN2v89ArgumentsE+0x77
+              << internal code >>
+              (anon) as (anon) at /root/node-bunyan/lib/bunyan.js position 40484
+              << adaptor >>
+              (anon) as doit at /root/my-prog.js position 360
+              (anon) as list.ontimeout at timers.js position 4960
+              << adaptor >>
+              << internal >>
+              << entry >>
+              node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
+              node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xcb
+              node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
+              node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11f
+              node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x66
+              node`_ZN4node9TimerWrap9OnTimeoutEP10uv_timer_si+0x63
+              node`uv__run_timers+0x66
+              node`uv__run+0x1b
+              node`uv_run+0x17
+              node`_ZN4node5StartEiPPc+0x1d0
+              node`main+0x1b
+              node`_start+0x83
+
+              node`0x87e2010
+              DTraceProviderBindings.node`usdt_fire_probe+0x32
+              DTraceProviderBindings.node`_ZN4node11DTraceProbe5_fireEN2v85LocalINS1_5ValueEEE+0x32d
+              DTraceProviderBindings.node`_ZN4node11DTraceProbe4FireERKN2v89ArgumentsE+0x77
+              << internal code >>
+              (anon) as (anon) at /root/node-bunyan/lib/bunyan.js position 40484
+              << adaptor >>
+              (anon) as doit at /root/my-prog.js position 360
+              (anon) as list.ontimeout at timers.js position 4960
+              << adaptor >>
+              << internal >>
+              << entry >>
+              node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
+              node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xcb
+              node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
+              node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11f
+              node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x66
+              node`_ZN4node9TimerWrap9OnTimeoutEP10uv_timer_si+0x63
+              node`uv__run_timers+0x66
+              node`uv__run+0x1b
+              node`uv_run+0x17
+              node`_ZN4node5StartEiPPc+0x1d0
+              node`main+0x1b
+              node`_start+0x83
+
+
 # Versioning
 
 The scheme I follow is most succintly described by the bootstrap guys
@@ -527,7 +620,6 @@ breaking backward compat and major reworks, new features without breaking
 change, and bug fixes, respectively.
 
 
-
 # License
 
 MIT.

lib/bunyan.js

@@ -25,6 +25,7 @@ var os = require('os');
 var fs = require('fs');
 var util = require('util');
 var assert = require('assert');
+var dtrace = require('dtrace-provider');
 var EventEmitter = require('events').EventEmitter;
 
 
@@ -156,6 +157,8 @@ var levelFromName = {
   'fatal': FATAL
 };
 
+var dtp = undefined;
+var probes = {};
 
 /**
  * Resolve a level number, name (upper or lowercase) to a level number value.
@@ -299,6 +302,22 @@ function Logger(options, _childOptions, _childSimple) {
     this.fields = {};
   }
 
+  if (!dtp) {
+    dtp = dtrace.createDTraceProvider('bunyan');
+
+    for (var level in levelFromName) {
+      var probe;
+
+      probes[levelFromName[level]] = probe = 
+        dtp.addProbe('log-' + level, 'char *');
+
+      // Explicitly add a reference to dtp to prevent it from being GC'd
+      probe.dtp = dtp;
+    }
+
+    dtp.enable();
+  }
+
   // Helpers
   function addStream(s) {
     s = objCopy(s);
@@ -641,8 +660,9 @@ Logger.prototype._mkRecord = function (fields, level, msgArgs) {
  * Emit a log record.
  *
  * @param rec {log record}
+ * @param noemit {Boolean} Optional. Set to true to only return the string.
  */
-Logger.prototype._emit = function (rec) {
+Logger.prototype._emit = function (rec, noemit) {
   var i;
 
   var obj = objCopy(rec[0]);
@@ -685,6 +705,9 @@ Logger.prototype._emit = function (rec) {
     str = JSON.stringify(obj, safeCycles()) + '\n';
   }
 
+  if (noemit)
+    return str;
+
   for (i = 0; i < this.streams.length; i++) {
     var s = this.streams[i];
     if (s.level <= level) {
@@ -693,6 +716,8 @@ Logger.prototype._emit = function (rec) {
       s.stream.write(s.raw ? obj : str);
     }
   };
+
+  return str;
 }
 
 
@@ -702,33 +727,50 @@ Logger.prototype._emit = function (rec) {
  */
 function mkLogEmitter(minLevel) {
   return function () {
+    var log = this;
+
+    var mkRecord = function (args) {
+      if (args[0] instanceof Error) {
+        // `log.<level>(err, ...)`
+        fields = {err: errSerializer(args[0])};
+        if (args.length === 1) {
+          msgArgs = [fields.err.message];
+        } else {
+          msgArgs = Array.prototype.slice.call(args, 1);
+        }
+      } else if (typeof (args[0]) === 'string') {  // `log.<level>(msg, ...)`
+        fields = null;
+        msgArgs = Array.prototype.slice.call(args);
+      } else if (Buffer.isBuffer(args[0])) {  // `log.<level>(buf, ...)`
+        // Almost certainly an error, show `inspect(buf)`. See bunyan issue #35.
+        fields = null;
+        msgArgs = Array.prototype.slice.call(args);
+        msgArgs[0] = util.inspect(msgArgs[0]);
+      } else {  // `log.<level>(fields, msg, ...)`
+        fields = args[0];
+        msgArgs = Array.prototype.slice.call(args, 1);
+      }
+      return log._mkRecord(fields, minLevel, msgArgs);
+    };
+
     var fields = null, msgArgs = null;
     if (arguments.length === 0) {   // `log.<level>()`
       return (this._level <= minLevel);
     } else if (this._level > minLevel) {
-      return;
-    } else if (arguments[0] instanceof Error) {
-      // `log.<level>(err, ...)`
-      fields = {err: errSerializer(arguments[0])};
-      if (arguments.length === 1) {
-        msgArgs = [fields.err.message];
-      } else {
-        msgArgs = Array.prototype.slice.call(arguments, 1);
-      }
-    } else if (typeof (arguments[0]) === 'string') {  // `log.<level>(msg, ...)`
-      fields = null;
-      msgArgs = Array.prototype.slice.call(arguments);
-    } else if (Buffer.isBuffer(arguments[0])) {  // `log.<level>(buf, ...)`
-      // Almost certainly an error, show `inspect(buf)`. See bunyan issue #35.
-      fields = null;
-      msgArgs = Array.prototype.slice.call(arguments);
-      msgArgs[0] = util.inspect(msgArgs[0]);
-    } else {  // `log.<level>(fields, msg, ...)`
-      fields = arguments[0];
-      msgArgs = Array.prototype.slice.call(arguments, 1);
+      /*
+       * Even if our level is such that we will not emit the record, we want
+       * to fire the DTrace probe associated with the level -- but we only
+       * assemble the string representation if the probe is in fact enabled.
+       */
+      msgArgs = arguments;
+
+      probes[minLevel].fire(function () {
+         return [ log._emit(mkRecord(msgArgs), true) ];
+      });
+    } else {
+      var str = this._emit(mkRecord(arguments));
+      probes[minLevel].fire(function () { return [ str ]; });
     }
-    var rec = this._mkRecord(fields, minLevel, msgArgs);
-    this._emit(rec);
   }
 }
 

package.json

@@ -15,6 +15,9 @@
   "engines": ["node >=0.6.0"],
   "keywords": ["log", "logging", "log4j", "json"],
 
+  "dependencies": {
+    "dtrace-provider": "0.2.2"
+  },
   "devDependencies": {
     "tap": "0.2.0",
     "ben": "0.0.0",