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