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

Remove all instances of dtrace

Browse source
This commit is contained in:
Jonatan Nilsson 2018-07-22 08:51:54 +00:00
parent 4a50ed39c2
commit 29019b3145
11 changed files with 7 additions and 542 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

26
Makefile
View file

@ -2,28 +2,14 @@
#---- Tools
NODEUNIT := ./node_modules/.bin/nodeunit
SUDO := sudo
ifeq ($(shell uname -s),SunOS)
# On SunOS (e.g. SmartOS) we expect to run the test suite as the
# root user -- necessary to run dtrace. Therefore `pfexec` isn't
# necessary.
SUDO :=
endif
DTRACE_UP_IN_HERE=
ifeq ($(shell uname -s),SunOS)
DTRACE_UP_IN_HERE=1
endif
ifeq ($(shell uname -s),Darwin)
DTRACE_UP_IN_HERE=1
endif
NODEOPT ?= $(HOME)/opt
#---- Files
JSSTYLE_FILES := $(shell find lib test tools examples -name "*.js") bin/bunyan
# All test files *except* dtrace.test.js.
NON_DTRACE_TEST_FILES := $(shell ls -1 test/*.test.js | grep -v dtrace | xargs)
# All test files
TEST_FILES := $(shell ls -1 test/*.test.js | xargs)
#---- Targets
@ -92,16 +78,10 @@ distclean:
.PHONY: test
test: $(NODEUNIT)
test -z "$(DTRACE_UP_IN_HERE)" || test -n "$(SKIP_DTRACE)" || \
(node -e 'require("dtrace-provider").createDTraceProvider("isthisthingon")' && \
echo "\nNote: Use 'SKIP_DTRACE=1 make test' to skip parts of the test suite that require root." && \
$(SUDO) $(NODEUNIT) test/dtrace.test.js)
$(NODEUNIT) $(NON_DTRACE_TEST_FILES)
$(NODEUNIT) $(TEST_FILES)
# Test with all node supported versions (presumes install locations I use on
# my machine -- "~/opt/node-VER"):
# Note: 'test4' is last so (if all is well) I end up with a binary
# dtrace-provider build for my current default node version.
.PHONY: testall
testall: test7 test6 test012 test010 test4

222
bin/bunyan
View file

@ -99,9 +99,6 @@ var exiting = false;
// The current raw input line being processed. Used for `uncaughtException`.
var currLine = null;
// Child dtrace process, if any. Used for signal-handling.
var child = null;
// Whether ANSI codes are being used. Used for signal-handling.
var usingAnsiCodes = false;
@ -199,13 +196,6 @@ function printHelp() {
p(' -h, --help print this help info and exit');
p(' --version print version of this command and exit');
p('');
p('Runtime log snooping (via DTrace, only on supported platforms):');
p(' -p PID Process bunyan:log-* probes from the process');
p(' with the given PID. Can be used multiple times,');
p(' or specify all processes with "*", or a set of');
p(' processes whose command & args match a pattern');
p(' with "-p NAME".');
p('');
p('Filtering options:');
p(' -l, --level LEVEL');
p(' Only show messages at or above the specified level.');
@ -416,8 +406,6 @@ function parseArgv(argv) {
jsonIndent: 2,
level: null,
strict: false,
pids: null,
pidsType: null,
timeFormat: TIME_UTC // one of the TIME_ constants
};
@ -518,31 +506,6 @@ function parseArgv(argv) {
timeArg));
}
break;
case '-p':
if (!parsed.pids) {
parsed.pids = [];
}
var pidArg = args.shift();
var pid = +(pidArg);
if (!isNaN(pid) || pidArg === '*') {
if (parsed.pidsType && parsed.pidsType !== 'num') {
throw new Error(format('cannot mix PID name and '
+ 'number arguments: "%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;
}
break;
case '-l':
case '--level':
var levelArg = args.shift();
@ -1124,173 +1087,6 @@ function processStdin(opts, stylize, callback) {
}
/**
* Process bunyan:log-* probes from the given pid.
*
* @params opts {Object} Bunyan options object.
* @param stylize {Function} Output stylize function to use.
* @param callback {Function} `function (code)`
*/
function processPids(opts, stylize, callback) {
var leftover = ''; // Left-over partial line from last chunk.
/**
* Get the PIDs to dtrace.
*
* @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);
}
);
}
}
getPids(function (errCode, pids) {
if (errCode) {
return callback(errCode);
}
var probes = pids.map(function (pid) {
if (!opts.level)
return format('bunyan%s:::log-*', pid);
var rval = [], l;
for (l in levelFromName) {
if (levelFromName[l] >= opts.level)
rval.push(format('bunyan%s:::log-%s', pid, l));
}
if (rval.length != 0)
return rval.join(',');
warn('bunyan: error: level (%d) exceeds maximum logging level',
opts.level);
cleanupAndExit(1);
}).join(',');
var argv = ['dtrace', '-Z', '-x', 'strsize=4k',
'-x', 'switchrate=10hz', '-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]});
dtrace.on('error', function (e) {
if (e.syscall === 'spawn' && e.errno === 'ENOENT') {
console.error('bunyan: error: could not spawn "dtrace" ' +
'("bunyan -p" is only supported on platforms with dtrace)');
} else {
console.error('bunyan: error: unexpected dtrace error: %s', e);
}
callback(1);
})
child = dtrace; // intentionally global
function finish(code) {
if (leftover) {
handleLogLine(null, leftover, opts, stylize);
leftover = '';
}
callback(code);
}
dtrace.stdout.setEncoding('utf8');
dtrace.stdout.on('data', function (chunk) {
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);
}
});
}
/**
* Process all input from the given log file.
*
@ -1409,11 +1205,6 @@ function cleanupAndExit(code, signal) {
stdout.write('\033[0m');
}
// Kill possible dtrace child.
if (child) {
child.kill(signal);
}
if (pager) {
// Let pager know that output is done, then wait for pager to exit.
pager.removeListener('exit', onPrematurePagerExit);
@ -1511,12 +1302,6 @@ function main(argv) {
console.log('bunyan ' + getVersion());
return;
}
if (opts.pids && opts.args.length > 0) {
warn('bunyan: error: can\'t use both "-p PID" (%s) and file (%s) args',
opts.pids, opts.args.join(' '));
cleanupAndExit(1);
return;
}
if (opts.color === null) {
if (process.env.BUNYAN_NO_COLOR &&
process.env.BUNYAN_NO_COLOR.length > 0) {
@ -1532,7 +1317,6 @@ function main(argv) {
var paginate = (
process.stdout.isTTY &&
process.stdin.isTTY &&
!opts.pids && // Don't page if following process output.
opts.args.length > 0 && // Don't page if no file args to process.
process.platform !== 'win32' &&
(nodeVer[0] > 0 || nodeVer[1] >= 8) &&
@ -1579,11 +1363,7 @@ function main(argv) {
});
var retval = 0;
if (opts.pids) {
processPids(opts, stylize, function (code) {
cleanupAndExit(code);
});
} else if (opts.args.length > 0) {
if (opts.args.length > 0) {
var files = opts.args;
files.forEach(function (file) {
streams[file] = { stream: null, records: [], done: false }

7
docs/bunyan.1
View file

@ -102,13 +102,6 @@ Print version of this command and exit\.
Don\'t warn if input isn\'t valid JSON\.
.
.P
Dtrace options (only on dtrace\-supporting platforms):
.
.TP
\fB\-p PID\fR, \fB\-p NAME\fR
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
Filtering options:
.
.TP

40
docs/bunyan.1.html
View file

@ -89,8 +89,6 @@
<p>... | <code>bunyan</code> [OPTIONS]</p>
<p><code>bunyan</code> [OPTIONS] -p PID</p>
<h2 id="DESCRIPTION">DESCRIPTION</h2>
<p>"Bunyan" is <strong>a simple and fast a JSON logging library</strong> for node.js services,
@ -152,16 +150,6 @@ record data. In the COND code, <code>this</code> refers to the record object:</p
</dl>
<p>Dtrace options (only on dtrace-supporting platforms):</p>
<dl>
<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>
<p>Filtering options:</p>
<dl>
@ -216,34 +204,6 @@ bunyan Alias for "json-0", the Bunyan "native" format.
inspect Node.js `util.inspect` output.
</code></pre>
<h2 id="DTRACE-SUPPORT">DTRACE SUPPORT</h2>
<p>On systems that support DTrace (e.g., MacOS, FreeBSD, illumos derivatives
like SmartOS and OmniOS), Bunyan will create a DTrace provider (<code>bunyan</code>)
that makes available the following probes:</p>
<pre><code>log-trace
log-debug
log-info
log-warn
log-error
log-fatal
</code></pre>
<p>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 <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>
<dl>
<dt><code>BUNYAN_NO_COLOR</code></dt><dd>Set to a non-empty value to force no output coloring. See '--no-color'.</dd>
</dl>
<h2 id="PROJECT-BUGS">PROJECT &amp; BUGS</h2>

32
docs/bunyan.1.ronn
View file

@ -7,8 +7,6 @@
... | `bunyan` \[OPTIONS\]
`bunyan` \[OPTIONS\] -p PID
## DESCRIPTION
@ -72,14 +70,6 @@ record data. In the COND code, `this` refers to the record object:
* `-q`, `--quiet`:
Don't warn if input isn't valid JSON.
Dtrace options (only on dtrace-supporting platforms):
* `-p PID`, `-p NAME`:
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:
* `-l`, `--level LEVEL`:
@ -141,28 +131,6 @@ scripts, uppercase symbols like "DEBUG" are defined for convenience.
inspect Node.js `util.inspect` output.
## 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 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.
See <https://github.com/trentm/node-bunyan#dtrace-support> for more details
and the '-p PID' option above for convenience usage.
## ENVIRONMENT
* `BUNYAN_NO_COLOR`:

42
lib/bunyan.js
View file

@ -61,7 +61,7 @@ if (!runtimeEnv) {
}
var os, fs, dtrace;
var os, fs;
if (runtimeEnv === 'browser') {
os = {
hostname: function () {
@ -69,15 +69,9 @@ if (runtimeEnv === 'browser') {
}
};
fs = {};
dtrace = null;
} else {
os = require('os');
fs = require('fs');
try {
dtrace = require('dtrace-provider' + '');
} catch (e) {
dtrace = null;
}
}
var util = require('util');
var assert = require('assert');
@ -271,10 +265,6 @@ Object.keys(levelFromName).forEach(function (name) {
nameFromLevel[levelFromName[name]] = name;
});
// Dtrace probes.
var dtp = undefined;
var probes = dtrace && {};
/**
* Resolve a level number, name (upper or lowercase) to a level number value.
*
@ -438,22 +428,6 @@ function Logger(options, _childOptions, _childSimple) {
this.fields = {};
}
if (!dtp && dtrace) {
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();
}
// Handle *config* options (i.e. options that are not just plain data
// for log records).
if (options.stream) {
@ -993,16 +967,6 @@ function mkRecord(log, minLevel, args) {
};
/**
* Build an array that dtrace-provider can use to fire a USDT probe. If we've
* already built the appropriate string, we use it. Otherwise, build the
* record object and stringify it.
*/
function mkProbeArgs(str, log, minLevel, msgArgs) {
return [ str || log._emit(mkRecord(log, minLevel, msgArgs), true) ];
}
/**
* Build a log emitter function for level minLevel. I.e. this is the
* creator of `log.info`, `log.error`, etc.
@ -1042,10 +1006,6 @@ function mkLogEmitter(minLevel) {
rec = mkRecord(log, minLevel, msgArgs);
str = this._emit(rec);
}
if (probes) {
probes[minLevel].fire(mkProbeArgs, str, log, minLevel, msgArgs);
}
}
}

2
package.json
View file

@ -19,10 +19,8 @@
"dependencies": {
"exeunt": "1.1.0"
},
"// dtrace-provider": "required for dtrace features",
"// mv": "required for RotatingFileStream",
"optionalDependencies": {
"dtrace-provider": "~0.8",
"mv": "~2",
"safe-json-stringify": "~1"
},

29
test/cli.test.js
View file

@ -99,24 +99,9 @@ test('cat simple.log', function (t) {
);
});
// A stable 'TZ' for 'local' timezone output.
tzEnv = objCopy(process.env);
tzEnv.TZ = 'Pacific/Honolulu';
test('time: simple.log local long', function (t) {
exec(_('%s -o long -L %s/corpus/simple.log', BUNYAN, __dirname),
{env: tzEnv}, function (err, stdout, stderr) {
t.ifError(err)
t.equal(stdout,
// JSSTYLED
'[2012-02-08T12:56:52.856-10:00] INFO: myservice/123 on example.com: '
+ 'My message\n');
t.end();
});
});
test('time: simple.log utc long', function (t) {
exec(_('%s -o long --time utc %s/corpus/simple.log', BUNYAN, __dirname),
{env: tzEnv}, function (err, stdout, stderr) {
{env: process.env}, function (err, stdout, stderr) {
t.ifError(err)
t.equal(stdout,
'[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: '
@ -124,19 +109,9 @@ test('time: simple.log utc long', function (t) {
t.end();
});
});
test('time: simple.log local short', function (t) {
exec(_('%s -o short -L %s/corpus/simple.log', BUNYAN, __dirname),
{env: tzEnv}, function (err, stdout, stderr) {
t.ifError(err)
t.equal(stdout,
'12:56:52.856 INFO myservice: '
+ 'My message\n');
t.end();
});
});
test('time: simple.log utc short', function (t) {
exec(_('%s -o short %s/corpus/simple.log', BUNYAN, __dirname),
{env: tzEnv}, function (err, stdout, stderr) {
{env: process.env}, function (err, stdout, stderr) {
t.ifError(err)
t.equal(stdout,
'22:56:52.856Z INFO myservice: '

122
test/dtrace.test.js
View file

@ -1,122 +0,0 @@
/*
* Copyright 2016 Trent Mick
*
* If available, test dtrace support.
*/
var spawn = require('child_process').spawn;
var format = require('util').format;
var bunyan = require('../lib/bunyan');
// node-tap API
if (require.cache[__dirname + '/tap4nodeunit.js'])
delete require.cache[__dirname + '/tap4nodeunit.js'];
var tap4nodeunit = require('./tap4nodeunit.js');
var after = tap4nodeunit.after;
var before = tap4nodeunit.before;
var test = tap4nodeunit.test;
// 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 dtrace', function (t) {
var argv = ['dtrace', '-Z', '-x', 'strsize=4k', '-qn',
'bunyan$target:::log-*{printf("%s", copyinstr(arg0))}',
'-c', format('node %s/log-some.js', __dirname)];
var dtrace = spawn(argv[0], argv.slice(1));
//console.error('ARGV: %j', argv);
//console.error('CMD: %s', argv.join(' '));
var traces = [];
dtrace.stdout.on('data', function (data) {
//console.error('DTRACE STDOUT:', data.toString());
traces.push(data.toString());
});
dtrace.stderr.on('data', function (data) {
console.error('DTRACE STDERR:', data.toString());
});
dtrace.on('exit', function (code) {
t.notOk(code, 'dtrace exited cleanly');
traces = traces.join('').split('\n')
.filter(function (t) { return t.trim().length })
.map(function (t) { return JSON.parse(t) });
t.equal(traces.length, 2, 'got 2 log records');
if (traces.length) {
t.equal(traces[0].level, bunyan.DEBUG);
t.equal(traces[0].foo, 'bar');
t.equal(traces[1].level, bunyan.TRACE);
t.equal(traces[1].msg, 'hi at trace');
}
t.end();
});
});
/*
* Run a logger that logs a couple records every second.
* Then run `bunyan -p PID` to capture.
* Let those run for a few seconds to ensure dtrace has time to attach and
* capture something.
*/
test('bunyan -p', function (t) {
var p = spawn('node', [__dirname + '/log-some-loop.js']);
var bunyanP = spawn('node',
[__dirname + '/../bin/bunyan', '-p', String(p.pid), '-0']);
var traces = [];
bunyanP.stdout.on('data', function (data) {
//console.error('BUNYAN -P STDOUT:', data.toString());
traces.push(data.toString());
});
bunyanP.stderr.on('data', function (data) {
console.error('BUNYAN -P STDERR:', data.toString());
});
bunyanP.on('exit', function (code) {
traces = traces.join('').split('\n')
.filter(function (t) { return t.trim().length })
.map(function (t) { return JSON.parse(t) });
t.ok(traces.length >= 3, 'got >=3 log records: ' + traces.length);
if (traces.length >= 3) {
if (traces[0].level !== bunyan.DEBUG) {
traces.shift();
}
t.equal(traces[0].level, bunyan.DEBUG);
t.equal(traces[0].foo, 'bar');
t.equal(traces[1].level, bunyan.TRACE);
t.equal(traces[1].msg, 'hi at trace');
}
t.end();
});
// Give it a few seconds to ensure we get some traces.
setTimeout(function () {
p.kill();
bunyanP.kill();
}, 5000);
});
} /* end of `if (runDtraceTests)` */

15
test/log-some-loop.js
View file

@ -1,15 +0,0 @@
// A helper script to log a few times, pause, repeat. We attempt to NOT emit
// to stdout or stderr because this is used for dtrace testing
// and we don't want to mix output.
var bunyan = require('../lib/bunyan');
var log = bunyan.createLogger({
name: 'play',
serializers: bunyan.stdSerializers
});
setInterval(function logSome() {
log.debug({foo: 'bar'}, 'hi at debug')
log.trace('hi at trace')
}, 1000);

12
test/log-some.js
View file

@ -1,12 +0,0 @@
// A helper script to log a few times. We attempt to NOT emit
// to stdout or stderr because this is used for dtrace testing
// and we don't want to mix output.
var bunyan = require('../lib/bunyan');
var log = bunyan.createLogger({
name: 'play',
serializers: bunyan.stdSerializers
});
log.debug({foo: 'bar'}, 'hi at debug')
log.trace('hi at trace')