res (HTTP server response) serializer; some cleanup; 'err.js' example;

Also add req/res/err details to `bunyan` tool default output mode.
2012-02-01 21:33:18 -08:00 · 2012-02-01 21:33:18 -08:00 · 7d3431eeb6
parent 8eb2abd15a
commit 7d3431eeb6
5 changed files with 145 additions and 44 deletions
--- a/TODO.md
+++ b/TODO.md
@ -1,11 +1,3 @@
- serializer support:
-    - Ask mark what else to put in `req`
-    - Ask mark what to put in `res`
-    - 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
@ -56,3 +48,9 @@
  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).
+- 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.
--- a/bin/bunyan
+++ b/bin/bunyan
@ -98,6 +98,9 @@ if (!format) {
  };
 }

+function indent(s) {
+  return '    ' + s.split(/\r?\n/).join('\n    ')
+}

 function isArray(ar) {
  return ar instanceof Array ||
@ -105,11 +108,6 @@ function isArray(ar) {
         (ar && ar !== Object.prototype && isArray(ar.__proto__));
 }

-// json_parse.js (<https://github.com/douglascrockford/JSON-js>)
-// START json_parse
-var json_parse=function(){"use strict";var a,b,c={'"':'"',"\\":"\\","/":"/",b:"\b",f:"\f",n:"\n",r:"\r",t:"\t"},d,e=function(b){throw{name:"SyntaxError",message:b,at:a,text:d}},f=function(c){return c&&c!==b&&e("Expected '"+c+"' instead of '"+b+"'"),b=d.charAt(a),a+=1,b},g=function(){var a,c="";b==="-"&&(c="-",f("-"));while(b>="0"&&b<="9")c+=b,f();if(b==="."){c+=".";while(f()&&b>="0"&&b<="9")c+=b}if(b==="e"||b==="E"){c+=b,f();if(b==="-"||b==="+")c+=b,f();while(b>="0"&&b<="9")c+=b,f()}a=+c;if(!isFinite(a))e("Bad number");else return a},h=function(){var a,d,g="",h;if(b==='"')while(f()){if(b==='"')return f(),g;if(b==="\\"){f();if(b==="u"){h=0;for(d=0;d<4;d+=1){a=parseInt(f(),16);if(!isFinite(a))break;h=h*16+a}g+=String.fromCharCode(h)}else if(typeof c[b]=="string")g+=c[b];else break}else g+=b}e("Bad string")},i=function(){while(b&&b<=" ")f()},j=function(){switch(b){case"t":return f("t"),f("r"),f("u"),f("e"),!0;case"f":return f("f"),f("a"),f("l"),f("s"),f("e"),!1;case"n":return f("n"),f("u"),f("l"),f("l"),null}e("Unexpected '"+b+"'")},k,l=function(){var a=[];if(b==="["){f("["),i();if(b==="]")return f("]"),a;while(b){a.push(k()),i();if(b==="]")return f("]"),a;f(","),i()}}e("Bad array")},m=function(){var a,c={};if(b==="{"){f("{"),i();if(b==="}")return f("}"),c;while(b){a=h(),i(),f(":"),Object.hasOwnProperty.call(c,a)&&e('Duplicate key "'+a+'"'),c[a]=k(),i();if(b==="}")return f("}"),c;f(","),i()}}e("Bad object")};return k=function(){i();switch(b){case"{":return m();case"[":return l();case'"':return h();case"-":return g();default:return b>="0"&&b<="9"?g():j()}},function(c,f){var g;return d=c,a=0,b=" ",g=k(),i(),b&&e("Syntax error"),typeof f=="function"?function h(a,b){var c,d,e=a[b];if(e&&typeof e=="object")for(c in e)Object.prototype.hasOwnProperty.call(e,c)&&(d=h(e,c),d!==undefined?e[c]=d:delete e[c]);return f.call(a,b,e)}({"":g},""):g}}();
-// END json_parse
-
 function printHelp() {
  util.puts("Usage:");
  util.puts("  cat some-json-log-file.log | bunyan [OPTIONS]");
@ -121,11 +119,9 @@ function printHelp() {
  util.puts("  -h, --help    print this help info and exit");
  util.puts("  --version     print version of this command and exit");
  util.puts("");
-  util.puts("  -e CODE       execute the given code on input, on each array item");
-  util.puts("                if '-a' is used. This execution is run before ");
-  util.puts("                filtering.");
-  util.puts("");
-  util.puts("  -o, --output MODE   Specify an output mode. One of");
+  util.puts("  -o, --output MODE");
+  util.puts("                Specify an output mode/format. One of");
+  util.puts("                  paul: (the default) pretty")
  util.puts("                  json: JSON output, 2-space indent");
  util.puts("                  json-N: JSON output, N-space indent, e.g. 'json-4'");
  util.puts("                  inspect: node.js `util.inspect` output");
@ -152,8 +148,6 @@ function parseArgv(argv) {
    args: [],
    help: false,
    quiet: false,
-    dropHeaders: false,
-    executableSnippets: [],
    outputMode: OM_PAUL,
    jsonIndent: 2
  };
@ -199,9 +193,6 @@ function parseArgv(argv) {
      case "--quiet":
        parsed.quiet = true;
        break;
-      case "-H": // drop any headers
-        parsed.dropHeaders = true;
-        break;
      case "-o":
      case "--output":
        var name = args.shift();
@ -221,9 +212,6 @@ function parseArgv(argv) {
      case "-j": // output with JSON.stringify
        parsed.outputMode = OM_JSON;
        break;
-      case "-e":
-        parsed.executableSnippets.push(args.shift());
-        break;
      default: // arguments
        if (!endOfOptions && arg.length > 0 && arg[0] === '-') {
          throw new Error("unknown option '"+arg+"'");
@ -268,11 +256,12 @@ function handleLogLine(line, opts) {
    // Multi-line msg:
    //    [time] LEVEL: service[/component] on hostname: (extras...)
    //        msg
-    // Request/HTTP info:
-    //    TODO
-    var svc = rec.service;
+    // If 'req', show the request.
+    // If 'res', show the response.
+    // If 'err' and 'err.stack' then show that.
+    var serviceStr = rec.service;
    if (rec.component) {
-      svc += '/' + rec.component;
+      serviceStr += '/' + rec.component;
    }
    var levelStr = (upperNameFromLevel[rec.level]
      || "<unknown-level " + rec.level + ">");
@ -280,24 +269,46 @@ function handleLogLine(line, opts) {
    if (rec.request_id) extras.push(rec.request_id);
    if (rec.latency) extras.push(rec.latency + "ms");
    extras = (extras.length ? ' (' + extras.join(', ') + ')' : '');
+    var details = [];
+    onelineMsg = ' ' + rec.msg;
    if (rec.msg.indexOf('\n') !== -1) {
-      XXX
-    } else {
-      emit(format("[%s] %s: %s on %s: %s%s\n",
-        rec.time,
-        upperNameFromLevel[rec.level] || "<unknown-level " + rec.level + ">",
-        svc,
-        rec.hostname || "<no-hostname>",
-        rec.msg,
-        extras));
+      onelineMsg = '';
+      details.push(indent(rec.msg));
    }
+    if (rec.req) {
+      var headers = rec.req.headers;
+      details.push(indent(format("%s %s\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()));
+    }
+    if (rec.err && rec.err.stack) {
+      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",
+      rec.time,
+      upperNameFromLevel[rec.level] || "<unknown-level " + rec.level + ">",
+      serviceStr,
+      rec.hostname || "<no-hostname>",
+      onelineMsg,
+      extras,
+      details));
    break;
+
  case OM_INSPECT:
    emit(util.inspect(rec, false, Infinity, true) + '\n');
    break;
+
  case OM_JSON:
    emit(JSON.stringify(rec, null, opts.jsonIndent) + '\n');
    break;
+
  case OM_SIMPLE:
    // <http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/SimpleLayout.html>
    emit(format("%s - %s",
--- a/examples/err.js
+++ b/examples/err.js
@ -0,0 +1,46 @@
+// Example logging an error:
+
+var http = require('http');
+var Logger = require('../lib/bunyan');
+
+var log = new Logger({
+  service: "myserver",
+  serializers: {
+    req: Logger.stdSerializers.req,
+    res: Logger.stdSerializers.res
+  }
+});
+
+try {
+  throw new TypeError("boom");
+} catch (err) {
+  log.warn({err: err}, "operation went boom: %s", err)   // <--- here
+}
+
+/*
+
+$ node err.js  | ../bin/bunyan -j
+{
+  "service": "myserver",
+  "hostname": "banana.local",
+  "err": {
+    "stack": "TypeError: boom\n    at Object.<anonymous> (/Users/trentm/tm/node-bunyan/examples/err.js:15:9)\n    at Module._compile (module.js:411:26)\n    at Object..js (module.js:417:10)\n    at Module.load (module.js:343:31)\n    at Function._load (module.js:302:12)\n    at Array.0 (module.js:430:10)\n    at EventEmitter._tickCallback (node.js:126:26)",
+    "message": "boom"
+  },
+  "level": 4,
+  "msg": "operation went boom: TypeError: boom",
+  "time": "2012-02-02T04:42:53.206Z",
+  "v": 0
+}
+$ node err.js  | ../bin/bunyan 
+[2012-02-02T05:02:39.412Z] WARN: myserver on banana.local: operation went boom: TypeError: boom
+    TypeError: boom
+        at Object.<anonymous> (/Users/trentm/tm/node-bunyan/examples/err.js:15:9)
+        at Module._compile (module.js:411:26)
+        at Object..js (module.js:417:10)
+        at Module.load (module.js:343:31)
+        at Function._load (module.js:302:12)
+        at Array.0 (module.js:430:10)
+        at EventEmitter._tickCallback (node.js:126:26)
+
+*/
--- a/examples/server.js
+++ b/examples/server.js
@ -1,21 +1,28 @@
+// Example logging HTTP server request and response objects.
+
 var http = require('http');
 var Logger = require('../lib/bunyan');

-// Basic usage.
 var log = new Logger({
  service: "myserver",
-  serializers: {req: Logger.stdSerializers.req}
+  serializers: {
+    req: Logger.stdSerializers.req,
+    res: Logger.stdSerializers.res
+  }
 });

-http.createServer(function (req, res) {
+var server = 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({res: res}, "done response");  // <-- this is the guy we're testing
+});
+server.listen(1337, "127.0.0.1", function () {
  log.info("server listening");
  var options = {
    port: 1337,
-    host: '127.0.0.1',
+    hostname: '127.0.0.1',
+    path: '/path?q=1#anchor',
    headers: {
      'X-Hi': 'Mom'
    }
@ -26,5 +33,29 @@ http.createServer(function (req, res) {
      process.exit();
    })
  });
+  req.write("hi from the client");
  req.end();
 });
+
+
+/*
+
+$ node server.js 
+{"service":"myserver","hostname":"banana.local","level":3,"msg":"server listening","time":"2012-02-02T05:32:13.257Z","v":0}
+{"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-02T05:32:13.260Z","v":0}
+{"service":"myserver","hostname":"banana.local","res":{"statusCode":200,"_hasBody":true,"_header":"HTTP/1.1 200 OK\r\nContent-Type: text/plain\r\nConnection: close\r\nTransfer-Encoding: chunked\r\n\r\n","_trailer":""},"level":3,"msg":"done response","time":"2012-02-02T05:32:13.261Z","v":0}
+
+$ node server.js | ../bin/bunyan
+[2012-02-02T05:32:16.006Z] INFO: myserver on banana.local: server listening
+[2012-02-02T05:32:16.010Z] INFO: myserver on banana.local: start request
+    GET /path?q=1#anchor
+    x-hi: Mom
+    connection: close
+[2012-02-02T05:32:16.011Z] INFO: myserver on banana.local: done response
+    HTTP/1.1 200 OK
+    Content-Type: text/plain
+    Connection: close
+    Transfer-Encoding: chunked
+    (body)
+
+*/
--- a/lib/bunyan.js
+++ b/lib/bunyan.js
@ -583,6 +583,8 @@ 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,
@ -590,6 +592,19 @@ Logger.stdSerializers.req = function req(req) {
  }
 };

+// 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,
+  }
+};
+