Skip to content

Commit

Permalink
issue trentm#48: add USDT DTrace support via node-dtrace-provider
Browse files Browse the repository at this point in the history
  • Loading branch information
@bcantrill
bcantrill committed Oct 31, 2012
1 parent 432eec6 commit af5a3d4
Show file tree
Hide file tree
Showing 3 changed files with 161 additions and 24 deletions.
94 changes: 93 additions & 1 deletion README.md
View file
Expand Up @@ -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
Expand All @@ -527,7 +620,6 @@ breaking backward compat and major reworks, new features without breaking
change, and bug fixes, respectively.



# License

MIT.
Expand Down
88 changes: 65 additions & 23 deletions lib/bunyan.js
View file
Expand Up @@ -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;


Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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]);
Expand Down Expand Up @@ -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) {
Expand All @@ -693,6 +716,8 @@ Logger.prototype._emit = function (rec) {
s.stream.write(s.raw ? obj : str);
}
};

return str;
}


Expand All @@ -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);
}
}

Expand Down
3 changes: 3 additions & 0 deletions package.json
View file
Expand Up @@ -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",
Expand Down

0 comments on commit af5a3d4

Please sign in to comment.