From d30580147236ced3f2884d823ad8e5b5c821056b Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Thu, 29 May 2014 00:13:01 -0700 Subject: [PATCH] [issue #139] Fix `bunyan` crash on a log record with `res.header` that is an object. --- CHANGES.md | 11 +++++++++++ bin/bunyan | 39 +++++++++++++++++++++++++-------------- package.json | 3 ++- test/cli.test.js | 21 ++++++++++++++++++++- test/corpus/139.log | 1 + test/corpus/144.log | 1 + 6 files changed, 60 insertions(+), 16 deletions(-) create mode 100644 test/corpus/139.log create mode 100644 test/corpus/144.log diff --git a/CHANGES.md b/CHANGES.md index 3c5e7ec..a0b98a1 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -8,6 +8,17 @@ Known issues: ## bunyan 0.23.0 (not yet released) +- [issue #139] Fix `bunyan` crash on a log record with `res.header` that is an + object. A side effect of this improvement is that a record with `res.statusCode` + but no header info will render a response block, for example: + + [2012-08-08T10:25:47.637Z] INFO: my-service/12859 on my-host: some message (...) + ... + -- + HTTP/1.1 200 OK + -- + ... + - [pull #42] Fix `bunyan` crash on a log record with `req.headers` that is a *string* (by https://github.com/aexmachina). diff --git a/bin/bunyan b/bin/bunyan index 41241aa..e5f4191 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -837,26 +837,37 @@ function emitRecord(rec, line, opts, stylize) { function _res(res) { var s = ''; - if (res.header) { - s += res.header.trimRight(); - } else if (typeof (res.headers) === 'string') { - s += res.headers.trimRight(); - } else if (res.headers) { - if (res.statusCode) { - s += format('HTTP/1.1 %s %s\n', res.statusCode, - http.STATUS_CODES[res.statusCode]); - } - var headers = res.headers; + if (res.statusCode !== undefined) { + s += format('HTTP/1.1 %s %s\n', res.statusCode, + http.STATUS_CODES[res.statusCode]); + delete res.statusCode; + } + // Handle `res.header` or `res.headers` as either a string or + // and object of header key/value pairs. Prefer `res.header` if set + // (TODO: Why? I don't recall. Typical of restify serializer? + // Typical JSON.stringify of a core node HttpResponse?) + var headers; + if (res.header !== undefined) { + headers = res.header; + delete res.header; + } else if (res.headers !== undefined) { + headers = res.headers; + delete res.headers; + } + if (!headers) { + /* pass through */ + } else if (typeof(headers) === 'string') { + s += headers.trimRight(); + } else { s += Object.keys(headers).map( function (h) { return h + ': ' + headers[h]; }).join('\n'); } - delete res.header; - delete res.headers; - delete res.statusCode; - if (res.body) { + if (res.body !== undefined) { s += '\n\n' + (typeof (res.body) === 'object' ? JSON.stringify(res.body, null, 2) : res.body); delete res.body; + } else { + s = s.trimRight(); } if (res.trailer) { s += '\n' + res.trailer; diff --git a/package.json b/package.json index 7aafafc..2e2fe8d 100644 --- a/package.json +++ b/package.json @@ -25,7 +25,8 @@ "devDependencies": { "nodeunit": "0.7.4", "ben": "0.0.0", - "verror": "1.3.3" + "verror": "1.3.3", + "vasync": "1.4.3" }, "scripts": { diff --git a/test/cli.test.js b/test/cli.test.js index d2ba55f..f71be5d 100644 --- a/test/cli.test.js +++ b/test/cli.test.js @@ -4,10 +4,11 @@ * Test the `bunyan` CLI. */ +var p = console.warn; var path = require('path'); var exec = require('child_process').exec; var _ = require('util').format; -var debug = console.warn; +var vasync = require('vasync'); // node-tap API if (require.cache[__dirname + '/tap4nodeunit.js']) @@ -365,6 +366,8 @@ test('robust req handling', function (t) { '[2012-08-08T10:25:47.637Z] INFO: amon-master/12859 on 9724a190-27b6-4fd8-830b-a574f839c67d: HeadAgentProbes handled: 200 (req_id=cce79d15-ffc2-487c-a4e4-e940bdaac31e, audit=true, remoteAddress=10.2.207.2, remotePort=50394, latency=3, secure=false, _audit=true, req.version=*)', ' HEAD /agentprobes?agent=ccf92af9-0b24-46b6-ab60-65095fdd3037 HTTP/1.1', ' --', + ' HTTP/1.1 200 OK', + ' --', ' route: {', ' "name": "HeadAgentProbes",', ' "version": false', @@ -378,3 +381,19 @@ test('robust req handling', function (t) { t.end(); }); }); + +// Some past crashes from issues. +test('should not crash on these', function (t) { + vasync.forEachPipeline({ + inputs: ['139.log', '144.log'], + func: function (logName, next) { + exec(_('%s %s/corpus/%s', BUNYAN, __dirname, logName), + function (err, stdout, stderr) { + next(err); + }); + } + }, function (err, results) { + t.ifError(err); + t.end(); + }); +}); diff --git a/test/corpus/139.log b/test/corpus/139.log new file mode 100644 index 0000000..0c00212 --- /dev/null +++ b/test/corpus/139.log @@ -0,0 +1 @@ +{"name":"wgaf","hostname":"vmac.local","pid":38947,"level":30,"res":{"statusCode":201,"header":{"connection":"close","access-control-allow-origin":"*","access-control-allow-headers":"Accept, Accept-Version, Content-Length, Content-MD5, Content-Type, Date, Api-Version, Response-Time","access-control-allow-methods":"POST","access-control-expose-headers":"Api-Version, Request-Id, Response-Time","date":"Wed, 23 Apr 2014 13:11:53 GMT","server":"wgaf","request-id":"d6cfe8a0-cae8-11e3-9f88-ff29f9d02103","response-time":7}},"msg":"finished","time":"2014-04-23T13:11:53.644Z","v":0} diff --git a/test/corpus/144.log b/test/corpus/144.log new file mode 100644 index 0000000..0759df6 --- /dev/null +++ b/test/corpus/144.log @@ -0,0 +1 @@ +{"name":"blah_api","hostname":"myhost.home","pid":69312,"level":30,"remote-address":"127.0.0.1","ip":"127.0.0.1","method":"GET","url":"/v0/opps?q=software","referer":"-","user-agent":{"family":"Chrome","major":"34","minor":"0","patch":"1847","device":{"family":"Other"},"os":{"family":"Mac OS X","major":"10","minor":"9","patch":"2"}},"body":{},"short-body":"{}","http-version":"1.1","response-time":232,"status-code":304,"req-headers":{"host":"localhost:3000","connection":"keep-alive","cache-control":"max-age=0","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/34.0.1847.137 Safari/537.36","accept-encoding":"gzip,deflate,sdch","accept-language":"en-US,en;q=0.8","cookie":"__atuvc=2%7C47; csrftoken=XXX; _ga=GA1.1.2104887628.1398883175","if-none-match":"\"-929537647\""},"res-headers":{"x-powered-by":"Express","access-control-allow-origin":"*","access-control-allow-headers":"X-Requested-With","etag":"\"-929537647\""},"req":{"method":"GET","url":"/v0/opps?q=software","headers":"[Circular]","remoteAddress":"127.0.0.1","remotePort":58387},"res":{"statusCode":304,"header":"HTTP/1.1 304 Not Modified\r\nX-Powered-By: Express\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Allow-Headers: X-Requested-With\r\nETag: \"-929537647\"\r\nDate: Fri, 16 May 2014 03:04:13 GMT\r\nConnection: keep-alive\r\n\r\n"},"incoming":"<--","msg":"127.0.0.1 <-- GET /v0/opps?q=software HTTP/1.1 304 - - Chrome 34.0 Mac OS X 10.9.2 232 ms","time":"2014-05-16T03:04:13.961Z","v":0}