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

log rotation support; v0.17.0; improve README docs

Browse source
This commit is contained in:
Trent Mick 2013-01-04 14:30:27 -08:00
parent 4145e63a6f
commit 480ee5d1e0
6 changed files with 713 additions and 191 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

16
CHANGES.md
View file

@ -6,7 +6,21 @@ Known issues:
bug](https://github.com/TooTallNate/node-gyp/issues/65). bug](https://github.com/TooTallNate/node-gyp/issues/65).
## bunyan 0.16.9 (not yet released) ## bunyan 0.17.0 (not yet released)
- Log rotation support:
var bunyan = require('bunyan');
var log = bunyan.createLogger({
name: 'myapp',
streams: [{
type: 'rotating-file',
path: '/var/log/myapp.log',
count: 7,
period: 'daily'
}]
});
- Tweak to CLI default pretty output: don't special case "latency" field. - Tweak to CLI default pretty output: don't special case "latency" field.
The special casing was perhaps nice, but less self-explanatory. The special casing was perhaps nice, but less self-explanatory.

571
README.md
View file

@ -1,11 +1,17 @@
Bunyan is **a simple and fast a JSON logging library** for node.js services and Bunyan is **a simple and fast JSON logging library** for node.js services:
**a `bunyan` CLI tool** for nicely viewing those logs).
var bunyan = require('bunyan');
var log = bunyan.createLogger({name: "myapp"});
log.info("hi");
and **a `bunyan` CLI tool** for nicely viewing those logs:
![bunyan CLI screenshot](https://raw.github.com/trentm/node-bunyan/master/tools/screenshot1.png) ![bunyan CLI screenshot](https://raw.github.com/trentm/node-bunyan/master/tools/screenshot1.png)
Server logs should be structured. JSON's a good format. Let's do that: a log Manifesto: Server logs should be structured. JSON's a good format. Let's do
record is one line of `JSON.stringify`'d output. Let's also specify some common that. A log record is one line of `JSON.stringify`'d output. Let's also
names for the requisite and common fields for a log record (see below). specify some common names for the requisite and common fields for a log
record (see below).
Also: log4j is way more than you need. Also: log4j is way more than you need.
@ -13,139 +19,207 @@ Also: log4j is way more than you need.
# Current Status # Current Status
Solid core functionality is there. Joyent is using this for a number of Solid core functionality is there. Joyent is using this for a number of
production services. Bunyan supports node 0.6 and greater. production services. Bunyan supports node 0.6 and greater. Follow
<a href="https://twitter.com/intent/user?screen_name=trentmick" target="_blank">@trentmick</a>
Follow <a href="https://twitter.com/intent/user?screen_name=trentmick" target="_blank">@trentmick</a>
for updates to Bunyan. for updates to Bunyan.
See also: [Bunyan for Bash](https://github.com/trevoro/bash-bunyan).
# Installation # Installation
npm install bunyan npm install bunyan
**Tip**: The `bunyan` CLI tool is written to be compatible (within reason) with
all versions of Bunyan logs. Therefore you might want to `npm install -g bunyan`
to get the bunyan CLI on your PATH, then use local bunyan installs for
node.js library usage of bunyan in your apps.
# Usage
**The usual.** All loggers must provide a "name". This is somewhat akin # Features
to log4j logger "name", but Bunyan doesn't do hierarchical logger names.
- elegant [log method API](#log-method-api)
- extensible [streams](#streams) system for controlling where log records
go (to a stream, to a file, [log file rotation](#stream-type-rotating-file),
etc.)
- [`bunyan` CLI](#cli-usage) for pretty-printing and filtering of Bunyan logs
- simple include of log call source location (file, line, function) with
[`src: true`](#src)
- light-weight specialization of Logger instances with [`log.child`](#logchild)
- custom rendering of logged objects with ["serializers"](#serializers)
- [Dtrace support](#dtrace-support)
# Introduction
Like most logging libraries you create a Logger instance and call methods
named after the logging levels:
$ cat hi.js $ cat hi.js
var Logger = require('bunyan');
var log = new Logger({name: "myapp"});
log.info("hi");
Alternatively, bunyan 0.7.0 and up supports a more node.js-land typical
style (which might become the preferred form over time):
var bunyan = require('bunyan'); var bunyan = require('bunyan');
var log = bunyan.createLogger({name: "myapp"}); var log = bunyan.createLogger({name: 'myapp'});
log.info('hi');
log.warn({lang: 'fr'}, 'au revoir');
**Log records are JSON.** "hostname", "time" and "v" (the Bunyan log All loggers must provide a "name". This is somewhat akin to the log4j logger
format version) are added for you. "name", but Bunyan doesn't do hierarchical logger names.
**Bunyan log records are JSON.** A few fields are added automatically:
"pid", "hostname", "time" and "v".
$ node hi.js $ node hi.js
{"name":"myapp","hostname":"banana.local","pid":123,"level":2,"msg":"hi","time":"2012-01-31T00:07:44.216Z","v":0} {"name":"myapp","hostname":"banana.local","pid":40161,"level":30,"msg":"hi","time":"2013-01-04T18:46:23.851Z","v":0}
{"name":"myapp","hostname":"banana.local","pid":40161,"level":40,"lang":"fr","msg":"au revoir","time":"2013-01-04T18:46:23.853Z","v":0}
The full `log.{trace|debug|...|fatal}(...)` API is:
## Log Method API
The example above shows two different ways to call `log.info(...)`. The
full API is:
log.info(); // Returns a boolean: is the "info" level enabled? log.info(); // Returns a boolean: is the "info" level enabled?
// This is equivalent to `log.isInfoEnabled()` or
// `log.isEnabledFor(INFO)` in log4j.
log.info('hi'); // Log a simple string message. log.info('hi'); // Log a simple string message.
log.info('hi %s', bob, anotherVar); // Uses `util.format` for msg formatting. log.info('hi %s', bob, anotherVar); // Uses `util.format` for msg formatting.
log.info({foo: 'bar'}, 'hi'); // Adds "foo" field to log record. log.info({foo: 'bar'}, 'hi');
// Adds "foo" field to log record. You can add any number
// of additional fields here.
log.info(err); // Special case to log an `Error` instance, adds "err" log.info(err); // Special case to log an `Error` instance to the record.
// key with exception details (including the stack) and // This adds an "err" field with exception details
// sets "msg" to the exception message. // (including the stack) and sets "msg" to the exception
// message.
log.info(err, 'more on this: %s', more); log.info(err, 'more on this: %s', more);
// ... or you can specify the "msg". // ... or you can specify the "msg".
Note that this implies **you cannot pass any object as the first argument Note that this implies **you cannot pass any object as the first argument
to log it**. IOW, `log.info(myobject)` isn't going to work the way you to log it**. IOW, `log.info(mywidget)` may not be what you expect. Instead
expect. Adding support for this API would necessitate (a) JSON-ifying safely of a string representation of `mywidget` that other logging libraries may
that given object (sometimes hard, and probably slow) and (b) putting all its give you, Bunyan will try to JSON-ify your object. It is a Bunyan best
attribs under a top-level 'x' field name or something to avoid field name practice to always give a field name to included objects, e.g.:
collisions.
log.info({widget: mywidget}, ...)
This will dove-tail with [Bunyan serializer support](#serializers), discussed
later.
The same goes for all of Bunyan's log levels: `log.trace`, `log.debug`,
`log.info`, `log.warn`, and `log.fatal`. See the [levels section](#levels)
below for details and suggestions.
## bunyan tool ## CLI Usage
A `bunyan` tool is provided **for pretty-printing bunyan logs** and for Bunyan log output is a stream of JSON objects. This is great for processing,
**filtering** (e.g. `| bunyan -c 'this.foo == "bar"'`). This shows the default but not for reading directly. A **`bunyan` tool** is provided **for
output and indented-JSON output. More output formats will be added, including pretty-printing bunyan logs** and for **filtering** (e.g.
support for custom formats. `| bunyan -c 'this.foo == "bar"'`). Using our example above:
$ node hi.js | ./bin/bunyan # CLI tool to filter/pretty-print JSON logs. $ node hi.js | ./bin/bunyan
[2012-01-31T00:08:11.387Z] INFO: myapp on banana.local/123: hi [2013-01-04T19:01:18.241Z] INFO: myapp/40208 on banana.local: hi
[2013-01-04T19:01:18.242Z] WARN: myapp/40208 on banana.local: au revoir (lang=fr)
$ node hi.js | ./bin/bunyan -o json See the screenshot above for an example of the default coloring of rendered
{ log output. That example also shows the nice formatting automatically done for
"name": "myapp", some well-known log record fields (e.g. `req` is formatted like an HTTP request,
"hostname": "banana.local", `res` like an HTTP response, `err` like an error stack trace).
"pid": 123,
"level": 2, One interesting feature is **filtering** of log content, which can be useful
"msg": "hi", for digging through large log files or for analysis. We can filter only
"time": "2012-01-31T00:10:00.676Z", records above a certain level:
"v": 0
} $ node hi.js | bunyan -l warn
[2013-01-04T19:08:37.182Z] WARN: myapp/40353 on banana.local: au revoir (lang=fr)
Or filter on the JSON fields in the records (e.g. only showing the French
records in our contrived example):
$ node hi.js | bunyan -c 'this.lang == "fr"'
[2013-01-04T19:08:26.411Z] WARN: myapp/40342 on banana.local: au revoir (lang=fr)
See `bunyan --help` for other facilities.
## streams ## Streams Introduction
By default, log output is to stdout (**stream**) and at the "info" level. By default, log output is to stdout and at the "info" level. Explicitly that
Explicitly that looks like: looks like:
var log = new Logger({name: "myapp", stream: process.stdout, var log = bunyan.createLogger({
level: "info"}); name: 'myapp',
stream: process.stdout,
level: 'info'
});
That is an abbreviated form for a single stream. **You can define multiple That is an abbreviated form for a single stream. **You can define multiple
streams at different levels**. streams at different levels**.
var log = new Logger({ var log = bunyan.createLogger({
name: "amon", name: 'myapp',
streams: [ streams: [
{ {
level: "info", level: 'info',
stream: process.stdout, // log INFO and above to stdout stream: process.stdout, // log INFO and above to stdout
}, },
{ {
level: "error", level: 'error',
path: "tmp/error.log" // log ERROR and above to a file path: '/var/log/myapp-error.log' // log ERROR and above to a file
} }
] ]
}); });
More on streams in the "Streams" section below. More on streams in the [Streams section](#streams) below.
## log.child ## log.child
A `log.child(...)` is provided to **specialize a logger for a sub-component**. Bunyan has a concept of a child logger to **specialize a logger for a
The following will have log records from "Wuzzle" instances use exactly the sub-component of your application**, i.e. to create a new logger with
same config as its parent, plus include the "component" field. additional bound fields that will be included in its log records. A child
logger is created with `log.child(...)`.
var log = new Logger(...); In the following example, logging on a "Wuzzle" instance's `this.log` will
be exactly as on the parent logger with the addition of the `widget_type`
field:
... var bunyan = require('bunyan');
var log = bunyan.createLogger({name: 'myapp'});
function Wuzzle(options) { function Wuzzle(options) {
this.log = options.log; this.log = options.log.child({widget_type: 'wuzzle'});
this.log.info("creating a wuzzle") this.log.info('creating a wuzzle')
} }
Wuzzle.prototype.woos = function () { Wuzzle.prototype.woos = function () {
this.log.warn("This wuzzle is woosey.") this.log.warn('This wuzzle is woosey.')
} }
var wuzzle = new Wuzzle({log: log.child({component: "wuzzle"})}); log.info('start');
var wuzzle = new Wuzzle({log: log});
wuzzle.woos(); wuzzle.woos();
log.info("done with the wuzzle") log.info('done');
The [node-restify](https://github.com/mcavage/node-restify) Running that looks like (raw):
framework integrates bunyan. One feature of its integration, is that each
restify request handler includes a `req.log` logger that is: $ node myapp.js
{"name":"myapp","hostname":"myhost","pid":34572,"level":30,"msg":"start","time":"2013-01-04T07:47:25.814Z","v":0}
{"name":"myapp","hostname":"myhost","pid":34572,"widget_type":"wuzzle","level":30,"msg":"creating a wuzzle","time":"2013-01-04T07:47:25.815Z","v":0}
{"name":"myapp","hostname":"myhost","pid":34572,"widget_type":"wuzzle","level":40,"msg":"This wuzzle is woosey.","time":"2013-01-04T07:47:25.815Z","v":0}
{"name":"myapp","hostname":"myhost","pid":34572,"level":30,"msg":"done","time":"2013-01-04T07:47:25.816Z","v":0}
And with the `bunyan` CLI (using the "short" output mode):
$ node myapp.js | bunyan -o short
07:46:42.707Z INFO myapp: start
07:46:42.709Z INFO myapp: creating a wuzzle (widget_type=wuzzle)
07:46:42.709Z WARN myapp: This wuzzle is woosey. (widget_type=wuzzle)
07:46:42.709Z INFO myapp: done
A more practical example is in the
[node-restify](https://github.com/mcavage/node-restify) web framework.
Restify uses Bunyan for its logging. One feature of its integration, is that
each restify request handler includes a `req.log` logger that is:
log.child({req_id: <unique request id>}, true) log.child({req_id: <unique request id>}, true)
@ -153,55 +227,56 @@ Apps using restify can then use `req.log` and have all such log records
include the unique request id (as "req_id"). Handy. include the unique request id (as "req_id"). Handy.
## serializers ## Serializers
Bunyan has a concept of **"serializers" to produce a JSON-able object from a Bunyan has a concept of **"serializers" to produce a JSON-able object from a
JavaScript object**, so you can easily do the following: JavaScript object**, so you can easily do the following:
log.info({req: <request object>}, "something about handling this request"); log.info({req: <request object>}, 'something about handling this request');
Association is by log record field name, "req" in this example, so this Serializers is a mapping of log record field name, "req" in this example, to
requires a registered serializer something like this: a serializer function. That looks like this:
function reqSerializer(req) { function reqSerializer(req) {
return { return {
method: req.method, method: req.method,
url: req.url, url: req.url,
headers: req.headers headers: req.headers
} }
} }
var log = new Logger({ var log = bunyan.createLogger({
... name: 'myapp',
serializers: { serializers: {
req: reqSerializer req: reqSerializer
} }
}); });
Or this: Or this:
var log = new Logger({ var log = bunyan.createLogger({
... name: 'myapp',
serializers: {req: Logger.stdSerializers.req} serializers: {req: bunyan.stdSerializers.req}
}); });
because Buyan includes a small set of standard serializers. To use all the because Buyan includes a small set of standard serializers. To use all the
standard serializers you can use: standard serializers you can use:
var log = new Logger({ var log = bunyan.createLogger({
... ...
serializers: Logger.stdSerializers serializers: bunyan.stdSerializers
}); });
*Note: Your own serializers should never throw, otherwise you'll get an **Note**: Your own serializers should never throw, otherwise you'll get an
ugly message on stderr from Bunyan (along with the traceback) and the field 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.* in your log record will be replaced with a short error message.
## src ## src
The **source file, line and function of the log call site** can be added to The **source file, line and function of the log call site** can be added to
log records by using the `src: true` config option: log records by using the `src: true` config option:
var log = new Logger({src: true, ...}); var log = bunyan.createLogger({src: true, ...});
This adds the call source info with the 'src' field, like this: This adds the call source info with the 'src' field, like this:
@ -248,7 +323,7 @@ on spewing mostly irrelevant debug messages all the time and sifting through
them when an error occurs. them when an error occurs.
Integers are used for the actual level values (10 for "trace", ..., 60 for Integers are used for the actual level values (10 for "trace", ..., 60 for
"fatal") and constants are defined for the (Logger.TRACE ... Logger.DEBUG). "fatal") and constants are defined for the (bunyan.TRACE ... bunyan.DEBUG).
The lowercase level names are aliases supported in the API. The lowercase level names are aliases supported in the API.
Here is the API for changing levels in an existing logger: Here is the API for changing levels in an existing logger:
@ -339,14 +414,14 @@ Core fields:
Logger. Never use in production as this is really slow. Logger. Never use in production as this is really slow.
Go ahead and add more fields, and nest ones are fine (and recommended) as Go ahead and add more fields, and nested ones are fine (and recommended) as
well. This is why we're using JSON. Some suggestions and best practices well. This is why we're using JSON. Some suggestions and best practices
follow (feedback from actual users welcome). follow (feedback from actual users welcome).
Recommended/Best Practice Fields: Recommended/Best Practice Fields:
- `err`: Object. A caught JS exception. Log that thing with `log.info(err)` - `err`: Object. A caught JS exception. Log that thing with `log.info(err)`
to get: to get:
... ...
@ -358,7 +433,7 @@ Recommended/Best Practice Fields:
"msg": "boom", "msg": "boom",
... ...
Or use the `Logger.stdSerializers.err` serializer in your Logger and Or use the `bunyan.stdSerializers.err` serializer in your Logger and
do this `log.error({err: err}, "oops")`. See "examples/err.js". do this `log.error({err: err}, "oops")`. See "examples/err.js".
- `req_id`: String. A request identifier. Including this field in all logging - `req_id`: String. A request identifier. Including this field in all logging
@ -369,7 +444,7 @@ Recommended/Best Practice Fields:
(as [node-restify](https://github.com/mcavage/node-restify) facilitates (as [node-restify](https://github.com/mcavage/node-restify) facilitates
with its 'X-Request-Id' header). with its 'X-Request-Id' header).
- `req`: An HTTP server request. Bunyan provides `Logger.stdSerializers.req` - `req`: An HTTP server request. Bunyan provides `bunyan.stdSerializers.req`
to serialize a request with a suggested set of keys. Example: to serialize a request with a suggested set of keys. Example:
{ {
@ -383,7 +458,7 @@ Recommended/Best Practice Fields:
"remotePort": 51244 "remotePort": 51244
} }
- `res`: An HTTP server response. Bunyan provides `Logger.stdSerializers.res` - `res`: An HTTP server response. Bunyan provides `bunyan.stdSerializers.res`
to serialize a response with a suggested set of keys. Example: to serialize a response with a suggested set of keys. Example:
{ {
@ -411,63 +486,234 @@ interface, but there are some additional attributes used to create and
manage the stream. A Bunyan Logger instance has one or more streams. manage the stream. A Bunyan Logger instance has one or more streams.
In general streams are specified with the "streams" option: In general streams are specified with the "streams" option:
var Logger = require('bunyan'); var bunyan = require('bunyan');
var log = new Logger({ var log = bunyan.createLogger({
name: "foo", name: "foo",
streams: [ streams: [
{ {
stream: process.stderr, stream: process.stderr,
level: "debug" level: "debug"
}, },
... ...
] ]
}) });
For convenience, if there is only one stream, it can specified with the For convenience, if there is only one stream, it can specified with the
"stream" and "level" options (internal converted to a `Logger.streams`): "stream" and "level" options (internally converted to a `Logger.streams`).
var log = new Logger({ var log = bunyan.createLogger({
name: "foo", name: "foo",
stream: process.stderr, stream: process.stderr,
level: "debug" level: "debug"
}) });
If none are specified, the default is a stream on `process.stdout` at the Note that "file" streams do not support this shortcut (partly for historical
"info" level. reasons and partly to not make it difficult to add a literal "path" field
on log records).
`Logger.streams` is an array of stream objects with the following attributes: If neither "streams" nor "stream" are specified, the default is a stream of
type "stream" emitting to `process.stdout` at the "info" level.
- `type`: One of "stream", "file" or "raw". See below. Often this is
implied from the other arguments.
- `path`: A file path for a file stream. If `path` is given and `type` is
not specified, then `type` will be set to "file".
- `stream`: This is the "Writable Stream", e.g. a std handle or an open
file write stream. If `stream` is given and `type` is not specified, then
`type` will be set to "stream".
- `level`: The level at which logging to this stream is enabled. If not
specified it defaults to INFO.
Supported stream types are: ## stream errors
- `stream`: A plain ol' node.js [Writable Bunyan re-emits error events from the created `WriteStream`. So you can
Stream](http://nodejs.org/docs/latest/api/all.html#writable_Stream). do this:
A "stream" (the writeable stream) value is required.
- `file`: A "path" argument is given. Bunyan will open this file for var log = bunyan.createLogger({name: 'mylog', streams: [{path: LOG_PATH}]});
appending. E.g.: log.on('error', function (err, stream) {
// Handle stream write or create error here.
});
{
"path": "/var/log/foo.log",
"level": "warn"
}
Bunyan re-emits error events from the created `WriteStream`. So you can ## stream type: `stream`
do this:
var log = new Logger({name: 'mylog', streams: [{path: LOG_PATH}]}); A `type === 'stream'` is a plain ol' node.js [Writable
log.on('error', function (err, stream) { Stream](http://nodejs.org/docs/latest/api/all.html#writable_Stream). A
// Handle stream write or create error here. "stream" (the writeable stream) field is required. E.g.: `process.stdout`,
}); `process.stderr`.
var log = bunyan.createLogger({
name: 'foo',
streams: [{
stream: process.stderr
// `type: 'stream'` is implied
}]
});
<table>
<tr>
<th>Field</th>
<th>Required?</th>
<th>Default</th>
<th>Description</th>
</tr>
<tr>
<td>stream</td>
<td>Yes</td>
<td>-</td>
<td>A "Writable Stream", e.g. a std handle or an open file write stream.</td>
</tr>
<tr>
<td>type</td>
<td>No</td>
<td>n/a</td>
<td>`type == 'stream'` is implied if the `stream` field is given.</td>
</tr>
<tr>
<td>level</td>
<td>No</td>
<td>info</td>
<td>The level at which logging to this stream is enabled. If not
specified it defaults to "info". If specified this can be one of the
level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
`bunyan.DEBUG`, ...).</td>
</tr>
<tr>
<td>name</td>
<td>No</td>
<td>-</td>
<td>A name for this stream. This may be useful for usage of `log.level(NAME,
LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
used for anything else.</td>
</tr>
</table>
## stream type: `file`
A `type === 'file'` stream requires a "path" field. Bunyan will open this
file for appending. E.g.:
var log = bunyan.createLogger({
name: 'foo',
streams: [{
path: '/var/log/foo.log',
// `type: 'file'` is implied
}]
});
<table>
<tr>
<th>Field</th>
<th>Required?</th>
<th>Default</th>
<th>Description</th>
</tr>
<tr>
<td>path</td>
<td>Yes</td>
<td>-</td>
<td>A file path to which to log.</td>
</tr>
<tr>
<td>type</td>
<td>No</td>
<td>n/a</td>
<td>`type == 'file'` is implied if the `path` field is given.</td>
</tr>
<tr>
<td>level</td>
<td>No</td>
<td>info</td>
<td>The level at which logging to this stream is enabled. If not
specified it defaults to "info". If specified this can be one of the
level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
`bunyan.DEBUG`, ...).</td>
</tr>
<tr>
<td>name</td>
<td>No</td>
<td>-</td>
<td>A name for this stream. This may be useful for usage of `log.level(NAME,
LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
used for anything else.</td>
</tr>
</table>
## stream type: `rotating-file`
A `type === 'rotating-file'` is a file stream that handles file automatic
rotation.
var log = bunyan.createLogger({
name: 'foo',
streams: [{
type: 'rotating-file',
path: '/var/log/foo.log',
period: '1d', // daily rotation
count: 3 // keep 3 back copies
}]
});
This will rotate '/var/log/foo.log' every day (at midnight) to:
/var/log/foo.log.0 # yesterday
/var/log/foo.log.1 # 1 day ago
/var/log/foo.log.2 # 2 days ago
*Currently*, there is no support for providing a template for the rotated
files, or for rotating when the log reaches a threshold size.
<table>
<tr>
<th>Field</th>
<th>Required?</th>
<th>Default</th>
<th>Description</th>
</tr>
<tr>
<td>type</td>
<td>Yes</td>
<td>-</td>
<td>"rotating-file"</td>
</tr>
<tr>
<td>path</td>
<td>Yes</td>
<td>-</td>
<td>A file path to which to log. Rotated files will be "$path.0",
"$path.1", ...</td>
</tr>
<tr>
<td>period</td>
<td>No</td>
<td>1d</td>
<td>The period at which to rotate. This is a string of the format
"$number$scope" where "$scope" is one of "h" (hours), "d" (days), "w" (weeks),
"m" (months), "y" (years). Or one of the following names can be used
"hourly" (means 1h), "daily" (1d), "weekly" (1w), "monthly" (1m),
"yearly" (1y). Rotation is done at the "start"</td>
</tr>
<tr>
<td>count</td>
<td>No</td>
<td>10</td>
<td>The number of rotated files to keep.</td>
</tr>
<tr>
<td>level</td>
<td>No</td>
<td>info</td>
<td>The level at which logging to this stream is enabled. If not
specified it defaults to "info". If specified this can be one of the
level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
`bunyan.DEBUG`, ...).</td>
</tr>
<tr>
<td>name</td>
<td>No</td>
<td>-</td>
<td>A name for this stream. This may be useful for usage of `log.level(NAME,
LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
used for anything else.</td>
</tr>
</table>
## stream type: `raw`
- `raw`: Similar to a "stream" writeable stream, except that the write method - `raw`: Similar to a "stream" writeable stream, except that the write method
is given raw log record *Object*s instead of a JSON-stringified string. is given raw log record *Object*s instead of a JSON-stringified string.
@ -475,7 +721,8 @@ Supported stream types are:
pushing to an external service, a RingBuffer (see below), etc. pushing to an external service, a RingBuffer (see below), etc.
## RingBuffer Stream
## `raw` + RingBuffer Stream
Bunyan comes with a special stream called a RingBuffer which keeps the last N Bunyan comes with a special stream called a RingBuffer which keeps the last N
records in memory and does *not* write the data anywhere else. One common records in memory and does *not* write the data anywhere else. One common
@ -488,7 +735,7 @@ To use a RingBuffer:
/* Create a ring buffer that stores the last 100 records. */ /* Create a ring buffer that stores the last 100 records. */
var bunyan = require('bunyan'); var bunyan = require('bunyan');
var ringbuffer = new bunyan.RingBuffer({ limit: 100 }); var ringbuffer = new bunyan.RingBuffer({ limit: 100 });
var log = new bunyan({ var log = bunyan.createLogger({
name: 'foo', name: 'foo',
streams: [ streams: [
{ {
@ -517,6 +764,16 @@ This example emits:
v: 0 } ] v: 0 } ]
## third-party streams
- syslog:
[mcavage/node-bunyan-syslog](https://github.com/mcavage/node-bunyan-syslog)
provides support for directing bunyan logging to a syslog server.
- TODO: eventually https://github.com/trentm/node-bunyan-winston
# DTrace support # DTrace support
On systems that support DTrace (e.g., MacOS, FreeBSD, illumos derivatives On systems that support DTrace (e.g., MacOS, FreeBSD, illumos derivatives
@ -535,6 +792,7 @@ 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.
## DTrace examples ## DTrace examples
Trace all log messages coming from any Bunyan module on the system. Trace all log messages coming from any Bunyan module on the system.
@ -634,10 +892,13 @@ change, and bug fixes, respectively.
# License # License
MIT. MIT. See "LICENSE.txt".
# See Also
# Future - Bunyan syslog support: <https://github.com/mcavage/node-bunyan-syslog>.
- An example of a Bunyan shim to the Winston logging system:
See "TODO.md". <https://github.com/trentm/node-bunyan-winston>.
- [Bunyan for Bash](https://github.com/trevoro/bash-bunyan).
- TODO: `RequestCaptureStream` example from restify.

44
TODO.md
View file

@ -1,9 +1,16 @@
- man page for the bunyan CLI (refer to it in the readme)
- full-on docs. The readme is too clunky now.
- paging
- `tail -f`-like support
- 1.0 with `v: 1` in log records. Fwd/bwd compat in `bunyan` CLI
# someday/maybe
- "template" support for 'rotating-file' stream to get dated rolled files
- "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.
- move custom keys out to 'x' ? What about req, res? Compat issues there?
Bunyan CLI would have to deal with both for a while. Just a change in
record.v from 0 to 1.
- buffered writes to increase speed: - buffered writes to increase speed:
- I'd start with a tools/timeoutput.js for some numbers to compare - I'd start with a tools/timeoutput.js for some numbers to compare
before/after. Sustained high output to a file. before/after. Sustained high output to a file.
@ -19,8 +26,6 @@
clones. clones.
- test that a `log.clone(...)` adding a new field matching a serializer - test that a `log.clone(...)` adding a new field matching a serializer
works *and* that an existing field in the parent is not *re-serialized*. 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)
- split out `bunyan` cli to a "bunyan" or "bunyan-reader" or "node-bunyan-reader" - split out `bunyan` cli to a "bunyan" or "bunyan-reader" or "node-bunyan-reader"
as the basis for tools to consume bunyan logs. It can grow indep of node-bunyan as the basis for tools to consume bunyan logs. It can grow indep of node-bunyan
for generating the logs. for generating the logs.
@ -32,47 +37,22 @@
- document "well-known" keys from bunyan CLI p.o.v.. Add "client_req". - document "well-known" keys from bunyan CLI p.o.v.. Add "client_req".
- bunyan tool: built in less usage (a la git?) so that I don't have to - bunyan tool: built in less usage (a la git?) so that I don't have to
go through this: `bunyan --color master.log | less -R` go through this: `bunyan --color master.log | less -R`
- want `bunyan -f foo.log` a la `tail -f`
# someday/maybe
- More `bunyan` output formats and filtering features. - More `bunyan` output formats and filtering features.
- 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.
- doc the restify RequestCaptureStream usage of RingBuffer. Great example. - 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.
- remove "rm -rf tmp" when this fixed: <https://github.com/isaacs/npm/issues/2144>
- what about promoting 'latency' field and making that easier? - what about promoting 'latency' field and making that easier?
- `log.close` to close streams and shutdown and `this.closed` - `log.close` to close streams and shutdown and `this.closed`
process.on('exit', log.close) process.on('exit', log.close)
- bunyan cli: -c COND args a la json -> 'end' for the name
- bunyan cli: more layouts (http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/EnhancedPatternLayout.html) - 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 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 or whatever. Dap wants field width control for lining up. Hogan.js is
probably overkill for this. probably overkill for this.
- syslog: Josh uses https://github.com/chrisdew/node-syslog - loggly example using raw streams, hook.io?, whatever.
streams: [
...
{
level: "warn",
type: "syslog",
syslog_facility: "LOG_LOCAL1", // one of the syslog facility defines
syslog_pid: true, // syslog logopt "LOG_PID"
syslog_cons: false // syslog logopt "LOG_CONS"
}
- 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.
- 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.
It would be a good hook for people with custom needs that Bunyan doesn't
care about (e.g. http://loggly.com/ or hook.io or whatever).
- serializer `req_id` that pulls it from req? `log.info({req_id: req}, "hi")`
- serializer support: - serializer support:
- restify-server.js example -> restifyReq ? or have `req` detect that. - restify-server.js example -> restifyReq ? or have `req` detect that.
That is nicer for the "use all standard ones". *Does* restify req That is nicer for the "use all standard ones". *Does* restify req

2
bin/bunyan
View file

@ -5,7 +5,7 @@
// See <https://github.com/trentm/node-bunyan>. // See <https://github.com/trentm/node-bunyan>.
// //
var VERSION = "0.16.9"; var VERSION = "0.17.0";
var util = require('util'); var util = require('util');
var pathlib = require('path'); var pathlib = require('path');

265
lib/bunyan.js
View file

@ -4,7 +4,7 @@
* The bunyan logging library for node.js. * The bunyan logging library for node.js.
*/ */
var VERSION = '0.16.9'; var VERSION = '0.17.0';
// Bunyan log format version. This becomes the 'v' field on all log records. // 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, // `0` is until I release a version '1.0.0' of node-bunyan. Thereafter,
@ -32,6 +32,13 @@ try {
} }
var EventEmitter = require('events').EventEmitter; var EventEmitter = require('events').EventEmitter;
// The 'mv' module is required for rotating-file stream support.
try {
var mv = require('mv');
} catch (e) {
mv = null;
}
//---- Internal support stuff //---- Internal support stuff
@ -371,6 +378,16 @@ function Logger(options, _childOptions, _childSimple) {
} }
} }
break; break;
case 'rotating-file':
assert.ok(!s.stream, '"rotating-file" stream should not give a "stream"');
assert.ok(s.path);
assert.ok(mv,
'"rotating-file" stream type is not supported: missing "mv" module');
s.stream = new RotatingFileStream(s);
if (!s.closeOnExit) {
s.closeOnExit = true;
}
break;
case 'raw': case 'raw':
if (!s.closeOnExit) { if (!s.closeOnExit) {
s.closeOnExit = false; s.closeOnExit = false;
@ -901,6 +918,252 @@ function safeCycles() {
}; };
} }
/**
* XXX
*/
if (mv) {
function RotatingFileStream(options) {
assert.ok(options.period, 'need a period');
this.path = options.path;
this.stream = fs.createWriteStream(this.path,
{flags: 'a', encoding: 'utf8'});
this.count = (options.count == null ? 10 : options.count);
assert.ok(typeof(this.count) === 'number' && this.count >= 0);
// Parse `options.period`.
if (options.period) {
// <number><scope> where scope is:
// h hours (at the start of the hour)
// d days (at the start of the day, i.e. just after midnight)
// w weeks (at the start of Sunday)
// m months (on the first of the month)
// y years (at the start of Jan 1st)
// with special values "hourly" (1h), "daily" (1d), "weekly" (1w),
// "monthly" (1m) and "yearly" (1y)
var period = {
'hourly': '1h',
'daily': '1d',
'weekly': '1w',
'monthly': '1m',
'yearly': '1y'
}[options.period] || options.period;
var m = /^([1-9][0-9]*)([hdwmy]|ms)$/.exec(period);
if (!m) {
throw new Error(format('invalid period: "%s"', options.period));
}
this.periodNum = Number(m[1]);
this.periodScope = m[2];
} else {
this.periodNum = 1;
this.periodScope = 'd';
}
// TODO: template support for backup files
// template: <path to which to rotate>
// default is %P.%n
// '/var/log/archive/foo.log' -> foo.log.%n
// '/var/log/archive/foo.log.%n'
// codes:
// XXX support strftime codes (per node version of those)
// or whatever module. Pick non-colliding for extra
// codes
// %P `path` base value
// %n integer number of rotated log (1,2,3,...)
// %d datetime in YYYY-MM-DD_HH-MM-SS
// XXX what should default date format be?
// prior art? Want to avoid ':' in
// filenames (illegal on Windows for one).
this.rotQueue = [];
this.rotating = false;
this._setupNextRot();
}
util.inherits(RotatingFileStream, EventEmitter);
RotatingFileStream.prototype._setupNextRot = function () {
var self = this;
this.rotAt = this._nextRotTime();
this.timeout = setTimeout(
function () { self.rotate(); },
this.rotAt - Date.now());
}
RotatingFileStream.prototype._nextRotTime = function _nextRotTime(first) {
var DEBUG = true;
if (DEBUG) console.log('-- _nextRotTime: %s%s', this.periodNum, this.periodScope);
var d = new Date();
if (DEBUG) console.log(' now local: %s', d);
if (DEBUG) console.log(' now utc: %s', d.toISOString());
var rotAt;
switch (this.periodScope) {
case 'ms':
// Hidden millisecond period for debugging.
if (this.rotAt) {
rotAt = this.rotAt + this.periodNum;
} else {
rotAt = Date.now() + this.periodNum;
}
break;
case 'h':
if (this.rotAt) {
rotAt = this.rotAt + this.periodNum * 60 * 60 * 1000;
} else {
// First time: top of the next hour.
rotAt = Date.UTC(d.getUTCFullYear(), d.getUTCMonth(), d.getUTCDate(),
d.getUTCHours() + 1);
}
break;
case 'd':
if (this.rotAt) {
rotAt = this.rotAt + this.periodNum * 24 * 60 * 60 * 1000;
} else {
// First time: start of tomorrow (i.e. at the coming midnight) UTC.
rotAt = Date.UTC(d.getUTCFullYear(), d.getUTCMonth(), d.getUTCDate() + 1);
}
break;
case 'w':
// Currently, always on Sunday morning at 00:00:00 (UTC).
if (this.rotAt) {
rotAt = this.rotAt + this.periodNum * 7 * 24 * 60 * 60 * 1000;
} else {
// First time: this coming Sunday.
rotAt = Date.UTC(d.getUTCFullYear(), d.getUTCMonth(),
d.getUTCDate() + (7 - d.getUTCDay()));
}
break;
case 'm':
if (this.rotAt) {
rotAt = Date.UTC(d.getUTCFullYear(), d.getUTCMonth() + this.periodNum, 1);
} else {
// First time: the start of the next month.
rotAt = Date.UTC(d.getUTCFullYear(), d.getUTCMonth() + 1, 1);
}
break;
case 'y':
if (this.rotAt) {
rotAt = Date.UTC(d.getUTCFullYear() + this.periodNum, 0, 1);
} else {
// First time: the start of the next year.
rotAt = Date.UTC(d.getUTCFullYear() + 1, 0, 1);
}
break;
default:
assert.fail(format('invalid period scope: "%s"', this.periodScope));
}
if (DEBUG) {
console.log(' **rotAt**: %s (utc: %s)', rotAt,
new Date(rotAt).toUTCString());
var now = Date.now();
console.log(' now: %s (%sms == %smin == %sh to go)',
now,
rotAt - now,
(rotAt-now)/1000/60,
(rotAt-now)/1000/60/60);
}
return rotAt;
};
RotatingFileStream.prototype.rotate = function rotate() {
// XXX What about shutdown?
var self = this;
var DEBUG = true;
if (DEBUG) console.log('-- [%s] rotating %s', new Date(), self.path);
if (self.rotating) {
throw new TypeError('cannot start a rotation when already rotating');
}
self.rotating = true;
self.stream.end(); // XXX can do moves sync after this? test at high rate
function del() {
var toDel = self.path + '.' + String(n - 1);
if (n === 0) {
toDel = self.path;
}
n -= 1;
if (DEBUG) console.log('rm %s', toDel);
fs.unlink(toDel, function (delErr) {
//XXX handle err other than not exists
moves();
});
}
function moves() {
if (self.count === 0 || n < 0) {
return finish();
}
var before = self.path;
var after = self.path + '.' + String(n);
if (n > 0) {
before += '.' + String(n - 1);
}
n -= 1;
fs.exists(before, function (exists) {
if (!exists) {
moves();
} else {
if (DEBUG) console.log('mv %s %s', before, after);
mv(before, after, function (mvErr) {
if (mvErr) {
self.emit('error', mvErr);
finish(); // XXX finish here?
} else {
moves();
}
});
}
})
}
function finish() {
if (DEBUG) console.log('open %s', self.path);
self.stream = fs.createWriteStream(self.path,
{flags: 'a', encoding: 'utf8'});
var q = self.rotQueue, len = q.length;
for (var i = 0; i < len; i++) {
self.stream.write(q[i]);
}
self.rotQueue = [];
self.rotating = false;
self.emit('drain');
self._setupNextRot();
}
var n = this.count;
del();
};
RotatingFileStream.prototype.write = function write(s) {
if (this.rotating) {
this.rotQueue.push(s);
return false;
} else {
return this.stream.write(s);
}
};
RotatingFileStream.prototype.end = function end(s) {
this.stream.end();
};
RotatingFileStream.prototype.destroy = function destroy(s) {
this.stream.destroy();
};
RotatingFileStream.prototype.destroySoon = function destroySoon(s) {
this.stream.destroySoon();
};
} /* if (mv) */
/** /**
* RingBuffer is a Writable Stream that just stores the last N records in * RingBuffer is a Writable Stream that just stores the last N records in
* memory. * memory.

6
package.json
View file

@ -1,6 +1,6 @@
{ {
"name": "bunyan", "name": "bunyan",
"version": "0.16.9", "version": "0.17.0",
"description": "a JSON Logger library for node.js services", "description": "a JSON Logger library for node.js services",
"author": "Trent Mick <trentm@gmail.com> (http://trentm.com)", "author": "Trent Mick <trentm@gmail.com> (http://trentm.com)",
"main": "./lib/bunyan.js", "main": "./lib/bunyan.js",
@ -18,6 +18,10 @@
"dependencies": { "dependencies": {
"dtrace-provider": "0.2.4" "dtrace-provider": "0.2.4"
}, },
"// comment": "'mv' required for RotatingFileStream",
"optionalDependencies": {
"mv": "0.0.4"
},
"devDependencies": { "devDependencies": {
"tap": "0.3.3", "tap": "0.3.3",
"ben": "0.0.0", "ben": "0.0.0",