From 778d0f70495fbc627a9e435fb088c868ae0c1d74 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 16 Mar 2016 22:32:52 -0700 Subject: [PATCH] Fix `bunyan -p ...` (i.e. DTrace integration) on node 4.x and 5.x This never worked with node >0.x because of faulty logic determining `nodeSpawnSupportsStdio` -- attempting to compare with, e.g., `Number('v1')`. Fixes #370 --- CHANGES.md | 2 ++ bin/bunyan | 7 ++----- test/dtrace.test.js | 48 +++++++++++++++++++++++++++++++++++++++++-- test/log-some-loop.js | 15 ++++++++++++++ 4 files changed, 65 insertions(+), 7 deletions(-) create mode 100644 test/log-some-loop.js diff --git a/CHANGES.md b/CHANGES.md index 7897b8f..51befe5 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -8,6 +8,8 @@ Known issues: ## 1.8.0 (not yet released) +- [issue #370] Fix `bunyan -p ...` (i.e. DTrace integration) on node + 4.x and 5.x. - [issue #329, pull #330] Update the 'rotating-file' stream to do a file rotation on initialization if the mtime on the file path indicates the last rotation time was missed -- i.e. if the app wasn't running at the diff --git a/bin/bunyan b/bin/bunyan index 280f670..c105c5e 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -35,9 +35,8 @@ try { //---- globals and constants -var nodeSpawnSupportsStdio = ( - Number(process.version.split('.')[0]) >= 0 || - Number(process.version.split('.')[1]) >= 8); +var nodeVer = process.versions.node.split('.').map(Number); +var nodeSpawnSupportsStdio = (nodeVer[0] > 0 || nodeVer[1] >= 8); // Internal debug logging via `console.warn`. var _DEBUG = false; @@ -1555,7 +1554,6 @@ function main(argv) { var stylize = (opts.color ? stylizeWithColor : stylizeWithoutColor); // Pager. - var nodeVer = process.versions.node.split('.').map(Number); var paginate = ( process.stdout.isTTY && process.stdin.isTTY && @@ -1655,7 +1653,6 @@ if (require.main === module) { // We override the `process.stdout.end` guard that core node.js puts in // place. The real fix is that `.end()` shouldn't be called on stdout // in node core. Node v0.6.9 fixes that. Only guard for v0.6.0..v0.6.8. - var nodeVer = process.versions.node.split('.').map(Number); if ([0, 6, 0] <= nodeVer && nodeVer <= [0, 6, 8]) { var stdout = process.stdout; stdout.end = stdout.destroy = stdout.destroySoon = function () { diff --git a/test/dtrace.test.js b/test/dtrace.test.js index 07094a5..b220a45 100644 --- a/test/dtrace.test.js +++ b/test/dtrace.test.js @@ -1,5 +1,5 @@ /* - * Copyright (c) 2012 Trent Mick. All rights reserved. + * Copyright 2016 Trent Mick * * If available, test dtrace support. */ @@ -22,7 +22,7 @@ var test = tap4nodeunit.test; var dtracePlats = ['sunos', 'darwin', 'freebsd']; var runDtraceTests = true; try { - require('dtrace-provider') + require('dtrace-provider'); } catch (e) { console.log('# skip dtrace tests: no dtrace-provider module'); runDtraceTests = false; @@ -75,4 +75,48 @@ test('basic dtrace', function (t) { }); +/* + * 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(); + }, 3000); +}); + + } /* end of `if (runDtraceTests)` */ diff --git a/test/log-some-loop.js b/test/log-some-loop.js new file mode 100644 index 0000000..eb98f2d --- /dev/null +++ b/test/log-some-loop.js @@ -0,0 +1,15 @@ + +// 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);