0.2: specing core log record fields (mainly)

.gitignore

@@ -1,2 +1,3 @@
 /tmp
 /npm-debug.log
+/node_modules

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

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

TODO.md

@@ -4,6 +4,8 @@
     <http://journal.paul.querna.org/articles/2011/12/26/log-for-machines-in-json/>
     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: <https://github.com/trentm/node-bunyan/blob/master/examples/multi.js#L4-13>
-  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.

bin/bunyan

@@ -5,11 +5,12 @@
 // See <https://github.com/trentm/node-bunyan>.
 //
 
-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))

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;
 
 

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": {