v0.4: add 'src' call source location info support (the Yunong release)

2012-02-05 20:33:57 -08:00 · 2012-02-05 20:33:57 -08:00 · e934baf74f
parent 9786827579
commit e934baf74f
9 changed files with 195 additions and 44 deletions
--- a/AUTHORS.txt
+++ b/AUTHORS.txt
@ -0,0 +1,2 @@
+Trent Mick <trentm@gmail.com>
+Mark Cavage <mcavage@gmail.com>
--- a/CHANGES.md
+++ b/CHANGES.md
@ -1,8 +1,16 @@
 # bunyan Changelog

-## bunyan 0.3.1 (not yet released)
+## bunyan 0.4.0 (not yet released)
+
+- Add `new Logger({src: true})` config option to have a 'src' attribute be
+  automatically added to log records with the log call source info. Example:
+
+        "src": {
+          "file": "/Users/trentm/tm/node-bunyan/examples/src.js",
+          "line": 20,
+          "func": "Wuzzle.woos"
+        },

-(nothing yet)

 ## bunyan 0.3.0

--- a/README.md
+++ b/README.md
@ -32,6 +32,16 @@ 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}

+The full `log.{trace|debug|...|fatal}(...)` API is:
+
+    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 tool
+
 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
@ -50,6 +60,9 @@ be added, including support for custom formats.
      "v": 0
    }

+
+## streams
+
 By default, log output is to stdout (**stream**) and at the "info" level.
 Explicitly that looks like:

@ -73,6 +86,9 @@ streams at different levels**.
      ]
    });

+
+## log.child
+
 A `log.child(...)` is provided to **specialize a logger for a sub-component**.
 The following will have log records from "Wuzzle" instances use exactly the
 same config as its parent, plus include the "component" field.
@ -111,12 +127,7 @@ See the changelog for node-bunyan 0.3.0 for details.

 * * *

-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
+## serializers

 Bunyan has a concept of **"serializers" to produce a JSON-able object from a
 JavaScript object**, so your can easily do the following:
@ -159,7 +170,32 @@ standard serializers you can use:
 ugly message on stderr from Bunyan (along with the traceback) and the field
 in your log record will be replaced with a short error message.*

+## src

+The **call source file, line and function** (if not at the global level) can
+be added to log records by using the `src: true` config option:
+
+    var log = new Logger({src: true, ...});
+
+This adds the call source info with the 'src' field, like this:
+
+    {
+      "service": "src-example",
+      "hostname": "banana.local",
+      "component": "wuzzle",
+      "level": 4,
+      "msg": "This wuzzle is woosey.",
+      "time": "2012-02-06T04:19:35.605Z",
+      "src": {
+        "file": "/Users/trentm/tm/node-bunyan/examples/src.js",
+        "line": 20,
+        "func": "Wuzzle.woos"
+      },
+      "v": 0
+    }
+
+**WARNING: Determining the call source info is slow. Never use this option
+in production.**


 # Levels
@ -245,6 +281,9 @@ Core fields:
  [`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.
+- `src`: Optional. Object giving log call source info. This is added
+  automatically by Bunyan if the "src: true" config option is given to the
+  Logger. Never use in production as this is really slow.


 Go ahead and add more fields, and nest ones are fine (and recommended) as
--- a/TODO.md
+++ b/TODO.md
@ -1,14 +1,12 @@
- `log.close` to close streams and shutdown and `this.closed`
 - line/file: possible to get quickly with v8? Yunong asked.
- what's the API for changing the logger/stream level(s)?
+    file/line/func (?)
+- Logger.setLevel()? How to change level for a given stream. Default all,
+  else, give an index... or type ... or support stream "names". Some positives
+  to stream names.
 - 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
  or whatever. Dap wants field width control for lining up. Hogan.js is
  probably overkill for this.
- bunyan cli: filter args a la json
- bunyan cli: -c COND args a la json
- mark wants pretty output for debug output
-    - not sure if 'bunyan --pretty' or whatever would suffice
 - ringBuffer stream
 - syslog: Josh uses https://github.com/chrisdew/node-syslog
    streams: [
@ -20,8 +18,6 @@
            syslog_pid: true,   // syslog logopt "LOG_PID"
            syslog_cons: false  // syslog logopt "LOG_CONS"
        }
- Logger.setLevel()? How to change level for a given stream. Default all,
-  else, give an index... or type ... or support stream "names".
 - "canWrite" handling for full streams. Need to buffer a la log4js
 - test file log with logadm rotation: does it handle that?
 - test suite:
@ -32,30 +28,24 @@
      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)
+- (mark) instanceof-based serialization:
+    log.info(new Error("blah blah")) -> {err: ..., msg: ""}
+  perhaps at least default for Error. Then perhaps augment or replace
+  serializers with registerable instanceof's.
+    log = new Logger({
+        serializers
+    })
+    


 # someday/maybe

- 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.
+- bunyan cli: filter args a la json
+- bunyan cli: -c COND args a la json
+- bunyan "compact" or "light", '-l'? Something like. Or pehaps this (with
+  color) could be the default, with '-l' for long output.
+    13:51.340 [src.js:20#Wuzzle.woos] WARN: This wuzzle is woosey.
+- `log.close` to close streams and shutdown and `this.closed`
 - get Mark to show me dtrace provider stuff and consider adding for
  logging, if helpful.
 - add option to "streams" to take the raw object, not serialized.
--- a/bin/bunyan
+++ b/bin/bunyan
@ -5,7 +5,7 @@
 // See <https://github.com/trentm/node-bunyan>.
 //

-var VERSION = "0.3.1";
+var VERSION = "0.4.0";

 var util = require('util');
 var pathlib = require('path');
@ -253,9 +253,9 @@ function handleLogLine(line, opts) {
  switch (opts.outputMode) {
  case OM_PAUL:
    // Single-line msg:
-    //    [time] LEVEL: service[/component] on hostname: msg (extras...)
+    //    [time] LEVEL: service[/component] on hostname (src): msg (extras...)
    // Multi-line msg:
-    //    [time] LEVEL: service[/component] on hostname: (extras...)
+    //    [time] LEVEL: service[/component] on hostname (src): (extras...)
    //        msg
    // If 'req', show the request.
    // If 'res', show the response.
@ -266,8 +266,17 @@ function handleLogLine(line, opts) {
    }
    var levelStr = (upperNameFromLevel[rec.level]
      || "<unknown-level " + rec.level + ">");
+    var src = "";
+    if (rec.src && rec.src.file) {
+      var s = rec.src;
+      if (s.func) {
+        src = format(" (%s:%d in %s)", s.file, s.line, s.func);
+      } else {
+        src = format(" (%s:%d)", s.file, s.line);
+      }
+    }
    var extras = [];
-    if (rec.request_id) extras.push(rec.request_id);
+    if (rec.req_id) extras.push("req_id=" + rec.req_id);
    if (rec.latency) extras.push(rec.latency + "ms");
    extras = (extras.length ? ' (' + extras.join(', ') + ')' : '');
    var details = [];
@ -304,11 +313,12 @@ function handleLogLine(line, opts) {
      details.push(indent(rec.err.stack))
    }
    details = (details.length ? details.join('\n--\n') + '\n' : '');
-    emit(format("[%s] %s: %s on %s:%s%s\n%s",
+    emit(format("[%s] %s: %s on %s%s:%s%s\n%s",
      rec.time,
      upperNameFromLevel[rec.level] || "<unknown-level " + rec.level + ">",
      serviceStr,
      rec.hostname || "<no-hostname>",
+      src,
      onelineMsg,
      extras,
      details));
--- a/examples/src.js
+++ b/examples/src.js
@ -0,0 +1,26 @@
+// Show the usage of `src: true` config option to get log call source info in
+// log records (the `src` field).
+
+var Logger = require('../lib/bunyan');
+
+var log = new Logger({service: "src-example", src: true});
+
+log.info("one");
+log.info("two");
+function doSomeFoo() {
+  log.info({foo:"bar"}, "three");
+}
+doSomeFoo();
+
+function Wuzzle(options) {
+  this.log = options.log;
+  this.log.info("creating a wuzzle")
+}
+Wuzzle.prototype.woos = function () {
+  this.log.warn("This wuzzle is woosey.")
+}
+
+var wuzzle = new Wuzzle({log: log.child({component: "wuzzle"})});
+wuzzle.woos();
+log.info("done with the wuzzle")
+
--- a/lib/bunyan.js
+++ b/lib/bunyan.js
@ -2,7 +2,7 @@
 * Copyright 2012 (c) Trent Mick. All rights reserved.
 */

-var VERSION = "0.3.1";
+var VERSION = "0.4.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,
@ -82,6 +82,32 @@ if (!format) {
 }


+/**
+ * Gather some caller info 3 stack levels up.
+ * See <http://code.google.com/p/v8/wiki/JavaScriptStackTraceApi>.
+ */
+function getCaller3Info() {
+  var obj = {};
+  var saveLimit = Error.stackTraceLimit;
+  var savePrepare = Error.prepareStackTrace;
+  Error.stackTraceLimit = 3;
+  Error.captureStackTrace(this, getCaller3Info);
+  Error.prepareStackTrace = function(_, stack) {
+    var caller = stack[2];
+    obj.file = caller.getFileName();
+    obj.line = caller.getLineNumber();
+    var func = caller.getFunctionName();
+    if (func)
+      obj.func = func;
+  };
+  this.stack;
+  Error.stackTraceLimit = saveLimit;
+  Error.prepareStackTrace = savePrepare;
+  return obj;
+}
+
+
+

 //---- Levels

@ -135,6 +161,8 @@ function resolveLevel(nameOrNum) {
 *        `process.stdout` (cannot be used with `streams`)
 *      - `serializers`: object mapping log record field names to
 *        serializing functions. See README.md for details.
+ *      - `src`: Boolean (default false). Set true to enable 'src' automatic
+ *        field with log call source info.
 *    All other keys are log record fields.
 *
 * An alternative *internal* call signature is used for creating a child:
@ -176,6 +204,7 @@ function Logger(options, _childOptions, _childSimple) {
    this.level = parent.level;
    this.streams = parent.streams;
    this.serializers = parent.serializers;
+    this.src = parent.src;
    this.fields = parent.fields;
    var names = Object.keys(options);
    for (var i = 0; i < names.length; i++) {
@ -196,11 +225,13 @@ function Logger(options, _childOptions, _childSimple) {
      this.streams.push(s);
    }
    this.serializers = objCopy(parent.serializers);
+    this.src = parent.src;
    this.fields = objCopy(parent.fields);
  } else {
    this.level = Number.POSITIVE_INFINITY;
    this.streams = [];
    this.serializers = null;
+    this.src = false;
    this.fields = {};
  }
  
@ -289,6 +320,9 @@ function Logger(options, _childOptions, _childSimple) {
  if (options.serializers) {
    addSerializers(options.serializers);
  }
+  if (options.src) {
+    this.src = true;
+  }
  xxx("Logger: ", self)
  
  // Fields.
@ -301,6 +335,7 @@ function Logger(options, _childOptions, _childSimple) {
  delete fields.level;
  delete fields.streams;
  delete fields.serializers;
+  delete fields.src;
  if (this.serializers) {
    this._applySerializers(fields);
  }
@ -443,8 +478,12 @@ Logger.prototype._emit = function (rec) {
  if (!obj.time) {
    obj.time = (new Date());
  }
+  // Get call source info
+  if (this.src && !obj.src) {
+    obj.src = getCaller3Info()
+  }
  obj.v = LOG_VERSION;
-  
+
  xxx('_emit: stringify this:', obj);
  var str = JSON.stringify(obj) + '\n';
  this.streams.forEach(function(s) {
--- a/package.json
+++ b/package.json
@ -1,6 +1,6 @@
 {
  "name": "bunyan",
-  "version": "0.3.1",
+  "version": "0.4.0",
  "description": "a JSON Logger library for node.js servers",
  "main": "./lib/bunyan.js",
  "bin": {
--- a/tools/timesrc.js
+++ b/tools/timesrc.js
@ -0,0 +1,37 @@
+#!/usr/bin/env node
+/*
+ * Time 'src' fields (getting log call source info). This is expensive.
+ */
+
+console.log("Time adding 'src' field with call source info:");
+
+var ben = require('ben');  // npm install ben
+var Logger = require('../lib/bunyan');
+
+var records = [];
+function Collector() {
+}
+Collector.prototype.write = function(s) {
+  //records.push(s);
+}
+var collector = new Collector();
+
+var logwith = new Logger({
+  service: "with-src",
+  src: true,
+  stream: collector
+});
+
+var ms = ben(1e5, function () {
+  logwith.info("hi");
+});
+console.log(' - log.info with    src:  %dms per iteration', ms);
+
+var logwithout = new Logger({
+  service: "without-src",
+  stream: collector
+});
+var ms = ben(1e5, function () {
+  logwithout.info("hi");
+});
+console.log(' - log.info without src:  %dms per iteration', ms);