From 7d3431eeb649cc421e5f8bfe40cc248620ca260b Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 1 Feb 2012 21:33:18 -0800 Subject: [PATCH] res (HTTP server response) serializer; some cleanup; 'err.js' example; Also add req/res/err details to `bunyan` tool default output mode. --- TODO.md | 14 ++++----- bin/bunyan | 73 ++++++++++++++++++++++++++-------------------- examples/err.js | 46 +++++++++++++++++++++++++++++ examples/server.js | 41 ++++++++++++++++++++++---- lib/bunyan.js | 15 ++++++++++ 5 files changed, 145 insertions(+), 44 deletions(-) create mode 100644 examples/err.js diff --git a/TODO.md b/TODO.md index 0551677..042c90f 100644 --- 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. diff --git a/bin/bunyan b/bin/bunyan index e3edeaf..5133d78 100755 --- 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 () -// 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] || ""); @@ -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] || "", - svc, - rec.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] || "", + serviceStr, + rec.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: // emit(format("%s - %s", diff --git a/examples/err.js b/examples/err.js new file mode 100644 index 0000000..63af6d6 --- /dev/null +++ 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. (/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. (/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) + +*/ diff --git a/examples/server.js b/examples/server.js index 219afec..e1df733 100644 --- 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) + +*/ diff --git a/lib/bunyan.js b/lib/bunyan.js index 519aba4..f1e64af 100644 --- 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, + } +}; +