Heartbeat HTTP "use of closed network connection"

When using a HTTP Heartbeat (6.4.0 on Centos 7.5) I'm finding it works fine if I only check the response status, but if I include a check on the response body I always get an error about "use of closed network connection". Have tested with several HTTPS and plain HTTP web sites.

Any suggestions please?

heartbeat.yml:

output.elasticsearch:
  hosts:
  - ******
heartbeat.monitors:
- type: http
  schedule: 30 * * * * * *
  urls:
  - https://www.elastic.co/
  check.request:
    method: GET
  check.response:
    status: 200
    body: Elasticsearch
logging.level: debug

heartbeat -c /etc/heartbeat/heartbeat.yml -e -d "*":

2018-09-10T13:44:58.219+1200 INFO instance/beat.go:544 Home path: [/usr/share/heartbeat] Config path: [/etc/heartbeat] Data path: [/var/lib/heartbeat] Logs path: [/var/log/heartbeat]
2018-09-10T13:44:58.220+1200 DEBUG [beat] instance/beat.go:571 Beat metadata path: /var/lib/heartbeat/meta.json
2018-09-10T13:44:58.220+1200 INFO instance/beat.go:551 Beat UUID: 04263c29-1ff6-49b7-b439-c11d3f1a6ed1
...
2018-09-10T13:44:58.220+1200 INFO [seccomp] seccomp/seccomp.go:116 Syscall filter successfully installed
2018-09-10T13:44:58.220+1200 INFO [beat] instance/beat.go:768 Beat info {"system_info": {"beat": {"path": {"config": "/etc/heartbeat", "data": "/var/lib/heartbeat", "home": "/usr/share/heartbeat", "logs": "/var/log/heartbeat"}, "type": "heartbeat", "uuid": "04263c29-1ff6-49b7-b439-c11d3f1a6ed1"}}}
2018-09-10T13:44:58.220+1200 INFO [beat] instance/beat.go:777 Build info {"system_info": {"build": {"commit": "34b4e2cc75fbbee5e7149f3916de72fb8892d070", "libbeat": "6.4.0", "time": "2018-08-17T22:21:25.000Z", "version": "6.4.0"}}}
2018-09-10T13:44:58.220+1200 INFO [beat] instance/beat.go:780 Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":2,"version":"go1.10.3"}}}
2018-09-10T13:44:58.222+1200 INFO [beat] instance/beat.go:784 Host info {"system_info": {"host": {"architecture":"x86_64","boot_time":"2018-09-05T09:39:16+12:00","containerized":true,"hostname":"elk","ips":["127.0.0.1/8","::1/128","10.0.2.15/24","fe80::a00:27ff:fe01:ab81/64","10.0.0.28/24","fe80::a00:27ff:fee7:9368/64"],"kernel_version":"3.10.0-862.9.1.el7.x86_64","mac_addresses":["08:00:27:01:ab:81","08:00:27:e7:93:68"],"os":{"family":"redhat","platform":"centos","name":"CentOS Linux","version":"7 (Core)","major":7,"minor":5,"patch":1804,"codename":"Core"},"timezone":"NZST","timezone_offset_sec":43200,"id":"4454d823e45548f38c7966cdf2c87d26"}}}
...
2018-09-10T13:45:31.025+1200 DEBUG [publish] pipeline/processor.go:308 Publish event: {
"@timestamp": "2018-09-10T01:45:30.000Z",
"@metadata": {
"beat": "heartbeat",
"type": "doc",
"version": "6.4.0"
},
"beat": {
"name": "elk",
"hostname": "elk",
"version": "6.4.0"
},
"host": {
"name": "elk"
},
"monitor": {
"type": "http",
"ip": "151.101.166.217",
"host": "www.elastic.co",
"duration": {
"us": 1024862
},
"status": "down",
"scheme": "https",
"id": "http@https://www.elastic.co/",
"name": "http"
},
"resolve": {
"ip": "151.101.166.217",
"rtt": {
"us": 33366
},
"host": "www.elastic.co"
},
"error": {
"message": "read tcp 10.0.2.15:48400->151.101.166.217:443: use of closed network connection",
"type": "validate"
},
"tcp": {
"port": 443,
"rtt": {
"connect": {
"us": 14068
}
}
},
"tls": {
"rtt": {
"handshake": {
"us": 47384
}
}
},
"http": {
"response": {
"status_code": 200
},
"rtt": {
"validate": {
"us": 929890
},
"content": {
"us": 110
},
"total": {
"us": 991436
},
"write_request": {
"us": 79
},
"response_header": {
"us": 929779
}
},
"url": "https://www.elastic.co/"
}
}
2018-09-10T13:45:31.025+1200 DEBUG [scheduler] scheduler/scheduler.go:225 Job 'http@https://www.elastic.co/' returned at 2018-09-10 13:45:31.025668512 +1200 NZST m=+32.815560624 (cont=0).

1 Like

Further testing indicates that the problem occurs when processing a large response. In the example below "go1.10.html" is 18kb and reproduces the error, while ".gitignore" is 1kb and works fine. Both URLs are on the same domain.

heartbeat.yml:
output.elasticsearch:
hosts:
- ******
heartbeat.monitors:
- type: http
schedule: 30 * * * * * *
urls:
- https://raw.githubusercontent.com/golang/go/master/doc/go1.10.html
- https://raw.githubusercontent.com/golang/go/master/.gitignore
check.request:
method: GET
check.response:
status: 200
body: go
logging.level: debug

2018-09-13T16:40:00.933+1200 INFO [beat] instance/beat.go:768 Beat info {"system_info": {"beat": {"path": {"config": "/etc/heartbeat", "data": "/var/lib/heartbeat", "home": "/usr/share/heartbeat", "logs": "/var/log/heartbeat"}, "type": "heartbeat", "uuid": "4bc15c91-3b1c-450b-8549-468457dc2537"}}}
2018-09-13T16:40:00.933+1200 INFO [beat] instance/beat.go:777 Build info {"system_info": {"build": {"commit": "34b4e2cc75fbbee5e7149f3916de72fb8892d070", "libbeat": "6.4.0", "time": "2018-08-17T22:21:25.000Z", "version": "6.4.0"}}}
2018-09-13T16:40:00.933+1200 INFO [beat] instance/beat.go:780 Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":2,"version":"go1.10.3"}}}
2018-09-13T16:40:00.935+1200 INFO [beat] instance/beat.go:784 Host info {"system_info": {"host": {"architecture":"x86_64","boot_time":"2018-09-12T15:50:28+12:00","containerized":true,"hostname":"elk","ips":["127.0.0.1/8","::1/128","10.0.2.15/24","fe80::a00:27ff:fe01:ab81/64","10.0.0.28/24","fe80::a00:27ff:fe95:b64e/64"],"kernel_version":"3.10.0-862.9.1.el7.x86_64","mac_addresses":["08:00:27:01:ab:81","08:00:27:95:b6:4e"],"os":{"family":"redhat","platform":"centos","name":"CentOS Linux","version":"7 (Core)","major":7,"minor":5,"patch":1804,"codename":"Core"},"timezone":"NZST","timezone_offset_sec":43200,"id":"4454d823e45548f38c7966cdf2c87d26"}}}

2018-09-13T16:40:30.120+1200 DEBUG [publish] pipeline/processor.go:308 Publish event: {
"@timestamp": "2018-09-13T04:40:30.004Z",
"@metadata": {
"beat": "heartbeat",
"type": "doc",
"version": "6.4.0"
},
"resolve": {
"host": "raw.githubusercontent.com",
"ip": "151.101.232.133",
"rtt": {
"us": 52056
}
},
"tls": {
"rtt": {
"handshake": {
"us": 46661
}
}
},
"http": {
"response": {
"status_code": 200
},
"rtt": {
"content": {
"us": 699
},
"total": {
"us": 63227
},
"write_request": {
"us": 122
},
"response_header": {
"us": 7778
},
"validate": {
"us": 8478
}
},
"url": "https://raw.githubusercontent.com/golang/go/master/.gitignore"
},
"tcp": {
"port": 443,
"rtt": {
"connect": {
"us": 7857
}
}
},
"monitor": {
"type": "http",
"host": "raw.githubusercontent.com",
"ip": "151.101.232.133",
"status": "up",
"duration": {
"us": 115438
},
"scheme": "https",
"id": "http@https://raw.githubusercontent.com/golang/go/master/.gitignore",
"name": "http"
},
"beat": {
"name": "elk",
"hostname": "elk",
"version": "6.4.0"
},
"host": {
"name": "elk"
}
}
2018-09-13T16:40:30.120+1200 DEBUG [scheduler] scheduler/scheduler.go:225 Job 'http@https://raw.githubusercontent.com/golang/go/master/.gitignore' returned at 2018-09-13 16:40:30.120650041 +1200 NZST m=+29.202853788 (cont=0).
2018-09-13T16:40:30.120+1200 DEBUG [scheduler] scheduler/scheduler.go:187 Next wakeup time: 2018-09-13 16:41:30 +1200 NZST
2018-09-13T16:40:30.121+1200 DEBUG [publish] pipeline/processor.go:308 Publish event: {
"@timestamp": "2018-09-13T04:40:30.004Z",
"@metadata": {
"beat": "heartbeat",
"type": "doc",
"version": "6.4.0"
},
"tls": {
"rtt": {
"handshake": {
"us": 47186
}
}
},
"beat": {
"name": "elk",
"hostname": "elk",
"version": "6.4.0"
},
"host": {
"name": "elk"
},
"http": {
"response": {
"status_code": 200
},
"rtt": {
"content": {
"us": 607
},
"total": {
"us": 64762
},
"write_request": {
"us": 77
},
"response_header": {
"us": 9370
},
"validate": {
"us": 9977
}
},
"url": "https://raw.githubusercontent.com/golang/go/master/doc/go1.10.html"
},
"resolve": {
"rtt": {
"us": 51888
},
"host": "raw.githubusercontent.com",
"ip": "151.101.232.133"
},
"monitor": {
"id": "http@https://raw.githubusercontent.com/golang/go/master/doc/go1.10.html",
"scheme": "https",
"name": "http",
"type": "http",
"host": "raw.githubusercontent.com",
"ip": "151.101.232.133",
"duration": {
"us": 116808
},
"status": "down"
},
"error": {
"type": "validate",
"message": "read tcp 10.0.2.15:49497->151.101.232.133:443: use of closed network connection"
},
"tcp": {
"rtt": {
"connect": {
"us": 7307
}
},
"port": 443
}
}

Thanks for the reports and analysis. Would you mind opening an issue on github @ https://github.com/elastic/beats ? We'll be taking a look soon either way, but an issue would be appreciated.

Hi,
Thanks for this issue report, i'm also using heartbeat for HTTPS healthcheck and getting this same error.
I also found articles about this kind of issue in Consul, seems Go is trying to reuse the same socket referring to https://github.com/hashicorp/consul/issues/1287.
So i also tried to adding a check.request.headers: {'Connection':'close'} to prevent keep-alive connection, but didn't work.
and now i have to use, "logstash->filter->ruby->shell->curl->event.set" to get the result, something like this.
filter {
ruby { code => "
ENV['url'] = event.get('[http][url]')
maintenance_result = curl -b -j -s -I -H 'User-Agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.79 Safari/537.36' --no-keepalive -k --connect-timeout 5 --max-time 5 --no-sessionid $url | grep maintenance;echo $?
event.set('[check][maintenance]', maintenance_result)
"}
}

Hope to see the fix in future versions, and also if there's a statement in check.response.body for adding different fields on the result then it can be great.

I've opened an issue #8588 to track this. I'm going to treat this as a higher priority bug.

As an update, I've opened a PR to fix this behavior. You can track it here: https://github.com/elastic/beats/pull/8660

The PR has been merged and will likely be part of the 6.5 release.

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.