From a475a1ac09b79b6708344b78e3f04e8ea0a7d0a7 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Fri, 3 Feb 2012 17:05:13 -0800 Subject: [PATCH] 0.2: specing core log record fields (mainly) --- .gitignore | 1 + CHANGES.md | 6 ++- README.md | 135 ++++++++++++++++++++++++++++++++++++++++++++------ TODO.md | 33 ++++++++++-- bin/bunyan | 23 +++++++-- lib/bunyan.js | 25 +++++----- package.json | 2 +- 7 files changed, 185 insertions(+), 40 deletions(-) diff --git a/.gitignore b/.gitignore index 1fcdc43..39a7c5c 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,3 @@ /tmp /npm-debug.log +/node_modules diff --git a/CHANGES.md b/CHANGES.md index a580584..b3b27d4 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -1,8 +1,10 @@ # bunyan Changelog -## bunyan 0.1.1 (not yet released) +## bunyan 0.2.0 (not yet released) -(nothing yet) +- Spec'ing core/recommended log record fields. +- Add `LOG_VERSION` to exports. +- Improvements to request/response serializations. ## bunyan 0.1.0 diff --git a/README.md b/README.md index 6576b5c..676dd90 100644 --- a/README.md +++ b/README.md @@ -19,7 +19,7 @@ base soonish. # Usage **The usual.** All loggers must provide a "service" name. This is somewhat akin -to log4j logger "name", but Bunyan doesn't so hierarchical logger names. +to log4j logger "name", but Bunyan doesn't do hierarchical logger names. $ cat hi.js var Logger = require('bunyan'); @@ -164,12 +164,12 @@ See "TODO.md", but basically: # Levels -- "fatal": the service is going to stop or become unusable now -- "error": fatal for a particular request, but the service continues servicing other requests -- "warn": a note on something that should probably be looked at by an operator -- "info": detail on regular operation -- "debug": anything else, i.e. too verbose to be included in "info" level. -- "trace": logging from external libraries used by your app +- "fatal" (6): the service is going to stop or become unusable now +- "error" (5): fatal for a particular request, but the service continues servicing other requests +- "warn" (4): a note on something that should probably be looked at by an operator +- "info" (3): detail on regular operation +- "debug" (2): anything else, i.e. too verbose to be included in "info" level. +- "trace" (1): logging from external libraries used by your app "debug" should be used sparingly. Information that will be useful to debug errors *post mortem* should usually be included in "info" messages if it's @@ -177,19 +177,124 @@ generally relevant or else with the corresponding "error" event. Don't rely on spewing mostly irrelevant debug messages all the time and sifting through them when an error occurs. -Integers are used for the actual level values (1 for "trace", ..., 6 for "fatal") and -constants are defined for the (Logger.TRACE ... Logger.DEBUG). The lowercase -level names are aliases supported in the API. +Integers are used for the actual level values (1 for "trace", ..., 6 for +"fatal") and constants are defined for the (Logger.TRACE ... Logger.DEBUG). +The lowercase level names are aliases supported in the API. # Log Record Fields -TODO: from dap and enforce these +This section will describe *rules* for the Bunyan log format: field names, +field meanings, required fields, etc. However, a Bunyan library doesn't +strictly enforce all these rules while records are being emitted. For example, +Bunyan will add a `time` field with the correct format to your log records, +but you can specify your own. It is the caller's responsibility to specify +the appropriate format. -- "request\_id" (better name?) can't be required because some things don't - happen in a per-request context. Startup and background processing stuff - for example. Tho for request-y things, it is strongly encouraged because it - allows collating logs from multiple services for the same request. +The reason for the above leniency is because IMO logging a message should +never break your app. This leads to this rule of logging: **a thrown +exception from `log.info(...)` or equivalent (other than for calling with the +incorrect signature) is always a bug in Bunyan.** + + +A typical Bunyan log record looks like this: + + {"service":"myserver","hostname":"banana.local","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} + +Pretty-printed: + + { + "service": "myserver", + "hostname": "banana.local", + "req": { + "method": "GET", + "url": "/path?q=1#anchor", + "headers": { + "x-hi": "Mom", + "connection": "close" + }, + "remoteAddress": "120.0.0.1", + "remotePort": 51244 + }, + "level": 3, + "msg": "start request", + "time": "2012-02-03T19:02:57.534Z", + "v": 0 + } + + +Core fields: + +- `v`: Required. Integer. Added by Bunion. Cannot be overriden. + This is the Bunyan log format version (`require('bunyan').LOG_VERSION`). + The log version is a single integer. `0` is until I release a version + "1.0.0" of node-bunyan. Thereafter, starting with `1`, this will be + incremented if there is any backward incompatible change to the log record + format. Details will be in "CHANGES.md" (the change log). +- `level`: Required. Integer. Added by Bunion. Cannot be overriden. + See the "Levels" section. +- `service`: Required. String. Provided at Logger creation. + You must specify a service name for your logger when creating it. +- `hostname`: Required. String. Provided or determined at Logger creation. + You can specify your hostname at Logger creation or it will be retrieved + vi `os.hostname()`. +- `time`: Required. String. Added by Bunion. Can be overriden. + The date and time of the event in [ISO 8601 + Extended Format](http://en.wikipedia.org/wiki/ISO_8601) format and in UTC, + as from + [`Date.toISOString()`](https://developer.mozilla.org/en/JavaScript/Reference/Global_Objects/Date/toISOString). +- `msg`: Required. String. + Every `log.debug(...)` et al call must provide a log message. + + +Go ahead and add more fields, and nest ones are fine (and recommended) as +well. This is why we're using JSON. Some suggestions and best practices +follow (feedback from actual users welcome). + + +Recommended/Best Practice Fields: + +- `err`: Object. A caught JS exception. Log that thing with + `log.error({err: err}, "oops")`! JS exceptions `JSON.stringify` quite + nicely so you don't need to do anything else. See "examples/err.js". +- `req_id`: String. A request identifier. Including this field in all logging + tied to handling a particular request to your server is strongly suggested. + This allows post analysis of logs to easily collate all related logging + for a request. This really shines when you have a SOA with multiple services + and you carry a single request ID from the top API down through all APIs + (as [node-restify](https://github.com/mcavage/node-restify) facilitates + with its 'X-Request-Id' header). +- `req`: An HTTP server request. Bunyan provides `Logger.stdSerializers.req` + to serialize a request with a suggested set of keys. Example: + + { + "method": "GET", + "url": "/path?q=1#anchor", + "headers": { + "x-hi": "Mom", + "connection": "close" + }, + "remoteAddress": "120.0.0.1", + "remotePort": 51244 + } + +- `res`: An HTTP server response. Bunyan provides `Logger.stdSerializers.res` + to serialize a response with a suggested set of keys. Example: + + { + "statusCode": 200, + "header": "HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nConnection: keep-alive\r\nTransfer-Encoding: chunked\r\n\r\n" + } + + +Other fields to consider: + +- `req.username`: Authenticated user (or for a 401, the user attempting to + auth). +- Some mechanism to calculate response latency. "restify" users will have + a "X-Response-Time" header. A `latency` custom field would be fine. +- `req.body`: If you know that request bodies are small (common in APIs, + for example), then logging the request body is good. # Streams diff --git a/TODO.md b/TODO.md index 021d1b1..1a6f1b1 100644 --- a/TODO.md +++ b/TODO.md @@ -4,6 +4,8 @@ require: facility and hostname line/file: possible to get quickly with v8? Yunong asked. +- fast clone: basically make it reasonable to clone per HTTP request. + Ditch mutability. Add another context (another entry in Log record tuple?)? - `log.close` to close streams and shutdown and `this.closed` - bunyan cli: more layouts (http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/EnhancedPatternLayout.html) Custom log formats (in config file? in '-f' arg) using printf or hogan.js @@ -42,15 +44,38 @@ # someday/maybe -- custom "emitter" feature: an additional "emitter" param on the "streams" - objects: - which you'd give instead of "stream" (a node "Writable Stream"). - It would take a Bunyan log record object and be expected to emit it. +- file/line fields automatic: "but it's fucking slow" (https://gist.github.com/1733234) + function getFileAndLine() { + var self = this; + var saveLimit = Error.stackTraceLimit; + var savePrepare = Error.prepareStackTrace; + Error.stackTraceLimit = 1; + Error.captureStackTrace(this, getFileAndLine); + Error.prepareStackTrace = function(_, stack) { + self.file = stack[0].getFileName(); + self.line = stack[0].getLineNumber(); + }; + this.stack; + Error.stackTraceLimit = saveLimit; + Error.prepareStackTrace = savePrepare; + return { + file: self.file, + line: self.line + } + } + Want some way to have file/line only at certain levesl and lazily. +- add option to "streams" to take the raw object, not serialized. It would be a good hook for people with custom needs that Bunyan doesn't care about (e.g. log.ly or hook.io or whatever). +- split out `bunyan` cli to a "bunyan" or "bunyan-reader" or "node-bunyan-reader" + as the basis for tools to consume bunyan logs. It can grow indep of node-bunyan + for generating the logs. + It would take a Bunyan log record object and be expected to emit it. - serializer `request_id` that pulls it from req? `log.info({request_id: req}, "hi")` - serializer support: - restify-server.js example -> restifyReq ? or have `req` detect that. That is nicer for the "use all standard ones". *Does* restify req have anything special? - differential HTTP *client* req/res with *server* req/res. +- statsd stream? http://codeascraft.etsy.com/2011/02/15/measure-anything-measure-everything/ + Think about it. diff --git a/bin/bunyan b/bin/bunyan index 6594409..23a2e9b 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -5,11 +5,12 @@ // See . // -var VERSION = "0.1.1"; +var VERSION = "0.2.0"; var util = require('util'); var pathlib = require('path'); var vm = require('vm'); +var http = require('http'); var warn = console.warn; @@ -277,15 +278,27 @@ function handleLogLine(line, opts) { } if (rec.req) { var headers = rec.req.headers; - details.push(indent(format("%s %s\n%s", rec.req.method, + details.push(indent(format("%s %s HTTP/1.1\n%s", rec.req.method, rec.req.url, Object.keys(headers).map( function (h) { return h + ': ' + headers[h]}).join('\n')))); } if (rec.res) { - var s = rec.res._header.trimRight() - + (rec.res._hasBody ? '\n(body)\n' : '') + rec.res._trailer; - details.push(indent(s.trimRight())); + var s = ''; + if (rec.res.header) { + s += rec.res.header.trimRight() + } else if (rec.res.headers) { + if (rec.res.statusCode) { + s += format("HTTP/1.1 %s %s\n", rec.res.statusCode, + http.STATUS_CODES[rec.res.statusCode]); + } + var headers = rec.res.headers; + s += Object.keys(headers).map( + function (h) { return h + ': ' + headers[h]}).join('\n'); + } + if (s) { + details.push(indent(s)); + } } if (rec.err && rec.err.stack) { details.push(indent(rec.err.stack)) diff --git a/lib/bunyan.js b/lib/bunyan.js index fc77352..eb5c0ca 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -2,7 +2,7 @@ * Copyright 2012 (c) Trent Mick. All rights reserved. */ -var VERSION = "0.1.1"; +var VERSION = "0.2.0"; // Bunyan log format version. This becomes the 'v' field on all log records. // `0` is until I release a version "1.0.0" of node-bunyan. Thereafter, @@ -585,35 +585,34 @@ Logger.stdSerializers = {}; // Serialize an HTTP request. Logger.stdSerializers.req = function req(req) { - // trailers? upgrade? httpVersion? complete? readable? - // Limit headers? return { method: req.method, url: req.url, - headers: req.headers - } + headers: req.headers, + remoteAddress: req.connection.remoteAddress, + remotePort: req.connection.remotePort + }; + // Trailers: Skipping for speed. If you need trailers in your app, then + // make a custom serializers. + //if (Object.keys(trailers).length > 0) { + // obj.trailers = req.trailers; + //} }; // Serialize an HTTP response. Logger.stdSerializers.res = function res(res) { - // _headerSent? - // Limit headers? return { statusCode: res.statusCode, - _hasBody: res._hasBody, - _header: res._header, - _trailer: res._trailer, - method: res.method, + header: res._header } }; - - //---- Exports module.exports = Logger; module.exports.VERSION = VERSION; +module.exports.LOG_VERSION = LOG_VERSION; diff --git a/package.json b/package.json index bc8f39c..3893ea8 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "bunyan", - "version": "0.1.1", + "version": "0.2.0", "description": "a JSON Logger library for node.js servers", "main": "./lib/bunyan.js", "bin": {