add TRACE level (use for external libraries). Also, some doc updates.

README.md

@@ -14,27 +14,27 @@ Just play stuff here. Don't try to use this for realz yet.
 
 # Usage
 
-The usual. All loggers must provide a "service" name. This is somewhat akin
+**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.
 
     $ cat hi.js
     var Logger = require('bunyan');
-    var log = new Logger({service: "myapp", level: "info"});
+    var log = new Logger({service: "myapp"});
     log.info("hi");
 
-Log records are JSON. "hostname", "time" and "v" (the Bunyan log
+**Log records are JSON.** "hostname", "time" and "v" (the Bunyan log
 format version) are added for you.
 
     $ node hi.js
     {"service":"myapp","hostname":"banana.local","level":2,"msg":"hi","time":"2012-01-31T00:07:44.216Z","v":0}
 
-A `bunyan` tool is provided for pretty-printing bunyan logs and, eventually,
+A **`bunyan` tool is provided for pretty-printing** bunyan logs and, eventually,
 for filtering (e.g. `| bunyan -c 'level>3'`). This shows the default output
 (which is fluid right now) and indented-JSON output. More output formats will
 be added, including support for custom formats.
 
     $ node hi.js | ./bin/bunyan  # CLI tool to filter/pretty-print JSON logs.
-    [2012-01-31T00:08:11.387Z] INFO: myapp on banana.local: hi (<no-request_id>)
+    [2012-01-31T00:08:11.387Z] INFO: myapp on banana.local: hi
     
     $ node hi.js | ./bin/bunyan -o json
     {
@@ -46,12 +46,14 @@ be added, including support for custom formats.
       "v": 0
     }
 
-By default, log output is to stdout. Explicitly that looks like:
+By default, log output is to stdout (**stream**) and at the "info" level.
+Explicitly that looks like:
 
-    var log = new Logger({service: "myapp", stream: process.stdout});
+    var log = new Logger({service: "myapp", stream: process.stdout, 
+      level: "info"});
 
-That is an abbreviated form for a single stream. You can defined multiple
+That is an abbreviated form for a single stream. **You can defined multiple
-streams at different levels:
+streams at different levels**.
 
     var log = new Logger({
       service: "amon",
@@ -67,20 +69,19 @@ streams at different levels:
       ]
     });
 
-Support for syslog is planned.
 
 
 # Future
 
 See "TODO.md", but basically:
 
-- "Renderer" support to handle extracting a JSON object for a log record
+- "Serializer" support to handle extracting a JSON object for a log record
   for particular object types, e.g. an HTTP request. So for example we
   could do:
   
         log.info({req: req}, "something about handling this request")
 
-  And the "req" renderer would extract a reasonable JSON object for that
+  And the "req" serializer would extract a reasonable JSON object for that
   request object -- presumably a subset of all attributes on the request
   object.
   
@@ -101,25 +102,47 @@ See "TODO.md", but basically:
 
 # Levels
 
-    fatal
+- "fatal": the service is going to stop or become unusable now
-    error
+- "error": fatal for a particular request, but the service continues servicing other requests
-    warn
+- "warn": a note on something that should probably be looked at by an operator
-    info
+- "info": detail on regular operation
-    debug
+- "debug": anything else, i.e. too verbose to be included in "info" level.
+- "trace": logging from external libraries used by your app
 
-TODO: doc these.
+"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
+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.
 
 
 # Log Record Fields
 
 TODO: from dap and enforce these
 
-- "request_id" (better name?) can't be required because some things don't
+- "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.
 
 
+# Streams
+
+A "stream" is Bunyan's name for an output for log messages. It expects a
+[Writable Stream](http://nodejs.org/docs/latest/api/all.html#writable_Stream)
+interface. See above for some examples of specifying streams. Supported streams
+are:
+
+- A writable "stream". Often this is one of the std handles (`process.stdout` or
+  `process.stderr`), but it can be anything you want supporting the node
+  writable stream interface, e.g. `fs.createWriteStream`.
+- A file. Will append to the given "path". 
+
+
 # License
 
 MIT.

TODO.md

@@ -1,5 +1,7 @@
 - add `clone` to readme
-- renderer support (i.e. repr of a restify request obj)
+- serializer support (i.e. repr of a restify request obj):
+    server.js example
+    restify-server.js example
 - 'x' extra fields object or no? discuss
 - expand set of fields: from dap
     time, hostname
@@ -35,3 +37,15 @@
     - test for a cloned logger double-`stream.end()` causing problems.
       Perhaps the "closeOnExit" for existing streams should be false for
       clones.
+- a "rolling-file" stream: but specifically by time, e.g. hourly. (MarkC
+  requested)
+
+
+# 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.
+  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).

bin/bunyan

@@ -30,13 +30,15 @@ var OM_FROM_NAME = {
 
 
 // Levels
-var DEBUG = 1;
+var TRACE = 1;
-var INFO = 2;
+var DEBUG = 2;
-var WARN = 3;
+var INFO = 3;
-var ERROR = 4;
+var WARN = 4;
-var FATAL = 5;
+var ERROR = 5;
+var FATAL = 6;
 
 var levelFromName = {
+  'trace': TRACE,
   'debug': DEBUG,
   'info': INFO,
   'warn': WARN,
@@ -262,9 +264,9 @@ function handleLogLine(line, opts) {
   switch (opts.outputMode) {
   case OM_PAUL:
     // Single-line msg:
-    //    [time] LEVEL: service[/component] on hostname: msg (request_id, $latencyms)
+    //    [time] LEVEL: service[/component] on hostname: msg (extras...)
     // Multi-line msg:
-    //    [time] LEVEL: service[/component] on hostname: (request_id, $latencyms)
+    //    [time] LEVEL: service[/component] on hostname: (extras...)
     //        msg
     // Request/HTTP info:
     //    TODO

lib/bunyan.js

@@ -77,13 +77,15 @@ if (!format) {
 
 //---- Levels
 
-var DEBUG = 1;
+var TRACE = 1;
-var INFO = 2;
+var DEBUG = 2;
-var WARN = 3;
+var INFO = 3;
-var ERROR = 4;
+var WARN = 4;
-var FATAL = 5;
+var ERROR = 5;
+var FATAL = 6;
 
 var levelFromName = {
+  'trace': TRACE,
   'debug': DEBUG,
   'info': INFO,
   'warn': WARN,
@@ -127,7 +129,7 @@ function Logger(options) {
   var level;
   if (options.level) {
     level = getLevel(options.level);
-    if (! (DEBUG <= level && level <= FATAL)) {
+    if (! (TRACE <= level && level <= FATAL)) {
       throw new Error('invalid level: ' + options.level);
     }
     delete this.fields.level;
@@ -303,6 +305,36 @@ Logger.prototype._emit = function (rec) {
 }
 
 
+/**
+ * Log a record at TRACE level.
+ *
+ * Usages:
+ *    log.trace()  -> boolean is-trace-enabled
+ *    log.trace(<string> msg, ...)
+ *    log.trace(<object> fields, <string> msg, ...)
+ *
+ * @params fields {Object} Optional set of additional fields to log.
+ * @params msg {String} Log message. This can be followed by additional
+ *    arguments that are handled like
+ *    [util.format](http://nodejs.org/docs/latest/api/all.html#util.format).
+ */
+Logger.prototype.trace = function () {
+  var fields = null, msgArgs = null;
+  if (arguments.length === 0) {   // `log.trace()`
+    return (this.level <= TRACE);
+  } else if (this.level > TRACE) {
+    return;
+  } else if (typeof arguments[0] === 'string') {  // `log.trace(msg, ...)`
+    fields = null;
+    msgArgs = Array.prototype.slice.call(arguments);
+  } else {  // `log.trace(fields, msg, ...)`
+    fields = arguments[0];
+    msgArgs = Array.prototype.slice.call(arguments, 1);
+  }
+  var rec = this._mkRecord(fields, TRACE, msgArgs);
+  this._emit(rec);
+}
+
 /**
  * Log a record at DEBUG level.
  *