UNPKG

45.7 kBMarkdownView Raw
1[![npm version](https://img.shields.io/npm/v/bunyan.svg?style=flat)](https://www.npmjs.com/package/bunyan)
2[![Build Status](https://travis-ci.org/trentm/node-bunyan.svg?branch=master)](https://travis-ci.org/trentm/node-bunyan)
3
4Bunyan is **a simple and fast JSON logging library** for node.js services:
5
6```js
7var bunyan = require('bunyan');
8var log = bunyan.createLogger({name: "myapp"});
9log.info("hi");
10```
11
12and **a `bunyan` CLI tool** for nicely viewing those logs:
13
14![bunyan CLI screenshot](https://raw.github.com/trentm/node-bunyan/master/tools/screenshot1.png)
15
16Manifesto: Server logs should be structured. JSON's a good format. Let's do
17that. A log record is one line of `JSON.stringify`'d output. Let's also
18specify some common names for the requisite and common fields for a log
19record (see below).
20
21
22## Table of Contents
23
24<!-- toc -->
25
26- [Current Status](#current-status)
27- [Installation](#installation)
28- [Features](#features)
29- [Introduction](#introduction)
30 * [Constructor API](#constructor-api)
31 * [Log Method API](#log-method-api)
32 * [CLI Usage](#cli-usage)
33 * [Streams Introduction](#streams-introduction)
34 * [log.child](#logchild)
35 * [Serializers](#serializers)
36 + [Requirements for serializers functions](#requirements-for-serializers-functions)
37 + [Standard Serializers](#standard-serializers)
38 * [src](#src)
39- [Levels](#levels)
40 * [Level suggestions](#level-suggestions)
41- [Log Record Fields](#log-record-fields)
42 * [Core fields](#core-fields)
43 * [Recommended/Best Practice Fields](#recommendedbest-practice-fields)
44 * [Other fields to consider](#other-fields-to-consider)
45- [Streams](#streams)
46 * [Adding a Stream](#adding-a-stream)
47 * [stream errors](#stream-errors)
48 * [stream type: `stream`](#stream-type-stream)
49 * [stream type: `file`](#stream-type-file)
50 * [stream type: `rotating-file`](#stream-type-rotating-file)
51 * [stream type: `raw`](#stream-type-raw)
52 * [`raw` + RingBuffer Stream](#raw--ringbuffer-stream)
53 * [third-party streams](#third-party-streams)
54- [Runtime log snooping via DTrace](#runtime-log-snooping-via-dtrace)
55 * [DTrace examples](#dtrace-examples)
56- [Runtime environments](#runtime-environments)
57 * [Browserify](#browserify)
58 * [Webpack](#webpack)
59- [Versioning](#versioning)
60- [License](#license)
61- [See Also](#see-also)
62
63<!-- tocstop -->
64
65# Current Status
66
67Solid core functionality is there. Joyent is using this for a number of
68production services. Bunyan supports node 0.10 and greater. Follow
69<a href="https://twitter.com/intent/user?screen_name=trentmick" target="_blank">@trentmick</a>
70for updates to Bunyan.
71
72There is an email discussion list
73[bunyan-logging@googlegroups.com](mailto:bunyan-logging@googlegroups.com),
74also [as a forum in the
75browser](https://groups.google.com/forum/?fromgroups#!forum/bunyan-logging).
76
77
78# Installation
79
80```sh
81npm install bunyan
82```
83
84**Tip**: The `bunyan` CLI tool is written to be compatible (within reason) with
85all versions of Bunyan logs. Therefore you might want to `npm install -g bunyan`
86to get the bunyan CLI on your PATH, then use local bunyan installs for
87node.js library usage of bunyan in your apps.
88
89**Tip**: Installing without optional dependencies can dramatically reduce
90bunyan's install size. **dtrace-provider** is used for dtrace features,
91**mv** is used for RotatingFileStream, and **moment** is used for local time.
92If you don't need these features, consider installing with the
93`--no-optional` flag.
94
95
96# Features
97
98- elegant [log method API](#log-method-api)
99- extensible [streams](#streams) system for controlling where log records
100 go (to a stream, to a file, [log file rotation](#stream-type-rotating-file),
101 etc.)
102- [`bunyan` CLI](#cli-usage) for pretty-printing and filtering of Bunyan logs
103- simple include of log call source location (file, line, function) with
104 [`src: true`](#src)
105- lightweight specialization of Logger instances with [`log.child`](#logchild)
106- custom rendering of logged objects with ["serializers"](#serializers)
107- [Runtime log snooping via DTrace support](#runtime-log-snooping-via-dtrace)
108- Support for a few [runtime environments](#runtime-environments): Node.js,
109 [Browserify](http://browserify.org/), [Webpack](https://webpack.github.io/), [NW.js](http://nwjs.io/).
110
111
112# Introduction
113
114Like most logging libraries you create a Logger instance and call methods
115named after the logging levels:
116
117```js
118// hi.js
119var bunyan = require('bunyan');
120var log = bunyan.createLogger({name: 'myapp'});
121log.info('hi');
122log.warn({lang: 'fr'}, 'au revoir');
123```
124
125All loggers must provide a "name". This is somewhat akin to the log4j logger
126"name", but Bunyan doesn't do hierarchical logger names.
127
128**Bunyan log records are JSON.** A few fields are added automatically:
129"pid", "hostname", "time" and "v".
130
131```sh
132$ node hi.js
133{"name":"myapp","hostname":"banana.local","pid":40161,"level":30,"msg":"hi","time":"2013-01-04T18:46:23.851Z","v":0}
134{"name":"myapp","hostname":"banana.local","pid":40161,"level":40,"lang":"fr","msg":"au revoir","time":"2013-01-04T18:46:23.853Z","v":0}
135```
136
137
138## Constructor API
139
140```js
141var bunyan = require('bunyan');
142var log = bunyan.createLogger({
143 name: <string>, // Required
144 level: <level name or number>, // Optional, see "Levels" section
145 stream: <node.js stream>, // Optional, see "Streams" section
146 streams: [<bunyan streams>, ...], // Optional, see "Streams" section
147 serializers: <serializers mapping>, // Optional, see "Serializers" section
148 src: <boolean>, // Optional, see "src" section
149
150 // Any other fields are added to all log records as is.
151 foo: 'bar',
152 ...
153});
154```
155
156
157## Log Method API
158
159The example above shows two different ways to call `log.info(...)`. The
160full API is:
161
162```js
163log.info(); // Returns a boolean: is the "info" level enabled?
164 // This is equivalent to `log.isInfoEnabled()` or
165 // `log.isEnabledFor(INFO)` in log4j.
166
167log.info('hi'); // Log a simple string message (or number).
168log.info('hi %s', bob, anotherVar); // Uses `util.format` for msg formatting.
169
170log.info({foo: 'bar'}, 'hi');
171 // The first field can optionally be a "fields" object, which
172 // is merged into the log record.
173
174log.info(err); // Special case to log an `Error` instance to the record.
175 // This adds an "err" field with exception details
176 // (including the stack) and sets "msg" to the exception
177 // message.
178log.info(err, 'more on this: %s', more);
179 // ... or you can specify the "msg".
180
181log.info({foo: 'bar', err: err}, 'some msg about this error');
182 // To pass in an Error *and* other fields, use the `err`
183 // field name for the Error instance.
184```
185
186Note that this implies **you cannot blindly pass any object as the first
187argument to log it** because that object might include fields that collide with
188Bunyan's [core record fields](#core-fields). In other words,
189`log.info(mywidget)` may not yield what you expect. Instead of a string
190representation of `mywidget` that other logging libraries may give you, Bunyan
191will try to JSON-ify your object. It is a Bunyan best practice to always give a
192field name to included objects, e.g.:
193
194```js
195log.info({widget: mywidget}, ...)
196```
197
198This will dove-tail with [Bunyan serializer support](#serializers), discussed
199later.
200
201The same goes for all of Bunyan's log levels: `log.trace`, `log.debug`,
202`log.info`, `log.warn`, `log.error`, and `log.fatal`. See the [levels
203section](#levels) below for details and suggestions.
204
205
206## CLI Usage
207
208Bunyan log output is a stream of JSON objects. This is great for processing,
209but not for reading directly. A **`bunyan` tool** is provided **for
210pretty-printing bunyan logs** and for **filtering** (e.g.
211`| bunyan -c 'this.foo == "bar"'`). Using our example above:
212
213```sh
214$ node hi.js | ./node_modules/.bin/bunyan
215[2013-01-04T19:01:18.241Z] INFO: myapp/40208 on banana.local: hi
216[2013-01-04T19:01:18.242Z] WARN: myapp/40208 on banana.local: au revoir (lang=fr)
217```
218
219See the screenshot above for an example of the default coloring of rendered
220log output. That example also shows the nice formatting automatically done for
221some well-known log record fields (e.g. `req` is formatted like an HTTP request,
222`res` like an HTTP response, `err` like an error stack trace).
223
224One interesting feature is **filtering** of log content, which can be useful
225for digging through large log files or for analysis. We can filter only
226records above a certain level:
227
228```sh
229$ node hi.js | bunyan -l warn
230[2013-01-04T19:08:37.182Z] WARN: myapp/40353 on banana.local: au revoir (lang=fr)
231```
232
233Or filter on the JSON fields in the records (e.g. only showing the French
234records in our contrived example):
235
236```sh
237$ node hi.js | bunyan -c 'this.lang == "fr"'
238[2013-01-04T19:08:26.411Z] WARN: myapp/40342 on banana.local: au revoir (lang=fr)
239```
240
241See `bunyan --help` for other facilities.
242
243
244## Streams Introduction
245
246By default, log output is to stdout and at the "info" level. Explicitly that
247looks like:
248
249```js
250var log = bunyan.createLogger({
251 name: 'myapp',
252 stream: process.stdout,
253 level: 'info'
254});
255```
256
257That is an abbreviated form for a single stream. **You can define multiple
258streams at different levels**.
259
260```js
261var log = bunyan.createLogger({
262 name: 'myapp',
263 streams: [
264 {
265 level: 'info',
266 stream: process.stdout // log INFO and above to stdout
267 },
268 {
269 level: 'error',
270 path: '/var/tmp/myapp-error.log' // log ERROR and above to a file
271 }
272 ]
273});
274```
275
276More on streams in the [Streams section](#streams) below.
277
278## log.child
279
280Bunyan has a concept of a child logger to **specialize a logger for a
281sub-component of your application**, i.e. to create a new logger with
282additional bound fields that will be included in its log records. A child
283logger is created with `log.child(...)`.
284
285In the following example, logging on a "Wuzzle" instance's `this.log` will
286be exactly as on the parent logger with the addition of the `widget_type`
287field:
288
289```js
290var bunyan = require('bunyan');
291var log = bunyan.createLogger({name: 'myapp'});
292
293function Wuzzle(options) {
294 this.log = options.log.child({widget_type: 'wuzzle'});
295 this.log.info('creating a wuzzle')
296}
297Wuzzle.prototype.woos = function () {
298 this.log.warn('This wuzzle is woosey.')
299}
300
301log.info('start');
302var wuzzle = new Wuzzle({log: log});
303wuzzle.woos();
304log.info('done');
305```
306
307Running that looks like (raw):
308
309```sh
310$ node myapp.js
311{"name":"myapp","hostname":"myhost","pid":34572,"level":30,"msg":"start","time":"2013-01-04T07:47:25.814Z","v":0}
312{"name":"myapp","hostname":"myhost","pid":34572,"widget_type":"wuzzle","level":30,"msg":"creating a wuzzle","time":"2013-01-04T07:47:25.815Z","v":0}
313{"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}
314{"name":"myapp","hostname":"myhost","pid":34572,"level":30,"msg":"done","time":"2013-01-04T07:47:25.816Z","v":0}
315```
316
317And with the `bunyan` CLI (using the "short" output mode):
318
319```sh
320$ node myapp.js | bunyan -o short
32107:46:42.707Z INFO myapp: start
32207:46:42.709Z INFO myapp: creating a wuzzle (widget_type=wuzzle)
32307:46:42.709Z WARN myapp: This wuzzle is woosey. (widget_type=wuzzle)
32407:46:42.709Z INFO myapp: done
325```
326
327A more practical example is in the
328[node-restify](https://github.com/mcavage/node-restify) web framework.
329Restify uses Bunyan for its logging. One feature of its integration, is that
330if `server.use(restify.requestLogger())` is used, each restify request handler
331includes a `req.log` logger that is:
332
333```js
334log.child({req_id: <unique request id>}, true)
335```
336
337Apps using restify can then use `req.log` and have all such log records
338include the unique request id (as "req\_id"). Handy.
339
340
341## Serializers
342
343Bunyan has a concept of **"serializer" functions to produce a JSON-able object
344from a JavaScript object**, so you can easily do the following:
345
346```js
347log.info({req: <request object>}, 'something about handling this request');
348```
349
350and have the `req` entry in the log record be just a reasonable subset of
351`<request object>` fields (or computed data about those fields).
352
353
354A logger instance can have a `serializers` mapping of log record field name
355("req" in this example) to a serializer function. When creating the log
356record, Bunyan will call the serializer function for fields of that name.
357An example:
358
359```js
360function reqSerializer(req) {
361 return {
362 method: req.method,
363 url: req.url,
364 headers: req.headers
365 };
366}
367var log = bunyan.createLogger({
368 name: 'myapp',
369 serializers: {
370 req: reqSerializer
371 }
372});
373```
374
375
376Typically serializers are added to a logger at creation time via
377`bunyan.createLogger({..., serializers: <serializers>})`. However, serializers
378can be added after creation via `<logger>.addSerializers(...)`, e.g.:
379
380```js
381var log = bunyan.createLogger({name: 'myapp'});
382log.addSerializers({req: reqSerializer});
383```
384
385### Requirements for serializers functions
386
387A serializer function is passed unprotected objects that are passed to the
388`log.info`, `log.debug`, etc. call. This means a poorly written serializer
389function can cause side-effects. Logging shouldn't do that. Here are a few
390rules and best practices for serializer functions:
391
392- A serializer function *should never throw*. The bunyan library *does*
393 protect somewhat from this: if the serializer throws an error, then
394 bunyan will (a) write an ugly message on stderr (along with the traceback),
395 and (b) the field in the log record will be replaced with a short error message.
396 For example:
397
398 ```
399 bunyan: ERROR: Exception thrown from the "foo" Bunyan serializer. This should never happen. This is a bug in that serializer function.
400 TypeError: Cannot read property 'not' of undefined
401 at Object.fooSerializer [as foo] (/Users/trentm/tm/node-bunyan/bar.js:8:26)
402 at /Users/trentm/tm/node-bunyan/lib/bunyan.js:873:50
403 at Array.forEach (native)
404 at Logger._applySerializers (/Users/trentm/tm/node-bunyan/lib/bunyan.js:865:35)
405 at mkRecord (/Users/trentm/tm/node-bunyan/lib/bunyan.js:978:17)
406 at Logger.info (/Users/trentm/tm/node-bunyan/lib/bunyan.js:1044:19)
407 at Object.<anonymous> (/Users/trentm/tm/node-bunyan/bar.js:13:5)
408 at Module._compile (module.js:409:26)
409 at Object.Module._extensions..js (module.js:416:10)
410 at Module.load (module.js:343:32)
411 {"name":"bar","hostname":"danger0.local","pid":47411,"level":30,"foo":"(Error in Bunyan log \"foo\" serializer broke field. See stderr for details.)","msg":"one","time":"2017-03-08T02:53:51.173Z","v":0}
412 ```
413
414- A serializer function *should never mutate the given object*. Doing so will
415 change the object in your application.
416
417- A serializer function *should be defensive*. In my experience, it is common to
418 set a serializer in an app, say for field name "foo", and then accidentally
419 have a log line that passes a "foo" that is undefined, or null, or of some
420 unexpected type. A good start at defensiveness is to start with this:
421
422 ```javascript
423 function fooSerializer(foo) {
424 // Guard against foo be null/undefined. Check that expected fields
425 // are defined.
426 if (!foo || !foo.bar)
427 return foo;
428 var obj = {
429 // Create the object to be logged.
430 bar: foo.bar
431 }
432 return obj;
433 };
434 ```
435
436
437### Standard Serializers
438
439Bunyan includes a small set of "standard serializers", exported as
440`bunyan.stdSerializers`. Their use is completely optional. An example using
441all of them:
442
443```js
444var log = bunyan.createLogger({
445 name: 'myapp',
446 serializers: bunyan.stdSerializers
447});
448```
449
450or particular ones:
451
452```js
453var log = bunyan.createLogger({
454 name: 'myapp',
455 serializers: {err: bunyan.stdSerializers.err}
456});
457```
458
459Standard serializers are:
460
461| Field | Description |
462| ----- | ----------- |
463| err | Used for serializing JavaScript error objects, including traversing an error's cause chain for error objects with a `.cause()` -- e.g. as from [verror](https://github.com/joyent/node-verror). |
464| req | Common fields from a node.js HTTP request object. |
465| res | Common fields from a node.js HTTP response object. |
466
467Note that the `req` and `res` serializers intentionally do not include the
468request/response *body*, as that can be prohibitively large. If helpful, the
469[restify framework's audit logger plugin](https://github.com/restify/node-restify/blob/ac13902ad9716dcb20aaa62295403983075b1841/lib/plugins/audit.js#L38-L87)
470has its own req/res serializers that include more information (optionally
471including the body).
472
473
474## src
475
476The **source file, line and function of the log call site** can be added to
477log records by using the `src: true` config option:
478
479```js
480var log = bunyan.createLogger({src: true, ...});
481```
482
483This adds the call source info with the 'src' field, like this:
484
485```js
486{
487 "name": "src-example",
488 "hostname": "banana.local",
489 "pid": 123,
490 "component": "wuzzle",
491 "level": 4,
492 "msg": "This wuzzle is woosey.",
493 "time": "2012-02-06T04:19:35.605Z",
494 "src": {
495 "file": "/Users/trentm/tm/node-bunyan/examples/src.js",
496 "line": 20,
497 "func": "Wuzzle.woos"
498 },
499 "v": 0
500}
501```
502
503**WARNING: Determining the call source info is slow. Never use this option
504in production.**
505
506
507# Levels
508
509The log levels in bunyan are as follows. The level descriptions are best
510practice *opinions* of the author.
511
512- "fatal" (60): The service/app is going to stop or become unusable now.
513 An operator should definitely look into this soon.
514- "error" (50): Fatal for a particular request, but the service/app continues
515 servicing other requests. An operator should look at this soon(ish).
516- "warn" (40): A note on something that should probably be looked at by an
517 operator eventually.
518- "info" (30): Detail on regular operation.
519- "debug" (20): Anything else, i.e. too verbose to be included in "info" level.
520- "trace" (10): Logging from external libraries used by your app or *very*
521 detailed application logging.
522
523Setting a logger instance (or one of its streams) to a particular level implies
524that all log records *at that level and above* are logged. E.g. a logger set to
525level "info" will log records at level info and above (warn, error, fatal).
526
527While using log level *names* is preferred, the actual level values are integers
528internally (10 for "trace", ..., 60 for "fatal"). Constants are defined for
529the levels: `bunyan.TRACE` ... `bunyan.FATAL`. The lowercase level names are
530aliases supported in the API, e.g. `log.level("info")`. There is one exception:
531DTrace integration uses the level names. The fired DTrace probes are named
532'bunyan-$levelName'.
533
534Here is the API for querying and changing levels on an existing logger.
535Recall that a logger instance has an array of output "streams":
536
537```js
538log.level() -> INFO // gets current level (lowest level of all streams)
539
540log.level(INFO) // set all streams to level INFO
541log.level("info") // set all streams to level INFO
542
543log.levels() -> [DEBUG, INFO] // get array of levels of all streams
544log.levels(0) -> DEBUG // get level of stream at index 0
545log.levels("foo") // get level of stream with name "foo"
546
547log.levels(0, INFO) // set level of stream 0 to INFO
548log.levels(0, "info") // can use "info" et al aliases
549log.levels("foo", WARN) // set stream named "foo" to WARN
550```
551
552
553## Level suggestions
554
555Trent's biased suggestions for server apps: Use "debug" sparingly. Information
556that will be useful to debug errors *post mortem* should usually be included in
557"info" messages if it's generally relevant or else with the corresponding
558"error" event. Don't rely on spewing mostly irrelevant debug messages all the
559time and sifting through them when an error occurs.
560
561Trent's biased suggestions for node.js libraries: IMHO, libraries should only
562ever log at `trace`-level. Fine control over log output should be up to the
563app using a library. Having a library that spews log output at higher levels
564gets in the way of a clear story in the *app* logs.
565
566
567# Log Record Fields
568
569This section will describe *rules* for the Bunyan log format: field names,
570field meanings, required fields, etc. However, a Bunyan library doesn't
571strictly enforce all these rules while records are being emitted. For example,
572Bunyan will add a `time` field with the correct format to your log records,
573but you can specify your own. It is the caller's responsibility to specify
574the appropriate format.
575
576The reason for the above leniency is because IMO logging a message should
577never break your app. This leads to this rule of logging: **a thrown
578exception from `log.info(...)` or equivalent (other than for calling with the
579incorrect signature) is always a bug in Bunyan.**
580
581
582A typical Bunyan log record looks like this:
583
584```js
585{"name":"myserver","hostname":"banana.local","pid":123,"req":{"method":"GET","url":"/path?q=1#anchor","headers":{"x-hi":"Mom","connection":"close"}},"level":3,"msg":"start request","time":"2012-02-03T19:02:46.178Z","v":0}
586```
587
588Pretty-printed:
589
590```js
591{
592 "name": "myserver",
593 "hostname": "banana.local",
594 "pid": 123,
595 "req": {
596 "method": "GET",
597 "url": "/path?q=1#anchor",
598 "headers": {
599 "x-hi": "Mom",
600 "connection": "close"
601 },
602 "remoteAddress": "120.0.0.1",
603 "remotePort": 51244
604 },
605 "level": 3,
606 "msg": "start request",
607 "time": "2012-02-03T19:02:57.534Z",
608 "v": 0
609}
610```
611
612## Core fields
613
614- `v`: Required. Integer. Added by Bunyan. Cannot be overridden.
615 This is the Bunyan log format version (`require('bunyan').LOG_VERSION`).
616 The log version is a single integer. `0` is until I release a version
617 "1.0.0" of node-bunyan. Thereafter, starting with `1`, this will be
618 incremented if there is any backward incompatible change to the log record
619 format. Details will be in "CHANGES.md" (the change log).
620- `level`: Required. Integer. Added by Bunyan. Cannot be overridden.
621 See the "Levels" section.
622- `name`: Required. String. Provided at Logger creation.
623 You must specify a name for your logger when creating it. Typically this
624 is the name of the service/app using Bunyan for logging.
625- `hostname`: Required. String. Provided or determined at Logger creation.
626 You can specify your hostname at Logger creation or it will be retrieved
627 via `os.hostname()`.
628- `pid`: Required. Integer. Filled in automatically at Logger creation.
629- `time`: Required. String. Added by Bunyan. Can be overridden.
630 The date and time of the event in [ISO 8601
631 Extended Format](http://en.wikipedia.org/wiki/ISO_8601) format and in UTC,
632 as from
633 [`Date.toISOString()`](https://developer.mozilla.org/en/JavaScript/Reference/Global_Objects/Date/toISOString).
634- `msg`: Required. String.
635 Every `log.debug(...)` et al call must provide a log message.
636- `src`: Optional. Object giving log call source info. This is added
637 automatically by Bunyan if the "src: true" config option is given to the
638 Logger. Never use in production as this is really slow.
639
640
641Go ahead and add more fields, and nested ones are fine (and recommended) as
642well. This is why we're using JSON. Some suggestions and best practices
643follow (feedback from actual users welcome).
644
645
646## Recommended/Best Practice Fields
647
648- `err`: Object. A caught JS exception. Log that thing with `log.info(err)`
649 to get:
650
651 ```js
652 ...
653 "err": {
654 "message": "boom",
655 "name": "TypeError",
656 "stack": "TypeError: boom\n at Object.<anonymous> ..."
657 },
658 "msg": "boom",
659 ...
660 ```
661
662 Or use the `bunyan.stdSerializers.err` serializer in your Logger and
663 do this `log.error({err: err}, "oops")`. See "examples/err.js".
664
665- `req_id`: String. A request identifier. Including this field in all logging
666 tied to handling a particular request to your server is strongly suggested.
667 This allows post analysis of logs to easily collate all related logging
668 for a request. This really shines when you have a SOA with multiple services
669 and you carry a single request ID from the top API down through all APIs
670 (as [node-restify](https://github.com/mcavage/node-restify) facilitates
671 with its 'Request-Id' header).
672
673- `req`: An HTTP server request. Bunyan provides `bunyan.stdSerializers.req`
674 to serialize a request with a suggested set of keys. Example:
675
676 ```js
677 {
678 "method": "GET",
679 "url": "/path?q=1#anchor",
680 "headers": {
681 "x-hi": "Mom",
682 "connection": "close"
683 },
684 "remoteAddress": "120.0.0.1",
685 "remotePort": 51244
686 }
687 ```
688
689- `res`: An HTTP server response. Bunyan provides `bunyan.stdSerializers.res`
690 to serialize a response with a suggested set of keys. Example:
691
692 ```js
693 {
694 "statusCode": 200,
695 "header": "HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nConnection: keep-alive\r\nTransfer-Encoding: chunked\r\n\r\n"
696 }
697 ```
698
699## Other fields to consider
700
701- `req.username`: Authenticated user (or for a 401, the user attempting to
702 auth).
703- Some mechanism to calculate response latency. "restify" users will have
704 an "X-Response-Time" header. A `latency` custom field would be fine.
705- `req.body`: If you know that request bodies are small (common in APIs,
706 for example), then logging the request body is good.
707
708
709# Streams
710
711A "stream" is Bunyan's name for where it outputs log messages (the equivalent
712to a log4j Appender). Ultimately Bunyan uses a
713[Writable Stream](https://nodejs.org/docs/latest/api/all.html#writable_Stream)
714interface, but there are some additional attributes used to create and
715manage the stream. A Bunyan Logger instance has one or more streams.
716In general streams are specified with the "streams" option:
717
718```js
719var bunyan = require('bunyan');
720var log = bunyan.createLogger({
721 name: "foo",
722 streams: [
723 {
724 stream: process.stderr,
725 level: "debug"
726 },
727 ...
728 ]
729});
730```
731
732For convenience, if there is only one stream, it can be specified with the
733"stream" and "level" options (internally converted to a `Logger.streams`).
734
735```js
736var log = bunyan.createLogger({
737 name: "foo",
738 stream: process.stderr,
739 level: "debug"
740});
741```
742
743Note that "file" streams do not support this shortcut (partly for historical
744reasons and partly to not make it difficult to add a literal "path" field
745on log records).
746
747If neither "streams" nor "stream" are specified, the default is a stream of
748type "stream" emitting to `process.stdout` at the "info" level.
749
750## Adding a Stream
751
752After a bunyan instance has been initialized, you may add additional streams by
753calling the `addStream` function.
754
755```js
756var bunyan = require('bunyan');
757var log = bunyan.createLogger('myLogger');
758log.addStream({
759 name: "myNewStream",
760 stream: process.stderr,
761 level: "debug"
762});
763```
764
765## stream errors
766
767A Bunyan logger instance can be made to re-emit "error" events from its
768streams. Bunyan does so by default for [`type === "file"`
769streams](#stream-type-file), so you can do this:
770
771```js
772var log = bunyan.createLogger({name: 'mylog', streams: [{path: LOG_PATH}]});
773log.on('error', function (err, stream) {
774 // Handle stream write or create error here.
775});
776```
777
778As of bunyan@1.7.0, the `reemitErrorEvents` field can be used when adding a
779stream to control whether "error" events are re-emitted on the Logger. For
780example:
781
782 var EventEmitter = require('events').EventEmitter;
783 var util = require('util');
784
785 function MyFlakyStream() {}
786 util.inherits(MyFlakyStream, EventEmitter);
787
788 MyFlakyStream.prototype.write = function (rec) {
789 this.emit('error', new Error('boom'));
790 }
791
792 var log = bunyan.createLogger({
793 name: 'this-is-flaky',
794 streams: [
795 {
796 type: 'raw',
797 stream: new MyFlakyStream(),
798 reemitErrorEvents: true
799 }
800 ]
801 });
802 log.info('hi there');
803
804The behaviour is as follows:
805
806- `reemitErrorEvents` not specified: `file` streams will re-emit error events
807 on the Logger instance.
808- `reemitErrorEvents: true`: error events will be re-emitted on the Logger
809 for any stream with a `.on()` function -- which includes file streams,
810 process.stdout/stderr, and any object that inherits from EventEmitter.
811- `reemitErrorEvents: false`: error events will not be re-emitted for any
812 streams.
813
814Note: "error" events are **not** related to log records at the "error" level
815as produced by `log.error(...)`. See [the node.js docs on error
816events](https://nodejs.org/api/events.html#events_error_events) for details.
817
818
819## stream type: `stream`
820
821A `type === 'stream'` is a plain ol' node.js [Writable
822Stream](http://nodejs.org/docs/latest/api/all.html#writable_Stream). A
823"stream" (the writable stream) field is required. E.g.: `process.stdout`,
824`process.stderr`.
825
826```js
827var log = bunyan.createLogger({
828 name: 'foo',
829 streams: [{
830 stream: process.stderr
831 // `type: 'stream'` is implied
832 }]
833});
834```
835
836<table>
837<tr>
838<th>Field</th>
839<th>Required?</th>
840<th>Default</th>
841<th>Description</th>
842</tr>
843<tr>
844<td>stream</td>
845<td>Yes</td>
846<td>-</td>
847<td>A "Writable Stream", e.g. a std handle or an open file write stream.</td>
848</tr>
849<tr>
850<td>type</td>
851<td>No</td>
852<td>n/a</td>
853<td>`type == 'stream'` is implied if the `stream` field is given.</td>
854</tr>
855<tr>
856<td>level</td>
857<td>No</td>
858<td>info</td>
859<td>The level to which logging to this stream is enabled. If not
860specified it defaults to "info". If specified this can be one of the
861level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
862`bunyan.DEBUG`, ...). This serves as a severity threshold for that stream
863so logs of greater severity will also pass through (i.e. If level="warn",
864error and fatal will also pass through this stream).</td>
865</tr>
866<tr>
867<td>name</td>
868<td>No</td>
869<td>-</td>
870<td>A name for this stream. This may be useful for usage of `log.level(NAME,
871LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
872used for anything else.</td>
873</tr>
874</table>
875
876
877## stream type: `file`
878
879A `type === 'file'` stream requires a "path" field. Bunyan will open this
880file for appending. E.g.:
881
882```js
883var log = bunyan.createLogger({
884 name: 'foo',
885 streams: [{
886 path: '/var/log/foo.log',
887 // `type: 'file'` is implied
888 }]
889});
890```
891
892<table>
893<tr>
894<th>Field</th>
895<th>Required?</th>
896<th>Default</th>
897<th>Description</th>
898</tr>
899<tr>
900<td>path</td>
901<td>Yes</td>
902<td>-</td>
903<td>A file path to which to log.</td>
904</tr>
905<tr>
906<td>type</td>
907<td>No</td>
908<td>n/a</td>
909<td>`type == 'file'` is implied if the `path` field is given.</td>
910</tr>
911<tr>
912<td>level</td>
913<td>No</td>
914<td>info</td>
915<td>The level to which logging to this stream is enabled. If not
916specified it defaults to "info". If specified this can be one of the
917level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
918`bunyan.DEBUG`, ...). This serves as a severity threshold for that
919stream so logs of greater severity will also pass through (i.e. If
920level="warn", error and fatal will also pass through this stream).</td>
921</tr>
922<tr>
923<td>name</td>
924<td>No</td>
925<td>-</td>
926<td>A name for this stream. This may be useful for usage of `log.level(NAME,
927LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
928used for anything else.</td>
929</tr>
930</table>
931
932
933## stream type: `rotating-file`
934
935**WARNING on node 0.8 usage:** Users of Bunyan's `rotating-file` should (a) be
936using at least bunyan 0.23.1 (with the fix for [this
937issue](https://github.com/trentm/node-bunyan/pull/97)), and (b) should use at
938least node 0.10 (node 0.8 does not support the `unref()` method on
939`setTimeout(...)` needed for the mentioned fix). The symptom is that process
940termination will hang for up to a full rotation period.
941
942**WARNING on [cluster](http://nodejs.org/docs/latest/api/all.html#all_cluster)
943usage:** Using Bunyan's `rotating-file` stream with node.js's "cluster" module
944can result in unexpected file rotation. You must not have multiple processes
945in the cluster logging to the same file path. In other words, you must have
946a separate log file path for the master and each worker in the cluster.
947Alternatively, consider using a system file rotation facility such as
948`logrotate` on Linux or `logadm` on SmartOS/Illumos. See
949[this comment on issue #117](https://github.com/trentm/node-bunyan/issues/117#issuecomment-44804938)
950for details.
951
952A `type === 'rotating-file'` is a file stream that handles file automatic
953rotation.
954
955```js
956var log = bunyan.createLogger({
957 name: 'foo',
958 streams: [{
959 type: 'rotating-file',
960 path: '/var/log/foo.log',
961 period: '1d', // daily rotation
962 count: 3 // keep 3 back copies
963 }]
964});
965```
966
967This will rotate '/var/log/foo.log' every day (at midnight) to:
968
969```sh
970/var/log/foo.log.0 # yesterday
971/var/log/foo.log.1 # 1 day ago
972/var/log/foo.log.2 # 2 days ago
973```
974
975*Currently*, there is no support for providing a template for the rotated
976files, or for rotating when the log reaches a threshold size.
977
978<table>
979<tr>
980<th>Field</th>
981<th>Required?</th>
982<th>Default</th>
983<th>Description</th>
984</tr>
985<tr>
986<td>type</td>
987<td>Yes</td>
988<td>-</td>
989<td>"rotating-file"</td>
990</tr>
991<tr>
992<td>path</td>
993<td>Yes</td>
994<td>-</td>
995<td>A file path to which to log. Rotated files will be "$path.0",
996"$path.1", ...</td>
997</tr>
998<tr>
999<td>period</td>
1000<td>No</td>
1001<td>1d</td>
1002<td>The period at which to rotate. This is a string of the format
1003"$number$scope" where "$scope" is one of "ms" (milliseconds -- only useful for
1004testing), "h" (hours), "d" (days), "w" (weeks), "m" (months), "y" (years). Or
1005one of the following names can be used "hourly" (means 1h), "daily" (1d),
1006"weekly" (1w), "monthly" (1m), "yearly" (1y). Rotation is done at the start of
1007the scope: top of the hour (h), midnight (d), start of Sunday (w), start of the
10081st of the month (m), start of Jan 1st (y).</td>
1009</tr>
1010<tr>
1011<td>count</td>
1012<td>No</td>
1013<td>10</td>
1014<td>The number of rotated files to keep.</td>
1015</tr>
1016<tr>
1017<td>level</td>
1018<td>No</td>
1019<td>info</td>
1020<td>The level at which logging to this stream is enabled. If not
1021specified it defaults to "info". If specified this can be one of the
1022level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
1023`bunyan.DEBUG`, ...).</td>
1024</tr>
1025<tr>
1026<td>name</td>
1027<td>No</td>
1028<td>-</td>
1029<td>A name for this stream. This may be useful for usage of `log.level(NAME,
1030LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
1031used for anything else.</td>
1032</tr>
1033</table>
1034
1035
1036**Note on log rotation**: Often you may be using external log rotation utilities
1037like `logrotate` on Linux or `logadm` on SmartOS/Illumos. In those cases, unless
1038you are ensuring "copy and truncate" semantics (via `copytruncate` with
1039logrotate or `-c` with logadm) then the fd for your 'file' stream will change.
1040You can tell bunyan to reopen the file stream with code like this in your
1041app:
1042
1043```js
1044var log = bunyan.createLogger(...);
1045...
1046process.on('SIGUSR2', function () {
1047 log.reopenFileStreams();
1048});
1049```
1050
1051where you'd configure your log rotation to send SIGUSR2 (or some other signal)
1052to your process. Any other mechanism to signal your app to run
1053`log.reopenFileStreams()` would work as well.
1054
1055
1056## stream type: `raw`
1057
1058- `raw`: Similar to a "stream" writable stream, except that the write method
1059 is given raw log record *Object*s instead of a JSON-stringified string.
1060 This can be useful for hooking on further processing to all Bunyan logging:
1061 pushing to an external service, a RingBuffer (see below), etc.
1062
1063
1064
1065## `raw` + RingBuffer Stream
1066
1067Bunyan comes with a special stream called a RingBuffer which keeps the last N
1068records in memory and does *not* write the data anywhere else. One common
1069strategy is to log 'info' and higher to a normal log file but log all records
1070(including 'trace') to a ringbuffer that you can access via a debugger, or your
1071own HTTP interface, or a post-mortem facility like MDB or node-panic.
1072
1073To use a RingBuffer:
1074
1075```js
1076/* Create a ring buffer that stores the last 100 records. */
1077var bunyan = require('bunyan');
1078var ringbuffer = new bunyan.RingBuffer({ limit: 100 });
1079var log = bunyan.createLogger({
1080 name: 'foo',
1081 streams: [
1082 {
1083 level: 'info',
1084 stream: process.stdout
1085 },
1086 {
1087 level: 'trace',
1088 type: 'raw', // use 'raw' to get raw log record objects
1089 stream: ringbuffer
1090 }
1091 ]
1092});
1093
1094log.info('hello world');
1095console.log(ringbuffer.records);
1096```
1097
1098This example emits:
1099
1100```js
1101[ { name: 'foo',
1102 hostname: '912d2b29',
1103 pid: 50346,
1104 level: 30,
1105 msg: 'hello world',
1106 time: '2012-06-19T21:34:19.906Z',
1107 v: 0 } ]
1108```
1109
1110## third-party streams
1111
1112See the [user-maintained list in the Bunyan
1113wiki](https://github.com/trentm/node-bunyan/wiki/Awesome-Bunyan).
1114
1115
1116# Runtime log snooping via DTrace
1117
1118On systems that support DTrace (e.g., illumos derivatives like SmartOS and
1119OmniOS, FreeBSD, Mac), Bunyan will create a DTrace provider (`bunyan`) that
1120makes available the following probes:
1121
1122```sh
1123log-trace
1124log-debug
1125log-info
1126log-warn
1127log-error
1128log-fatal
1129```
1130
1131Each of these probes has a single argument: the string that would be
1132written to the log. Note that when a probe is enabled, it will
1133fire whenever the corresponding function is called, even if the level of
1134the log message is less than that of any stream.
1135
1136
1137## DTrace examples
1138
1139Trace all log messages coming from any Bunyan module on the system.
1140(The `-x strsize=4k` is to raise dtrace's default 256 byte buffer size
1141because log messages are longer than typical dtrace probes.)
1142
1143```sh
1144dtrace -x strsize=4k -qn 'bunyan*:::log-*{printf("%d: %s: %s", pid, probefunc, copyinstr(arg0))}'
1145```
1146
1147Trace all log messages coming from the "wuzzle" component:
1148
1149```sh
1150dtrace -x strsize=4k -qn 'bunyan*:::log-*/strstr(this->str = copyinstr(arg0), "\"component\":\"wuzzle\"") != NULL/{printf("%s", this->str)}'
1151```
1152
1153Aggregate debug messages from process 1234, by message:
1154
1155```sh
1156dtrace -x strsize=4k -n 'bunyan1234:::log-debug{@[copyinstr(arg0)] = count()}'
1157```
1158
1159Have the bunyan CLI pretty-print the traced logs:
1160
1161```sh
1162dtrace -x strsize=4k -qn 'bunyan1234:::log-*{printf("%s", copyinstr(arg0))}' | bunyan
1163```
1164
1165A convenience handle has been made for this:
1166
1167```sh
1168bunyan -p 1234
1169```
1170
1171On systems that support the
1172[`jstack`](http://dtrace.org/blogs/dap/2012/04/25/profiling-node-js/) action
1173via a node.js helper, get a stack backtrace for any debug message that
1174includes the string "danger!":
1175
1176```sh
1177dtrace -x strsize=4k -qn 'log-debug/strstr(copyinstr(arg0), "danger!") != NULL/{printf("\n%s", copyinstr(arg0)); jstack()}'
1178```
1179
1180Output of the above might be:
1181
1182```
1183{"name":"foo","hostname":"763bf293-d65c-42d5-872b-4abe25d5c4c7.local","pid":12747,"level":20,"msg":"danger!","time":"2012-10-30T18:28:57.115Z","v":0}
1184
1185 node`0x87e2010
1186 DTraceProviderBindings.node`usdt_fire_probe+0x32
1187 DTraceProviderBindings.node`_ZN4node11DTraceProbe5_fireEN2v85LocalINS1_5ValueEEE+0x32d
1188 DTraceProviderBindings.node`_ZN4node11DTraceProbe4FireERKN2v89ArgumentsE+0x77
1189 << internal code >>
1190 (anon) as (anon) at /root/node-bunyan/lib/bunyan.js position 40484
1191 << adaptor >>
1192 (anon) as doit at /root/my-prog.js position 360
1193 (anon) as list.ontimeout at timers.js position 4960
1194 << adaptor >>
1195 << internal >>
1196 << entry >>
1197 node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
1198 node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xcb
1199 node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
1200 node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11f
1201 node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x66
1202 node`_ZN4node9TimerWrap9OnTimeoutEP10uv_timer_si+0x63
1203 node`uv__run_timers+0x66
1204 node`uv__run+0x1b
1205 node`uv_run+0x17
1206 node`_ZN4node5StartEiPPc+0x1d0
1207 node`main+0x1b
1208 node`_start+0x83
1209
1210 node`0x87e2010
1211 DTraceProviderBindings.node`usdt_fire_probe+0x32
1212 DTraceProviderBindings.node`_ZN4node11DTraceProbe5_fireEN2v85LocalINS1_5ValueEEE+0x32d
1213 DTraceProviderBindings.node`_ZN4node11DTraceProbe4FireERKN2v89ArgumentsE+0x77
1214 << internal code >>
1215 (anon) as (anon) at /root/node-bunyan/lib/bunyan.js position 40484
1216 << adaptor >>
1217 (anon) as doit at /root/my-prog.js position 360
1218 (anon) as list.ontimeout at timers.js position 4960
1219 << adaptor >>
1220 << internal >>
1221 << entry >>
1222 node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
1223 node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xcb
1224 node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
1225 node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11f
1226 node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x66
1227 node`_ZN4node9TimerWrap9OnTimeoutEP10uv_timer_si+0x63
1228 node`uv__run_timers+0x66
1229 node`uv__run+0x1b
1230 node`uv_run+0x17
1231 node`_ZN4node5StartEiPPc+0x1d0
1232 node`main+0x1b
1233 node`_start+0x83
1234```
1235
1236
1237# Runtime environments
1238
1239Node-bunyan supports running in a few runtime environments:
1240
1241- [Node.js](https://nodejs.org/)
1242- [Browserify](http://browserify.org/): See the
1243 [Browserify section](#browserify) below.
1244- [Webpack](https://webpack.github.io/): See the [Webpack section](#webpack) below.
1245- [NW.js](http://nwjs.io/)
1246
1247Support for other runtime environments is welcome. If you have suggestions,
1248fixes, or mentions that node-bunyan already works in some other JavaScript
1249runtime, please open an [issue](https://github.com/trentm/node-bunyan/issues/new)
1250or a pull request.
1251
1252The primary target is Node.js. It is the only environment in which I
1253regularly test. If you have suggestions for how to automate testing for other
1254environments, I'd appreciate feedback on [this automated testing
1255issue](https://github.com/trentm/node-bunyan/issues/342).
1256
1257## Browserify
1258
1259As the [Browserify](http://browserify.org/) site says it "lets you
1260`require('modules')` in the browser by bundling up all of your dependencies."
1261It is a build tool to run on your node.js script to bundle up your script and
1262all its node.js dependencies into a single file that is runnable in the
1263browser via:
1264
1265```html
1266<script src="play.browser.js"></script>
1267```
1268
1269As of version 1.1.0, node-bunyan supports being run via Browserify. The
1270default [stream](#streams) when running in the browser is one that emits
1271raw log records to `console.log/info/warn/error`.
1272
1273Here is a quick example showing you how you can get this working for your
1274script.
1275
12761. Get browserify and bunyan installed in your module:
1277
1278 ```sh
1279 $ npm install browserify bunyan
1280 ```
1281
12822. An example script using Bunyan, "play.js":
1283
1284 ```js
1285 var bunyan = require('bunyan');
1286 var log = bunyan.createLogger({name: 'play', level: 'debug'});
1287 log.trace('this one does not emit');
1288 log.debug('hi on debug'); // console.log
1289 log.info('hi on info'); // console.info
1290 log.warn('hi on warn'); // console.warn
1291 log.error('hi on error'); // console.error
1292 ```
1293
12943. Build this into a bundle to run in the browser, "play.browser.js":
1295
1296 ```sh
1297 $ ./node_modules/.bin/browserify play.js -o play.browser.js
1298 ```
1299
13004. Put that into an HTML file, "play.html":
1301
1302 ```html
1303 <!DOCTYPE html>
1304 <html>
1305 <head>
1306 <meta charset="utf-8">
1307 <script src="play.browser.js"></script>
1308 </head>
1309 <body>
1310 <div>hi</div>
1311 </body>
1312 </html>
1313 ```
1314
13155. Open that in your browser and open your browser console:
1316
1317 ```sh
1318 $ open play.html
1319 ```
1320
1321Here is what it looks like in Firefox's console: ![Bunyan + Browserify in the
1322Firefox console](./docs/img/bunyan.browserify.png)
1323
1324For some, the raw log records might not be desired. To have a rendered log line
1325you'll want to add your own stream, starting with something like this:
1326
1327```js
1328var bunyan = require('./lib/bunyan');
1329
1330function MyRawStream() {}
1331MyRawStream.prototype.write = function (rec) {
1332 console.log('[%s] %s: %s',
1333 rec.time.toISOString(),
1334 bunyan.nameFromLevel[rec.level],
1335 rec.msg);
1336}
1337
1338var log = bunyan.createLogger({
1339 name: 'play',
1340 streams: [
1341 {
1342 level: 'info',
1343 stream: new MyRawStream(),
1344 type: 'raw'
1345 }
1346 ]
1347});
1348
1349log.info('hi on info');
1350```
1351
1352## webpack
1353To include bunyan in your webpack bundle you need to tell webpack to
1354ignore the optional dependencies that are unavailable in browser environments.
1355
1356Mark the following dependencies as
1357[externals](https://webpack.js.org/configuration/externals/) in your webpack
1358configuration file to exclude them from the bundle:
1359
1360```
1361module: {
1362 externals: ['dtrace-provider', 'fs', 'mv', 'os', 'source-map-support']
1363}
1364```
1365
1366# Versioning
1367
1368All versions are `<major>.<minor>.<patch>` which will be incremented for
1369breaking backward compat and major reworks, new features without breaking
1370change, and bug fixes, respectively. tl;dr: [Semantic
1371versioning](http://semver.org/).
1372
1373# License
1374
1375[MIT](./LICENSE.txt).
1376
1377# See Also
1378
1379See the [user-maintained list of Bunyan-related software in the Bunyan
1380wiki](https://github.com/trentm/node-bunyan/wiki/Awesome-Bunyan).