Desconexion Aleatoria de Nodos por error en uso de memoria RAM

Elastic In Your Native Tongue Elastic en Español
1

Buenos dias,

Estoy teniendo un problema con el funcionamiento del Cluster, los nodos se desconectan y cuando verifico los logs no deja ningun registro de error. El archivo esta /etc/default/elasticsearch (linux) esta definida la variable ES_HEAP_SIZE esta definida en 2g (%50 del total disponible). La variable bootstrap.mlockaall esta seteada = true en el archivo elasticsearch.yml tambien es configurada.
Cuando 'grepeo' en busca de procesos java o alguno vinculado a elasticsearch no encuentro ninguno.

2

Hola Emiliano,

Como estas? Una consulta, cual es el ultimo log que puedes ver en alguno de los nodos que se desconectan? Por otro lado, en el MASTER node, puedes ver alguna informacion sobre esto? El proceso java se muere en estas maquinas?

Saludos!

--Gabriel

3

Gracias por la pronta respuesta Gabriel,

Si, en uno de los reinicio dejo el siguiente log:

[2016-09-01 19:34:48,872][DEBUG][bootstrap                ] seccomp(SECCOMP_SET_MODE_FILTER): `Preformatted text`Función no implementada, falling back to prctl(PR_SET_SECCOMP)...
[2016-09-01 19:34:48,874][DEBUG][bootstrap                ] Linux seccomp filter installation successful, threads: [app]

Y a continuacion mostraba como levantaba:

[2016-09-01 19:33:42,479][DEBUG][bootstrap                ] java.home: /usr/lib/jvm/jdk1.8.0_31/jre
[2016-09-01 19:33:42,480][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/e
lasticsearch-2.3.4.jar
[2016-09-01 19:33:42,527][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/j
ackson-dataformat-smile-2.6.6.jar
[2016-09-01 19:33:42,529][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/l
ucene-grouping-5.5.0.jar
[2016-09-01 19:33:42,530][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/c
ompiler-0.8.13.jar
[2016-09-01 19:33:42,532][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/j
oda-time-2.9.4.jar
[2016-09-01 19:33:42,535][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/l
ucene-misc-5.5.0.jar
[2016-09-01 19:33:42,537][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/H
drHistogram-2.1.6.jar
[2016-09-01 19:33:42,538][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/j
sr166e-1.1.0.jar
[2016-09-01 19:33:42,539][DEBUG][bootstrap                ] examining jar: /usr/share/elasticsearch/lib/j
oda-convert-1.2.jar
[2016-09-01 19:33:42,540][DEBUG][bootstrap

[2016-09-01 19:33:44,817][DEBUG][bootstrap                ] excluding duplicate classpath element: /usr/s
hare/elasticsearch/lib/elasticsearch-2.3.4.jar

Lo que yo note es que quedaba la memoria reservada como si estuviera funcionando, pero al buscar no encontre ningun proceso java, tampoco analizando los arboles de proceso encontre algo que pudiera relacionarlo.
Ahora lo que voy a hacer es dejarlo funcionando hasta mañana con el modo > bootstrap.mlockall: true comentado (entiendo que comentado [como esta por defecto] esta en false).
En el dmseg y en el syslog tampoco encontre errores...
Me recomendas que cambie el nivel de logging a otro distinto a debug en '/etc/default/elasticsearch' o esta bien este nivel para analizar estos errores?

Saludos

4

Hola Emiliano,

Por curiosidad, que versión de ES estas usando? Cuántos nodos tiene el cluster? Están corriendo todos en la misma maquina? Todos tienen el role master&data, usas master dedicados?
Como dice Gabriel, sería interesante ver el log completo cuando el problema ocurre de uno de los nodos afectados y el del node master.
Algún cambio reciente a partir del cual el problema apareció?

Saludos
Miguel

5

Hola @miguel, te paso los datos por los que preguntas:

  • ES: 2.3.4
    *JVM: 1.8.0_31

Es la misma version en todos los nodos.

En cuanto a donde estan corriendo los nodos, no, no corren en la misma maquina. Estan virtualizados y funcionan en 2 servidores ESXi distintos.
En relacion a los roles, son dedicados todos y la etructura es la siguiente.

  • 2 nodos clientes
  • 2 nodos master
  • 3 nodos de datos.

La idea es, a esta estructura (cuando quede estable) agregarle algunos nodos de datos mas.

El cambio fue agregar un nodo cliente y un nodo de datos mas, pero estos no son los nodos que se caen necesariamente.
En cuanto al log, deberia cambiarle el nivel, porque pasarles el log en modo DEBUG es una locura, creo que deberia cambiarlo a otro nivel, no?
Recien arranca el dia con unos mates, asi q me pongo a leer logs a ver si encuentro q esta pasando. Hoy estuvo mas estable, si encuentro algo nuevo o la solucion se los paso. Si se les ocurre alguna idea por la cual empezar a mirar, o consejos de arquitectura seran mas que bienvenidos.
Muchas gracias! Saludos!

6

Bueno @miguel y @gmoskovicz, ahi estuve mirando un buen rato logs, y haciendo un grep sobre los logs del nodo master que tenia el control y el nodo data que se cayo encuentro el siguiente error (que estoy buscando mas datos para entender porque se produjo).

7

NODO MASTER

[2016-09-01 22:05:38,128][DEBUG][transport.netty          ] [G-ES-MASTER-02] disconnecting from [{G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false}], channel closed event
[2016-09-01 22:05:38,138][DEBUG][cluster.service          ] [G-ES-MASTER-02] processing [zen-disco-node_failed({G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false}), reason transport disconnected]: execute
[2016-09-01 22:05:38,174][INFO ][cluster.routing.allocation] [G-ES-MASTER-02] Cluster health status changed from [GREEN] to [YELLOW] (reason: [[{G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false}] failed]).
[2016-09-01 22:05:38,174][DEBUG][cluster.service          ] [G-ES-MASTER-02] cluster state updated, version [577], source [zen-disco-node_failed({G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false}), reason transport disconnected]
[2016-09-01 22:05:38,174][INFO ][cluster.service          ] [G-ES-MASTER-02] removed {{G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false},}, reason: zen-disco-node_failed({G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false}), reason transport disconnected
SendRequestTransportException[[G-ES-DATA-03][10.0.100.33:9300][cluster:monitor/nodes/stats[n]]]; nested: NodeNotConnectedException[[G-ES-DATA-03][10.0.100.33:9300] Node not connected];
Caused by: NodeNotConnectedException[[G-ES-DATA-03][10.0.100.33:9300] Node not connected]
SendRequestTransportException[[G-ES-DATA-03][10.0.100.33:9300][indices:monitor/stats[n]]]; nested: NodeNotConnectedException[[G-ES-DATA-03][10.0.100.33:9300] Node not connected];
Caused by: NodeNotConnectedException[[G-ES-DATA-03][10.0.100.33:9300] Node not connected]
[2016-09-01 22:06:08,277][DEBUG][cluster.service          ] [G-ES-MASTER-02] processing [zen-disco-node_failed({G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false}), reason transport disconnected]: took 30.1s done applying updated cluster_state (version: 577, uuid: xoNvFuYsRfWVio4ZgW2Tfw)
[2016-09-01 22:06:08,277][WARN ][cluster.service          ] [G-ES-MASTER-02] cluster state update task [zen-disco-node_failed({G-ES-DATA-03}{NW7DtlHqSyGR_4jGtxgmFQ}{10.0.100.33}{10.0.100.33:9300}{master=false}), reason transport disconnected] took 30.1s above the warn threshold of 30s
8

y estas son las ultimas lineas del log de NODO DATA:

[2016-09-01 22:01:43,705][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:02:13,706][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:02:43,706][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:03:13,708][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:03:43,708][DEBUG][index.shard              ] [G-ES-DATA-03] [z2_hdr_dem0-20160901][0] updating index_buffer_size from [4mb] to [500kb]; IndexWriter now using [0] bytes
[2016-09-01 22:03:43,709][DEBUG][index.shard              ] [G-ES-DATA-03] [z2_hdr_dem0-20160901][0] marking shard as inactive (inactive_time=[300000000000]) indexing wise
[2016-09-01 22:03:43,709][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [75] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:03:43,738][DEBUG][index.engine             ] [G-ES-DATA-03] [z2_hdr_dem0-20160901][0] successfully sync committed. sync id [AVbnx3TzxbYqAYOWMHO5].
[2016-09-01 22:03:48,690][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:03:48,700][DEBUG][index.shard              ] [G-ES-DATA-03] [z2_hdr_dem0-20160901][0] updating index_buffer_size from [500kb] to [4mb]; IndexWriter now using [0] bytes
[2016-09-01 22:04:13,710][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:04:43,712][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]
[2016-09-01 22:05:13,713][DEBUG][indices.memory           ] [G-ES-DATA-03] recalculating shard indexing buffer, total is [203.1mb] with [76] active shards, each shard set to indexing=[4mb], translog=[64kb]

Las anteriores lineas del node.data son iguales.
Si yo intento reinicializar el proceso elasticsearch en el servidor no se puede, y el uso de la RAM esta bloqueado como si estuviera corriendo el proceso. No hay ningun proceso java si busco con un ps -ef|grep java o elasticsearch.

Saludos

9

Fin de una parte del misterio:

Sep  1 22:05:38 G-ES-DATA-03 kernel: [17506.859489] Out of memory: Kill process 2805 (java) score 573 or sacrifice child
Sep  1 22:05:38 G-ES-DATA-03 kernel: [17506.859564] Killed process 2805 (java) total-vm:4637456kB, anon-rss:1763364kB, file-rss:0kB
Sep  1 22:05:38 G-ES-DATA-03 kernel: [17506.864030] in:imklog invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Sep  1 22:05:38 G-ES-DATA-03 kernel: [17506.864034] in:imklog cpuset=/ mems_allowed=0

Eso es el syslog del nodo de datos que se cayo. Ahora, el ubuntu server 14 no usa mas de 2gb, y la heap esta definida en 2g, por lo q no debiera usar mas que eso. la memoria quedo "bloqueada" en 2.4 g.

10

Buenissimo que hayamos encontrado esto.

Una consulta, por casualidad tienes el cluster en AWS? o algo asi?

Generalmente este tipo de errores suelen estarn en el OS level mas que en JVM. Asi que buen encontrado!

11

No no, @gmoskovicz. Son dos servidores ESXi que usamos para desarrollo y testing.
Lo que estoy haciendo ahora es usarlo sin que reserve el espacio en memoria, es decir (si no interprete mal lo que lei en el manual) dejando comentada la opcion:

 # Lock the memory on startup:
#
#bootstrap.mlockall: true

Entiendo que de esa manera deja de reservar. Vamos a probar con esto a ver si de esa manera se puede evitar el desborde de la memoria. Los mantengo al tanto si se soluciona o no, y como siempre, son bienvenidos los consejos.
PD: Los recursos asignados se que son pocos en relacion a los que lei en el manua, pero son de los que se disponen por ahora. Si la implementacion funciona seguramente pueda conseguir algo mas :wink: .

12

Finalmente el problema tenia que ver con que reservaba la ram al iniciarse junto a un problema de disponibilidad de recursos en el server.

13

Generalmente este tipo de errores suelen estarn en el OS level mas que en JVM. Asi que buen encontrado!

Es lo que pensaba yo. Es un problema de OS en realidad. Es muy comun esto porque dice que hay un problema Antes de inicializar la JVM.

Gracias por el heads up!