Heartbeat HTTP "use of closed network connection"


(Simon Hardman) #1

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).


(Simon Hardman) #2

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
}
}


(Andrew Cholakian) #3

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.


(Sikishen) #4

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.


(Andrew Cholakian) #5

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


(Andrew Cholakian) #6

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


(Andrew Cholakian) #7

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


(system) #8

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