cli: don't add Host header for client_req if it already has one (#504)

CHANGES.md

@@ -7,7 +7,13 @@ Known issues:
 
 ## not yet released
 
-(nothing yet)
+- [issue #504] The `bunyan` 1.x CLI adds a `Host: $client_req.address[:$client_req.port]`
+  header when rendering a `client_req` field in a log record. Fix that here to:
+  (a) not add it if `client_req.headers` already includes a host header; and
+  (b) not include the given `port` if it is 80 or 443 (*assuming* that is the
+  default port.
+  Note: `bunyan` 2.x CLI will stop adding this Host header because it is a guess
+  that can be wrong and misleading.
 
 
 ## 1.8.10

bin/bunyan

@@ -898,21 +898,57 @@ function emitRecord(rec, line, opts, stylize) {
             })
         }
 
+        /*
+         * `client_req` is the typical field name for an *HTTP client request
+         * object* serialized by the restify-clients library. Render the
+         * client request somewhat like `curl` debug output shows it.
+         */
         if (rec.client_req && typeof (rec.client_req) === 'object') {
             var client_req = rec.client_req;
             delete rec.client_req;
+
             var headers = client_req.headers;
+            delete client_req.headers;
+
+            /*
+             * `client_req.address`, and `client_req.port`, provide values for
+             * a *likely* "Host" header that wasn't included in the serialized
+             * headers. Node.js will often add this "Host" header in its
+             * `http.ClientRequest`, e.g. for node v6.10.3:
+             *      // JSSTYLED
+             *      https://github.com/nodejs/node/blob/v6.10.3/lib/_http_client.js#L88-L105
+             *
+             * If `client_req.port` exists and is 80 or 443, we *assume* that
+             * is the default protocol port, and elide it per the `defaultPort`
+             * handling in the node.js link above.
+             *
+             * Note: This added Host header is a *guess*. Bunyan shouldn't be
+             * doing this "favour" for users because it can be wrong and
+             * misleading. Bunyan 2.x will drop adding this. See issue #504
+             * for details.
+             */
             var hostHeaderLine = '';
-            var s = '';
-            if (client_req.address) {
+            if (!headers || !(
+                    Object.hasOwnProperty.call(headers, 'host') ||
+                    Object.hasOwnProperty.call(headers, 'Host') ||
+                    Object.hasOwnProperty.call(headers, 'HOST')
+                )
+            ) {
+                if (Object.hasOwnProperty.call(client_req, 'address')) {
                     hostHeaderLine = '\nHost: ' + client_req.address;
-                if (client_req.port)
+                    if (Object.hasOwnProperty.call(client_req, 'port')) {
+                        // XXX
+                        var port = +client_req.port;
+                        if (port !== 80 && port !== 443) {
                             hostHeaderLine += ':' + client_req.port;
                         }
-            delete client_req.headers;
-            delete client_req.address;
                         delete client_req.port;
-            s += format('%s %s HTTP/%s%s%s', client_req.method,
+                    }
+                    delete client_req.address;
+                }
+            }
+
+            var s = format('%s %s HTTP/%s%s%s', client_req.method,
                 client_req.url,
                 client_req.httpVersion || '1.1',
                 hostHeaderLine,
@@ -925,6 +961,7 @@ function emitRecord(rec, line, opts, stylize) {
             delete client_req.method;
             delete client_req.url;
             delete client_req.httpVersion;
+
             if (client_req.body) {
                 s += '\n\n' + (typeof (client_req.body) === 'object' ?
                     JSON.stringify(client_req.body, null, 2) :

test/cli-client-req.test.js

@@ -0,0 +1,120 @@
+/*
+ * Copyright (c) 2017, Trent Mick.
+ *
+ * Test the bunyan CLI's handling of the "client_req" field.
+ * "client_req" is a common-ish Bunyan log field from restify-clients. See:
+ *      // JSSTYLED
+ *      https://github.com/restify/clients/blob/85374f87db9f4469de2605b6b15632b317cc12be/lib/helpers/bunyan.js#L213
+ */
+
+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
+
+// The bunyan CLI shouldn't add a "Host:" line if client_req.headers has one.
+// See <https://github.com/trentm/node-bunyan/issues/504>.
+test('client_req renders without extra Host header', function (t) {
+    exec(_('%s %s/corpus/issue504-client-req-with-host.log', BUNYAN, __dirname),
+             function (err, stdout, stderr) {
+        t.ifError(err)
+        t.equal(stdout, [
+            // JSSTYLED
+            '[2017-05-12T23:59:15.877Z] TRACE: minfo/66266 on sharptooth.local: request sent (client_req.address=127.0.0.1)',
+            '    HEAD /dap/stor HTTP/1.1',
+            '    accept: application/json, */*',
+            '    host: foo.example.com',
+            '    date: Fri, 12 May 2017 23:59:15 GMT',
+            ''
+        ].join('\n'));
+        t.end();
+    });
+});
+
+test('client_req added Host header elides port 80', function (t) {
+    exec(_('%s %s/corpus/issue504-client-req-with-port80.log',
+            BUNYAN, __dirname),
+            function (err, stdout, stderr) {
+        t.ifError(err)
+        t.equal(stdout, [
+            // JSSTYLED
+            '[2017-05-12T23:59:15.877Z] TRACE: minfo/66266 on sharptooth.local: request sent',
+            '    HEAD /dap/stor HTTP/1.1',
+            '    Host: 127.0.0.1',
+            '    accept: application/json, */*',
+            '    date: Fri, 12 May 2017 23:59:15 GMT',
+            ''
+        ].join('\n'));
+        t.end();
+    });
+});
+
+test('client_req added Host header elides port 443', function (t) {
+    exec(_('%s %s/corpus/issue504-client-req-with-port443.log',
+            BUNYAN, __dirname),
+            function (err, stdout, stderr) {
+        t.ifError(err)
+        t.equal(stdout, [
+            // JSSTYLED
+            '[2017-05-12T23:59:15.877Z] TRACE: minfo/66266 on sharptooth.local: request sent',
+            '    HEAD /dap/stor HTTP/1.1',
+            '    Host: 127.0.0.1',
+            '    accept: application/json, */*',
+            '    date: Fri, 12 May 2017 23:59:15 GMT',
+            ''
+        ].join('\n'));
+        t.end();
+    });
+});
+
+test('client_req added Host header, non-default port', function (t) {
+    exec(_('%s %s/corpus/issue504-client-req-with-port8080.log',
+            BUNYAN, __dirname),
+            function (err, stdout, stderr) {
+        t.ifError(err)
+        t.equal(stdout, [
+            // JSSTYLED
+            '[2017-05-12T23:59:15.877Z] TRACE: minfo/66266 on sharptooth.local: request sent',
+            '    HEAD /dap/stor HTTP/1.1',
+            '    Host: 127.0.0.1:8080',
+            '    accept: application/json, */*',
+            '    date: Fri, 12 May 2017 23:59:15 GMT',
+            ''
+        ].join('\n'));
+        t.end();
+    });
+});
+
+test('client_req without address does not add Host header', function (t) {
+    exec(_('%s %s/corpus/issue504-client-req-without-address.log',
+            BUNYAN, __dirname),
+            function (err, stdout, stderr) {
+        t.ifError(err)
+        t.equal(stdout, [
+            // JSSTYLED
+            '[2017-05-12T23:59:15.877Z] TRACE: minfo/66266 on sharptooth.local: request sent',
+            '    HEAD /dap/stor HTTP/1.1',
+            '    accept: application/json, */*',
+            '    date: Fri, 12 May 2017 23:59:15 GMT',
+            ''
+        ].join('\n'));
+        t.end();
+    });
+});

test/corpus/issue504-client-req-with-host.log

@@ -0,0 +1 @@
+{"name":"minfo","hostname":"sharptooth.local","pid":66266,"level":10,"client_req":{"method":"HEAD","url":"/dap/stor","address":"127.0.0.1","headers":{"accept":"application/json, */*","host":"foo.example.com","date":"Fri, 12 May 2017 23:59:15 GMT"}},"msg":"request sent","time":"2017-05-12T23:59:15.877Z","v":0}

test/corpus/issue504-client-req-with-port443.log

@@ -0,0 +1 @@
+{"name":"minfo","hostname":"sharptooth.local","pid":66266,"level":10,"client_req":{"method":"HEAD","url":"/dap/stor","address":"127.0.0.1","port":"443","headers":{"accept":"application/json, */*","date":"Fri, 12 May 2017 23:59:15 GMT"}},"msg":"request sent","time":"2017-05-12T23:59:15.877Z","v":0}

test/corpus/issue504-client-req-with-port80.log

@@ -0,0 +1 @@
+{"name":"minfo","hostname":"sharptooth.local","pid":66266,"level":10,"client_req":{"method":"HEAD","url":"/dap/stor","address":"127.0.0.1","port":"80","headers":{"accept":"application/json, */*","date":"Fri, 12 May 2017 23:59:15 GMT"}},"msg":"request sent","time":"2017-05-12T23:59:15.877Z","v":0}

test/corpus/issue504-client-req-with-port8080.log

@@ -0,0 +1 @@
+{"name":"minfo","hostname":"sharptooth.local","pid":66266,"level":10,"client_req":{"method":"HEAD","url":"/dap/stor","address":"127.0.0.1","port":"8080","headers":{"accept":"application/json, */*","date":"Fri, 12 May 2017 23:59:15 GMT"}},"msg":"request sent","time":"2017-05-12T23:59:15.877Z","v":0}

test/corpus/issue504-client-req-without-address.log

@@ -0,0 +1 @@
+{"name":"minfo","hostname":"sharptooth.local","pid":66266,"level":10,"client_req":{"method":"HEAD","url":"/dap/stor","headers":{"accept":"application/json, */*","date":"Fri, 12 May 2017 23:59:15 GMT"}},"msg":"request sent","time":"2017-05-12T23:59:15.877Z","v":0}