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 |
|
4 | Bunyan is **a simple and fast JSON logging library** for node.js services:
|
5 |
|
6 | ```js
|
7 | var bunyan = require('bunyan');
|
8 | var log = bunyan.createLogger({name: "myapp"});
|
9 | log.info("hi");
|
10 | ```
|
11 |
|
12 | and **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 |
|
16 | Manifesto: Server logs should be structured. JSON's a good format. Let's do
|
17 | that. A log record is one line of `JSON.stringify`'d output. Let's also
|
18 | specify some common names for the requisite and common fields for a log
|
19 | record (see below).
|
20 |
|
21 |
|
22 | ## Table of Contents
|
23 |
|
24 |
|
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 |
|
64 |
|
65 | # Current Status
|
66 |
|
67 | Solid core functionality is there. Joyent is using this for a number of
|
68 | production services. Bunyan supports node 0.10 and greater. Follow
|
69 | <a href="https://twitter.com/intent/user?screen_name=trentmick" target="_blank">@trentmick</a>
|
70 | for updates to Bunyan.
|
71 |
|
72 | There is an email discussion list
|
73 | [bunyan-logging@googlegroups.com](mailto:bunyan-logging@googlegroups.com),
|
74 | also [as a forum in the
|
75 | browser](https://groups.google.com/forum/?fromgroups#!forum/bunyan-logging).
|
76 |
|
77 |
|
78 | # Installation
|
79 |
|
80 | ```sh
|
81 | npm install bunyan
|
82 | ```
|
83 |
|
84 | **Tip**: The `bunyan` CLI tool is written to be compatible (within reason) with
|
85 | all versions of Bunyan logs. Therefore you might want to `npm install -g bunyan`
|
86 | to get the bunyan CLI on your PATH, then use local bunyan installs for
|
87 | node.js library usage of bunyan in your apps.
|
88 |
|
89 | **Tip**: Installing without optional dependencies can dramatically reduce
|
90 | bunyan's install size. **dtrace-provider** is used for dtrace features,
|
91 | **mv** is used for RotatingFileStream, and **moment** is used for local time.
|
92 | If 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 |
|
114 | Like most logging libraries you create a Logger instance and call methods
|
115 | named after the logging levels:
|
116 |
|
117 | ```js
|
118 | // hi.js
|
119 | var bunyan = require('bunyan');
|
120 | var log = bunyan.createLogger({name: 'myapp'});
|
121 | log.info('hi');
|
122 | log.warn({lang: 'fr'}, 'au revoir');
|
123 | ```
|
124 |
|
125 | All 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
|
141 | var bunyan = require('bunyan');
|
142 | var 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 |
|
159 | The example above shows two different ways to call `log.info(...)`. The
|
160 | full API is:
|
161 |
|
162 | ```js
|
163 | log.info(); // Returns a boolean: is the "info" level enabled?
|
164 | // This is equivalent to `log.isInfoEnabled()` or
|
165 | // `log.isEnabledFor(INFO)` in log4j.
|
166 |
|
167 | log.info('hi'); // Log a simple string message (or number).
|
168 | log.info('hi %s', bob, anotherVar); // Uses `util.format` for msg formatting.
|
169 |
|
170 | log.info({foo: 'bar'}, 'hi');
|
171 | // The first field can optionally be a "fields" object, which
|
172 | // is merged into the log record.
|
173 |
|
174 | log.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.
|
178 | log.info(err, 'more on this: %s', more);
|
179 | // ... or you can specify the "msg".
|
180 |
|
181 | log.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 |
|
186 | Note that this implies **you cannot blindly pass any object as the first
|
187 | argument to log it** because that object might include fields that collide with
|
188 | Bunyan's [core record fields](#core-fields). In other words,
|
189 | `log.info(mywidget)` may not yield what you expect. Instead of a string
|
190 | representation of `mywidget` that other logging libraries may give you, Bunyan
|
191 | will try to JSON-ify your object. It is a Bunyan best practice to always give a
|
192 | field name to included objects, e.g.:
|
193 |
|
194 | ```js
|
195 | log.info({widget: mywidget}, ...)
|
196 | ```
|
197 |
|
198 | This will dove-tail with [Bunyan serializer support](#serializers), discussed
|
199 | later.
|
200 |
|
201 | The 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
|
203 | section](#levels) below for details and suggestions.
|
204 |
|
205 |
|
206 | ## CLI Usage
|
207 |
|
208 | Bunyan log output is a stream of JSON objects. This is great for processing,
|
209 | but not for reading directly. A **`bunyan` tool** is provided **for
|
210 | pretty-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 |
|
219 | See the screenshot above for an example of the default coloring of rendered
|
220 | log output. That example also shows the nice formatting automatically done for
|
221 | some 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 |
|
224 | One interesting feature is **filtering** of log content, which can be useful
|
225 | for digging through large log files or for analysis. We can filter only
|
226 | records 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 |
|
233 | Or filter on the JSON fields in the records (e.g. only showing the French
|
234 | records 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 |
|
241 | See `bunyan --help` for other facilities.
|
242 |
|
243 |
|
244 | ## Streams Introduction
|
245 |
|
246 | By default, log output is to stdout and at the "info" level. Explicitly that
|
247 | looks like:
|
248 |
|
249 | ```js
|
250 | var log = bunyan.createLogger({
|
251 | name: 'myapp',
|
252 | stream: process.stdout,
|
253 | level: 'info'
|
254 | });
|
255 | ```
|
256 |
|
257 | That is an abbreviated form for a single stream. **You can define multiple
|
258 | streams at different levels**.
|
259 |
|
260 | ```js
|
261 | var 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 |
|
276 | More on streams in the [Streams section](#streams) below.
|
277 |
|
278 | ## log.child
|
279 |
|
280 | Bunyan has a concept of a child logger to **specialize a logger for a
|
281 | sub-component of your application**, i.e. to create a new logger with
|
282 | additional bound fields that will be included in its log records. A child
|
283 | logger is created with `log.child(...)`.
|
284 |
|
285 | In the following example, logging on a "Wuzzle" instance's `this.log` will
|
286 | be exactly as on the parent logger with the addition of the `widget_type`
|
287 | field:
|
288 |
|
289 | ```js
|
290 | var bunyan = require('bunyan');
|
291 | var log = bunyan.createLogger({name: 'myapp'});
|
292 |
|
293 | function Wuzzle(options) {
|
294 | this.log = options.log.child({widget_type: 'wuzzle'});
|
295 | this.log.info('creating a wuzzle')
|
296 | }
|
297 | Wuzzle.prototype.woos = function () {
|
298 | this.log.warn('This wuzzle is woosey.')
|
299 | }
|
300 |
|
301 | log.info('start');
|
302 | var wuzzle = new Wuzzle({log: log});
|
303 | wuzzle.woos();
|
304 | log.info('done');
|
305 | ```
|
306 |
|
307 | Running 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 |
|
317 | And with the `bunyan` CLI (using the "short" output mode):
|
318 |
|
319 | ```sh
|
320 | $ node myapp.js | bunyan -o short
|
321 | 07:46:42.707Z INFO myapp: start
|
322 | 07:46:42.709Z INFO myapp: creating a wuzzle (widget_type=wuzzle)
|
323 | 07:46:42.709Z WARN myapp: This wuzzle is woosey. (widget_type=wuzzle)
|
324 | 07:46:42.709Z INFO myapp: done
|
325 | ```
|
326 |
|
327 | A more practical example is in the
|
328 | [node-restify](https://github.com/mcavage/node-restify) web framework.
|
329 | Restify uses Bunyan for its logging. One feature of its integration, is that
|
330 | if `server.use(restify.requestLogger())` is used, each restify request handler
|
331 | includes a `req.log` logger that is:
|
332 |
|
333 | ```js
|
334 | log.child({req_id: <unique request id>}, true)
|
335 | ```
|
336 |
|
337 | Apps using restify can then use `req.log` and have all such log records
|
338 | include the unique request id (as "req\_id"). Handy.
|
339 |
|
340 |
|
341 | ## Serializers
|
342 |
|
343 | Bunyan has a concept of **"serializer" functions to produce a JSON-able object
|
344 | from a JavaScript object**, so you can easily do the following:
|
345 |
|
346 | ```js
|
347 | log.info({req: <request object>}, 'something about handling this request');
|
348 | ```
|
349 |
|
350 | and 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 |
|
354 | A 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
|
356 | record, Bunyan will call the serializer function for fields of that name.
|
357 | An example:
|
358 |
|
359 | ```js
|
360 | function reqSerializer(req) {
|
361 | return {
|
362 | method: req.method,
|
363 | url: req.url,
|
364 | headers: req.headers
|
365 | };
|
366 | }
|
367 | var log = bunyan.createLogger({
|
368 | name: 'myapp',
|
369 | serializers: {
|
370 | req: reqSerializer
|
371 | }
|
372 | });
|
373 | ```
|
374 |
|
375 |
|
376 | Typically serializers are added to a logger at creation time via
|
377 | `bunyan.createLogger({..., serializers: <serializers>})`. However, serializers
|
378 | can be added after creation via `<logger>.addSerializers(...)`, e.g.:
|
379 |
|
380 | ```js
|
381 | var log = bunyan.createLogger({name: 'myapp'});
|
382 | log.addSerializers({req: reqSerializer});
|
383 | ```
|
384 |
|
385 | ### Requirements for serializers functions
|
386 |
|
387 | A serializer function is passed unprotected objects that are passed to the
|
388 | `log.info`, `log.debug`, etc. call. This means a poorly written serializer
|
389 | function can cause side-effects. Logging shouldn't do that. Here are a few
|
390 | rules 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 |
|
439 | Bunyan includes a small set of "standard serializers", exported as
|
440 | `bunyan.stdSerializers`. Their use is completely optional. An example using
|
441 | all of them:
|
442 |
|
443 | ```js
|
444 | var log = bunyan.createLogger({
|
445 | name: 'myapp',
|
446 | serializers: bunyan.stdSerializers
|
447 | });
|
448 | ```
|
449 |
|
450 | or particular ones:
|
451 |
|
452 | ```js
|
453 | var log = bunyan.createLogger({
|
454 | name: 'myapp',
|
455 | serializers: {err: bunyan.stdSerializers.err}
|
456 | });
|
457 | ```
|
458 |
|
459 | Standard 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 |
|
467 | Note that the `req` and `res` serializers intentionally do not include the
|
468 | request/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)
|
470 | has its own req/res serializers that include more information (optionally
|
471 | including the body).
|
472 |
|
473 |
|
474 | ## src
|
475 |
|
476 | The **source file, line and function of the log call site** can be added to
|
477 | log records by using the `src: true` config option:
|
478 |
|
479 | ```js
|
480 | var log = bunyan.createLogger({src: true, ...});
|
481 | ```
|
482 |
|
483 | This 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
|
504 | in production.**
|
505 |
|
506 |
|
507 | # Levels
|
508 |
|
509 | The log levels in bunyan are as follows. The level descriptions are best
|
510 | practice *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 |
|
523 | Setting a logger instance (or one of its streams) to a particular level implies
|
524 | that all log records *at that level and above* are logged. E.g. a logger set to
|
525 | level "info" will log records at level info and above (warn, error, fatal).
|
526 |
|
527 | While using log level *names* is preferred, the actual level values are integers
|
528 | internally (10 for "trace", ..., 60 for "fatal"). Constants are defined for
|
529 | the levels: `bunyan.TRACE` ... `bunyan.FATAL`. The lowercase level names are
|
530 | aliases supported in the API, e.g. `log.level("info")`. There is one exception:
|
531 | DTrace integration uses the level names. The fired DTrace probes are named
|
532 | 'bunyan-$levelName'.
|
533 |
|
534 | Here is the API for querying and changing levels on an existing logger.
|
535 | Recall that a logger instance has an array of output "streams":
|
536 |
|
537 | ```js
|
538 | log.level() -> INFO // gets current level (lowest level of all streams)
|
539 |
|
540 | log.level(INFO) // set all streams to level INFO
|
541 | log.level("info") // set all streams to level INFO
|
542 |
|
543 | log.levels() -> [DEBUG, INFO] // get array of levels of all streams
|
544 | log.levels(0) -> DEBUG // get level of stream at index 0
|
545 | log.levels("foo") // get level of stream with name "foo"
|
546 |
|
547 | log.levels(0, INFO) // set level of stream 0 to INFO
|
548 | log.levels(0, "info") // can use "info" et al aliases
|
549 | log.levels("foo", WARN) // set stream named "foo" to WARN
|
550 | ```
|
551 |
|
552 |
|
553 | ## Level suggestions
|
554 |
|
555 | Trent's biased suggestions for server apps: Use "debug" sparingly. Information
|
556 | that 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
|
559 | time and sifting through them when an error occurs.
|
560 |
|
561 | Trent's biased suggestions for node.js libraries: IMHO, libraries should only
|
562 | ever log at `trace`-level. Fine control over log output should be up to the
|
563 | app using a library. Having a library that spews log output at higher levels
|
564 | gets in the way of a clear story in the *app* logs.
|
565 |
|
566 |
|
567 | # Log Record Fields
|
568 |
|
569 | This section will describe *rules* for the Bunyan log format: field names,
|
570 | field meanings, required fields, etc. However, a Bunyan library doesn't
|
571 | strictly enforce all these rules while records are being emitted. For example,
|
572 | Bunyan will add a `time` field with the correct format to your log records,
|
573 | but you can specify your own. It is the caller's responsibility to specify
|
574 | the appropriate format.
|
575 |
|
576 | The reason for the above leniency is because IMO logging a message should
|
577 | never break your app. This leads to this rule of logging: **a thrown
|
578 | exception from `log.info(...)` or equivalent (other than for calling with the
|
579 | incorrect signature) is always a bug in Bunyan.**
|
580 |
|
581 |
|
582 | A 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 |
|
588 | Pretty-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 |
|
641 | Go ahead and add more fields, and nested ones are fine (and recommended) as
|
642 | well. This is why we're using JSON. Some suggestions and best practices
|
643 | follow (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 |
|
711 | A "stream" is Bunyan's name for where it outputs log messages (the equivalent
|
712 | to a log4j Appender). Ultimately Bunyan uses a
|
713 | [Writable Stream](https://nodejs.org/docs/latest/api/all.html#writable_Stream)
|
714 | interface, but there are some additional attributes used to create and
|
715 | manage the stream. A Bunyan Logger instance has one or more streams.
|
716 | In general streams are specified with the "streams" option:
|
717 |
|
718 | ```js
|
719 | var bunyan = require('bunyan');
|
720 | var log = bunyan.createLogger({
|
721 | name: "foo",
|
722 | streams: [
|
723 | {
|
724 | stream: process.stderr,
|
725 | level: "debug"
|
726 | },
|
727 | ...
|
728 | ]
|
729 | });
|
730 | ```
|
731 |
|
732 | For 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
|
736 | var log = bunyan.createLogger({
|
737 | name: "foo",
|
738 | stream: process.stderr,
|
739 | level: "debug"
|
740 | });
|
741 | ```
|
742 |
|
743 | Note that "file" streams do not support this shortcut (partly for historical
|
744 | reasons and partly to not make it difficult to add a literal "path" field
|
745 | on log records).
|
746 |
|
747 | If neither "streams" nor "stream" are specified, the default is a stream of
|
748 | type "stream" emitting to `process.stdout` at the "info" level.
|
749 |
|
750 | ## Adding a Stream
|
751 |
|
752 | After a bunyan instance has been initialized, you may add additional streams by
|
753 | calling the `addStream` function.
|
754 |
|
755 | ```js
|
756 | var bunyan = require('bunyan');
|
757 | var log = bunyan.createLogger('myLogger');
|
758 | log.addStream({
|
759 | name: "myNewStream",
|
760 | stream: process.stderr,
|
761 | level: "debug"
|
762 | });
|
763 | ```
|
764 |
|
765 | ## stream errors
|
766 |
|
767 | A Bunyan logger instance can be made to re-emit "error" events from its
|
768 | streams. Bunyan does so by default for [`type === "file"`
|
769 | streams](#stream-type-file), so you can do this:
|
770 |
|
771 | ```js
|
772 | var log = bunyan.createLogger({name: 'mylog', streams: [{path: LOG_PATH}]});
|
773 | log.on('error', function (err, stream) {
|
774 | // Handle stream write or create error here.
|
775 | });
|
776 | ```
|
777 |
|
778 | As of bunyan@1.7.0, the `reemitErrorEvents` field can be used when adding a
|
779 | stream to control whether "error" events are re-emitted on the Logger. For
|
780 | example:
|
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 |
|
804 | The 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 |
|
814 | Note: "error" events are **not** related to log records at the "error" level
|
815 | as produced by `log.error(...)`. See [the node.js docs on error
|
816 | events](https://nodejs.org/api/events.html#events_error_events) for details.
|
817 |
|
818 |
|
819 | ## stream type: `stream`
|
820 |
|
821 | A `type === 'stream'` is a plain ol' node.js [Writable
|
822 | Stream](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
|
827 | var 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
|
860 | specified it defaults to "info". If specified this can be one of the
|
861 | level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
|
862 | `bunyan.DEBUG`, ...). This serves as a severity threshold for that stream
|
863 | so logs of greater severity will also pass through (i.e. If level="warn",
|
864 | error 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,
|
871 | LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
|
872 | used for anything else.</td>
|
873 | </tr>
|
874 | </table>
|
875 |
|
876 |
|
877 | ## stream type: `file`
|
878 |
|
879 | A `type === 'file'` stream requires a "path" field. Bunyan will open this
|
880 | file for appending. E.g.:
|
881 |
|
882 | ```js
|
883 | var 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
|
916 | specified it defaults to "info". If specified this can be one of the
|
917 | level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`,
|
918 | `bunyan.DEBUG`, ...). This serves as a severity threshold for that
|
919 | stream so logs of greater severity will also pass through (i.e. If
|
920 | level="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,
|
927 | LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
|
928 | used 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
|
936 | using at least bunyan 0.23.1 (with the fix for [this
|
937 | issue](https://github.com/trentm/node-bunyan/pull/97)), and (b) should use at
|
938 | least 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
|
940 | termination will hang for up to a full rotation period.
|
941 |
|
942 | **WARNING on [cluster](http://nodejs.org/docs/latest/api/all.html#all_cluster)
|
943 | usage:** Using Bunyan's `rotating-file` stream with node.js's "cluster" module
|
944 | can result in unexpected file rotation. You must not have multiple processes
|
945 | in the cluster logging to the same file path. In other words, you must have
|
946 | a separate log file path for the master and each worker in the cluster.
|
947 | Alternatively, 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)
|
950 | for details.
|
951 |
|
952 | A `type === 'rotating-file'` is a file stream that handles file automatic
|
953 | rotation.
|
954 |
|
955 | ```js
|
956 | var 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 |
|
967 | This 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
|
976 | files, 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
|
1004 | testing), "h" (hours), "d" (days), "w" (weeks), "m" (months), "y" (years). Or
|
1005 | one 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
|
1007 | the scope: top of the hour (h), midnight (d), start of Sunday (w), start of the
|
1008 | 1st 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
|
1021 | specified it defaults to "info". If specified this can be one of the
|
1022 | level 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,
|
1030 | LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't
|
1031 | used for anything else.</td>
|
1032 | </tr>
|
1033 | </table>
|
1034 |
|
1035 |
|
1036 | **Note on log rotation**: Often you may be using external log rotation utilities
|
1037 | like `logrotate` on Linux or `logadm` on SmartOS/Illumos. In those cases, unless
|
1038 | you are ensuring "copy and truncate" semantics (via `copytruncate` with
|
1039 | logrotate or `-c` with logadm) then the fd for your 'file' stream will change.
|
1040 | You can tell bunyan to reopen the file stream with code like this in your
|
1041 | app:
|
1042 |
|
1043 | ```js
|
1044 | var log = bunyan.createLogger(...);
|
1045 | ...
|
1046 | process.on('SIGUSR2', function () {
|
1047 | log.reopenFileStreams();
|
1048 | });
|
1049 | ```
|
1050 |
|
1051 | where you'd configure your log rotation to send SIGUSR2 (or some other signal)
|
1052 | to 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 |
|
1067 | Bunyan comes with a special stream called a RingBuffer which keeps the last N
|
1068 | records in memory and does *not* write the data anywhere else. One common
|
1069 | strategy 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
|
1071 | own HTTP interface, or a post-mortem facility like MDB or node-panic.
|
1072 |
|
1073 | To use a RingBuffer:
|
1074 |
|
1075 | ```js
|
1076 | /* Create a ring buffer that stores the last 100 records. */
|
1077 | var bunyan = require('bunyan');
|
1078 | var ringbuffer = new bunyan.RingBuffer({ limit: 100 });
|
1079 | var 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 |
|
1094 | log.info('hello world');
|
1095 | console.log(ringbuffer.records);
|
1096 | ```
|
1097 |
|
1098 | This 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 |
|
1112 | See the [user-maintained list in the Bunyan
|
1113 | wiki](https://github.com/trentm/node-bunyan/wiki/Awesome-Bunyan).
|
1114 |
|
1115 |
|
1116 | # Runtime log snooping via DTrace
|
1117 |
|
1118 | On systems that support DTrace (e.g., illumos derivatives like SmartOS and
|
1119 | OmniOS, FreeBSD, Mac), Bunyan will create a DTrace provider (`bunyan`) that
|
1120 | makes available the following probes:
|
1121 |
|
1122 | ```sh
|
1123 | log-trace
|
1124 | log-debug
|
1125 | log-info
|
1126 | log-warn
|
1127 | log-error
|
1128 | log-fatal
|
1129 | ```
|
1130 |
|
1131 | Each of these probes has a single argument: the string that would be
|
1132 | written to the log. Note that when a probe is enabled, it will
|
1133 | fire whenever the corresponding function is called, even if the level of
|
1134 | the log message is less than that of any stream.
|
1135 |
|
1136 |
|
1137 | ## DTrace examples
|
1138 |
|
1139 | Trace 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
|
1141 | because log messages are longer than typical dtrace probes.)
|
1142 |
|
1143 | ```sh
|
1144 | dtrace -x strsize=4k -qn 'bunyan*:::log-*{printf("%d: %s: %s", pid, probefunc, copyinstr(arg0))}'
|
1145 | ```
|
1146 |
|
1147 | Trace all log messages coming from the "wuzzle" component:
|
1148 |
|
1149 | ```sh
|
1150 | dtrace -x strsize=4k -qn 'bunyan*:::log-*/strstr(this->str = copyinstr(arg0), "\"component\":\"wuzzle\"") != NULL/{printf("%s", this->str)}'
|
1151 | ```
|
1152 |
|
1153 | Aggregate debug messages from process 1234, by message:
|
1154 |
|
1155 | ```sh
|
1156 | dtrace -x strsize=4k -n 'bunyan1234:::log-debug{@[copyinstr(arg0)] = count()}'
|
1157 | ```
|
1158 |
|
1159 | Have the bunyan CLI pretty-print the traced logs:
|
1160 |
|
1161 | ```sh
|
1162 | dtrace -x strsize=4k -qn 'bunyan1234:::log-*{printf("%s", copyinstr(arg0))}' | bunyan
|
1163 | ```
|
1164 |
|
1165 | A convenience handle has been made for this:
|
1166 |
|
1167 | ```sh
|
1168 | bunyan -p 1234
|
1169 | ```
|
1170 |
|
1171 | On systems that support the
|
1172 | [`jstack`](http://dtrace.org/blogs/dap/2012/04/25/profiling-node-js/) action
|
1173 | via a node.js helper, get a stack backtrace for any debug message that
|
1174 | includes the string "danger!":
|
1175 |
|
1176 | ```sh
|
1177 | dtrace -x strsize=4k -qn 'log-debug/strstr(copyinstr(arg0), "danger!") != NULL/{printf("\n%s", copyinstr(arg0)); jstack()}'
|
1178 | ```
|
1179 |
|
1180 | Output 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 |
|
1239 | Node-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 |
|
1247 | Support for other runtime environments is welcome. If you have suggestions,
|
1248 | fixes, or mentions that node-bunyan already works in some other JavaScript
|
1249 | runtime, please open an [issue](https://github.com/trentm/node-bunyan/issues/new)
|
1250 | or a pull request.
|
1251 |
|
1252 | The primary target is Node.js. It is the only environment in which I
|
1253 | regularly test. If you have suggestions for how to automate testing for other
|
1254 | environments, I'd appreciate feedback on [this automated testing
|
1255 | issue](https://github.com/trentm/node-bunyan/issues/342).
|
1256 |
|
1257 | ## Browserify
|
1258 |
|
1259 | As the [Browserify](http://browserify.org/) site says it "lets you
|
1260 | `require('modules')` in the browser by bundling up all of your dependencies."
|
1261 | It is a build tool to run on your node.js script to bundle up your script and
|
1262 | all its node.js dependencies into a single file that is runnable in the
|
1263 | browser via:
|
1264 |
|
1265 | ```html
|
1266 | <script src="play.browser.js"></script>
|
1267 | ```
|
1268 |
|
1269 | As of version 1.1.0, node-bunyan supports being run via Browserify. The
|
1270 | default [stream](#streams) when running in the browser is one that emits
|
1271 | raw log records to `console.log/info/warn/error`.
|
1272 |
|
1273 | Here is a quick example showing you how you can get this working for your
|
1274 | script.
|
1275 |
|
1276 | 1. Get browserify and bunyan installed in your module:
|
1277 |
|
1278 | ```sh
|
1279 | $ npm install browserify bunyan
|
1280 | ```
|
1281 |
|
1282 | 2. 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 |
|
1294 | 3. 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 |
|
1300 | 4. 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 |
|
1315 | 5. Open that in your browser and open your browser console:
|
1316 |
|
1317 | ```sh
|
1318 | $ open play.html
|
1319 | ```
|
1320 |
|
1321 | Here is what it looks like in Firefox's console: ![Bunyan + Browserify in the
|
1322 | Firefox console](./docs/img/bunyan.browserify.png)
|
1323 |
|
1324 | For some, the raw log records might not be desired. To have a rendered log line
|
1325 | you'll want to add your own stream, starting with something like this:
|
1326 |
|
1327 | ```js
|
1328 | var bunyan = require('./lib/bunyan');
|
1329 |
|
1330 | function MyRawStream() {}
|
1331 | MyRawStream.prototype.write = function (rec) {
|
1332 | console.log('[%s] %s: %s',
|
1333 | rec.time.toISOString(),
|
1334 | bunyan.nameFromLevel[rec.level],
|
1335 | rec.msg);
|
1336 | }
|
1337 |
|
1338 | var log = bunyan.createLogger({
|
1339 | name: 'play',
|
1340 | streams: [
|
1341 | {
|
1342 | level: 'info',
|
1343 | stream: new MyRawStream(),
|
1344 | type: 'raw'
|
1345 | }
|
1346 | ]
|
1347 | });
|
1348 |
|
1349 | log.info('hi on info');
|
1350 | ```
|
1351 |
|
1352 | ## webpack
|
1353 | To include bunyan in your webpack bundle you need to tell webpack to
|
1354 | ignore the optional dependencies that are unavailable in browser environments.
|
1355 |
|
1356 | Mark the following dependencies as
|
1357 | [externals](https://webpack.js.org/configuration/externals/) in your webpack
|
1358 | configuration file to exclude them from the bundle:
|
1359 |
|
1360 | ```
|
1361 | module: {
|
1362 | externals: ['dtrace-provider', 'fs', 'mv', 'os', 'source-map-support']
|
1363 | }
|
1364 | ```
|
1365 |
|
1366 | # Versioning
|
1367 |
|
1368 | All versions are `<major>.<minor>.<patch>` which will be incremented for
|
1369 | breaking backward compat and major reworks, new features without breaking
|
1370 | change, and bug fixes, respectively. tl;dr: [Semantic
|
1371 | versioning](http://semver.org/).
|
1372 |
|
1373 | # License
|
1374 |
|
1375 | [MIT](./LICENSE.txt).
|
1376 |
|
1377 | # See Also
|
1378 |
|
1379 | See the [user-maintained list of Bunyan-related software in the Bunyan
|
1380 | wiki](https://github.com/trentm/node-bunyan/wiki/Awesome-Bunyan).
|