diff --git a/AUTHORS.txt b/AUTHORS.txt new file mode 100644 index 0000000..88c1589 --- /dev/null +++ b/AUTHORS.txt @@ -0,0 +1,2 @@ +Trent Mick +Mark Cavage diff --git a/CHANGES.md b/CHANGES.md index 57864e6..165d68c 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -1,8 +1,16 @@ # bunyan Changelog -## bunyan 0.3.1 (not yet released) +## bunyan 0.4.0 (not yet released) + +- Add `new Logger({src: true})` config option to have a 'src' attribute be + automatically added to log records with the log call source info. Example: + + "src": { + "file": "/Users/trentm/tm/node-bunyan/examples/src.js", + "line": 20, + "func": "Wuzzle.woos" + }, -(nothing yet) ## bunyan 0.3.0 diff --git a/README.md b/README.md index b01f308..3de03bf 100644 --- a/README.md +++ b/README.md @@ -32,6 +32,16 @@ format version) are added for you. $ node hi.js {"service":"myapp","hostname":"banana.local","level":2,"msg":"hi","time":"2012-01-31T00:07:44.216Z","v":0} +The full `log.{trace|debug|...|fatal}(...)` API is: + + log.info(); // returns a boolean: is the "info" level enabled? + log.info("hi"); // log a simple string message + log.info("hi %s", bob, anotherVar); // uses `util.format` for msg formatting + log.info({foo: "bar"}, "hi"); // adds "foo" field to log record + + +## bunyan tool + A `bunyan` tool is provided **for pretty-printing bunyan logs** and, eventually, for filtering (e.g. `| bunyan -c 'level>3'`). This shows the default output (which is fluid right now) and indented-JSON output. More output formats will @@ -50,6 +60,9 @@ be added, including support for custom formats. "v": 0 } + +## streams + By default, log output is to stdout (**stream**) and at the "info" level. Explicitly that looks like: @@ -73,6 +86,9 @@ streams at different levels**. ] }); + +## log.child + A `log.child(...)` is provided to **specialize a logger for a sub-component**. The following will have log records from "Wuzzle" instances use exactly the same config as its parent, plus include the "component" field. @@ -111,12 +127,7 @@ See the changelog for node-bunyan 0.3.0 for details. * * * -Back to the `log.{trace|debug|...|fatal}(...)` API: - - log.info(); // returns a boolean: is the "info" level enabled? - log.info("hi"); // log a simple string message - log.info("hi %s", bob, anotherVar); // uses `util.format` for msg formatting - log.info({foo: "bar"}, "hi"); // adds "foo" field to log record +## serializers Bunyan has a concept of **"serializers" to produce a JSON-able object from a JavaScript object**, so your can easily do the following: @@ -159,7 +170,32 @@ standard serializers you can use: ugly message on stderr from Bunyan (along with the traceback) and the field in your log record will be replaced with a short error message.* +## src +The **call source file, line and function** (if not at the global level) can +be added to log records by using the `src: true` config option: + + var log = new Logger({src: true, ...}); + +This adds the call source info with the 'src' field, like this: + + { + "service": "src-example", + "hostname": "banana.local", + "component": "wuzzle", + "level": 4, + "msg": "This wuzzle is woosey.", + "time": "2012-02-06T04:19:35.605Z", + "src": { + "file": "/Users/trentm/tm/node-bunyan/examples/src.js", + "line": 20, + "func": "Wuzzle.woos" + }, + "v": 0 + } + +**WARNING: Determining the call source info is slow. Never use this option +in production.** # Levels @@ -245,6 +281,9 @@ Core fields: [`Date.toISOString()`](https://developer.mozilla.org/en/JavaScript/Reference/Global_Objects/Date/toISOString). - `msg`: Required. String. Every `log.debug(...)` et al call must provide a log message. +- `src`: Optional. Object giving log call source info. This is added + automatically by Bunyan if the "src: true" config option is given to the + Logger. Never use in production as this is really slow. Go ahead and add more fields, and nest ones are fine (and recommended) as diff --git a/TODO.md b/TODO.md index d511a8d..b924775 100644 --- a/TODO.md +++ b/TODO.md @@ -1,14 +1,12 @@ -- `log.close` to close streams and shutdown and `this.closed` - line/file: possible to get quickly with v8? Yunong asked. -- what's the API for changing the logger/stream level(s)? + file/line/func (?) +- Logger.setLevel()? How to change level for a given stream. Default all, + else, give an index... or type ... or support stream "names". Some positives + to stream names. - bunyan cli: more layouts (http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/EnhancedPatternLayout.html) Custom log formats (in config file? in '-f' arg) using printf or hogan.js or whatever. Dap wants field width control for lining up. Hogan.js is probably overkill for this. -- bunyan cli: filter args a la json -- bunyan cli: -c COND args a la json -- mark wants pretty output for debug output - - not sure if 'bunyan --pretty' or whatever would suffice - ringBuffer stream - syslog: Josh uses https://github.com/chrisdew/node-syslog streams: [ @@ -20,8 +18,6 @@ syslog_pid: true, // syslog logopt "LOG_PID" syslog_cons: false // syslog logopt "LOG_CONS" } -- Logger.setLevel()? How to change level for a given stream. Default all, - else, give an index... or type ... or support stream "names". - "canWrite" handling for full streams. Need to buffer a la log4js - test file log with logadm rotation: does it handle that? - test suite: @@ -32,30 +28,24 @@ works *and* that an existing field in the parent is not *re-serialized*. - a "rolling-file" stream: but specifically by time, e.g. hourly. (MarkC requested) +- (mark) instanceof-based serialization: + log.info(new Error("blah blah")) -> {err: ..., msg: ""} + perhaps at least default for Error. Then perhaps augment or replace + serializers with registerable instanceof's. + log = new Logger({ + serializers + }) + # someday/maybe -- file/line fields automatic: "but it's fucking slow" (https://gist.github.com/1733234) - function getFileAndLine() { - var self = this; - var saveLimit = Error.stackTraceLimit; - var savePrepare = Error.prepareStackTrace; - Error.stackTraceLimit = 1; - Error.captureStackTrace(this, getFileAndLine); - Error.prepareStackTrace = function(_, stack) { - self.file = stack[0].getFileName(); - self.line = stack[0].getLineNumber(); - }; - this.stack; - Error.stackTraceLimit = saveLimit; - Error.prepareStackTrace = savePrepare; - return { - file: self.file, - line: self.line - } - } - Want some way to have file/line only at certain levesl and lazily. +- bunyan cli: filter args a la json +- bunyan cli: -c COND args a la json +- bunyan "compact" or "light", '-l'? Something like. Or pehaps this (with + color) could be the default, with '-l' for long output. + 13:51.340 [src.js:20#Wuzzle.woos] WARN: This wuzzle is woosey. +- `log.close` to close streams and shutdown and `this.closed` - get Mark to show me dtrace provider stuff and consider adding for logging, if helpful. - add option to "streams" to take the raw object, not serialized. diff --git a/bin/bunyan b/bin/bunyan index 3c8ea7c..e9ed588 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -5,7 +5,7 @@ // See . // -var VERSION = "0.3.1"; +var VERSION = "0.4.0"; var util = require('util'); var pathlib = require('path'); @@ -253,9 +253,9 @@ function handleLogLine(line, opts) { switch (opts.outputMode) { case OM_PAUL: // Single-line msg: - // [time] LEVEL: service[/component] on hostname: msg (extras...) + // [time] LEVEL: service[/component] on hostname (src): msg (extras...) // Multi-line msg: - // [time] LEVEL: service[/component] on hostname: (extras...) + // [time] LEVEL: service[/component] on hostname (src): (extras...) // msg // If 'req', show the request. // If 'res', show the response. @@ -266,8 +266,17 @@ function handleLogLine(line, opts) { } var levelStr = (upperNameFromLevel[rec.level] || ""); + var src = ""; + if (rec.src && rec.src.file) { + var s = rec.src; + if (s.func) { + src = format(" (%s:%d in %s)", s.file, s.line, s.func); + } else { + src = format(" (%s:%d)", s.file, s.line); + } + } var extras = []; - if (rec.request_id) extras.push(rec.request_id); + if (rec.req_id) extras.push("req_id=" + rec.req_id); if (rec.latency) extras.push(rec.latency + "ms"); extras = (extras.length ? ' (' + extras.join(', ') + ')' : ''); var details = []; @@ -304,11 +313,12 @@ function handleLogLine(line, opts) { details.push(indent(rec.err.stack)) } details = (details.length ? details.join('\n--\n') + '\n' : ''); - emit(format("[%s] %s: %s on %s:%s%s\n%s", + emit(format("[%s] %s: %s on %s%s:%s%s\n%s", rec.time, upperNameFromLevel[rec.level] || "", serviceStr, rec.hostname || "", + src, onelineMsg, extras, details)); diff --git a/examples/src.js b/examples/src.js new file mode 100644 index 0000000..60f1b61 --- /dev/null +++ b/examples/src.js @@ -0,0 +1,26 @@ +// Show the usage of `src: true` config option to get log call source info in +// log records (the `src` field). + +var Logger = require('../lib/bunyan'); + +var log = new Logger({service: "src-example", src: true}); + +log.info("one"); +log.info("two"); +function doSomeFoo() { + log.info({foo:"bar"}, "three"); +} +doSomeFoo(); + +function Wuzzle(options) { + this.log = options.log; + this.log.info("creating a wuzzle") +} +Wuzzle.prototype.woos = function () { + this.log.warn("This wuzzle is woosey.") +} + +var wuzzle = new Wuzzle({log: log.child({component: "wuzzle"})}); +wuzzle.woos(); +log.info("done with the wuzzle") + diff --git a/lib/bunyan.js b/lib/bunyan.js index f150298..6ec219b 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -2,7 +2,7 @@ * Copyright 2012 (c) Trent Mick. All rights reserved. */ -var VERSION = "0.3.1"; +var VERSION = "0.4.0"; // Bunyan log format version. This becomes the 'v' field on all log records. // `0` is until I release a version "1.0.0" of node-bunyan. Thereafter, @@ -82,6 +82,32 @@ if (!format) { } +/** + * Gather some caller info 3 stack levels up. + * See . + */ +function getCaller3Info() { + var obj = {}; + var saveLimit = Error.stackTraceLimit; + var savePrepare = Error.prepareStackTrace; + Error.stackTraceLimit = 3; + Error.captureStackTrace(this, getCaller3Info); + Error.prepareStackTrace = function(_, stack) { + var caller = stack[2]; + obj.file = caller.getFileName(); + obj.line = caller.getLineNumber(); + var func = caller.getFunctionName(); + if (func) + obj.func = func; + }; + this.stack; + Error.stackTraceLimit = saveLimit; + Error.prepareStackTrace = savePrepare; + return obj; +} + + + //---- Levels @@ -135,6 +161,8 @@ function resolveLevel(nameOrNum) { * `process.stdout` (cannot be used with `streams`) * - `serializers`: object mapping log record field names to * serializing functions. See README.md for details. + * - `src`: Boolean (default false). Set true to enable 'src' automatic + * field with log call source info. * All other keys are log record fields. * * An alternative *internal* call signature is used for creating a child: @@ -176,6 +204,7 @@ function Logger(options, _childOptions, _childSimple) { this.level = parent.level; this.streams = parent.streams; this.serializers = parent.serializers; + this.src = parent.src; this.fields = parent.fields; var names = Object.keys(options); for (var i = 0; i < names.length; i++) { @@ -196,11 +225,13 @@ function Logger(options, _childOptions, _childSimple) { this.streams.push(s); } this.serializers = objCopy(parent.serializers); + this.src = parent.src; this.fields = objCopy(parent.fields); } else { this.level = Number.POSITIVE_INFINITY; this.streams = []; this.serializers = null; + this.src = false; this.fields = {}; } @@ -289,6 +320,9 @@ function Logger(options, _childOptions, _childSimple) { if (options.serializers) { addSerializers(options.serializers); } + if (options.src) { + this.src = true; + } xxx("Logger: ", self) // Fields. @@ -301,6 +335,7 @@ function Logger(options, _childOptions, _childSimple) { delete fields.level; delete fields.streams; delete fields.serializers; + delete fields.src; if (this.serializers) { this._applySerializers(fields); } @@ -443,8 +478,12 @@ Logger.prototype._emit = function (rec) { if (!obj.time) { obj.time = (new Date()); } + // Get call source info + if (this.src && !obj.src) { + obj.src = getCaller3Info() + } obj.v = LOG_VERSION; - + xxx('_emit: stringify this:', obj); var str = JSON.stringify(obj) + '\n'; this.streams.forEach(function(s) { diff --git a/package.json b/package.json index eb871ef..cfa28c0 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "bunyan", - "version": "0.3.1", + "version": "0.4.0", "description": "a JSON Logger library for node.js servers", "main": "./lib/bunyan.js", "bin": { diff --git a/tools/timesrc.js b/tools/timesrc.js new file mode 100755 index 0000000..86f0119 --- /dev/null +++ b/tools/timesrc.js @@ -0,0 +1,37 @@ +#!/usr/bin/env node +/* + * Time 'src' fields (getting log call source info). This is expensive. + */ + +console.log("Time adding 'src' field with call source info:"); + +var ben = require('ben'); // npm install ben +var Logger = require('../lib/bunyan'); + +var records = []; +function Collector() { +} +Collector.prototype.write = function(s) { + //records.push(s); +} +var collector = new Collector(); + +var logwith = new Logger({ + service: "with-src", + src: true, + stream: collector +}); + +var ms = ben(1e5, function () { + logwith.info("hi"); +}); +console.log(' - log.info with src: %dms per iteration', ms); + +var logwithout = new Logger({ + service: "without-src", + stream: collector +}); +var ms = ben(1e5, function () { + logwithout.info("hi"); +}); +console.log(' - log.info without src: %dms per iteration', ms);