Fix the bunyan CLI to not duplicate the "HTTP/1.1 ..." status line when serializing a "res" field. (#444)

CHANGES.md

@@ -7,7 +7,8 @@ Known issues:
 
 ## not yet released
 
-(nothing yet)
+- [issue #444] Fix the `bunyan` CLI to not duplicate the "HTTP/1.1 ..." status
+  line when serializing a "res" field.
 
 
 ## 2.0.1 (beta)

bin/bunyan

@@ -953,17 +953,21 @@ function emitRecord(rec, line, opts, stylize) {
 
         function _res(res) {
             var s = '';
-            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?)
+
+            /*
+             * Handle `res.header` or `res.headers` as either a string or
+             * an object of header key/value pairs. Prefer `res.header` if set,
+             * because that's what Bunyan's own `res` serializer specifies,
+             * because that's the value in Node.js's core HTTP server response
+             * implementation that has all the implicit headers.
+             *
+             * Note: `res.header` (string) typically includes the 'HTTP/1.1 ...'
+             * status line.
+             */
             var headerTypes = {string: true, object: true};
             var headers;
+            var headersStr = '';
+            var headersHaveStatusLine = false;
             if (res.header && headerTypes[typeof (res.header)]) {
                 headers = res.header;
                 delete res.header;
@@ -974,11 +978,26 @@ function emitRecord(rec, line, opts, stylize) {
             if (headers === undefined) {
                 /* pass through */
             } else if (typeof (headers) === 'string') {
-                s += headers.trimRight();
+                headersStr = headers.trimRight(); // Trim the CRLF.
+                if (headersStr.slice(0, 5) === 'HTTP/') {
+                    headersHaveStatusLine = true;
+                }
             } else {
-                s += Object.keys(headers).map(
+                headersStr += Object.keys(headers).map(
                     function (h) { return h + ': ' + headers[h]; }).join('\n');
             }
+
+            /*
+             * Add a 'HTTP/1.1 ...' status line if the headers didn't already
+             * include it.
+             */
+            if (!headersHaveStatusLine && res.statusCode !== undefined) {
+                s += format('HTTP/1.1 %s %s\n', res.statusCode,
+                    http.STATUS_CODES[res.statusCode]);
+            }
+            delete res.statusCode;
+            s += headersStr;
+
             if (res.body !== undefined) {
                 var body = (typeof (res.body) === 'object'
                     ? JSON.stringify(res.body, null, 2) : res.body);

test/cli-res.test.js

@@ -0,0 +1,61 @@
+/*
+ * Copyright (c) 2017, Trent Mick.
+ *
+ * Test the bunyan CLI's handling of the "res" field.
+ */
+
+var exec = require('child_process').exec;
+var fs = require('fs');
+var path = require('path');
+var _ = require('util').format;
+var vasync = require('vasync');
+
+// node-tap API
+if (require.cache[__dirname + '/tap4nodeunit.js'])
+        delete require.cache[__dirname + '/tap4nodeunit.js'];
+var tap4nodeunit = require('./tap4nodeunit.js');
+var after = tap4nodeunit.after;
+var before = tap4nodeunit.before;
+var test = tap4nodeunit.test;
+
+
+// ---- globals
+
+var BUNYAN = path.resolve(__dirname, '../bin/bunyan');
+
+
+// ---- tests
+
+test('res with "header" string (issue #444)', function (t) {
+    var expect = [
+        /* BEGIN JSSTYLED */
+        '[2017-08-02T22:37:34.798Z]  INFO: res-header/76488 on danger0.local: response sent',
+        '    HTTP/1.1 200 OK',
+        '    Foo: bar',
+        '    Date: Wed, 02 Aug 2017 22:37:34 GMT',
+        '    Connection: keep-alive',
+        '    Content-Length: 21'
+        /* END JSSTYLED */
+    ].join('\n') + '\n';
+    exec(_('%s %s/corpus/res-header.log', BUNYAN, __dirname),
+            function (err, stdout, stderr) {
+        t.ifError(err);
+        t.equal(stdout, expect);
+        t.end();
+    });
+});
+
+test('res without "header"', function (t) {
+    var expect = [
+        /* BEGIN JSSTYLED */
+        '[2017-08-02T22:37:34.798Z]  INFO: res-header/76488 on danger0.local: response sent',
+        '    HTTP/1.1 200 OK'
+        /* END JSSTYLED */
+    ].join('\n') + '\n';
+    exec(_('%s %s/corpus/res-without-header.log', BUNYAN, __dirname),
+            function (err, stdout, stderr) {
+        t.ifError(err);
+        t.equal(stdout, expect);
+        t.end();
+    });
+});

test/corpus/res-header.log

@@ -0,0 +1 @@
+{"name":"res-header","hostname":"danger0.local","pid":76488,"level":30,"res":{"statusCode":200,"header":"HTTP/1.1 200 OK\r\nFoo: bar\r\nDate: Wed, 02 Aug 2017 22:37:34 GMT\r\nConnection: keep-alive\r\nContent-Length: 21\r\n\r\n"},"msg":"response sent","time":"2017-08-02T22:37:34.798Z","v":0}

test/corpus/res-without-header.log

@@ -0,0 +1 @@
+{"name":"res-header","hostname":"danger0.local","pid":76488,"level":30,"res":{"statusCode":200},"msg":"response sent","time":"2017-08-02T22:37:34.798Z","v":0}