[issue #139] Fix bunyan crash on a log record with res.header that is an object.

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).
 

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;

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": {

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();
+    });
+});

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}

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}