bunyan CLI reports wrong "Host" header for client requests using default port

[davepacheco]

I've been trying to debug a problem involving an HTTP client sending the wrong Host header. The background is in node-manta#306. I was thrown off because the bunyan CLI reported the wrong "Host" header.

With bunyan logging enabled, the client reports this (I've removed my own key signature from all of these outputs):

$ MANTA_URL=http://127.0.0.1:80 minfo -v /dap/stor
...
{"name":"minfo","hostname":"sharptooth.local","pid":66266,"component":"MantaClient","level":10,"client_req":{"method":"HEAD","url":"/dap/stor","address":"127.0.0.1","port":"80","headers":{"accept":"application/json, */*","x-request-id":"9dc63a62-f84e-4508-a128-f1fbca963a7d","date":"Fri, 12 May 2017 23:59:15 GMT","authorization":"Signature keyId=\"/dap/keys/...\",algorithm=\"rsa-sha1\",headers=\"date\",signature=\"...\"","user-agent":"restify/1.3.1 (x64-darwin; v8/3.14.5.9; OpenSSL/1.0.1t) node/0.10.45","accept-version":"~1.0"}},"msg":"request sent","time":"2017-05-12T23:59:15.877Z","src":{"file":"/Users/dap/install/lib/node_modules/manta/node_modules/restify-clients/lib/HttpClient.js","line":314,"func":"rawRequest"},"v":0}

If you run this second log entry through json(1), you can see that the "client_req" object is accurate:

{
  "name": "minfo",
  "hostname": "sharptooth.local",
  "pid": 66266,
  "component": "MantaClient",
  "level": 10,
  "client_req": {
    "method": "HEAD",
    "url": "/dap/stor",
    "address": "127.0.0.1",
    "port": "80",
    "headers": {
      "accept": "application/json, */*",
      "x-request-id": "9dc63a62-f84e-4508-a128-f1fbca963a7d",
      "date": "Fri, 12 May 2017 23:59:15 GMT",
      "authorization": "Signature keyId=\"/dap/keys/...\",algorithm=\"rsa-sha1\",headers=\"date\",signature=\"...\"",
      "user-agent": "restify/1.3.1 (x64-darwin; v8/3.14.5.9; OpenSSL/1.0.1t) node/0.10.45",
      "accept-version": "~1.0"
    }
  },
  "msg": "request sent",
  "time": "2017-05-12T23:59:15.877Z",
  "src": {
    "file": "/Users/dap/install/lib/node_modules/manta/node_modules/restify-clients/lib/HttpClient.js",
    "line": 314,
    "func": "rawRequest"
  },
  "v": 0
}

but if you run this through the bunyan CLI:

[2017-05-12T23:59:15.877Z] TRACE: minfo/MantaClient/66266 on sharptooth.local (/Users/dap/install/lib/node_modules/manta/node_modules/restify-clients/lib/HttpClient.js:314 in rawRequest): request sent
    HEAD /dap/stor HTTP/1.1
    Host: 127.0.0.1:80
    accept: application/json, */*
    x-request-id: 9dc63a62-f84e-4508-a128-f1fbca963a7d
    date: Fri, 12 May 2017 23:59:15 GMT
    authorization: Signature keyId="/dap/keys/...",algorithm="rsa-sha1",headers="date",signature="..."
    user-agent: restify/1.3.1 (x64-darwin; v8/3.14.5.9; OpenSSL/1.0.1t) node/0.10.45
    accept-version: ~1.0

bunyan is printing this out like it's the headers of an HTTP request, with the "Host:" header having value "127.0.0.1:80". But that's wrong. I ran this against a local "nc" server and saw that the Host header received was:

HEAD /dap/stor HTTP/1.1
accept: application/json, */*
x-request-id: 9dc63a62-f84e-4508-a128-f1fbca963a7d
date: Fri, 12 May 2017 23:59:15 GMT
...
accept-version: ~1.0
Host: 127.0.0.1
Connection: keep-alive

That's because Node omits the port when it matches the default for the protocol.

I'm not sure what the best fix is. bunyan could try to mimic Node's logic here, but that's fraught if Node ever changes its behavior. I understand why we want to report this header, but there's no way to know what Node really sent, and it's really confusing when it gets this wrong. Maybe we could report this as "expected headers" or "requested headers" (and leave out Host) instead of reporting it as though it were the actual HTTP request line?

[trentm]

Here is the code where node is adding the "Host" header: https://github.com/nodejs/node/blob/v6.10.3/lib/_http_client.js#L88-L105

That behaviour can depend on:

• options.headers being an array (atypical)
• usage of an undocumented options.setHost boolean
• usage of an undocumented options.defaultPort
• depending on if an agent is in play, and if it defines agent.defaultPort

Anyway, that is more colour for why we can't reliably guess what node is going to do here. Also, who says this is a client_req log record from a node program.

Another issue I believe, is that the bunyan CLI will always write that "Host: ..." line when rendering a client_req object, even if the headers include a Host key.

Ideas:

1. Fix the duplicate-Host problem for Bunyan 1.x and 2.x.
2. For Bunyan 1.x for compat I'd worry slightly about just dropping the "Host" header. That's debatable though. Assuming we keep it, we could fix it to elide the port for Bunyan 1.x.
3. For Bunyan 2.x we could just stop guessing and not do special "Host" header rendering. For example, your log line above would look like this:

$ bunyan issue504.log
[2017-05-12T23:59:15.877Z] TRACE: minfo/MantaClient/66266 on sharptooth.local (/Users/dap/install/lib/node_modules/manta/node_modules/restify-clients/lib/HttpClient.js:314 in rawRequest): request sent (client_req.address=127.0.0.1, client_req.port=80)
    HEAD /dap/stor HTTP/1.1
    accept: application/json, */*
    x-request-id: 9dc63a62-f84e-4508-a128-f1fbca963a7d
    date: Fri, 12 May 2017 23:59:15 GMT
    authorization: Signature keyId="/dap/keys/...",algorithm="rsa-sha1",headers="date",signature="..."
    user-agent: restify/1.3.1 (x64-darwin; v8/3.14.5.9; OpenSSL/1.0.1t) node/0.10.45
    accept-version: ~1.0

Notice the client_req.address=127.0.0.1, client_req.port=80. I'm not sure if that'll be unsatisfying.
A possible way to improve on that would be to have a smarter serializer. I.e. get the client_req serializer from restify-clients to learn how to include a hostHeader field or something.

[aiham]

@trentm This is similar to #444 where the status line gets printed twice. Once because bunyan generates it based onres.statusCode and again if its in the header/headers string/object.

[trentm]

Proposal for Bunyan 1.x:

• Fix the bunyan CLI to not emit a duplicate "Host" line (i.e. if there is a Host header in client_req.headers.
• For 1.x compat we'll keep the bunyan CLI guessing at the Host header. We'll improve that guessing slightly to elide the port if it is 80 or 443 on the assumption that those are the likely defaultPort values for the given request.

Proposal for Bunyan 2.x:

• Change the bunyan CLI to stop guessing at the Host header and update the documentation around this. I imagine this will only affect restify users (likely the main/only place where there is client_req Bunyan serializer usage).

[trentm]

^^^ that commit is the proposed change for 1.x

[trentm]

^^^ that commit for bunyan 2.x proposed change.

[trentm]

published [email protected] (latest) and [email protected] (beta) to npm