diff --git a/Makefile b/Makefile index 08acfb8..b1ac5ab 100644 --- a/Makefile +++ b/Makefile @@ -77,7 +77,7 @@ test: $(TAP) # Note: 'test08' is last so (if all is well) I end up with a binary # dtrace-provider build for node 0.8 (my current version). .PHONY: testall -testall: test06 test09 test08 +testall: test06 test08 .PHONY: test09 test09: diff --git a/test/dtrace.test.js b/test/dtrace.test.js index c6ed039..9ea3b56 100644 --- a/test/dtrace.test.js +++ b/test/dtrace.test.js @@ -35,51 +35,36 @@ if (!runDtraceTests) { if (runDtraceTests) { -test('basic', function (t) { - var log = bunyan.createLogger({name: 'basic'}); // at default 'info' level - - // Should be '%%s' in that `format` frankly, but node *0.6* doesn't see - // it that way. Node *0.8* has fixed '%%' handling. - var argv = ['dtrace', '-x', 'strsize=4k', '-qn', - format('bunyan%d:::log-*{printf("%s", copyinstr(arg0))}', process.pid)]; +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); + var traces = []; dtrace.stdout.on('data', function (data) { - //console.error("STDOUT:", data.toString()); + //console.error("DTRACE STDOUT:", data.toString()); traces.push(data.toString()); }); dtrace.stderr.on('data', function (data) { - console.error(data.toString()); + console.error("DTRACE STDERR:", data.toString()); }); dtrace.on('exit', function (code) { - if (code) { - console.log("# error: dtrace exited non-zero:", 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(); }); - - setTimeout(function () { - log.debug({basic: true}, 'hi at debug'); - log.trace({basic: true}, 'hi at trace'); - - setTimeout(function () { - dtrace.kill('SIGTERM'); - - traces = traces.join('').split('\n') - .filter(function (t) { return t.trim().length }) - .map(function (t) { return JSON.parse(t) }); - t.equal(traces.length, 2, - "(If this fails, it is often a timing issue. Please try again.)"); - if (traces.length) { - t.equal(traces[0].pid, process.pid); - t.equal(traces[0].level, bunyan.DEBUG); - t.equal(traces[1].basic, true); - } - t.end(); - }, 1000); - }, 3000); // Give dtrace some time to startup. How much? }); - } /* end of `if (runDtraceTests)` */ diff --git a/test/log-some.js b/test/log-some.js new file mode 100644 index 0000000..997fd64 --- /dev/null +++ b/test/log-some.js @@ -0,0 +1,13 @@ + +// 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') +