[v.0.8.5] consul monitor breaks on HTTP response in healthcheck output

[ashald]

consul version for both Client and Server

Client: 0.8.5
Server: 0.8.5

Reproduction steps & Description of the Issue (and unexpected/desired result)

curl based HTTP health-check crashes consul monitor -lo-level=debug:

$ consul monitor -log-level=debug
2017/07/10 15:46:37 [DEBUG] http: Request GET /v1/catalog/services?stale=true&index=46075769&dc=dc1 (765.335523ms) from=127.0.0.1:54538
2017/07/10 15:46:37 [DEBUG] http: Request GET /v1/catalog/services?stale=true&index=46075770&dc=dc1 (132.031762ms) from=127.0.0.1:54538
2017/07/10 15:46:37 [DEBUG] http: Request GET /v1/catalog/services?stale=true&index=46075773&dc=dc1 (6.124493ms) from=127.0.0.1:54538
2017/07/10 15:46:37 [DEBUG] agent: Check 'service:my-service' script 'curl -fisS -H "Host: self" http://localhost:4140/admin/ping' output: HTTP/1.1 200 OK
Content-Language: en
Content-Length: 4
Content-Type: text/plain;charset=UTF-8

Remote side ended the monitor! This usually means that the
remote side has exited or crashed.

Presumably, writing logged HTTP response to the log stream forces client to close the stream. I.e., log output is not escaped.

Check definition:

{
    "service": {
        "checks": [
            {
                "interval": "3s",
                "name": "my-service",
                "notes": "HTTP check on localhost:4140",
                "script": "curl -fisS -H 'Host: self' http://localhost:4140/admin/ping",
                "timeout": "1s"
            }
        ],
        "enableTagOverride": false,
        "id": "my-service",
        "name": "my-service",
        "port": 4140
    }
}

Yes, we do know that curl-based checks should be avoided in favor of native http checks but this is what we've got after updating from the 0.7.4 to the 0.8.5 (since the former one didn't support headers and Host header support seem to be broken until 0.9).

Please let me know whether I provided enough details.

[slackpad]

Hi @ashald thanks for opening an issue. I wasn't able to reproduce this with other endpoints that produce HTTP response using curl. Can you get this to happen against a public endpoint some place that I can observe locally?

[ashald]

In fact, this is very easy to reproduce with Consul itself. Here is minimal config I used:

{
    "service": {
        "checks": [
            {
                "interval": "3s",
                "name": "my-service",
                "script": "curl -fisS http://localhost:8500",
                "timeout": "1s"
            }
        ],
        "name": "my-service",
        "port": 8500
    }
}

and started consul using:

$ consul agent -dev -config-dir . -data-dir data

Once we have it running now we just start monitoring with debug log level:

$ consul monitor -log-level=debug
2017/08/08 21:18:46 [DEBUG] Using random ID "58c772ea-79d6-7a2b-e70e-10a1e24ec571" as node ID
2017/08/08 21:18:46 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:127.0.0.1:8300 Address:127.0.0.1:8300}]
2017/08/08 21:18:46 [INFO] raft: Node at 127.0.0.1:8300 [Follower] entering Follower state (Leader: "")
2017/08/08 21:18:46 [INFO] serf: EventMemberJoin: iebdev13 127.0.0.1
2017/08/08 21:18:46 [INFO] consul: Adding LAN server iebdev13 (Addr: tcp/127.0.0.1:8300) (DC: dc1)
2017/08/08 21:18:46 [INFO] serf: EventMemberJoin: iebdev13.dc1 127.0.0.1
2017/08/08 21:18:46 [DEBUG] agent: pausing 2.052145682s before first invocation of curl -fisS http://localhost:8500
2017/08/08 21:18:46 [INFO] agent: Started DNS server 127.0.0.1:8600 (udp)
2017/08/08 21:18:46 [INFO] agent: Started DNS server 127.0.0.1:8600 (tcp)
2017/08/08 21:18:46 [INFO] consul: Handled member-join event for server "iebdev13.dc1" in area "wan"
2017/08/08 21:18:46 [INFO] agent: Started HTTP server on 127.0.0.1:8500
2017/08/08 21:18:46 [WARN] raft: Heartbeat timeout from "" reached, starting election
2017/08/08 21:18:46 [INFO] raft: Node at 127.0.0.1:8300 [Candidate] entering Candidate state in term 2
2017/08/08 21:18:46 [DEBUG] raft: Votes needed: 1
2017/08/08 21:18:46 [DEBUG] raft: Vote granted from 127.0.0.1:8300 in term 2. Tally: 1
2017/08/08 21:18:46 [INFO] raft: Election won. Tally: 1
2017/08/08 21:18:46 [INFO] raft: Node at 127.0.0.1:8300 [Leader] entering Leader state
2017/08/08 21:18:46 [INFO] consul: cluster leadership acquired
2017/08/08 21:18:46 [INFO] consul: New leader elected: iebdev13
2017/08/08 21:18:46 [DEBUG] consul: reset tombstone GC to index 3
2017/08/08 21:18:46 [INFO] consul: member 'iebdev13' joined, marking health alive
2017/08/08 21:18:46 [INFO] agent: Synced service 'consul'
2017/08/08 21:18:46 [INFO] agent: Synced service 'my-service'
2017/08/08 21:18:46 [DEBUG] agent: Check 'service:my-service' in sync
2017/08/08 21:18:46 [DEBUG] agent: Node info in sync
2017/08/08 21:18:48 [DEBUG] agent: Check 'service:my-service' script 'curl -fisS http://localhost:8500' output: HTTP/1.1 200 OK
Date: Tue, 08 Aug 2017 21:18:48 GMT
Content-Length: 12
Content-Type: text/plain; charset=utf-8

Remote side ended the monitor! This usually means that the
remote side has exited or crashed.

[ashald]

Thanks!