From af5a3d487332278a0b044be8197e000a38ee6836 Mon Sep 17 00:00:00 2001 From: Bryan Cantrill Date: Wed, 31 Oct 2012 00:28:24 -0700 Subject: [PATCH] issue #48: add USDT DTrace support via node-dtrace-provider --- README.md | 94 ++++++++++++++++++++++++++++++++++++++++++++++++++- lib/bunyan.js | 88 ++++++++++++++++++++++++++++++++++------------- package.json | 3 ++ 3 files changed, 161 insertions(+), 24 deletions(-) diff --git a/README.md b/README.md index 054526c1..4627aa4c 100644 --- a/README.md +++ b/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. diff --git a/lib/bunyan.js b/lib/bunyan.js index d3b2b46b..1fdc1263 100644 --- a/lib/bunyan.js +++ b/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.(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.(msg, ...)` + fields = null; + msgArgs = Array.prototype.slice.call(args); + } else if (Buffer.isBuffer(args[0])) { // `log.(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.(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.()` return (this._level <= minLevel); } else if (this._level > minLevel) { - return; - } else if (arguments[0] instanceof Error) { - // `log.(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.(msg, ...)` - fields = null; - msgArgs = Array.prototype.slice.call(arguments); - } else if (Buffer.isBuffer(arguments[0])) { // `log.(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.(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); } } diff --git a/package.json b/package.json index f872489e..a99e3976 100644 --- a/package.json +++ b/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",