Estamos ejecutando Logstash en un servidor que envía registros a un clúster de Elasticsearch. En los registros de Logstash, vemos que se pierde la conexión con los servidores de Elasticsearch con un error de restablecimiento de la conexión. Vemos esto entre todas nuestras instancias de logstash y elasticsearch en todos los servidores. En este ejemplo vemos que logstash3 (192.168.1.133) pierde conexión con elasticsearch4 (192.168.1.88)
[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"}
Mirando en syslog podemos ver que UFW está bloqueando un paquete unos segundos antes:
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
Tenemos una regla en ufw para permitir todas las conexiones entre estos servidores. Inicialmente solo permitíamos puertos específicos, pero lo abrí a todos los puertos en caso de que ese fuera el problema. La regla que permite conexiones es:
logstash3:~$ sudo ufw status | grep '\.88'
Anywhere ALLOW 192.168.1.88
Si reiniciamos logstash, estas conexiones caídas desaparecen por un tiempo (~1 hora), pero luego comienzan a repetirse.
Debido a que vemos que esto comienza a suceder después de un tiempo, me inclino a pensar que es una cola que se está llenando en alguna parte. La conexión no se detiene en seco, simplemente comenzamos a perder algún paquete ocasional. Pensé que podría estar relacionado con el seguimiento de la conexión, pero no vemos ningún registro al respecto. Hemos aumentado conntrack_maxanteriormente porque lo hemos visto como un problema, pero no ayuda en este caso.
elasticsearch4:~$ cat /proc/sys/net/nf_conntrack_max
262144
No hay evidencia de caídas de paquetes genéricos:
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
Siguiendo el consejo de @Lenniey, intenté deshabilitar UFW y ver si todavía veíamos los errores en los registros de logstash. Deshabilité ufw en varios servidores y vi que todavía recibíamos Connection resetmensajes en los registros entre servidores con ufw deshabilitado, por lo que parece que las entradas de ufw en syslog pueden ser un síntoma más que una causa.
Produje una captura de paquete ( sudo tcpdump -i enp0s31f6 -s 65535 -w logstash.pcap 'port 9200') mientras veíamos el error.
[2018-08-23T07:20:11,108][WARN ][logstash.outputs.elasticsearch] Marking url as dead. Last error: [LogStash::Outputs::ElasticSearch::
HttpClient::Pool::HostUnreachableError] Elasticsearch inalcanzable: [http://elasticsearch3:9200/][Mantícora::Socket Excepción] Restablecimiento de conexión {:url=>http://elasticsearch3:9200/, :error_message=>"Elasticsearch inalcanzable: [http: //elasticsearch3:9200/][Manticore::SocketException] Restablecimiento de conexión", :error_class=>"LogStash::Outputs::ElasticSe arch::HttpClient::Pool:: HostUnreachableError"}
En la captura del paquete puedo ver que elasticsearch responde con un error 400:
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
}
Luego veo 5 paquetes TCP RST de elasticsearch a logstash. El último paquete RST fue a las 07:20:11.107663, que coincide con la hora del error de logstash 07:20:11,108.
La captura de paquetes me parece un poco confusa. He filtrado la captura de paquetes hasta las IP del servidor logstash y ES en cuestión, y hasta los puertos donde vemos el 400 y el RST, sin embargo, antes del 400 parece haber una _bulksolicitud en progreso, luego una respuesta 414. durante la solicitud en medio de la _bulksolicitud, luego la _bulksolicitud continúa, luego obtenemos el 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}
¿Alguien tiene alguna sugerencia sobre qué más debería mirar?