issue #48: changelog, add Bryan to AUTHORS, basic dtrace test suite

The test suite for this is a bit finnicky because root rights are
required to run dtrace. By default we run the dtrace.test.js file
with 'sudo'. Use this to skip the dtrace tests:
    SKIP_DTRACE=1 make test

Note taht 'make test09' is busted because dtrace-provider seems
busted with node 0.9.1 at least.

AUTHORS

@@ -4,3 +4,4 @@ Dave Pacheco <dap@joyent.com> (https://github.com/davepacheco)
 Michael Hart (https://github.com/mhart)
 Isaac Schlueter (https://github.com/isaacs)
 Rob Gulewich (https://github.com/rgulewich)
+Bryan Cantrill (https://github.com/bcantrill)

CHANGES.md

@@ -1,8 +1,18 @@
 # bunyan Changelog
 
-## bunyan 0.14.7 (not yet released)
+## bunyan 0.15.0 (not yet released)
 
-- Add a man page. See <http://trentm.com/node-bunyan/bunyan.1.html>.
+- issue #48: Dtrace support! The elevator pitch is you can watch all logging
+  from all Bunyan-using process with this:
+
+        dtrace -x strsize=4k -qn 'bunyan*:::log-*{printf("%d: %s: %s", pid, probefunc, copyinstr(arg0))}'
+
+  Or get the bunyan CLI to render those:
+
+        dtrace -x strsize=4k -qn 'bunyan*:::log-*{printf("%s", copyinstr(arg0))}' | bunyan
+
+  See <https://github.com/trentm/node-bunyan#dtrace-support> for details. By
+  Bryan Cantrill.
 
 
 ## bunyan 0.14.6
@@ -22,8 +32,8 @@
         # After
         var childLog = log.child({..., level: 'debug'});
 
-- Improve the crash message to make it easier to provide relevant details in a
+- Improve the Bunyan CLI crash message to make it easier to provide relevant
-  bug report.
+  details in a bug report.
 
 
 ## bunyan 0.14.5

Makefile

@@ -7,12 +7,15 @@ TAP := ./node_modules/.bin/tap
 #---- Files
 
 JSSTYLE_FILES := $(shell find lib test tools examples -name "*.js") bin/bunyan
+# All test files *except* dtrace.test.js.
+TEST_FILES := $(shell ls -1 test/*.test.js | grep -v dtrace | xargs)
 
 
 
 #---- Targets
 
 all:
+	npm install
 
 # Ensure all version-carrying files have the same version.
 .PHONY: versioncheck
@@ -51,24 +54,37 @@ publish:
 
 .PHONY: test
 test: $(TAP)
-	TAP=1 $(TAP) test/*.test.js
+	TAP=1 $(TAP) $(TEST_FILES)
+	[[ -n "$(SKIP_DTRACE)" ]] || sudo TAP=1 $(TAP) test/dtrace.test.js
 
-# Test will all node supported versions (presumes install locations I use on my machine).
+# Test will all node supported versions (presumes install locations I use on
+# my machine).
+# Note: 'test08' is last so (if all is well) I end up with a binary
+# dtrace-provider build for node 0.8 (my current version).
 .PHONY: testall
-testall: test08 test06 test09
+testall: test06 test09 test08
 
 .PHONY: test09
 test09:
 	@echo "# Test node 0.9.x (with node `$(HOME)/opt/node-0.9/bin/node --version`)"
-	PATH="$(HOME)/opt/node-0.9/bin:$(PATH)" TAP=1 $(TAP) test/*.test.js
+	[[ -n "$(SKIP_DTRACE)" ]] \
+		|| PATH="$(HOME)/opt/node-0.9/bin:$(PATH)" npm rebuild dtrace-provider \
+		&& sudo PATH="$(HOME)/opt/node-0.9/bin:$(PATH)" TAP=1 $(TAP) test/dtrace.test.js
+	PATH="$(HOME)/opt/node-0.9/bin:$(PATH)" TAP=1 $(TAP) $(TEST_FILES)
 .PHONY: test08
 test08:
 	@echo "# Test node 0.8.x (with node `$(HOME)/opt/node-0.8/bin/node --version`)"
-	PATH="$(HOME)/opt/node-0.8/bin:$(PATH)" TAP=1 $(TAP) test/*.test.js
+	[[ -n "$(SKIP_DTRACE)" ]] \
+		|| PATH="$(HOME)/opt/node-0.8/bin:$(PATH)" npm rebuild dtrace-provider \
+		&& sudo PATH="$(HOME)/opt/node-0.8/bin:$(PATH)" TAP=1 $(TAP) test/dtrace.test.js
+	PATH="$(HOME)/opt/node-0.8/bin:$(PATH)" TAP=1 $(TAP) $(TEST_FILES)
 .PHONY: test06
 test06:
 	@echo "# Test node 0.6.x (with node `$(HOME)/opt/node-0.6/bin/node --version`)"
-	PATH="$(HOME)/opt/node-0.6/bin:$(PATH)" TAP=1 $(TAP) test/*.test.js
+	[[ -n "$(SKIP_DTRACE)" ]] \
+		|| PATH="$(HOME)/opt/node-0.6/bin:$(PATH)" npm rebuild dtrace-provider \
+		&& sudo PATH="$(HOME)/opt/node-0.6/bin:$(PATH)" TAP=1 $(TAP) test/dtrace.test.js
+	PATH="$(HOME)/opt/node-0.6/bin:$(PATH)" TAP=1 $(TAP) $(TEST_FILES)
 
 
 

README.md

@@ -530,30 +530,33 @@ that makes available the following probes:
     log-error
     log-fatal
 
-Each of these probes has a single arugment: the string that would be 
+Each of these probes has a single argument: 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:
+Trace all log messages coming from any Bunyan module on the system.
+(The `-x strsize=4k` is to raise dtrace's default 256 byte buffer size
+because log messages are longer than typical dtrace probes.)
 
-    dtrace -qn 'bunyan*:::log-*{printf("%d: %s: %s", pid, probefunc, copyinstr(arg0))}'
+    dtrace -x strsize=4k -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)}'
+    dtrace -x strsize=4k -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()}'
+    dtrace -x strsize=4k -n 'bunyan1234:::log-debug{@[copyinstr(arg0)] = count()}'
 
-On systems that support the `jstack` action via a node.js helper, get
+On systems that support the
-a stack backtrace for any debug message that includes the string 
+[`jstack`](http://dtrace.org/blogs/dap/2012/04/25/profiling-node-js/) action
-"danger!":
+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()}'
+    dtrace -x strsize=4k -qn 'log-debug/strstr(copyinstr(arg0), "danger!") != NULL/{printf("\n%s", copyinstr(arg0)); jstack()}'
 
 Output of the above might be:
 

bin/bunyan

@@ -5,7 +5,7 @@
 // See <https://github.com/trentm/node-bunyan>.
 //
 
-var VERSION = "0.14.7";
+var VERSION = "0.15.0";
 
 var util = require('util');
 var pathlib = require('path');

lib/bunyan.js

@@ -4,7 +4,7 @@
  * The bunyan logging library for node.js.
  */
 
-var VERSION = '0.14.7';
+var VERSION = '0.15.0';
 
 // Bunyan log format version. This becomes the 'v' field on all log records.
 // `0` is until I release a version '1.0.0' of node-bunyan. Thereafter,

package.json

@@ -1,6 +1,6 @@
 {
   "name": "bunyan",
-  "version": "0.14.7",
+  "version": "0.15.0",
   "description": "a JSON Logger library for node.js services",
   "author": "Trent Mick <trentm@gmail.com> (http://trentm.com)",
   "main": "./lib/bunyan.js",

test/dtrace.test.js

@@ -0,0 +1,79 @@
+/*
+ * Copyright (c) 2012 Trent Mick. All rights reserved.
+ *
+ * If available, test dtrace support.
+ */
+
+var spawn = require('child_process').spawn;
+var format = require('util').format;
+
+var test = require('tap').test;
+var bunyan = require('../lib/bunyan');
+
+
+// Determine if we can run the dtrace tests.
+var dtracePlats = ['sunos', 'darwin', 'freebsd'];
+var runDtraceTests = true;
+try {
+  require('dtrace-provider')
+} catch (e) {
+  console.log('# skip dtrace tests: no dtrace-provider module');
+  runDtraceTests = false;
+}
+if (!runDtraceTests) {
+  /* pass through */
+} else if (dtracePlats.indexOf(process.platform) === -1) {
+  console.log('# skip dtrace tests: not on a platform with dtrace');
+  runDtraceTests = false;
+} else if (process.env.SKIP_DTRACE) {
+  console.log('# skip dtrace tests: SKIP_DTRACE envvar set');
+  runDtraceTests = false;
+} else if (process.getgid() !== 0) {
+  console.log('# skip dtrace tests: gid is not 0, run with `sudo`');
+  runDtraceTests = false;
+}
+if (runDtraceTests) {
+
+
+test('basic', function (t) {
+  var log = bunyan.createLogger({name: 'basic'}); // at default 'info' level
+
+  // Should be '%%s' in that `format` frankly, but node *0.6* doesn't see
+  // it that way. Node *0.8* has fixed '%%' handling.
+  var dtrace = spawn('dtrace', ['-x', 'strsize=4k', '-qn',
+    format('bunyan%d:::log-*{printf("%s", copyinstr(arg0))}', process.pid)]);
+  var traces = [];
+  dtrace.stdout.on('data', function (data) {
+    traces.push(data.toString());
+  });
+  dtrace.stderr.on('data', function (data) {
+    console.error(data.toString());
+  });
+  dtrace.on('exit', function (code) {
+    if (code) {
+      console.log("dtrace exited non-zero:", code);
+    }
+  });
+
+  setTimeout(function () {
+    log.debug({basic: true}, 'hi at debug');
+    log.trace({basic: true}, 'hi at trace');
+
+    setTimeout(function () {
+      dtrace.kill('SIGTERM');
+
+      traces = traces.join('').split('\n')
+        .filter(function (t) { return t.trim().length })
+        .map(function (t) { return JSON.parse(t) });
+      t.equal(traces.length, 2);
+      t.equal(traces[0].pid, process.pid);
+      t.equal(traces[0].level, bunyan.DEBUG);
+      t.equal(traces[1].basic, true);
+      t.end();
+    }, 1000);
+  }, 1000); // Give dtrace some time to startup. How much?
+});
+
+
+
+} /* end of `if (runDtraceTests)` */