TheThing/node-bunyan-lite
1
0
Fork 0
Code Issues Pull requests Projects Releases 1 Wiki Activity

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

Browse source
This commit is contained in:
Bryan Cantrill 2012-10-31 00:28:24 -07:00
parent 432eec6f29
commit af5a3d4873
3 changed files with 161 additions and 24 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

94
README.md
View file

@ -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.

88
lib/bunyan.js
View file

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

3
package.json
View file

@ -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",