issue #56: bunyan -p NAME

This commit is contained in:
Trent Mick 2012-11-13 00:12:57 -08:00
parent 9d7bd77c76
commit f08c2e6f2c
7 changed files with 193 additions and 73 deletions

View file

@ -2,7 +2,15 @@
## bunyan 0.16.6 (not yet released) ## bunyan 0.16.6 (not yet released)
(nothing yet) - [issue #56] Support `bunyan -p NAME` to dtrace all PIDs matching 'NAME' in
their command and args (using `ps -A -o pid,command | grep NAME` or, on SunOS
`pgrep -lf NAME`). E.g.:
bunyan -p myappname
This is useful for usage of node's [cluster
module](http://nodejs.org/docs/latest/api/all.html#all_cluster) where you'll
have multiple worker processes.
## bunyan 0.16.5 ## bunyan 0.16.5

View file

@ -551,6 +551,15 @@ Aggregate debug messages from process 1234, by message:
dtrace -x strsize=4k -n 'bunyan1234:::log-debug{@[copyinstr(arg0)] = count()}' dtrace -x strsize=4k -n 'bunyan1234:::log-debug{@[copyinstr(arg0)] = count()}'
Have the bunyan CLI pretty-print the traced logs:
dtrace -x strsize=4k -qn 'bunyan1234:::log-*{printf("%s", copyinstr(arg0))}' | bunyan
A convenience handle has been made for this:
bunyan -p 1234
On systems that support the On systems that support the
[`jstack`](http://dtrace.org/blogs/dap/2012/04/25/profiling-node-js/) action [`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 via a node.js helper, get a stack backtrace for any debug message that

View file

@ -1,4 +1,3 @@
- -p PID: proper handling of '-l level'
- "all" or "off" levels? log4j? logging.py? - "all" or "off" levels? log4j? logging.py?
logging.py has NOTSET === 0. I think that is only needed/used for logging.py has NOTSET === 0. I think that is only needed/used for
multi-level hierarchical effective level. multi-level hierarchical effective level.
@ -42,6 +41,7 @@
- Think about a bunyan dashboard that supports organizing and viewing logs - Think about a bunyan dashboard that supports organizing and viewing logs
from multiple hosts and services. from multiple hosts and services.
- Syslog support. - Syslog support.
- doc the restify RequestCaptureStream usage of RingBuffer. Great example.
- A vim plugin (a la http://vim.cybermirror.org/runtime/autoload/zip.vim ?) to - A vim plugin (a la http://vim.cybermirror.org/runtime/autoload/zip.vim ?) to
allow browsing (read-only) a bunyan log in rendered form. allow browsing (read-only) a bunyan log in rendered form.
- Some speed comparisons with others to get a feel for Bunyan's speed. - Some speed comparisons with others to get a feel for Bunyan's speed.

View file

@ -13,7 +13,10 @@ var vm = require('vm');
var http = require('http'); var http = require('http');
var fs = require('fs'); var fs = require('fs');
var warn = console.warn; var warn = console.warn;
var spawn = require('child_process').spawn; var child_process = require('child_process'),
spawn = child_process.spawn,
exec = child_process.exec,
execFile = child_process.execFile;
var nodeSpawnSupportsStdio = (Number(process.version.split('.')[1]) >= 8); var nodeSpawnSupportsStdio = (Number(process.version.split('.')[1]) >= 8);
@ -151,7 +154,10 @@ function printHelp() {
console.log(""); console.log("");
console.log("Dtrace options (only on dtrace-supporting platforms):"); console.log("Dtrace options (only on dtrace-supporting platforms):");
console.log(" -p PID Process bunyan:log-* probes from the process"); console.log(" -p PID Process bunyan:log-* probes from the process");
console.log(" with the given PID."); console.log(" with the given PID. Can be used multiple times,");
console.log(" or specify all processes with '*', or a set of");
console.log(" processes whose command & args match a pattern");
console.log(" with '-p NAME'.");
console.log(""); console.log("");
console.log("Filtering options:"); console.log("Filtering options:");
console.log(" -l, --level LEVEL"); console.log(" -l, --level LEVEL");
@ -324,7 +330,8 @@ function parseArgv(argv) {
level: null, level: null,
conditions: null, conditions: null,
strict: false, strict: false,
pid: null pids: null,
pidsType: null
}; };
// Turn '-iH' into '-i -H', except for argument-accepting options. // Turn '-iH' into '-i -H', except for argument-accepting options.
@ -400,16 +407,29 @@ function parseArgv(argv) {
parsed.outputMode = OM_JSON; parsed.outputMode = OM_JSON;
break; break;
case "-p": case "-p":
if (!parsed.pids) {
parsed.pids = [];
}
var pidArg = args.shift(); var pidArg = args.shift();
var pid = +(pidArg); var pid = +(pidArg);
if (isNaN(pid)) { if (!isNaN(pid) || pidArg === '*') {
if (pidArg === '*') { if (parsed.pidsType && parsed.pidsType !== 'num') {
pid = '*' throw new Error(format(
} else { 'cannot mix PID name and number arguments: "%s"', pidArg));
throw new Error(format('invalid pid: "%s"', pidArg));
} }
parsed.pidsType = 'num';
if (!parsed.pids) {
parsed.pids = [];
}
parsed.pids.push(isNaN(pid) ? pidArg : pid);
} else {
if (parsed.pidsType && parsed.pidsType !== 'name') {
throw new Error(format(
'cannot mix PID name and number arguments: "%s"', pidArg));
}
parsed.pidsType = 'name';
parsed.pids = pidArg;
} }
parsed.pid = pid;
break; break;
case "-l": case "-l":
case "--level": case "--level":
@ -913,62 +933,127 @@ function processStdin(opts, stylize, callback) {
* @param stylize {Function} Output stylize function to use. * @param stylize {Function} Output stylize function to use.
* @param callback {Function} `function (code)` * @param callback {Function} `function (code)`
*/ */
function processPid(opts, stylize, callback) { function processPids(opts, stylize, callback) {
var leftover = ""; // Left-over partial line from last chunk. var leftover = ""; // Left-over partial line from last chunk.
var argv = ['dtrace', '-Z', '-x', 'strsize=4k', '-qn',
format('bunyan%s:::log-*{printf("%s", copyinstr(arg0))}', opts.pid)];
var dtrace = spawn(argv[0], argv.slice(1),
// Share the stderr handle to have error output come
// straight through. Only supported in v0.8+.
{stdio: ['pipe', 'pipe', process.stderr]});
child = dtrace; // intentionally global
function finish(code) { /**
if (leftover) { * Get the PIDs to dtrace.
handleLogLine(null, leftover, opts, stylize); *
leftover = ''; * @param cb {Function} `function (errCode, pids)`
*/
function getPids(cb) {
if (opts.pidsType === 'num') {
return cb(null, opts.pids);
}
if (process.platform === 'sunos') {
execFile('/bin/pgrep', ['-lf', opts.pids],
function (pidsErr, stdout, stderr) {
if (pidsErr) {
warn('bunyan: error getting PIDs for "%s": %s\n%s\n%s',
opts.pids, pidsErr.message, stdout, stderr);
return cb(1);
}
var pids = stdout.trim().split('\n')
.map(function (line) { return line.trim().split(/\s+/)[0] })
.filter(function (pid) { return Number(pid) !== process.pid });
if (pids.length === 0) {
warn('bunyan: error: no matching PIDs found for "%s"', opts.pids);
return cb(2);
}
cb(null, pids);
}
);
} else {
var regex = opts.pids;
if (regex && /[a-zA-Z0-9_]/.test(regex[0])) {
// 'foo' -> '[f]oo' trick to exclude the 'grep' PID from its own
// search.
regex = '[' + regex[0] + ']' + regex.slice(1);
}
exec(format('ps -A -o pid,command | grep \'%s\'', regex),
function (pidsErr, stdout, stderr) {
if (pidsErr) {
warn('bunyan: error getting PIDs for "%s": %s\n%s\n%s',
opts.pids, pidsErr.message, stdout, stderr);
return cb(1);
}
var pids = stdout.trim().split('\n')
.map(function (line) { return line.trim().split(/\s+/)[0] })
.filter(function (pid) { return Number(pid) !== process.pid });
if (pids.length === 0) {
warn('bunyan: error: no matching PIDs found for "%s"', opts.pids);
return cb(2);
}
cb(null, pids);
}
);
} }
callback(returnCode);
} }
dtrace.stdout.setEncoding('utf8'); getPids(function (errCode, pids) {
dtrace.stdout.on('data', function (chunk) { if (errCode) {
var lines = chunk.split(/\r\n|\n/); return callback(errCode);
var length = lines.length;
if (length === 1) {
leftover += lines[0];
return;
} }
if (length > 1) {
handleLogLine(null, leftover + lines[0], opts, stylize); var probes = pids.map(function (pid) {
return format('bunyan%s:::log-*', pid);
}).join(',');
var argv = ['dtrace', '-Z', '-x', 'strsize=4k', '-qn',
format('%s{printf("%s", copyinstr(arg0))}', probes)];
//console.log('dtrace argv: %s', argv);
var dtrace = spawn(argv[0], argv.slice(1),
// Share the stderr handle to have error output come
// straight through. Only supported in v0.8+.
{stdio: ['pipe', 'pipe', process.stderr]});
child = dtrace; // intentionally global
function finish(code) {
if (leftover) {
handleLogLine(null, leftover, opts, stylize);
leftover = '';
}
callback(returnCode);
} }
leftover = lines.pop();
length -= 1; dtrace.stdout.setEncoding('utf8');
for (var i=1; i < length; i++) { dtrace.stdout.on('data', function (chunk) {
handleLogLine(null, lines[i], opts, stylize); var lines = chunk.split(/\r\n|\n/);
var length = lines.length;
if (length === 1) {
leftover += lines[0];
return;
}
if (length > 1) {
handleLogLine(null, leftover + lines[0], opts, stylize);
}
leftover = lines.pop();
length -= 1;
for (var i=1; i < length; i++) {
handleLogLine(null, lines[i], opts, stylize);
}
});
if (nodeSpawnSupportsStdio) {
dtrace.on('exit', finish);
} else {
// Fallback (for < v0.8) to pipe the dtrace process' stderr to this stderr.
// Wait for all of (1) process 'exit', (2) stderr 'end', and (2) stdout
// 'end' before returning to ensure all stderr is flushed (issue #54).
var returnCode = null;
var eventsRemaining = 3;
function countdownToFinish(code) {
returnCode = code;
eventsRemaining--;
if (eventsRemaining == 0) {
finish(returnCode);
}
}
dtrace.stderr.pipe(process.stderr);
dtrace.stderr.on('end', countdownToFinish);
dtrace.stderr.on('end', countdownToFinish);
dtrace.on('exit', countdownToFinish);
} }
}); });
if (nodeSpawnSupportsStdio) {
dtrace.on('exit', finish);
} else {
// Fallback (for < v0.8) to pipe the dtrace process' stderr to this stderr.
// Wait for all of (1) process 'exit', (2) stderr 'end', and (2) stdout
// 'end' before returning to ensure all stderr is flushed (issue #54).
var returnCode = null;
var eventsRemaining = 3;
function countdownToFinish(code) {
returnCode = code;
eventsRemaining--;
if (eventsRemaining == 0) {
finish(returnCode);
}
}
dtrace.stderr.pipe(process.stderr);
dtrace.stderr.on('end', countdownToFinish);
dtrace.stderr.on('end', countdownToFinish);
dtrace.on('exit', countdownToFinish);
}
} }
@ -1133,8 +1218,8 @@ function main(argv) {
var stylize = (opts.color ? stylizeWithColor : stylizeWithoutColor); var stylize = (opts.color ? stylizeWithColor : stylizeWithoutColor);
var retval = 0; var retval = 0;
if (opts.pid) { if (opts.pids) {
processPid(opts, stylize, function (code) { processPids(opts, stylize, function (code) {
process.exit(code); process.exit(code);
}); });
} else if (opts.args.length > 0) { } else if (opts.args.length > 0) {

View file

@ -7,7 +7,13 @@
\fBbunyan\fR \- filter and pretty\-print Bunyan log file content \fBbunyan\fR \- filter and pretty\-print Bunyan log file content
. .
.SH "SYNOPSIS" .SH "SYNOPSIS"
\fBbunyan\fR [OPTIONS] [LOOKUPS\.\.\.] \.\.\. | \fBbunyan\fR [OPTIONS] \fBbunyan\fR [OPTIONS] \-p PID \fBbunyan\fR [OPTIONS]
.
.P
\&\.\.\. | \fBbunyan\fR [OPTIONS]
.
.P
\fBbunyan\fR [OPTIONS] \-p PID
. .
.SH "DESCRIPTION" .SH "DESCRIPTION"
"Bunyan" is \fBa simple and fast a JSON logging library\fR for node\.js services, a one\-JSON\-object\-per\-line log format, and \fBa \fBbunyan\fR CLI tool\fR for nicely viewing those logs\. This man page describes the latter\. "Bunyan" is \fBa simple and fast a JSON logging library\fR for node\.js services, a one\-JSON\-object\-per\-line log format, and \fBa \fBbunyan\fR CLI tool\fR for nicely viewing those logs\. This man page describes the latter\.
@ -99,8 +105,8 @@ Don\'t warn if input isn\'t valid JSON\.
Dtrace options (only on dtrace\-supporting platforms): Dtrace options (only on dtrace\-supporting platforms):
. .
.TP .TP
\fB\-p PID\fR \fB\-p PID\fR, \fB\-p NAME\fR
Process bunyan:log\-* probes from the process with the given PID\. Process bunyan:log\-* probes from the process with the given PID\. Can be used multiple times, or specify all processes with \'*\', or a set of processes whose command & args match a pattern with \'\-p NAME\'\.
. .
.P .P
Filtering options: Filtering options:
@ -195,7 +201,7 @@ log\-fatal
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\. 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\.
. .
.P .P
See \fIhttps://github\.com/trentm/node\-bunyan#dtrace\-support\fR for more details\. See \fIhttps://github\.com/trentm/node\-bunyan#dtrace\-support\fR for more details and the \'\-p PID\' option above for convenience usage\.
. .
.SH "ENVIRONMENT" .SH "ENVIRONMENT"
. .

View file

@ -85,9 +85,11 @@
<h2 id="SYNOPSIS">SYNOPSIS</h2> <h2 id="SYNOPSIS">SYNOPSIS</h2>
<p><code>bunyan</code> [OPTIONS] [LOOKUPS...] <p><code>bunyan</code> [OPTIONS]</p>
... | <code>bunyan</code> [OPTIONS]
<code>bunyan</code> [OPTIONS] -p PID</p> <p>... | <code>bunyan</code> [OPTIONS]</p>
<p><code>bunyan</code> [OPTIONS] -p PID</p>
<h2 id="DESCRIPTION">DESCRIPTION</h2> <h2 id="DESCRIPTION">DESCRIPTION</h2>
@ -153,7 +155,10 @@ record data. In the COND code, <code>this</code> refers to the record object:</p
<p>Dtrace options (only on dtrace-supporting platforms):</p> <p>Dtrace options (only on dtrace-supporting platforms):</p>
<dl> <dl>
<dt class="flush"><code>-p PID</code></dt><dd>Process bunyan:log-* probes from the process with the given PID.</dd> <dt><code>-p PID</code>, <code>-p NAME</code></dt><dd>Process bunyan:log-* probes from the process with the given PID.
Can be used multiple times, or specify all processes with '*',
or a set of processes whose command &amp; args match a pattern with
'-p NAME'.</dd>
</dl> </dl>
@ -229,7 +234,8 @@ 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 fire whenever the corresponding function is called, even if the level of
the log message is less than that of any stream.</p> the log message is less than that of any stream.</p>
<p>See <a href="https://github.com/trentm/node-bunyan#dtrace-support" data-bare-link="true">https://github.com/trentm/node-bunyan#dtrace-support</a> for more details.</p> <p>See <a href="https://github.com/trentm/node-bunyan#dtrace-support" data-bare-link="true">https://github.com/trentm/node-bunyan#dtrace-support</a> for more details
and the '-p PID' option above for convenience usage.</p>
<h2 id="ENVIRONMENT">ENVIRONMENT</h2> <h2 id="ENVIRONMENT">ENVIRONMENT</h2>

View file

@ -3,8 +3,10 @@
## SYNOPSIS ## SYNOPSIS
`bunyan` \[OPTIONS\] \[LOOKUPS...\] `bunyan` \[OPTIONS\]
... | `bunyan` \[OPTIONS\] ... | `bunyan` \[OPTIONS\]
`bunyan` \[OPTIONS\] -p PID `bunyan` \[OPTIONS\] -p PID
@ -72,8 +74,11 @@ record data. In the COND code, `this` refers to the record object:
Dtrace options (only on dtrace-supporting platforms): Dtrace options (only on dtrace-supporting platforms):
* `-p PID`: * `-p PID`, `-p NAME`:
Process bunyan:log-* probes from the process with the given PID. Process bunyan:log-\* probes from the process with the given PID.
Can be used multiple times, or specify all processes with '\*',
or a set of processes whose command & args match a pattern with
'-p NAME'.
Filtering options: Filtering options:
@ -153,7 +158,8 @@ 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 fire whenever the corresponding function is called, even if the level of
the log message is less than that of any stream. the log message is less than that of any stream.
See <https://github.com/trentm/node-bunyan#dtrace-support> for more details. See <https://github.com/trentm/node-bunyan#dtrace-support> for more details
and the '-p PID' option above for convenience usage.
## ENVIRONMENT ## ENVIRONMENT