From 8732764c672bef45f27fa47c831e7c65844fbd63 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 31 Oct 2012 23:52:53 -0700 Subject: [PATCH] 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 | 1 + CHANGES.md | 18 ++++++++--- Makefile | 28 ++++++++++++---- README.md | 21 ++++++------ bin/bunyan | 2 +- lib/bunyan.js | 2 +- package.json | 2 +- test/dtrace.test.js | 79 +++++++++++++++++++++++++++++++++++++++++++++ 8 files changed, 131 insertions(+), 22 deletions(-) create mode 100644 test/dtrace.test.js diff --git a/AUTHORS b/AUTHORS index ba2edfe..10f706e 100644 --- a/AUTHORS +++ b/AUTHORS @@ -4,3 +4,4 @@ Dave Pacheco (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) diff --git a/CHANGES.md b/CHANGES.md index e9b59a1..4f86ceb 100644 --- a/CHANGES.md +++ b/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 . +- 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 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 - bug report. +- Improve the Bunyan CLI crash message to make it easier to provide relevant + details in a bug report. ## bunyan 0.14.5 diff --git a/Makefile b/Makefile index 502455c..6a9c4c3 100644 --- a/Makefile +++ b/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) diff --git a/README.md b/README.md index 4627aa4..b6115fb 100644 --- a/README.md +++ b/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 -a stack backtrace for any debug message that includes the string -"danger!": +On systems that support the +[`jstack`](http://dtrace.org/blogs/dap/2012/04/25/profiling-node-js/) 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()}' + dtrace -x strsize=4k -qn 'log-debug/strstr(copyinstr(arg0), "danger!") != NULL/{printf("\n%s", copyinstr(arg0)); jstack()}' Output of the above might be: diff --git a/bin/bunyan b/bin/bunyan index 96e31e3..a7bfe6b 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -5,7 +5,7 @@ // See . // -var VERSION = "0.14.7"; +var VERSION = "0.15.0"; var util = require('util'); var pathlib = require('path'); diff --git a/lib/bunyan.js b/lib/bunyan.js index 4a0d6ec..ec549d7 100644 --- a/lib/bunyan.js +++ b/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, diff --git a/package.json b/package.json index d1d0980..a127273 100644 --- a/package.json +++ b/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 (http://trentm.com)", "main": "./lib/bunyan.js", diff --git a/test/dtrace.test.js b/test/dtrace.test.js new file mode 100644 index 0000000..193baf2 --- /dev/null +++ b/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)` */