Name: js-handler/node_modules/restify/node_modules/bunyan/README.md
| 1: | Bunyan is **a simple and fast JSON logging library** for node.js services: |
| 2: | |
| 3: | var bunyan = require('bunyan'); |
| 4: | var log = bunyan.createLogger({name: "myapp"}); |
| 5: | log.info("hi"); |
| 6: | |
| 7: | and **a `bunyan` CLI tool** for nicely viewing those logs: |
| 8: | |
| 9: |  |
| 10: | |
| 11: | Manifesto: Server logs should be structured. JSON's a good format. Let's do |
| 12: | that. A log record is one line of `JSON.stringify`'d output. Let's also |
| 13: | specify some common names for the requisite and common fields for a log |
| 14: | record (see below). |
| 15: | |
| 16: | Also: log4j is way more than you need. |
| 17: | |
| 18: | |
| 19: | # Current Status |
| 20: | |
| 21: | Solid core functionality is there. Joyent is using this for a number of |
| 22: | production services. Bunyan supports node 0.6 and greater. Follow |
| 23: | <a href="https://twitter.com/intent/user?screen_name=trentmick" target="_blank">@trentmick</a> |
| 24: | for updates to Bunyan. |
| 25: | |
| 26: | |
| 27: | # Installation |
| 28: | |
| 29: | npm install bunyan |
| 30: | |
| 31: | **Tip**: The `bunyan` CLI tool is written to be compatible (within reason) with |
| 32: | all versions of Bunyan logs. Therefore you might want to `npm install -g bunyan` |
| 33: | to get the bunyan CLI on your PATH, then use local bunyan installs for |
| 34: | node.js library usage of bunyan in your apps. |
| 35: | |
| 36: | |
| 37: | # Features |
| 38: | |
| 39: | - elegant [log method API](#log-method-api) |
| 40: | - extensible [streams](#streams) system for controlling where log records |
| 41: | go (to a stream, to a file, [log file rotation](#stream-type-rotating-file), |
| 42: | etc.) |
| 43: | - [`bunyan` CLI](#cli-usage) for pretty-printing and filtering of Bunyan logs |
| 44: | - simple include of log call source location (file, line, function) with |
| 45: | [`src: true`](#src) |
| 46: | - light-weight specialization of Logger instances with [`log.child`](#logchild) |
| 47: | - custom rendering of logged objects with ["serializers"](#serializers) |
| 48: | - [Dtrace support](#dtrace-support) |
| 49: | |
| 50: | |
| 51: | # Introduction |
| 52: | |
| 53: | Like most logging libraries you create a Logger instance and call methods |
| 54: | named after the logging levels: |
| 55: | |
| 56: | $ cat hi.js |
| 57: | var bunyan = require('bunyan'); |
| 58: | var log = bunyan.createLogger({name: 'myapp'}); |
| 59: | log.info('hi'); |
| 60: | log.warn({lang: 'fr'}, 'au revoir'); |
| 61: | |
| 62: | All loggers must provide a "name". This is somewhat akin to the log4j logger |
| 63: | "name", but Bunyan doesn't do hierarchical logger names. |
| 64: | |
| 65: | **Bunyan log records are JSON.** A few fields are added automatically: |
| 66: | "pid", "hostname", "time" and "v". |
| 67: | |
| 68: | $ node hi.js |
| 69: | {"name":"myapp","hostname":"banana.local","pid":40161,"level":30,"msg":"hi","time":"2013-01-04T18:46:23.851Z","v":0} |
| 70: | {"name":"myapp","hostname":"banana.local","pid":40161,"level":40,"lang":"fr","msg":"au revoir","time":"2013-01-04T18:46:23.853Z","v":0} |
| 71: | |
| 72: | |
| 73: | ## Log Method API |
| 74: | |
| 75: | The example above shows two different ways to call `log.info(...)`. The |
| 76: | full API is: |
| 77: | |
| 78: | log.info(); // Returns a boolean: is the "info" level enabled? |
| 79: | // This is equivalent to `log.isInfoEnabled()` or |
| 80: | // `log.isEnabledFor(INFO)` in log4j. |
| 81: | |
| 82: | log.info('hi'); // Log a simple string message. |
| 83: | log.info('hi %s', bob, anotherVar); // Uses `util.format` for msg formatting. |
| 84: | |
| 85: | log.info({foo: 'bar'}, 'hi'); |
| 86: | // Adds "foo" field to log record. You can add any number |
| 87: | // of additional fields here. |
| 88: | |
| 89: | log.info(err); // Special case to log an `Error` instance to the record. |
| 90: | // This adds an "err" field with exception details |
| 91: | // (including the stack) and sets "msg" to the exception |
| 92: | // message. |
| 93: | log.info(err, 'more on this: %s', more); |
| 94: | // ... or you can specify the "msg". |
| 95: | |
| 96: | Note that this implies **you cannot pass any object as the first argument |
| 97: | to log it**. IOW, `log.info(mywidget)` may not be what you expect. Instead |
| 98: | of a string representation of `mywidget` that other logging libraries may |
| 99: | give you, Bunyan will try to JSON-ify your object. It is a Bunyan best |
| 100: | practice to always give a field name to included objects, e.g.: |
| 101: | |
| 102: | log.info({widget: mywidget}, ...) |
| 103: | |
| 104: | This will dove-tail with [Bunyan serializer support](#serializers), discussed |
| 105: | later. |
| 106: | |
| 107: | The same goes for all of Bunyan's log levels: `log.trace`, `log.debug`, |
| 108: | `log.info`, `log.warn`, and `log.fatal`. See the [levels section](#levels) |
| 109: | below for details and suggestions. |
| 110: | |
| 111: | |
| 112: | ## CLI Usage |
| 113: | |
| 114: | Bunyan log output is a stream of JSON objects. This is great for processing, |
| 115: | but not for reading directly. A **`bunyan` tool** is provided **for |
| 116: | pretty-printing bunyan logs** and for **filtering** (e.g. |
| 117: | `| bunyan -c 'this.foo == "bar"'`). Using our example above: |
| 118: | |
| 119: | $ node hi.js | ./bin/bunyan |
| 120: | [2013-01-04T19:01:18.241Z] INFO: myapp/40208 on banana.local: hi |
| 121: | [2013-01-04T19:01:18.242Z] WARN: myapp/40208 on banana.local: au revoir (lang=fr) |
| 122: | |
| 123: | See the screenshot above for an example of the default coloring of rendered |
| 124: | log output. That example also shows the nice formatting automatically done for |
| 125: | some well-known log record fields (e.g. `req` is formatted like an HTTP request, |
| 126: | `res` like an HTTP response, `err` like an error stack trace). |
| 127: | |
| 128: | One interesting feature is **filtering** of log content, which can be useful |
| 129: | for digging through large log files or for analysis. We can filter only |
| 130: | records above a certain level: |
| 131: | |
| 132: | $ node hi.js | bunyan -l warn |
| 133: | [2013-01-04T19:08:37.182Z] WARN: myapp/40353 on banana.local: au revoir (lang=fr) |
| 134: | |
| 135: | Or filter on the JSON fields in the records (e.g. only showing the French |
| 136: | records in our contrived example): |
| 137: | |
| 138: | $ node hi.js | bunyan -c 'this.lang == "fr"' |
| 139: | [2013-01-04T19:08:26.411Z] WARN: myapp/40342 on banana.local: au revoir (lang=fr) |
| 140: | |
| 141: | See `bunyan --help` for other facilities. |
| 142: | |
| 143: | |
| 144: | ## Streams Introduction |
| 145: | |
| 146: | By default, log output is to stdout and at the "info" level. Explicitly that |
| 147: | looks like: |
| 148: | |
| 149: | var log = bunyan.createLogger({ |
| 150: | name: 'myapp', |
| 151: | stream: process.stdout, |
| 152: | level: 'info' |
| 153: | }); |
| 154: | |
| 155: | That is an abbreviated form for a single stream. **You can define multiple |
| 156: | streams at different levels**. |
| 157: | |
| 158: | var log = bunyan.createLogger({ |
| 159: | name: 'myapp', |
| 160: | streams: [ |
| 161: | { |
| 162: | level: 'info', |
| 163: | stream: process.stdout, // log INFO and above to stdout |
| 164: | }, |
| 165: | { |
| 166: | level: 'error', |
| 167: | path: '/var/log/myapp-error.log' // log ERROR and above to a file |
| 168: | } |
| 169: | ] |
| 170: | }); |
| 171: | |
| 172: | More on streams in the [Streams section](#streams) below. |
| 173: | |
| 174: | |
| 175: | ## log.child |
| 176: | |
| 177: | Bunyan has a concept of a child logger to **specialize a logger for a |
| 178: | sub-component of your application**, i.e. to create a new logger with |
| 179: | additional bound fields that will be included in its log records. A child |
| 180: | logger is created with `log.child(...)`. |
| 181: | |
| 182: | In the following example, logging on a "Wuzzle" instance's `this.log` will |
| 183: | be exactly as on the parent logger with the addition of the `widget_type` |
| 184: | field: |
| 185: | |
| 186: | var bunyan = require('bunyan'); |
| 187: | var log = bunyan.createLogger({name: 'myapp'}); |
| 188: | |
| 189: | function Wuzzle(options) { |
| 190: | this.log = options.log.child({widget_type: 'wuzzle'}); |
| 191: | this.log.info('creating a wuzzle') |
| 192: | } |
| 193: | Wuzzle.prototype.woos = function () { |
| 194: | this.log.warn('This wuzzle is woosey.') |
| 195: | } |
| 196: | |
| 197: | log.info('start'); |
| 198: | var wuzzle = new Wuzzle({log: log}); |
| 199: | wuzzle.woos(); |
| 200: | log.info('done'); |
| 201: | |
| 202: | Running that looks like (raw): |
| 203: | |
| 204: | $ node myapp.js |
| 205: | {"name":"myapp","hostname":"myhost","pid":34572,"level":30,"msg":"start","time":"2013-01-04T07:47:25.814Z","v":0} |
| 206: | {"name":"myapp","hostname":"myhost","pid":34572,"widget_type":"wuzzle","level":30,"msg":"creating a wuzzle","time":"2013-01-04T07:47:25.815Z","v":0} |
| 207: | {"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} |
| 208: | {"name":"myapp","hostname":"myhost","pid":34572,"level":30,"msg":"done","time":"2013-01-04T07:47:25.816Z","v":0} |
| 209: | |
| 210: | And with the `bunyan` CLI (using the "short" output mode): |
| 211: | |
| 212: | $ node myapp.js | bunyan -o short |
| 213: | 07:46:42.707Z INFO myapp: start |
| 214: | 07:46:42.709Z INFO myapp: creating a wuzzle (widget_type=wuzzle) |
| 215: | 07:46:42.709Z WARN myapp: This wuzzle is woosey. (widget_type=wuzzle) |
| 216: | 07:46:42.709Z INFO myapp: done |
| 217: | |
| 218: | |
| 219: | A more practical example is in the |
| 220: | [node-restify](https://github.com/mcavage/node-restify) web framework. |
| 221: | Restify uses Bunyan for its logging. One feature of its integration, is that |
| 222: | each restify request handler includes a `req.log` logger that is: |
| 223: | |
| 224: | log.child({req_id: <unique request id>}, true) |
| 225: | |
| 226: | Apps using restify can then use `req.log` and have all such log records |
| 227: | include the unique request id (as "req_id"). Handy. |
| 228: | |
| 229: | |
| 230: | ## Serializers |
| 231: | |
| 232: | Bunyan has a concept of **"serializers" to produce a JSON-able object from a |
| 233: | JavaScript object**, so you can easily do the following: |
| 234: | |
| 235: | log.info({req: <request object>}, 'something about handling this request'); |
| 236: | |
| 237: | Serializers is a mapping of log record field name, "req" in this example, to |
| 238: | a serializer function. That looks like this: |
| 239: | |
| 240: | function reqSerializer(req) { |
| 241: | return { |
| 242: | method: req.method, |
| 243: | url: req.url, |
| 244: | headers: req.headers |
| 245: | } |
| 246: | } |
| 247: | var log = bunyan.createLogger({ |
| 248: | name: 'myapp', |
| 249: | serializers: { |
| 250: | req: reqSerializer |
| 251: | } |
| 252: | }); |
| 253: | |
| 254: | Or this: |
| 255: | |
| 256: | var log = bunyan.createLogger({ |
| 257: | name: 'myapp', |
| 258: | serializers: {req: bunyan.stdSerializers.req} |
| 259: | }); |
| 260: | |
| 261: | because Buyan includes a small set of standard serializers. To use all the |
| 262: | standard serializers you can use: |
| 263: | |
| 264: | var log = bunyan.createLogger({ |
| 265: | ... |
| 266: | serializers: bunyan.stdSerializers |
| 267: | }); |
| 268: | |
| 269: | **Note**: Your own serializers should never throw, otherwise you'll get an |
| 270: | ugly message on stderr from Bunyan (along with the traceback) and the field |
| 271: | in your log record will be replaced with a short error message. |
| 272: | |
| 273: | |
| 274: | ## src |
| 275: | |
| 276: | The **source file, line and function of the log call site** can be added to |
| 277: | log records by using the `src: true` config option: |
| 278: | |
| 279: | var log = bunyan.createLogger({src: true, ...}); |
| 280: | |
| 281: | This adds the call source info with the 'src' field, like this: |
| 282: | |
| 283: | { |
| 284: | "name": "src-example", |
| 285: | "hostname": "banana.local", |
| 286: | "pid": 123, |
| 287: | "component": "wuzzle", |
| 288: | "level": 4, |
| 289: | "msg": "This wuzzle is woosey.", |
| 290: | "time": "2012-02-06T04:19:35.605Z", |
| 291: | "src": { |
| 292: | "file": "/Users/trentm/tm/node-bunyan/examples/src.js", |
| 293: | "line": 20, |
| 294: | "func": "Wuzzle.woos" |
| 295: | }, |
| 296: | "v": 0 |
| 297: | } |
| 298: | |
| 299: | **WARNING: Determining the call source info is slow. Never use this option |
| 300: | in production.** |
| 301: | |
| 302: | |
| 303: | # Levels |
| 304: | |
| 305: | The log levels in bunyan are as follows. The level descriptions are best |
| 306: | practice *opinions*. |
| 307: | |
| 308: | - "fatal" (60): The service/app is going to stop or become unusable now. |
| 309: | An operator should definitely look into this soon. |
| 310: | - "error" (50): Fatal for a particular request, but the service/app continues |
| 311: | servicing other requests. An operator should look at this soon(ish). |
| 312: | - "warn" (40): A note on something that should probably be looked at by an |
| 313: | operator eventually. |
| 314: | - "info" (30): Detail on regular operation. |
| 315: | - "debug" (20): Anything else, i.e. too verbose to be included in "info" level. |
| 316: | - "trace" (10): Logging from external libraries used by your app or *very* |
| 317: | detailed application logging. |
| 318: | |
| 319: | Suggestions: Use "debug" sparingly. Information that will be useful to debug |
| 320: | errors *post mortem* should usually be included in "info" messages if it's |
| 321: | generally relevant or else with the corresponding "error" event. Don't rely |
| 322: | on spewing mostly irrelevant debug messages all the time and sifting through |
| 323: | them when an error occurs. |
| 324: | |
| 325: | Integers are used for the actual level values (10 for "trace", ..., 60 for |
| 326: | "fatal") and constants are defined for the (bunyan.TRACE ... bunyan.DEBUG). |
| 327: | The lowercase level names are aliases supported in the API. |
| 328: | |
| 329: | Here is the API for changing levels in an existing logger: |
| 330: | |
| 331: | log.level() -> INFO // gets current level (lowest level of all streams) |
| 332: | |
| 333: | log.level(INFO) // set all streams to level INFO |
| 334: | log.level("info") // set all streams to level INFO |
| 335: | |
| 336: | log.levels() -> [DEBUG, INFO] // get array of levels of all streams |
| 337: | log.levels(0) -> DEBUG // get level of stream at index 0 |
| 338: | log.levels("foo") // get level of stream with name "foo" |
| 339: | |
| 340: | log.levels(0, INFO) // set level of stream 0 to INFO |
| 341: | log.levels(0, "info") // can use "info" et al aliases |
| 342: | log.levels("foo", WARN) // set stream named "foo" to WARN |
| 343: | |
| 344: | |
| 345: | |
| 346: | # Log Record Fields |
| 347: | |
| 348: | This section will describe *rules* for the Bunyan log format: field names, |
| 349: | field meanings, required fields, etc. However, a Bunyan library doesn't |
| 350: | strictly enforce all these rules while records are being emitted. For example, |
| 351: | Bunyan will add a `time` field with the correct format to your log records, |
| 352: | but you can specify your own. It is the caller's responsibility to specify |
| 353: | the appropriate format. |
| 354: | |
| 355: | The reason for the above leniency is because IMO logging a message should |
| 356: | never break your app. This leads to this rule of logging: **a thrown |
| 357: | exception from `log.info(...)` or equivalent (other than for calling with the |
| 358: | incorrect signature) is always a bug in Bunyan.** |
| 359: | |
| 360: | |
| 361: | A typical Bunyan log record looks like this: |
| 362: | |
| 363: | {"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} |
| 364: | |
| 365: | Pretty-printed: |
| 366: | |
| 367: | { |
| 368: | "name": "myserver", |
| 369: | "hostname": "banana.local", |
| 370: | "pid": 123, |
| 371: | "req": { |
| 372: | "method": "GET", |
| 373: | "url": "/path?q=1#anchor", |
| 374: | "headers": { |
| 375: | "x-hi": "Mom", |
| 376: | "connection": "close" |
| 377: | }, |
| 378: | "remoteAddress": "120.0.0.1", |
| 379: | "remotePort": 51244 |
| 380: | }, |
| 381: | "level": 3, |
| 382: | "msg": "start request", |
| 383: | "time": "2012-02-03T19:02:57.534Z", |
| 384: | "v": 0 |
| 385: | } |
| 386: | |
| 387: | |
| 388: | Core fields: |
| 389: | |
| 390: | - `v`: Required. Integer. Added by Bunyan. Cannot be overriden. |
| 391: | This is the Bunyan log format version (`require('bunyan').LOG_VERSION`). |
| 392: | The log version is a single integer. `0` is until I release a version |
| 393: | "1.0.0" of node-bunyan. Thereafter, starting with `1`, this will be |
| 394: | incremented if there is any backward incompatible change to the log record |
| 395: | format. Details will be in "CHANGES.md" (the change log). |
| 396: | - `level`: Required. Integer. Added by Bunyan. Cannot be overriden. |
| 397: | See the "Levels" section. |
| 398: | - `name`: Required. String. Provided at Logger creation. |
| 399: | You must specify a name for your logger when creating it. Typically this |
| 400: | is the name of the service/app using Bunyan for logging. |
| 401: | - `hostname`: Required. String. Provided or determined at Logger creation. |
| 402: | You can specify your hostname at Logger creation or it will be retrieved |
| 403: | vi `os.hostname()`. |
| 404: | - `pid`: Required. Integer. Filled in automatically at Logger creation. |
| 405: | - `time`: Required. String. Added by Bunyan. Can be overriden. |
| 406: | The date and time of the event in [ISO 8601 |
| 407: | Extended Format](http://en.wikipedia.org/wiki/ISO_8601) format and in UTC, |
| 408: | as from |
| 409: | [`Date.toISOString()`](https://developer.mozilla.org/en/JavaScript/Reference/Global_Objects/Date/toISOString). |
| 410: | - `msg`: Required. String. |
| 411: | Every `log.debug(...)` et al call must provide a log message. |
| 412: | - `src`: Optional. Object giving log call source info. This is added |
| 413: | automatically by Bunyan if the "src: true" config option is given to the |
| 414: | Logger. Never use in production as this is really slow. |
| 415: | |
| 416: | |
| 417: | Go ahead and add more fields, and nested ones are fine (and recommended) as |
| 418: | well. This is why we're using JSON. Some suggestions and best practices |
| 419: | follow (feedback from actual users welcome). |
| 420: | |
| 421: | |
| 422: | Recommended/Best Practice Fields: |
| 423: | |
| 424: | - `err`: Object. A caught JS exception. Log that thing with `log.info(err)` |
| 425: | to get: |
| 426: | |
| 427: | ... |
| 428: | "err": { |
| 429: | "message": "boom", |
| 430: | "name": "TypeError", |
| 431: | "stack": "TypeError: boom\n at Object.<anonymous> ..." |
| 432: | }, |
| 433: | "msg": "boom", |
| 434: | ... |
| 435: | |
| 436: | Or use the `bunyan.stdSerializers.err` serializer in your Logger and |
| 437: | do this `log.error({err: err}, "oops")`. See "examples/err.js". |
| 438: | |
| 439: | - `req_id`: String. A request identifier. Including this field in all logging |
| 440: | tied to handling a particular request to your server is strongly suggested. |
| 441: | This allows post analysis of logs to easily collate all related logging |
| 442: | for a request. This really shines when you have a SOA with multiple services |
| 443: | and you carry a single request ID from the top API down through all APIs |
| 444: | (as [node-restify](https://github.com/mcavage/node-restify) facilitates |
| 445: | with its 'X-Request-Id' header). |
| 446: | |
| 447: | - `req`: An HTTP server request. Bunyan provides `bunyan.stdSerializers.req` |
| 448: | to serialize a request with a suggested set of keys. Example: |
| 449: | |
| 450: | { |
| 451: | "method": "GET", |
| 452: | "url": "/path?q=1#anchor", |
| 453: | "headers": { |
| 454: | "x-hi": "Mom", |
| 455: | "connection": "close" |
| 456: | }, |
| 457: | "remoteAddress": "120.0.0.1", |
| 458: | "remotePort": 51244 |
| 459: | } |
| 460: | |
| 461: | - `res`: An HTTP server response. Bunyan provides `bunyan.stdSerializers.res` |
| 462: | to serialize a response with a suggested set of keys. Example: |
| 463: | |
| 464: | { |
| 465: | "statusCode": 200, |
| 466: | "header": "HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nConnection: keep-alive\r\nTransfer-Encoding: chunked\r\n\r\n" |
| 467: | } |
| 468: | |
| 469: | |
| 470: | Other fields to consider: |
| 471: | |
| 472: | - `req.username`: Authenticated user (or for a 401, the user attempting to |
| 473: | auth). |
| 474: | - Some mechanism to calculate response latency. "restify" users will have |
| 475: | a "X-Response-Time" header. A `latency` custom field would be fine. |
| 476: | - `req.body`: If you know that request bodies are small (common in APIs, |
| 477: | for example), then logging the request body is good. |
| 478: | |
| 479: | |
| 480: | # Streams |
| 481: | |
| 482: | A "stream" is Bunyan's name for an output for log messages (the equivalent |
| 483: | to a log4j Appender). Ultimately Bunyan uses a |
| 484: | [Writable Stream](http://nodejs.org/docs/latest/api/all.html#writable_Stream) |
| 485: | interface, but there are some additional attributes used to create and |
| 486: | manage the stream. A Bunyan Logger instance has one or more streams. |
| 487: | In general streams are specified with the "streams" option: |
| 488: | |
| 489: | var bunyan = require('bunyan'); |
| 490: | var log = bunyan.createLogger({ |
| 491: | name: "foo", |
| 492: | streams: [ |
| 493: | { |
| 494: | stream: process.stderr, |
| 495: | level: "debug" |
| 496: | }, |
| 497: | ... |
| 498: | ] |
| 499: | }); |
| 500: | |
| 501: | For convenience, if there is only one stream, it can specified with the |
| 502: | "stream" and "level" options (internally converted to a `Logger.streams`). |
| 503: | |
| 504: | var log = bunyan.createLogger({ |
| 505: | name: "foo", |
| 506: | stream: process.stderr, |
| 507: | level: "debug" |
| 508: | }); |
| 509: | |
| 510: | Note that "file" streams do not support this shortcut (partly for historical |
| 511: | reasons and partly to not make it difficult to add a literal "path" field |
| 512: | on log records). |
| 513: | |
| 514: | If neither "streams" nor "stream" are specified, the default is a stream of |
| 515: | type "stream" emitting to `process.stdout` at the "info" level. |
| 516: | |
| 517: | |
| 518: | ## stream errors |
| 519: | |
| 520: | Bunyan re-emits error events from the created `WriteStream`. So you can |
| 521: | do this: |
| 522: | |
| 523: | var log = bunyan.createLogger({name: 'mylog', streams: [{path: LOG_PATH}]}); |
| 524: | log.on('error', function (err, stream) { |
| 525: | // Handle stream write or create error here. |
| 526: | }); |
| 527: | |
| 528: | |
| 529: | ## stream type: `stream` |
| 530: | |
| 531: | A `type === 'stream'` is a plain ol' node.js [Writable |
| 532: | Stream](http://nodejs.org/docs/latest/api/all.html#writable_Stream). A |
| 533: | "stream" (the writeable stream) field is required. E.g.: `process.stdout`, |
| 534: | `process.stderr`. |
| 535: | |
| 536: | var log = bunyan.createLogger({ |
| 537: | name: 'foo', |
| 538: | streams: [{ |
| 539: | stream: process.stderr |
| 540: | // `type: 'stream'` is implied |
| 541: | }] |
| 542: | }); |
| 543: | |
| 544: | <table> |
| 545: | <tr> |
| 546: | <th>Field</th> |
| 547: | <th>Required?</th> |
| 548: | <th>Default</th> |
| 549: | <th>Description</th> |
| 550: | </tr> |
| 551: | <tr> |
| 552: | <td>stream</td> |
| 553: | <td>Yes</td> |
| 554: | <td>-</td> |
| 555: | <td>A "Writable Stream", e.g. a std handle or an open file write stream.</td> |
| 556: | </tr> |
| 557: | <tr> |
| 558: | <td>type</td> |
| 559: | <td>No</td> |
| 560: | <td>n/a</td> |
| 561: | <td>`type == 'stream'` is implied if the `stream` field is given.</td> |
| 562: | </tr> |
| 563: | <tr> |
| 564: | <td>level</td> |
| 565: | <td>No</td> |
| 566: | <td>info</td> |
| 567: | <td>The level at which logging to this stream is enabled. If not |
| 568: | specified it defaults to "info". If specified this can be one of the |
| 569: | level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`, |
| 570: | `bunyan.DEBUG`, ...).</td> |
| 571: | </tr> |
| 572: | <tr> |
| 573: | <td>name</td> |
| 574: | <td>No</td> |
| 575: | <td>-</td> |
| 576: | <td>A name for this stream. This may be useful for usage of `log.level(NAME, |
| 577: | LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't |
| 578: | used for anything else.</td> |
| 579: | </tr> |
| 580: | </table> |
| 581: | |
| 582: | |
| 583: | ## stream type: `file` |
| 584: | |
| 585: | A `type === 'file'` stream requires a "path" field. Bunyan will open this |
| 586: | file for appending. E.g.: |
| 587: | |
| 588: | var log = bunyan.createLogger({ |
| 589: | name: 'foo', |
| 590: | streams: [{ |
| 591: | path: '/var/log/foo.log', |
| 592: | // `type: 'file'` is implied |
| 593: | }] |
| 594: | }); |
| 595: | |
| 596: | <table> |
| 597: | <tr> |
| 598: | <th>Field</th> |
| 599: | <th>Required?</th> |
| 600: | <th>Default</th> |
| 601: | <th>Description</th> |
| 602: | </tr> |
| 603: | <tr> |
| 604: | <td>path</td> |
| 605: | <td>Yes</td> |
| 606: | <td>-</td> |
| 607: | <td>A file path to which to log.</td> |
| 608: | </tr> |
| 609: | <tr> |
| 610: | <td>type</td> |
| 611: | <td>No</td> |
| 612: | <td>n/a</td> |
| 613: | <td>`type == 'file'` is implied if the `path` field is given.</td> |
| 614: | </tr> |
| 615: | <tr> |
| 616: | <td>level</td> |
| 617: | <td>No</td> |
| 618: | <td>info</td> |
| 619: | <td>The level at which logging to this stream is enabled. If not |
| 620: | specified it defaults to "info". If specified this can be one of the |
| 621: | level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`, |
| 622: | `bunyan.DEBUG`, ...).</td> |
| 623: | </tr> |
| 624: | <tr> |
| 625: | <td>name</td> |
| 626: | <td>No</td> |
| 627: | <td>-</td> |
| 628: | <td>A name for this stream. This may be useful for usage of `log.level(NAME, |
| 629: | LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't |
| 630: | used for anything else.</td> |
| 631: | </tr> |
| 632: | </table> |
| 633: | |
| 634: | |
| 635: | ## stream type: `rotating-file` |
| 636: | |
| 637: | A `type === 'rotating-file'` is a file stream that handles file automatic |
| 638: | rotation. |
| 639: | |
| 640: | var log = bunyan.createLogger({ |
| 641: | name: 'foo', |
| 642: | streams: [{ |
| 643: | type: 'rotating-file', |
| 644: | path: '/var/log/foo.log', |
| 645: | period: '1d', // daily rotation |
| 646: | count: 3 // keep 3 back copies |
| 647: | }] |
| 648: | }); |
| 649: | |
| 650: | This will rotate '/var/log/foo.log' every day (at midnight) to: |
| 651: | |
| 652: | /var/log/foo.log.0 # yesterday |
| 653: | /var/log/foo.log.1 # 1 day ago |
| 654: | /var/log/foo.log.2 # 2 days ago |
| 655: | |
| 656: | *Currently*, there is no support for providing a template for the rotated |
| 657: | files, or for rotating when the log reaches a threshold size. |
| 658: | |
| 659: | <table> |
| 660: | <tr> |
| 661: | <th>Field</th> |
| 662: | <th>Required?</th> |
| 663: | <th>Default</th> |
| 664: | <th>Description</th> |
| 665: | </tr> |
| 666: | <tr> |
| 667: | <td>type</td> |
| 668: | <td>Yes</td> |
| 669: | <td>-</td> |
| 670: | <td>"rotating-file"</td> |
| 671: | </tr> |
| 672: | <tr> |
| 673: | <td>path</td> |
| 674: | <td>Yes</td> |
| 675: | <td>-</td> |
| 676: | <td>A file path to which to log. Rotated files will be "$path.0", |
| 677: | "$path.1", ...</td> |
| 678: | </tr> |
| 679: | <tr> |
| 680: | <td>period</td> |
| 681: | <td>No</td> |
| 682: | <td>1d</td> |
| 683: | <td>The period at which to rotate. This is a string of the format |
| 684: | "$number$scope" where "$scope" is one of "h" (hours), "d" (days), "w" (weeks), |
| 685: | "m" (months), "y" (years). Or one of the following names can be used |
| 686: | "hourly" (means 1h), "daily" (1d), "weekly" (1w), "monthly" (1m), |
| 687: | "yearly" (1y). Rotation is done at the start of the scope: top of the hour (h), |
| 688: | midnight (d), start of Sunday (w), start of the 1st of the month (m), |
| 689: | start of Jan 1st (y).</td> |
| 690: | </tr> |
| 691: | <tr> |
| 692: | <td>count</td> |
| 693: | <td>No</td> |
| 694: | <td>10</td> |
| 695: | <td>The number of rotated files to keep.</td> |
| 696: | </tr> |
| 697: | <tr> |
| 698: | <td>level</td> |
| 699: | <td>No</td> |
| 700: | <td>info</td> |
| 701: | <td>The level at which logging to this stream is enabled. If not |
| 702: | specified it defaults to "info". If specified this can be one of the |
| 703: | level strings ("trace", "debug", ...) or constants (`bunyan.TRACE`, |
| 704: | `bunyan.DEBUG`, ...).</td> |
| 705: | </tr> |
| 706: | <tr> |
| 707: | <td>name</td> |
| 708: | <td>No</td> |
| 709: | <td>-</td> |
| 710: | <td>A name for this stream. This may be useful for usage of `log.level(NAME, |
| 711: | LEVEL)`. See the [Levels section](#levels) for details. A stream "name" isn't |
| 712: | used for anything else.</td> |
| 713: | </tr> |
| 714: | </table> |
| 715: | |
| 716: | |
| 717: | |
| 718: | ## stream type: `raw` |
| 719: | |
| 720: | - `raw`: Similar to a "stream" writeable stream, except that the write method |
| 721: | is given raw log record *Object*s instead of a JSON-stringified string. |
| 722: | This can be useful for hooking on further processing to all Bunyan logging: |
| 723: | pushing to an external service, a RingBuffer (see below), etc. |
| 724: | |
| 725: | |
| 726: | |
| 727: | ## `raw` + RingBuffer Stream |
| 728: | |
| 729: | Bunyan comes with a special stream called a RingBuffer which keeps the last N |
| 730: | records in memory and does *not* write the data anywhere else. One common |
| 731: | strategy is to log 'info' and higher to a normal log file but log all records |
| 732: | (including 'trace') to a ringbuffer that you can access via a debugger, or your |
| 733: | own HTTP interface, or a post-mortem facility like MDB or node-panic. |
| 734: | |
| 735: | To use a RingBuffer: |
| 736: | |
| 737: | /* Create a ring buffer that stores the last 100 records. */ |
| 738: | var bunyan = require('bunyan'); |
| 739: | var ringbuffer = new bunyan.RingBuffer({ limit: 100 }); |
| 740: | var log = bunyan.createLogger({ |
| 741: | name: 'foo', |
| 742: | streams: [ |
| 743: | { |
| 744: | level: 'info', |
| 745: | stream: process.stdout |
| 746: | }, |
| 747: | { |
| 748: | level: 'trace', |
| 749: | type: 'raw', // use 'raw' to get raw log record objects |
| 750: | stream: ringbuffer |
| 751: | } |
| 752: | ] |
| 753: | }); |
| 754: | |
| 755: | log.info('hello world'); |
| 756: | console.log(ringbuffer.records); |
| 757: | |
| 758: | This example emits: |
| 759: | |
| 760: | [ { name: 'foo', |
| 761: | hostname: '912d2b29', |
| 762: | pid: 50346, |
| 763: | level: 30, |
| 764: | msg: 'hello world', |
| 765: | time: '2012-06-19T21:34:19.906Z', |
| 766: | v: 0 } ] |
| 767: | |
| 768: | |
| 769: | ## third-party streams |
| 770: | |
| 771: | - syslog: |
| 772: | [mcavage/node-bunyan-syslog](https://github.com/mcavage/node-bunyan-syslog) |
| 773: | provides support for directing bunyan logging to a syslog server. |
| 774: | |
| 775: | - TODO: eventually https://github.com/trentm/node-bunyan-winston |
| 776: | |
| 777: | |
| 778: | |
| 779: | # DTrace support |
| 780: | |
| 781: | On systems that support DTrace (e.g., MacOS, FreeBSD, illumos derivatives |
| 782: | like SmartOS and OmniOS), Bunyan will create a DTrace provider (`bunyan`) |
| 783: | that makes available the following probes: |
| 784: | |
| 785: | log-trace |
| 786: | log-debug |
| 787: | log-info |
| 788: | log-warn |
| 789: | log-error |
| 790: | log-fatal |
| 791: | |
| 792: | Each of these probes has a single argument: the string that would be |
| 793: | written to the log. Note that when a probe is enabled, it will |
| 794: | fire whenever the corresponding function is called, even if the level of |
| 795: | the log message is less than that of any stream. |
| 796: | |
| 797: | |
| 798: | ## DTrace examples |
| 799: | |
| 800: | Trace all log messages coming from any Bunyan module on the system. |
| 801: | (The `-x strsize=4k` is to raise dtrace's default 256 byte buffer size |
| 802: | because log messages are longer than typical dtrace probes.) |
| 803: | |
| 804: | dtrace -x strsize=4k -qn 'bunyan*:::log-*{printf("%d: %s: %s", pid, probefunc, copyinstr(arg0))}' |
| 805: | |
| 806: | Trace all log messages coming from the "wuzzle" component: |
| 807: | |
| 808: | dtrace -x strsize=4k -qn 'bunyan*:::log-*/strstr(this->str = copyinstr(arg0), "\"component\":\"wuzzle\"") != NULL/{printf("%s", this->str)}' |
| 809: | |
| 810: | Aggregate debug messages from process 1234, by message: |
| 811: | |
| 812: | dtrace -x strsize=4k -n 'bunyan1234:::log-debug{@[copyinstr(arg0)] = count()}' |
| 813: | |
| 814: | Have the bunyan CLI pretty-print the traced logs: |
| 815: | |
| 816: | dtrace -x strsize=4k -qn 'bunyan1234:::log-*{printf("%s", copyinstr(arg0))}' | bunyan |
| 817: | |
| 818: | A convenience handle has been made for this: |
| 819: | |
| 820: | bunyan -p 1234 |
| 821: | |
| 822: | |
| 823: | On systems that support the |
| 824: | [`jstack`](http://dtrace.org/blogs/dap/2012/04/25/profiling-node-js/) action |
| 825: | via a node.js helper, get a stack backtrace for any debug message that |
| 826: | includes the string "danger!": |
| 827: | |
| 828: | dtrace -x strsize=4k -qn 'log-debug/strstr(copyinstr(arg0), "danger!") != NULL/{printf("\n%s", copyinstr(arg0)); jstack()}' |
| 829: | |
| 830: | Output of the above might be: |
| 831: | |
| 832: | {"name":"foo","hostname":"763bf293-d65c-42d5-872b-4abe25d5c4c7.local","pid":12747,"level":20,"msg":"danger!","time":"2012-10-30T18:28:57.115Z","v":0} |
| 833: | |
| 834: | node`0x87e2010 |
| 835: | DTraceProviderBindings.node`usdt_fire_probe+0x32 |
| 836: | DTraceProviderBindings.node`_ZN4node11DTraceProbe5_fireEN2v85LocalINS1_5ValueEEE+0x32d |
| 837: | DTraceProviderBindings.node`_ZN4node11DTraceProbe4FireERKN2v89ArgumentsE+0x77 |
| 838: | << internal code >> |
| 839: | (anon) as (anon) at /root/node-bunyan/lib/bunyan.js position 40484 |
| 840: | << adaptor >> |
| 841: | (anon) as doit at /root/my-prog.js position 360 |
| 842: | (anon) as list.ontimeout at timers.js position 4960 |
| 843: | << adaptor >> |
| 844: | << internal >> |
| 845: | << entry >> |
| 846: | node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 |
| 847: | node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xcb |
| 848: | node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 |
| 849: | node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11f |
| 850: | node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x66 |
| 851: | node`_ZN4node9TimerWrap9OnTimeoutEP10uv_timer_si+0x63 |
| 852: | node`uv__run_timers+0x66 |
| 853: | node`uv__run+0x1b |
| 854: | node`uv_run+0x17 |
| 855: | node`_ZN4node5StartEiPPc+0x1d0 |
| 856: | node`main+0x1b |
| 857: | node`_start+0x83 |
| 858: | |
| 859: | node`0x87e2010 |
| 860: | DTraceProviderBindings.node`usdt_fire_probe+0x32 |
| 861: | DTraceProviderBindings.node`_ZN4node11DTraceProbe5_fireEN2v85LocalINS1_5ValueEEE+0x32d |
| 862: | DTraceProviderBindings.node`_ZN4node11DTraceProbe4FireERKN2v89ArgumentsE+0x77 |
| 863: | << internal code >> |
| 864: | (anon) as (anon) at /root/node-bunyan/lib/bunyan.js position 40484 |
| 865: | << adaptor >> |
| 866: | (anon) as doit at /root/my-prog.js position 360 |
| 867: | (anon) as list.ontimeout at timers.js position 4960 |
| 868: | << adaptor >> |
| 869: | << internal >> |
| 870: | << entry >> |
| 871: | node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 |
| 872: | node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xcb |
| 873: | node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 |
| 874: | node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11f |
| 875: | node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x66 |
| 876: | node`_ZN4node9TimerWrap9OnTimeoutEP10uv_timer_si+0x63 |
| 877: | node`uv__run_timers+0x66 |
| 878: | node`uv__run+0x1b |
| 879: | node`uv_run+0x17 |
| 880: | node`_ZN4node5StartEiPPc+0x1d0 |
| 881: | node`main+0x1b |
| 882: | node`_start+0x83 |
| 883: | |
| 884: | |
| 885: | # Versioning |
| 886: | |
| 887: | The scheme I follow is most succintly described by the bootstrap guys |
| 888: | [here](https://github.com/twitter/bootstrap#versioning). |
| 889: | |
| 890: | tl;dr: All versions are `<major>.<minor>.<patch>` which will be incremented for |
| 891: | breaking backward compat and major reworks, new features without breaking |
| 892: | change, and bug fixes, respectively. |
| 893: | |
| 894: | |
| 895: | # License |
| 896: | |
| 897: | MIT. See "LICENSE.txt". |
| 898: | |
| 899: | |
| 900: | # See Also |
| 901: | |
| 902: | - Bunyan syslog support: <https://github.com/mcavage/node-bunyan-syslog>. |
| 903: | - Bunyan + Graylog2: <https://github.com/mhart/gelf-stream>. |
| 904: | - An example of a Bunyan shim to the Winston logging system: |
| 905: | <https://github.com/trentm/node-bunyan-winston>. |
| 906: | - [Bunyan for Bash](https://github.com/trevoro/bash-bunyan). |
| 907: | - TODO: `RequestCaptureStream` example from restify. |
