start serializers support. Add 'req' standard serializer. You can add your own.

README.md

@@ -90,7 +90,49 @@ same config as its parent, plus include the "component" field.
     log.info("done with the wuzzle")
 
 
+Back to the `log.{trace|debug|...|fatal}(...)` API:
 
+    log.info();     // returns a boolean: is the "info" level enabled?
+    log.info("hi"); // log a simple string message
+    log.info("hi %s", bob, anotherVar); // uses `util.format` for msg formatting
+    log.info({foo: "bar"}, "hi");       // adds "foo" field to log record
+
+Bunyan has a concept of **"serializers" to produce a JSON-able object from a
+JavaScript object**, so your can easily do the following:
+
+    log.info({req: <request object>}, "something about handling this request");
+
+Association is by log record field name, "req" in this example, so this
+requires a registered serializer something like this:
+
+    function reqSerializer(req) {
+      return {
+        method: req.method,
+        url: req.url,
+        headers: req.headers
+      }
+    }
+    var log = new Logger({
+      ...
+      serializers: {
+        req: reqSerializer
+      }
+    });
+
+Or this:
+
+    var log = new Logger({
+      ...
+      serializers: {req: Logger.stdSerializers.req}
+    });
+
+because Buyan includes a small set of standard serializers. To use all the
+standard serializers you can use:
+
+    var log = new Logger({
+      ...
+      serializers: Logger.stdSerializers
+    });
 
 
 # Future

TODO.md

@@ -1,7 +1,12 @@
-- serializer support (i.e. repr of a restify request obj):
+- serializer support:
-    server.js example
+    - Ask mark what else to put in `req`
-    restify-server.js example
+    - Ask mark what to put in `res`
-- 'x' extra fields object or no? discuss
+    - 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?
+    - Add `err`.
+    - `request_id` that pulls it from req? `log.info({request_id: req}, "hi")`
+- `log.close` to close streams and shutdown and `this.closed`
 - expand set of fields: from dap
     time, hostname
     <https://github.com/Graylog2/graylog2-docs/wiki/GELF>
@@ -32,10 +37,13 @@
 - Logger.set to mutate config or `this.fields`
 - Logger.del to remove a field
 - "canWrite" handling for full streams. Need to buffer a la log4js
+- test file log with logadm rotation: does it handle that?
 - test suite:
     - test for a cloned logger double-`stream.end()` causing problems.
       Perhaps the "closeOnExit" for existing streams should be false for
       clones.
+    - test that a `log.clone(...)` adding a new field matching a serializer
+      works *and* that an existing field in the parent is not *re-serialized*.
 - a "rolling-file" stream: but specifically by time, e.g. hourly. (MarkC
   requested)
 

examples/server.js

@@ -0,0 +1,30 @@
+var http = require('http');
+var Logger = require('../lib/bunyan');
+
+// Basic usage.
+var log = new Logger({
+  service: "myserver",
+  serializers: {req: Logger.stdSerializers.req}
+});
+
+http.createServer(function (req, res) {
+  log.info({req: req}, "start request");  // <-- this is the guy we're testing
+  res.writeHead(200, {'Content-Type': 'text/plain'});
+  res.end('Hello World\n');
+}).listen(1337, "127.0.0.1", function () {
+  log.info("server listening");
+  var options = {
+    port: 1337,
+    host: '127.0.0.1',
+    headers: {
+      'X-Hi': 'Mom'
+    }
+  };
+  var req = http.request(options);
+  req.on('response', function (res) {
+    res.on('end', function () {
+      process.exit();
+    })
+  });
+  req.end();
+});

lib/bunyan.js

@@ -11,7 +11,7 @@ var LOG_VERSION = 0;
 
 
 var xxx = function xxx(s) {     // internal dev/debug logging
-  var args = ["PAUL: "+s].concat(Array.prototype.slice.call(arguments, 1));
+  var args = ['XX' + 'X: '+s].concat(Array.prototype.slice.call(arguments, 1));
   console.error.apply(this, args);
 };
 var xxx = function xxx() {};  // uncomment to turn of debug logging
@@ -101,10 +101,20 @@ function getLevel(nameOrNum) {
 }
 
 
+
 //---- Logger class
 
-function Logger(options) {
+/**
-  paul('Logger start:', options)
+ * Create a Logger instance.
+ *
+ * @param options {Object} See documentation for full details. At minimum
+ *    this must include a "service" string key.
+ * @param _newCloneKeys {Array} Internal var. Should not be used externally.
+ *    Array of new keys for this clone. This is necessary to assist with
+ *    applying necessary serializers to the new keys.
+ */
+function Logger(options, _newCloneKeys) {
+  xxx('Logger start:', options)
   if (! this instanceof Logger) {
     return new Logger(options);
   }
@@ -116,6 +126,9 @@ function Logger(options) {
   if (options.stream && options.streams) {
     throw new TypeError('can only have one of "stream" or "streams"');
   }
+  if (_newCloneKeys && !Array.isArray(_newCloneKeys)) {
+    throw new TypeError('_newCloneKeys (Array) is an internal var');
+  }
   
   // These are the default fields for log records (minus the attributes
   // removed in this constructor). To allow storing raw log records
@@ -136,6 +149,7 @@ function Logger(options) {
   } else {
     level = INFO;
   }
+
   this.streams = [];
   if (options.stream) {
     this.streams.push({
@@ -210,15 +224,41 @@ function Logger(options) {
   }
   this.level = lowestLevel;
   
+  delete this.fields.serializers;
+  if (!options.serializers) {
+    this.serializers = null;
+  } else {
+    this.serializers = {};
+    Object.keys(options.serializers).forEach(function (field) {
+      var serializer = options.serializers[field];
+      if (typeof(serializer) !== "function") {
+        throw new TypeError(format(
+          'invalid serializer for "%s" field: must be a function', field));
+      } else {
+        self.serializers[field] = serializer;
+      }
+    });
+  }
+  
   xxx("Logger: ", self)
   
+  // Apply serializers to initial fields.
+  if (this.serializers) {
+    if (_newCloneKeys && _newCloneKeys.length > 0) {
+      // Note that this includes *config* vars send to `log.clone()` in
+      // addition to log record *fields*, so the impl. needs to handle that.
+      this._applySerializers(this.fields, _newCloneKeys);
+    } else {
+      this._applySerializers(this.fields);
+    }
+  }
+  
   // Automatic fields.
   if (!this.fields.hostname) {
     this.fields.hostname = os.hostname();
   }
   
-  //XXX Non-core fields should go in 'x' sub-object.
+  //XXX Turn this on or ditch it.
-
   //process.on('exit', function () {
   //  self.streams.forEach(function (s) {
   //    if (s.closeOnExit) {
@@ -250,11 +290,54 @@ Logger.prototype.clone = function (options) {
   var cloneOptions = objCopy(this.fields);
   cloneOptions.streams = this.streams;
   if (options) {
-    Object.keys(options).forEach(function(k) {
+    var newCloneKeys = Object.keys(options);
+    newCloneKeys.forEach(function(k) {
       cloneOptions[k] = options[k];
     });
   }
-  return new Logger(cloneOptions);
+  return new Logger(cloneOptions, newCloneKeys);
+}
+
+
+/**
+ * Apply registered serializers to the appropriate keys in the given fields.
+ *
+ * Pre-condition: This is only called if there is at least one serializer.
+ *
+ * @param fields (Object) The log record fields.
+ * @param keys (Array) Optional array of keys to which to limit processing.
+ */
+Logger.prototype._applySerializers = function (fields, keys) {
+  var self = this;
+
+  // Mapping of keys to potentially serialize.
+  var applyKeys = fields;
+  if (keys) {
+    applyKeys = {};
+    for (var i=0; i < keys.length; i++) {
+      applyKeys[keys[i]] = true;
+    }
+  }
+  
+  xxx('_applySerializers: applyKeys', applyKeys);
+  
+  // Check each serializer against these (presuming number of serializers
+  // is typically less than number of fields).
+  Object.keys(this.serializers).forEach(function (name) {
+    if (applyKeys[name]) {
+      xxx('_applySerializers; apply to "%s" key', name)
+      try {
+        fields[name] = self.serializers[name](fields[name]);
+      } catch (err) {
+        process.stderr.write(format('bunyan: ERROR: This should never happen. '
+          + 'This is a bug in <https://github.com/trentm/node-bunyan> or '
+          + 'in this application. Exception from "%s" Logger serializer: %s',
+          name, err.stack || err));
+        fields[name] = format('(Error in Bunyan log "%s" serializer '
+          + 'broke field. See stderr for details.)', name);
+      }
+    }
+  });
 }
 
 
@@ -282,6 +365,9 @@ Logger.prototype._emit = function (rec) {
   var obj = objCopy(rec[0]);
   var recFields = rec[1];
   if (recFields) {
+    if (this.serializers) {
+      this._applySerializers(recFields);
+    }
     Object.keys(recFields).forEach(function (k) {
       obj[k] = recFields[k];
     });
@@ -294,6 +380,7 @@ Logger.prototype._emit = function (rec) {
   }
   obj.v = LOG_VERSION;
   
+  xxx('_emit: stringify this:', obj);
   var str = JSON.stringify(obj) + '\n';
   this.streams.forEach(function(s) {
     if (s.level <= level) {
@@ -486,6 +573,29 @@ Logger.prototype.fatal = function () {
 }
 
 
+
+//---- Standard serializers
+// A serializer is a function that serializes a JavaScript object to a
+// JSON representation for logging. There is a standard set of presumed
+// interesting objects in node.js-land.
+
+Logger.stdSerializers = {};
+
+// Serialize an HTTP request.
+Logger.stdSerializers.req = function req(req) {
+  return {
+    method: req.method,
+    url: req.url,
+    headers: req.headers
+  }
+};
+
+
+
+
+
+//---- Exports
+
 module.exports = Logger;