Wir führen Logstash auf einem Server aus, der Protokolle in einen Elasticsearch-Cluster überträgt. In den Logstash-Protokollen sehen wir, dass die Verbindung zu den Elasticsearch-Servern verloren geht und ein Verbindungsreset-Fehler auftritt. Wir sehen dies zwischen allen unseren Logstash- und Elasticsearch-Instanzen auf allen Servern. In diesem Beispiel sehen wir, dass logstash3 (192.168.1.133) die Verbindung zu elasticsearch4 (192.168.1.88) verliert.
[2018-08-21T20:21:21,414][WARN ][logstash.outputs.elasticsearch] Marking url as dead. Last error: [LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError] Elasticsearch Unreachable: [http://elasticsearch4:9200/][Manticore::SocketException] Connection reset {:url=>http://elasticsearch4:9200/, :error_message=>"Elasticsearch Unreachable: [http://elasticsearch4:9200/][Manticore::SocketException] Connection reset", :error_class=>"LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError"}
Wenn wir ins Syslog schauen, können wir sehen, dass UFW vor einigen Sekunden ein Paket blockiert:
Aug 21 20:21:03 logstash3 kernel: [1760565.386970] [UFW BLOCK] IN=enp0s31f6 OUT= MAC=90:1b:0e:cc:50:95:30:b6:4f:d8:05:51:08:00 SRC=192.168.1.88 DST=192.168.1.133 LEN=40 TOS=0x0 PREC=0x00 TTL=57 ID=442 DF PROTO=TCP SPT=9200 DPT=59338 WINDOW=0 RES=0x00 RST URGP=0
Wir haben in ufw eine Regel eingerichtet, die alle Verbindungen zwischen diesen Servern zulässt. Anfangs haben wir nur bestimmte Ports zugelassen, aber ich habe es für alle Ports geöffnet, falls das das Problem sein sollte. Die Regel, die Verbindungen zulässt, lautet:
logstash3:~$ sudo ufw status | grep '\.88'
Anywhere ALLOW 192.168.1.88
Wenn wir Logstash neu starten, verschwinden diese unterbrochenen Verbindungen für eine gewisse Zeit (~1 Stunde), treten dann aber erneut auf.
Da wir sehen, dass es nach einer Weile passiert, neige ich zu der Annahme, dass sich irgendwo eine Warteschlange füllt. Die Verbindung bricht nicht ab, wir verlieren nur gelegentlich Pakete. Ich dachte, es könnte mit der Verbindungsverfolgung zusammenhängen, aber wir sehen keine Protokolle in diesem Sinne. Wir haben die Anzahl conntrack_maxzuvor erhöht, da wir das als Problem erkannt haben, aber in diesem Fall hilft es nicht.
elasticsearch4:~$ cat /proc/sys/net/nf_conntrack_max
262144
Keine Hinweise auf allgemeine Paketverluste:
logstash3:~$ ifconfig
enp0s31f6: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 192.168.1.133 netmask 255.255.255.255 broadcast 0.0.0.0
inet6 2a01:4f8:121:53b7::2 prefixlen 64 scopeid 0x0<global>
inet6 fe80::921b:eff:fecc:5095 prefixlen 64 scopeid 0x20<link>
ether 90:1b:0e:cc:50:95 txqueuelen 1000 (Ethernet)
RX packets 7746452399 bytes 8566845158411 (8.5 TB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 5792178105 bytes 5164493104253 (5.1 TB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
device interrupt 16 memory 0xef000000-ef020000
Auf Anraten von @Lenniey habe ich versucht, UFW zu deaktivieren und zu sehen, ob die Fehler in den Logstash-Protokollen immer noch angezeigt werden. Ich habe UFW auf mehreren Servern deaktiviert und festgestellt, dass wir Connection resetin den Protokollen immer noch Nachrichten zwischen Servern mit deaktiviertem UFW erhalten. Es scheint also, dass die UFW-Einträge im Syslog eher ein Symptom als eine Ursache sind.
Ich habe eine Paketerfassung ( sudo tcpdump -i enp0s31f6 -s 65535 -w logstash.pcap 'port 9200') durchgeführt, während der Fehler auftrat
[2018-08-23T07:20:11,108][WARN ][logstash.outputs.elasticsearch] Marking url as dead. Last error: [LogStash::Outputs::ElasticSearch::
HttpClient::Pool::HostUnreachableError] Elasticsearch nicht erreichbar: [http://elasticsearch3:9200/][Manticore::Socket Ausnahme] Verbindung zurückgesetzt {:url=>http://elasticsearch3:9200/, :error_message=>"Elasticsearch nicht erreichbar: [http: //elasticsearch3:9200/][Manticore::SocketException] Verbindung zurückgesetzt", :error_class=>"LogStash::Outputs::ElasticSe arch::HttpClient::Pool::HostUnreachableError"}
In der Paketerfassung kann ich sehen, dass Elasticsearch mit einem 400-Fehler antwortet:
HTTP/1.0 400 Bad Request
content-type: application/json; charset=UTF-8
content-length: 203
{
"error": {
"root_cause": [
{
"type": "illegal_argument_exception",
"reason": "text is empty (possibly HTTP/0.9)"
}
],
"type": "illegal_argument_exception",
"reason": "text is empty (possibly HTTP/0.9)"
},
"status": 400
}
Dann sehe ich 5 TCP RST-Pakete von Elasticsearch an Logstash. Das letzte RST-Paket war um 07:20:11.107663, was mit der Zeit des Logstash-Fehlers übereinstimmt, 07:20:11,108.
Ich finde die Paketerfassung etwas verwirrend. Ich habe die Paketerfassung auf die IPs des betreffenden Logstash- und ES-Servers und auf die Ports gefiltert, auf denen wir die 400 und RSTs sehen. Vor der 400 scheint jedoch eine _bulkAnfrage in Bearbeitung zu sein, dann eine 414-Antwort während der Anfrage mitten in der _bulkAnfrage, dann wird die _bulkAnfrage fortgesetzt, dann erhalten wir die 400:
Logstash -> ES
POST /_bulk HTTP/1.1
Connection: Keep-Alive
Content-Type: application/json
Content-Length: 167481062
Host: elasticsearch3.channelgrabber.com:9200
User-Agent: Manticore 0.6.1
Accept-Encoding: gzip,deflate
{ ... data ... }
ES -> Logstash
HTTP/1.1 413 Request Entity Too Large
content-length: 0
Logstash -> ES
{ ... data continues ... }
ES -> Logstash
HTTP/1.0 400 Bad Request
content-type: application/json; charset=UTF-8
content-length: 203
{"error":{"root_cause":[{"type":"illegal_argument_exception","reason":"text is empty (possibly HTTP/0.9)"}],"type":"illegal_argument_exception","reason":"text is empty (possibly HTTP/0.9)"},"status":400}
Hat jemand Vorschläge, worauf ich sonst noch achten sollte?