diff --git a/CHANGES.md b/CHANGES.md index 0be116c..b82ca20 100644 --- a/CHANGES.md +++ b/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 diff --git a/bin/bunyan b/bin/bunyan index 330e25a..a2a4e22 100755 --- a/bin/bunyan +++ b/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; - var hostHeaderLine = ''; - var s = ''; - if (client_req.address) { - hostHeaderLine = '\nHost: ' + client_req.address; - if (client_req.port) - 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, + + /* + * `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 = ''; + 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 (Object.hasOwnProperty.call(client_req, 'port')) { + // XXX + var port = +client_req.port; + if (port !== 80 && port !== 443) { + hostHeaderLine += ':' + client_req.port; + } + delete client_req.port; + } + 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) : diff --git a/test/cli-client-req.test.js b/test/cli-client-req.test.js new file mode 100644 index 0000000..ce95260 --- /dev/null +++ b/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 . +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(); + }); +}); diff --git a/test/corpus/issue504-client-req-with-host.log b/test/corpus/issue504-client-req-with-host.log new file mode 100644 index 0000000..cceb8dd --- /dev/null +++ b/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} diff --git a/test/corpus/issue504-client-req-with-port443.log b/test/corpus/issue504-client-req-with-port443.log new file mode 100644 index 0000000..044fe5e --- /dev/null +++ b/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} diff --git a/test/corpus/issue504-client-req-with-port80.log b/test/corpus/issue504-client-req-with-port80.log new file mode 100644 index 0000000..e4c5350 --- /dev/null +++ b/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} diff --git a/test/corpus/issue504-client-req-with-port8080.log b/test/corpus/issue504-client-req-with-port8080.log new file mode 100644 index 0000000..e6177bc --- /dev/null +++ b/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} diff --git a/test/corpus/issue504-client-req-without-address.log b/test/corpus/issue504-client-req-without-address.log new file mode 100644 index 0000000..1a932df --- /dev/null +++ b/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}